search

mathieucarbou / ESPAsyncWebServer

Asynchronous HTTP and WebSocket Server Library for ESP32, ESP8266 and RP2040
https://mathieu.carbou.me/ESPAsyncWebServer/
GNU Lesser General Public License v3.0
83 stars 17 forks source link

[BUG]WebSocket.printfAll causes a "CORRUPT HEAP: Bad tail at 0x3ffe389c. Expected 0xbaad5678 got 0xbaad5600" crash #94

Closed benpeart closed 2 months ago

benpeart commented 2 months ago

I have an application that successfully opens a AsyncWebSocket connection to a web page. The web page can successfully send messages to my application but my application does not successfully send messages to the web page.

In my OnEvent handler for the WS_EVT_CONNECT event, calling:

 wsServer.printfAll("kp%.4f", Kp);

generates a corrupt heap crash. If I switch it to:

        char wBuf[63];

        sprintf(wBuf, "kp%.4f", Kp);
        wsServer.textAll(wBuf);

it doesn't crash but the web page doesn't get the message. If I continue attempting to send messages, I will get a "too many messages queued" error and then the connection will be closed:

[ 33532][E][AsyncWebSocket.cpp:424] _queueMessage(): Too many messages queued: closing connection
[ 41658][E][AsyncWebSocket.cpp:424] _queueMessage(): Too many messages queued: closing connection

Board

esp32dev

Stack trace

CORRUPT HEAP: Bad tail at 0x3ffe389c. Expected 0xbaad5678 got 0xbaad5600

assert failed: multi_heap_free multi_heap_poisoning.c:259 (head != NULL)

