Websocket client disconnecting after receiving weird opcodes #235

TobiasRobl · 2017-09-12T13:44:28Z

I am using the latest git version of the arduinoWebSockets lib and the WebSocketClientSSL example.
Tested with both ESP8266 Arduino core 2.4.0-rc1 and git version.
Websocket Server using the ws lib on node.js

After the ws client established the connection a first "Connected" is sent but then the client disconnects after receiving weird opCodes and reconnects again and again:

[WSc] Connected to url: /
[WSc] Disconnected!
[WSc] Connected to url: /
[WSc] Disconnected!
[WSc] Connected to url: /
[WSc] Disconnected!
...

Full debug output: (opCode 8)

[WS-Client] connect wss...
please start sntp first !
[WS-Client] connected to <url-of-node-app>:443.
[WS-Client][sendHeader] sending header...
[WS-Client][sendHeader] handshake GET / HTTP/1.1
Host: <url-of-node-app>:443
Connection: Upgrade
Upgrade: websocket
Sec-WebSocket-Version: 13
Sec-WebSocket-Key: fXQ/uAk61ZApRRSAMIAkHw==
Origin: file://
User-Agent: arduino-WebSocket-Client

[write] n: 241 t: 26597
[WS-Client][sendHeader] sending header... Done (27999us).
[WS-Client][handleHeader] RX: HTTP/1.1 101 Switching Protocols
[WS-Client][handleHeader] RX: Upgrade: websocket
[WS-Client][handleHeader] RX: Connection: Upgrade
[WS-Client][handleHeader] RX: Sec-WebSocket-Accept: ZDRc0LuCGFe3AUGkJdyRqMI214g=
[WS-Client][handleHeader] Header read fin.
[WS-Client][handleHeader] Client settings:
[WS-Client][handleHeader]  - cURL: /
[WS-Client][handleHeader]  - cKey: fXQ/uAk61ZApRRSAMIAkHw==
[WS-Client][handleHeader] Server header:
[WS-Client][handleHeader]  - cCode: 101
[WS-Client][handleHeader]  - cIsUpgrade: 1
[WS-Client][handleHeader]  - cIsWebsocket: 1
[WS-Client][handleHeader]  - cAccept: ZDRc0LuCGFe3AUGkJdyRqMI214g=
[WS-Client][handleHeader]  - cProtocol: 
[WS-Client][handleHeader]  - cExtensions: 
[WS-Client][handleHeader]  - cVersion: 0
[WS-Client][handleHeader]  - cSessionId: 
[WS-Client][handleHeader] Websocket connection init done.
[WS][0][headerDone] Header Handling Done (0us).
[WSc] Connected to url: /
[WS][0][sendFrame] ------- send massage frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 1 length: 9 headerToPayload: 0
[WS][0][sendFrame] text: Connected
[WS][0][sendFrame] pack to one TCP package...
[write] n: 15 t: 26715
[WS][0][sendFrame] sending Frame Done (4467us).
[WS][0][handleWebsocketWaitFor] size: 2 cWsRXsize: 0
[readCb] n: 2 t: 26725
[WS][0][handleWebsocketWaitFor][readCb] size: 2 ok: 1
[WS][0][handleWebsocket] ------- read massage frame -------
[WS][0][handleWebsocket] fin: 0 rsv1: 1 rsv2: 1 rsv3 0  opCode: 8
[WS][0][handleWebsocket] mask: 1 payloadLen: 24
[WS][0][handleWebsocketWaitFor] size: 6 cWsRXsize: 2
[readCb] n: 4 t: 26752
[WS][0][handleWebsocketWaitFor][readCb] size: 6 ok: 1
[WS][0][handleWebsocket] ------- read massage frame -------
[WS][0][handleWebsocket] fin: 0 rsv1: 1 rsv2: 1 rsv3 0  opCode: 8
[WS][0][handleWebsocket] mask: 1 payloadLen: 24
[readCb] n: 24 t: 26773
[readCb] receive TIMEOUT! 2001                        <------------------------ Why is that?
[WS][0][handleWebsocket] missing data!
[WS][0][handleWebsocket] clientDisconnect code: 1002
[WS][0][sendFrame] ------- send massage frame -------
[WS][0][sendFrame] fin: 1 opCode: 8 mask: 0 length: 2 headerToPayload: 0
[WS][0][sendFrame] pack to one TCP package...
[write] n: 4 t: 28790
[WS][0][sendFrame] sending Frame Done (5008us).
[WS-Client] client disconnected.
[WSc] Disconnected!

