Francisco López
2016-Feb-16 01:13 UTC
BackupPC using rsync fails with "protocol version mismatch -- is your shell clean?"
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\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 ########
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.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.samba.org/pipermail/rsync/attachments/20160216/1b62bbf3/attachment.html>
Kevin Korb
2016-Feb-16 01:24 UTC
BackupPC using rsync fails with "protocol version mismatch -- is your shell clean?"
-----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-----
Francisco López
2016-Feb-16 01:31 UTC
BackupPC using rsync fails with "protocol version mismatch -- is your shell clean?"
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> testfilebackup-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>
Apparently Analagous Threads
- BackupPC using rsync fails with "protocol version mismatch -- is your shell clean?"
- geo-replication command rsync returned with 3
- geo-replication command rsync returned with 3
- 2.6.2 rsync --daemon is not working for me
- Reproducible SIGSEGV when Dovecot 2.3 compiled against glibc-2.28