Backtrace: 0x40083ff1:0x3ffdcb70 0x40095ded:0x3ffdcb90 0x4009bcf5:0x3ffdcbb0 0x4009b8f1:0x3ffdcce0 0x40084561:0x3ffdcd00 0x4009bd25:0x3ffdcd20 0x4018d169:0x3ffdcd40 0x400eeeea:0x3ffdcd60 0x400f1746:0x3ffdcd80 0x400d30b6:0x3ffdcde0 0x401a72ab:0x3ffdce20 0x400efe05:0x3ffdce40 0x400efe2e:0x3ffdce90 0x400f0719:0x3ffdcec0 0x400f07ff:0x3ffdcf00 0x400f083e:0x3ffdcf20 0x400f3361:0x3ffdcf40 0x400f339d:0x3ffdcf60 0x4018fd33:0x3ffdcf80 0x4018fd65:0x3ffdcfb0 0x4018fd78:0x3ffdcfd0 0x4018ffb2:0x3ffdcff0 0x40190009:0x3ffdd010
  #0  0x40083ff1 in panic_abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp_system/panic.c:408
  #1  0x40095ded 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  0x4009bcf5 in __assert_func at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/newlib/assert.c:85
  #3  0x4009b8f1 in multi_heap_free at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/multi_heap_poisoning.c:259 (discriminator 1)
  #4  0x40084561 in heap_caps_free at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/heap_caps.c:382
  #5  0x4009bd25 in free at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/newlib/heap.c:39
  #6  0x4018d169 in operator delete(void*) at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/gcc/libstdc++-v3/libsupc++/del_op.cc:49
  #7  0x400eeeea in __gnu_cxx::new_allocator<unsigned char>::deallocate(unsigned char*, unsigned int) at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\ext/new_allocator.h:125
      (inlined by) std::allocator_traits<std::allocator<unsigned char> >::deallocate(std::allocator<unsigned char>&, unsigned char*, unsigned int) at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/alloc_traits.h:462
      (inlined by) std::_Vector_base<unsigned char, std::allocator<unsigned char> >::_M_deallocate(unsigned char*, unsigned int) at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/stl_vector.h:304        
      (inlined by) std::_Vector_base<unsigned char, std::allocator<unsigned char> >::~_Vector_base() at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/stl_vector.h:285
      (inlined by) std::vector<unsigned char, std::allocator<unsigned char> >::~vector() at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/stl_vector.h:570
      (inlined by) void __gnu_cxx::new_allocator<std::vector<unsigned char, std::allocator<unsigned char> > >::destroy<std::vector<unsigned char, std::allocator<unsigned char> > >(std::vector<unsigned char, std::allocator<unsigned char> >*) at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\ext/new_allocator.h:140
      (inlined by) void std::allocator_traits<std::allocator<std::vector<unsigned char, std::allocator<unsigned char> > > >::destroy<std::vector<unsigned char, std::allocator<unsigned char> > >(std::allocator<std::vector<unsigned char, std::allocator<unsigned char> > >&, std::vector<unsigned char, std::allocator<unsigned char> >*) at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/alloc_traits.h:487
      (inlined by) std::_Sp_counted_ptr_inplace<std::vector<unsigned char, std::allocator<unsigned char> >, std::allocator<std::vector<unsigned char, std::allocator<unsigned char> > >, (__gnu_cxx::_Lock_policy)2>::_M_dispose() at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/shared_ptr_base.h:554
  #8  0x400f1746 in std::_Sp_counted_base<(__gnu_cxx::_Lock_policy)2>::_M_release() at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/shared_ptr_base.h:155
      (inlined by) std::__shared_count<(__gnu_cxx::_Lock_policy)2>::~__shared_count() at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/shared_ptr_base.h:728
      (inlined by) std::__shared_ptr<std::vector<unsigned char, std::allocator<unsigned char> >, (__gnu_cxx::_Lock_policy)2>::~__shared_ptr() at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/shared_ptr_base.h:1167
      (inlined by) std::shared_ptr<std::vector<unsigned char, std::allocator<unsigned char> > >::~shared_ptr() at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/shared_ptr.h:103
      (inlined by) AsyncWebSocket::printfAll(char const*, ...) at .pio/libdeps/debug/ESPAsyncWebServer/src/AsyncWebSocket.cpp:1020
  #9  0x400d30b6 in onEvent(AsyncWebSocket*, AsyncWebSocketClient*, AwsEventType, void*, unsigned char*, unsigned int) at src/webui.cpp:48 (discriminator 7)

 #10 0x401a72ab in std::_Function_handler<void (AsyncWebSocket*, AsyncWebSocketClient*, AwsEventType, void*, unsigned char*, unsigned int), void (*)(AsyncWebSocket*, AsyncWebSocketClient*, AwsEventType, void*, unsigned char*, unsigned int)>::_M_invoke(std::_Any_data const&, AsyncWebSocket*&&, AsyncWebSocketClient*&&, AwsEventType&&, void*&&, unsigned char*&&, unsigned int&&) at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/std_function.h:297
  #11 0x400efe05 in std::function<void (AsyncWebSocket*, AsyncWebSocketClient*, AwsEventType, void*, unsigned char*, unsigned int)>::operator()(AsyncWebSocket*, AsyncWebSocketClient*, AwsEventType, void*, unsigned char*, unsigned int) const at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/std_function.h:687
  #12 0x400efe2e in AsyncWebSocket::_handleEvent(AsyncWebSocketClient*, AwsEventType, void*, unsigned char*, unsigned int) at .pio/libdeps/debug/ESPAsyncWebServer/src/AsyncWebSocket.cpp:766
  #13 0x400f0719 in AsyncWebSocketClient::AsyncWebSocketClient(AsyncWebServerRequest*, AsyncWebSocket*) at .pio/libdeps/debug/ESPAsyncWebServer/src/AsyncWebSocket.cpp:290
  #14 0x400f07ff in void __gnu_cxx::new_allocator<std::_List_node<AsyncWebSocketClient> >::construct<AsyncWebSocketClient, AsyncWebServerRequest*&, AsyncWebSocket*>(AsyncWebSocketClient*, AsyncWebServerRequest*&, AsyncWebSocket*&&) at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\ext/new_allocator.h:136
      (inlined by) void std::allocator_traits<std::allocator<std::_List_node<AsyncWebSocketClient> > >::construct<AsyncWebSocketClient, AsyncWebServerRequest*&, AsyncWebSocket*>(std::allocator<std::_List_node<AsyncWebSocketClient> >&, AsyncWebSocketClient*, AsyncWebServerRequest*&, AsyncWebSocket*&&) at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/alloc_traits.h:475
      (inlined by) std::_List_node<AsyncWebSocketClient>* std::__cxx11::list<AsyncWebSocketClient, std::allocator<AsyncWebSocketClient> >::_M_create_node<AsyncWebServerRequest*&, AsyncWebSocket*>(AsyncWebServerRequest*&, AsyncWebSocket*&&) at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/stl_list.h:645
      (inlined by) void std::__cxx11::list<AsyncWebSocketClient, std::allocator<AsyncWebSocketClient> >::_M_insert<AsyncWebServerRequest*&, AsyncWebSocket*>(std::_List_iterator<AsyncWebSocketClient>, AsyncWebServerRequest*&, AsyncWebSocket*&&) at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/stl_list.h:1903
      (inlined by) void std::__cxx11::list<AsyncWebSocketClient, std::allocator<AsyncWebSocketClient> >::emplace_back<AsyncWebServerRequest*&, AsyncWebSocket*>(AsyncWebServerRequest*&, AsyncWebSocket*&&) at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/stl_list.h:1235
      (inlined by) AsyncWebSocket::_newClient(AsyncWebServerRequest*) at .pio/libdeps/debug/ESPAsyncWebServer/src/AsyncWebSocket.cpp:771
  #15 0x400f083e in AsyncWebSocketResponse::_ack(AsyncWebServerRequest*, unsigned int, unsigned int) at .pio/libdeps/debug/ESPAsyncWebServer/src/AsyncWebSocket.cpp:1205
  #16 0x400f3361 in AsyncWebServerRequest::_onAck(unsigned int, unsigned int) at .pio/libdeps/debug/ESPAsyncWebServer/src/WebRequest.cpp:188
  #17 0x400f339d in std::_Function_handler<void (void*, AsyncClient*, unsigned int, unsigned int), AsyncWebServerRequest::AsyncWebServerRequest(AsyncWebServer*, AsyncClient*)::{lambda(void*, AsyncClient*, unsigned int, unsigned int)#2}>::_M_invoke(std::_Any_data const&, void*&&, AsyncClient*&&, unsigned int&&, AsyncClient*&&) at .pio/libdeps/debug/ESPAsyncWebServer/src/WebRequest.cpp:40
      (inlined by) _M_invoke at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/std_function.h:297
  #18 0x4018fd33 in std::function<void (void*, AsyncClient*, unsigned int, unsigned int)>::operator()(void*, AsyncClient*, unsigned int, unsigned int) const at c:\users\benpe\.platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits/std_function.h:687
  #19 0x4018fd65 in AsyncClient::_sent(tcp_pcb*, unsigned short) at .pio/libdeps/debug/AsyncTCP/src/AsyncTCP.cpp:978
  #20 0x4018fd78 in AsyncClient::_s_sent(void*, tcp_pcb*, unsigned short) at .pio/libdeps/debug/AsyncTCP/src/AsyncTCP.cpp:1387
  #21 0x4018ffb2 in _handle_async_event(lwip_event_packet_t*) at .pio/libdeps/debug/AsyncTCP/src/AsyncTCP.cpp:176
  #22 0x40190009 in _async_service_task(void*) at .pio/libdeps/debug/AsyncTCP/src/AsyncTCP.cpp:205

