async_tcp watchdog triggers when Websocket message queue is exhausted

[mathieucarbou]

Platform

ESP32

IDE / Tooling

Arduino (IDE/CLI)

What happened?

This can be reproduced with an example sending to the client a lot of websocket messages.

Open the browser, then just switch tab or reduce the window.
The UI is no more consuming the messages (and does not send back acks) but the server is still considering the client object alive and keeps enqueuing messages.
Since we are now not waiting anymore to have received previous message ack to send next message, we are stacking messages waiting for acks.

Stack Trace

E (322929) async_ws: _queueMessage() 491: Too many messages queued: discarding new message
E (322931) async_ws: _queueMessage() 491: Too many messages queued: discarding new message
E (322941) async_ws: _queueMessage() 491: Too many messages queued: discarding new message
E (322952) async_ws: _queueMessage() 491: Too many messages queued: discarding new message
E (322953) async_ws: _queueMessage() 491: Too many messages queued: discarding new message
E (322963) async_ws: _queueMessage() 491: Too many messages queued: discarding new message
Guru Meditation Error: Core  1 panic'ed (Unhandled debug exception). 
Debug exception reason: Stack canary watchpoint triggered (async_tcp) 
Core  1 register dump:
PC      : 0x402004ec  PS      : 0x00060936  A0      : 0x801f9668  A1      : 0x3ffe4580  
A2      : 0x3ffe5988  A3      : 0x3ffe48a0  A4      : 0x3ffe4590  A5      : 0x3ffe4a60  
A6      : 0x3ffe4a20  A7      : 0x0000000c  A8      : 0x3ffe48a0  A9      : 0x3ffe4570  
A10     : 0x00000001  A11     : 0x3f46c5f6  A12     : 0x000000ff  A13     : 0x0000ff00  
A14     : 0x00ff0000  A15     : 0xff000000  SAR     : 0x0000000a  EXCCAUSE: 0x00000001  
EXCVADDR: 0x00000000  LBEG    : 0x4008ac14  LEND    : 0x4008ac1f  LCOUNT  : 0xffffffff  


