[stunnel-users] stunnel-4.36 issues ("Operation now in progress")

Thu Jun 16 15:20:40 CEST 2011

Hi,

today our blessed Enterprise-class distribution SLES11.1 made a major upgrade from stunnel 4.27 to stunnel 4.36, which somewhat broke our monitoring agent.

Config:
------

client = no
pid = /var/run/stunnel.pid
debug = 4
socket = l:TCP_NODELAY=1
socket = r:TCP_NODELAY=1
cert = /etc/stunnel/stunnel.pem

[uptimeagent]
accept = 9998
exec = /opt/uptime-agent/bin/uptimeagent
------

We get the following output when connecting:

2011.06.16 15:13:37 LOG7[4597:140226692765440]: local socket: FD=12 allocated (non-blocking mode)
2011.06.16 15:13:37 LOG7[4597:140226692765440]: Service uptimeagent accepted FD=12 from 10.156.10.160:55926
2011.06.16 15:13:37 LOG7[4597:140226692757264]: Service uptimeagent started
2011.06.16 15:13:37 LOG7[4597:140226692757264]: Option TCP_NODELAY set on local socket
2011.06.16 15:13:37 LOG7[4597:140226692757264]: Waiting for a libwrap process
2011.06.16 15:13:37 LOG7[4597:140226692757264]: Acquired libwrap process #0
2011.06.16 15:13:37 LOG7[4597:140226692757264]: Releasing libwrap process #0
2011.06.16 15:13:37 LOG7[4597:140226692757264]: Released libwrap process #0
2011.06.16 15:13:37 LOG7[4597:140226692757264]: Service uptimeagent permitted by libwrap from 10.156.10.160:55926
2011.06.16 15:13:37 LOG5[4597:140226692757264]: Service uptimeagent accepted connection from 10.156.10.160:55926
2011.06.16 15:13:37 LOG7[4597:140226692757264]: SSL state (accept): before/accept initialization
2011.06.16 15:13:37 LOG7[4597:140226692757264]: SSL state (accept): SSLv3 read client hello A
2011.06.16 15:13:37 LOG7[4597:140226692757264]: SSL state (accept): SSLv3 write server hello A
2011.06.16 15:13:37 LOG7[4597:140226692757264]: SSL state (accept): SSLv3 write certificate A
2011.06.16 15:13:37 LOG7[4597:140226692757264]: SSL state (accept): SSLv3 write server done A
2011.06.16 15:13:37 LOG7[4597:140226692757264]: SSL state (accept): SSLv3 flush data
2011.06.16 15:13:37 LOG7[4597:140226692757264]: SSL state (accept): SSLv3 read client key exchange A
2011.06.16 15:13:37 LOG7[4597:140226692757264]: SSL state (accept): SSLv3 read finished A
2011.06.16 15:13:37 LOG7[4597:140226692757264]: SSL state (accept): SSLv3 write change cipher spec A
2011.06.16 15:13:37 LOG7[4597:140226692757264]: SSL state (accept): SSLv3 write finished A
2011.06.16 15:13:37 LOG7[4597:140226692757264]: SSL state (accept): SSLv3 flush data
2011.06.16 15:13:37 LOG7[4597:140226692757264]:    1 items in the session cache
2011.06.16 15:13:37 LOG7[4597:140226692757264]:    0 client connects (SSL_connect())
2011.06.16 15:13:37 LOG7[4597:140226692757264]:    0 client connects that finished
2011.06.16 15:13:37 LOG7[4597:140226692757264]:    0 client renegotiations requested
2011.06.16 15:13:37 LOG7[4597:140226692757264]:    1 server connects (SSL_accept())
2011.06.16 15:13:37 LOG7[4597:140226692757264]:    1 server connects that finished
2011.06.16 15:13:37 LOG7[4597:140226692757264]:    0 server renegotiations requested
2011.06.16 15:13:37 LOG7[4597:140226692757264]:    0 session cache hits
2011.06.16 15:13:37 LOG7[4597:140226692757264]:    0 external session cache hits
2011.06.16 15:13:37 LOG7[4597:140226692757264]:    0 session cache misses
2011.06.16 15:13:37 LOG7[4597:140226692757264]:    0 session cache timeouts
2011.06.16 15:13:37 LOG6[4597:140226692757264]: SSL accepted: new session negotiated
2011.06.16 15:13:37 LOG6[4597:140226692757264]: Negotiated ciphers: RC4-MD5 SSLv3 Kx=RSA Au=RSA Enc=RC4(128) Mac=MD5
2011.06.16 15:13:37 LOG7[4597:140226692757264]: socket#1: FD=13 allocated (non-blocking mode)
2011.06.16 15:13:37 LOG7[4597:140226692757264]: socket#2: FD=14 allocated (non-blocking mode)
2011.06.16 15:13:37 LOG3[4597:140226692757264]: connect: Operation now in progress (115)
2011.06.16 15:13:37 LOG5[4597:140226692757264]: Connection reset: 0 bytes sent to SSL, 0 bytes sent to socket
2011.06.16 15:13:37 LOG7[4597:140226692757264]: Service uptimeagent finished (0 left)
2011.06.16 15:13:37 LOG7[4597:140226692757264]: str_stats: 0 blocks, 0 bytes

We did not see this in 4.27, 4.33 and 4.34, but we see it in a 3rd party 4.35 RPM. This suspiciously sounds like http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=626856, and according to the changelog there is already a fix in the unreleased 4.37 version for this. 

- Could this in fact be the same bug?
- Is the patch available somewhere? I could not find a source repository
- Is there a workaround?

Thanks,
Bernhard