6

I just installed BackupPC in a Debian box to use it as backup server. As you know, this software makes use, among others, of rsync. When using the rsync option, it fails.

  • Server: Debian Jessie. BackupPC 3.3.1 built from source, executed by user "backup-user". Rsync 3.1.2 built from source with the default options.

  • Client: Debian Jessie. Rsync 3.1.2 built from source with the default options.

After the fail, the rsync command used can be found in BackupPC's logs. Trying the command in a shell, logged as the BackupPC user, I run into this "protocol version mismatch -- is your shell clean?" error. The command is:

/usr/bin/ssh -q -x -l backup-user 192.168.10.20 /usr/local/bin/rsync
--server --sender --numeric-ids --perms --owner --group -D --links
--hard-links --times --block-size=2048 --recursive --ignore-times .
/home/backup-user/test

Adding some verbose to the rsync command sent to the client, it says (Notice the remote protocol version):

FILE_STRUCT_LEN=24, EXTRA_LEN=4

(Server) Protocol versions: remote=168430090, negotiated=31
protocol version mismatch -- is your shell clean? 
(see the rsync man page for an explanation) 
[sender] _exit_cleanup(code=2, file=compat.c, line=178): entered rsync error: protocol incompatibility (code 2) at compat.c(178) [sender=3.1.2] 
[sender] _exit_cleanup(code=2, file=compat.c, line=178): about to call exit(2)

Looks like the 168430090 in the remote protocol is the decimal representation for 0xA0A0A0A, but no clue of what is writing it. I searched for similar errors in the list, but all I found are due to things I already checked.

In the client, using the debug script I found in rsync site:

/usr/bin/ssh -q -x -l backup-user 192.168.206.103
/home/backup-user/rsync-debug --server --sender --numeric-ids --perms
--owner --group -D --links --hard-links --times --block-size=2048
--recursive --ignore-times . /home/backup-user/test

rsync-2991.out content:

