rsync - Oct 2004 - rsync 2.6.3 hang (was rsync 2.6.2 crash)

Here are strace outputs of a hung session, 2.6.3 on both ends (server, client
process 1, client process 2):

$ strace -t -p 4040
Attached to pid 4040 (windows pid 2488)
14:04:47 [unknown (0x938)] rsync 4040 _cygtls::remove: wait 0x0
14:05:17 [main] rsync 4040 select_stuff::wait: timed out
14:05:17 [main] rsync 4040 select_stuff::wait: returning 1
14:05:17 [main] rsync 4040 select_stuff::cleanup: calling cleanup routines
14:05:17 [select_pipe] rsync 4040 thread_pipe: stopping
14:05:17 [main] rsync 4040 select_stuff::poll: returning 0
14:05:17 [main] rsync 4040 select_stuff::cleanup: calling cleanup routines
14:05:17 [main] rsync 4040 select_stuff::~select_stuff: deleting select records
14:05:17 [main] rsync 4040 cygwin_select: 2, 0x0, 0x22D9A0, 0x0, 0x22D990
14:05:17 [main] rsync 4040 dtable::select_write:  fd 1
14:05:17 [main] rsync 4040 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms
60000

14:05:17 [main] rsync 4040 cygwin_select: sel.always_ready 0
14:05:17 [main] rsync 4040 select_stuff::wait: m 2, ms 60000
14:06:17 [main] rsync 4040 select_stuff::wait: timed out
14:06:17 [main] rsync 4040 select_stuff::wait: returning 1
14:06:17 [main] rsync 4040 select_stuff::cleanup: calling cleanup routines
14:06:17 [select_pipe] rsync 4040 thread_pipe: stopping
14:06:17 [main] rsync 4040 select_stuff::poll: returning 0
14:06:17 [main] rsync 4040 select_stuff::cleanup: calling cleanup routines
14:06:17 [main] rsync 4040 select_stuff::~select_stuff: deleting select records
14:06:17 [main] rsync 4040 cygwin_select: 2, 0x0, 0x22D9A0, 0x0, 0x22D990
14:06:17 [main] rsync 4040 dtable::select_write:  fd 1
14:06:17 [main] rsync 4040 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms
60000

14:06:17 [main] rsync 4040 cygwin_select: sel.always_ready 0
14:06:17 [main] rsync 4040 select_stuff::wait: m 2, ms 60000
14:07:17 [main] rsync 4040 select_stuff::wait: timed out
14:07:17 [main] rsync 4040 select_stuff::wait: returning 1
14:07:17 [main] rsync 4040 select_stuff::cleanup: calling cleanup routines
14:07:17 [select_pipe] rsync 4040 thread_pipe: stopping
14:07:17 [main] rsync 4040 select_stuff::poll: returning 0
14:07:17 [main] rsync 4040 select_stuff::cleanup: calling cleanup routines
14:07:17 [main] rsync 4040 select_stuff::~select_stuff: deleting select records
14:07:17 [main] rsync 4040 cygwin_select: 2, 0x0, 0x22D9A0, 0x0, 0x22D990
14:07:17 [main] rsync 4040 dtable::select_write:  fd 1
14:07:17 [main] rsync 4040 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms
60000

14:07:17 [main] rsync 4040 cygwin_select: sel.always_ready 0
14:07:17 [main] rsync 4040 select_stuff::wait: m 2, ms 60000
14:08:17 [main] rsync 4040 select_stuff::wait: timed out
14:08:17 [main] rsync 4040 select_stuff::wait: returning 1
14:08:17 [main] rsync 4040 select_stuff::cleanup: calling cleanup routines
14:08:17 [select_pipe] rsync 4040 thread_pipe: stopping
14:08:17 [main] rsync 4040 select_stuff::poll: returning 0
14:08:17 [main] rsync 4040 select_stuff::cleanup: calling cleanup routines
14:08:17 [main] rsync 4040 select_stuff::~select_stuff: deleting select records
14:08:17 [main] rsync 4040 cygwin_select: 2, 0x0, 0x22D9A0, 0x0, 0x22D990
14:08:17 [main] rsync 4040 dtable::select_write:  fd 1
14:08:17 [main] rsync 4040 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms
60000

14:08:17 [main] rsync 4040 cygwin_select: sel.always_ready 0
14:08:17 [main] rsync 4040 select_stuff::wait: m 2, ms 60000
14:09:17 [main] rsync 4040 select_stuff::wait: timed out
14:09:17 [main] rsync 4040 select_stuff::wait: returning 1
14:09:17 [main] rsync 4040 select_stuff::cleanup: calling cleanup routines
14:09:17 [select_pipe] rsync 4040 thread_pipe: stopping
14:09:17 [main] rsync 4040 select_stuff::poll: returning 0
14:09:17 [main] rsync 4040 select_stuff::cleanup: calling cleanup routines
14:09:17 [main] rsync 4040 select_stuff::~select_stuff: deleting select records
14:09:17 [main] rsync 4040 cygwin_select: 2, 0x0, 0x22D9A0, 0x0, 0x22D990
14:09:17 [main] rsync 4040 dtable::select_write:  fd 1
14:09:17 [main] rsync 4040 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms
60000