Example with opCode 4:

[WSc] Connected to url: /
[WS][0][sendFrame] ------- send massage frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 1 length: 9 headerToPayload: 0
[WS][0][sendFrame] text: Connected
[WS][0][sendFrame] pack to one TCP package...
[write] n: 15 t: 30886
[WS][0][sendFrame] sending Frame Done (3791us).
[WS][0][handleWebsocketWaitFor] size: 2 cWsRXsize: 0
[readCb] n: 2 t: 30897
[WS][0][handleWebsocketWaitFor][readCb] size: 2 ok: 1
[WS][0][handleWebsocket] ------- read massage frame -------
[WS][0][handleWebsocket] fin: 0 rsv1: 0 rsv2: 0 rsv3 0  opCode: 4
[WS][0][handleWebsocket] mask: 0 payloadLen: 45
[readCb] n: 45 t: 30919
[readCb] receive TIMEOUT! 2001
[WS][0][handleWebsocket] missing data!
[WS][0][handleWebsocket] clientDisconnect code: 1002
[WS][0][sendFrame] ------- send massage frame -------
[WS][0][sendFrame] fin: 1 opCode: 8 mask: 0 length: 2 headerToPayload: 0
[WS][0][sendFrame] pack to one TCP package...
[write] n: 4 t: 32936
[WS][0][sendFrame] sending Frame Done (4642us).
[WS-Client] client disconnected.
[WSc] Disconnected!

Example with opCode 15:

[WS][0][sendFrame] ------- send massage frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 1 length: 9 headerToPayload: 0
[WS][0][sendFrame] text: Connected
[WS][0][sendFrame] pack to one TCP package...
[write] n: 15 t: 33953
[WS][0][sendFrame] sending Frame Done (4188us).
[WS][0][handleWebsocketWaitFor] size: 2 cWsRXsize: 0
[readCb] n: 2 t: 33964
[WS][0][handleWebsocketWaitFor][readCb] size: 2 ok: 1
[WS][0][handleWebsocket] ------- read massage frame -------
[WS][0][handleWebsocket] fin: 1 rsv1: 1 rsv2: 0 rsv3 1  opCode: 15
[WS][0][handleWebsocket] mask: 1 payloadLen: 102
[WS][0][handleWebsocketWaitFor] size: 6 cWsRXsize: 2
[readCb] n: 4 t: 33990
[WS][0][handleWebsocketWaitFor][readCb] size: 6 ok: 1
[WS][0][handleWebsocket] ------- read massage frame -------
[WS][0][handleWebsocket] fin: 1 rsv1: 1 rsv2: 0 rsv3 1  opCode: 15
[WS][0][handleWebsocket] mask: 1 payloadLen: 102
[readCb] n: 102 t: 34012
[readCb] receive TIMEOUT! 2001
[WS][0][handleWebsocket] missing data!
[WS][0][handleWebsocket] clientDisconnect code: 1002
[WS][0][sendFrame] ------- send massage frame -------
[WS][0][sendFrame] fin: 1 opCode: 8 mask: 0 length: 2 headerToPayload: 0
[WS][0][sendFrame] pack to one TCP package...
[write] n: 4 t: 36030
[WS][0][sendFrame] sending Frame Done (4906us).
[WS-Client] client disconnected.
[WSc] Disconnected!

Am I missing something?
Thank you very much in advance! :)

The text was updated successfully, but these errors were encountered:

Links2004 · 2017-09-12T17:03:44Z

the opcodes are defined here:
https://github.com/Links2004/arduinoWebSockets/blob/master/src/WebSockets.h#L173

but 4 and 15 are reserved according to RFC6455.

