rsync Failure

[Matt McCutchen]

On Tue, 2008-12-09 at 14:15 -0500, Shawn Geraghty wrote:
> I ran the debug-script on the remote host.

> Here is the output:
> 
> strce generated via the rsync-debug script on the machine being backed  
> up:

> select(2, NULL, [1], NULL, {60, 0})     = 1 (out [1], left {60, 0})
> write(1, "\374\17\0\0072\255m\330/f\32\267\330\2546#,\305\271\223"...,  
> 4096) = 4096
> select(2, NULL, [1], NULL, {60, 0})     = 0 (Timeout)
> select(2, NULL, [1], NULL, {60, 0})     = 0 (Timeout)
> [...]

> strace from [server performing backup]:
> 
> 7362  <... write resumed> )             = 8192
> 7386  <... read resumed> "\26\337\346\371\351\313\21\16\26\300gfJJ 
> \22\253\231\270\326<\210\347\351\303\315Z~\3604\243\227\311"..., 4092)  
> = 4092
> 7362  select(8, [4], [], NULL, NULL <unfinished ...>
> 7386  select(7, [6], [], NULL, {60, 0}) = 1 (in [6], left {60, 0})
> 7386  read(6, "\374\17\0\7", 4)         = 4
> 7386  select(7, [6], [], NULL, {60, 0}) = 1 (in [6], left {60, 0})
> 7386  read(6, "\360\313\23\261\"n\371Q\354\347\30z@\227\262\372E 
> \35\342b\335\0r\325\301SM\374}\233\367g"..., 4092) = 4092
> 7386  select(7, [6], [], NULL, {60, 0}) = 1 (in [6], left {60, 0})
> 7386  read(6, "\374\17\0\7", 4)         = 4
> 7386  select(7, [6], [], NULL, {60, 0}) = 1 (in [6], left {60, 0})
> 7386  read(6, "\241\4Q\223\232\"\377\r\312!\244vx\16\340\270Z 
> \37\377\37h\374\373\271\177\fb\330k\'{\322"..., 4092) = 4092
> 7386  select(7, [6], [], NULL, {60, 0}) = 1 (in [6], left {60, 0})
> 7386  read(6, "\374\17\0\7", 4)         = 4
> 7386  select(7, [6], [], NULL, {60, 0}) = 1 (in [6], left {60, 0})
> 7386  read(6, "\10fs\322\203f\232\246rF\320\204]G 
> \2\320\26\266\256]\202m\351dP\345\2128%\336\276\223"..., 4092) = 4092
> 7386  select(7, [6], [], NULL, {60, 0}) = 1 (in [6], left {60, 0})
> 7386  read(6, "\374\17\0\7", 4)         = 4
> 7386  select(7, [6], [], NULL, {60, 0}) = 1 (in [6], left {60, 0})
> 7386  read(6, "\314~;\355`\224\264}\204\366\330\341Xr!\333)\346N\r 
> \274\275\346y\270\234\262\25\363X\352^"..., 4092) = 4092
> 7386  select(7, [6], [], NULL, {60, 0} <unfinished ...>
> 7361  <... select resumed> )            = 0 (Timeout)
> 7361  select(6, [4], [5], [5], {60, 0} <unfinished ...>
> 7386  <... select resumed> )            = 0 (Timeout)
> 7386  select(7, [6], [], NULL, {60, 0} <unfinished ...>
> 7361  <... select resumed> )            = 0 (Timeout)
> 7361  select(6, [4], [5], [5], {60, 0} <unfinished ...>
> 7386  <... select resumed> )            = 0 (Timeout)

Looking at the output, the sender (first strace) has written a bunch of
file data to the network and is waiting for space in the outgoing buffer
so it can write more, while the receiver (process 7386 in second strace)
is trying to read data from the network and isn't getting any.  This
type of hang can't be an rsync bug; something between the two rsyncs,
such as the ssh tunnel you mentioned or the network itself, is failing
to deliver the data.

Unfortunately, I don't have any great ideas about how to debug this.  I
can only suggest running the backup using a single hop of ssh or one of
the first two methods on http://rsync.samba.org/firewall.html (if I
understand correctly, you are currently using the third).  If none of
these are possible, I might be able to suggest something else if you
tell me a bit more about your network arrangement.

-- 
Matt