14:09:17 [main] rsync 4040 cygwin_select: sel.always_ready 0
14:09:17 [main] rsync 4040 select_stuff::wait: m 2, ms 60000

----------------------------------------------------

client 1:
$ strace -t -p 2472
Attached to pid 2472 (windows pid 1248)
14:03:19 [unknown (0x528)] rsync 2472 _cygtls::remove: wait 0x0
14:03:19 [unknown (0x528)] rsync 2472 _cygtls::remove: removed 0xF8F140 element
1
14:04:19 [main] rsync 2472 select_stuff::wait: timed out
14:04:19 [main] rsync 2472 select_stuff::wait: returning 1
14:04:19 [main] rsync 2472 select_stuff::cleanup: calling cleanup routines
14:04:19 [main] rsync 2472 socket_cleanup: si 0x101A65C8 si->thread
0x610F38D8
14:04:19 [main] rsync 2472 socket_cleanup: connection to si->exitsock 0x2E4
14:04:19 [select_socket] rsync 2472 thread_socket: Win32 select returned 1
14:04:19 [select_socket] rsync 2472 thread_socket: s 0x10013780, testing fd 4 ()
14:04:19 [select_socket] rsync 2472 thread_socket: s 0x10012A78, testing fd 3 ()
14:04:19 [select_socket] rsync 2472 thread_socket: saw exitsock read
14:04:19 [main] rsync 2472 socket_cleanup: returning
14:04:19 [main] rsync 2472 socket_cleanup: si 0x0 si->thread 0x0
14:04:19 [main] rsync 2472 socket_cleanup: returning
14:04:19 [main] rsync 2472 peek_socket: considering handle 0x308
14:04:19 [main] rsync 2472 peek_socket: adding write fd_set , fd 4
14:04:19 [main] rsync 2472 peek_socket: WINSOCK_SELECT returned 0
14:04:19 [main] rsync 2472 peek_socket: considering handle 0x2C0
14:04:19 [main] rsync 2472 peek_socket: adding read fd_set , fd 3
14:04:19 [main] rsync 2472 peek_socket: WINSOCK_SELECT returned 0
14:04:19 [main] rsync 2472 select_stuff::poll: returning 0
14:04:19 [main] rsync 2472 select_stuff::cleanup: calling cleanup routines
14:04:19 [main] rsync 2472 select_stuff::~select_stuff: deleting select records
14:04:19 [main] rsync 2472 cygwin_select: 5, 0x22E9C8, 0x22E9D0, 0x0, 0x22E9C0
14:04:19 [main] rsync 2472 dtable::select_read:  fd 3
14:04:19 [main] rsync 2472 dtable::select_write:  fd 4
14:04:19 [main] rsync 2472 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms
60000
14:04:19 [main] rsync 2472 cygwin_select: sel.always_ready 0
14:04:19 [main] rsync 2472 start_thread_socket: Handle 0x308
14:04:19 [main] rsync 2472 start_thread_socket: Added to writefds
14:04:19 [main] rsync 2472 start_thread_socket: Handle 0x2C0
14:04:19 [main] rsync 2472 start_thread_socket: Added to readfds
14:04:19 [main] rsync 2472 start_thread_socket: exitsock 0x2E4
14:04:19 [main] rsync 2472 start_thread_socket: stuff_start 0x22E934
14:04:19 [main] rsync 2472 select_stuff::wait: m 2, ms 60000
14:04:20 [select_socket] rsync 2472 thread_socket: stuff_start 0x101A95EC
14:05:20 [main] rsync 2472 select_stuff::wait: timed out
14:05:20 [main] rsync 2472 select_stuff::wait: returning 1
14:05:20 [main] rsync 2472 select_stuff::cleanup: calling cleanup routines
14:05:20 [main] rsync 2472 socket_cleanup: si 0x101A65C8 si->thread
0x610F38D8
14:05:20 [main] rsync 2472 socket_cleanup: connection to si->exitsock 0x2E4
14:05:20 [select_socket] rsync 2472 thread_socket: Win32 select returned 1
14:05:20 [select_socket] rsync 2472 thread_socket: s 0x10013780, testing fd 4 ()
14:05:20 [select_socket] rsync 2472 thread_socket: s 0x10012A78, testing fd 3 ()
14:05:20 [select_socket] rsync 2472 thread_socket: saw exitsock read
14:05:20 [main] rsync 2472 socket_cleanup: returning
14:05:20 [main] rsync 2472 socket_cleanup: si 0x0 si->thread 0x0
14:05:20 [main] rsync 2472 socket_cleanup: returning
14:05:20 [main] rsync 2472 peek_socket: considering handle 0x308
14:05:20 [main] rsync 2472 peek_socket: adding write fd_set , fd 4
14:05:20 [main] rsync 2472 peek_socket: WINSOCK_SELECT returned 0
14:05:20 [main] rsync 2472 peek_socket: considering handle 0x2C0
14:05:20 [main] rsync 2472 peek_socket: adding read fd_set , fd 3
14:05:20 [main] rsync 2472 peek_socket: WINSOCK_SELECT returned 0
14:05:20 [main] rsync 2472 select_stuff::poll: returning 0
14:05:20 [main] rsync 2472 select_stuff::cleanup: calling cleanup routines
14:05:20 [main] rsync 2472 select_stuff::~select_stuff: deleting select records
14:05:20 [main] rsync 2472 cygwin_select: 5, 0x22E9C8, 0x22E9D0, 0x0, 0x22E9C0
14:05:20 [main] rsync 2472 dtable::select_read:  fd 3
14:05:20 [main] rsync 2472 dtable::select_write:  fd 4
14:05:20 [main] rsync 2472 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms
60000
14:05:20 [main] rsync 2472 cygwin_select: sel.always_ready 0
14:05:20 [main] rsync 2472 start_thread_socket: Handle 0x308
14:05:20 [main] rsync 2472 start_thread_socket: Added to writefds
14:05:20 [main] rsync 2472 start_thread_socket: Handle 0x2C0
14:05:20 [main] rsync 2472 start_thread_socket: Added to readfds
14:05:20 [main] rsync 2472 start_thread_socket: exitsock 0x2E4
14:05:20 [main] rsync 2472 start_thread_socket: stuff_start 0x22E934
14:05:20 [main] rsync 2472 select_stuff::wait: m 2, ms 60000
14:05:20 [select_socket] rsync 2472 thread_socket: stuff_start 0x101A95EC
14:06:20 [main] rsync 2472 select_stuff::wait: timed out
14:06:20 [main] rsync 2472 select_stuff::wait: returning 1
14:06:20 [main] rsync 2472 select_stuff::cleanup: calling cleanup routines
14:06:20 [main] rsync 2472 socket_cleanup: si 0x101A65C8 si->thread
0x610F38D8
14:06:20 [main] rsync 2472 socket_cleanup: connection to si->exitsock 0x2E4
14:06:20 [select_socket] rsync 2472 thread_socket: Win32 select returned 1
14:06:20 [select_socket] rsync 2472 thread_socket: s 0x10013780, testing fd 4 ()
14:06:20 [select_socket] rsync 2472 thread_socket: s 0x10012A78, testing fd 3 ()
14:06:20 [select_socket] rsync 2472 thread_socket: saw exitsock read
14:06:20 [main] rsync 2472 socket_cleanup: returning
14:06:20 [main] rsync 2472 socket_cleanup: si 0x0 si->thread 0x0
14:06:20 [main] rsync 2472 socket_cleanup: returning
14:06:20 [main] rsync 2472 peek_socket: considering handle 0x308
14:06:20 [main] rsync 2472 peek_socket: adding write fd_set , fd 4
14:06:21 [main] rsync 2472 peek_socket: WINSOCK_SELECT returned 0
14:06:21 [main] rsync 2472 peek_socket: considering handle 0x2C0
14:06:21 [main] rsync 2472 peek_socket: adding read fd_set , fd 3
14:06:21 [main] rsync 2472 peek_socket: WINSOCK_SELECT returned 0
14:06:21 [main] rsync 2472 select_stuff::poll: returning 0
14:06:21 [main] rsync 2472 select_stuff::cleanup: calling cleanup routines
14:06:21 [main] rsync 2472 select_stuff::~select_stuff: deleting select records
14:06:21 [main] rsync 2472 cygwin_select: 5, 0x22E9C8, 0x22E9D0, 0x0, 0x22E9C0
14:06:21 [main] rsync 2472 dtable::select_read:  fd 3
14:06:21 [main] rsync 2472 dtable::select_write:  fd 4
14:06:21 [main] rsync 2472 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms
60000
14:06:21 [main] rsync 2472 cygwin_select: sel.always_ready 0
14:06:21 [main] rsync 2472 start_thread_socket: Handle 0x308
14:06:21 [main] rsync 2472 start_thread_socket: Added to writefds
14:06:21 [main] rsync 2472 start_thread_socket: Handle 0x2C0
14:06:21 [main] rsync 2472 start_thread_socket: Added to readfds
14:06:21 [main] rsync 2472 start_thread_socket: exitsock 0x2E4
14:06:21 [main] rsync 2472 start_thread_socket: stuff_start 0x22E934
14:06:21 [main] rsync 2472 select_stuff::wait: m 2, ms 60000
14:06:21 [select_socket] rsync 2472 thread_socket: stuff_start 0x101A95EC
14:07:21 [main] rsync 2472 select_stuff::wait: timed out
14:07:21 [main] rsync 2472 select_stuff::wait: returning 1
14:07:21 [main] rsync 2472 select_stuff::cleanup: calling cleanup routines
14:07:21 [main] rsync 2472 socket_cleanup: si 0x101A65C8 si->thread
0x610F38D8
14:07:21 [main] rsync 2472 socket_cleanup: connection to si->exitsock 0x2E4
14:07:21 [select_socket] rsync 2472 thread_socket: Win32 select returned 1
14:07:21 [select_socket] rsync 2472 thread_socket: s 0x10013780, testing fd 4 ()
14:07:21 [select_socket] rsync 2472 thread_socket: s 0x10012A78, testing fd 3 ()
14:07:21 [select_socket] rsync 2472 thread_socket: saw exitsock read
14:07:21 [main] rsync 2472 socket_cleanup: returning
14:07:21 [main] rsync 2472 socket_cleanup: si 0x0 si->thread 0x0
14:07:21 [main] rsync 2472 socket_cleanup: returning
14:07:21 [main] rsync 2472 peek_socket: considering handle 0x308
14:07:21 [main] rsync 2472 peek_socket: adding write fd_set , fd 4
14:07:21 [main] rsync 2472 peek_socket: WINSOCK_SELECT returned 0
14:07:21 [main] rsync 2472 peek_socket: considering handle 0x2C0
14:07:21 [main] rsync 2472 peek_socket: adding read fd_set , fd 3
14:07:21 [main] rsync 2472 peek_socket: WINSOCK_SELECT returned 0
14:07:21 [main] rsync 2472 select_stuff::poll: returning 0
14:07:21 [main] rsync 2472 select_stuff::cleanup: calling cleanup routines
14:07:21 [main] rsync 2472 select_stuff::~select_stuff: deleting select records
14:07:21 [main] rsync 2472 cygwin_select: 5, 0x22E9C8, 0x22E9D0, 0x0, 0x22E9C0
14:07:21 [main] rsync 2472 dtable::select_read:  fd 3
14:07:21 [main] rsync 2472 dtable::select_write:  fd 4
14:07:21 [main] rsync 2472 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms
60000
14:07:21 [main] rsync 2472 cygwin_select: sel.always_ready 0
14:07:21 [main] rsync 2472 start_thread_socket: Handle 0x308
14:07:21 [main] rsync 2472 start_thread_socket: Added to writefds
14:07:21 [main] rsync 2472 start_thread_socket: Handle 0x2C0
14:07:21 [main] rsync 2472 start_thread_socket: Added to readfds
14:07:21 [main] rsync 2472 start_thread_socket: exitsock 0x2E4
14:07:21 [main] rsync 2472 start_thread_socket: stuff_start 0x22E934
14:07:21 [main] rsync 2472 select_stuff::wait: m 2, ms 60000
14:07:21 [select_socket] rsync 2472 thread_socket: stuff_start 0x101A95EC
14:08:21 [main] rsync 2472 select_stuff::wait: timed out
14:08:21 [main] rsync 2472 select_stuff::wait: returning 1
14:08:21 [main] rsync 2472 select_stuff::cleanup: calling cleanup routines
14:08:21 [main] rsync 2472 socket_cleanup: si 0x101A65C8 si->thread
0x610F38D8
14:08:21 [main] rsync 2472 socket_cleanup: connection to si->exitsock 0x2E4
14:08:21 [select_socket] rsync 2472 thread_socket: Win32 select returned 1
14:08:21 [select_socket] rsync 2472 thread_socket: s 0x10013780, testing fd 4 ()
14:08:21 [select_socket] rsync 2472 thread_socket: s 0x10012A78, testing fd 3 ()
14:08:21 [select_socket] rsync 2472 thread_socket: saw exitsock read
14:08:21 [main] rsync 2472 socket_cleanup: returning
14:08:21 [main] rsync 2472 socket_cleanup: si 0x0 si->thread 0x0
14:08:21 [main] rsync 2472 socket_cleanup: returning
14:08:21 [main] rsync 2472 peek_socket: considering handle 0x308
14:08:21 [main] rsync 2472 peek_socket: adding write fd_set , fd 4
14:08:21 [main] rsync 2472 peek_socket: WINSOCK_SELECT returned 0
14:08:21 [main] rsync 2472 peek_socket: considering handle 0x2C0
14:08:21 [main] rsync 2472 peek_socket: adding read fd_set , fd 3
14:08:21 [main] rsync 2472 peek_socket: WINSOCK_SELECT returned 0
14:08:21 [main] rsync 2472 select_stuff::poll: returning 0
14:08:21 [main] rsync 2472 select_stuff::cleanup: calling cleanup routines
14:08:21 [main] rsync 2472 select_stuff::~select_stuff: deleting select records
14:08:21 [main] rsync 2472 cygwin_select: 5, 0x22E9C8, 0x22E9D0, 0x0, 0x22E9C0
14:08:21 [main] rsync 2472 dtable::select_read:  fd 3
14:08:21 [main] rsync 2472 dtable::select_write:  fd 4
14:08:21 [main] rsync 2472 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms
60000
14:08:21 [main] rsync 2472 cygwin_select: sel.always_ready 0
14:08:21 [main] rsync 2472 start_thread_socket: Handle 0x308
14:08:21 [main] rsync 2472 start_thread_socket: Added to writefds
14:08:21 [main] rsync 2472 start_thread_socket: Handle 0x2C0
14:08:21 [main] rsync 2472 start_thread_socket: Added to readfds
14:08:21 [main] rsync 2472 start_thread_socket: exitsock 0x2E4
14:08:21 [main] rsync 2472 start_thread_socket: stuff_start 0x22E934
14:08:21 [main] rsync 2472 select_stuff::wait: m 2, ms 60000
14:08:21 [select_socket] rsync 2472 thread_socket: stuff_start 0x101A95EC


