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@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@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@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@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)
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
Scott Weisman wrote:
exec = /opt/cmf/bin/cf-server execargs = /opt/cmf/bin/cf-server -p /opt/jail/stunnel/pipes/
[cut]
2015.05.01 15:37:33 LOG6[main]: Child process 2899 terminated on signal 11
Your /opt/cmf/bin/cf-server died with signal 11, i.e., SIGSEGV. The proper course of action is to enable creating core files with "ulimit -c unlimited", create the core file, and inspect it with gdb.
Mike
Thanks for the tip Michal.
I figured out the problem. There was an undocumented change in the format of the env var SSL_CLIENT_DN.
I was using this code to extract the CN:
char *cn = strstr(env, "/CN=");
Now I need to use this:
char *cn = strstr(env, " CN=");
Seems like a pointless change. But a change that should have been documented.
Scott
On Sun, May 3, 2015 at 10:59 PM, Michal Trojnara Michal.Trojnara@mirt.net wrote:
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
Scott Weisman wrote:
exec = /opt/cmf/bin/cf-server execargs = /opt/cmf/bin/cf-server -p /opt/jail/stunnel/pipes/
[cut]
2015.05.01 15:37:33 LOG6[main]: Child process 2899 terminated on signal 11
Your /opt/cmf/bin/cf-server died with signal 11, i.e., SIGSEGV. The proper course of action is to enable creating core files with "ulimit -c unlimited", create the core file, and inspect it with gdb.
Mike -----BEGIN PGP SIGNATURE----- Version: GnuPG v1 Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/
iQIcBAEBAgAGBQJVRn4HAAoJEC78f/DUFuAUw8cQALcaTNk+xERG3eEfacv+Sg5s nJGr/Nlgk5NozFlBY0LiE1Sv8n28ExNMegVrwqkio/1xS8sGT3UEQWbNGRsL9KPD 9OHx1jY4xkmcY8t9hIRghMl6UPzFAr7yeJfbcsQbF5p+Zxp1szwCWDhXunhRShWR hKEdJ1qNOehBfAOM1j65cpPZGhLb8CdvI5wioM9qms62+jPH0p7OR0Pcxj/AUfYY 98P6VZBf3R27Nwxa1suI9l2UFhrO5SWcGwB2mhqQyID4U6iSelnjZkly91gJ8fv+ 7VKzF1Xnp+5hL9tY0Yb1pjRMDmk6R6UuQbXWKLkoTbGKTl0Mr5r+rifLd/vh+F8z VbRa9Gd0aaOpdnYs+KaeOV6iou0scjhpxM78SFo0HMBIs18+baXfGZNbRjnvD3Gw aaBgnOQuPuXUGPfwIfTnP0HUo3P7+ZRng7620EDUTskIrO0WIinzWHkMhwfpqpgq /PFp+7YTrxnfMCBU6UAoONk/Tr0jrTv9eVBkvykk2Qfhm6fEem2jrqWzOuiS5jkg z3epcuPdXTkamI0gAQ3dJo3TmFw8Ai6Q46/7CJVTxYGzwgIXf3yNNGpUEWNrC9R6 KpfPfB2A4sT3J3oHdXh7I/q0BcBgpAF/CvooRdCA+Ib8tzOzWeM9kzprzxowhtDt tSko3NkMnv0ihEi5S8fu =fjzb -----END PGP SIGNATURE----- _______________________________________________ stunnel-users mailing list stunnel-users@stunnel.org https://www.stunnel.org/cgi-bin/mailman/listinfo/stunnel-users
-
Michal Trojnara -
Scott Weisman