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

Francisco López
2016-02-16T01:31:42Z

Hello Kevin,

Thank you for your answer. Yes, sorry, I forgot to mention that test. I did
it. The result is:

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

--

Francisco López
flopez @ hispasec.com
Hispasec Sistemas
+34 952 020 494
Málaga (Spain)

--


2016-02-16 2:24 GMT+01:00 Kevin Korb <kmk at sanitarium.net>:

> -----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-----
>
> --
> Please use reply-all for most replies to avoid omitting the mailing list.
> To unsubscribe or change options:
> https://lists.samba.org/mailman/listinfo/rsync
> Before posting, read: http://www.catb.org/~esr/faqs/smart-questions.html
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.samba.org/pipermail/rsync/attachments/20160216/46aeb636/attachment.html>