[stunnel-users] problem migrating from 4.54 to 5.x

[Scott Weisman]

Hi there. I have a program I have used successfully with Stunnel for many
years.

A while back, I discovered that my program, which is a pure stdio console
program, stopped working with 5.x versions of Stunnel. I have spent many
hours but have been unable to solve the problem, so I regretfully continue
to use the 4.x branch. I was wondering if anyone had similar experiences?
Relevant data is pasted below. I comment in the log output where the
problem occurs.

Any help at all would be greatly appreciated.

stunnel.conf:
setuid = stunnel
setgid = stunnel
pid = /var/run/stunnel/stunnel.pid
socket = l:TCP_NODELAY=1
socket = r:TCP_NODELAY=1
foreground = no
debug = 7
output = /var/log/stunnel.log

[CF2]
client = no
accept = 21
verify = 3
sslVersion = all
cert = /etc/stunnel/demo.pem
key = /etc/stunnel/demo.pem
CApath = /etc/stunnel/certs
CRLpath = /etc/stunnel/crls
TIMEOUTbusy = 60
TIMEOUTclose = 0
TIMEOUTconnect = 60
TIMEOUTidle = 60

exec = /opt/cmf/bin/cf-server
execargs = /opt/cmf/bin/cf-server -p /opt/jail/stunnel/pipes/

Log of successful session with 4.54:
2015.05.01 15:39:39 LOG7[3080:140402563495680]: Starting certificate
verification: depth=0, /C=US/L=Bryan/ST=TX/O=Demo Account/emailAddress=
demo at demo.com/CN=demo
2015.05.01 15:39:39 LOG6[3080:140402563495680]: CERT: Locally installed
certificate matched
2015.05.01 15:39:39 LOG5[3080:140402563495680]: Certificate accepted:
depth=0, /C=US/L=Bryan/ST=TX/O=Demo Account/emailAddress=
demo at demo.com/CN=demo
2015.05.01 15:39:39 LOG7[3080:140402563495680]: SSL state (accept): SSLv3
read client certificate A
2015.05.01 15:39:39 LOG7[3080:140402563495680]: SSL state (accept): SSLv3
read client key exchange A
2015.05.01 15:39:39 LOG7[3080:140402563495680]: SSL state (accept): SSLv3
read certificate verify A
2015.05.01 15:39:39 LOG7[3080:140402563495680]: SSL state (accept): SSLv3
read finished A
2015.05.01 15:39:39 LOG7[3080:140402563495680]: SSL state (accept): SSLv3
write session ticket A
2015.05.01 15:39:39 LOG7[3080:140402563495680]: SSL state (accept): SSLv3
write change cipher spec A
2015.05.01 15:39:39 LOG7[3080:140402563495680]: SSL state (accept): SSLv3
write finished A
2015.05.01 15:39:39 LOG7[3080:140402563495680]: SSL state (accept): SSLv3
flush data
2015.05.01 15:39:39 LOG7[3080:140402563495680]:    0 items in the session
cache
2015.05.01 15:39:39 LOG7[3080:140402563495680]:    0 client connects
(SSL_connect())
2015.05.01 15:39:39 LOG7[3080:140402563495680]:    0 client connects that
finished
2015.05.01 15:39:39 LOG7[3080:140402563495680]:    0 client renegotiations
requested
2015.05.01 15:39:39 LOG7[3080:140402563495680]:    1 server connects
(SSL_accept())
2015.05.01 15:39:39 LOG7[3080:140402563495680]:    1 server connects that
finished
2015.05.01 15:39:39 LOG7[3080:140402563495680]:    0 server renegotiations
requested
2015.05.01 15:39:39 LOG7[3080:140402563495680]:    0 session cache hits
2015.05.01 15:39:39 LOG7[3080:140402563495680]:    0 external session cache
hits
2015.05.01 15:39:39 LOG7[3080:140402563495680]:    0 session cache misses
2015.05.01 15:39:39 LOG7[3080:140402563495680]:    0 session cache timeouts
2015.05.01 15:39:39 LOG6[3080:140402563495680]: SSL accepted: new session
negotiated
2015.05.01 15:39:39 LOG6[3080:140402563495680]: Negotiated TLSv1/SSLv3
ciphersuite: ECDHE-RSA-AES256-GCM-SHA384 (256-bit encryption)
2015.05.01 15:39:39 LOG6[3080:140402563495680]: Compression: null,
expansion: null
2015.05.01 15:39:39 LOG6[3080:140402563495680]: Local mode child started
(PID=3118)
2015.05.01 15:39:39 LOG7[3080:140402563495680]: Remote socket (FD=11)
initialized
*** the connection is established and stable; i explicitly disconnect
several seconds later
2015.05.01 15:39:45 LOG7[3080:140402563495680]: SSL socket closed on
SSL_read
2015.05.01 15:39:45 LOG7[3080:140402563495680]: Sent socket write shutdown
2015.05.01 15:39:45 LOG5[3080:140402563495680]: Connection closed: 0
byte(s) sent to SSL, 0 byte(s) sent to socket
2015.05.01 15:39:45 LOG7[3080:140402563495680]: Remote socket (FD=11) closed
2015.05.01 15:39:45 LOG7[3080:140402563495680]: Local socket (FD=3) closed
2015.05.01 15:39:45 LOG7[3080:140402563495680]: Service [CF2] finished (0
left)

