Ratchet: ratchet detected an invalid reserve code - immediate disconnect after connection under SSL

[arvanus]

Hi.
I'm testing ratchet (updated) under apache with SSL (Let's Encrypt)

Server version: Apache/2.4.6 (CentOS)
Server built: Apr 20 2018 18:10:38
/usr/bin/supervisord -v 3.1.4

• Updating ratchet/rfc6455 (v0.2.3 => 0.2.4): Downloading (100%)
• Updating react/event-loop (v0.4.3 => v0.5.2): Downloading (100%)
• Updating react/promise-timer (v1.2.1 => v1.3.0): Downloading (100%)
• Updating react/socket (v0.8.10 => v0.8.11): Downloading (100%)
• Updating symfony/polyfill-mbstring (v1.7.0 => v1.8.0): Downloading (100%)
• Updating symfony/http-foundation (v4.0.6 => v4.0.9): Downloading (100%)
• Updating symfony/routing (v4.0.6 => v4.0.9): Downloading (100%)

And I`m encountering a random problem during connection, sometimes everything works just fine, but other times when I'm connecting, after sending default websocket HTTP connection header I receive from Ratchet this error:

[2 characters from default websocket msg frame]ratchet detected an invalid reserve code

Note that in this case I didn't received the normal response after sending the HTTP connection header.
Here is a normal operation example:

TIdSSLIOHandlerSocketOpenSSL#hsResolving:Resolving XXXXXXXXXXXXXXXX.
TIdSSLIOHandlerSocketOpenSSL#hsConnecting:Connecting to XXX.XXX.XXX.XXX.
StatusInfo:SSL status: "before/connect initialization"
StatusInfo:SSL status: "before/connect initialization"
StatusInfo:SSL status: "SSLv2/v3 write client hello A"
StatusInfo:SSL status: "SSLv3 read server hello A"
StatusInfo:SSL status: "SSLv3 read server certificate A"
StatusInfo:SSL status: "SSLv3 read server key exchange A"
StatusInfo:SSL status: "SSLv3 read server done A"
StatusInfo:SSL status: "SSLv3 write client key exchange A"
StatusInfo:SSL status: "SSLv3 write change cipher spec A"
StatusInfo:SSL status: "SSLv3 write finished A"
StatusInfo:SSL status: "SSLv3 flush data"
StatusInfo:SSL status: "SSLv3 read server session ticket A"
StatusInfo:SSL status: "SSLv3 read finished A"
StatusInfo:SSL status: "SSL negotiation finished successfully"
StatusInfo:SSL status: "SSL negotiation finished successfully"
StatusInfo:Cipher: name = ECDHE-RSA-AES128-GCM-SHA256; description = ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 Kx=ECDH     Au=RSA  Enc=AESGCM(128) Mac=AEAD
; bits = 128; version = TLSv1/SSLv3; 
TIdTCPClient#hsConnected:Connected.
SENDING
GET /wss/ HTTP/1.1
Host: XXXXXXXXXXXXXX:XXXX
User-Agent: Delphi TCP
Connection: keep-alive, Upgrade
Upgrade: websocket
Sec-WebSocket-Version: 13
Sec-WebSocket-Key: wljiVCqHsNeAbmqn4741Pw==

RECEIVING
HTTP/1.1 101 Switching Protocols
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Accept: Ad3sUpmwS8qGAbIshGLzWnT4+j0=
X-Powered-By: Ratchet/0.4.1

.... normal operation

Apache log:

[Thu May 10 14:00:59.348194 2018] [ssl:debug] [pid 21725] ssl_engine_kernel.c(225): [client 192.168.1.1:50603] AH02034: Initial (No.1) HTTPS request received for child 4 (server XXXXXXXXXXXXXXXXXX:443)
[Thu May 10 14:00:59.348302 2018] [authz_core:debug] [pid 21725] mod_authz_core.c(835): [client 192.168.1.1:50603] AH01628: authorization result: granted (no directives)
[Thu May 10 14:00:59.348368 2018] [proxy:debug] [pid 21725] mod_proxy.c(1123): [client 192.168.1.1:50603] AH01143: Running scheme ws handler (attempt 0)
[Thu May 10 14:00:59.348384 2018] [proxy_ajp:debug] [pid 21725] mod_proxy_ajp.c(722): [client 192.168.1.1:50603] AH00894: declining URL ws://localhost:8080//
[Thu May 10 14:00:59.348397 2018] [proxy_fcgi:debug] [pid 21725] mod_proxy_fcgi.c(972): [client 192.168.1.1:50603] AH01076: url: ws://localhost:8080// proxyname: (null) proxyport: 0
[Thu May 10 14:00:59.348408 2018] [proxy_fcgi:debug] [pid 21725] mod_proxy_fcgi.c(975): [client 192.168.1.1:50603] AH01077: declining URL ws://localhost:8080//
[Thu May 10 14:00:59.348421 2018] [proxy_http:debug] [pid 21725] mod_proxy_http.c(1930): [client 192.168.1.1:50603] AH01113: HTTP: declining URL ws://localhost:8080//
[Thu May 10 14:00:59.348432 2018] [proxy_scgi:debug] [pid 21725] mod_proxy_scgi.c(517): [client 192.168.1.1:50603] AH00865: declining URL ws://localhost:8080//
[Thu May 10 14:00:59.348443 2018] [proxy_wstunnel:debug] [pid 21725] mod_proxy_wstunnel.c(336): [client 192.168.1.1:50603] AH02451: serving URL ws://localhost:8080//
[Thu May 10 14:00:59.348454 2018] [proxy:debug] [pid 21725] proxy_util.c(2203): AH00942: WS: has acquired connection for (localhost)
[Thu May 10 14:00:59.348467 2018] [proxy:debug] [pid 21725] proxy_util.c(2256): [client 192.168.1.1:50603] AH00944: connecting ws://localhost:8080// to localhost:8080
[Thu May 10 14:00:59.348481 2018] [proxy:debug] [pid 21725] proxy_util.c(2422): [client 192.168.1.1:50603] AH00947: connected // to localhost:8080
[Thu May 10 14:00:59.348563 2018] [proxy:debug] [pid 21725] proxy_util.c(2658): AH00951: WS: backend socket is disconnected.
[Thu May 10 14:00:59.348652 2018] [proxy:debug] [pid 21725] proxy_util.c(2789): (111)Connection refused: AH00957: WS: attempt to connect to [::1]:8080 (localhost) failed
[Thu May 10 14:00:59.348748 2018] [proxy:debug] [pid 21725] proxy_util.c(2798): AH02824: WS: connection established with 127.0.0.1:8080 (localhost)
[Thu May 10 14:00:59.348807 2018] [proxy:debug] [pid 21725] proxy_util.c(2938): AH00962: WS: connection complete to [::1]:8080 (localhost)
[Thu May 10 14:00:59.349640 2018] [proxy_wstunnel:debug] [pid 21725] mod_proxy_wstunnel.c(257): [client 192.168.1.1:50603] AH02445: woke from poll(), i=1
[Thu May 10 14:00:59.349661 2018] [proxy_wstunnel:debug] [pid 21725] mod_proxy_wstunnel.c(266): [client 192.168.1.1:50603] AH02446: sock was readable
success^

Now an example with error:

TIdSSLIOHandlerSocketOpenSSL#hsResolving:Resolving XXXXXXXXXXXXXXXX.
TIdSSLIOHandlerSocketOpenSSL#hsConnecting:Connecting to XXX.XXX.XXX.XXX.
StatusInfo:SSL status: "before/connect initialization"
StatusInfo:SSL status: "before/connect initialization"
StatusInfo:SSL status: "SSLv2/v3 write client hello A"
StatusInfo:SSL status: "SSLv3 read server hello A"
StatusInfo:SSL status: "SSLv3 read server certificate A"
StatusInfo:SSL status: "SSLv3 read server key exchange A"
StatusInfo:SSL status: "SSLv3 read server done A"
StatusInfo:SSL status: "SSLv3 write client key exchange A"
StatusInfo:SSL status: "SSLv3 write change cipher spec A"
StatusInfo:SSL status: "SSLv3 write finished A"
StatusInfo:SSL status: "SSLv3 flush data"
StatusInfo:SSL status: "SSLv3 read server session ticket A"
StatusInfo:SSL status: "SSLv3 read finished A"
StatusInfo:SSL status: "SSL negotiation finished successfully"
StatusInfo:SSL status: "SSL negotiation finished successfully"
StatusInfo:Cipher: name = ECDHE-RSA-AES128-GCM-SHA256; description = ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 Kx=ECDH     Au=RSA  Enc=AESGCM(128) Mac=AEAD
; bits = 128; version = TLSv1/SSLv3; 
TIdTCPClient#hsConnected:Connected.
SENDING
GET /wss/ HTTP/1.1
Host: XXXXXXXXXXXXXX:XXXX
User-Agent: Delphi TCP
Connection: keep-alive, Upgrade
Upgrade: websocket
Sec-WebSocket-Version: 13
Sec-WebSocket-Key: wljiVCqHsNeAbmqn4741Pw==

RECEIVING
__ratchet detected an invalid reserve code

Apache log:

[Thu May 10 14:00:07.752369 2018] [ssl:debug] [pid 21722] ssl_engine_kernel.c(225): [client 192.168.1.1:50601] AH02034: Initial (No.1) HTTPS request received for child 1 (server XXXXXXXXXXXXXXXXXX:443)
[Thu May 10 14:00:07.752480 2018] [authz_core:debug] [pid 21722] mod_authz_core.c(835): [client 192.168.1.1:50601] AH01628: authorization result: granted (no directives)
[Thu May 10 14:00:07.752532 2018] [proxy:debug] [pid 21722] mod_proxy.c(1123): [client 192.168.1.1:50601] AH01143: Running scheme ws handler (attempt 0)
[Thu May 10 14:00:07.752548 2018] [proxy_ajp:debug] [pid 21722] mod_proxy_ajp.c(722): [client 192.168.1.1:50601] AH00894: declining URL ws://localhost:8080//
[Thu May 10 14:00:07.752560 2018] [proxy_fcgi:debug] [pid 21722] mod_proxy_fcgi.c(972): [client 192.168.1.1:50601] AH01076: url: ws://localhost:8080// proxyname: (null) proxyport: 0
[Thu May 10 14:00:07.752573 2018] [proxy_fcgi:debug] [pid 21722] mod_proxy_fcgi.c(975): [client 192.168.1.1:50601] AH01077: declining URL ws://localhost:8080//
[Thu May 10 14:00:07.752586 2018] [proxy_http:debug] [pid 21722] mod_proxy_http.c(1930): [client 192.168.1.1:50601] AH01113: HTTP: declining URL ws://localhost:8080//
[Thu May 10 14:00:07.752599 2018] [proxy_scgi:debug] [pid 21722] mod_proxy_scgi.c(517): [client 192.168.1.1:50601] AH00865: declining URL ws://localhost:8080//
[Thu May 10 14:00:07.752610 2018] [proxy_wstunnel:debug] [pid 21722] mod_proxy_wstunnel.c(336): [client 192.168.1.1:50601] AH02451: serving URL ws://localhost:8080//
[Thu May 10 14:00:07.752622 2018] [proxy:debug] [pid 21722] proxy_util.c(2203): AH00942: WS: has acquired connection for (localhost)
[Thu May 10 14:00:07.752636 2018] [proxy:debug] [pid 21722] proxy_util.c(2256): [client 192.168.1.1:50601] AH00944: connecting ws://localhost:8080// to localhost:8080
[Thu May 10 14:00:07.752650 2018] [proxy:debug] [pid 21722] proxy_util.c(2422): [client 192.168.1.1:50601] AH00947: connected // to localhost:8080
[Thu May 10 14:00:07.753080 2018] [proxy_wstunnel:debug] [pid 21722] mod_proxy_wstunnel.c(257): [client 192.168.1.1:50601] AH02445: woke from poll(), i=1
[Thu May 10 14:00:07.753102 2018] [proxy_wstunnel:debug] [pid 21722] mod_proxy_wstunnel.c(266): [client 192.168.1.1:50601] AH02446: sock was readable
[Thu May 10 14:00:07.753170 2018] [proxy:debug] [pid 21722] proxy_util.c(2218): AH00943: WS: has released connection for (localhost)
[Thu May 10 14:00:07.753238 2018] [ssl:debug] [pid 21722] ssl_engine_io.c(993): [client 192.168.1.1:50601] AH02001: Connection closed to child 1 with standard shutdown (server XXXXXXXXXXXXXXXXXX:443)
^fail

My apache config.:

<IfModule mod_ssl.c>
<VirtualHost  *:8443>
    ProxyPreserveHost On
    ProxyPass "/ws" "ws://localhost:8080/"
    ProxyPass "/wss" "ws://localhost:8080/"
    ProxyPassReverse "/ws" "ws://localhost:8080/"
    ProxyPassReverse "/wss" "ws://localhost:8080/"

    ServerName XXXXXXXXXXXXXXXXXXX
    Alias /index.php /usr/share/httpd/noindex/index.html

SSLCertificateFile /etc/letsencrypt/live/XXXXXXX/cert.pem
SSLCertificateKeyFile /etc/letsencrypt/live/XXXXXXX/privkey.pem
Include /etc/letsencrypt/options-ssl-apache.conf
SSLCertificateChainFile /etc/letsencrypt/live/XXXXXXX/chain.pem
</VirtualHost>
</IfModule>

Has someone experienced this problem before?
*Connecting directly without SSL always worked.

Thanks!

[mbonneau]

I am thinking there may be some other issue. Ratchet should not be able to tell the difference between ws and wss if you are reverse-proxying.

Is the connection being dropped on one end or perhaps there are unprintable characters that are sent after the request?

A packet capture between Apache and Ratchet would be helpful if possible.

[arvanus]

Hi!
Finally, I discovered how to reproduce the problem!
Apparently, when a client disconnected without sending the specific opcode, it`s connection was still active inside ratchet. So, when another user connects, ratchet somehow send to this new user a error that was raised from the offline client.
I'm using the chatbot example.

