search

Links2004 / arduinoWebSockets

arduinoWebSockets
GNU Lesser General Public License v2.1
1.88k stars 556 forks source link

ESP8266 NodeMCU WebSocket server: "[write] write TIMEOUT!" error after a certain amount of time #596

Open distlibs opened 3 years ago

distlibs commented 3 years ago

I created WebSocket server that sends data to WebSocket client at 1 second interval. Server is running on ESP8266 NodeMCU, client implemented using JavaScript.

WebSocket server:

#include <ESP8266WiFi.h>
#include <WebSocketsServer.h>

const char *ssid = "ssid";
const char *password = "pass";
const int interval = 1000;
unsigned long prev = 0;;
WebSocketsServer ws = WebSocketsServer(81);

void onEvent(uint8_t num, WStype_t type, uint8_t * payload, size_t length) {
    switch (type) {
        case WStype_CONNECTED:
            Serial.println("Connected");
            break;
        case WStype_DISCONNECTED:
            Serial.println("Disconnected");
            break;
    }
}

void setup() {
    Serial.begin(9600);
    WiFi.begin(ssid, password);
    while (WiFi.status() != WL_CONNECTED) {
        delay(500);
    }
    Serial.println(WiFi.localIP());
    ws.begin();
    ws.onEvent(onEvent);
}

void loop() {
    ws.loop();
    unsigned long current = millis();
    if (current - prev >= interval) {
        prev = current;
        Serial.println(ESP.getFreeHeap());
        String msg = String(random(1, 101));
        ws.broadcastTXT(msg);
    }
}

WebSocket client:

<!DOCTYPE html>
<html>
<head>
<title>Client</title>
<script>
    var webSocket = new WebSocket('ws://192.168.0.123:81');
    webSocket.onopen = function() { console.log('Connection opened'); };
    webSocket.onclose = function() { console.log('Connection closed'); };
    webSocket.onmessage = function(event) { console.log(event.data); };
</script>
</head>
<body>
</body>
</html>

After a certain amount of time I get error "[write] write TIMEOUT!". Debug log:

..............

43248
[WS][0][sendFrame] ------- send message frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 0 length: 2 headerToPayload: 0
[WS][0][sendFrame] text: 56
[WS][0][sendFrame] pack to one TCP package...
[write] n: 4 t: 94556
[WS][0][sendFrame] sending Frame Done (23973us).
42552
[WS][0][sendFrame] ------- send message frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 0 length: 2 headerToPayload: 0
[WS][0][sendFrame] text: 74
[WS][0][sendFrame] pack to one TCP package...
[write] n: 4 t: 95556
[WS][0][sendFrame] sending Frame Done (23972us).
41856
[WS][0][sendFrame] ------- send message frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 0 length: 2 headerToPayload: 0
[WS][0][sendFrame] text: 42
[WS][0][sendFrame] pack to one TCP package...
[write] n: 4 t: 96556
[WS][0][sendFrame] sending Frame Done (23989us).
41160
[WS][0][sendFrame] ------- send message frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 0 length: 1 headerToPayload: 0
[WS][0][sendFrame] text: 8
[WS][0][sendFrame] pack to one TCP package...
[write] n: 3 t: 97555
[WS][0][sendFrame] sending Frame Done (24587us).
40464
[WS][0][sendFrame] ------- send message frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 0 length: 2 headerToPayload: 0
[WS][0][sendFrame] text: 60
[WS][0][sendFrame] pack to one TCP package...
[write] n: 4 t: 98556
WS write 0 failed left 4!
[write] write TIMEOUT! 5236
[WS][0][sendFrame] sending Frame Done (5264960us).
40464
[WS][0][sendFrame] ------- send message frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 0 length: 2 headerToPayload: 0
[WS][0][sendFrame] text: 19
[WS][0][sendFrame] pack to one TCP package...
[write] n: 4 t: 104092
WS write 0 failed left 4!
[write] write TIMEOUT! 5350
[WS][0][sendFrame] sending Frame Done (5378420us).
40464
[WS][0][sendFrame] ------- send message frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 0 length: 2 headerToPayload: 0
[WS][0][sendFrame] text: 69
[WS][0][sendFrame] pack to one TCP package...
[write] n: 4 t: 109742
WS write 0 failed left 4!
[write] write TIMEOUT! 5250
[WS][0][sendFrame] sending Frame Done (5279029us).

..............

Client is always connected. I also tested using WebSocket client implemented using Python. I got same problem. Something wrong with WebSocket server.

Links2004 commented 3 years ago

Hi, is this a direct connection or are there any firewalls NAT or proxy's in between? looks like a Network or network stack problem, the websocket code that is running is always the same ;)

you can try to use enableHeartbeat

ws.enableHeartbeat(15000, 3000, 2);

https://github.com/Links2004/arduinoWebSockets/blob/08caf3bfc6625ebf6da9bb39f39d58dd113ceff4/src/WebSocketsServer.h#L90

this helps in most of the cases where you run in a network related timeout. since it looks like your client never sends anything.

distlibs commented 3 years ago

It is direct connection. I added enableHeartbeat:

