Looks like esp_wifi_sta_get_ap_info cause stack overflow or corrupt stack (IDFGH-4113)

[maxd]

Environment

• Development Kit: ESP32-DevKitC
• Kit version (for DevKitC): v4
• Module or chip used: ESP32-WROOM-32D
• IDF version : v4.1
• Build System: CMake and idf.py
• Compiler version: xtensa-esp32-elf-gcc (crosstool-NG esp-2020r2) 8.2.0
• Operating System: macOS
• Using an IDE?: No
• Power Supply: USB

Problem Description

Looks like call of esp_wifi_sta_get_ap_info cause stack overflow (or corrupt stack).

I have implemented test project to reproduce problem (it's part of my other project with minimal code to reproduce problem): esp_wifi_sta_get_ap_info_stack_overflow.

It cause the following error (from 1 sec till several minutes after start) (see full monitoring output here):

I (4607) LOG_TAG: Wi-Fi RSSI:***ERROR*** A stack overflow in task Tmr Svc has been detected.
abort() was called at PC 0x40088451 on core 0
0x40088451: vApplicationStackOverflowHook at /Users/mdobryakov/.esp-idf/components/esp32/panic.c:125


ELF file SHA256: dcacbb36167eb951

Backtrace: 0x40087fec:0x3ffbc210 0x4008842c:0x3ffbc240 0x40088451:0x3ffbc270 0x4008a208:0x3ffbc2a0 0x40088f40:0x3ffbc2d0 0x40088ef6:0xa5a5a5a5 |<-CORRUPTED
0x40087fec: invoke_abort at /Users/mdobryakov/.esp-idf/components/esp32/panic.c:157

0x4008842c: abort at /Users/mdobryakov/.esp-idf/components/esp32/panic.c:174

0x40088451: vApplicationStackOverflowHook at /Users/mdobryakov/.esp-idf/components/esp32/panic.c:125

0x4008a208: vTaskSwitchContext at /Users/mdobryakov/.esp-idf/components/freertos/tasks.c:2770

0x40088f40: _frxt_dispatch at /Users/mdobryakov/.esp-idf/components/freertos/portasm.S:406

0x40088ef6: _frxt_int_exit at /Users/mdobryakov/.esp-idf/components/freertos/portasm.S:206


Rebooting...

in some stack traces I see additional line:

0x400ff6b3: esp_wifi_sta_get_ap_info at ??:?

Stack for FreeRTOS timer has size of 2048 bytes (see sdkconfig). I suppose this is big stack size for such small handler and it should be enough to work of my code. So, I suppose that esp_wifi_sta_get_ap_info corrupt this stack and cause error.

P.S. I have set Stack smashing protection mode to Overall to decrease time of error appear but without this option the error happens too (required more time to reproduce).

Expected Behavior

esp_wifi_sta_get_ap_info must not corrupt stack.

Actual Behavior

Looks like esp_wifi_sta_get_ap_info corrupt stack.

Steps to reproduce

1. Clone esp_wifi_sta_get_ap_info_stack_overflow test project to reproduce problem.
2. Set correct SSID and password in main.cpp
3. Run idf.py reconfigure build flash monitor.

Code to reproduce this issue

See esp_wifi_sta_get_ap_info_stack_overflow test project.

It establish Wi-Fi connection use SSID and password and then run FreeRTOS timer to collect Wi-Fi RSSI every second (it real app every 10 sec) use esp_wifi_sta_get_ap_info method.

Here is method which cause error:

void WiFiManager::strangeMeasurementsTimerHandler(TimerHandle_t timer) {
    void *p0 = nullptr;
    ESP_LOGW("STACK POSITION", "p0: %p", (void *)&p0);

    wifi_ap_record_t wifiApRecord = {};

    void *p1 = nullptr;
    ESP_LOGW("STACK POSITION", "p1: %p", (void *)&p1);

    esp_err_t result = esp_wifi_sta_get_ap_info(&wifiApRecord);

    void *p2 = nullptr;
    ESP_LOGW("STACK POSITION", "p2: %p", (void *)&p2);

    ESP_LOGI("LOG_TAG", "Wi-Fi RSSI: %d", wifiApRecord.rssi);
}

I have added additional logging of current stack position because it helps to decrease time of reproduce problem. If you wish you can replace it to something like ESP_LOGW("", "Point 1"); and it will decrease time of reproduction too. Without additional code around esp_wifi_sta_get_ap_info very hard to catch error in test project.

Debug Logs

See full monitoring output here. Here is main part:

...
I (4608) LOG_TAG: Wi-Fi RSSI: -58
***ERROR*** A stack overflow in task Tmr Svc has been detected.
abort() was called at PC 0x40088451 on core 0
0x40088451: vApplicationStackOverflowHook at /Users/mdobryakov/.esp-idf/components/esp32/panic.c:125


ELF file SHA256: dcacbb36167eb951

Backtrace: 0x40087fec:0x3ffbc7a0 0x4008842c:0x3ffbc7d0 0x40088451:0x3ffbc800 0x4008a208:0x3ffbc830 0x40088f40:0x3ffbc860 0x40088ef6:0x3ffbc890 0x400ff6b3:0x00000001 |<-CORRUPTED
0x40087fec: invoke_abort at /Users/mdobryakov/.esp-idf/components/esp32/panic.c:157

0x4008842c: abort at /Users/mdobryakov/.esp-idf/components/esp32/panic.c:174

0x40088451: vApplicationStackOverflowHook at /Users/mdobryakov/.esp-idf/components/esp32/panic.c:125

0x4008a208: vTaskSwitchContext at /Users/mdobryakov/.esp-idf/components/freertos/tasks.c:2770

0x40088f40: _frxt_dispatch at /Users/mdobryakov/.esp-idf/components/freertos/portasm.S:406

0x40088ef6: _frxt_int_exit at /Users/mdobryakov/.esp-idf/components/freertos/portasm.S:206

0x400ff6b3: esp_wifi_sta_get_ap_info at ??:?


Rebooting...

...

Other items if possible

• sdkconfig file - see test project
• coredump - I suppose I can provide it if it will be required.

[zhangyanjiaoesp]

hi @maxd ,

I have tested with your example code locally, but I didn't reproduce your problem. Attachment is the full monitoring output .

1016.cap.zip

[maxd]

@zhangyanjiaoesp I see that you have other versions of wifi firmware and PHY:

I (580) wifi:wifi firmware version: 04f00f3
I (589) wifi:wifi firmware version: 3ea4c76 # on my side


I (820) phy: phy_version: 4390, 6b3c1f2, Sep 10 2020, 15:09:07, 0, 2
I (879) phy: phy_version: 4180, cb3948e, Sep 12 2019, 16:39:13, 0, 2 # on my side

Can it cause described problem on my side? How to upgrade them?

[zhangyanjiaoesp]

hi @maxd ,
you can provide your IDF commit, then I will test again.

You can update the IDF directly, then the wifi firmware and PHY will be updated.

[maxd]

@zhangyanjiaoesp This is current commit in directory with ESP-IDF (it point to v4.1 tag):

➜  .esp-idf git:(5ef1b3900) git rev-parse HEAD
5ef1b390026270503634ac3ec9f1ec2e364e23b2

So, looks like I am using latest release of ESP-IDF (v.4.2 is not released yet). Or should I use release/v4.1 branch instead of v4.1 tag?

[maxd]

@zhangyanjiaoesp FYI: I have switched to release/v4.1 branch (looks like it point to latest version of ESP-IDF because I see the save versions as in your output).

I will try to reproduce problem in this version and let you known.

[zhangyanjiaoesp]

hi @maxd ,
My first test's IDF version is I (30) boot: ESP-IDF v4.1-386-gd1c78c7 2nd stage bootloader, this is the latest IDF version for v4.1 on my side, it works well. With the version 5ef1b3900, I can reproduce your problem. That's mean this issue can be solved with the latest 4.1 version. But you can't get it now, you need to wait for the release v4.1.1.
Suggest you use release/v4.1 branch instead of v4.1 tag, because the release version is relatively stable.

[maxd]

@zhangyanjiaoesp Looks like the ESP-IDF from release/4.1 branch has the same problem but required more time to reproduce.

W (618443) STACK POSITION: p0: 0x3ffbc5b0
W (618443) STACK POSITION: p1: 0x3ffbc5b4
***ERROR*** A stack overflow in task Tmr Svc has been detected.
abort() was called at PC 0x40088a7d on core 0
0x40088a7d: vApplicationStackOverflowHook at /Users/mdobryakov/.esp-idf/components/esp32/panic.c:125


ELF file SHA256: a90fe48a7c216554

Backtrace: 0x40088608:0x3ffbbe10 0x40088a58:0x3ffbbe40 0x40088a7d:0x3ffbbe70 0x4008a8d7:0x3ffbbea0 0x4008965c:0x3ffbbed0 0x40089612:0x3ffc5f20 0x000000ba:0xb33fffff |<-CORRUPTED
0x40088608: invoke_abort at /Users/mdobryakov/.esp-idf/components/esp32/panic.c:157

0x40088a58: abort at /Users/mdobryakov/.esp-idf/components/esp32/panic.c:174

0x40088a7d: vApplicationStackOverflowHook at /Users/mdobryakov/.esp-idf/components/esp32/panic.c:125

0x4008a8d7: vTaskSwitchContext at /Users/mdobryakov/.esp-idf/components/freertos/tasks.c:2770

0x4008965c: _frxt_dispatch at /Users/mdobryakov/.esp-idf/components/freertos/portasm.S:406

0x40089612: _frxt_int_exit at /Users/mdobryakov/.esp-idf/components/freertos/portasm.S:206


Rebooting...

Here is a full log and all errors (include described above):

• Error #1
• Error #2
• Error #3

The ESP-IDF commit point to origin/release/v4.1 branch:

➜  .esp-idf git:(5d258af93) git rev-parse HEAD
5d258af93c668d748a5d190137c1bf8ae58489b4

And latest version of compiler is installed too:

➜  ~ xtensa-esp32-elf-gcc --version
xtensa-esp32-elf-gcc (crosstool-NG esp-2020r3) 8.4.0
Copyright (C) 2018 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.  There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

[maxd]

@zhangyanjiaoesp FYI: Looks like you can decrease reproduction time if replace void * pointers to small arrays:

void WiFiManager::strangeMeasurementsTimerHandler(TimerHandle_t timer) {
    char p0[64];
    ESP_LOGW("STACK POSITION", "p0: %p", (void *)&p0);

    wifi_ap_record_t wifiApRecord = {};

    char p1[64];
    ESP_LOGW("STACK POSITION", "p1: %p", (void *)&p1);

    esp_err_t result = esp_wifi_sta_get_ap_info(&wifiApRecord);

    char p2[64];
    ESP_LOGW("STACK POSITION", "p2: %p", (void *)&p2);

    ESP_LOGI("LOG_TAG", "Wi-Fi RSSI: %d", wifiApRecord.rssi);
}

In this case I can catch error after several seconds after start firmware.

[maxd]

@zhangyanjiaoesp Can you reproduce problem with this changes?

[zhangyanjiaoesp]

@maxd

You can increasing the stack size of the timer service task via CONFIG_FREERTOS_TIMER_TASK_STACK_DEPTH in the menuconfig. I set it to 4096, and test for more than 30min, there is no stack overflow.
Actually, the timer task alone doesn't use much stack, but your callbacks ( the strangeMeasurementsTimerHandler) are run in the same stack as the timer's stack, so the result is the timer task's stack will use whatever stack space your callbacks use, you can evaluate how much stack esp_wifi_sta_get_ap_info() or ESP_LOG uses, and set the CONFIG_FREERTOS_TIMER_TASK_STACK_DEPTH.

But the better way is like the following:
If you have some heavy duty work to do, you can create your own "event handler task" where you get to control the priority and stack size. This event handler task will then read events/commands from an event queue. The callbacks will only need to send an event/command to the queue, and have the bulk of the handling/logging work done by the event handler task.

[Alvin1Zhang]

@maxd Thanks for reporting, would you please help share if any updates for this issue? Thanks.

[maxd]

@zhangyanjiaoesp @Alvin1Zhang

Excuse me for delay with response. I have returned back to my ESP32 project several days ago after long break.

Yes, the provided solution with enlarged stack is working fine. Looks like default stack with size equals to 2048 is too small for WiFi sub-system and sometimes it need more stack size.

So, I close this issue. Thank you for help with this problem :)