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
On Thu, Mar 31, 2005 at 02:18:07PM +0200, Steven Van Acker wrote:
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)
Hi,
I've traced the problem with strace, and found that in transfer() in client.c, the code does an unintended sleep(60). This happens because no filedescriptors are added to fds, causing poll to be called like poll(0xwhatever,0,60*1000), which is the same as sleep(60);
The attached patch fixes the problem. I'm unsure whether the fix can be applied to s_poll_wait(). Are there any calls to s_poll_wait() that are intended to be sleep() calls ?
At first glance, the patch also seems to fix the second problem I had.
greets, -- Steven
On Thu, Mar 31, 2005 at 02:18:07PM +0200, Steven Van Acker wrote:
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)
Hi,
I've traced the problem with strace, and found that in transfer() in client.c, the code does an unintended sleep(60). This happens because no filedescriptors are added to fds, causing poll to be called like poll(0xwhatever,0,60*1000), which is the same as sleep(60);
The attached patch fixes the problem. I'm unsure whether the fix can be applied to s_poll_wait(). Are there any calls to s_poll_wait() that are intended to be sleep() calls ?
At first glance, the patch also seems to fix the second problem I had.
greets, -- Steven
Hello,
I've unsubscribed to the list 3 or 4 times... but I'm still getting e-mails. I unsubscribed via the web interface.
Does anyone know why I can't be removed from the list? Is there a problem with the listserv?
Thanks!
-- Michael She E: michael.she@binaryio.com P: (416) 816-2566 W: http://www.binaryio.com
Michael She wrote:
I've unsubscribed to the list 3 or 4 times... but I'm still getting e-mails. I unsubscribed via the web interface.
Does anyone know why I can't be removed from the list? Is there a problem with the listserv?
You're right. Web interface is not currently working. I'll try to fix it ASAP.
BTW: You're unsubscribed.
Best regards, Mike