void setup() {
    Serial.begin(9600);
    WiFi.begin(ssid, password);
    while (WiFi.status() != WL_CONNECTED) {
        delay(500);
    }
    Serial.println(WiFi.localIP());
    ws.enableHeartbeat(15000, 3000, 2);
    ws.begin();
    ws.onEvent(onEvent);
}

Problem still exist. Debug log:

..............
45984
[WS][0][sendFrame] ------- send message frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 0 length: 2 headerToPayload: 0
[WS][0][sendFrame] text: 28
[WS][0][sendFrame] pack to one TCP package...
[write] n: 4 t: 147853
[WS][0][sendFrame] sending Frame Done (25176us).
45288
[WS][0][sendFrame] ------- send message frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 0 length: 2 headerToPayload: 0
[WS][0][sendFrame] text: 17
[WS][0][sendFrame] pack to one TCP package...
[write] n: 4 t: 148853
[WS][0][sendFrame] sending Frame Done (25059us).
44592
[WS][0][sendFrame] ------- send message frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 0 length: 2 headerToPayload: 0
[WS][0][sendFrame] text: 35
[WS][0][sendFrame] pack to one TCP package...
[write] n: 4 t: 149853
[WS][0][sendFrame] sending Frame Done (25704us).
[WS-Server][0] sending HB ping
[WS][0][sendFrame] ------- send message frame -------
[WS][0][sendFrame] fin: 1 opCode: 9 mask: 0 length: 0 headerToPayload: 0
[write] n: 2 t: 150124
[WS][0][sendFrame] sending Frame Done (25182us).
43200
[WS][0][sendFrame] ------- send message frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 0 length: 2 headerToPayload: 0
[WS][0][sendFrame] text: 91
[WS][0][sendFrame] pack to one TCP package...
[write] n: 4 t: 150853
[WS][0][sendFrame] sending Frame Done (25019us).
42504
[WS][0][sendFrame] ------- send message frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 0 length: 2 headerToPayload: 0
[WS][0][sendFrame] text: 95
[WS][0][sendFrame] pack to one TCP package...
[write] n: 4 t: 151853
[WS][0][sendFrame] sending Frame Done (25121us).
41808
[WS][0][sendFrame] ------- send message frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 0 length: 1 headerToPayload: 0
[WS][0][sendFrame] text: 3
[WS][0][sendFrame] pack to one TCP package...
[write] n: 3 t: 152852
[WS][0][sendFrame] sending Frame Done (25148us).
[HBtimeout] pong TIMEOUT! lp=137701 millis=153201 pi=3001 count=1
[WS-Server][0] sending HB ping
[WS][0][sendFrame] ------- send message frame -------
[WS][0][sendFrame] fin: 1 opCode: 9 mask: 0 length: 0 headerToPayload: 0
[write] n: 2 t: 153435
[WS][0][sendFrame] sending Frame Done (25050us).
40416
[WS][0][sendFrame] ------- send message frame -------
[WS][0][sendFrame] fin: 1 opCode: 1 mask: 0 length: 2 headerToPayload: 0
[WS][0][sendFrame] text: 29
[WS][0][sendFrame] pack to one TCP package...
[write] n: 4 t: 153853
WS write 0 failed left 4!
[write] write TIMEOUT! 5507
[WS][0][sendFrame] sending Frame Done (5536102us).
[HBtimeout] pong TIMEOUT! lp=143943 millis=159443 pi=5931 count=2
[HBtimeout] count=2, DISCONNECTING
[WS-Server][0] client disconnected.
Disconnected
40360
40360
40360
40360
40360
..............

I saw that WebSocket server now sends HB ping but TIMEOUT occurred.

Links2004 commented 3 years ago

ok that is strange and a hint more that there is something on the lower network levels going on. are you using the ESP in AP, STA or AP + STA mode?

may this debug code can give us some hints:

void WiFiEvent(WiFiEvent_t event) {
    Serial.printf("[WiFi-event] event: %d\n", event);
}

void setup() {
....
    WiFi.onEvent(WiFiEvent);
....
}
distlibs commented 3 years ago

Hi. WiFi events was presented only at beginning:

SDK:2.2.2-dev(38a443e)/Core:2.6.3=20603000/lwIP:STABLE-2_1_2_RELEASE/glue:1.2-16-ge23a07e/BearSSL:89454af
scandone
[WiFi-event] event: 2
scandone
state: 0 -> 2 (b0)
state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 1
cnt 

connected with XXX_SSID, channel 1
dhcp client start...
[WiFi-event] event: 0
ip:192.168.0.123,mask:255.255.255.0,gw:192.168.0.1
[WiFi-event] event: 3
192.168.0.123
1
[WS-Server] Server Started.

Serial.println(WiFi.getMode()); returns 1. It means WIFI_STA.

Links2004 commented 3 years ago

ok, currently the best way to debug this I see is to look at the TCP packets on WiFi via for example Wireshark. The big questions is does the ESP get a ACK for the write or not.

If its getting one then the TCP stack in the ESP has a bug. If its not then your Network setup is buggy.

other possible tests:

have you tried to use a other AP / Network? may open a AP with a notebook or for example a raspberry PI. change the channel of your WiFi Network. setup the ESP in AP only mode and connect your client directly.