search

espressif / arduino-esp32

Arduino core for the ESP32
GNU Lesser General Public License v2.1
13.53k stars 7.39k forks source link

Crash with error message: "Required to lock TCPIP core functionality" #10526

Open mathieucarbou opened 3 hours ago

mathieucarbou commented 3 hours ago

Description

I have several apps that I keep updated to lats Arduino RC.

3.1.0-RC1 work fine.

[env]
build_type = release
framework = arduino
platform = https://github.com/pioarduino/platform-espressif32/releases/download/53.03.10-rc1/platform-espressif32.zip

Since RC2 (3.1.0-RC2), I am observing several crashes with always the same error, in STA mode (not in AP mode).

[env]
build_type = release
framework = arduino
platform = https://github.com/pioarduino/platform-espressif32/releases/download/53.03.10-rc2/platform-espressif32.zip
[  3555][D][ESPCONNECT][1][arduino_events] [NETWORK_CONNECTING] WiFiEvent: ARDUINO_EVENT_WIFI_STA_GOT_IP
[  3558][D][ESPCONNECT][1][arduino_events] State: NETWORK_CONNECTING => NETWORK_CONNECTED
[  3568][D][JSY-UDP][1][arduino_events] NetworkState: NETWORK_CONNECTING => NETWORK_CONNECTED
[  3579][I][JSY-UDP][1][arduino_events] Connected with IP address 192.168.125.130
[  3579][I][JSY-UDP][1][core] Enable Network Services...
[  3589][I][JSY-UDP][1][core] Enable Web Server...

assert failed: tcp_alloc /IDF/components/lwip/lwip/src/core/tcp.c:1851 (Required to lock TCPIP core functionality!)

