On Thu, Dec 13, 2007 at 12:35:03PM +0100, Otto Moerbeek wrote: > On Thu, Dec 13, 2007 at 11:10:51AM +0000, Stuart Henderson wrote: > > > On 2007/12/13 09:09, Otto Moerbeek wrote: > > > It's depening on the application if sockets staying in CLOSE_WAIT are > > > a problem or not: it might be intentional (in the hulp duplex case), > > Strange typo by me... that's a Dutch word, but not very relevant in > this context. It should be half-duplex of course. Stupid autonomous > fingers ;-) > > > > or it might be a program "forgetting" to do a close. > > > > Does select() notify the application of FIN from the other side? > > > > If not, that would explain things, it wouldn't be reasonable for > > httpd to manually try and receive from all sockets in keepalive > > to see whether it needs to close the socket, since it will only > > wait KeepAliveTimeout (default 15s) before it closes them anyway. > > Nice suggestion, but if you've marked the fd for read I would expect > select to notify if the other side does a shutdown(SHUT_WR). > > Other scenarios are also thinkable: like the server socket being > blocked because of outgoing data that cannot be written out. That > might prevent the server from doing a close too. But in the end the > close will happen, otherwise you would run out of fd's very soon. >
I have been doing a little ktrace:ing on the httpd worker process(es) that gets stuck with a socket in CLOSE_WAIT. It appears when it finally (after e.g 8.5 minutes) continues, it: 28749 httpd 1197541469.470707 EMUL "native" 28749 httpd 53.276754 RET write -1 errno 32 Broken pipe 28749 httpd 0.000031 CALL close(0x4) 28749 httpd 0.000005 RET close 0 28749 httpd 0.000012 CALL gettimeofday(0xcfbd12c8,0) 28749 httpd 0.000002 RET gettimeofday 0 28749 httpd 0.000002 CALL gettimeofday(0xcfbd12c8,0) 28749 httpd 0.000001 RET gettimeofday 0 28749 httpd 0.000002 CALL stat(0x2d5a3945,0xcfbd1370) 28749 httpd 0.000002 NAMI "/etc/resolv.conf" 28749 httpd 0.000009 RET stat 0 28749 httpd 0.000012 CALL open(0x2d5a1ffb,0,0x1b6) 28749 httpd 0.000004 NAMI "/etc/hosts" 28749 httpd 0.000005 RET open 4 28749 httpd 0.000003 CALL fstat(0x4,0xcfbd16d0) 28749 httpd 0.000002 RET fstat 0 28749 httpd 0.000003 CALL mprotect(0x8111e000,0x1000,0x3) 28749 httpd 0.000005 RET mprotect 0 28749 httpd 0.000006 CALL mprotect(0x8111e000,0x1000,0x1) 28749 httpd 0.000003 RET mprotect 0 28749 httpd 0.000002 CALL read(0x4,0x8103a000,0x4000) 28749 httpd 0.000004 GIO fd 4 read 725 bytes that must be the start of finding my own hostname, it proceeds with looking up the remote host over DNS and then writes a log entry: 28749 httpd 0.000019 CALL write(0x16,0x7cc0b4ac,0x7c) 28749 httpd 0.000008 GIO fd 22 wrote 124 bytes : 28749 httpd 0.000002 RET write 124/0x7c 28749 httpd 0.000011 CALL close(0x3) 28749 httpd 0.000016 RET close 0 28749 httpd 0.000003 CALL sigaction(0x1e,0xcfbd1e00,0xcfbd1df0) 28749 httpd 0.000003 RET sigaction 0 28749 httpd 0.000004 CALL accept(0x12,0xcfbd1e50,0xcfbd1e3c) 28749 httpd 2.751318 RET accept 3 there comes the next connection. Note the close(0x3) call. The lsof output said the HTTP connection socket had fd 3. To compare with the end of a later successful request/reply in the same log: 28749 httpd 0.000004 CALL write(0x3,0x85b7200c,0xb57) 28749 httpd 0.000042 GIO fd 3 wrote 2903 bytes : 28749 httpd 0.000010 RET write 2903/0xb57 28749 httpd 0.000006 CALL gettimeofday(0xcfbd12c8,0) 28749 httpd 0.000003 RET gettimeofday 0 28749 httpd 0.000002 CALL gettimeofday(0xcfbd12c8,0) 28749 httpd 0.000002 RET gettimeofday 0 28749 httpd 0.000001 CALL stat(0x2d5a3945,0xcfbd1370) 28749 httpd 0.000002 NAMI "/etc/resolv.conf" 28749 httpd 0.000009 RET stat 0 and then lookup of my name and the other name, and write log: 28749 httpd 0.000021 CALL write(0x16,0x7cc0b2ac,0x97) 28749 httpd 0.000008 GIO fd 22 wrote 151 bytes : 28749 httpd 0.000002 RET write 151/0x97 28749 httpd 0.000011 CALL shutdown(0x3,0x1) 28749 httpd 0.000017 RET shutdown 0 28749 httpd 0.000003 CALL select(0x4,0xcfbd1b70,0,0,0xcfbd1b68) 28749 httpd 0.115966 RET select 1 28749 httpd 0.000009 CALL read(0x3,0xcfbd1bf0,0x200) 28749 httpd 0.000004 RET read 0 28749 httpd 0.000004 CALL close(0x3) 28749 httpd 0.000004 RET close 0 28749 httpd 0.000005 CALL sigaction(0x1e,0xcfbd1e00,0xcfbd1df0) 28749 httpd 0.000002 RET sigaction 0 28749 httpd 0.000002 CALL munmap(0x8b60d000,0xa2b) 28749 httpd 0.000018 RET munmap 0 28749 httpd 0.000016 CALL accept(0x12,0xcfbd1e50,0xcfbd1e3c) Note that close(0x3) follows after select() RET 1, read() RET 0. In the fail case log, close(0x3) is called without select() and read() probably because it is already known fd 3 is dead due to the failing write(). So, the conclusion closest at hand is that it is a write of HTTP data on fd 3 that times out with "errno 32 Broken pipe" after 8.5 minutes, even though lsof reports the socket as being in CLOSE_WAIT. Then the question is if this is a TCP stack bug, or a feature. One might expect write() to return immediately when the socket enters CLOSE_WAIT due to remote end socket close... > -Otto -- / Raimo Niskanen, Erlang/OTP, Ericsson AB
