strace data seems to show hang during socket close

Mark Pizzolato list-cygwin@subscriptions.pizzolato.net
Thu Jun 2 21:28:00 GMT 2005


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/



More information about the Cygwin mailing list