How can I prevent one connection to disturb the others?

Thanks!

[sudoanand]

Any luck? I'm facing the same

[arvanus]

@mbonneau

Is the connection being dropped on one end or perhaps there are unprintable characters that are sent after the request?

Yes, the client receives 2 bytes referring the websocket message frame.
I could say that when some client disconnects without default websockt close protocol, ratchet keeps the connection "open", but when a new user connects then ratchet reuses somehow the last "open"(closed) connection...
Because the new client uses a old "active" connection, when it sends the HTTP handshake, ratchet complains because it isn't the default message frame.

[sudoanand]

I was using Apache proxypass and reverse proxy, I simply switched to Nginx and this problem vanished.

Following is my working server block:

upstream localhost{
   server xxx.in:12345;
}


server {
    listen       443;
    server_name  xxx.in;
    root         /var/www/html;
    ssl_certificate "/etc/letsencrypt/live/xxx.in/cert.pem";
    ssl_certificate_key "/etc/letsencrypt/live/xxx.in/privkey.pem";
    ssl_session_cache shared:SSL:1m;
    ssl_session_timeout  10m;
    ssl_ciphers HIGH:!aNULL:!MD5;
    ssl_prefer_server_ciphers on;


    location / {
        proxy_pass http://localhost;
        proxy_http_version 1.1;
        proxy_set_header Upgrade $http_upgrade;
        proxy_set_header Connection $connection_upgrade;
        proxy_redirect off;
        proxy_read_timeout 86400s;
        proxy_send_timeout 86400s;
        keepalive_timeout 86400s;
        # prevents 502 bad gateway error
        proxy_buffers 8 32k;
        proxy_buffer_size 64k;
        proxy_set_header X-Real-IP $remote_addr;
        proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
        proxy_set_header X-Forwarded-Proto https;
        reset_timedout_connection on;
    }
}

