[stunnel-users] stunnel hanging (libwrap)

[Roman Fiedler]

Ulrich Wisser wrote:
> 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.

Which version are you using?

Could it be an old one? (see 
https://bugs.launchpad.net/ubuntu/+source/stunnel4/+bug/327222)

lg roman

>
> 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
>
>
>
>
> _______________________________________________
> stunnel-users mailing list
> stunnel-users at mirt.net
> http://stunnel.mirt.net/mailman/listinfo/stunnel-users