Secure Websocket (wss) Handshake does not happen using Stunnel

Question

We have made an application that using websockets. We have built our own websocket server in PHP and use Stunnel for using secure websockets. We use Amazon EC2 Medium Server

Every thing was working fine till last week when suddenly the chrome browser started showing failed: Error during WebSocket handshake: net::ERR_CONNECTION_RESET. The connection also has stopped happening on Firefox.

However at time the wss connection does happen. Its like may be after 4 or 5 times when we refresh the page, the wss connection happens once.

We have analysed the issue and below are the things we have observed :

In STUNNEL :

When a new SSL session is created, everything works fine. Below is the log

2014.12.05 05:56:08 LOG7[13990:140019053639616]: Service [websockets] accepted (FD=14) from 115.111.211.142:60018
2014.12.05 05:56:08 LOG7[13990:140019053496064]: Service [websockets] started
2014.12.05 05:56:08 LOG5[13990:140019053496064]: Service [websockets] accepted connection from 115.111.211.142:60018
2014.12.05 05:56:08 LOG7[13990:140019053496064]: SSL state (accept): before/accept initialization
2014.12.05 05:56:08 LOG7[13990:140019053496064]: SNI: no virtual services defined
2014.12.05 05:56:08 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 read client hello B
2014.12.05 05:56:08 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 write server hello A
2014.12.05 05:56:08 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 write certificate A
2014.12.05 05:56:08 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 write key exchange A
2014.12.05 05:56:08 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 write server done A
2014.12.05 05:56:08 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 flush data
2014.12.05 05:56:08 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 read client key exchange A
2014.12.05 05:56:08 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 read finished A
2014.12.05 05:56:08 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 write session ticket A
2014.12.05 05:56:08 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 write change cipher spec A
2014.12.05 05:56:08 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 write finished A
2014.12.05 05:56:08 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 flush data
2014.12.05 05:56:08 LOG7[13990:140019053496064]:   10 items in the session cache
2014.12.05 05:56:08 LOG7[13990:140019053496064]:    0 client connects (SSL_connect())
2014.12.05 05:56:08 LOG7[13990:140019053496064]:    0 client connects that finished
2014.12.05 05:56:08 LOG7[13990:140019053496064]:    0 client renegotiations requested
2014.12.05 05:56:08 LOG7[13990:140019053496064]: 1138 server connects (SSL_accept())
2014.12.05 05:56:08 LOG7[13990:140019053496064]: 1087 server connects that finished
2014.12.05 05:56:08 LOG7[13990:140019053496064]:    0 server renegotiations requested
2014.12.05 05:56:08 LOG7[13990:140019053496064]:  558 session cache hits
2014.12.05 05:56:08 LOG7[13990:140019053496064]:    0 external session cache hits
2014.12.05 05:56:08 LOG7[13990:140019053496064]:    0 session cache misses
2014.12.05 05:56:08 LOG7[13990:140019053496064]:  132 session cache timeouts
2014.12.05 05:56:08 LOG6[13990:140019053496064]: SSL accepted: new session negotiated
2014.12.05 05:56:08 LOG6[13990:140019053496064]: Negotiated TLSv1/SSLv3 ciphersuite: DHE-RSA-AES128-SHA (128-bit encryption)
2014.12.05 05:56:08 LOG6[13990:140019053496064]: Compression: null, expansion: null
2014.12.05 05:56:08 LOG6[13990:140019053496064]: connect_blocking: connecting 127.0.0.1:9000
2014.12.05 05:56:08 LOG7[13990:140019053496064]: connect_blocking: s_poll_wait 127.0.0.1:9000: waiting 10 seconds
2014.12.05 05:56:08 LOG5[13990:140019053496064]: connect_blocking: connected 127.0.0.1:9000
2014.12.05 05:56:08 LOG5[13990:140019053496064]: Service [websockets] connected remote server from 127.0.0.1:18479

However when the a session is reused, the connection is closed from the PHP websocket. below is the log