Backtrace: 0x402004e9:0x3ffe4580 0x401f9665:0x3ffe48a0 0x401f96a5:0x3ffe4930 0x4010bdda:0x3ffe4970 0x400fde65:0x3ffe49f0 0x400969e5:0x3ffe4a20 0x400df041:0x3ffe4a80 0x4012a499:0x3ffe4ae0 0x400f12c9:0x3ffe4b10 0x400f136b:0x3ffe4b30 0x4010be1a:0x3ffe4b50 0x400fdea1:0x3ffe4bd0 0x400969e5:0x3ffe4c00 0x400df041:0x3ffe4c60 0x4012a499:0x3ffe4cc0 0x400f12c9:0x3ffe4cf0 0x400f136b:0x3ffe4d10 0x4010be1a:0x3ffe4d30 0x400fdea1:0x3ffe4db0 0x400969e5:0x3ffe4de0 0x400df041:0x3ffe4e40 0x4012a499:0x3ffe4ea0 0x400f12c9:0x3ffe4ed0 0x400f136b:0x3ffe4ef0 0x4010be1a:0x3ffe4f10 0x400fdea1:0x3ffe4f90 0x400969e5:0x3ffe4fc0 0x400df041:0x3ffe5020 0x4012a499:0x3ffe5080 0x400f12c9:0x3ffe50b0 0x400f136b:0x3ffe50d0 0x4010be1a:0x3ffe50f0 0x400fdea1:0x3ffe5170 0x400969e5:0x3ffe51a0 0x400df041:0x3ffe5200 0x4012a499:0x3ffe5260 0x400f12c9:0x3ffe5290 0x400f136b:0x3ffe52b0 0x4010be1a:0x3ffe52d0 0x400fdea1:0x3ffe5350 0x400969e5:0x3ffe5380 0x400df041:0x3ffe53e0 0x4012a499:0x3ffe5440 0x400f12c9:0x3ffe5470 0x400f136b:0x3ffe5490 0x4010be1a:0x3ffe54b0 0x400fdea1:0x3ffe5530 0x400969e5:0x3ffe5560 0x400df041:0x3ffe55c0 0x4012a3cd:0x3ffe5620 0x400ee001:0x3ffe5650 0x400dbef2:0x3ffe5680 0x400dc329:0x3ffe56d0 0x400dc72d:0x3ffe5700 0x400d94a1:0x3ffe5740 0x4009130d:0x3ffe5790
  #0  0x402004e9 in _svfprintf_r at /builds/idf/crosstool-NG/.build/xtensa-esp-elf/src/newlib/newlib/libc/stdio/vfprintf.c:866
  #1  0x401f9665 in _vsnprintf_r at /builds/idf/crosstool-NG/.build/xtensa-esp-elf/src/newlib/newlib/libc/stdio/vsnprintf.c:70
  #2  0x401f96a5 in vsnprintf at /builds/idf/crosstool-NG/.build/xtensa-esp-elf/src/newlib/newlib/libc/stdio/vsnprintf.c:40 (discriminator 1)
  #3  0x4010bdda in Print::vprintf(char const*, __va_list_tag) at ??:?
  #4  0x400fde65 in _ZL20log_redirect_vprintfPKc13__va_list_tag$lto_priv$0 at ??:?
  #5  0x400969e5 in esp_log_va at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/log/src/log.c:43
      (inlined by) esp_log at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/log/src/log.c:88
  #6  0x400df041 in AsyncWebSocketClient::binary(std::shared_ptr<std::vector<unsigned char, std::allocator<unsigned char> > >) at ??:?
  #7  0x4012a499 in _ZN14AsyncWebSocket9binaryAllEP27AsyncWebSocketMessageBuffer$isra$0 at ??:?
  #8  0x400f12c9 in WebSerialProClass::_send(unsigned char const*, unsigned int) at :?
  #9  0x400f136b in WebSerialProClass::write(unsigned char const*, unsigned int) at :?
  #10 0x4010be1a in Print::vprintf(char const*, __va_list_tag) at ??:?
  #11 0x400fdea1 in _ZL20log_redirect_vprintfPKc13__va_list_tag$lto_priv$0 at ??:?
  #12 0x400969e5 in esp_log_va at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/log/src/log.c:43
      (inlined by) esp_log at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/log/src/log.c:88
  #13 0x400df041 in AsyncWebSocketClient::binary(std::shared_ptr<std::vector<unsigned char, std::allocator<unsigned char> > >) at ??:?
  #14 0x4012a499 in _ZN14AsyncWebSocket9binaryAllEP27AsyncWebSocketMessageBuffer$isra$0 at ??:?
  #15 0x400f12c9 in WebSerialProClass::_send(unsigned char const*, unsigned int) at :?
  #16 0x400f136b in WebSerialProClass::write(unsigned char const*, unsigned int) at :?
  #17 0x4010be1a in Print::vprintf(char const*, __va_list_tag) at ??:?
  #18 0x400fdea1 in _ZL20log_redirect_vprintfPKc13__va_list_tag$lto_priv$0 at ??:?
  #19 0x400969e5 in esp_log_va at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/log/src/log.c:43
      (inlined by) esp_log at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/log/src/log.c:88
  #20 0x400df041 in AsyncWebSocketClient::binary(std::shared_ptr<std::vector<unsigned char, std::allocator<unsigned char> > >) at ??:?
  #21 0x4012a499 in _ZN14AsyncWebSocket9binaryAllEP27AsyncWebSocketMessageBuffer$isra$0 at ??:?
  #22 0x400f12c9 in WebSerialProClass::_send(unsigned char const*, unsigned int) at :?
  #23 0x400f136b in WebSerialProClass::write(unsigned char const*, unsigned int) at :?
  #24 0x4010be1a in Print::vprintf(char const*, __va_list_tag) at ??:?
  #25 0x400fdea1 in _ZL20log_redirect_vprintfPKc13__va_list_tag$lto_priv$0 at ??:?
  #26 0x400969e5 in esp_log_va at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/log/src/log.c:43
      (inlined by) esp_log at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/log/src/log.c:88
  #27 0x400df041 in AsyncWebSocketClient::binary(std::shared_ptr<std::vector<unsigned char, std::allocator<unsigned char> > >) at ??:?
  #28 0x4012a499 in _ZN14AsyncWebSocket9binaryAllEP27AsyncWebSocketMessageBuffer$isra$0 at ??:?
  #29 0x400f12c9 in WebSerialProClass::_send(unsigned char const*, unsigned int) at :?
  #30 0x400f136b in WebSerialProClass::write(unsigned char const*, unsigned int) at :?
  #31 0x4010be1a in Print::vprintf(char const*, __va_list_tag) at ??:?
  #32 0x400fdea1 in _ZL20log_redirect_vprintfPKc13__va_list_tag$lto_priv$0 at ??:?
  #33 0x400969e5 in esp_log_va at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/log/src/log.c:43
      (inlined by) esp_log at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/log/src/log.c:88
  #34 0x400df041 in AsyncWebSocketClient::binary(std::shared_ptr<std::vector<unsigned char, std::allocator<unsigned char> > >) at ??:?
  #35 0x4012a499 in _ZN14AsyncWebSocket9binaryAllEP27AsyncWebSocketMessageBuffer$isra$0 at ??:?
  #36 0x3ffe5260 in _stack_sentry_app in ROM
  #37 0x400f12c9 in WebSerialProClass::_send(unsigned char const*, unsigned int) at :?
  #38 0x3ffe5290 in _stack_sentry_app in ROM
  #39 0x400f136b in WebSerialProClass::write(unsigned char const*, unsigned int) at :?
  #40 0x3ffe52b0 in _stack_sentry_app in ROM
  #41 0x4010be1a in Print::vprintf(char const*, __va_list_tag) at ??:?
  #42 0x3ffe52d0 in _stack_sentry_app in ROM
  #43 0x400fdea1 in _ZL20log_redirect_vprintfPKc13__va_list_tag$lto_priv$0 at ??:?
  #44 0x3ffe5350 in _stack_sentry_app in ROM
  #45 0x400969e5 in esp_log_va at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/log/src/log.c:43
      (inlined by) esp_log at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/log/src/log.c:88
  #46 0x3ffe5380 in _stack_sentry_app in ROM
  #47 0x400df041 in AsyncWebSocketClient::binary(std::shared_ptr<std::vector<unsigned char, std::allocator<unsigned char> > >) at ??:?
  #48 0x3ffe53e0 in _stack_sentry_app in ROM
  #49 0x4012a499 in _ZN14AsyncWebSocket9binaryAllEP27AsyncWebSocketMessageBuffer$isra$0 at ??:?
  #50 0x3ffe5440 in _stack_sentry_app in ROM
  #51 0x400f12c9 in WebSerialProClass::_send(unsigned char const*, unsigned int) at :?
  #52 0x3ffe5470 in _stack_sentry_app in ROM
  #53 0x400f136b in WebSerialProClass::write(unsigned char const*, unsigned int) at :?
  #54 0x3ffe5490 in _stack_sentry_app in ROM
  #55 0x4010be1a in Print::vprintf(char const*, __va_list_tag) at ??:?
  #56 0x3ffe54b0 in _stack_sentry_app in ROM
  #57 0x400fdea1 in _ZL20log_redirect_vprintfPKc13__va_list_tag$lto_priv$0 at ??:?
  #58 0x3ffe5530 in _stack_sentry_app in ROM
  #59 0x400969e5 in esp_log_va at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/log/src/log.c:43
      (inlined by) esp_log at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/log/src/log.c:88
  #60 0x3ffe5560 in _stack_sentry_app in ROM
  #61 0x400df041 in AsyncWebSocketClient::binary(std::shared_ptr<std::vector<unsigned char, std::allocator<unsigned char> > >) at ??:?
  #62 0x3ffe55c0 in _stack_sentry_app in ROM
  #63 0x4012a3cd in _ZN20AsyncWebSocketClient6binaryEPKhj$isra$0 at ??:?
  #64 0x3ffe5620 in _stack_sentry_app in ROM
  #65 0x400ee001 in _ZNSt17_Function_handlerIFvP14AsyncWebSocketP20AsyncWebSocketClient12AwsEventTypePvPhjEZN17WebSerialProClass5beginEP14AsyncWebServerPKcEUlS1_S3_S4_S5_S6_jE_E9_M_invokeERKSt9_Any_dataOS1_OS3_OS4_OS5_OS6_Oj$lto_priv$0 at ??:?
  #66 0x3ffe5650 in _stack_sentry_app in ROM
  #67 0x400dbef2 in AsyncWebSocket::_handleEvent(AsyncWebSocketClient*, AwsEventType, void*, unsigned char*, unsigned int) at :?
  #68 0x3ffe5680 in _stack_sentry_app in ROM
  #69 0x400dc329 in AsyncWebSocketClient::_handleDataEvent(unsigned char*, unsigned int, bool) at :?
  #70 0x3ffe56d0 in _stack_sentry_app in ROM
  #71 0x400dc72d in std::_Function_handler<void (void*, AsyncClient*, void*, unsigned int), AsyncWebSocketClient::AsyncWebSocketClient(AsyncClient*, AsyncWebSocket*)::{lambda(void*, AsyncClient*, void*, unsigned int)#1}>::_M_invoke(std::_Any_data const&, void*&&, AsyncClient*&&, void*&&, unsigned int&&) at :?
  #72 0x3ffe5700 in _stack_sentry_app in ROM
  #73 0x400d94a1 in std::function<void (void*, AsyncClient*, void*, unsigned int)>::operator()(void*, AsyncClient*, void*, unsigned int) const at /Users/mat/.platformio/packages/toolchain-xtensa-esp-elf/xtensa-esp-elf/include/c++/14.2.0/bits/std_function.h:591
      (inlined by) AsyncClient::_recv(tcp_pcb*, pbuf*, signed char) at .pio/libdeps/pro-esp32/AsyncTCP/src/AsyncTCP.cpp:1068
      (inlined by) AsyncTCP_detail::handle_async_event(lwip_tcp_event_packet_t*) at .pio/libdeps/pro-esp32/AsyncTCP/src/AsyncTCP.cpp:293
      (inlined by) _async_service_task at .pio/libdeps/pro-esp32/AsyncTCP/src/AsyncTCP.cpp:328
  #74 0x3ffe5740 in _stack_sentry_app in ROM

