[rdiff-backup-users] Freeze problem when pulling backups

[Joonas Pulakka]

Hello,

I've set up a rdiff-backup like in this recipe: http://arctic.org/~dean/rdiff-backup/unattended.html , whereby backups are pulled from remote hosts by a central backup server. The ssh connection works fine, and rdiff-backup --server obviously gets initiated at the host end. However, the whole process freezes after a couple of seconds, consuming 100 % CPU at the remote host, and nothing happens. The process then has to be killed manually. Here's the output from the backup server:

----

address@hidden:~$ rdiff-backup --terminal-verbosity 9 test-backup::/home/jpulakka/test/ testi/
Thu Apr 30 17:24:57 2009  Using rdiff-backup version 1.2.5
Thu Apr 30 17:24:57 2009  Executing ssh -C test-backup rdiff-backup --server
Thu Apr 30 17:24:57 2009  Client sending (0): ConnectionRequest: Globals.get with 1 arguments
Thu Apr 30 17:24:57 2009  Client sending (0): 'version'
Thu Apr 30 17:24:59 2009  Client received (0): '1.2.5'
Thu Apr 30 17:24:59 2009  Registering connection 1
Thu Apr 30 17:24:59 2009  Client sending (0): ConnectionRequest: SetConnections.init_connection_remote with 1 arguments
Thu Apr 30 17:24:59 2009  Client sending (0): 1
Thu Apr 30 17:25:00 2009  Client received (0): None
Thu Apr 30 17:25:00 2009  Client sending (0): ConnectionRequest: log.Log.setverbosity with 1 arguments
Thu Apr 30 17:25:00 2009  Client sending (0): 3
Thu Apr 30 17:25:00 2009  Client received (0): None
Thu Apr 30 17:25:00 2009  Client sending (0): ConnectionRequest: log.Log.setterm_verbosity with 1 arguments
Thu Apr 30 17:25:00 2009  Client sending (0): 9
Thu Apr 30 17:25:10 2009  Server sending (0): None
Thu Apr 30 17:25:00 2009  Client received (0): None
Thu Apr 30 17:25:00 2009  Client sending (0): ConnectionRequest: rpath.make_file_dict with 1 arguments
Thu Apr 30 17:25:00 2009  Client sending (0): '/home/jpulakka/test/'
Thu Apr 30 17:25:10 2009  Server received (0): ConnectionRequest: rpath.make_file_dict with 1 arguments
Thu Apr 30 17:25:10 2009  Server received (0): '/home/jpulakka/test/'
Thu Apr 30 17:25:10 2009  Server sending (0): {'uid': 1000, 'perms': 448, 'type': 'dir', 'ctime': 1241101434, 'devloc': 51744L, 'nlink': 2, 'gid': 1000, 'mtime': 1241101434, 'atime': 1241101457, 'inode': 589872L, 'size': 4096L}
Thu Apr 30 17:25:00 2009  Client received (0): {'size': 4096L, 'uid': 1000, 'perms': 448, 'inode': 589872L, 'devloc': 51744L, 'nlink': 2, 'mtime': 1241101434, 'gid': 1000, 'atime': 1241101457, 'type': 'dir', 'ctime': 1241101434}
Thu Apr 30 17:25:00 2009  Client sending (0): ConnectionRequest: rpath.setdata_local with 1 arguments
Thu Apr 30 17:25:00 2009  Client sending (0): Path: /home/jpulakka/test/
Index: ()
Data: {'size': 4096L, 'uid': 1000, 'perms': 448, 'inode': 589872L, 'devloc': 51744L, 'nlink': 2, 'mtime': 1241101434, 'gid': 1000, 'atime': 1241101457, 'type': 'dir', 'ctime': 1241101434}
Thu Apr 30 17:25:10 2009  Server received (0): ConnectionRequest: rpath.setdata_local with 1 arguments
Thu Apr 30 17:25:10 2009  Server received (0): Path: /home/jpulakka/test/
Index: ()
Data: {'uid': 1000, 'perms': 448, 'type': 'dir', 'ctime': 1241101434, 'devloc': 51744L, 'nlink': 2, 'mtime': 1241101434, 'gid': 1000, 'atime': 1241101457, 'inode': 589872L, 'size': 4096L}
Thu Apr 30 17:25:10 2009  Server sending (0): None
Thu Apr 30 17:25:00 2009  Client received (0): None
Thu Apr 30 17:25:00 2009  Client sending (0): ConnectionRequest: rpath.make_file_dict with 1 arguments
Thu Apr 30 17:25:00 2009  Client sending (0): '/home/jpulakka/test'
Thu Apr 30 17:25:10 2009  Server received (0): ConnectionRequest: rpath.make_file_dict with 1 arguments
Thu Apr 30 17:25:10 2009  Server received (0): '/home/jpulakka/test'
Thu Apr 30 17:25:10 2009  Server sending (0): {'uid': 1000, 'perms': 448, 'type': 'dir', 'ctime': 1241101434, 'devloc': 51744L, 'nlink': 2, 'gid': 1000, 'mtime': 1241101434, 'atime': 1241101457, 'inode': 589872L, 'size': 4096L}
Thu Apr 30 17:25:00 2009  Client received (0): {'size': 4096L, 'uid': 1000, 'perms': 448, 'inode': 589872L, 'devloc': 51744L, 'nlink': 2, 'mtime': 1241101434, 'gid': 1000, 'atime': 1241101457, 'type': 'dir', 'ctime': 1241101434}
Thu Apr 30 17:25:00 2009  Client sending (0): ConnectionRequest: rpath.setdata_local with 1 arguments
Thu Apr 30 17:25:00 2009  Client sending (0): Path: /home/jpulakka/test
Index: ()
Data: {'size': 4096L, 'uid': 1000, 'perms': 448, 'inode': 589872L, 'devloc': 51744L, 'nlink': 2, 'mtime': 1241101434, 'gid': 1000, 'atime': 1241101457, 'type': 'dir', 'ctime': 1241101434}
Thu Apr 30 17:25:11 2009  Server received (0): ConnectionRequest: rpath.setdata_local with 1 arguments
Thu Apr 30 17:25:11 2009  Server received (0): Path: /home/jpulakka/test
Index: ()
Data: {'uid': 1000, 'perms': 448, 'type': 'dir', 'ctime': 1241101434, 'devloc': 51744L, 'nlink': 2, 'mtime': 1241101434, 'gid': 1000, 'atime': 1241101457, 'inode': 589872L, 'size': 4096L}
Thu Apr 30 17:25:01 2009  Client received (0): None
Thu Apr 30 17:25:01 2009  Client sending (0): ConnectionRequest: rpath.make_file_dict with 1 arguments
Thu Apr 30 17:25:01 2009  Client sending (0): '/home/jpulakka/test'
Thu Apr 30 17:25:11 2009  Server sending (0): None
Thu Apr 30 17:25:11 2009  Server received (0): ConnectionRequest: rpath.make_file_dict with 1 arguments
Thu Apr 30 17:25:11 2009  Server received (0): '/home/jpulakka/test'
Thu Apr 30 17:25:11 2009  Server sending (0): {'uid': 1000, 'perms': 448, 'type': 'dir', 'ctime': 1241101434, 'devloc': 51744L, 'nlink': 2, 'gid': 1000, 'mtime': 1241101434, 'atime': 1241101457, 'inode': 589872L, 'size': 4096L}
Thu Apr 30 17:25:01 2009  Client received (0): {'size': 4096L, 'uid': 1000, 'perms': 448, 'inode': 589872L, 'devloc': 51744L, 'nlink': 2, 'mtime': 1241101434, 'gid': 1000, 'atime': 1241101457, 'type': 'dir', 'ctime': 1241101434}
Thu Apr 30 17:25:01 2009  Client sending (0): ConnectionRequest: rpath.setdata_local with 1 arguments
Thu Apr 30 17:25:01 2009  Client sending (0): Path: /home/jpulakka/test
Index: ()
Data: {'size': 4096L, 'uid': 1000, 'perms': 448, 'inode': 589872L, 'devloc': 51744L, 'nlink': 2, 'mtime': 1241101434, 'gid': 1000, 'atime': 1241101457, 'type': 'dir', 'ctime': 1241101434}
Thu Apr 30 17:25:11 2009  Server received (0): ConnectionRequest: rpath.setdata_local with 1 arguments
Thu Apr 30 17:25:11 2009  Server received (0): Path: /home/jpulakka/test
Index: ()
Data: {'uid': 1000, 'perms': 448, 'type': 'dir', 'ctime': 1241101434, 'devloc': 51744L, 'nlink': 2, 'mtime': 1241101434, 'gid': 1000, 'atime': 1241101457, 'inode': 589872L, 'size': 4096L}
Thu Apr 30 17:25:11 2009  Server sending (0): None
Thu Apr 30 17:25:01 2009  Client received (0): None
Thu Apr 30 17:25:01 2009  Client sending (0): ConnectionRequest: os.getuid with 0 arguments
Thu Apr 30 17:25:11 2009  Server received (0): ConnectionRequest: os.getuid with 0 arguments
Thu Apr 30 17:25:11 2009  Server sending (0): 1000
Thu Apr 30 17:25:01 2009  Client received (0): 1000
Thu Apr 30 17:25:01 2009  Client sending (0): ConnectionRequest: os.listdir with 1 arguments
Thu Apr 30 17:25:01 2009  Client sending (0): '/home/jpulakka/test'
Thu Apr 30 17:25:11 2009  Server received (0): ConnectionRequest: os.listdir with 1 arguments
Thu Apr 30 17:25:11 2009  Server received (0): '/home/jpulakka/test'
Thu Apr 30 17:25:11 2009  Server sending (0): ['test.txt']
Thu Apr 30 17:25:01 2009  Client received (0): ['test.txt']
Thu Apr 30 17:25:01 2009  Client sending (0): ConnectionRequest: Globals.get with 1 arguments
Thu Apr 30 17:25:01 2009  Client sending (0): 'restrict_path'
Thu Apr 30 17:25:11 2009  Server received (0): ConnectionRequest: Globals.get with 1 arguments
Thu Apr 30 17:25:11 2009  Server received (0): 'restrict_path'
Thu Apr 30 17:25:11 2009  Server sending (0): '/home/jpulakka/test'
Thu Apr 30 17:25:01 2009  Client received (0): '/home/jpulakka/test'
Thu Apr 30 17:25:01 2009  Client sending (0): ConnectionRequest: Time.setcurtime_local with 1 arguments
Thu Apr 30 17:25:01 2009  Client sending (0): 1241101501
Thu Apr 30 17:25:11 2009  Server received (0): ConnectionRequest: Time.setcurtime_local with 1 arguments
Thu Apr 30 17:25:11 2009  Server received (0): 1241101501
Thu Apr 30 17:25:11 2009  Server sending (0): None
Thu Apr 30 17:25:01 2009  Client received (0): None
Thu Apr 30 17:25:01 2009  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Thu Apr 30 17:25:01 2009  Client sending (0): 'client_conn'
Thu Apr 30 17:25:01 2009  Client sending (0): LocalConnection
Thu Apr 30 17:25:12 2009  Server received (0): ConnectionRequest: Globals.set with 2 arguments
Thu Apr 30 17:25:12 2009  Server received (0): 'client_conn'
Thu Apr 30 17:25:12 2009  Server received (0): PipeConnection 0
Thu Apr 30 17:25:12 2009  Server sending (0): None
Thu Apr 30 17:25:01 2009  Client received (0): None
Thu Apr 30 17:25:02 2009  Client sending (0): ConnectionRequest: Globals.postset_regexp_local with 3 arguments
Thu Apr 30 17:25:02 2009  Client sending (0): 'no_compression_regexp'
Thu Apr 30 17:25:02 2009  Client sending (0): '(?i).*\\.(gz|z|bz|bz2|tgz|zip|rpm|deb|jpg|jpeg|gif|png|jp2|mp3|ogg|avi|wmv|mpeg|mpg|rm|mov|flac|shn|pgp|gpg|rz|lzh|zoo|lharc|rar|arj|asc)$'
Thu Apr 30 17:25:02 2009  Client sending (0): None
Thu Apr 30 17:25:12 2009  Server received (0): ConnectionRequest: Globals.postset_regexp_local with 3 arguments
Thu Apr 30 17:25:12 2009  Server received (0): 'no_compression_regexp'

---- (hangs here probably forever) ----

Some more info:

  * All parties are running Debian 5.0 and the rdiff-backup version is 1.2.5.

  * Local rdiff-backup within the hosts as well as within the server works fine.

  * The ssh connection from backup server to remote host works fine.

  * The rdiff-backups obviously talk to each other over the ssh for a while, but then the remote side freezes.

  * Also the test command "rdiff-backup --test-server hostname.net::/something" causes similar freezing.

  * The backup server is behind a firewall, but how could this be a problem, since the ssh connection works anyway?

  * The backup server is a Qnap TS-109 II. Could the unusual armel architecture cause problems? Though, it's the remote end that freezes, not the Qnap. The remote end is a standard x86 machine.

Any ideas what's happening here, and what to do? Thanks!

Best Regards,

Joonas Pulakka