2014.12.05 05:56:08 LOG7[13990:140019053496064]: Remote socket (FD=15) initialized
2014.12.05 05:56:39 LOG6[13990:140019053496064]: Read socket closed (readsocket)
2014.12.05 05:56:39 LOG7[13990:140019053496064]: Sending close_notify alert
2014.12.05 05:56:39 LOG7[13990:140019053496064]: SSL alert (write): warning: close notify
2014.12.05 05:56:39 LOG6[13990:140019053496064]: SSL_shutdown successfully sent close_notify alert
2014.12.05 05:56:39 LOG3[13990:140019053496064]: transfer: s_poll_wait: TIMEOUTclose exceeded: closing
2014.12.05 05:56:39 LOG5[13990:140019053496064]: Connection closed: 988 byte(s) sent to SSL, 873 byte(s) sent to socket
2014.12.05 05:56:39 LOG7[13990:140019053496064]: Remote socket (FD=15) closed
2014.12.05 05:56:39 LOG7[13990:140019053496064]: Local socket (FD=14) closed
2014.12.05 05:56:39 LOG7[13990:140019053496064]: Service [websockets] finished (3 left)
2014.12.05 05:56:43 LOG7[13990:140019053639616]: Service [websockets] accepted (FD=14) from 115.111.211.142:60045
2014.12.05 05:56:43 LOG7[13990:140019053496064]: Service [websockets] started
2014.12.05 05:56:43 LOG5[13990:140019053496064]: Service [websockets] accepted connection from 115.111.211.142:60045
2014.12.05 05:56:43 LOG7[13990:140019053496064]: SSL state (accept): before/accept initialization
2014.12.05 05:56:43 LOG7[13990:140019053496064]: SNI: no virtual services defined
2014.12.05 05:56:43 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 read client hello B
2014.12.05 05:56:43 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 write server hello A
2014.12.05 05:56:43 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 write change cipher spec A
2014.12.05 05:56:43 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 write finished A
2014.12.05 05:56:43 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 flush data
2014.12.05 05:56:43 LOG7[13990:140019053496064]: SSL state (accept): SSLv3 read finished A
2014.12.05 05:56:43 LOG7[13990:140019053496064]:   10 items in the session cache
2014.12.05 05:56:43 LOG7[13990:140019053496064]:    0 client connects (SSL_connect())
2014.12.05 05:56:43 LOG7[13990:140019053496064]:    0 client connects that finished
2014.12.05 05:56:43 LOG7[13990:140019053496064]:    0 client renegotiations requested
2014.12.05 05:56:43 LOG7[13990:140019053496064]: 1139 server connects (SSL_accept())
2014.12.05 05:56:43 LOG7[13990:140019053496064]: 1088 server connects that finished
2014.12.05 05:56:43 LOG7[13990:140019053496064]:    0 server renegotiations requested
2014.12.05 05:56:43 LOG7[13990:140019053496064]:  559 session cache hits
2014.12.05 05:56:43 LOG7[13990:140019053496064]:    0 external session cache hits
2014.12.05 05:56:43 LOG7[13990:140019053496064]:    0 session cache misses
2014.12.05 05:56:43 LOG7[13990:140019053496064]:  132 session cache timeouts
2014.12.05 05:56:43 LOG6[13990:140019053496064]: SSL accepted: previous session reused
2014.12.05 05:56:43 LOG6[13990:140019053496064]: connect_blocking: connecting 127.0.0.1:9000
2014.12.05 05:56:43 LOG7[13990:140019053496064]: connect_blocking: s_poll_wait 127.0.0.1:9000: waiting 10 seconds
2014.12.05 05:56:43 LOG5[13990:140019053496064]: connect_blocking: connected 127.0.0.1:9000
2014.12.05 05:56:43 LOG5[13990:140019053496064]: Service [websockets] connected remote server from 127.0.0.1:18480
2014.12.05 05:56:43 LOG7[13990:140019053496064]: Remote socket (FD=15) initialized
2014.12.05 05:56:43 LOG6[13990:140019053496064]: Read socket closed (readsocket)
2014.12.05 05:56:43 LOG7[13990:140019053496064]: Sending close_notify alert
2014.12.05 05:56:43 LOG5[13990:140019053496064]: Read socket error: Broken pipe (32)
2014.12.05 05:56:43 LOG5[13990:140019053496064]: Connection reset: 0 byte(s) sent to SSL, 516 byte(s) sent to socket
2014.12.05 05:56:43 LOG7[13990:140019053496064]: Remote socket (FD=15) closed
2014.12.05 05:56:43 LOG7[13990:140019053496064]: Local socket (FD=14) closed
2014.12.05 05:56:43 LOG7[13990:140019053496064]: Service [websockets] finished (3 left)

In our PHP WebSocket Server :

When the session reuse happens the WebSocket server just gets string 'G' as the data and nothing else so the handshake fails. However when a new session is create in the Stunnel, the handshake works fine.

It would be great if someone could help us out.

What have we done to solve this issue till now :

Disabled SSL Cache in Apache. ISSUE STILL THERE
Used Session Cache setting in stunnel. ISSUE STILL THERE. Also we dont have a clear understanding on the Session cache setting and how to disable it.

What we plan to do next

Recompile STUNNEL and try to disable SSL cache from the code.
Stop using STUNNEL and find out how to establish SSL Connection in PHP. Got something like stream_context_create to create these connections. However still we have to see the details of stream_context_create
Move everything to a new server and see where the issue.

Hope I have made things clear. Awaiting for replies. Thanks!

Read 1 byte off the stream first, then do a full read (concatenating the 1 byte to the full read). The "G" is most likely the first byte of a "GET". I'm not sure what causes it, but I experienced this recently. — John V.
WOW :D this worked! thanks a lot John! I am amazed such a simple solution! — yashair23
This happened to me as well in .NET with a normal SslStream. I think it is because the buffer also contains data about TLS negotiation, so only the first bytes of the actual data made it to the buffer. — vtortola

John V. John V. · Accepted Answer · 2017-11-17T22:37:52

Read 1 byte off the stream first, then do a full read (concatenating the 1 byte to the full read). The "G" is most likely the first byte of a "GET". I'm not sure what causes it, but I experienced this recently.

Secure Websocket (wss) Handshake does not happen using Stunnel

1 Answers