Disconnect when sending ping() from server.

[vindolin]

I'm using WebSocketsClient on my ESP8266 which connects to a python websocket server (https://github.com/aaugustin/websockets/ v3.0).
Everything works perfect but when I'm sending a ping() from the server handler to the client, I see a

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

on the serial console.
Am I missing something here?

Thanks for the great library!

[Links2004]

ping is supported, and tested with nodejs:

arduinoWebSockets/src/WebSockets.h

Line 106 in 848979e

WSop_ping = 0x09, ///< %x9 denotes a ping

https://github.com/Links2004/arduinoWebSockets/blob/master/src/WebSockets.cpp#L304

can you please enable debug here:
https://github.com/Links2004/arduinoWebSockets/blob/master/src/WebSockets.h#L30
and post the output.

Note: you may need to change Serial1 to Serial based on what you use.

[vindolin]

[WS-Client] connect ws...
[WS-Client] connected to 192.168.178.45:8081.
[WS-Client][sendHeader] sending header...
[WS-Client][sendHeader] sending header... Done (8472us).
[WS-Client][handleHeader] RX: HTTP/1.1 101 Switching Protocols
[WS-Client][handleHeader] RX: Server: Python/3.5 websockets/3.0
[WS-Client][handleHeader] RX: Upgrade: WebSocket
[WS-Client][handleHeader] RX: Connection: Upgrade
[WS-Client][handleHeader] RX: Sec-WebSocket-Accept: Tg5S3KZPuQlTHymEcLR11f/JRn0=
[WS-Client][handleHeader] Header read fin.
[WS-Client][handleHeader] Client settings:
[WS-Client][handleHeader]  - cURL: /
[WS-Client][handleHeader]  - cKey: sjlV+exvKPnhP1RBJsBxbQ==
[WS-Client][handleHeader] Server header:
[WS-Client][handleHeader]  - cCode: 101
[WS-Client][handleHeader]  - cIsUpgrade: 1
[WS-Client][handleHeader]  - cIsWebsocket: 1
[WS-Client][handleHeader]  - cAccept: Tg5S3KZPuQlTHymEcLR11f/JRn0=
[WS-Client][handleHeader]  - cProtocol: 
[WS-Client][handleHeader]  - cExtensions: 
[WS-Client][handleHeader]  - cVersion: 0
[WS-Client][handleHeader] Websocket connection init done.
[WSc] Connected to url: /
[WS][0][sendFrame] ------- send massage frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 1 length: 6 headerToPayload: 0
[WS][0][sendFrame] text: 101822
[WS][0][handleWebsocket] ------- read massage frame -------
[WS][0][handleWebsocket] fin: 1 rsv1: 0 rsv2: 0 rsv3 0  opCode: 9
[WS][0][handleWebsocket] mask: 0 payloadLen: 4
[WS][0][sendFrame] ------- send massage frame -------
[WS][0][sendFrame] fin: 1 opCode: 10 mask: 0 length: 4 headerToPayload: 0
[WS][0][handleWebsocket] ------- read massage frame -------
[WS][0][handleWebsocket] fin: 1 rsv1: 0 rsv2: 0 rsv3 0  opCode: 8
[WS][0][handleWebsocket] mask: 0 payloadLen: 2
[WS][0][handleWebsocket] get ask for close. Code: 1002
[WS][0][handleWebsocket] clientDisconnect code: 1000
[WS][0][sendFrame] not Connected!?
[WS-Client] client disconnected.
[WSc] Disconnected!

[Links2004]

the server has closed the connection

[WS][0][handleWebsocket] ------- read massage frame -------
[WS][0][handleWebsocket] fin: 1 rsv1: 0 rsv2: 0 rsv3 0  opCode: 8
[WS][0][handleWebsocket] get ask for close. Code: 1002

you shut enable debug for you server and check why it close the connection.

[vindolin]

Ok, thanks so far, I'll dive into that code later.

[vindolin]

I couldn't find anything obvious in the code.
I whipped up two client examples one with the python websocket library and one with nodejs and both run without problems against the server handler.
I'll do some more dissecting tomorrow.

[vindolin]

Merry Xmas!

Here's the nodejs server/client I'm testing with: https://gist.github.com/vindolin/1601c29319f466b70dfc

When the ESP joins the party, the server crashes with:

Connection closed

events.js:72
        throw er; // Unhandled 'error' event
              ^
Error: read ECONNRESET
    at errnoException (net.js:901:11)
    at TCP.onread (net.js:556:19)

