Description
I am still investigating this but posting this before I fully understand it because I am having to understand the library code to work out what's happening and hopefully more knowledgeable people can look/suggest things.
The symptom is that a client on an ESP32 sends a 1002 protocol error and usually, but not always, restarts the protocol. This is because it is, instead of reading the frame header reads frame data expecting it to be the header and then very soon afterwards the protocol breaks down either directly or via timeouts.
I can see this occurring from the debug, (and with additional statements inserted into the library) where the handleWebsocketWaitFor requests 2 bytes and gets 8 caused by a negative 1 response from client->tcp->read(). I haven't checked to see if this exceeds the buffer pointed to by out.
console log:
[WS][0][handleWebsocketWaitFor] size: 2 cWsRXsize: 0
[readCb] n: 2 t: 92050
n:2
[MJG][WebSockets.read :⸮�0I
Receive -1 left 3!
n:3
[MJG][WebSockets.read :
Receive -1 left 4!
n:4
[MJG][WebSockets.read :�({"
Receive 4 left 0!
[WS][0][handleWebsocketWaitFor][readCb] size: 2 ok: 1
[WS][0][handleWebsocket] ------- read massage frame -------
[WS][0][handleWebsocket] fin: 0 rsv1: 1 rsv2: 1 rsv3 1 opCode: 11
[WS][0][handleWebsocket] mask: 0 payloadLen: 34
[readCb] n: 34 t: 92057
I have no idea where the first four bytes are coming from at the moment as they are not in the websocket data stream captured as sent from the server by wireshark. The �( is the correct header. Examining the wireshark capture the transmitted data is correct protocol and is correctly decoded by wireshark.
There is perhaps something time/speed related as without any debug messages the protocol error occurs very quickly and it feels that with more messages it is longer between fails. So the time taken to transfer data to the console does have an impact. But this is purely subjective.
The code section from the library with modified debug messages just to verify that I'm not affecting variables. My changes are tagged [MJG] so I know what to back out later:
bool WebSockets::readCb(WSclient_t * client, uint8_t * out, size_t n, WSreadWaitCb cb) {
#if(WEBSOCKETS_NETWORK_TYPE == NETWORK_ESP8266_ASYNC)
if(!client->tcp || !client->tcp->connected()) {
return false;
}
client->tcp->readBytes(out, n, std::bind([](WSclient_t * client, bool ok, WSreadWaitCb cb) {
if(cb) {
cb(client, ok);
}
},
client, std::placeholders::_1, cb));
#else
unsigned long t = millis();
size_t len;
DEBUG_WEBSOCKETS("[readCb] n: %zu t: %lu\n", n, t);
while(n > 0) {
DEBUG_WEBSOCKETS("n:%d\n",n);
if(client->tcp == NULL) {
DEBUG_WEBSOCKETS("[readCb] tcp is null!\n");
if(cb) {
cb(client, false);
}
return false;
}
if(!client->tcp->connected()) {
DEBUG_WEBSOCKETS("[readCb] not connected!\n");
if(cb) {
cb(client, false);
}
return false;
}
if((millis() - t) > WEBSOCKETS_TCP_TIMEOUT) {
DEBUG_WEBSOCKETS("[readCb] receive TIMEOUT! %lu\n", (millis() - t));
if(cb) {
cb(client, false);
}
return false;
}
if(!client->tcp->available()) {
#if(WEBSOCKETS_NETWORK_TYPE == NETWORK_ESP8266)
delay(0);
#endif
continue;
}
len = client->tcp->read((uint8_t *)out, n);
if(len) {
//[MJG]
DEBUG_WEBSOCKETS("[MJG][WebSockets.read :%.*s\n",len,out);
t = millis();
out += len;
n -= len;
DEBUG_WEBSOCKETS("Receive %d left %d!\n", len, n); //[MJG]
} else {
//DEBUG_WEBSOCKETS("Receive %d left %d!\n", len, n);
}
#if(WEBSOCKETS_NETWORK_TYPE == NETWORK_ESP8266)
delay(0);
#endif
}
if(cb) {
cb(client, true);
}
#endif
return true;
}