Possible race condition causing random disconnects

[mmakaay]

The issue

I am currently working on an ESPHome firmware for a single-core ESP32 MCU. The ESPHome code sets up a server using AsyncTCP. The clients send a ping message every few seconds. Very regularly, the server-side console logs "ack timeout 4" after sending a ping response, disconnecting the connected client. I suspect that this is because of a race condition in AsyncTCP.

Network issue?

The network quality is not the issue here. After disconnecting I always see the Home Assistant client reconnect successfully right away, the network tcp dumps look okay and I can ping the ESP32 continuously. I find various threads on the internet suggesting to disable power management, using a fixed IP address and using wifi fast connect. Those suggestions did not improve my issue.

Log showing the behavior

To debug the issue, I added some extra log messages to AsyncTCP.cpp and here's a log flow that shows the behavior that I see before a disconnect. I added my comments in capitals:

1) A PING REQUEST IS RECEIVED
[17:20:40][VV][api.service:220]: on_ping_request: PingRequest {}

2) THE ESP32 SENDS A PING RESPONSE
[17:20:40][VV][api.service:032]: send_ping_response: PingResponse {}

3) THE METHOD AsyncClient::send() IS CALLED TO SEND THE RESPONSE
[17:20:40]send() send enqueued data with tcp_output(), busy = 0, now = 2119326: 0x3ffd3440

4) THE ACK FOR THE SENT RESPONSE IS RECEIVED AND PROCESSED
BY THE AsyncClient::_sent() CALLBACK (_pcb_busy is set to false)
[17:20:40]-S: 0x3ffd3440
[17:20:40]_sent() sets busy = false, now = 2119336: 0x3ffd3440
[17:20:40]_sent() end of function, busy = 0: 0x3ffd3440

5) WE'RE BACK IN THE AsyncClient::send() METHOD, WHICH NOW SETS _pcb_busy to true
[17:20:40]send() OK sets busy = 1, _pcb_sent_at=2119343, now = 2119343: 0x3ffd3440

6) THE POLLING LOOP IS STARTED, WITH THE INCORRECT _pcb_busy == true STATE
[17:20:40]-P: 0x3ffd3440
[17:20:40][W][AsyncTCP.cpp:965] _poll(): _pcb_busy=1, now=2119394, _pcb_sent_at=2119343, _rx_last_packet=2119336: 0x3ffd3440
[17:20:40]-P: 0x3ffd3440
[17:20:40][W][AsyncTCP.cpp:965] _poll(): _pcb_busy=1, now=2119894, _pcb_sent_at=2119343, _rx_last_packet=2119336: 0x3ffd3440
--------------------8<---------------------------- snipped the polling loglines at this point
[17:20:45]-P: 0x3ffd3440
[17:20:45][W][AsyncTCP.cpp:965] _poll(): _pcb_busy=1, now=2124394, _pcb_sent_at=2119343, _rx_last_packet=2119336: 0x3ffd3440

7) THE POLL LOOP THINKS THAT WE HAVE A TIMEOUT WAITING FOR THE ACK
[17:20:45]_poll() sets busy = false after ack timeout: 0x3ffd3440
[17:20:45][W][AsyncTCP.cpp:971] _poll(): ack timeout 4

8) AND DISCONNECTS THE CONNECTED CLIENT
[17:20:45][V][api.connection:696]: Error: Disconnecting Home Assistant 2021.3.2 (192.168.100.135)
[17:20:45][D][api:067]: Disconnecting Home Assistant 2021.3.2 (192.168.100.135)