Does the ESP ws client respond with pongs by itself or do I have to do this myself?

[Links2004]

yes it auto response with the same message then the server send as pong (RFC6455).
https://github.com/Links2004/arduinoWebSockets/blob/master/src/WebSockets.cpp#L306

you can see it in the log:

[WS][0][sendFrame] ------- send massage frame -------                                              
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 1 length: 6 headerToPayload: 0            # your sendTXT
[WS][0][sendFrame] text: 101822
[WS][0][handleWebsocket] ------- read massage frame ------- 
[WS][0][handleWebsocket] fin: 1 rsv1: 0 rsv2: 0 rsv3 0  opCode: 9                   # server sends ping
[WS][0][handleWebsocket] mask: 0 payloadLen: 4
[WS][0][sendFrame] ------- send massage frame -------
[WS][0][sendFrame] fin: 1 opCode: 10 mask: 0 length: 4 headerToPayload: 0           # pong is send to the server
[WS][0][handleWebsocket] ------- read massage frame -------
[WS][0][handleWebsocket] fin: 1 rsv1: 0 rsv2: 0 rsv3 0  opCode: 8                   # server sends close command
[WS][0][handleWebsocket] mask: 0 payloadLen: 2
[WS][0][handleWebsocket] get ask for close. Code: 1002
[WS][0][handleWebsocket] clientDisconnect code: 1000                                # client want to ack to the close command but server has closed TCP already
[WS][0][sendFrame] not Connected!?
[WS-Client] client disconnected.
[WSc] Disconnected!

i think the server has some how a problem with the pong response, or the response comes too late to the server,
may increase the possible response time.

i use this for testing:
https://github.com/Links2004/arduinoWebSockets/blob/master/tests/webSocketServer/index.js
the server sends every 20sec a ping to the client, it working fine:

[WS][0][handleWebsocket] ------- read massage frame -------
[WS][0][handleWebsocket] fin: 1 rsv1: 0 rsv2: 0 rsv3 0  opCode: 9                    # server sends ping
[WS][0][handleWebsocket] mask: 0 payloadLen: 0
[WS][0][sendFrame] ------- send massage frame -------
[WS][0][sendFrame] fin: 1 opCode: 10 mask: 0 length: 0 headerToPayload: 0            # pong is send to the server
[WS][0][handleWebsocket] ------- read massage frame -------
[WS][0][handleWebsocket] fin: 1 rsv1: 0 rsv2: 0 rsv3 0  opCode: 9                    # server sends ping
[WS][0][handleWebsocket] mask: 0 payloadLen: 0
[WS][0][sendFrame] ------- send massage frame -------
[WS][0][sendFrame] fin: 1 opCode: 10 mask: 0 length: 0 headerToPayload: 0            # pong is send to the server

[vindolin]

Weird... that's the first library that actually doesn't drop the connection in my tests and I see the same debug messages as you.
All the other three that I tried dropped the connection.
The last one I tried was Autobahn.ws and it showed the same problem event though I changed the parameters for autoPingTimeout and keepaliveGracePeriod.

WebSocket connection closed: connection was closed uncleanly (I failed the WebSocket connection by dropping the TCP connection)

https://gist.github.com/vindolin/3e67d511e6c0d37251e8

[Links2004]

can you measure the delay in which the ESP answers?
I get my answers around 8-12ms.

I have seen some people have problems with the inter working form ESP and there router / AP,
resulting in high package delay up to 1000ms.
may you have a similar problem.

[vindolin]

The project I'm working on transmits a payload with data for neopixel arrays to the ESP, the ESP then answers with it's module id, then the next payload is sent. My proof of concept here with a onmousemove colorpicker runs in realtime, so the delay can't be much more than a few milliseconds.

[Links2004]

right now I am out of ideas,

• the log show that the pong is send after the ping is received.
• the delay is low.
• I have reread the RFC6455 ping / pong part and see no problems.

the RFC can be found here:
https://tools.ietf.org/html/rfc6455#page-37
may you see something i not see right now.

[vindolin]

Thanks for the effort, I'll look into that when I have more time as everything else is working perfectly, I just wanted to have a way for the server to know if any of the modules were disconnected so the server handles get closed. I think, I can workaround that with some custom messages and timeouts myself, until I find the bug.

[Links2004]

I had some idea, may the server cant handle the fact that the pong frame where in to TCP frames.
I change the code, now it automatically combined in on TCP package if possible.