[stunnel-users] stunnel hanging (libwrap)

[Ulrich Wisser]

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