Hi,
after upgrading to stunnel 4.09, we are having 2 problems with it that did not exist in a previous version (our case: stunnel 4.05 without pthreads)
---[ My testsetup is as follows:
* stunnel listening on port 4321, connects to localhost port 13 (daytime)
* daytime is enabled in inetd
* stunnel was compiled without pthreads
* ulimit -u = 8192
---[ problem 1
At first, it works fine. For every incoming connection, the process
forks and data is transferred. However, when the connection is closed,
the forked process remains hanging for a while (about 1 minute) and then
exits.
This in itself is not a real problem, except that it generates a lot of
processes. (and maybe causes problem 2 ?)
---[ data and logs concerning problem 1 (process hangs for 1 minute):
I run the following command:
openssl s_client -connect 192.168.2.119:4321
the output follows immediately
The logfile (debug = debug) looks like this:
2005.03.31 14:05:05 LOG7[4552:0]: daytime accepted FD=8 from 192.168.2.103:47200
2005.03.31 14:05:05 LOG7[4552:0]: FD 8 in non-blocking mode
2005.03.31 14:05:05 LOG7[4553:0]: daytime started
2005.03.31 14:05:05 LOG5[4553:0]: daytime connected from 192.168.2.103:47200
2005.03.31 14:05:05 LOG7[4553:0]: SSL state (accept): before/accept initialization
2005.03.31 14:05:05 LOG7[4553:0]: SSL state (accept): SSLv3 read client hello A
2005.03.31 14:05:05 LOG7[4553:0]: SSL state (accept): SSLv3 write server hello A
2005.03.31 14:05:05 LOG7[4553:0]: SSL state (accept): SSLv3 write certificate A
2005.03.31 14:05:05 LOG7[4553:0]: SSL state (accept): SSLv3 write server done A
2005.03.31 14:05:05 LOG7[4553:0]: SSL state (accept): SSLv3 flush data
2005.03.31 14:05:05 LOG7[4553:0]: SSL state (accept): SSLv3 read client key exchange A
2005.03.31 14:05:05 LOG7[4553:0]: SSL state (accept): SSLv3 read finished A
2005.03.31 14:05:05 LOG7[4553:0]: SSL state (accept): SSLv3 write change cipher spec A
2005.03.31 14:05:05 LOG7[4553:0]: SSL state (accept): SSLv3 write finished A
2005.03.31 14:05:05 LOG7[4553:0]: SSL state (accept): SSLv3 flush data
2005.03.31 14:05:05 LOG7[4553:0]: 1 items in the session cache
2005.03.31 14:05:05 LOG7[4553:0]: 0 client connects (SSL_connect())
2005.03.31 14:05:05 LOG7[4553:0]: 0 client connects that finished
2005.03.31 14:05:05 LOG7[4553:0]: 0 client renegotiatations requested
2005.03.31 14:05:05 LOG7[4553:0]: 1 server connects (SSL_accept())
2005.03.31 14:05:05 LOG7[4553:0]: 1 server connects that finished
2005.03.31 14:05:05 LOG7[4553:0]: 0 server renegotiatiations requested
2005.03.31 14:05:05 LOG7[4553:0]: 0 session cache hits
2005.03.31 14:05:05 LOG7[4553:0]: 0 session cache misses
2005.03.31 14:05:05 LOG7[4553:0]: 0 session cache timeouts
2005.03.31 14:05:05 LOG6[4553:0]: SSL accepted: new session negotiated
2005.03.31 14:05:05 LOG6[4553:0]: Negotiated ciphers: RC4-SHA SSLv3 Kx=RSA Au=RSA Enc=RC4(128) Mac=SHA1
2005.03.31 14:05:05 LOG7[4553:0]: FD 7 in non-blocking mode
2005.03.31 14:05:05 LOG7[4553:0]: daytime connecting 127.0.0.1:13
2005.03.31 14:05:05 LOG7[4553:0]: connect_wait: waiting 10 seconds
2005.03.31 14:05:05 LOG7[4553:0]: connect_wait: connected
2005.03.31 14:05:05 LOG7[4553:0]: Remote FD=7 initialized
2005.03.31 14:05:05 LOG7[4553:0]: Socket closed on read
2005.03.31 14:05:05 LOG7[4553:0]: SSL write shutdown
2005.03.31 14:05:05 LOG7[4553:0]: SSL alert (write): warning: close notify
2005.03.31 14:05:05 LOG7[4553:0]: SSL_shutdown retrying
2005.03.31 14:05:06 LOG7[4553:0]: SSL alert (read): warning: close notify
2005.03.31 14:05:06 LOG7[4553:0]: SSL closed on SSL_read
2005.03.31 14:05:06 LOG7[4553:0]: Socket write shutdown
When I check netstat, the connection from the client to stunnel is in the CLOSE_WAIT state
and the connection from stunnel to the daytime server is in TIME_WAIT state
then 1 minute later, this follows:
2005.03.31 14:06:06 LOG6[4553:0]: s_poll_wait timeout: connection close
2005.03.31 14:06:06 LOG5[4553:0]: Connection closed: 26 bytes sent to SSL, 0 bytes sent to socket
2005.03.31 14:06:06 LOG7[4553:0]: removing pid file /stunnel.pid
2005.03.31 14:06:06 LOG7[4552:0]: Steven: going into client_status with num_clients = 1
2005.03.31 14:06:06 LOG7[4552:0]: Process 4553 finished with code 0 (0 left)
Now, netstat no longer shows the connections in any state.
---[ problem 2
Another problem that was found is that after bombarding stunnel with
lots of connections, it stops accepting new connections. This would be
normal if all connections remained open, but they are all closed.
This is the error:
Mar 31 13:53:40 hostname stunnel[13044]: Connection rejected: too many clients (>=4000)
netstat only shows +- 500 connections, of which none are aimed at the
stunnel process in question (port 4321 in my test setup)
there is only 1 stunnel process active aswell.
I dug into the problem a bit and it probably has to do with num_clients
not being decreased after a process is closed (although I can not find
any specifics :/)
greets,
-- Steven
