Rollback #18 (assert failed: tcp_update_rcv_ann_wnd)

[mathieucarbou]

This PR is a rollback of the changes merged in #18, which were done following some testing showing they fixed the issues raised in:

• assert failed: tcp_update_rcv_ann_wnd (needs help to test fix) #14
• [BUG] assert failed: tcp_update_rcv_ann_wnd IDF/components/lwip/lwip/src/core/tcp.c:951 (new_rcv_ann_wnd <= 0xffff) ONLY when connected in AP #23
• crashes especially after firmware update at tcp_update_rcv_ann_wnd tbnobody/OpenDTU#2180

As it turns out in issue #23, it is still there.

The issue was easily reproductible by adding a delay as @mikeg0 pointed out in #14

    // Route for root / web page
    server.on("/", HTTP_GET, [](AsyncWebServerRequest *request)
    {
        digitalWrite(networkLedPin, HIGH);

        request->send(SPIFFS, "/index.html", "text/html", false);

        delay(500);
        digitalWrite(networkLedPin, LOW);
    });

After some local testing, I am not able to reproduce it with the following code:

  // Issue #14: assert failed: tcp_update_rcv_ann_wnd (needs help to test fix)
  // > curl -v http://192.168.4.1/issue-14
  pinMode(4, OUTPUT);
  server.on("/issue-14", HTTP_GET, [](AsyncWebServerRequest* request) {
    digitalWrite(4, HIGH);
    request->send(LittleFS, "/index.txt", "text/pain");
    delay(500);
    digitalWrite(4, LOW);
  });

