Bug 26605

Summary: "rsync a-DVD.iso ./" fails in the middle (at about 1.8G)
Product: Branch 5.1 Reporter: Ivan Zakharyaschev <imz>
Component: rsyncAssignee: Michael Shigorin <mike>
Status: CLOSED WORKSFORME QA Contact: QA 5.1 <qa-5.1>
Severity: normal    
Priority: P3 CC: billmartinnn, mike
Version: unspecified   
Hardware: all   
OS: Linux   
Bug Depends on:    
Bug Blocks: 26604    

Description Ivan Zakharyaschev 2011-11-22 22:24:50 MSK
rsync-3.0.8-alt0.M51.1

+++ This bug was initially created as a clone of Bug #26604 +++

rsync gets interrupted in the middle of the transfer of a DVD image. (I'm continuing a previous partial transfer.) This has repeated many times, so there is no real progress further than about 1.8G of the file.

$ rsync -avz -P rsync.altlinux.org::beta/p6/simply/*rc2*i586* ./ -vv --stats --inplace
opening tcp connection to rsync.altlinux.org port 873
sending daemon args: --server --sender -vvvlogDtprze.iLsf --inplace . "beta/p6/simply/*rc2*i586*" 
Welcome to ALT Linux Team public rsync archive!

receiving incremental file list
recv_file_name(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso)
received 1 names
recv_file_list done
get_local_name count=1 ./
recv_files(1) starting
generator starting pid=15816
delta-transmission enabled
recv_generator(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso,1)
generating and sending sums for 1
count=43231 rem=17936 blength=43216 s2length=3 flength=1868245616
generate_files phase=1
recv_files(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso)
altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso
recv mapped altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso of size 1868245616
  1865072912  51%   11.68MB/s    0:02:26
rsync error: timeout in data send/receive (code 30) at io.c(137) [sender=3.0.9]
rsync: connection unexpectedly closed (98438 bytes received so far) [receiver]
rsync error: error in rsync protocol data stream (code 12) at io.c(601) [receiver=3.0.8]
[receiver] _exit_cleanup(code=12, file=io.c, line=601): about to call exit(12)
rsync: connection unexpectedly closed (77 bytes received so far) [generator]
rsync error: error in rsync protocol data stream (code 12) at io.c(601) [generator=3.0.8]
[generator] _exit_cleanup(code=12, file=io.c, line=601): about to call exit(12)
$ du -sb *
1868245616	altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso
732954624	altlinux-6.0.1_rc1-simply-i586-ru-live-cd.iso
721420288	altlinux-6.0.0_beta20110620-simply-i586-ru-live-cd.iso
$ 

Perhaps, it's because of a timeout at the server side (which fails to wait enough for my client to process the initial, already-present chunk of the file)...
Comment 1 Michael Shigorin 2011-11-22 23:41:59 MSK
Try this one: rsync://ftp.linux.kiev.ua/pub/Linux/ALT/beta/p6/simply/

PS: blaming a package for presumable configuration issues is, erm, funny...
Comment 2 Ivan Zakharyaschev 2011-11-23 00:01:09 MSK
Thanks for your suggestion. I'll try your server and post what the result is.

Re blaming the program: I'm not sure whether it's a configuration issue at the server side or not. Perhaps, it's a bug in rsync. 

Or it could be a feature request for rsync and the rsync protocol: the rsync client could warn the server that it's going to take some time, or send some keep-alive messages meanwhile...
Comment 3 Ivan Zakharyaschev 2011-11-23 00:26:10 MSK
The same happens when working with ftp.linux.kiev.ua:

$ rsync -avz -P ftp.linux.kiev.ua::pub/Linux/ALT/beta/p6/simply/*rc2*i586* ./ -vv --stats --inplace
opening tcp connection to ftp.linux.kiev.ua port 873
Connected to ftp.linux.kiev.ua (62.149.13.37)
sending daemon args: --server --sender -vvvlogDtprz --inplace . "pub/Linux/ALT/beta/p6/simply/*rc2*i586*" 
Welcome to ftp.linux.kiev.ua rsync server!

Gigabit bandwidth for this site is generously provided
by Colocall ISP -- visit http://www.colocall.net
if you need *amazing* hosting service!

receiving file list ... 
recv_file_name(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso)
received 1 names
1 file to consider
recv_file_list done
get_local_name count=1 ./
recv_files(1) starting
generator starting pid=19250
delta-transmission enabled
recv_generator(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso,0)
generating and sending sums for 0
count=43231 rem=17936 blength=43216 s2length=3 flength=1868245616
generate_files phase=1
recv_files(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso)
altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso
recv mapped altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso of size 1868245616
  1851416656  51%   21.30MB/s    0:01:21
rsync error: timeout in data send/receive (code 30) at io.c(165) [sender=2.6.9]
rsync: connection unexpectedly closed (114864 bytes received so far) [receiver]
rsync error: error in rsync protocol data stream (code 12) at io.c(605) [receiver=3.0.9]
[receiver] _exit_cleanup(code=12, file=io.c, line=605): about to call exit(12)
rsync: connection unexpectedly closed (97 bytes received so far) [generator]
rsync error: error in rsync protocol data stream (code 12) at io.c(605) [generator=3.0.9]
[generator] _exit_cleanup(code=12, file=io.c, line=605): about to call exit(12)
$ 

Reproduced 2 times.
Comment 4 Michael Shigorin 2011-11-23 16:12:45 MSK
(In reply to comment #2)
> Or it could be a feature request for rsync and the rsync protocol: the rsync
> client could warn the server that it's going to take some time, or send some
> keep-alive messages meanwhile...
That might make a nice upstream FR if the current rsync versions at both ends are confirmed to (mis)behave like this.

(In reply to comment #3)
> The same happens when working with ftp.linux.kiev.ua:
[...]
>   1851416656  51%   21.30MB/s    0:01:21
> rsync error: timeout in data send/receive (code 30) at io.c(165)
[...]
> Reproduced 2 times.
Could you please run it under time(1) once more?  I can tweak timeouts at f.l.k.u for us to understand whether it depends on those or not (didn't change anything yet).
Comment 5 Ivan Zakharyaschev 2011-11-24 03:51:54 MSK
[imz@localhost p6beta]$ du -sh altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso 
1,8G	altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso
[imz@localhost p6beta]$ du -shb altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso 
1868245616	altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso
[imz@localhost p6beta]$ time rsync -avz -P ftp.linux.kiev.ua::pub/Linux/ALT/beta/p6/simply/*rc2*i586* ./ -vv --stats --inplace
opening tcp connection to ftp.linux.kiev.ua port 873
Connected to ftp.linux.kiev.ua (62.149.13.37)
sending daemon args: --server --sender -vvvlogDtprz --inplace . "pub/Linux/ALT/beta/p6/simply/*rc2*i586*" 
Welcome to ftp.linux.kiev.ua rsync server!

Gigabit bandwidth for this site is generously provided
by Colocall ISP -- visit http://www.colocall.net
if you need *amazing* hosting service!

receiving file list ... 
recv_file_name(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso)
received 1 names
1 file to consider
recv_file_list done
get_local_name count=1 ./
recv_files(1) starting
generator starting pid=31626
delta-transmission enabled
recv_generator(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso,0)
generating and sending sums for 0
count=43231 rem=17936 blength=43216 s2length=3 flength=1868245616
generate_files phase=1
recv_files(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso)
altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso
recv mapped altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso of size 1868245616
  1853231728  51%   27.01MB/s    0:01:03
rsync error: timeout in data send/receive (code 30) at io.c(165) [sender=2.6.9]
rsync: connection unexpectedly closed (114858 bytes received so far) [receiver]
rsync error: error in rsync protocol data stream (code 12) at io.c(605) [receiver=3.0.9]
[receiver] _exit_cleanup(code=12, file=io.c, line=605): about to call exit(12)
rsync: connection unexpectedly closed (97 bytes received so far) [generator]
rsync error: error in rsync protocol data stream (code 12) at io.c(605) [generator=3.0.9]
[generator] _exit_cleanup(code=12, file=io.c, line=605): about to call exit(12)
Command exited with non-zero status 12
13.85user 2.10system 3:15.33elapsed 8%CPU (0avgtext+0avgdata 0maxresident)k
3649704inputs+0outputs (6major+613minor)pagefaults 0swaps
[imz@localhost p6beta]$
Comment 6 Ivan Zakharyaschev 2011-11-24 04:14:50 MSK
Yes, 3 minutes is more than the default, according to /etc/rsyncd.conf:  #timeout # The "timeout" option allows you to override the clients choice for IO timeout for # this module. Using this option you can ensure that rsync won't wait on a dead client # forever. The timeout is specified in seconds. A value of zero means no timeout and # is the default. A good choice for anonymous rsync servers may be 600 (giving a 10 # minute timeout). Default value is 60 (one minute).  Another run, under "time -v":  $ time -v rsync -avz -P ftp.linux.kiev.ua::pub/Linux/ALT/beta/p6/simply/*rc2*i586* ./ -vv --stats --inplace opening tcp connection to ftp.linux.kiev.ua port 873 Connected to ftp.linux.kiev.ua (62.149.13.37) sending daemon args: --server --sender -vvvlogDtprz --inplace . "pub/Linux/ALT/beta/p6/simply/*rc2*i586*"  Welcome to ftp.linux.kiev.ua rsync server!  Gigabit bandwidth for this site is generously provided by Colocall ISP -- visit http://www.colocall.net if you need *amazing* hosting service!  receiving file list ...  recv_file_name(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso) received 1 names 1 file to consider recv_file_list done get_local_name count=1 ./ recv_files(1) starting generator starting pid=31668 delta-transmission enabled recv_generator(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso,0) generating and sending sums for 0 count=43231 rem=17936 blength=43216 s2length=3 flength=1868245616 ^[[2^generate_files phase=1 recv_files(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso) altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso recv mapped altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso of size 1868245616   1861874928  51%   27.32MB/s    0:01:02 rsync error: timeout in data send/receive (code 30) at io.c(165) [sender=2.6.9] rsync: connection unexpectedly closed (114858 bytes received so far) [receiver] rsync error: error in rsync protocol data stream (code 12) at io.c(605) [receiver=3.0.9] [receiver] _exit_cleanup(code=12, file=io.c, line=605): about to call exit(12) rsync: connection unexpectedly closed (97 bytes received so far) [generator] rsync error: error in rsync protocol data stream (code 12) at io.c(605) [generator=3.0.9] [generator] _exit_cleanup(code=12, file=io.c, line=605): about to call exit(12) Command exited with non-zero status 12 	Command being timed: "rsync -avz -P ftp.linux.kiev.ua::pub/Linux/ALT/beta/p6/simply/*rc2*i586* ./ -vv --stats --inplace" 	User time (seconds): 13.87 	System time (seconds): 2.16 	Percent of CPU this job got: 8% 	Elapsed (wall clock) time (h:mm:ss or m:ss): 3:08.38 	Average shared text size (kbytes): 0 	Average unshared data size (kbytes): 0 	Average stack size (kbytes): 0 	Average total size (kbytes): 0 	Maximum resident set size (kbytes): 0 	Average resident set size (kbytes): 0 	Major (requiring I/O) page faults: 2 	Minor (reclaiming a frame) page faults: 609 	Voluntary context switches: 14166 	Involuntary context switches: 5082 	Swaps: 0 	File system inputs: 3649320 	File system outputs: 0 	Socket messages sent: 0 	Socket messages received: 0 	Signals delivered: 0 	Page size (bytes): 4096 	Exit status: 12 $
Comment 7 Ivan Zakharyaschev 2011-11-24 04:16:18 MSK
Yes, 3 minutes is more than the default, according to /etc/rsyncd.conf:

#timeout
# The "timeout" option allows you to override the clients choice for IO timeout for
# this module. Using this option you can ensure that rsync won't wait on a dead client
# forever. The timeout is specified in seconds. A value of zero means no timeout and
# is the default. A good choice for anonymous rsync servers may be 600 (giving a 10
# minute timeout). Default value is 60 (one minute).

Another run, under "time -v":

$ time -v rsync -avz -P ftp.linux.kiev.ua::pub/Linux/ALT/beta/p6/simply/*rc2*i586* ./ -vv --stats --inplace
opening tcp connection to ftp.linux.kiev.ua port 873
Connected to ftp.linux.kiev.ua (62.149.13.37)
sending daemon args: --server --sender -vvvlogDtprz --inplace . "pub/Linux/ALT/beta/p6/simply/*rc2*i586*" 
Welcome to ftp.linux.kiev.ua rsync server!

Gigabit bandwidth for this site is generously provided
by Colocall ISP -- visit http://www.colocall.net
if you need *amazing* hosting service!

receiving file list ... 
recv_file_name(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso)
received 1 names
1 file to consider
recv_file_list done
get_local_name count=1 ./
recv_files(1) starting
generator starting pid=31668
delta-transmission enabled
recv_generator(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso,0)
generating and sending sums for 0
count=43231 rem=17936 blength=43216 s2length=3 flength=1868245616
^[[2^generate_files phase=1
recv_files(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso)
altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso
recv mapped altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso of size 1868245616
  1861874928  51%   27.32MB/s    0:01:02
rsync error: timeout in data send/receive (code 30) at io.c(165) [sender=2.6.9]
rsync: connection unexpectedly closed (114858 bytes received so far) [receiver]
rsync error: error in rsync protocol data stream (code 12) at io.c(605) [receiver=3.0.9]
[receiver] _exit_cleanup(code=12, file=io.c, line=605): about to call exit(12)
rsync: connection unexpectedly closed (97 bytes received so far) [generator]
rsync error: error in rsync protocol data stream (code 12) at io.c(605) [generator=3.0.9]
[generator] _exit_cleanup(code=12, file=io.c, line=605): about to call exit(12)
Command exited with non-zero status 12
	Command being timed: "rsync -avz -P ftp.linux.kiev.ua::pub/Linux/ALT/beta/p6/simply/*rc2*i586* ./ -vv --stats --inplace"
	User time (seconds): 13.87
	System time (seconds): 2.16
	Percent of CPU this job got: 8%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 3:08.38
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 0
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 2
	Minor (reclaiming a frame) page faults: 609
	Voluntary context switches: 14166
	Involuntary context switches: 5082
	Swaps: 0
	File system inputs: 3649320
	File system outputs: 0
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0
	Page size (bytes): 4096
	Exit status: 12
$
Comment 8 Michael Shigorin 2011-11-24 18:51:26 MSK
Bumped, please retry.
Comment 9 Ivan Zakharyaschev 2011-11-26 05:31:56 MSK
Yes, now it proceeds successfully past that critical point: 

$ time -v rsync -avz -P ftp.linux.kiev.ua::pub/Linux/ALT/beta/p6/simply/*rc2*i586* ./ -vv --stats --inplace
opening tcp connection to ftp.linux.kiev.ua port 873
Connected to ftp.linux.kiev.ua (62.149.13.37)
sending daemon args: --server --sender -vvvlogDtprz --inplace . "pub/Linux/ALT/beta/p6/simply/*rc2*i586*" 
Welcome to ftp.linux.kiev.ua rsync server!

Gigabit bandwidth for this site is generously provided
by Colocall ISP -- visit http://www.colocall.net
if you need *amazing* hosting service!

receiving file list ... 
recv_file_name(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso)
received 1 names
1 file to consider
recv_file_list done
get_local_name count=1 ./
recv_files(1) starting
generator starting pid=10977
delta-transmission enabled
recv_generator(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso,0)
generating and sending sums for 0
count=43231 rem=17936 blength=43216 s2length=3 flength=1868245616
generate_files phase=1
recv_files(altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso)
altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso
recv mapped altlinux-6.0.1_rc2-simply-i586-ru-install-dvd5.iso of size 1868245616
  1929487450  53%  297.08kB/s    1:34:49
Comment 10 Michael Shigorin 2011-11-26 14:52:19 MSK
Let's consider it "resolved" then. :)