From 030b7476164e58c355cb3a47d44b8cc3d82e0ec5 Mon Sep 17 00:00:00 2001 From: Maurice Makaay Date: Sun, 11 Apr 2021 19:09:21 +0200 Subject: [PATCH] Fix race condition causing 'ack timeout 4' disconnects (#4) The AsyncClient::send() methods sets a boolean to true after pushing data over the TCP socket successfully using tcp_output(). It also sets a timestamp to remember at what time the data was sent. The AsyncClient::_sent() callback method reacts to ACKs coming from the connected client. This method sets the boolean to false. In the AsyncClient::_poll() method, a check is done to see if the boolean is true ("I'm waiting for an ACK") and if the time at which the data was sent is too long ago (5000 ms). If this is the case, a connection issue with the connected client is assumed and the connection is forcibly closed by the server. The race condition is when these operations get mixed up, because of multithreading behavior. The _sent() method can be called during the execution of the send() method: 1. send() sends out data using tcp_output() 2. _sent() is called because an ACK is processed, sets boolean to false 3. send() continues and sets boolean to true + timestamp to "now" After this, the data exchange with the client was successful. Data were sent and the ACK was seen. However, the boolean ended up as true, making the _poll() method think that an ACK is still to be expected. As a result, 5000 ms later, the connection is dropped. This commit fixes the code by first registering that an ACK is expected, before calling tcp_output(). This way, there is no race condition when the ACK is processed right after that call. Additionally, I changed the boolean to an integer counter value. The server might send multiple messages to the client, resulting in multiple expected ACKs. A boolean does not cover this situation. Co-authored-by: Maurice Makaay --- src/AsyncTCP.cpp | 21 +++++++++++---------- src/AsyncTCP.h | 2 +- 2 files changed, 12 insertions(+), 11 deletions(-) diff --git a/src/AsyncTCP.cpp b/src/AsyncTCP.cpp index c305a70..471e8fc 100644 --- a/src/AsyncTCP.cpp +++ b/src/AsyncTCP.cpp @@ -575,7 +575,7 @@ AsyncClient::AsyncClient(tcp_pcb* pcb) , _pb_cb_arg(0) , _timeout_cb(0) , _timeout_cb_arg(0) -, _pcb_busy(false) +, _pcb_busy(0) , _pcb_sent_at(0) , _ack_pcb(true) , _rx_last_packet(0) @@ -783,13 +783,14 @@ size_t AsyncClient::add(const char* data, size_t size, uint8_t apiflags) { } bool AsyncClient::send(){ - int8_t err = ERR_OK; - err = _tcp_output(_pcb, _closed_slot); - if(err == ERR_OK){ - _pcb_busy = true; - _pcb_sent_at = millis(); + auto pcb_sent_at_backup = _pcb_sent_at; + _pcb_sent_at = millis(); + _pcb_busy++; + if (_tcp_output(_pcb, _closed_slot) == ERR_OK) { return true; } + _pcb_sent_at = pcb_sent_at_backup; + _pcb_busy--; return false; } @@ -869,7 +870,7 @@ int8_t AsyncClient::_connected(void* pcb, int8_t err){ _pcb = reinterpret_cast(pcb); if(_pcb){ _rx_last_packet = millis(); - _pcb_busy = false; + _pcb_busy = 0; // tcp_recv(_pcb, &_tcp_recv); // tcp_sent(_pcb, &_tcp_sent); // tcp_poll(_pcb, &_tcp_poll, 1); @@ -932,7 +933,7 @@ int8_t AsyncClient::_fin(tcp_pcb* pcb, int8_t err) { int8_t AsyncClient::_sent(tcp_pcb* pcb, uint16_t len) { _rx_last_packet = millis(); //log_i("%u", len); - _pcb_busy = false; + _pcb_busy--; if(_sent_cb) { _sent_cb(_sent_cb_arg, this, len, (millis() - _pcb_sent_at)); } @@ -977,8 +978,8 @@ int8_t AsyncClient::_poll(tcp_pcb* pcb){ uint32_t now = millis(); // ACK Timeout - if(_pcb_busy && _ack_timeout && (now - _pcb_sent_at) >= _ack_timeout){ - _pcb_busy = false; + if(_pcb_busy > 0 && _ack_timeout && (now - _pcb_sent_at) >= _ack_timeout){ + _pcb_busy = 0; log_w("ack timeout %d", pcb->state); if(_timeout_cb) _timeout_cb(_timeout_cb_arg, this, (now - _pcb_sent_at)); diff --git a/src/AsyncTCP.h b/src/AsyncTCP.h index ac87ded..fcd511b 100644 --- a/src/AsyncTCP.h +++ b/src/AsyncTCP.h @@ -160,7 +160,7 @@ class AsyncClient { AcConnectHandler _poll_cb; void* _poll_cb_arg; - bool _pcb_busy; + uint32_t _pcb_busy; uint32_t _pcb_sent_at; bool _ack_pcb; uint32_t _rx_ack_len;