Log of unsuccessful session with 5.16:
2015.05.01 15:37:33 LOG7[0]: Verification started at depth=0: C=US,
L=Bryan, ST=TX, O=Demo Account, emailAddress=demo at demo.com, CN=demo
2015.05.01 15:37:33 LOG7[0]: CERT: Pre-verification succeeded
2015.05.01 15:37:33 LOG6[0]: CERT: Locally installed certificate matched
2015.05.01 15:37:33 LOG5[0]: Certificate accepted at depth=0: C=US,
L=Bryan, ST=TX, O=Demo Account, emailAddress=demo at demo.com, CN=demo
2015.05.01 15:37:33 LOG7[0]: SSL state (accept): SSLv3 read client
certificate A
2015.05.01 15:37:33 LOG7[0]: SSL state (accept): SSLv3 read client key
exchange A
2015.05.01 15:37:33 LOG7[0]: SSL state (accept): SSLv3 read certificate
verify A
2015.05.01 15:37:33 LOG7[0]: SSL state (accept): SSLv3 read finished A
2015.05.01 15:37:33 LOG7[0]: SSL state (accept): SSLv3 write change cipher
spec A
2015.05.01 15:37:33 LOG7[0]: SSL state (accept): SSLv3 write finished A
2015.05.01 15:37:33 LOG7[0]: SSL state (accept): SSLv3 flush data
2015.05.01 15:37:33 LOG7[0]:    1 server accept(s) requested
2015.05.01 15:37:33 LOG7[0]:    1 server accept(s) succeeded
2015.05.01 15:37:33 LOG7[0]:    0 server renegotiation(s) requested
2015.05.01 15:37:33 LOG7[0]:    0 session reuse(s)
2015.05.01 15:37:33 LOG7[0]:    0 internal session cache item(s)
2015.05.01 15:37:33 LOG7[0]:    0 internal session cache fill-up(s)
2015.05.01 15:37:33 LOG7[0]:    0 internal session cache miss(es)
2015.05.01 15:37:33 LOG7[0]:    0 external session cache hit(s)
2015.05.01 15:37:33 LOG7[0]:    0 expired session(s) retrieved
2015.05.01 15:37:33 LOG6[0]: SSL accepted: new session negotiated
2015.05.01 15:37:33 LOG7[0]: Peer certificate was cached (1610 bytes)
2015.05.01 15:37:33 LOG6[0]: Negotiated TLSv1.2 ciphersuite
ECDHE-RSA-AES256-GCM-SHA384 (256-bit encryption)
2015.05.01 15:37:33 LOG7[0]: Compression: null, expansion: null
2015.05.01 15:37:33 LOG6[0]: Local mode child started (PID=2899)
2015.05.01 15:37:33 LOG7[0]: Remote socket (FD=11) initialized
*** immediately after successful connection, something happens; my program
has no log output either, which seems to indicate that stunnel is closing it
2015.05.01 15:37:33 LOG6[0]: Read socket closed (readsocket)
2015.05.01 15:37:33 LOG7[main]: Dispatching signals from the signal pipe
2015.05.01 15:37:33 LOG7[0]: Sending close_notify alert
2015.05.01 15:37:33 LOG7[main]: Processing SIGCHLD
2015.05.01 15:37:33 LOG7[0]: SSL alert (write): warning: close notify
2015.05.01 15:37:33 LOG6[main]: Child process 2899 terminated on signal 11
2015.05.01 15:37:33 LOG6[0]: SSL_shutdown successfully sent close_notify
alert
2015.05.01 15:37:33 LOG7[main]: Signal pipe is empty
2015.05.01 15:37:33 LOG3[0]: transfer: s_poll_wait: TIMEOUTclose exceeded:
closing
2015.05.01 15:37:33 LOG5[0]: Connection closed: 0 byte(s) sent to SSL, 0
byte(s) sent to socket
2015.05.01 15:37:33 LOG7[0]: Remote socket (FD=11) closed
2015.05.01 15:37:33 LOG7[0]: Local socket (FD=3) closed
2015.05.01 15:37:33 LOG7[0]: Service [CF2] finished (0 left)
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.stunnel.org/pipermail/stunnel-users/attachments/20150503/26f2b3f3/attachment.html>