X-Recipient: archive-cygwin AT delorie DOT com X-SWARE-Spam-Status: No, hits=-1.0 required=5.0 tests=BAYES_00,DKIM_ADSP_CUSTOM_MED,FREEMAIL_FROM,NML_ADSP_CUSTOM_MED,SPF_HELO_PASS,T_RP_MATCHES_RCVD X-Spam-Check-By: sourceware.org To: cygwin AT cygwin DOT com From: Richard Ivarson Subject: Re: Rsync stops inmid of synchronisation Date: Thu, 15 Mar 2012 11:20:50 +0100 Lines: 185 Message-ID: References: <4F4E5478 DOT 1080100 AT molconn DOT com> <20120313200005 DOT GB5890 AT jethro DOT local DOT lan> Mime-Version: 1.0 Content-Type: multipart/mixed; boundary="------------070400070800000400090000" User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:10.0.3) Gecko/20120306 Thunderbird/10.0.3 In-Reply-To: <20120313200005.GB5890@jethro.local.lan> X-IsSubscribed: yes Mailing-List: contact cygwin-help AT cygwin DOT com; run by ezmlm Precedence: bulk List-Id: List-Unsubscribe: List-Subscribe: List-Archive: List-Post: List-Help: , Sender: cygwin-owner AT cygwin DOT com Mail-Followup-To: cygwin AT cygwin DOT com Delivered-To: mailing list cygwin AT cygwin DOT com --------------070400070800000400090000 Content-Type: text/plain; charset=ISO-8859-15; format=flowed Content-Transfer-Encoding: 7bit OK, so I called "strace -p " where ID is the pid of a running rsync command. Then I waited until the rsync command timed out due to the unknown problem which I try to encircle. In short the problem is: two computers with WinXP_pro 32bit and up-to-date Cygwin are connected, and I try to rsync some folders of the first computer to the remote computer. However, after the sender rsynced some thousands of smaller files correctly (respectivly: it checked them without transfering the up-to-date files), it suddently stops to do anything... That's why I've added the "--timeout=30" parameter to the sending rsync, so that my rsync aborts the "offending" folders and the bash script can continue with the following rsync commands. So now rsync said this: [sender] io timeout after 30 seconds -- exiting rsync error: timeout in data send/receive (code 30) at /home/lapo/package/rsync-3.0.9-1/src/rsync-3.0.9/io.c(140) [sender=3.0.9] And the strace log which happened before and during the time-out is attached below. (I cut the middle part of it because it just repeated about 250 times the "_set_errno" & "fstat64" lines.) Unfortunately the log doesn't say anything to me, but maybe some reader knowing the internas of Cygwin and rsync command in particular, sees more? Thank you very much! -Richard Am 13.03.2012 21:00, schrieb David Sastre Medina: > On Mon, Mar 12, 2012 at 01:48:45PM +0100, Richard Ivarson wrote: >> Is there a way to increase the verbosity level of the sending rsync >> (aside the parameter "-v" which we can increase to "-vv" or even >> "-vvv") ? >> Or could rsync print further helpful information about what it is >> doing right now ? >> >> Because that could help me. With "-vvv" rsync prints information >> about the files it's sending to the remote rsync, but in my case >> when it has rsynced for a while it suddenly stops to print and do >> anything, and I got no idea what is happening... > > Maybe overkill, but you could try to strace the process. --------------070400070800000400090000 Content-Type: text/plain; name="strace.log" Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename="strace.log" [..] 22 569009835 [main] rsync 2200 cygwin_select: sel.always_ready 0 36 569009871 [main] rsync 2200 start_thread_socket: stuff_start 0x228208 36 569009907 [socksel] rsync 2200 thread_socket: stuff_start 0x228208 32 569009939 [socksel] rsync 2200 peek_socket: read_ready: 0, write_ready: 0, except_ready: 0 39 569009978 [main] rsync 2200 select_stuff::wait: m 3, ms 15000 14999596 584009574 [main] rsync 2200 select_stuff::cleanup: calling cleanup routines 143 584009717 [main] rsync 2200 socket_cleanup: si 0x2004F1C8 si->thread 0x61186390 78 584009795 [socksel] rsync 2200 thread_socket: leaving thread_socket 108 584009903 [main] rsync 2200 socket_cleanup: returning 56 584009959 [main] rsync 2200 select_stuff::wait: timed out 55 584010014 [main] rsync 2200 select_stuff::wait: returning 1 55 584010069 [main] rsync 2200 cygwin_select: 0 = select(4, 0x2282D8, 0x2282D0, 0x228180, 0x2282C8) 61 584010130 [main] rsync 2200 select_stuff::cleanup: calling cleanup routines 56 584010186 [main] rsync 2200 select_stuff::destroy: deleting select records 79 584010265 [main] rsync 2200 time: 1331803941 = time(0) 185 584010450 [main] rsync 2200 fhandler_console::write: 2265F0, 47 60 584010510 [main] rsync 2200 fhandler_console::write: at 91([) state is 0 87 584010597 [main] rsync 2200 fhandler_console::write: 47 = fhandler_console::write(...) 58 584010655 [main] rsync 2200 write: 47 = write(2, 0x2265F0, 47) 224 584010879 [main] rsync 2200 fhandler_console::write: 61183757, 1 55 584010934 [main] rsync 2200 fhandler_console::write: at 10(0x20) state is 0 169 584011103 [main] rsync 2200 fhandler_console::write: 1 = fhandler_console::write(...) 62 584011165 [main] rsync 2200 write: 1 = write(2, 0x61183757, 1) 248 584011413 [main] rsync 2200 sigaction_worker: signal 30, newact 0x4641DC (handler 0x1), oa 0x419660 67 584011480 [main] rsync 2200 sig_send: sendsig 0x77C, pid 2200, signal -30, its_me 1 60 584011540 [main] rsync 2200 sig_send: wakeup 0x6B8 64 584011604 [main] rsync 2200 sig_send: Waiting for pack.wakeup 0x6B8 85 584011689 [sig] rsync 2200 wait_sig: signalling pack.wakeup 0x6B8 64 584011753 [main] rsync 2200 sig_send: returning 0x0 from sending signal -30 59 584011812 [main] rsync 2200 sigaction_worker: 0 = sigaction(30, 0x4641DC, 0x0) 58 584011870 [main] rsync 2200 sigaction_worker: signal 31, newact 0x4641DC (handler 0x1), oa 0x419FF0 65 584011935 [main] rsync 2200 sig_send: sendsig 0x77C, pid 2200, signal -31, its_me 1 65 584012000 [main] rsync 2200 sig_send: wakeup 0x6B8 60 584012060 [main] rsync 2200 sig_send: Waiting for pack.wakeup 0x6B8 3 584012063 [sig] rsync 2200 wait_sig: signalling pack.wakeup 0x6B8 108 584012171 [main] rsync 2200 sig_send: returning 0x0 from sending signal -31 58 584012229 [main] rsync 2200 sigaction_worker: 0 = sigaction(31, 0x4641DC, 0x0) 133 584012362 [main] rsync 2200 fhandler_console::write: 226550, 128 56 584012418 [main] rsync 2200 fhandler_console::write: at 114(r) state is 0 132 584012550 [main] rsync 2200 fhandler_console::write: 128 = fhandler_console::write(...) 61 584012611 [main] rsync 2200 write: 128 = write(2, 0x226550, 128) 232 584012843 [main] rsync 2200 fhandler_console::write: 61183757, 1 58 584012901 [main] rsync 2200 fhandler_console::write: at 10(0x20) state is 0 135 584013036 [main] rsync 2200 fhandler_console::write: 1 = fhandler_console::write(...) 61 584013097 [main] rsync 2200 write: 1 = write(2, 0x61183757, 1) 244 584013341 [main] rsync 2200 __set_errno: cygheap_fdget::cygheap_fdget(int, bool, bool):396 setting errno 9 60 584013401 [main] rsync 2200 fstat64: -1 = fstat(255, 0x228180), errno 9 [... 250 more "_set_errno" & "fstat64" ...] 55 584041431 [main] rsync 2200 __set_errno: cygheap_fdget::cygheap_fdget(int, bool, bool):396 setting errno 9 57 584041488 [main] rsync 2200 fstat64: -1 = fstat(4, 0x228180), errno 9 59 584041547 [main] rsync 2200 time: 1331803941 = time(0) 55 584041602 [main] rsync 2200 fstat64: 0 = fstat(3, 0x228180) 76 584041678 [main] rsync 2200 cygwin_getsockopt: 0 = getsockopt(3, 65535, 0x1008, 0x22815C, 0x228158) 102 584041780 [main] rsync 2200 cygwin_shutdown: 0 = shutdown(3, 2) 64 584041844 [main] rsync 2200 close: close(3) 81 584041925 [main] rsync 2200 fhandler_socket::close: 0 = fhandler_socket::close() 59 584041984 [main] rsync 2200 close: 0 = close(3) 56 584042040 [main] rsync 2200 time: 1331803941 = time(0) 56 584042096 [main] rsync 2200 fstat64: 0 = fstat(2, 0x228180) 55 584042151 [main] rsync 2200 __set_errno: fhandler_socket* get(int):83 setting errno 108 57 584042208 [main] rsync 2200 cygwin_getsockopt: -1 = getsockopt(2, 65535, 0x1008, 0x22815C, 0x228158), errno 108 59 584042267 [main] rsync 2200 close: close(2) 54 584042321 [main] rsync 2200 fhandler_base::close_with_arch: line 1118: /dev/cons0<0x61273FFC> usecount + -1 = 3 59 584042380 [main] rsync 2200 fhandler_base::close_with_arch: not closing archetype 57 584042437 [main] rsync 2200 close: 0 = close(2) 54 584042491 [main] rsync 2200 time: 1331803941 = time(0) 54 584042545 [main] rsync 2200 fstat64: 0 = fstat(1, 0x228180) 55 584042600 [main] rsync 2200 __set_errno: fhandler_socket* get(int):83 setting errno 108 56 584042656 [main] rsync 2200 cygwin_getsockopt: -1 = getsockopt(1, 65535, 0x1008, 0x22815C, 0x228158), errno 108 59 584042715 [main] rsync 2200 close: close(1) 53 584042768 [main] rsync 2200 fhandler_base::close_with_arch: line 1118: /dev/cons0<0x61273FFC> usecount + -1 = 2 59 584042827 [main] rsync 2200 fhandler_base::close_with_arch: not closing archetype 56 584042883 [main] rsync 2200 close: 0 = close(1) 55 584042938 [main] rsync 2200 time: 1331803941 = time(0) 55 584042993 [main] rsync 2200 fstat64: 0 = fstat(0, 0x228180) 54 584043047 [main] rsync 2200 __set_errno: fhandler_socket* get(int):83 setting errno 108 57 584043104 [main] rsync 2200 cygwin_getsockopt: -1 = getsockopt(0, 65535, 0x1008, 0x22815C, 0x228158), errno 108 59 584043163 [main] rsync 2200 close: close(0) 54 584043217 [main] rsync 2200 fhandler_base::close_with_arch: line 1118: /dev/cons0<0x61273FFC> usecount + -1 = 1 58 584043275 [main] rsync 2200 fhandler_base::close_with_arch: not closing archetype 56 584043331 [main] rsync 2200 close: 0 = close(0) 353 584043684 [main] rsync 2200 close: close(0) 56 584043740 [main] rsync 2200 __set_errno: cygheap_fdget::cygheap_fdget(int, bool, bool):396 setting errno 9 59 584043799 [main] rsync 2200 close: -1 = close(0), errno 9 342 584044141 [main] rsync 2200 close: close(1) 55 584044196 [main] rsync 2200 __set_errno: cygheap_fdget::cygheap_fdget(int, bool, bool):396 setting errno 9 63 584044259 [main] rsync 2200 close: -1 = close(1), errno 9 316 584044575 [main] rsync 2200 close: close(2) 54 584044629 [main] rsync 2200 __set_errno: cygheap_fdget::cygheap_fdget(int, bool, bool):396 setting errno 9 59 584044688 [main] rsync 2200 close: -1 = close(2), errno 9 188 584044876 [main] rsync 2200 do_exit: do_exit (7680), exit_state 1 56 584044932 [main] rsync 2200 void: 0x41A040 = signal (20, 0x1) 55 584044987 [main] rsync 2200 void: 0x409770 = signal (1, 0x1) 54 584045041 [main] rsync 2200 void: 0x409770 = signal (2, 0x1) 54 584045095 [main] rsync 2200 void: 0x0 = signal (3, 0x1) 58 584045153 [main] rsync 2200 init_cygheap::close_ctty: closing cygheap->ctty 0x61273FFC 58 584045211 [main] rsync 2200 fhandler_base::close_with_arch: closing passed in archetype, usecount 0 92 584045303 [main] rsync 2200 fhandler_console::free_console: freed console, res 1 66 584045369 [main] rsync 2200 getpid: 2200 = getpid() 76 584045445 [main] rsync 2200 sigproc_terminate: entering 55 584045500 [main] rsync 2200 sig_send: sendsig 0x77C, pid 2200, signal -42, its_me 1 63 584045563 [main] rsync 2200 sig_send: Not waiting for sigcomplete. its_me 1 signal -42 3 584045566 [sig] rsync 2200 wait_sig: saw __SIGEXIT 55 584045621 [main] rsync 2200 sig_send: returning 0x0 from sending signal -42 107 584045728 [main] rsync 2200 proc_terminate: nprocs 0 1 584045729 [sig] rsync 2200 wait_sig: signal thread exiting 53 584045782 [main] rsync 2200 proc_terminate: leaving 129 584045911 [main] rsync 2200 __to_clock_t: dwHighDateTime 0, dwLowDateTime 134218750 58 584045969 [main] rsync 2200 __to_clock_t: total 00000000 0000346D 88 584046057 [main] rsync 2200 __to_clock_t: dwHighDateTime 0, dwLowDateTime 50781250 58 584046115 [main] rsync 2200 __to_clock_t: total 00000000 000013D6 61 584046176 [main] rsync 2200 pinfo::exit: Calling ExitProcess n 0x1E00, exitcode 0x1E00 Windows process 3904 detached --------------070400070800000400090000 Content-Type: text/plain; charset=us-ascii -- Problem reports: http://cygwin.com/problems.html FAQ: http://cygwin.com/faq/ Documentation: http://cygwin.com/docs.html Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple --------------070400070800000400090000--