Warning: Rollback #18 (assert failed: tcp_update_rcv_ann_wnd)

[mathieucarbou]

FYI @AloisKlingler and @tbnobody : mathieucarbou/AsyncTCP#24

Ref: #2180

If you happen to see the issue again with the new upcoming releases, please let me know.

[tbnobody]

@mathieucarbou

you mean something like this?

18:00:30.967 > Network connected
18:00:35.014 > 
18:00:35.015 > assert failed: tcp_update_rcv_ann_wnd IDF/components/lwip/lwip/src/core/tcp.c:951 (new_rcv_ann_wnd <= 0xffff)
18:00:35.025 >
18:00:35.025 >
18:00:35.025 > Backtrace: 0x40026f96:0x3ffdc6f0 0x4002d371:0x3ffdc710 0x4003333d:0x3ffdc730 0x400e350e:0x3ffdc860 0x400e35a2:0x3ffdc880 0x4014ba26:0x3ffdc8a0 0x400e01b5:0x3ffdc8c0
18:00:35.347 >   #0  0x40026f96 in panic_abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp_system/panic.c:408
18:00:35.347 >   #1  0x4002d371 in esp_system_abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp_system/esp_system.c:137
18:00:35.347 >   #2  0x4003333d in __assert_func at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/newlib/assert.c:85
18:00:35.347 >   #3  0x400e350e in tcp_update_rcv_ann_wnd at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/core/tcp.c:951
18:00:35.347 >       (inlined by) tcp_update_rcv_ann_wnd at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/core/tcp.c:931
18:00:35.347 >   #4  0x400e35a2 in tcp_recved at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/core/tcp.c:991
18:00:35.347 >   #5  0x4014ba26 in _tcp_recved_api(tcpip_api_call_data*) at .pio/libdeps/lolin_s2_mini/AsyncTCP/src/AsyncTCP.cpp:452
18:00:35.347 >   #6  0x400e01b5 in tcpip_thread_handle_msg at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/api/tcpip.c:172
18:00:35.347 >       (inlined by) tcpip_thread at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/api/tcpip.c:154

I am using mathieucarbou/ESPAsyncWebServer @ 3.3.12

[mathieucarbou]

Thanks!
I will issue a release with this patch: if(msg->closed_slot != INVALID_CLOSED_SLOT) { now.

[tbnobody]

Thank you! I will include it as soon as it is available, test it at my local environment and also release a new version.

[mathieucarbou]

Released!

• mathieucarbou/AsyncTCP @ 3.2.9
• mathieucarbou/ESPAsyncWebServer @ 3.3.13

Could you please run those tests again with the releases and let me know ?

Thanks a lot for helping troubleshoot this issue... This is a really hard one...

[tbnobody]

And already updated in my local dev branch. I've also updated 3 of my test DTUs and didn't see the excpetion anywhere. Lets hope it stays like that :)

[mathieucarbou]

I really hope too! Thanks again for the tests 👍

[DaeMonSxy]

happened again:
used only:

mathieucarbou/AsyncTCP @ 3.2.9
mathieucarbou/ESPAsyncWebServer @ 3.3.13

199100|2024-10-13_08:20:164 [http] [9] #> 192.168.11.100:88/json.htm?type=command&param=udevice&idx=68&nvalue=0&svalue=18.30
198284|2024-10-13_08:20:164 [http] [9] #< {"status":"OK","title":"UpdateDevice"}

assert failed: tcp_update_rcv_ann_wnd IDF/components/lwip/lwip/src/core/tcp.c:951 (new_rcv_ann_wnd <= 0xffff)


