rsync: connection unexpectedly closed

[Kip Warner]

On Thu, 2016-10-13 at 20:08 -0400, Kevin Korb wrote:
> I don't remember whether or not you said you were running rsync over
> ssh but if you are you can also debug the ssh layer.  You can even do
> it at both ends....
> 
> On the server run a debugging sshd on an alternate port with:
> /usr/sbin/sshd -dDp222
> (note that this will only accept 1 connection, debug to the terminal,
> then exit) then on the client use rsync -e "ssh -vp222" to go verbose
> and use the debugging port.

Hey Kevin,

I managed to get a chance to try your suggestion. I noticed something
very interesting. On the server side, there's actually two processes of
rsync that appear to be spawned by the client's connection. 

Running the ssh daemon on the server side, I notice that long after the
server dies like so...

    ...
    debug1: session_by_channel: session 0 channel 0
    debug1: session_input_channel_req: session 0 req exec
    Read error from remote host <snip>: Connection reset by peer
    debug1: do_cleanup
    debug1: do_cleanup
    debug1: PAM: cleanup
    debug1: PAM: closing session
    Sessions still open, not unmounting
    debug1: PAM: deleting credentials

...and the client rsync dies...

    match at 32949010432 last_match=32949010432 j=251381 len=131072 n=0
    match at 32949141504 last_match=32949141504 j=251382 len=131072 n=0
             32.95G  96%   74.13MB/s    0:00:14  packet_write_wait: Connection to <snip> port 22223: Broken pipe

    rsync: [sender] write error: Broken pipe (32)
    rsync error: unexplained error (code 255) at io.c(820) [sender=3.1.1]
    [sender] _exit_cleanup(code=10, file=io.c, line=820): about to call exit(255)

...one of the server side rsync processes according to strace is still
alive...

    write(1, "h\340\0\7\310\376\\\233\227\241\236\255VC\31\351\323X\206\314F$\337\0321\202\374\"\320(d\271"..., 57452) = 57452
    select(4, [3], [], [3], {60, 0})        = 0 (Timeout)
    (last line repeats a couple hundred times)

    ...and apparently the second rsync server side process is actually
    still performing reads and writes more than an hour after the
    connection died...

    ...
    read(1, "\337\363\356\1^\26L\316\17\31izD\254\27\346\267\266H\343\223\v\357\252d'h\351\371\0ny"..., 262144) = 262144
    write(3, "\337\363\356\1^\26L\316\17\31izD\254\27\346\267\266H\343\223\v\357\252d'h\351\371\0ny"..., 262144) = 262144
    ...

    This makes me wonder if this has something to do with memory buffers
    for file i/o being exhausted on the server and this server side
    activity long after the connection died is an effort to flush a file
    buffer to disk. The file this always breaks on is 30+GB, but the server
    hardware is a small embedded system.

    -- 
    Kip Warner -- Senior Software Engineer
OpenPGP encrypted/signed mail preferred
http://www.thevertigo.com
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 163 bytes
Desc: This is a digitally signed message part
URL: <http://lists.samba.org/pipermail/rsync/attachments/20161015/3435fbd7/signature.sig>