client 2:

$ strace -t -p1468
Attached to pid 1468 (windows pid 1468)
14:03:40 [unknown (0x9F4)] rsync 1468 _cygtls::remove: wait 0x0
14:03:40 [unknown (0x9F4)] rsync 1468 _cygtls::remove: removed 0xDCF140 element
1
14:04:19 [main] rsync 1468 select_stuff::wait: timed out
14:04:19 [main] rsync 1468 select_stuff::wait: returning 1
14:04:19 [main] rsync 1468 select_stuff::cleanup: calling cleanup routines
14:04:19 [main] rsync 1468 socket_cleanup: si 0x101BB968 si->thread
0x610F38B0
14:04:19 [main] rsync 1468 socket_cleanup: connection to si->exitsock 0x324
14:04:20 [select_socket] rsync 1468 thread_socket: Win32 select returned 1
14:04:20 [select_socket] rsync 1468 thread_socket: s 0x10012A58, testing fd 5 ()
14:04:20 [select_socket] rsync 1468 thread_socket: saw exitsock read
14:04:20 [main] rsync 1468 socket_cleanup: returning
14:04:20 [main] rsync 1468 peek_socket: considering handle 0x3E8
14:04:20 [main] rsync 1468 peek_socket: adding read fd_set , fd 5
14:04:20 [main] rsync 1468 peek_socket: WINSOCK_SELECT returned 0
14:04:20 [main] rsync 1468 select_stuff::poll: returning 0
14:04:20 [main] rsync 1468 select_stuff::cleanup: calling cleanup routines
14:04:20 [main] rsync 1468 select_stuff::~select_stuff: deleting select records
14:04:20 [main] rsync 1468 cygwin_select: 6, 0x22E4C0, 0x22E4B8, 0x0, 0x22E4B0
14:04:20 [main] rsync 1468 dtable::select_read:  fd 5
14:04:20 [main] rsync 1468 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms
60000
14:04:20 [main] rsync 1468 cygwin_select: sel.always_ready 0
14:04:20 [main] rsync 1468 start_thread_socket: Handle 0x3E8
14:04:20 [main] rsync 1468 start_thread_socket: Added to readfds
14:04:20 [main] rsync 1468 start_thread_socket: exitsock 0x324
14:04:20 [main] rsync 1468 start_thread_socket: stuff_start 0x22E434
14:04:20 [main] rsync 1468 select_stuff::wait: m 2, ms 60000
14:04:20 [select_socket] rsync 1468 thread_socket: stuff_start 0x101BE98C
14:05:20 [main] rsync 1468 select_stuff::wait: timed out
14:05:20 [main] rsync 1468 select_stuff::wait: returning 1
14:05:20 [main] rsync 1468 select_stuff::cleanup: calling cleanup routines
14:05:20 [main] rsync 1468 socket_cleanup: si 0x101BB968 si->thread
0x610F38B0
14:05:20 [main] rsync 1468 socket_cleanup: connection to si->exitsock 0x324
14:05:20 [select_socket] rsync 1468 thread_socket: Win32 select returned 1
14:05:20 [select_socket] rsync 1468 thread_socket: s 0x10012A58, testing fd 5 ()
14:05:20 [select_socket] rsync 1468 thread_socket: saw exitsock read
14:05:20 [main] rsync 1468 socket_cleanup: returning
14:05:20 [main] rsync 1468 peek_socket: considering handle 0x3E8
14:05:20 [main] rsync 1468 peek_socket: adding read fd_set , fd 5
14:05:20 [main] rsync 1468 peek_socket: WINSOCK_SELECT returned 0
14:05:20 [main] rsync 1468 select_stuff::poll: returning 0
14:05:20 [main] rsync 1468 select_stuff::cleanup: calling cleanup routines
14:05:20 [main] rsync 1468 select_stuff::~select_stuff: deleting select records
14:05:20 [main] rsync 1468 cygwin_select: 6, 0x22E4C0, 0x22E4B8, 0x0, 0x22E4B0
14:05:20 [main] rsync 1468 dtable::select_read:  fd 5
14:05:20 [main] rsync 1468 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms
60000
14:05:20 [main] rsync 1468 cygwin_select: sel.always_ready 0
14:05:20 [main] rsync 1468 start_thread_socket: Handle 0x3E8
14:05:20 [main] rsync 1468 start_thread_socket: Added to readfds
14:05:20 [main] rsync 1468 start_thread_socket: exitsock 0x324
14:05:20 [main] rsync 1468 start_thread_socket: stuff_start 0x22E434
14:05:20 [main] rsync 1468 select_stuff::wait: m 2, ms 60000
14:05:20 [select_socket] rsync 1468 thread_socket: stuff_start 0x101BE98C
14:06:20 [main] rsync 1468 select_stuff::wait: timed out
14:06:20 [main] rsync 1468 select_stuff::wait: returning 1
14:06:20 [main] rsync 1468 select_stuff::cleanup: calling cleanup routines
14:06:20 [main] rsync 1468 socket_cleanup: si 0x101BB968 si->thread
0x610F38B0
14:06:20 [main] rsync 1468 socket_cleanup: connection to si->exitsock 0x324
14:06:20 [select_socket] rsync 1468 thread_socket: Win32 select returned 1
14:06:20 [select_socket] rsync 1468 thread_socket: s 0x10012A58, testing fd 5 ()
14:06:20 [select_socket] rsync 1468 thread_socket: saw exitsock read
14:06:20 [main] rsync 1468 socket_cleanup: returning
14:06:20 [main] rsync 1468 peek_socket: considering handle 0x3E8
14:06:20 [main] rsync 1468 peek_socket: adding read fd_set , fd 5
14:06:20 [main] rsync 1468 peek_socket: WINSOCK_SELECT returned 0
14:06:20 [main] rsync 1468 select_stuff::poll: returning 0
14:06:21 [main] rsync 1468 select_stuff::cleanup: calling cleanup routines
14:06:21 [main] rsync 1468 select_stuff::~select_stuff: deleting select records
14:06:21 [main] rsync 1468 cygwin_select: 6, 0x22E4C0, 0x22E4B8, 0x0, 0x22E4B0
14:06:21 [main] rsync 1468 dtable::select_read:  fd 5
14:06:21 [main] rsync 1468 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms
60000
14:06:21 [main] rsync 1468 cygwin_select: sel.always_ready 0
14:06:21 [main] rsync 1468 start_thread_socket: Handle 0x3E8
14:06:21 [main] rsync 1468 start_thread_socket: Added to readfds
14:06:21 [main] rsync 1468 start_thread_socket: exitsock 0x324
14:06:21 [main] rsync 1468 start_thread_socket: stuff_start 0x22E434
14:06:21 [main] rsync 1468 select_stuff::wait: m 2, ms 60000
14:06:21 [select_socket] rsync 1468 thread_socket: stuff_start 0x101BE98C
14:07:21 [main] rsync 1468 select_stuff::wait: timed out
14:07:21 [main] rsync 1468 select_stuff::wait: returning 1
14:07:21 [main] rsync 1468 select_stuff::cleanup: calling cleanup routines
14:07:21 [main] rsync 1468 socket_cleanup: si 0x101BB968 si->thread
0x610F38B0
14:07:21 [main] rsync 1468 socket_cleanup: connection to si->exitsock 0x324
14:07:21 [select_socket] rsync 1468 thread_socket: Win32 select returned 1
14:07:21 [select_socket] rsync 1468 thread_socket: s 0x10012A58, testing fd 5 ()
14:07:21 [select_socket] rsync 1468 thread_socket: saw exitsock read
14:07:21 [main] rsync 1468 socket_cleanup: returning
14:07:21 [main] rsync 1468 peek_socket: considering handle 0x3E8
14:07:21 [main] rsync 1468 peek_socket: adding read fd_set , fd 5
14:07:21 [main] rsync 1468 peek_socket: WINSOCK_SELECT returned 0
14:07:21 [main] rsync 1468 select_stuff::poll: returning 0
14:07:21 [main] rsync 1468 select_stuff::cleanup: calling cleanup routines
14:07:21 [main] rsync 1468 select_stuff::~select_stuff: deleting select records
14:07:21 [main] rsync 1468 cygwin_select: 6, 0x22E4C0, 0x22E4B8, 0x0, 0x22E4B0
14:07:21 [main] rsync 1468 dtable::select_read:  fd 5
14:07:21 [main] rsync 1468 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms
60000
14:07:21 [main] rsync 1468 cygwin_select: sel.always_ready 0
14:07:21 [main] rsync 1468 start_thread_socket: Handle 0x3E8
14:07:21 [main] rsync 1468 start_thread_socket: Added to readfds
14:07:21 [main] rsync 1468 start_thread_socket: exitsock 0x324
14:07:21 [main] rsync 1468 start_thread_socket: stuff_start 0x22E434
14:07:21 [main] rsync 1468 select_stuff::wait: m 2, ms 60000
14:07:21 [select_socket] rsync 1468 thread_socket: stuff_start 0x101BE98C
14:08:21 [main] rsync 1468 select_stuff::wait: timed out
14:08:21 [main] rsync 1468 select_stuff::wait: returning 1
14:08:21 [main] rsync 1468 select_stuff::cleanup: calling cleanup routines
14:08:21 [main] rsync 1468 socket_cleanup: si 0x101BB968 si->thread
0x610F38B0
14:08:21 [main] rsync 1468 socket_cleanup: connection to si->exitsock 0x324
14:08:21 [select_socket] rsync 1468 thread_socket: Win32 select returned 1
14:08:21 [select_socket] rsync 1468 thread_socket: s 0x10012A58, testing fd 5 ()
14:08:21 [select_socket] rsync 1468 thread_socket: saw exitsock read
14:08:21 [main] rsync 1468 socket_cleanup: returning
14:08:21 [main] rsync 1468 peek_socket: considering handle 0x3E8
14:08:21 [main] rsync 1468 peek_socket: adding read fd_set , fd 5
14:08:21 [main] rsync 1468 peek_socket: WINSOCK_SELECT returned 0
14:08:21 [main] rsync 1468 select_stuff::poll: returning 0
14:08:21 [main] rsync 1468 select_stuff::cleanup: calling cleanup routines
14:08:21 [main] rsync 1468 select_stuff::~select_stuff: deleting select records
14:08:21 [main] rsync 1468 cygwin_select: 6, 0x22E4C0, 0x22E4B8, 0x0, 0x22E4B0
14:08:21 [main] rsync 1468 dtable::select_read:  fd 5
14:08:21 [main] rsync 1468 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms
60000
14:08:21 [main] rsync 1468 cygwin_select: sel.always_ready 0
14:08:21 [main] rsync 1468 start_thread_socket: Handle 0x3E8
14:08:21 [main] rsync 1468 start_thread_socket: Added to readfds
14:08:21 [main] rsync 1468 start_thread_socket: exitsock 0x324
14:08:21 [main] rsync 1468 start_thread_socket: stuff_start 0x22E434
14:08:21 [main] rsync 1468 select_stuff::wait: m 2, ms 60000
14:08:21 [select_socket] rsync 1468 thread_socket: stuff_start 0x101BE98C
14:09:21 [main] rsync 1468 select_stuff::wait: timed out
14:09:21 [main] rsync 1468 select_stuff::wait: returning 1
14:09:21 [main] rsync 1468 select_stuff::cleanup: calling cleanup routines
14:09:21 [main] rsync 1468 socket_cleanup: si 0x101BB968 si->thread
0x610F38B0
14:09:21 [main] rsync 1468 socket_cleanup: connection to si->exitsock 0x324
14:09:21 [select_socket] rsync 1468 thread_socket: Win32 select returned 1
14:09:21 [select_socket] rsync 1468 thread_socket: s 0x10012A58, testing fd 5 ()
14:09:21 [select_socket] rsync 1468 thread_socket: saw exitsock read
14:09:21 [main] rsync 1468 socket_cleanup: returning
14:09:21 [main] rsync 1468 peek_socket: considering handle 0x3E8
14:09:21 [main] rsync 1468 peek_socket: adding read fd_set , fd 5
14:09:22 [main] rsync 1468 peek_socket: WINSOCK_SELECT returned 0
14:09:22 [main] rsync 1468 select_stuff::poll: returning 0
14:09:22 [main] rsync 1468 select_stuff::cleanup: calling cleanup routines
14:09:22 [main] rsync 1468 select_stuff::~select_stuff: deleting select records
14:09:22 [main] rsync 1468 cygwin_select: 6, 0x22E4C0, 0x22E4B8, 0x0, 0x22E4B0
14:09:22 [main] rsync 1468 dtable::select_read:  fd 5
14:09:22 [main] rsync 1468 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms
60000
14:09:22 [main] rsync 1468 cygwin_select: sel.always_ready 0
14:09:22 [main] rsync 1468 start_thread_socket: Handle 0x3E8
14:09:22 [main] rsync 1468 start_thread_socket: Added to readfds
14:09:22 [main] rsync 1468 start_thread_socket: exitsock 0x324
14:09:22 [main] rsync 1468 start_thread_socket: stuff_start 0x22E434
14:09:22 [main] rsync 1468 select_stuff::wait: m 2, ms 60000
14:09:22 [select_socket] rsync 1468 thread_socket: stuff_start 0x101BE98C