Backtrace: 0x40083d65:0x3ffb2e80 0x4008ca11:0x3ffb2ea0 0x40092039:0x3ffb2ec0 0x401258d2:0x3ffb2ff0 0x40125980:0x3ffb3010 0x400f4be8:0x3ffb3030 0x40122758:0x3ffb3050
  #0  0x40083d65 in panic_abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp_system/panic.c:408
  #1  0x4008ca11 in esp_system_abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp_system/esp_system.c:137
  #2  0x40092039 in __assert_func at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/newlib/assert.c:85
  #3  0x401258d2 in tcp_update_rcv_ann_wnd at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/core/tcp.c:951
      (inlined by) tcp_update_rcv_ann_wnd at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/core/tcp.c:931
  #4  0x40125980 in tcp_recved at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/core/tcp.c:991
  #5  0x400f4be8 in _tcp_recved_api(tcpip_api_call_data*) at /Users/daemons/platformio_libdeps/ESP32/AsyncTCP/src/AsyncTCP.cpp:462
  #6  0x40122758 in tcpip_thread_handle_msg at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/api/tcpip.c:172
      (inlined by) tcpip_thread at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/api/tcpip.c:154



ELF file SHA256: 176fc0a647b6bafd

let me share the async req code also, maybe i am overlooking some issues here:

unsigned long sendRequest(const Request &req)
{
    AsyncClient *client = new AsyncClient();
    if (!client) return 0;

    char request[512];
    snprintf(request, sizeof(request),
             "GET %s HTTP/1.1\r\n"
             "Host: %s:%d\r\n"
             "Authorization: Basic %s\r\n"
             "User-Agent: iqESP\r\n"
             "Connection: close\r\n\r\n",
             req.query, req.host, req.port, req.auth);

    unsigned long requestID = req.id;

    client->onError([requestID](void *arg, AsyncClient *client, int error) {
        LOG_I("[%lu] ## onError\n", requestID);
        delete client;
        requestOngoing = false;
    },
                    nullptr);

    client->onConnect([client, request, requestID, req](void *arg, AsyncClient *client) {
        LOG_I("[%lu] #> %s:%i%s", requestID, req.host, req.port, req.query);

        client->onDisconnect([requestID, client](void *arg, AsyncClient *client) {
            LOG_I("[%d] onDisconnect", requestID);
            delete client;
            requestOngoing = false;
        },
                             nullptr);

        client->onData([requestID](void *arg, AsyncClient *client, void *data, size_t len) {
            //LOG_I("[%d] onData", requestID);
            handleData(client, requestID, data, len);
            client->close();
        },
                       nullptr);

        client->write(request);
        lastRequestTime = millis();
    },
                      nullptr);

    if (!client->connect(req.host, req.port)) {
        //LOG_I("[%d] connect", requestID);
        delete client;
        return 0;
    }

    return requestID;
}

[mathieucarbou]

I have updated the example at https://github.com/mathieucarbou/AsyncTCP/blob/main/examples/Client/Client.ino.

I am now maintaining a max of CONFIG_LWIP_MAX_ACTIVE_TCP concurrent clients, recreating them as soon as one closes.

I have also rolled back to my original fix lone 457:

