rsync icon indicating copy to clipboard operation
rsync copied to clipboard
verified publisher icon WayneD

Sender waits for IO timeout instead of exiting

Open benrubson opened this issue 5 years ago • 2 comments

Hi,

I found a bug / edge case where sender waits for IO timeout instead of exiting, whereas receiver has closed the transfer. Below are some test cases.

Source tree :

-rw------- 1 root root 1610612736 May 31 10:17 anotherfile.iso
-rw------- 1 root root 2147483648 May 31 10:16 bf2

Destination tree :

-rw------- 1 root root 2147483648 May 31 10:16 bf1

Destination disk space remaining : around 200MB, much less than anotherfile.iso size. Options used for debug below : -M--debug=FUZZY2,FLIST4 --debug=FUZZY2,FLIST4.

rsync -e "ssh ..." --progress -a /tmp/source dest: :

FILE_STRUCT_LEN=24, EXTRA_LEN=4
FILE_STRUCT_LEN=24, EXTRA_LEN=4
sending incremental file list
[sender] make_file(source,*,0)
[sender] flist start=1, used=1, low=0, high=0
[sender] i=1 /tmp source/ mode=040700 len=4,096 uid=0 gid=0 flags=1005
send_file_list done
[sender] make_file(source/anotherfile.iso,*,2)
[sender] make_file(source/bf2,*,2)
[sender] flist start=3, used=2, low=0, high=1
[sender] i=3 /tmp source/anotherfile.iso mode=0100600 len=1,610,612,736 uid=0 gid=0 flags=1000
[sender] i=4 /tmp source/bf2 mode=0100600 len=2,147,483,648 uid=0 gid=0 flags=1000
[sender] flist_eof=1
file list sent
recv_file_name(source)
received 1 names
[Receiver] flist start=1, used=1, low=0, high=0
[Receiver] i=1 1 source/ mode=040700 len=4,096 gid=(0) flags=1405
recv_file_list done
[Receiver] receiving flist for dir 0
recv_file_name(source/anotherfile.iso)
recv_file_name(source/bf2)
received 2 names
[Receiver] flist start=3, used=2, low=0, high=1
[Receiver] i=3 2 source/anotherfile.iso mode=0100600 len=1,610,612,736 gid=(0) flags=1400
[Receiver] i=4 2 source/bf2 mode=0100600 len=2,147,483,648 gid=(0) flags=1400
recv_file_list done
delta-transmission enabled
[receiver] flist_eof=1
[generator] flist_eof=1
source/
source/anotherfile.iso
  1,610,612,736 100%   19.90MB/s    0:01:17 (xfr#1, to-chk=1/3)
source/bf2
  2,147,483,648 100%   19.96MB/s    0:01:42 (xfr#2, to-chk=0/3)
rsync: write failed on "anotherfile.iso": Disc quota exceeded (69)
rsync error: error in file IO (code 11) at receiver.c(378) [receiver=3.2.0dev]

Above we see that both files are fully sent, even if there's not enough space for the first one.

rsync -e "ssh ..." --progress -a -M--msgs2stderr /tmp/source dest: :

FILE_STRUCT_LEN=24, EXTRA_LEN=4
FILE_STRUCT_LEN=24, EXTRA_LEN=4
sending incremental file list
[sender] make_file(source,*,0)
[sender] flist start=1, used=1, low=0, high=0
[sender] i=1 /tmp source/ mode=040700 len=4,096 uid=0 gid=0 flags=1005
send_file_list done
[sender] make_file(source/anotherfile.iso,*,2)
[sender] make_file(source/bf2,*,2)
[sender] flist start=3, used=2, low=0, high=1
[sender] i=3 /tmp source/anotherfile.iso mode=0100600 len=1,610,612,736 uid=0 gid=0 flags=1000
[sender] i=4 /tmp source/bf2 mode=0100600 len=2,147,483,648 uid=0 gid=0 flags=1000
[sender] flist_eof=1
file list sent
recv_file_name(source)
received 1 names
[Receiver] flist start=1, used=1, low=0, high=0
[Receiver] i=1 1 source/ mode=040700 len=4,096 gid=(0) flags=1405
recv_file_list done
[Receiver] receiving flist for dir 0
recv_file_name(source/anotherfile.iso)
recv_file_name(source/bf2)
received 2 names
[Receiver] flist start=3, used=2, low=0, high=1
[Receiver] i=3 2 source/anotherfile.iso mode=0100600 len=1,610,612,736 gid=(0) flags=1400
[Receiver] i=4 2 source/bf2 mode=0100600 len=2,147,483,648 gid=(0) flags=1400
recv_file_list done
delta-transmission enabled
[receiver] flist_eof=1
[generator] flist_eof=1
source/
source/anotherfile.iso
    253,526,016  15%   20.05MB/s    0:01:06
rsync: write failed on "anotherfile.iso": Disc quota exceeded (69)
rsync error: error in file IO (code 11) at receiver.c(378) [receiver=3.2.0dev]
rsync: [sender] write error: Broken pipe (32)

-M--msgs2stderr really helps here, perfect (thank you #3 !).

rsync -e "ssh ..." --progress -a -M--msgs2stderr -y --timeout=600 /tmp/source dest: :

FILE_STRUCT_LEN=24, EXTRA_LEN=4
FILE_STRUCT_LEN=24, EXTRA_LEN=4
sending incremental file list
[sender] make_file(source,*,0)
[sender] flist start=1, used=1, low=0, high=0
[sender] i=1 /tmp source/ mode=040700 len=4,096 uid=0 gid=0 flags=1005
send_file_list done
[sender] make_file(source/anotherfile.iso,*,2)
[sender] make_file(source/bf2,*,2)
[sender] flist start=3, used=2, low=0, high=1
[sender] i=3 /tmp source/anotherfile.iso mode=0100600 len=1,610,612,736 uid=0 gid=0 flags=1000
[sender] i=4 /tmp source/bf2 mode=0100600 len=2,147,483,648 uid=0 gid=0 flags=1000
[sender] flist_eof=1
file list sent
recv_file_name(source)
received 1 names
[Receiver] flist start=1, used=1, low=0, high=0
[Receiver] i=1 1 source/ mode=040700 len=4,096 gid=(0) flags=1405
recv_file_list done
[Receiver] receiving flist for dir 0
recv_file_name(source/anotherfile.iso)
recv_file_name(source/bf2)
received 2 names
[Receiver] flist start=3, used=2, low=0, high=1
[Receiver] i=3 2 source/anotherfile.iso mode=0100600 len=1,610,612,736 gid=(0) flags=1400
[Receiver] i=4 2 source/bf2 mode=0100600 len=2,147,483,648 gid=(0) flags=1400
recv_file_list done
delta-transmission enabled
[receiver] flist_eof=1
[generator] make_file(source/bf1,*,1)
[generator] flist start=0, used=1, low=0, high=0
[generator] i=0 0 source/bf1 mode=0100600 len=2,147,483,648 gid=1025 flags=1001
fuzzy distance for source/bf1 = 54.04428
fuzzy size/modtime match for source/bf1
fuzzy basis selected for source/bf2: source/bf1
source/
source/anotherfile.iso
     84,475,904   5%   20.11MB/s    0:01:14
[generator] flist_eof=1
    253,132,800  15%   20.03MB/s    0:01:06
rsync: write failed on "anotherfile.iso": Disc quota exceeded (69)
rsync error: error in file IO (code 11) at receiver.c(378) [receiver=3.2.0dev]
[sender] io timeout after 600 seconds -- exiting
rsync error: timeout in data send/receive (code 30) at io.c(195) [sender=3.2.0dev]

Here we are. What is strange in the above test case is that when a fuzzy basis is selected, even if it's for the second file, the transfer will not abort while sending the first file (as in the second test case), but will hang until IO timeout is reached (or indefinitely if no timeout is set). As then if socket was not closed by the receiver 😕

Thank you very much for your support :+1:

Ben

benrubson avatar Jun 01 '20 13:06 benrubson

(https://github.com/WayneD/rsync/commit/01b9bbb0f94e4ddd4b1e3ad678b220ca09bc0ad0 which solves a more or less "similar" issue does not help here)

benrubson avatar Jun 15 '20 20:06 benrubson