(https://github.com/mathieucarbou/ESPAsyncWebServer/blob/main/examples/SimpleServer/SimpleServer.ino#L327-L335)

So what changed ?

With the introduction of middleware, the response is NOT ANYMORE sent over the network when send() is called. Instead, the response is kept in memory until the middleware chain finished. At the end, the response (or a new one if a middleware replaced it) is sent, so the sending is done from the internal ESpAsyncWS code.

So even if we can have some delays or slowdown in the async_tcp callback prior to the real sending on the network, while processing the request, it not now impossible to introduce some delays after the sending on the network is done and before returning from the callback.

I tested by introducing some delay in the ESPAsyncWS code after the request is sent over the network, and in fact, the problem appears.

My hypothesis is that the client code should return ASAP after the sending over the network (tcp operation), maybe to let the asynctcp code read the ack or whatever, which it could not do if a delay is introduced.

Conclusions

• The issue seems to be caused by the introduction of delay (or yield to a more priority task ?) after send() and before returning
• With the middleware redesign, this situation becomes impossible since the response is sent once the handler / middleware chain is finished

[DaeMonSxy]

Well ,it seem so : trying to investigate
happens occasionally..btu still

201216|00000116.478 [http] [19] Connected 192.168.11.100:88/json.htm?type=command&param=udevice&idx=5&nvalue=0&svalue=0.00
200368|00000116.488 [http] #< [19] {"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:0x3ffb39a0 0x4008ca11:0x3ffb39c0 0x40092039:0x3ffb39e0 0x40124d5e:0x3ffb3b10 0x40124e0c:0x3ffb3b30 0x400f4152:0x3ffb3b50 0x40121be4:0x3ffb3b70
  #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  0x40124d5e 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  0x40124e0c 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  0x400f4152 in _tcp_recved_api(tcpip_api_call_data*) at /Users/daemons/platformio_libdeps/ESP32/AsyncTCP-esphome/src/AsyncTCP.cpp:444
  #6  0x40121be4 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

[mathieucarbou]

@DaeMonSxy you mean that it happens again after the rollback ? It didn't happened before with the (supposed) fix merged in #14 ?
Do you have something somewhere in your code that could introduce delays in the tcp stack, like calling some sort of long operations from the handlers ?

[DaeMonSxy]

trying to figure out what/where caused, or maybe wrong lib..
found that some libraries could have been used, cannot yet figure out which lib downloads old async.

lib_deps =
        modules/
        SPI
        
        ; All
            paulstoffregen/Time ; date-time
            https://github.com/bblanchon/ArduinoJson
            https://github.com/adafruit/Adafruit_NeoPixel
            ;https://github.com/marvinroger/async-mqtt-client/archive/refs/tags/v0.9.0.zip
            https://github.com/HeMan/async-mqtt-client ;20240728 This branch is 24 commits ahead of OttoWinter/async-mqtt-client:master.


        ; ESPHOME
        
        ; mathieucarbou
            https://github.com/mathieucarbou/AsyncTCP
            ;https://github.com/mathieucarbou/AsyncTCP/archive/refs/tags/v3.1.4.zip
            https://github.com/mathieucarbou/ESPAsyncWebServer ; library.jsonbol a dependencies-bol az AsyncTCP-t
            ;https://github.com/mathieucarbou/ESPAsyncWebServer/archive/refs/tags/v3.2.0.zip
            ;https://github.com/mathieucarbou/MycilaMQTT
            ;https://github.com/mathieucarbou/WebSerialLite
            ;https://github.com/mathieucarbou/MycilaWebSerial
       
        ;rc-switch
            https://github.com/Martin-Laclaustra/rc-switch
            https://github.com/LSatan/SmartRC-CC1101-Driver-Lib 

        ; milight
            https://github.com/nRF24/RF24

Iam using just a few external libs- maybe mqtt, or basically your server also downloads additional sync lib code:
AsyncTCP@src-b53d29dd5994d000eb4cab7086b6ac38

at the moment Iam seeng the following libs, quite confusing:

AsyncTCP
AsyncTCP@src-79401a3222d23d1578cd11f26708a2e5
AsyncTCP@src-b53d29dd5994d000eb4cab7086b6ac38

[DaeMonSxy]

AsyncTCP

{
  "name": "AsyncTCP",
  "version": "3.2.8",
  "description": "Asynchronous TCP Library for ESP32",
  "keywords": "async,tcp",
  "repository": {
    "type": "git",
    "url": "https://github.com/mathieucarbou/AsyncTCP.git"
  },
  "authors": [
    {
      "name": "Hristo Gochkov"
    },
    {
      "name": "Mathieu Carbou",
      "maintainer": true
    }
  ],
  "license": "LGPL-3.0",
  "frameworks": "arduino",
  "platforms": [
    "espressif32",
    "libretiny"
  ],
  "build": {
    "libCompatMode": 2
  },
  "export": {
    "include": [
      "examples",
      "src",
      "library.json",
      "library.properties",
      "LICENSE",
      "README.md"
    ]
  }
}

AsyncTCP@src-79401a3222d23d1578cd11f26708a2e5

{
  "name": "AsyncTCP",
  "version": "3.2.4",
  "description": "Asynchronous TCP Library for ESP32",
  "keywords": "async,tcp",
  "repository": {
    "type": "git",
    "url": "https://github.com/mathieucarbou/AsyncTCP.git"
  },
  "authors": [
    {
      "name": "Hristo Gochkov"
    },
    {
      "name": "Mathieu Carbou",
      "maintainer": true
    }
  ],
  "license": "LGPL-3.0",
  "frameworks": "arduino",
  "platforms": [
    "espressif32",
    "libretiny"
  ],
  "build": {
    "libCompatMode": 2
  },
  "export": {
    "include": [
      "examples",
      "src",
      "library.json",
      "library.properties",
      "LICENSE",
      "README.md"
    ]
  }
}

AsyncTCP@src-b53d29dd5994d000eb4cab7086b6ac38

this has been dissapeared after removing platformio: lib_dep: ;https://github.com/mathieucarbou/AsyncTCP

[mathieucarbou]

@DaeMonSxy : yes you happen to have several versions of AsyncTCP in your build this is not good.
https://github.com/HeMan/async-mqtt-client depends on AsyncTCP-esphome also, so you might event have 3 versions:

• AsyncTCP-esphome
• AsyncTCP version X
• AsyncTCP version Y

[DaeMonSxy]

So figured out, I have had an old version of yours inside modules/ .. and that has been linked to platformio-dependencies.
fixed.

now i have properly only "version": "3.2.8", installed.
After first compile and upload still seeing tcp_update_rcv_ann_wnd error.
After restart seems ok again...

203656|00000009.978 [http] [1] #> 192.168.11.100:80/iqdt/index.php
195032|2024-10-12_20:55:382 [http] [1] #< {"iqserver":1,"date":"2024-10-12","time":"20:55:38","timezone":"Europe\/Budapest","lat":47.4979,"long":19.0402,"wan":"81.182.175.80","sunrise":"06:57:22","sunset":"18:03:02"}
202088|2024-10-12_20:55:493 [time] Synced 2024-10-12_20:55:493
199840|2024-10-12_20:55:382 [http] sunrise: 06:57:22
199840|2024-10-12_20:55:382 [http] sunset : 18:03:02
196312|2024-10-12_20:55:383 [mqtt] #> iqHome/0c8b957618c8_iqHeat32/location 0c8b957618c8

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


Backtrace: 0x40083d65:0x3ffb39a0 0x4008ca11:0x3ffb39c0 0x40092039:0x3ffb39e0 0x401249b6:0x3ffb3b10 0x40124a64:0x3ffb3b30 0x400f3cf6:0x3ffb3b50 0x4012183c:0x3ffb3b70
  #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  0x401249b6 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  0x40124a64 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  0x400f3cf6 in _tcp_recved_api(tcpip_api_call_data*) at /Users/daemons/platformio_libdeps/ESP32/AsyncTCP/src/AsyncTCP.cpp:452
  #6  0x4012183c 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: ccc2fe2af3b4bd09

Rebooting...
ets Jun  8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:1184
load:0x40078000,len:13232
load:0x40080400,len:3028
entry 0x400805e4
#
#
271060|00000001.096 [    ] ----------------------------------------
271060|00000001.096 [info] ID        : 0c8b957618c8
271060|00000001.096 [info] Type      : iqHeat32
271060|00000001.107 [info] ver       : 2024-1012
271060|00000001.107 [info] build     : 7508
271060|00000001.117 [info] Heap      :: 271060
271060|00000001.118 [info] Core      : v4.4.7-dirty
271060|00000001.118 [info] chModel   : ESP32-D0WD
271060|00000001.128 [info] chRev     :: 1
271060|00000001.128 [info] Cores     :: 2
271060|00000001.139 [info] boot      : SW_CPU_RESET

[mathieucarbou]

@DaeMonSxy turns out we just did some testing this evening with @tbnobody: tbnobody/OpenDTU#2326 (comment) and I've just released new versions juts now:

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

You can read the discussion FYI.

You can try again with those and let me know. Pay attention to only have those ones ;)