if(msg->closed_slot != INVALID_CLOSED_SLOT && !_closed_slots[msg->closed_slot]) {

Would you be able to ry on your end with the example ?

[mathieucarbou]

I am testing against a local jekyll server :

#define HOST "192.168.125.118"
#define PORT 4000

Since a few minutes, no crash., but this is slow. Opening 16 clients at the same time makes reading data slower.
If I set MAX_CLIENTS to 3,

[mathieucarbou]

I suspect that AsyncTCP is not good at handling concurrent connexions a lot and would be better handle one connection at a time to be more efficient, backed by a queue.

[DaeMonSxy]

yes, did not mention previously, iam handling that inside function:

waiting req to be finished, then immediatelly start new reqest. However ,this is only for arg-requests - not taken into account for webserver or websocket at all.

void loop_arg()
{
    if (millis() - lastRequestTime > 1000)
        if (!requestOngoing && !requestQueue.empty()) {
            processQueue();
        }

    if (requestOngoing && millis() - lastRequestTime > 10000) {
        Serial.println("## Timeout - closing connection");
        requestOngoing = false;
        processQueue();
    }
}

[mathieucarbou]

ok. In my example, this is equivalent à running with #define MAX_CLIENTS 1, which will only keep 1 client alive. Tested with 1 client, works fine also, but strangly, after a bunch of requests, next ones become very slow.

[mathieucarbou]

@tbnobody : the fix seems to have a huge effect on watchdog: me-no-dev/ESPAsyncWebServer#1437

[mathieucarbou]

@DaeMonSxy @tbnobody : I think I found something.... There were a bottlenek in this patch here:

https://github.com/me-no-dev/AsyncTCP/pull/173/files#diff-5312944d5b5f39741f3827dd678a8e828e2624ceab236264c025ef2bdf400d6aR938-R941

That was slowing down the reads at some point. I've reverted to the original code and this fixes the slowdown and I do not have ack timeouts anymore.

Would you be able both of you to test release v3.2.10 ?

I will wait for your feedback before releasing ESPAsyncWebServer again

Thanks!

[tbnobody]

I don't see any crashes right now!

Using

lib_deps =
    mathieucarbou/ESPAsyncWebServer @ 3.3.13
    https://github.com/mathieucarbou/AsyncTCP.git#main

[mathieucarbou]

Cool! And the perf should be better, that's what I saw in my testing.
I was able to run 16 clients at the same time doing reads, so on server side this translates to concurrent (16) readings of incoming requests. And without slowdown after a few seconds.

[mathieucarbou]

There were so many issues in this guy's PR! (me-no-dev/AsyncTCP#173). I only took the memory leak fix and slot allocation checks but the rest was problematic.

[mathieucarbou]

ESPAsyncWS released: v3.3.14

[mathieucarbou]

I've put something in place to run some benchmarks over some endpoints.

=> https://github.com/mathieucarbou/ESPAsyncWebServer?tab=readme-ov-file#performance

With the fix, I can now reach that amount of concurrency.

The limit begin set by CONFIG_LWIP_MAX_ACTIVE_TCP from the lwip layer (16).

[DaeMonSxy]

hi there,

Going to test with :
mathieucarbou/ESPAsyncWebServer @ 3.3.14

For the first look, the overall webserver is much faster, I will leave code run on my devices 24/7, so lets see tomorrow.
Thanks

[mathieucarbou]

Awesome! Thanks a lot!

[DaeMonSxy]

bit of an offtopic, but linked here:
I have a home-center-automation device, collectting all mqtt communications and based on certain rules executing control, and arg-requests....
yet this is plugged to linux headless system for logging purposes, so-please addvice platformio settings for debugging till tomorrow, and lets see if crash happens we will have a detailed log.

yet:

build_flags =
-ggdb                       ; Enable debugging symbols for use with GDB
        -Og                         ; Optimize for debugging, suitable for debugging with line numbers
        -g3                         ; Include extensive debugging information in the compiled binary
        -Os                         ; Optimize for size (Smallest code size)
        -Wformat
        -Wunused-function
        -Wl,--print-memory-usage    ; Print memory usage information after the build
        ;-DCORE_DEBUG_LEVEL=0 ; None
        ;-DCORE_DEBUG_LEVEL=1 ; Error
        ;-DCORE_DEBUG_LEVEL=2 ; Warn
        ;-DCORE_DEBUG_LEVEL=3 ; Info
        ;-DCORE_DEBUG_LEVEL=4 ; Debug (verbose)
        -DCORE_DEBUG_LEVEL=5  ; Verbose
        -D CONFIG_ASYNC_TCP_QUEUE_SIZE=128      ; Async TCP queue size
        -D CONFIG_ASYNC_TCP_RUNNING_CORE=1      ; Async TCP async task core
        -D CONFIG_ASYNC_TCP_STACK_SIZE=8096     ; Async TCP async stac ksize
        -D WS_MAX_QUEUED_MESSAGES=64            ; WebSocket queue size

What else would you put into build_flags to see if error/crash would happen?

[mathieucarbou]

That's perfect! Although I find your stack size very high for async_tcp task. Mine is 4k.
Probably you can reduce it if you need to ;-)

Easiest thing would be to run with a USB cable attached in order to collect stack traces and decode them.

For so far all our testing both of us look promising!

[DaeMonSxy]

so far so good , uptime: 0 d, 08:53:36
lets wait few more days :)
thanks

[mathieucarbou]

@DaeMonSxy @tbnobody : FYI I also took the time to fork AsyncTCPSock (AsyncTCP replacement based on BSD sockets which is also more performant since does not use the queue mechanism of AsyncTCP) and align it with AsyncTCP macros.

