26605 2011-11-22 22:24:50 +0400 "rsync a-DVD.iso ./" fails in the middle (at about 1.8G) 2019-12-16 11:39:04 +0300 1 1 3 Distributions Branch 5.1 rsync unspecified all Linux CLOSED WORKSFORME P3 normal --- 26604 1 imz mike billmartinnn mike qa-5.1 oldest_to_newest 127091 0 imz 2011-11-22 22:24:50 +0400 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)... 127093 1 mike 2011-11-22 23:41:59 +0400 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... 127094 2 imz 2011-11-23 00:01:09 +0400 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... 127095 3 imz 2011-11-23 00:26:10 +0400 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. 127128 4 mike 2011-11-23 16:12:45 +0400 (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). 127152 5 imz 2011-11-24 03:51:54 +0400 [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]$ 127153 6 imz 2011-11-24 04:14:50 +0400 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 $ 127154 7 imz 2011-11-24 04:16:18 +0400 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 $ 127170 8 mike 2011-11-24 18:51:26 +0400 Bumped, please retry. 127203 9 imz 2011-11-26 05:31:56 +0400 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 127208 10 mike 2011-11-26 14:52:19 +0400 Let's consider it "resolved" then. :)