Hi,

I really need to get the bottom of this problem. I have now experienced the hang
while
synching two local directories.

Can you explain to me the relationship between the parent rsync process and
it's children?
At the time of the latest hang, there two children rsync processes. Why not use
a single
process?

Jim

Thanks for the additional info.

I actually have tried the --no-blocking-io option, but the sync still hung.

Since no one on Unix-like platforms are reporting an issue, do you think it may
be
something in the Cygwin compatibility layer?

Interestingly (to me anyway,) is that I have encountered the problem with
syncing
across the network using ssh, and syncing locally, but not over the network 
rsync to rsync. Maybe it's just a matter of time....


   -------Original Message-------
   > From: Wayne Davison <wayned@samba.org>
   > Subject: Re: rsync 2.6.3 hang (was rsync 2.6.2 crash)
   > Sent: 05 Oct 2004 10:06:15
   >
   >  On Tue, Oct 05, 2004 at 07:07:17AM -0700, jim wrote:
   >  > Can you explain to me the relationship between the parent rsync
   >  > process and it's children?
   >  
   >  Rsync has a separate process for each major function.
   >  
   >  The generator process (on the receiving side) has the job of figuring
   >  out which files are different and sending checksum data for all the
   >  files it wants to see updated.  It sends that data to the sender.
   >  
   >  The sender has the job of taking the checksum data and generating a
   >  stream of data that can be used to recreate the sender's file using