2997  00:58:30 brk(0)                   = 0xefb000
2997  00:58:30 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file
or directory)
2997  00:58:30 mmap(NULL, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fefc7341000
2997  00:58:30 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file
or directory)
2997  00:58:30 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
2997  00:58:30 fstat(3, {st_mode=S_IFREG|0644, st_size=33837, ...}) = 0
2997  00:58:30 mmap(NULL, 33837, PROT_READ, MAP_PRIVATE, 3, 0) =
0x7fefc7338000
2997  00:58:30 close(3)                 = 0
2997  00:58:30 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file
or directory)
2997  00:58:30 open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC)
= 3
2997  00:58:30 read(3,
"\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\34\2\0\0\0\0\0@
\0\0\0\0\0\0\0\300T\32\0\0\0\0\0\0\0\0\0@\0008\0\n\0@
\0D\0C\0\6\0\0\0\5\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0000\2\0\0\0\0\0\0000\2\0\0\0\0\0\0\10\0\0\0\0\0\0\0\3\0\0\0\4\0\0\0000\303\26\0\0\0\0\0000\303\26\0\0\0\0\0000\303\26\0\0\0\0\0\34\0\0\0\0\0\0\0\34\0\0\0\0\0\0\0\20\0\0\0\0\0\0\0\1\0\0\0\5\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\364\352\31\0\0\0\0\0\364\352\31\0\0\0\0\0\0\0
\0\0\0\0\0\1\0\0\0\6\0\0\0@\367\31\0\0\0\0\0@\3679\0\0\0\0\0@\3679\0\0\0\0\0\370O\0\0\0\0\0\0\340\222\0\0\0\0\0\0\0\0
\0\0\0\0\0\2\0\0\0\6\0\0\0\240 \32\0\0\0\0\0\240 :\0\0\0\0\0\240
:\0\0\0\0\0\340\1\0\0\0\0\0\0\340\1\0\0\0\0\0\0\10\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0p\2\0\0\0\0\0\0p\2\0\0\0\0\0\0p\2\0\0\0\0\0\0D\0\0\0\0\0\0\0D\0\0\0\0\0\0\0\4\0\0\0\0\0\0\0\7\0\0\0\4\0\0\0@
\367\31\0\0\0\0\0@\3679\0\0\0\0\0@
\3679\0\0\0\0\0\20\0\0\0\0\0\0\0\200\0\0\0\0\0\0\0\10\0\0\0\0\0\0\0P\345td\4\0\0\0L\303\26\0\0\0\0\0L\303\26\0\0\0\0\0L\303\26\0\0\0\0\0$j\0\0\0\0\0\0$j\0\0\0\0\0\0\4\0\0\0\0\0\0\0Q\345td\6\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\20\0\0\0\0\0\0\0R\345td\4\0\0\0@
\367\31\0\0\0\0\0@\3679\0\0\0\0\0@
\3679\0\0\0\0\0\3008\0\0\0\0\0\0\3008\0\0\0\0\0\0\1\0\0\0\0\0\0\0\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\371?y\343\344|\332K|C=\2\323!\316@\34J\205\1\4\0\0\0\20\0\0\0\1\0\0\0GNU\0\0\0\0\0\2\0\0\0\6\0\0\0
\0\0\0\0\0\0\0\363\3\0\0\n\0\0\0\0\1\0\0\16\0\0\0\0000\20D\240
\2\1\210\3\346\220\305E\214\0\300\0\10\0\5\200\0`\300\200\0\r\212\f\0\4\20\0\210D2\10.@\210P4,
\16\"H&\204\300\214\4\10\0\2\2\16\241\254\32\4f\300\0\3002\0\300\0P\1
\201\10\204\v  ($\0\4 P\0\20X\200\312DB(\0\6\200\20\30B\0
@\200\0\tP\0Q\212@\20\0\0\0\0\10\0\0\21\20",
832) = 832
2997  00:58:30 fstat(3, {st_mode=S_IFREG|0755, st_size=1729984, ...}) = 0
2997  00:58:30 mmap(NULL, 3836448, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fefc6d7a000
2997  00:58:30 mprotect(0x7fefc6f19000, 2097152, PROT_NONE) = 0
2997  00:58:30 mmap(0x7fefc7119000, 24576, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x19f000) = 0x7fefc7119000
2997  00:58:30 mmap(0x7fefc711f000, 14880, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fefc711f000
2997  00:58:30 close(3)                 = 0
2997  00:58:30 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fefc7337000
2997  00:58:30 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fefc7336000
2997  00:58:30 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fefc7335000
2997  00:58:30 arch_prctl(ARCH_SET_FS, 0x7fefc7336700) = 0
2997  00:58:30 mprotect(0x7fefc7119000, 16384, PROT_READ) = 0
2997  00:58:30 mprotect(0x7fefc7343000, 4096, PROT_READ) = 0
2997  00:58:30 munmap(0x7fefc7338000, 33837) = 0
2997  00:58:30 rt_sigaction(SIGUSR1, {0x41c690, [],
SA_RESTORER|SA_NOCLDSTOP, 0x7fefc6daf180}, NULL, 8) = 0
2997  00:58:30 rt_sigaction(SIGUSR2, {0x41d220, [],
SA_RESTORER|SA_NOCLDSTOP, 0x7fefc6daf180}, NULL, 8) = 0
2997  00:58:30 rt_sigaction(SIGCHLD, {0x41c630, [],
SA_RESTORER|SA_NOCLDSTOP, 0x7fefc6daf180}, NULL, 8) = 0
2997  00:58:30 geteuid()                = 1001
2997  00:58:30 getegid()                = 1001
2997  00:58:30 umask(0)                 = 022
2997  00:58:30 umask(022)               = 0
2997  00:58:30 brk(0)                   = 0xefb000
2997  00:58:30 brk(0xf1c000)            = 0xf1c000
2997  00:58:30 open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) =
3
2997  00:58:30 fstat(3, {st_mode=S_IFREG|0644, st_size=1607632, ...}) = 0
2997  00:58:30 mmap(NULL, 1607632, PROT_READ, MAP_PRIVATE, 3, 0) =
0x7fefc71ac000
2997  00:58:30 close(3)                 = 0
2997  00:58:30 open("/etc/popt", O_RDONLY) = -1 ENOENT (No such file or
directory)
2997  00:58:30 open("/home/backup-user/.popt", O_RDONLY) = -1 ENOENT (No
such file or directory)
2997  00:58:30 rt_sigaction(SIGINT, {0x40cca0, [],
SA_RESTORER|SA_NOCLDSTOP, 0x7fefc6daf180}, NULL, 8) = 0
2997  00:58:30 rt_sigaction(SIGHUP, {0x40cca0, [],
SA_RESTORER|SA_NOCLDSTOP, 0x7fefc6daf180}, NULL, 8) = 0
2997  00:58:30 rt_sigaction(SIGTERM, {0x40cca0, [],
SA_RESTORER|SA_NOCLDSTOP, 0x7fefc6daf180}, NULL, 8) = 0
2997  00:58:30 rt_sigprocmask(SIG_UNBLOCK, [HUP INT USR1 USR2 TERM CHLD],
NULL, 8) = 0
2997  00:58:30 rt_sigaction(SIGPIPE, {SIG_IGN, [],
SA_RESTORER|SA_NOCLDSTOP, 0x7fefc6daf180}, NULL, 8) = 0
2997  00:58:30 rt_sigaction(SIGXFSZ, {SIG_IGN, [],
SA_RESTORER|SA_NOCLDSTOP, 0x7fefc6daf180}, NULL, 8) = 0
2997  00:58:30 getcwd("/home/backup-user", 4095) = 13
2997  00:58:30 fcntl(0, F_GETFL)        = 0 (flags O_RDONLY)
2997  00:58:30 fcntl(0, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
2997  00:58:30 fcntl(1, F_GETFL)        = 0x1 (flags O_WRONLY)
2997  00:58:30 fcntl(1, F_SETFL, O_WRONLY|O_NONBLOCK) = 0
2997  00:58:30 fcntl(0, F_GETFL)        = 0x800 (flags O_RDONLY|O_NONBLOCK)
2997  00:58:30 fcntl(1, F_GETFL)        = 0x801 (flags O_WRONLY|O_NONBLOCK)
2997  00:58:30 write(1, "\37\0\0\0", 4) = 4

Here is where the script stops. I have to hit return several times in the server. Then it continues:

2997  00:58:30 select(1, [0], NULL, [0], {60, 0}) = 1 (in [0], left {55,
558348})
2997  00:58:34 read(0, "\n", 4)         = 1
2997  00:58:34 select(1, [0], NULL, [0], {60, 0}) = 1 (in [0], left {59,
793510})
2997  00:58:35 read(0, "\n", 3)         = 1
2997  00:58:35 select(1, [0], NULL, [0], {60, 0}) = 1 (in [0], left {59,
975726})
2997  00:58:35 read(0, "\n", 2)         = 1
2997  00:58:35 select(1, [0], NULL, [0], {60, 0}) = 1 (in [0], left {59,
968630})
2997  00:58:35 read(0, "\n", 1)         = 1
2997  00:58:35 write(2, "protocol version mismatch -- is your shell
clean?", 49) = 49
2997  00:58:35 write(2, "\n", 1)        = 1
2997  00:58:35 write(2, "(see the rsync man page for an explanation)", 43)
= 43
2997  00:58:35 write(2, "\n", 1)        = 1
2997  00:58:35 rt_sigaction(SIGUSR1, {SIG_IGN, [], SA_RESTORER,
0x7fefc6daf180}, NULL, 8) = 0
2997  00:58:35 rt_sigaction(SIGUSR2, {SIG_IGN, [], SA_RESTORER,
0x7fefc6daf180}, NULL, 8) = 0
2997  00:58:35 write(2, "rsync error: protocol incompatibility (code 2) at
compat.c(178) [sender=3.1.2]", 78) = 78
2997  00:58:35 write(2, "\n", 1)        = 1
2997  00:58:35 nanosleep({0, 100000000}, NULL) = 0
2997  00:58:35 exit_group(2)            = ?
2997  00:58:35     exited with 2

After some hours of research, I can't figure out what is wrong. I removed and checked everything that could write any text (ssh welcome message, .bashrc echos, passphrase and even the system prompt) and rsync is still unable to gather the files. ssh connection is made passwordless.

I also made the true > testfile test, with no problems:

backup-user@backup:~$ /usr/bin/ssh -q -x -l backup-user 192.168.10.20 true
> testfile
backup-user@backup:~$ ll testfile
-rw-r--r-- 1 backup-user backup-user 0 feb 16 02:26 testfile

The lines:

2997  00:58:30 open("/etc/popt", O_RDONLY) = -1 ENOENT (No such file or
directory)
2997  00:58:30 open("/home/backup-user/.popt", O_RDONLY) = -1 ENOENT (No
such file or directory)

Looks suspicious to me, but also checked the libraries involved.

Options --server and --sender are added by BackupPC, but are not supposed to be needed in a regular use, as the rsync documentation states.

Did somebody find the same problem? I know usually this is caused by something writting data on the terminal, but with the debug script I can see that is rsync the proccess writing the data.

Hope this information is clear enough. Thanks for your time.

  • Did you try a simple rsync from one server to the other ? Do you get the same issue ? or is it only with BackupPC ? – Pierre-Alain TORET Apr 19 '16 at 14:52
  • Yes, I tried a simple rsync command and it works flawlessly. It only happens with that specific command used by BackupPC. – zisk0 Jun 23 '16 at 15:00
2

BackupPC is likely using the Perl File::Rsync module to connect to the client. I would suspect a bug or compatibility issue in this module.

There is a BackupPC package for Debian. It should list all the appropriate dependencies. The source package may list dependencies.

I generally prefer the packed modules, as they are more likely to be patched on a regular basis. If you do want to build from source, consider downloading the build package and replacing the source tar with your own.

  • Thanks Bill! Yes, I agree with your suspicion. I tried both (packed for Debian and source) with same results. – zisk0 Dec 4 '16 at 18:55

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.