Additional notes

I'm currently using:

build_flags = 
    -D CONFIG_ASYNC_TCP_MAX_ACK_TIME=3000
    -D CONFIG_ASYNC_TCP_PRIORITY=10
    -D CONFIG_ASYNC_TCP_QUEUE_SIZE=128
    -D CONFIG_ASYNC_TCP_RUNNING_CORE=1
    -D CONFIG_ASYNC_TCP_STACK_SIZE=4096

in my platform.ini in hopes it will help (but it doesn't appear to).

Complete source for my project is here.

The onEvent handler in question is here.

The corresponding code in the web page is here

mathieucarbou commented 2 months ago

I don't know where is exactly the bug yet, but I would suggest to not use such method for this use case. If you look how it is implemented, it does twice the formatting to detect the string length. I don't know why this method was added to the library but it is IMO not the best move that was done,

Also, they do not check if the return from vsnprintf is negative, and they put that in a size_t (unsigned), so if the return is negative, you'll end up with a huge unsigned number.

I would suggest:

String payload;
payload.reserve(2+10); // 10, depending on your PID Kp acceptable values
payload.concat("kp");
payload.concat(String(f, 4));
client.text(payload)
mathieucarbou commented 2 months ago

Will open a PR to try fix these methods... I saw at least 3 issues... I really encourage you to not use these printf variants: they are slow.

mathieucarbou commented 2 months ago

@benpeart : I have opened PR #95 and I've tested it locally with the SimpleServer.ino example and websocat sending each 100 ms: ws.printfAll("kp%.4f", (10.0 / 3.0));.

it works fine now, will merge and release soon.

But I still advise you to not use this method because it is far from being efficient...

mathieucarbou commented 2 months ago

v3.2.4 released

benpeart commented 2 months ago

Thank you for your suggestion. I have switched my code over as recommended and now it works correctly. That was an amazingly fast fix!