the
   >  receiver's file as a source of data.  It talks to the receiver
process
   >  (which is on the same system as the generator, and which actually
   >  spawned the generator when things were starting up).
   >  
   >  The receiver has the job of taking the update data from the sender and
   >  turning it into the final updated files.  The final bit of
communication
   >  is that the receiver has a pipe between it and the generator that can
be
   >  used to send the generator some messages that need to be forwarded to
   >  the sender (since it can't send things to the sender directly).
   >  
   >  All these channels are selected for reading and writing using the
   >  select() function.  Most of the processes are in a constant state of
I/O
   >  blocking, which is just fine going from the generator to the sender to
   >  the receiver.  However, the channel from the receiver to the generator
   >  has to be kept unblocked by buffering any messages that appear so that
   >  rsync doesn't deadlock.  That should all be handled just fine
unless
   >  there is a bug.
   >  
   >  In the trace output you sent, it looks like the sender is waiting to
   >  write to the socket, the receiver is waiting to read from the socket,
   >  and the generator is waiting simultaneously on reading the pipe and
   >  writing the socket, so I don't see anything wrong there.
   >  
   >  One thing you might try is specifying --no-blocking-io and see if that
   >  makes a difference in the hanging you're seeing.
   >  
   >  ..wayne..
   -------Original Message-------

Wayne,

I'm trying to debug the hanging problem. I rebuilt cygwin1.dll to include
debugging
info, and I'm using rsync 2.6.3 compiled without optimization and with -g. I
need a
little assistance with gdb. 

When I attach to a hung rsync process, none of the backtraces of any of the
threads
seem to have any stack frames showing calls from rsync code. I think the
backtrace
I sent to the mailing list was the same way.  What am I doing wrong? Also, why
does the rsync process have four threads? Do these threads get started before
main
is called?

Thanks,
Jim

> "jim" writes:
 >
 > > Thanks for the additional info.
 > >
 > > I actually have tried the --no-blocking-io option, but the sync
 > > still hung.
 > >
 > > Since no one on Unix-like platforms are reporting an issue, do you
 > > think it may be something in the Cygwin compatibility layer?
 >
 
 > Yes, I think so.  When I tried to debug this some time ago with rsync
 > over ssh using cygwin I found that data that was flushed by one end's
 > rsync never arrived at the other end: the other end was still blocked
 > on select. I presume that somewhere between rsync/ssh/cygwin, and
 > cygwin/ssh/rsync on the other end, some buffer was not getting flushed
 > properly. I don't know anything about cygwin internals, so I
didn't
 > look at this further.
 >
 
 If its worth it, I too was getting hangs with rsync and cygwin (latest
 release of both).  I now actually run rsync over stunnel under windows :
 
 http://www.stunnel.org/examples/rsync_mike.html
 
 This seems to work quite well, with no more hangs I have seen :)
 
 Hope this can be of some help.
 
  Regards,
 
  Paul Arch

