stunnel connection to my server fails first time, then works if session caching is on. What can I change to get it to work the first time?

Question

I have a device in the field connecting to my service via SSL using stunnel. Nice new valid certificate...all other devices work fine. But this one, for some reason, fails on the first attempt to connect. Then, if I have session caching turned on, it'll work fine on subsequent attempts. Here's the debug log from stunnel. Any ideas on what I might change to get this to work the first time??

Here's the first connect:

2020.05.01 13:55:58 LOG7[12830:140495407708160]: Clients allowed=500
2020.05.01 13:55:58 LOG5[12830:140495407708160]: stunnel 4.56 on x86_64-redhat-linux-gnu platform
2020.05.01 13:55:58 LOG5[12830:140495407708160]: Compiled/running with OpenSSL 1.0.2k-fips  26 Jan 2017
2020.05.01 13:55:58 LOG5[12830:140495407708160]: Threading:PTHREAD Sockets:POLL,IPv6 SSL:ENGINE,OCSP,FIPS Auth:LIBWRAP
2020.05.01 13:55:58 LOG5[12830:140495407708160]: Reading configuration from file test2.conf
2020.05.01 13:55:58 LOG5[12830:140495407708160]: FIPS mode is disabled
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Compression not enabled
2020.05.01 13:55:58 LOG7[12830:140495407708160]: PRNG seeded successfully
2020.05.01 13:55:58 LOG6[12830:140495407708160]: Initializing service [60666-v570]
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Certificate: [redacted]
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Certificate loaded
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Key file: [redacted]
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Private key loaded
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Could not load DH parameters from [redacted]
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Using hardcoded DH parameters
2020.05.01 13:55:58 LOG7[12830:140495407708160]: DH initialized with 2048-bit key
2020.05.01 13:55:58 LOG7[12830:140495407708160]: ECDH initialized with curve prime256v1
2020.05.01 13:55:58 LOG7[12830:140495407708160]: SSL options set: 0x03000004
2020.05.01 13:55:58 LOG5[12830:140495407708160]: Configuration successful
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Service [60666-v570] (FD=12) bound to 0.0.0.0:60666
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Created pid file /var/run/stunnel.pid
2020.05.01 13:56:35 LOG7[12830:140495407708160]: Service [60666-v570] accepted (FD=3) from [redacted]
2020.05.01 13:56:35 LOG7[12830:140495407703808]: Service [60666-v570] started
2020.05.01 13:56:35 LOG7[12830:140495407703808]: Waiting for a libwrap process
2020.05.01 13:56:35 LOG7[12830:140495407703808]: Acquired libwrap process #0
2020.05.01 13:56:35 LOG7[12830:140495407703808]: Releasing libwrap process #0
2020.05.01 13:56:35 LOG7[12830:140495407703808]: Released libwrap process #0
2020.05.01 13:56:35 LOG7[12830:140495407703808]: Service [60666-v570] permitted by libwrap from [redacted]
2020.05.01 13:56:35 LOG5[12830:140495407703808]: Service [60666-v570] accepted connection from [redacted]
2020.05.01 13:56:35 LOG7[12830:140495407703808]: SSL state (accept): before/accept initialization
2020.05.01 13:56:35 LOG7[12830:140495407703808]: SNI: no virtual services defined
2020.05.01 13:56:35 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 read client hello A
2020.05.01 13:56:35 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 write server hello A
2020.05.01 13:56:35 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 write certificate A
2020.05.01 13:56:35 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 write server done A
2020.05.01 13:56:35 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 flush data
2020.05.01 13:56:35 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 read client certificate A

Client gives up at this point...after 32 seconds...but my stunnel server finishes the connection process.