Minimal Reproductible Example (MRE)

Websocket example pushing messages to clients

I confirm that:

• I have read the documentation.
• I have searched for similar discussions.
• I have searched for similar issues.
• I have looked at the examples.
• I have upgraded to the lasted version of ESPAsyncWebServer (and AsyncTCP for ESP32).

[mathieucarbou]

I am closing the issue since this might not be a problem with the library.

There were 2 causes for this issue:

=> 1. setCloseClientOnQueueFull(bool) badly set in WebSerial:

WebSerial was using client->setCloseClientOnQueueFull(false);

So when the message queue is filled, the client connection is not closed.
This could happen on any issue (slow, timeout, etc or even while waiting for acks we will never receive.)

This flag was introduced because false was the default behavior in the original repo and true the default behavior in yubox-node-org/ESPAsyncWebServer fork.

So it should be set to true (default) in order to let espasync_ws free resources when it detects it has to.

=> 2. Logging from async_tcp task

I was forwarding the ESP_LOGs to the Serial, an optionally a another stream, and also WebSerial (which is a web console based on espsync_ws and websocket).

static int log_redirect_vprintf(const char* format, va_list args) {
  size_t written = Serial.vprintf(format, args);
  if (logStream != nullptr)
    logStream->vprintf(format, args);
  if (WebSerial.getConnectionCount())
    WebSerial.vprintf(format, args);
  return written;
}
///[...]
esp_log_set_vprintf(log_redirect_vprintf);