Thanks for the suggestions for different tunneling tools. This really only helps
with half
my problem- I need to sync local dirs, too. I'm guessing that this is really
a cygwin problem
in select(), but I'm not a good enough programmer to dig into it. I've
got a local guru
looking at it, but I think I may have to investigate other options, such as
Unison
(http://www.cis.upenn.edu/~bcpierce/unison/index.html).

Right. This is the command that hangs for a local sync:

rsync -Pvvvtr --delete /cygdrive/f/ /cygdrive/e

It hangs at different places, sometimes during the file list generation,
sometimes during the copying. It's very similar to what I saw doing 
remote syncing. I double checked that file contents are readable
(no disk problems or file locks). 

If I comment that out, how will that affect a remote sync?


   -------Original Message-------
   > From: Wayne Davison <wayned@samba.org>
   > Subject: Re: rsync 2.6.3 hang (was rsync 2.6.2 crash)
   > Sent: 07 Oct 2004 10:09:16
   >
   >  When you say that a local copy hangs, I'm assuming you're not
using the
   >  host: name for the local machine or "localhost:", right?
   >  
   >  If HAVE_SOCKETPAIR is defined in config.h, I'd suggest commenting
it
   >  out, recompiling, and trying the local copying again -- perhaps having
   >  rsync use pipes instead of socketpairs will avoid a hang.
   >  
   >  ..wayne..
   -------Original Message-------