OK, so I called "strace -p <ID>" 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.
[..]
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
--
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
