Hi,
on my current project I have a strange error. Stunnel will work for months and suddenly stop accepting connections. At other times it will fail after a couple of hours. It doesn't crash. Connections are still accepted, but no SSL negotiation does take place. Please find a log below.
It seems to be some problem with libwrap. As you can see in the logs the last usage of libwrap doesn't release libwrap properly. "Released libwrap process" log statement is missing. And after that just everything hangs waiting for libwrap. But why is this happening?
Our host.allow and host.deny files are empty. libwrap is supposed to allow everything.
Any suggestions are welcome!
Thanks in advance
Ulrich
2009.02.10 09:23:16 LOG7[24594:3083130544]: epp accepted FD=22 from 212.227.111.32:59551 2009.02.10 09:23:16 LOG7[24594:3082640272]: epp started 2009.02.10 09:23:16 LOG7[24594:3082640272]: FD 22 in non-blocking mode 2009.02.10 09:23:16 LOG7[24594:3082640272]: TCP_NODELAY option set on local socket 2009.02.10 09:23:16 LOG7[24594:3082640272]: Waiting for a libwrap process 2009.02.10 09:23:16 LOG7[24594:3082640272]: Acquired libwrap process #4 2009.02.10 09:23:16 LOG7[24594:3082640272]: Releasing libwrap process #4 2009.02.10 09:23:16 LOG7[24594:3082640272]: Released libwrap process #4 2009.02.10 09:23:16 LOG7[24594:3082640272]: epp permitted by libwrap from 212.227.111.32:59551 2009.02.10 09:23:16 LOG5[24594:3082640272]: epp accepted connection from 212.227.111.32:59551 2009.02.10 09:23:16 LOG7[24594:3082640272]: SSL state (accept): before/accept initialization 2009.02.10 09:23:16 LOG7[24594:3082640272]: SSL state (accept): SSLv3 read client hello A 2009.02.10 09:23:16 LOG7[24594:3082640272]: SSL state (accept): SSLv3 write server hello A 2009.02.10 09:23:16 LOG7[24594:3082640272]: SSL state (accept): SSLv3 write certificate A 2009.02.10 09:23:16 LOG7[24594:3082640272]: SSL state (accept): SSLv3 write server done A 2009.02.10 09:23:16 LOG7[24594:3082640272]: SSL state (accept): SSLv3 flush data 2009.02.10 09:23:16 LOG7[24594:3082918800]: Socket closed on read 2009.02.10 09:23:16 LOG7[24594:3082918800]: SSL write shutdown 2009.02.10 09:23:16 LOG7[24594:3082918800]: SSL alert (write): warning: close notify 2009.02.10 09:23:16 LOG6[24594:3082918800]: SSL socket closed on SSL_shutdown 2009.02.10 09:23:16 LOG7[24594:3082918800]: Socket write shutdown 2009.02.10 09:23:16 LOG5[24594:3082918800]: Connection closed: 2249 bytes sent to SSL, 1169 bytes sent to socket 2009.02.10 09:23:16 LOG7[24594:3082918800]: epp finished (5 left) 2009.02.10 09:23:16 LOG7[24594:3082709904]: SSL state (accept): SSLv3 read client key exchange A 2009.02.10 09:23:16 LOG7[24594:3082709904]: SSL state (accept): SSLv3 read finished A 2009.02.10 09:23:16 LOG7[24594:3082709904]: SSL state (accept): SSLv3 write change cipher spec A 2009.02.10 09:23:16 LOG7[24594:3082709904]: SSL state (accept): SSLv3 write finished A 2009.02.10 09:23:16 LOG7[24594:3082709904]: SSL state (accept): SSLv3 flush data 2009.02.10 09:23:16 LOG7[24594:3082709904]: 36 items in the session cache 2009.02.10 09:23:16 LOG7[24594:3082709904]: 0 client connects (SSL_connect()) 2009.02.10 09:23:16 LOG7[24594:3082709904]: 0 client connects that finished 2009.02.10 09:23:16 LOG7[24594:3082709904]: 0 client renegotiations requested 2009.02.10 09:23:16 LOG7[24594:3082709904]: 292 server connects (SSL_accept()) 2009.02.10 09:23:16 LOG7[24594:3082709904]: 290 server connects that finished 2009.02.10 09:23:16 LOG7[24594:3082709904]: 0 server renegotiations requested 2009.02.10 09:23:16 LOG7[24594:3082709904]: 41 session cache hits 2009.02.10 09:23:16 LOG7[24594:3082709904]: 1 session cache misses 2009.02.10 09:23:16 LOG7[24594:3082709904]: 6 session cache timeouts 2009.02.10 09:23:16 LOG6[24594:3082709904]: SSL accepted: new session negotiated 2009.02.10 09:23:16 LOG6[24594:3082709904]: Negotiated ciphers: AES256-SHA SSLv3 Kx=RSA Au=RSA Enc=AES(256) Mac=SHA1 2009.02.10 09:23:16 LOG7[24594:3082709904]: FD 16 in non-blocking mode 2009.02.10 09:23:16 LOG7[24594:3082709904]: epp connecting 127.0.0.1:9777 2009.02.10 09:23:16 LOG7[24594:3082709904]: connect_wait: waiting 10 seconds 2009.02.10 09:23:16 LOG7[24594:3082709904]: connect_wait: connected 2009.02.10 09:23:16 LOG5[24594:3082709904]: epp connected remote server from 127.0.0.1:40831 2009.02.10 09:23:16 LOG7[24594:3082709904]: Remote FD=16 initialized 2009.02.10 09:23:16 LOG7[24594:3082709904]: TCP_NODELAY option set on remote socket 2009.02.10 09:23:16 LOG7[24594:3082640272]: SSL state (accept): SSLv3 read client key exchange A 2009.02.10 09:23:16 LOG7[24594:3082640272]: SSL state (accept): SSLv3 read finished A 2009.02.10 09:23:16 LOG7[24594:3082640272]: SSL state (accept): SSLv3 write change cipher spec A 2009.02.10 09:23:16 LOG7[24594:3082640272]: SSL state (accept): SSLv3 write finished A 2009.02.10 09:23:16 LOG7[24594:3082640272]: SSL state (accept): SSLv3 flush data 2009.02.10 09:23:16 LOG7[24594:3082640272]: 37 items in the session cache 2009.02.10 09:23:16 LOG7[24594:3082640272]: 0 client connects (SSL_connect()) 2009.02.10 09:23:16 LOG7[24594:3082640272]: 0 client connects that finished 2009.02.10 09:23:16 LOG7[24594:3082640272]: 0 client renegotiations requested 2009.02.10 09:23:16 LOG7[24594:3082640272]: 292 server connects (SSL_accept()) 2009.02.10 09:23:16 LOG7[24594:3082640272]: 291 server connects that finished 2009.02.10 09:23:16 LOG7[24594:3082640272]: 0 server renegotiations requested 2009.02.10 09:23:16 LOG7[24594:3082640272]: 41 session cache hits 2009.02.10 09:23:16 LOG7[24594:3082640272]: 1 session cache misses 2009.02.10 09:23:16 LOG7[24594:3082640272]: 6 session cache timeouts 2009.02.10 09:23:16 LOG6[24594:3082640272]: SSL accepted: new session negotiated 2009.02.10 09:23:16 LOG6[24594:3082640272]: Negotiated ciphers: AES256-SHA SSLv3 Kx=RSA Au=RSA Enc=AES(256) Mac=SHA1 2009.02.10 09:23:16 LOG7[24594:3082640272]: FD 18 in non-blocking mode 2009.02.10 09:23:16 LOG7[24594:3082640272]: epp connecting 127.0.0.1:9777 2009.02.10 09:23:16 LOG7[24594:3082640272]: connect_wait: waiting 10 seconds 2009.02.10 09:23:16 LOG7[24594:3082640272]: connect_wait: connected 2009.02.10 09:23:16 LOG5[24594:3082640272]: epp connected remote server from 127.0.0.1:40832 2009.02.10 09:23:16 LOG7[24594:3082640272]: Remote FD=18 initialized 2009.02.10 09:23:16 LOG7[24594:3082640272]: TCP_NODELAY option set on remote socket 2009.02.10 09:23:16 LOG7[24594:3083127696]: Socket closed on read 2009.02.10 09:23:16 LOG7[24594:3083127696]: SSL write shutdown 2009.02.10 09:23:16 LOG7[24594:3083127696]: SSL alert (write): warning: close notify 2009.02.10 09:23:16 LOG6[24594:3083127696]: SSL socket closed on SSL_shutdown 2009.02.10 09:23:16 LOG7[24594:3083127696]: Socket write shutdown 2009.02.10 09:23:16 LOG5[24594:3083127696]: Connection closed: 2249 bytes sent to SSL, 1169 bytes sent to socket 2009.02.10 09:23:16 LOG7[24594:3083127696]: epp finished (4 left) 2009.02.10 09:23:30 LOG7[24594:3083130544]: epp accepted FD=15 from 62.116.129.3:3503 2009.02.10 09:23:30 LOG7[24594:3083127696]: epp started 2009.02.10 09:23:30 LOG7[24594:3083127696]: FD 15 in non-blocking mode 2009.02.10 09:23:30 LOG7[24594:3083127696]: TCP_NODELAY option set on local socket 2009.02.10 09:23:30 LOG7[24594:3083127696]: Waiting for a libwrap process 2009.02.10 09:23:30 LOG7[24594:3083127696]: Acquired libwrap process #4 2009.02.10 09:23:30 LOG7[24594:3083130544]: epp accepted FD=17 from 62.116.129.3:3504 2009.02.10 09:23:30 LOG7[24594:3082918800]: epp started 2009.02.10 09:23:30 LOG7[24594:3082918800]: FD 17 in non-blocking mode 2009.02.10 09:23:30 LOG7[24594:3082918800]: TCP_NODELAY option set on local socket 2009.02.10 09:23:30 LOG7[24594:3082918800]: Waiting for a libwrap process 2009.02.10 09:23:30 LOG7[24594:3083127696]: Releasing libwrap process #4 2009.02.10 09:23:45 LOG7[24594:3083130544]: epp accepted FD=23 from 62.116.129.3:35076 2009.02.10 09:23:45 LOG7[24594:3082779536]: epp started 2009.02.10 09:23:45 LOG7[24594:3082779536]: FD 23 in non-blocking mode 2009.02.10 09:23:45 LOG7[24594:3082779536]: TCP_NODELAY option set on local socket 2009.02.10 09:23:45 LOG7[24594:3082779536]: Waiting for a libwrap process 2009.02.10 09:23:48 LOG7[24594:3083130544]: epp accepted FD=24 from 212.209.10.53:4853 2009.02.10 09:23:48 LOG7[24594:3083058064]: epp started 2009.02.10 09:23:48 LOG7[24594:3083058064]: FD 24 in non-blocking mode 2009.02.10 09:23:48 LOG7[24594:3083058064]: TCP_NODELAY option set on local socket 2009.02.10 09:23:48 LOG7[24594:3083058064]: Waiting for a libwrap process 2009.02.10 09:24:01 LOG7[24594:3083130544]: epp accepted FD=25 from 62.116.129.3:35084 2009.02.10 09:24:01 LOG7[24594:3082570640]: epp started 2009.02.10 09:24:01 LOG7[24594:3082570640]: FD 25 in non-blocking mode 2009.02.10 09:24:01 LOG7[24594:3082570640]: TCP_NODELAY option set on local socket 2009.02.10 09:24:01 LOG7[24594:3082570640]: Waiting for a libwrap process 2009.02.10 09:24:50 LOG7[24594:3083130544]: epp accepted FD=26 from 91.203.4.58:3814 2009.02.10 09:24:50 LOG7[24594:3082501008]: epp started 2009.02.10 09:24:50 LOG7[24594:3082501008]: FD 26 in non-blocking mode 2009.02.10 09:24:50 LOG7[24594:3082501008]: TCP_NODELAY option set on local socket 2009.02.10 09:24:50 LOG7[24594:3082501008]: Waiting for a libwrap process 2009.02.10 09:25:29 LOG7[24594:3083130544]: epp accepted FD=27 from 87.96.215.128:34595 2009.02.10 09:25:29 LOG7[24594:3082431376]: epp started 2009.02.10 09:25:29 LOG7[24594:3082431376]: FD 27 in non-blocking mode 2009.02.10 09:25:29 LOG7[24594:3082431376]: TCP_NODELAY option set on local socket 2009.02.10 09:25:29 LOG7[24594:3082431376]: Waiting for a libwrap process 2009.02.10 09:25:40 LOG7[24594:3083130544]: epp accepted FD=28 from 195.249.40.26:36799 2009.02.10 09:25:40 LOG7[24594:3082361744]: epp started 2009.02.10 09:25:40 LOG7[24594:3082361744]: FD 28 in non-blocking mode