Backtrace: 0x400832e5:0x3ffb23e0 0x4008c429:0x3ffb2400 0x400926d6:0x3ffb2420 0x400fb4cb:0x3ffb2550 0x400fb645:0x3ffb2570 0x40173517:0x3ffb2590 0x400dd44d:0x3ffb25e0 0x400d41b3:0x3ffb2600 0x400d4245:0x3ffb2640 0x400e01b5:0x3ffb2660 0x400e0440:0x3ffb2690 0x400e0481:0x3ffb26c0 0x400e04a5:0x3ffb26e0 0x4008cefe:0x3ffb2700
  #0  0x400832e5 in panic_abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp_system/panic.c:463
  #1  0x4008c429 in esp_system_abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp_system/port/esp_system_chip.c:92
  #2  0x400926d6 in __assert_func at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/newlib/assert.c:80
  #3  0x400fb4cb in tcp_alloc at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/core/tcp.c:1851 (discriminator 1)
  #4  0x400fb645 in tcp_new_ip_type at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/core/tcp.c:2006
  #5  0x40173517 in AsyncServer::begin() at .pio/libdeps/dev/AsyncTCP/src/AsyncTCP.cpp:1464 (discriminator 10)
  #6  0x400dd44d in AsyncWebServer::begin() at .pio/libdeps/dev/ESPAsyncWebServer/src/WebServer.cpp:120
  #7  0x400d41b3 in networkUpTask::{lambda(void*)#1}::operator()(void*) const at Sender.ino:240
  #8  0x400d4245 in void std::__invoke_impl<void, networkUpTask::{lambda(void*)#1}&, void*>(std::__invoke_other, networkUpTask::{lambda(void*)#1}&, void*&&) at /Users/mat/.platformio/packages/toolchain-xtensa-esp-elf/xtensa-esp-elf/include/c++/13.2.0/bits/invoke.h:61
      (inlined by) std::enable_if<is_invocable_r_v<void, networkUpTask::{lambda(void*)#1}&, void*>, void>::type std::__invoke_r<void, networkUpTask::{lambda(void*)#1}&, void*>(networkUpTask::{lambda(void*)#1}&, void*&&) at /Users/mat/.platformio/packages/toolchain-xtensa-esp-elf/xtensa-esp-elf/include/c++/13.2.0/bits/invoke.h:111
      (inlined by) std::_Function_handler<void (void*), networkUpTask::{lambda(void*)#1}>::_M_invoke(std::_Any_data const&, void*&&) at /Users/mat/.platformio/packages/toolchain-xtensa-esp-elf/xtensa-esp-elf/include/c++/13.2.0/bits/std_function.h:290
  #9  0x400e01b5 in std::function<void (void*)>::operator()(void*) const at /Users/mat/.platformio/packages/toolchain-xtensa-esp-elf/xtensa-esp-elf/include/c++/13.2.0/bits/std_function.h:591
      (inlined by) Mycila::Task::_run(long long const&) at .pio/libdeps/dev/MycilaTaskManager/src/MycilaTaskManager.cpp:417
  #10 0x400e0440 in Mycila::Task::tryRun() at .pio/libdeps/dev/MycilaTaskManager/src/MycilaTaskManager.cpp:334
  #11 0x400e0481 in Mycila::TaskManager::loop() at .pio/libdeps/dev/MycilaTaskManager/src/MycilaTaskManager.cpp:106
  #12 0x400e04a5 in Mycila::TaskManager::_asyncTaskManager(void*) at .pio/libdeps/dev/MycilaTaskManager/src/MycilaTaskManager.cpp:196
  #13 0x4008cefe in vPortTaskWrapper at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:139

Another app:

[  2797][I][ESPCONNECT][1][y-pio] Set WiFi Static IP Configuration:
[  2798][I][ESPCONNECT][1][y-pio]  - IP: 192.168.[  2867][V][STA.cpp:184] _onStaEvent(): STA Started
125.99
[  2814][I][ESPCONNECT][1][y-pio]  - Gateway: 192.168.125.1
[  2814][I][ESPCONNECT][1][y-pio]  - Subnet: 255.255.255.0
[  2824][I][ESPCONNECT][1][y-pio]  - DNS: 192.168.125.1
[  2901][V][NetworkEvents.cpp:113] _checkForEvent(): Network Event: 110 - STA_START
[  2910][V][STA.cpp:110] _onStaArduinoEvent(): Arduino STA Event: 110 - STA_START
[  2850][D][ESPCONNECT][1][y-pio] Connecting to SSID: IoT...
[  2854][D][ESPCONNECT][1][y-pio] WiFi started.
[  3312][I][YASOLR][1][y-core] Starting Thyristor with semi-period: 10000 us
[  3314][I][DIMMER][1][y-core] Enable Dimmer on pin 25 with semi-period 10000 us
[  3405][V][esp32-hal-periman.c:235] perimanSetBusDeinit(): Deinit function for type GPIO (1) successfully set to 0x401dd584
[  3420][V][esp32-hal-periman.c:160] perimanSetPinBus(): Pin 25 successfully set to type GPIO (1) with bus 0x1a
[  3352][I][DIMMER][1][y-core] Enable Dimmer on pin 26 with semi-period 10000 us
[  3432][V][esp32-hal-periman.c:235] perimanSetBusDeinit(): Deinit function for type GPIO (1) successfully set to 0x401dd584
[  3452][V][esp32-hal-periman.c:160] perimanSetPinBus(): Pin 26 successfully set to type GPIO (1) with bus 0x1b
[  5359][V][STA.cpp:204] _onStaEvent(): STA Connected: SSID: IoT, BSSID: 00:17:13:37:28:c0, Channel: 11, Auth: OPEN
[  5372][V][NetworkEvents.cpp:113] _checkForEvent(): Network Event: 112 - STA_CONNECTED
[  5372][V][NetworkInterface.cpp:78] _onIpEvent(): sta Got New IP: 192.168.125.99 MASK: 255.255.255.0 GW: 192.168.125.1
[  5393][V][STA.cpp:110] _onStaArduinoEvent(): Arduino STA Event: 112 - STA_CONNECTED
[  5401][V][NetworkEvents.cpp:113] _checkForEvent(): Network Event: 115 - STA_GOT_IP
[  5410][V][STA.cpp:110] _onStaArduinoEvent(): Arduino STA Event: 115 - STA_GOT_IP
[  5418][V][STA.cpp:169] _onStaArduinoEvent(): STA IP: 192.168.125.99, MASK: 255.255.255.0, GW: 192.168.125.1
[  5302][D][ESPCONNECT][1][arduino_events] [NETWORK_CONNECTING] WiFiEvent: ARDUINO_EVENT_WIFI_STA_GOT_IP
[  5307][D][ESPCONNECT][1][arduino_events] State: NETWORK_CONNECTING => NETWORK_CONNECTED
[  5317][D][YASOLR][1][arduino_events] NetworkState: NETWORK_CONNECTING => NETWORK_CONNECTED
[  5328][I][YASOLR][1][arduino_events] Connected with IP address 192.168.125.99
[  5403][I][YASOLR][1][y-pio] Enable Network Services
[  5404][I][YASOLR][1][y-pio] Enable Web Server
[  5533][I][AsyncTCP.cpp:62] _start_asyncsock_task(): Creating asyncTcpSock task running in core 1 (-1 for any available core)...
[  5431][I][YASOLR][1][y-pio] Enable NTP

assert failed: sntp_setoperatingmode /IDF/components/lwip/lwip/src/apps/sntp/sntp.c:728 (Required to lock TCPIP core functionality!)

Backtrace: 0x400835f9:0x3ffd7cc0 0x4008f099:0x3ffd7ce0 0x4009558a:0x3ffd7d00 0x4012ac0c:0x3ffd7e30 0x40116492:0x3ffd7e50 0x4010272f:0x3ffd7ec0 0x400ef37a:0x3ffd7f20 0x400ef441:0x3ffd7f60 0x4010582a:0x3ffd7f80 0x40105aec:0x3ffd7fb0 0x40105b2d:0x3ffd7fe0 0x40105b51:0x3ffd8000 0x4008fad2:0x3ffd8020
  #0  0x400835f9 in panic_abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp_system/panic.c:463
  #1  0x4008f099 in esp_system_abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp_system/port/esp_system_chip.c:92
  #2  0x4009558a in __assert_func at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/newlib/assert.c:80
  #3  0x4012ac0c in sntp_setoperatingmode at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/apps/sntp/sntp.c:729 (discriminator 1)
  #4  0x40116492 in configTime at /Users/mat/.platformio/packages/framework-arduinoespressif32@src-e589a26bbeefbfd0fcf50e49e574e2c6/cores/esp32/esp32-hal-time.c:53
  #5  0x4010272f in Mycila::NTPClass::sync(char const*, unsigned char) at .pio/libdeps/pro-esp32/MycilaNTP/src/MycilaNTP.cpp:66 (discriminator 1)
  #6  0x400ef37a in networkConfigTask::{lambda(void*)#1}::operator()(void*) const at src/tasks/Network.cpp:26 (discriminator 4)
  #7  0x400ef441 in void std::__invoke_impl<void, networkConfigTask::{lambda(void*)#1}&, void*>(std::__invoke_other, networkConfigTask::{lambda(void*)#1}&, void*&&) at /Users/mat/.platformio/packages/toolchain-xtensa-esp-elf/xtensa-esp-elf/include/c++/13.2.0/bits/invoke.h:61
      (inlined by) std::enable_if<is_invocable_r_v<void, networkConfigTask::{lambda(void*)#1}&, void*>, void>::type std::__invoke_r<void, networkConfigTask::{lambda(void*)#1}&, void*>(networkConfigTask::{lambda(void*)#1}&, void*&&) at /Users/mat/.platformio/packages/toolchain-xtensa-esp-elf/xtensa-esp-elf/include/c++/13.2.0/bits/invoke.h:111
      (inlined by) std::_Function_handler<void (void*), networkConfigTask::{lambda(void*)#1}>::_M_invoke(std::_Any_data const&, void*&&) at /Users/mat/.platformio/packages/toolchain-xtensa-esp-elf/xtensa-esp-elf/include/c++/13.2.0/bits/std_function.h:290
  #8  0x4010582a in std::function<void (void*)>::operator()(void*) const at /Users/mat/.platformio/packages/toolchain-xtensa-esp-elf/xtensa-esp-elf/include/c++/13.2.0/bits/std_function.h:591
      (inlined by) Mycila::Task::_run(long long const&) at .pio/libdeps/pro-esp32/MycilaTaskManager/src/MycilaTaskManager.cpp:417
  #9  0x40105aec in Mycila::Task::tryRun() at .pio/libdeps/pro-esp32/MycilaTaskManager/src/MycilaTaskManager.cpp:334
  #10 0x40105b2d in Mycila::TaskManager::loop() at .pio/libdeps/pro-esp32/MycilaTaskManager/src/MycilaTaskManager.cpp:106
  #11 0x40105b51 in Mycila::TaskManager::_asyncTaskManager(void*) at .pio/libdeps/pro-esp32/MycilaTaskManager/src/MycilaTaskManager.cpp:196
  #12 0x4008fad2 in vPortTaskWrapper at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:139

Sketch

N/A

Debug Message

N/A

Other Steps to Reproduce

No response

I have checked existing issues, online documentation and the Troubleshooting Guide

mathieucarbou commented 3 hours ago

I suspect this is caused by: CONFIG_LWIP_CHECK_THREAD_SAFETY being activated ? See:

https://github.com/espressif/esp-idf/blob/release/v5.3/components/lwip/port/include/lwipopts.h#L53-L55

As I understand, CONFIG_LWIP_CHECK_THREAD_SAFETY will fail if we do not properly lock ?

That is not a bad check per see, but right now, activating it could break a lof of downstream projects, but also Arduino components right ? Example of the stack trace above, which lies in the sntp feature.

Example:

https://github.com/espressif/esp-lwip/blob/f150e2321ac09bb0fd35a7fcbc1b116fbf93434e/src/apps/sntp/sntp.c#L714

This issue seems related: https://github.com/espressif/arduino-esp32/pull/10415

mathieucarbou commented 2 hours ago

Another ref: https://github.com/espressif/esp-matter/issues/853#issuecomment-1971065330

me-no-dev commented 2 hours ago

It is Matter that enabled it..

~/Desktop/ESP32/ESP-IDF-5/esp32-arduino-lib-builder/managed_components/espressif__esp_matter/connectedhomeip/connectedhomeip/config/esp32/components/chip/Kconfig:
  220              bool "Enable LwIP Thread safety options"
  221              default y
  222:             select LWIP_TCPIP_CORE_LOCKING
  223              select LWIP_CHECK_THREAD_SAFETY
  224              help
  225                  CHIP SDK performs LwIP core locking before calling an LwIP API.
  226:                 To make the calls thread safe we have to enable LWIP_TCPIP_CORE_LOCKING.
  227                  Here, we are also enabling LWIP_CHECK_THREAD_SAFETY which will assert when
  228                  LwIP code gets called from any other context or without holding the LwIP lock.

AsyncUDP in this repo is already made to work with the locks. The fastest way is to have a look and see if you can solve it yourself. Not everything in Async is executed in the LwIP thread, so some locking will now be required. We can not get rid of Matter :)

mathieucarbou commented 2 hours ago

But for the last stack trace, only sntp is involved... I am not using AsyncTCP in the second app, but AsyncTcpSock (bsd sockets). So the bug could come from where ?

For the first stack trace, do you mean that I should port in AsyncTCP these locks like they are done in AsyncUDP ?

That's impressive the amount of libs, web servers and mqtt clients will break when they will adopt 3.1.0.

I wish AsyncTCP were included in Arduino Core !