BackupPC using rsync fails with "protocol version mismatch -- is your shell clean?"

Kevin Korb kmk at sanitarium.net
Tue Feb 16 01:24:38 UTC 2016 

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Did you do the clean shell test?
/usr/bin/ssh -q -x -l backup-user 192.168.10.20 true > testfile
After running that, testfile should be 0 bytes.

On 02/15/2016 08:13 PM, Francisco López wrote:
> Hello,
> 
> 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:
> 
> FILE_STRUCT_LEN=24, EXTRA_LEN=4
> 
> (Server) Protocol versions: remote=168430090, negotiated=31 
> ########################### Notice the remote protocol version 
> 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)
> 
> In the client, using the debug script I found in this 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\3
64\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 ######## 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.
> 
> 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.
> 
> 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.
> 
> Hope this information is clear enough. Thanks for your time.
> 
> 

- -- 
~*-,._.,-*~'`^`'~*-,._.,-*~'`^`'~*-,._.,-*~'`^`'~*-,._.,-*~'`^`'~*-,._.,
	Kevin Korb			Phone:    (407) 252-6853
	Systems Administrator		Internet:
	FutureQuest, Inc.		Kevin at FutureQuest.net  (work)
	Orlando, Florida		kmk at sanitarium.net (personal)
	Web page:			http://www.sanitarium.net/
	PGP public key available on web site.
~*-,._.,-*~'`^`'~*-,._.,-*~'`^`'~*-,._.,-*~'`^`'~*-,._.,-*~'`^`'~*-,._.,
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2

iEYEARECAAYFAlbCelYACgkQVKC1jlbQAQdKTgCgy3hO4GMZ4/OiC9bDhICSYmDu
AfAAn32LO3+qj3/p6l8Tzw8G77awYV8q
=hjjV
-----END PGP SIGNATURE-----

More information about the rsync mailing list