the read function has a timeout of 2sec by default.
https://github.com/Links2004/arduinoWebSockets/blob/master/src/WebSockets.cpp#L562
https://github.com/Links2004/arduinoWebSockets/blob/master/src/WebSockets.h#L70

I can think of two possible problems:

there are some unknown opcodes send from the server
there are too less or too many bytes in the message before the wrong opcode which creates a offset in the passing resulting in the strange 15 / 4 opcodes.

how does the server side look?

the git repo includes nodejs websocket server code, may this helps you to track this down a little more.

schlaegerz · 2017-09-14T19:37:49Z

I'm getting the same issue. It looks like the first frame it reads is always junk. If i print out the payload it will sometimes look like this:

iޟ��G�W`}��2K��1{"msg":"connected","session":"xKi85FN2uLFr3Nz23"}

The opcode seems to change everytime I rerun it so it looks like there is just junk being read.

Links2004 · 2017-09-15T09:21:11Z

how does the server side look?
is this only happening with SSL involved?

schlaegerz · 2017-09-15T16:58:03Z

For mine... It's does only happen when I use SSL. Normal websockets work just fine.

Our server is a meteor server hosted on heroku. Plenty of other clients have been able to use SSL for us so it should be workable.

schlaegerz · 2017-09-15T17:56:11Z

Just a further data point, if i ignore the first 19 characters in the buffer after it connects, everything seems to work a lot better.

schlaegerz · 2017-09-21T17:39:08Z

After even more investigating, it looks like it might just be failing to decode the first message or something which is "{"server_id":"0"}" If i make sure it ignores that, i have no issue the rest of the way.

Any idea why it would not decode the first thing sent to it?

schlaegerz · 2017-09-22T18:12:26Z

My issue ended up being related to this issue. esp8266/Arduino#3002

There is a merge request in that issue to the WifiClientSecure and to the TLS library. When I incorportated those changes locally it ended up fixing my issue.

Links2004 · 2017-09-23T19:04:43Z

ok the problem is in the WifiClientSecure,
that´s why I dont get it tracked down in the websocket code.
Had driving me nuts.

schlaegerz · 2017-09-23T19:21:19Z

Yeah oddly it never happened when I do a httpClient download over ssl which made me think it was websockets.

I think you can prevent most of the problems by calling available() less often as that is the function call that screws it up.

The root of the problem is every time you call available() you need to read everything in the buffer before you write anything.

sluebbert · 2017-12-28T02:31:34Z

A recent update to WiFiClientSecure fixed the issues I had relating to this behavior. I was getting those constant 2 second timeouts once I switched to SSL, but this cleared that up.
esp8266/Arduino#4024
Looks like the related issue referenced above (esp8266/Arduino#3002) got closed up too.

Links2004 mentioned this issue Nov 11, 2017

beginSocketIOSSL() Disconnects repeatedly. #251

Closed

Links2004 closed this as completed Dec 28, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Websocket client disconnecting after receiving weird opcodes #235

Websocket client disconnecting after receiving weird opcodes #235

TobiasRobl commented Sep 12, 2017

Links2004 commented Sep 12, 2017 •

edited

Loading

schlaegerz commented Sep 14, 2017

Links2004 commented Sep 15, 2017

schlaegerz commented Sep 15, 2017

schlaegerz commented Sep 15, 2017

schlaegerz commented Sep 21, 2017

schlaegerz commented Sep 22, 2017

Links2004 commented Sep 23, 2017

schlaegerz commented Sep 23, 2017

sluebbert commented Dec 28, 2017

Websocket client disconnecting after receiving weird opcodes #235

Websocket client disconnecting after receiving weird opcodes #235

Comments

TobiasRobl commented Sep 12, 2017

Links2004 commented Sep 12, 2017 • edited Loading

schlaegerz commented Sep 14, 2017

Links2004 commented Sep 15, 2017

schlaegerz commented Sep 15, 2017

schlaegerz commented Sep 15, 2017

schlaegerz commented Sep 21, 2017

schlaegerz commented Sep 22, 2017

Links2004 commented Sep 23, 2017

schlaegerz commented Sep 23, 2017

sluebbert commented Dec 28, 2017

Links2004 commented Sep 12, 2017 •

edited

Loading