What was happening is that if the browser sends a WS Message, and in the reception callback (so while the asyn_tcp stask is in the onData callback) I do a ESP-LOG, WebSerial will then create a new WS message and add it to the message queue and try to send it (while we are in the onData callback of async_tcp). The log is really small. But queue is filled faster.

So i avoid reentrant calls:

static bool alreadyLogging = false;
static int log_redirect_vprintf(const char* format, va_list args) {
  if (alreadyLogging) {
    // prevent re-entry in WebSerial when we have some logs in esp_async_ws like WS message queue overflow
    Serial.println("WARNING: Re-entry prevented in log_redirect_vprintf");
    return Serial.vprintf(format, args);
  } else {
    alreadyLogging = true;
    size_t written = Serial.vprintf(format, args);
    if (logStream != nullptr) logStream->vprintf(format, args);
    if (WebSerial.getConnectionCount()) WebSerial.vprintf(format, args);
    alreadyLogging = false;
    return written;
  }
}

If WebSerial was not there, all would be OK. WebSerial has 2 ways of working:

• with an intermediary large buffer / queue sent from loop task (which I do not use to reduce heap size)
• and without, directly crafting and sending a WS messages as soon as it sees \n, which is more suitable for faster log streaming.

[mathieucarbou]

For the story, thanks to the added logs, I was able to pinpoint exactly the loop I got.

our lock is recursive: std::unique_lock<std::recursive_mutex> lock(_lock);

So WebSerial is sending a message => call to send() => call to _queueMessage().
Here, we have a check: if (closeWhenFull) { close client then log } else { log "too many messages queued" }
Remember: WebSerial was setting closeWhenFull to false... And I redirect all the logs to WebSerial...

So that's where the recursive loop comes from.

That solved the crash... But not the reason why WebSerial filled up the message queue quickly!!

So it turns out that if you happen to have a website using websocket with Chrome, and this tab is not selected, plus chrome runs in the background, our acks come back really slowly. So with short messages sent fast, the queue tends to grow faster than we receive the acks from Chrome.

What is bad is that Chrome on the background tab does not close the websocket connection and re-opens it later. Instead it keeps it opened, but slows it down.

[mathieucarbou]

With WebSerial, to avoid logging from the async_tcp task, you can do something like:

static bool alreadyLogging = false;
static int log_redirect_vprintf(const char* format, va_list args) {
  if (alreadyLogging) {
    // prevent re-entry in WebSerial when we have some logs in esp_async_ws like WS message queue overflow
    // Serial.println("WARNING: Re-entry prevented in log_redirect_vprintf");
    return Serial.vprintf(format, args);
  } else {
    alreadyLogging = true;
    size_t written = Serial.vprintf(format, args);
    if (logStream != nullptr && !logStream->isFull()) {
      logStream->vprintf(format, args);
    }
    if (WebSerial.getConnectionCount()) {
      if (strcmp(pcTaskGetTaskName(xTaskGetCurrentTaskHandle()), "async_tcp") != 0) {
        WebSerial.vprintf(format, args);
      }
    }
    alreadyLogging = false;
    return written;
  }
}