Edit: People still looking for a solution to this issue will find this helpful, How to setup WSS for Ratchet WebSocket Server on Nginx or Apache

[arvanus]

@hack4mer I'll try it here too (later, can't now)! Thanks!

[cytsunny]

Curious if switching to Nginx is not an option, is there other solution using Apache only?

[arvanus]

Hi, I was looking for some configuration at Apache, and found this:
https://httpd.apache.org/docs/trunk/mod/mod_proxy.html#proxypass
[...]

ProxyPass "/example" "http://backend.example.com"  disablereuse=On

[...]

Parameter | Default | Description
-- | -- | --
disablereuse | Off | This parameter should be used when you want to force mod_proxy to immediately close a connection to the backend after being used, and thus, disable its persistent connection and pool for that backend. This helps in various situations where a firewall between Apache httpd and the backend server (regardless of protocol) tends to silently drop connections or when backends themselves may be under round- robin DNS. When connection reuse is enabled each backend domain is resolved (with a DNS query) only once per child process and cached for all further connections until the child is recycled. To disable connection reuse, set this property value to On.
-- | -- | --
enablereuse | On | This is the inverse of 'disablereuse' above, provided as a convenience for scheme handlers that require opt-in for connection reuse (such as mod_proxy_fcgi).

Probably this could help. Someone can test this? Because I'm not using this right know...

[cytsunny]

Thanks for your reply. I have changed the settings and set it running for an hour now and it seems this error did not come back. If I do not further ask for help here, you may treat that as a working solution.

[maynor96]

Hi, I was looking for some configuration at Apache, and found this:
https://httpd.apache.org/docs/trunk/mod/mod_proxy.html#proxypass
[...]

ProxyPass "/example" "http://backend.example.com"  disablereuse=On

[...]

Parameter Default Description
disablereuse Off This parameter should be used when you want to force mod_proxy to immediately close a connection to the backend after being used, and thus, disable its persistent connection and pool for that backend. This helps in various situations where a firewall between Apache httpd and the backend server (regardless of protocol) tends to silently drop connections or when backends themselves may be under round- robin DNS. When connection reuse is enabled each backend domain is resolved (with a DNS query) only once per child process and cached for all further connections until the child is recycled. To disable connection reuse, set this property value to On.
-- -- --
enablereuse On This is the inverse of 'disablereuse' above, provided as a convenience for scheme handlers that require opt-in for connection reuse (such as mod_proxy_fcgi).
Probably this could help. Someone can test this? Because I'm not using this right know...

It works for me, thanks!