2020.05.01 13:57:07 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 read client key exchange A
2020.05.01 13:57:07 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 read certificate verify A
2020.05.01 13:57:07 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 read finished A
2020.05.01 13:57:07 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 write change cipher spec A
2020.05.01 13:57:07 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 write finished A
2020.05.01 13:57:07 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 flush data
2020.05.01 13:57:07 LOG7[12830:140495407703808]:    1 items in the session cache
2020.05.01 13:57:07 LOG7[12830:140495407703808]:    0 client connects (SSL_connect())
2020.05.01 13:57:07 LOG7[12830:140495407703808]:    0 client connects that finished
2020.05.01 13:57:07 LOG7[12830:140495407703808]:    0 client renegotiations requested
2020.05.01 13:57:07 LOG7[12830:140495407703808]:    1 server connects (SSL_accept())
2020.05.01 13:57:07 LOG7[12830:140495407703808]:    1 server connects that finished
2020.05.01 13:57:07 LOG7[12830:140495407703808]:    0 server renegotiations requested
2020.05.01 13:57:07 LOG7[12830:140495407703808]:    0 session cache hits
2020.05.01 13:57:07 LOG7[12830:140495407703808]:    0 external session cache hits
2020.05.01 13:57:07 LOG7[12830:140495407703808]:    0 session cache misses
2020.05.01 13:57:07 LOG7[12830:140495407703808]:    0 session cache timeouts
2020.05.01 13:57:07 LOG6[12830:140495407703808]: SSL accepted: new session negotiated
2020.05.01 13:57:07 LOG6[12830:140495407703808]: Negotiated TLSv1/SSLv3 ciphersuite: AES256-SHA (256-bit encryption)
2020.05.01 13:57:07 LOG6[12830:140495407703808]: Compression: null, expansion: null
2020.05.01 13:57:07 LOG6[12830:140495407703808]: local_bind succeeded on an ephemeral port
2020.05.01 13:57:07 LOG6[12830:140495407703808]: connect_blocking: connecting 127.0.0.1:50001
2020.05.01 13:57:07 LOG7[12830:140495407703808]: connect_blocking: s_poll_wait 127.0.0.1:50001: waiting 10 seconds
2020.05.01 13:57:07 LOG5[12830:140495407703808]: connect_blocking: connected 127.0.0.1:50001
2020.05.01 13:57:07 LOG5[12830:140495407703808]: Service [60666-v570] connected remote server from 127.0.0.66:43790
2020.05.01 13:57:07 LOG7[12830:140495407703808]: Remote socket (FD=14) initialized
2020.05.01 13:57:07 LOG7[12830:140495407703808]: SSL alert (read): warning: close notify
2020.05.01 13:57:07 LOG6[12830:140495407703808]: SSL closed (SSL_read)
2020.05.01 13:57:07 LOG7[12830:140495407703808]: Sent socket write shutdown
2020.05.01 13:57:07 LOG6[12830:140495407703808]: Read socket closed (hangup)
2020.05.01 13:57:07 LOG6[12830:140495407703808]: Write socket closed (hangup)
2020.05.01 13:57:07 LOG7[12830:140495407703808]: Sending close_notify alert
2020.05.01 13:57:07 LOG7[12830:140495407703808]: SSL alert (write): warning: close notify
2020.05.01 13:57:07 LOG6[12830:140495407703808]: SSL_shutdown successfully sent close_notify alert
2020.05.01 13:57:07 LOG5[12830:140495407703808]: Connection closed: 0 byte(s) sent to SSL, 0 byte(s) sent to socket
2020.05.01 13:57:07 LOG7[12830:140495407703808]: Remote socket (FD=14) closed
2020.05.01 13:57:07 LOG7[12830:140495407703808]: Local socket (FD=3) closed
2020.05.01 13:57:07 LOG7[12830:140495407703808]: Service [60666-v570] finished (0 left)

Second attempt from client...works fine, no 32 second wait, and completes successfully