9) A NEW CLIENT CONNECTION COMES IN AND IS ACCEPTED RIGHT AWAY
[17:20:45]A: 0x3ffb8b68 0x3ffd3690
[17:20:45]-R: 0x3ffd3d3c
[17:20:45][VV][api.service:192]: on_hello_request: HelloRequest {
[17:20:45]  client_info: 'Home Assistant 2021.3.2'

Looking at this flow, I would say that the flow of the AsyncClient::send() method (3) is interrupted by the lwIP thread that handles the incoming ACK does interrupt (4). This causes the _pcb_busy field to be set to false before AsyncClient::send() sets is to true (5).

Another example

Here's a snippet of log output that even better shows the interruption of the AsyncClient::send() flow. It's an image, so I could color the loglines for clarity.

What you see is the red text, which gets interrupted mid sentence by the green text, after which the red text continues where it left off. During the green log lines, the _pcb_busy is set to false and only afterwards the _pcb_busy is set to true in the following red log lines.

Possible solution

Maybe the fix could be as simple as moving setting of _pcb_sent_at and _pcb_busy above the _tcp_output() call, and resetting _pcb_busy in case _tcp_output() fails:

bool AsyncClient::send(){
    int8_t err = ERR_OK;
    _pcb_sent_at = millis();
    _pcb_busy = true;
    err = _tcp_output(_pcb, _closed_slot);
    if(err == ERR_OK){
        return true;
    }
    _pcb_busy = false;
    return false;
}

I will impement this in my local copy, to see if things improve.

[mmakaay]

My first tests look quite good. My device has been running solid for a few hours now.

I modified the code to make _pcb_busy an integer counter instead of a boolean, because sometimes there are multiple data sending operations active. This makes _pcb_busy more of a stack counter than a simple yes/no. On send, the counter is incremented, on ACK the counter is decremented.

I just captured a case where multiple sends were mingling within the same timeframe:

SEND 1 START, _pcb_busy goes to 1
[00:04:42]send() send enqueued data with tcp_output(), busy = 1, now = 6751: 0x3ffd3b84

SEND 1 END
[00:04:42]send() tcp_output() OK, busy = 1, now = 6754: 0x3ffd3b84

ACK 1, _pcb_busy goes to 0
[00:04:42]_sent() sets busy = 0, now = 6761: 0x3ffd3b84

SEND 2 START, _pcb_busy goes to 1
[00:04:42]send() send enqueued data with tcp_output(), busy = 1, now = 6764: 0x3ffd3b84

SEND 2 END
[00:04:42]send() tcp_output() OK, busy = 1, now = 6771: 0x3ffd3b84

SEND 3 START, _pcb_busy goes to 2
[00:04:42]send() send enqueued data with tcp_output(), busy = 2, now = 6776: 0x3ffd3b84

ACK 2, _pcb_busy goes to 1
[00:04:42]_sent() sets busy = 1, now = 6779: 0x3ffd3b84

ACK 3, _pcb_busy goes to 0
[00:04:42]_sent() sets busy = 0, now = 6782: 0x3ffd3b84

SEND 3 END
[00:04:42]send() tcp_output() OK, busy = 0, now = 6791: 0x3ffd3b84

In this flow after SEND 3 START (the start of the send() function), there are two send operations that are waiting for the ACKs.
These ACKs arrive and are processed by the lwIP thread before SEND 3 END (the end of the send() function) is reached.

Note:
This change was mainly implemented to get some better insights in the processing flows.
It does not mean that there is a hard requirements for using a stack counter instead of a boolean. The boolean might be enough for the use case that we're looking at here: to disconnect a client when no ACK is received after sending data to that client.

[mmakaay]

I implemented the stack counter idea in a fork of the AsyncTCP-esphome lib as used for ESPHome.
I had to use that fork of this project, to make it work with ESPHome.
However, the required code changes are equal:

https://github.com/mmakaay/AsyncTCP/commit/e8ac46b7f2292c1e71b005bef1115246f95fc6b7

This commit fixes the erratic diconnect behavior for me.

Update after some more teseting

The device has been running perfectly for more than 18 hours straight. My graphs show only one service interruption, and that was because I unplugged the device. For the rest of the time, the device has been connected continously.

[mmakaay]

Some more work on this was done in the ESPHome fork of this code.
OttoWinter#5

[mmakaay]

Closing the issue here, because the issue was solved in the ESPHome fork of this code instead.
For those insterested: https://github.com/esphome/AsyncTCP