You can see here some perf comparison:

https://github.com/mathieucarbou/ESPAsyncWebServer?tab=readme-ov-file#performance

AsyncTCPSock is definitely faster and also consumes about the same heap (maybe 1% more in my case but not so different).
AsyncTCPSock by default defines a stack of 16K, but I run it with a stack of 4K, like also do with AsyncTCP.

How to ignore AsyncTCP and use AsyncTCPSock instead:

https://github.com/mathieucarbou/ESPAsyncWebServer?tab=readme-ov-file#dependencies

Depending on the app, switching might bring more perf, especially in the case of an app doing heavy tasks like I have (electricity monitoring tasks) or like OpenDTU (rf scanning). Less cpu time in i/o serving requests means more cpu time available for other tasks.

[DaeMonSxy]

Well ,early happyness,
previously I have not had any issues with mqtt conenctions, now it seems something is going on in the background.
changing code back and forse, tryng to debug the root... after few messages crashing, im on 3.2.10 asynctcp

Guru Meditation Error: Core  1 panic'ed (Unhandled debug exception). 
Debug exception reason: Stack canary watchpoint triggered (async_tcp) 
Core  1 register dump:
PC      : 0x4008fe83  PS      : 0x00060036  A0      : 0x8008e6e0  A1      : 0x3ffd7df0  
A2      : 0x3ffc54d8  A3      : 0xb33fffff  A4      : 0x0000cdcd  A5      : 0x00060023  
A6      : 0x00060023  A7      : 0x0000abab  A8      : 0xb33fffff  A9      : 0xffffffff  
A10     : 0x00000024  A11     : 0x00000001  A12     : 0x80084ece  A13     : 0x3ffc542c  
A14     : 0x007c54d8  A15     : 0x003fffff  SAR     : 0x00000004  EXCCAUSE: 0x00000001  
EXCVADDR: 0x00000000  LBEG    : 0x4008a7d1  LEND    : 0x4008a7e1  LCOUNT  : 0xffffffaf  


Backtrace: 0x4008fe80:0x3ffd7df0 0x4008e6dd:0x3ffd7e30 0x4008cb9c:0x3ffd7e60 0x4008cb4c:0xa5a5a5a5 |<-CORRUPTED

[tbnobody]

I am also using AsyncTCP with 3.2.10 with https://github.com/bertmelis/espMqttClient.git#v1.7.0 and everything works without problems.. Uptime 1 day and 6hrs....
What mqtt library are you using?

Also using this flags:

OpenDTU/platformio.ini

Lines 30 to 32 in b7f830f

	-DCONFIG_ASYNC_TCP_EVENT_QUEUE_SIZE=128
	-DCONFIG_ASYNC_TCP_QUEUE_SIZE=128
	-DEMC_TASK_STACK_SIZE=6400

[mathieucarbou]

Debug exception reason: Stack canary watchpoint triggered (async_tcp)

@DaeMonSxy : this one is easy ;-)

You need more stack size for the async_tcp task.

If you want to monitor the stack usage of the different tasks in your code you can use something like https://mathieu.carbou.me/MycilaTaskMonitor which periodically prints (or expose in a json object) the stack high watermark of the registered tasks.

You can start with -D CONFIG_ASYNC_TCP_STACK_SIZE=8096 or more, then use the app a lot, see what's remaining and decrease the value. I use to leave around ~500-1000b of free stack space depending on the task, and a little more than 2k for the mqttTask (because activating mqtts takes more stack memory).

FYI, the async_tcp task, like a lof of other I/O tasks in ESP_IDF (mqttTask, async_udp task, etc) should run ok with only 4K of stack.

If you use / need more, it means you are probably incorrectly allocating memory in the wrong place, like on the stack in a http handler in your app called by the async_tcp task, or using a library which does too many things in a handler.

[DaeMonSxy]

using :
https://github.com/HeMan/async-mqtt-client

still, having a lot of esp8266's and ESP32's - so for compatibility purposes that fit my needs.
Just checked, very similar to bertmelis git - but cannot see who is forking from whom.

nevertheless, my Center device already riched uptime : 1 d, 04:57:22 - so server and async seems good for now.