2020.05.01 13:58:01 LOG7[12830:140495407708160]: Service [60666-v570] accepted (FD=3) from [redacted]
2020.05.01 13:58:01 LOG7[12830:140495407703808]: Service [60666-v570] started
2020.05.01 13:58:01 LOG7[12830:140495407703808]: Waiting for a libwrap process
2020.05.01 13:58:01 LOG7[12830:140495407703808]: Acquired libwrap process #0
2020.05.01 13:58:01 LOG7[12830:140495407703808]: Releasing libwrap process #0
2020.05.01 13:58:01 LOG7[12830:140495407703808]: Released libwrap process #0
2020.05.01 13:58:01 LOG7[12830:140495407703808]: Service [60666-v570] permitted by libwrap from [redacted]
2020.05.01 13:58:01 LOG5[12830:140495407703808]: Service [60666-v570] accepted connection from [redacted]
2020.05.01 13:58:01 LOG7[12830:140495407703808]: SSL state (accept): before/accept initialization
2020.05.01 13:58:01 LOG7[12830:140495407703808]: SNI: no virtual services defined
2020.05.01 13:58:01 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 read client hello A
2020.05.01 13:58:01 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 write server hello A
2020.05.01 13:58:01 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 write change cipher spec A
2020.05.01 13:58:01 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 write finished A
2020.05.01 13:58:01 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 flush data
2020.05.01 13:58:02 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 read finished A
2020.05.01 13:58:02 LOG7[12830:140495407703808]:    1 items in the session cache
2020.05.01 13:58:02 LOG7[12830:140495407703808]:    0 client connects (SSL_connect())
2020.05.01 13:58:02 LOG7[12830:140495407703808]:    0 client connects that finished
2020.05.01 13:58:02 LOG7[12830:140495407703808]:    0 client renegotiations requested
2020.05.01 13:58:02 LOG7[12830:140495407703808]:    2 server connects (SSL_accept())
2020.05.01 13:58:02 LOG7[12830:140495407703808]:    2 server connects that finished
2020.05.01 13:58:02 LOG7[12830:140495407703808]:    0 server renegotiations requested
2020.05.01 13:58:02 LOG7[12830:140495407703808]:    1 session cache hits
2020.05.01 13:58:02 LOG7[12830:140495407703808]:    0 external session cache hits
2020.05.01 13:58:02 LOG7[12830:140495407703808]:    0 session cache misses
2020.05.01 13:58:02 LOG7[12830:140495407703808]:    0 session cache timeouts
2020.05.01 13:58:02 LOG6[12830:140495407703808]: SSL accepted: previous session reused
2020.05.01 13:58:02 LOG6[12830:140495407703808]: local_bind succeeded on an ephemeral port
2020.05.01 13:58:02 LOG6[12830:140495407703808]: connect_blocking: connecting 127.0.0.1:50001
2020.05.01 13:58:02 LOG7[12830:140495407703808]: connect_blocking: s_poll_wait 127.0.0.1:50001: waiting 10 seconds
2020.05.01 13:58:02 LOG5[12830:140495407703808]: connect_blocking: connected 127.0.0.1:50001
2020.05.01 13:58:02 LOG5[12830:140495407703808]: Service [60666-v570] connected remote server from 127.0.0.66:42546
2020.05.01 13:58:02 LOG7[12830:140495407703808]: Remote socket (FD=14) initialized
2020.05.01 13:58:03 LOG6[12830:140495407703808]: Read socket closed (readsocket)
2020.05.01 13:58:03 LOG7[12830:140495407703808]: Sending close_notify alert
2020.05.01 13:58:03 LOG7[12830:140495407703808]: SSL alert (write): warning: close notify
2020.05.01 13:58:03 LOG6[12830:140495407703808]: SSL_shutdown successfully sent close_notify alert
2020.05.01 13:58:04 LOG7[12830:140495407703808]: SSL alert (read): warning: close notify
2020.05.01 13:58:04 LOG6[12830:140495407703808]: SSL closed (SSL_read)
2020.05.01 13:58:04 LOG7[12830:140495407703808]: Sent socket write shutdown
2020.05.01 13:58:04 LOG5[12830:140495407703808]: Connection closed: 40 byte(s) sent to SSL, 64 byte(s) sent to socket
2020.05.01 13:58:04 LOG7[12830:140495407703808]: Remote socket (FD=14) closed
2020.05.01 13:58:04 LOG7[12830:140495407703808]: Local socket (FD=3) closed
2020.05.01 13:58:04 LOG7[12830:140495407703808]: Service [60666-v570] finished (0 left)

Does the client's cert/chain specify an OCSP responder that is unreachable or very slow? — dave_thompson_085, May 01 '20 at 19:24
I wish I could know that answer. It's a proprietary system and I have no insight into its inner workings. BUT, if that's the problem, I still don't understand why that very same client would work fine with a cached connection. Could it be just poor coding in the client that considers a failed OCSP response to be as good as a successful one? — Gnetbucket, May 01 '20 at 22:45
If you are running the receiving stunnel you should be able to see the certificate(s) the client is sending, and probably any outgoing requests the stunnel process makes. The difference with a cached connection (more exactly, SSL/TLS _session resumption_) is that is uses the saved security context, and does not (send/receive and) check the certificate(s)., hence it does not incur any OCSP problem or delay. — dave_thompson_085, May 04 '20 at 08:30

stunnel connection to my server fails first time, then works if session caching is on. What can I change to get it to work the first time?

0 Answers0