This is the mail archive of the cygwin mailing list for the Cygwin project.

Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]
Other format: [Raw text]

strace data seems to show hang during socket close

I trying to debug an aparrent hang problem in clamav's clamd.

Under my test load, I can usually get clamd to hang rather easily. Today I got lucky and managed to get an strace of the hang happening (usually the hang doesn't happen while stracing...). When this app hung, it stopped consuming any CPU cycles.

Now, I'm trying to interpret the strace results to get a clue about what isn't working right.

When clamd hung, the clamd log file ended with the following lines:

Wed Jun  1 15:57:10 2005 -> stream 1753: OK
Wed Jun  1 16:00:11 2005 -> ERROR: ScanStream 2043: accept timeout.
Wed Jun  1 16:00:14 2005 -> ERROR: ScanStream 1289: accept timeout.

I'm trying to understand why it appears that the two worker threads (0x95C and 0x490) seem to have "disappeared" and hung indefinately while attempting to close a socket. Why might this happen?

strace was invoked with: strace --pid=3772 --output=clamd.strace --flush-period=30 --mask=all

The end of the strace data contains.

311 528007410 [unknown (0x948)] clamd 3772 writev: 44 = write (3, 0x26CC500, 1), errno 90
247 528007657 [unknown (0x948)] clamd 3772 close: close (11)
1606 528009263 [unknown (0x948)] clamd 3772 fhandler_socket::close: 0 = fhandler_socket::close()
210 528009473 [unknown (0x948)] clamd 3772 close: 0 = close (11)
409 528009882 [unknown (0x948)] clamd 3772 time: 1117666631 = time (0)
1068 528010950 [unknown (0x948)] clamd 3772 _cygtls::remove: wait 0xFFFFFFFF
527 528011477 [unknown (0x948)] clamd 3772 _cygtls::remove: removed 0x26CF0A0 element 6
228 528011705 [unknown (0x948)] clamd 3772 _cygtls::remove: wait 0x0
26718851 554730556 [select_socket] clamd 3772 thread_socket: Win32 select returned 1
274 554730830 [select_socket] clamd 3772 thread_socket: s 0x102F7C28, testing fd 4 ()
321 554731151 [select_socket] clamd 3772 thread_socket: read_ready
3275 554734426 [main] clamd 3772 select_stuff::wait: woke up. wait_ret 1. verifying
221 554734647 [main] clamd 3772 select_stuff::wait: gotone 1
131 554734778 [main] clamd 3772 select_stuff::wait: returning 0
605 554735383 [main] clamd 3772 select_stuff::cleanup: calling cleanup routines
175 554735558 [main] clamd 3772 socket_cleanup: si 0x10B48140 si->thread 0x610FFC60
185 554735743 [main] clamd 3772 socket_cleanup: sent a byte to exitsock 0x2C4, res 1
249 554735992 [main] clamd 3772 socket_cleanup: reading a byte from exitsock 0x2C4
528 554736520 [main] clamd 3772 socket_cleanup: recv returned 1
615 554737135 [main] clamd 3772 socket_cleanup: returning
133 554737268 [main] clamd 3772 peek_socket: considering handle 0x2F0
160 554737428 [main] clamd 3772 set_bits: me 0x102F7C28, testing fd 4 ()
117 554737545 [main] clamd 3772 set_bits: ready 1
629 554738174 [main] clamd 3772 select_stuff::poll: returning 1
372 554738546 [main] clamd 3772 select_stuff::cleanup: calling cleanup routines
134 554738680 [main] clamd 3772 select_stuff::~select_stuff: deleting select records
435 554739115 [main] clamd 3772 fdsock: reset socket inheritance since winsock2_active 1
395 554739510 [main] clamd 3772 build_fh_pc: fh 0x61816738
156 554739666 [main] clamd 3772 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
116 554739782 [main] clamd 3772 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
111 554739893 [main] clamd 3772 fhandler_base::set_flags: filemode set to binary
110 554740003 [main] clamd 3772 fdsock: fd 6, name '', soc 0x3FC
109 554740112 [main] clamd 3772 fhandler_socket::accept: res 6
522 554740634 [main] clamd 3772 cygwin_accept: 6 = accept (4, 0x0, 0x0)
153999229 708739863 [unknown (0x490)] clamd 3772 select_stuff::wait: timed out
282 708740145 [unknown (0x490)] clamd 3772 select_stuff::wait: returning 1
129 708740274 [unknown (0x490)] clamd 3772 select_stuff::cleanup: calling cleanup routines
121 708740395 [unknown (0x490)] clamd 3772 socket_cleanup: si 0x10448370 si->thread 0x610FFC08
303 708740698 [unknown (0x490)] clamd 3772 socket_cleanup: sent a byte to exitsock 0x28C, res 1
1332 708742030 [select_socket] clamd 3772 thread_socket: Win32 select returned 1
213 708742243 [select_socket] clamd 3772 thread_socket: s 0x10222FB0, testing fd 5 ()
122 708742365 [select_socket] clamd 3772 thread_socket: saw exitsock read
389 708742754 [unknown (0x490)] clamd 3772 socket_cleanup: reading a byte from exitsock 0x28C
263 708743017 [unknown (0x490)] clamd 3772 socket_cleanup: recv returned 1
250 708743267 [unknown (0x490)] clamd 3772 socket_cleanup: returning
120 708743387 [unknown (0x490)] clamd 3772 peek_socket: considering handle 0x7C
116 708743503 [unknown (0x490)] clamd 3772 peek_socket: adding read fd_set , fd 5
762 708744265 [unknown (0x490)] clamd 3772 peek_socket: adding except fd_set , fd 5
429 708744694 [unknown (0x490)] clamd 3772 peek_socket: WINSOCK_SELECT returned 0
155 708744849 [unknown (0x490)] clamd 3772 select_stuff::poll: returning 0
118 708744967 [unknown (0x490)] clamd 3772 select_stuff::cleanup: calling cleanup routines
203 708745170 [unknown (0x490)] clamd 3772 select_stuff::~select_stuff: deleting select records
705 708745875 [unknown (0x490)] clamd 3772 __set_winsock_errno: sendto:1239 - winsock error 10053 -> errno 113
148 708746023 [unknown (0x490)] clamd 3772 cygwin_sendto: -1 = sendto (29, 0x10CC870, 22, 0, 0x0, 0)
131 708746154 [unknown (0x490)] clamd 3772 time: 1117666811 = time (10CC5CC)
1383 708747537 [unknown (0x490)] clamd 3772 stat64: entering
163 708747700 [unknown (0x490)] clamd 3772 normalize_posix_path: src /var/log/clamd.log
119 708747819 [unknown (0x490)] clamd 3772 normalize_posix_path: /var/log/clamd.log = normalize_posix_path (/var/log/clamd.log)
122 708747941 [unknown (0x490)] clamd 3772 mount_info::conv_to_win32_path: conv_to_win32_path (/var/log/clamd.log)
1608 708749549 [unknown (0x490)] clamd 3772 set_flags: flags: binary (0x2)
14886 708764435 [unknown (0x490)] clamd 3772 mount_info::conv_to_win32_path: src_path /var/log/clamd.log, dst C:\cygwin\var\log\clamd.log, flags 0xA, rc 0
407 708764842 [unknown (0x490)] clamd 3772 symlink_info::check: not a symlink
1213 708766055 [unknown (0x490)] clamd 3772 symlink_info::check: 0 = symlink.check (C:\cygwin\var\log\clamd.log, 0x10CBF70) (0xA)
207 708766262 [unknown (0x490)] clamd 3772 path_conv::check: this->path(C:\cygwin\var\log\clamd.log), has_acls(1)
132 708766394 [unknown (0x490)] clamd 3772 build_fh_pc: fh 0x61814AC8
120 708766514 [unknown (0x490)] clamd 3772 stat_worker: (/var/log/clamd.log, 0x10CC5D0, 0, 0x61814AC8), file_attributes 32
174 708766688 [unknown (0x490)] clamd 3772 fhandler_base::open: (C:\cygwin\var\log\clamd.log, 0x110000)
268 708766956 [unknown (0x490)] clamd 3772 fhandler_base::set_flags: flags 0x110000, supplied_bin 0x10000
512 708767468 [unknown (0x490)] clamd 3772 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
264 708767732 [unknown (0x490)] clamd 3772 fhandler_base::set_flags: filemode set to binary
140 708767872 [unknown (0x490)] clamd 3772 fhandler_base::open: 0 = NtCreateFile (0x20, 20080, C:\cygwin\var\log\clamd.log, io, NULL, 0, 7, 1, 4000, NULL, 0)
120 708767992 [unknown (0x490)] clamd 3772 fhandler_base::open: 1 = fhandler_base::open (C:\cygwin\var\log\clamd.log, 0x110000)
118 708768110 [unknown (0x490)] clamd 3772 fhandler_base::open_fs: 1 = fhandler_disk_file::open (C:\cygwin\var\log\clamd.log, 0x10000)
158 708768268 [unknown (0x490)] clamd 3772 get_file_attribute: file: C:\cygwin\var\log\clamd.log
910 708769178 [unknown (0x490)] clamd 3772 cygpsid::debug_print: get_sids_info: owner SID = S-1-5-21-1645522239-926492609-682003330-1112
830 708770008 [unknown (0x490)] clamd 3772 cygpsid::debug_print: get_sids_info: group SID = S-1-5-32-545
171 708770179 [unknown (0x490)] clamd 3772 get_info_from_sd: ACL 1A0, uid 11112, gid 10545
416 708770595 [unknown (0x490)] clamd 3772 fhandler_base::fstat_helper: 0 = fstat (, 0x10CC5D0) st_atime=429E3D47 st_size=23601972, st_mode=0x81A0, st_ino=22949, sizeof=96
1592 708772187 [unknown (0x490)] clamd 3772 fhandler_base::close: closing '/var/log/clamd.log' handle 0x20
268 708772455 [unknown (0x490)] clamd 3772 stat_worker: 0 = (/var/log/clamd.log, 0x10CC5D0)
850 708773305 [unknown (0x490)] clamd 3772 fhandler_base::lseek: lseek (/var/log/clamd.log, 0, 2)
126 708773431 [unknown (0x490)] clamd 3772 fhandler_base::lseek: setting file pointer to 0 (high), 0 (low)
130 708773561 [unknown (0x490)] clamd 3772 lseek64: 23601972 = lseek (3, 0, 2)
149 708773710 [unknown (0x490)] clamd 3772 writev: writev (3, 0x10CC500, 1)
130 708773840 [unknown (0x490)] clamd 3772 fhandler_base::write: binary write
265 708774105 [unknown (0x490)] clamd 3772 writev: 68 = write (3, 0x10CC500, 1), errno 113
236 708774341 [unknown (0x490)] clamd 3772 close: close (5)
345 708774686 [unknown (0x490)] clamd 3772 fhandler_socket::close: 0 = fhandler_socket::close()
164 708774850 [unknown (0x490)] clamd 3772 close: 0 = close (5)
126 708774976 [unknown (0x490)] clamd 3772 close: close (29)
1046 708776022 [unknown (0x490)] clamd 3772 fhandler_socket::close: 0 = fhandler_socket::close()
206 708776228 [unknown (0x490)] clamd 3772 close: 0 = close (29)
2680015 711456243 [unknown (0x95C)] clamd 3772 select_stuff::wait: timed out
592 711456835 [unknown (0x95C)] clamd 3772 select_stuff::wait: returning 1
190 711457025 [unknown (0x95C)] clamd 3772 select_stuff::cleanup: calling cleanup routines
1616 711458641 [unknown (0x95C)] clamd 3772 socket_cleanup: si 0x101B67A8 si->thread 0x610FFC34
274 711458915 [unknown (0x95C)] clamd 3772 socket_cleanup: sent a byte to exitsock 0x214, res 1
236 711459151 [select_socket] clamd 3772 thread_socket: Win32 select returned 1
20814 711479965 [select_socket] clamd 3772 thread_socket: s 0x10BA70B8, testing fd 8 ()
206 711480171 [select_socket] clamd 3772 thread_socket: saw exitsock read
908 711481079 [unknown (0x95C)] clamd 3772 socket_cleanup: reading a byte from exitsock 0x214
184 711481263 [unknown (0x95C)] clamd 3772 socket_cleanup: recv returned 1
757 711482020 [unknown (0x95C)] clamd 3772 socket_cleanup: returning
193 711482213 [unknown (0x95C)] clamd 3772 peek_socket: considering handle 0x158
159 711482372 [unknown (0x95C)] clamd 3772 peek_socket: adding read fd_set , fd 8
122 711482494 [unknown (0x95C)] clamd 3772 peek_socket: adding except fd_set , fd 8
156 711482650 [unknown (0x95C)] clamd 3772 peek_socket: WINSOCK_SELECT returned 0
126 711482776 [unknown (0x95C)] clamd 3772 select_stuff::poll: returning 0
558 711483334 [unknown (0x95C)] clamd 3772 select_stuff::cleanup: calling cleanup routines
175 711483509 [unknown (0x95C)] clamd 3772 select_stuff::~select_stuff: deleting select records
4210 711487719 [unknown (0x95C)] clamd 3772 __set_winsock_errno: sendto:1239 - winsock error 10053 -> errno 113
162 711487881 [unknown (0x95C)] clamd 3772 cygwin_sendto: -1 = sendto (30, 0x14CC870, 22, 0, 0x0, 0)
132 711488013 [unknown (0x95C)] clamd 3772 time: 1117666814 = time (14CC5CC)
1376 711489389 [unknown (0x95C)] clamd 3772 stat64: entering
132 711489521 [unknown (0x95C)] clamd 3772 normalize_posix_path: src /var/log/clamd.log
119 711489640 [unknown (0x95C)] clamd 3772 normalize_posix_path: /var/log/clamd.log = normalize_posix_path (/var/log/clamd.log)
252 711489892 [unknown (0x95C)] clamd 3772 mount_info::conv_to_win32_path: conv_to_win32_path (/var/log/clamd.log)
138 711490030 [unknown (0x95C)] clamd 3772 set_flags: flags: binary (0x2)
123 711490153 [unknown (0x95C)] clamd 3772 mount_info::conv_to_win32_path: src_path /var/log/clamd.log, dst C:\cygwin\var\log\clamd.log, flags 0xA, rc 0
330 711490483 [unknown (0x95C)] clamd 3772 symlink_info::check: not a symlink
181 711490664 [unknown (0x95C)] clamd 3772 symlink_info::check: 0 = symlink.check (C:\cygwin\var\log\clamd.log, 0x14CBF70) (0xA)
126 711490790 [unknown (0x95C)] clamd 3772 path_conv::check: this->path(C:\cygwin\var\log\clamd.log), has_acls(1)
431 711491221 [unknown (0x95C)] clamd 3772 build_fh_pc: fh 0x618156F8
199 711491420 [unknown (0x95C)] clamd 3772 stat_worker: (/var/log/clamd.log, 0x14CC5D0, 0, 0x618156F8), file_attributes 32
141 711491561 [unknown (0x95C)] clamd 3772 fhandler_base::open: (C:\cygwin\var\log\clamd.log, 0x110000)
260 711491821 [unknown (0x95C)] clamd 3772 fhandler_base::set_flags: flags 0x110000, supplied_bin 0x10000
160 711491981 [unknown (0x95C)] clamd 3772 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
123 711492104 [unknown (0x95C)] clamd 3772 fhandler_base::set_flags: filemode set to binary
289 711492393 [unknown (0x95C)] clamd 3772 fhandler_base::open: 0 = NtCreateFile (0x428, 20080, C:\cygwin\var\log\clamd.log, io, NULL, 0, 7, 1, 4000, NULL, 0)
145 711492538 [unknown (0x95C)] clamd 3772 fhandler_base::open: 1 = fhandler_base::open (C:\cygwin\var\log\clamd.log, 0x110000)
120 711492658 [unknown (0x95C)] clamd 3772 fhandler_base::open_fs: 1 = fhandler_disk_file::open (C:\cygwin\var\log\clamd.log, 0x10000)
156 711492814 [unknown (0x95C)] clamd 3772 get_file_attribute: file: C:\cygwin\var\log\clamd.log
427 711493241 [unknown (0x95C)] clamd 3772 cygpsid::debug_print: get_sids_info: owner SID = S-1-5-21-1645522239-926492609-682003330-1112
1077 711494318 [unknown (0x95C)] clamd 3772 cygpsid::debug_print: get_sids_info: group SID = S-1-5-32-545
237 711494555 [unknown (0x95C)] clamd 3772 get_info_from_sd: ACL 1A0, uid 11112, gid 10545
230 711494785 [unknown (0x95C)] clamd 3772 fhandler_base::fstat_helper: 0 = fstat (, 0x14CC5D0) st_atime=429E3DFD st_size=23602040, st_mode=0x81A0, st_ino=22949, sizeof=96
124 711494909 [unknown (0x95C)] clamd 3772 fhandler_base::close: closing '/var/log/clamd.log' handle 0x428
182 711495091 [unknown (0x95C)] clamd 3772 stat_worker: 0 = (/var/log/clamd.log, 0x14CC5D0)
1549 711496640 [unknown (0x95C)] clamd 3772 fhandler_base::lseek: lseek (/var/log/clamd.log, 0, 2)
553 711497193 [unknown (0x95C)] clamd 3772 fhandler_base::lseek: setting file pointer to 0 (high), 0 (low)
230 711497423 [unknown (0x95C)] clamd 3772 lseek64: 23602040 = lseek (3, 0, 2)
133 711497556 [unknown (0x95C)] clamd 3772 writev: writev (3, 0x14CC500, 1)
131 711497687 [unknown (0x95C)] clamd 3772 fhandler_base::write: binary write
131 711497818 [unknown (0x95C)] clamd 3772 writev: 68 = write (3, 0x14CC500, 1), errno 113
355 711498173 [unknown (0x95C)] clamd 3772 close: close (8)
368 711498541 [unknown (0x95C)] clamd 3772 fhandler_socket::close: 0 = fhandler_socket::close()
164 711498705 [unknown (0x95C)] clamd 3772 close: 0 = close (8)
124 711498829 [unknown (0x95C)] clamd 3772 close: close (30)
220 711499049 [unknown (0x95C)] clamd 3772 fhandler_socket::close: 0 = fhandler_socket::close()
148 711499197 [unknown (0x95C)] clamd 3772 close: 0 = close (30)

Below corresponds to a kill -9 3772 I did some hours after the above output was produced.

-39462844 672036353 [sig] clamd 3772 sigpacket::process: signal 9 processing
278 672036631 [sig] clamd 3772 sigpacket::process: signal 9, about to call do_exit
409 672037040 [sig] clamd 3772 signal_exit: about to call do_exit (9)
130 672037170 [sig] clamd 3772 do_exit: do_exit (9), exit_state 0
36124 672073294 [sig] clamd 3772 void: 0x0 = signal (20, 0x1)
199 672073493 [sig] clamd 3772 void: 0x405170 = signal (1, 0x1)
119 672073612 [sig] clamd 3772 void: 0x405170 = signal (2, 0x1)
111 672073723 [sig] clamd 3772 void: 0x0 = signal (3, 0x1)
188 672073911 [sig] clamd 3772 fhandler_console::close: decremented open_fhs, now 3
157 672074068 [sig] clamd 3772 fhandler_console::close: decremented open_fhs, now 2
150 672074218 [sig] clamd 3772 fhandler_console::close: decremented open_fhs, now 1
662 672074880 [sig] clamd 3772 fhandler_base::close: closing '/var/log/clamd.log' handle 0x33C
680 672075560 [sig] clamd 3772 fhandler_socket::close: 0 = fhandler_socket::close()
423 672075983 [sig] clamd 3772 fhandler_socket::close: 0 = fhandler_socket::close()
305 672076288 [sig] clamd 3772 sigproc_terminate: entering
147 672076435 [sig] clamd 3772 proc_terminate: n

Thanks for any comments, observations or advise.

- Mark Pizzolato 


--
Unsubscribe info:      http://cygwin.com/ml/#unsubscribe-simple
Problem reports:       http://cygwin.com/problems.html
Documentation:         http://cygwin.com/docs.html
FAQ:                   http://cygwin.com/faq/

Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]