ESP32-S2 abort() in locks.c with no reference to my code in backtrace [WIFI-3462][WIFI-3463]

[william.ferguson.au]

On an ESP32-S2 using ESP-IDF v4.3-beta1-25-g603db1828

I'm getting a deterministic abort about 1400ms after boot.
The backtrace doesn't reference any of my code.

Code: Select all

abort() was called at PC 0x40026786 on core 0
0x40026786: lock_acquire_generic at E:/Dev/Espressif/esp-idf/components/newlib/locks.c:138


Backtrace:0x4002d14b:0x3ffdd350 0x4002d90d:0x3ffdd370 0x40034462:0x3ffdd390 0x40026786:0x3ffdd400 0x400268d1:0x3ffdd430 0x4010bd0a:0x3ffdd450 0x4010ed69:0x3ffdd760 0x40119849:0x3ffdd790 0x40032ee5:
0x3ffdd7c0 0x400ff285:0x3ffdd810 0x400ff2af:0x3ffdd890 0x40029ae7:0x3ffdd8e0 0x40029bc1:0x3ffdd940 0x4002b62c:0x3ffdd960 0x400ec0eb:0x3ffdd980 0x40035e41:0x3ffdd9c0 0x40030651:0x3ffdd9f0
0x4002d14b: panic_abort at E:/Dev/Espressif/esp-idf/components/esp_system/panic.c:356

0x4002d90d: esp_system_abort at E:/Dev/Espressif/esp-idf/components/esp_system/system_api.c:112

0x40034462: abort at E:/Dev/Espressif/esp-idf/components/newlib/abort.c:46

0x40026786: lock_acquire_generic at E:/Dev/Espressif/esp-idf/components/newlib/locks.c:138

0x400268d1: _lock_acquire_recursive at E:/Dev/Espressif/esp-idf/components/newlib/locks.c:166

0x4010bd0a: _vfprintf_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s2-elf/src/newlib/newlib/libc/stdio/vfprintf.c:853 (discriminator 2)

0x4010ed69: vprintf at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s2-elf/src/newlib/newlib/libc/stdio/vprintf.c:34 (discriminator 5)

0x40119849: esp_log_writev at E:/Dev/Espressif/esp-idf/components/log/log.c:189

0x40032ee5: esp_log_write at E:/Dev/Espressif/esp-idf/components/log/log.c:199

0x400ff285: lib_printf at E:/Dev/Espressif/esp-idf/components/esp_wifi/src/lib_printf.c:47 (discriminator 13)

0x400ff2af: phy_printf at E:/Dev/Espressif/esp-idf/components/esp_wifi/src/lib_printf.c:57

0x40029ae7: pll_vol_cal at ??:?

0x40029bc1: wifi_track_pll_cap at ??:?

0x4002b62c: tx_pwctrl_background at ??:?

0x400ec0eb: lmacProcessTxComplete at ??:?

0x40035e41: ppTask at ??:?

0x40030651: vPortTaskWrapper at E:/Dev/Espressif/esp-idf/components/freertos/port/xtensa/port.c:168

Looking for suggestions on how to work out what is going on.

[william.ferguson.au]

And where do I find these 2 files, since those paths don't refer to anything on my Windows machine.

Code: Select all

0x4010bd0a: _vfprintf_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s2-elf/src/newlib/newlib/libc/stdio/vfprintf.c:853 (discriminator 2)

0x4010ed69: vprintf at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s2-elf/src/newlib/newlib/libc/stdio/vprintf.c:34 (discriminator 5)

[ESP-Marius]

Looks like the wifi code is calling a log function (from phy_printf) in a critical section, causing the crash.

I'll talk to our wifi team and get them to fix this, if this is the case.

Meanwhile you can try replacing ESP_LOGI with ESP_EARLY_LOGI in lib_printf (components/esp_wifi/src/lib_printf.c). This should fix it if the error is what I suspect it is.

[ESP_Sprite]

Also, that backtrace goes trough somewhere in Newlib; as it's tightly bound to the ROM that library is distributed as a binary. (You can get the source if you want, though in this case it will likely not help you.)

[william.ferguson.au]

Thanks ESP-Marius. Changing ESP_LOGI to ESP_EARLY_LOGI in lib_printf did indeed stop the aborts.

But there seems to be some other problem with the wifi module.
In an earlier version of 4.3 it worked fine, but now it takes 10 seconds after boot before the wifi manages to start up then it looks like it is restarting the wifi and then it cannot connect to the wifi AP, even though it is there.

Very frustrating.

Code: Select all

 (10299) phy: pll_cap_ext 10
I (10309) phy: pll_cap_ext 10
I (10309) phy: pll_cap_ext 10
I (10309) phy: pll_cap_ext 10
I (10309) wifi:ap_probe_send over, resett wifi status to disassoc
I (10319) wifi:state: run -> init (c800)
I (10319) wifi:pm stop, total sleep time: 0 us / 8476767 us

I (10319) wifi:new:<9,0>, old:<9,0>, ap:<255,255>, sta:<9,0>, prof:1
I (10329) phy: pll_cap_ext 10
I (1032I (10339) phy: pll_cap_ext 10
9) wt_wifi: Wifi DISCONNECTED fI (10339) phy: pll_cap_ext 10
rom Access Point
I (I (10349) phy: pll_cap_ext 10
10349) wt_wifi: Restarting wifi I (10349) phy: pll_cap_ext 10
connection
I (10359) phy: pll_cap_ext 10
I (10369) phy: pll_cap_ext 10
I (10369) phy: pll_cap_ext 10
I (10369) phy: pll_cap_ext 10
I (10379) phy: pll_cap_ext 10
I (10379) phy: pll_cap_ext 10
I (10379) phy: pll_cap_ext 10
I (10389) phy: pll_cap_ext 10
I (10479) phy: pll_cap_ext 10
I (10609) phy: pll_cap_ext 10
I (10609) phy: pll_cap_ext 10
I (10729) phy: pll_cap_ext 10
I (10859) phy: pll_cap_ext 10
I (10979) phy: pll_cap_ext 10
I (11099) phy: pll_cap_ext 10
I (11229) phy: pll_cap_ext 10
I (11229) phy: pll_cap_ext 10
I (11349) phy: pll_cap_ext 10
I (11479) phy: pll_cap_ext 10
I (11599) phy: pll_cap_ext 10
I (11729) phy: pll_cap_ext 10
W (11889) wifi:Haven't to connect to a suitable AP now!
I (12089) phy: pll_cap_ext 10
I (12449) phy: pll_cap_ext 10
I (12449) wt_wifi: Wifi DISCONNECTED from Access Point
I (12449) wt_wifi: Restarting wifi connection
I (12579) phy: pll_cap_ext 10
I

Can you point me to an issue I can track for the first.
And any ideas on the 2nd?

[william.ferguson.au]

Also logging

Code: Select all

I (1915) phy: pll_cap_ext 10

at INFO seems a little heavy handed considering how often it is printed.

[ESP-Marius]

I dont know much about the wifi lib, so afraid I cant give any advice on the connection issue, but if it works fine when you roll back to an earlier v4.3 version then it definitely sounds like a regression. Note that 4.3 is still in beta, so we are still running internal tests and deploying fixes.

I've created two internal issues for you: WIFI-3462 for the log problem and WIFI-3463 for the connection problem.

[ESP_Alvin]

Moderator's note: edit the topic title for issue tracking, thanks for reporting.

[WiFive]

https://github.com/espressif/esp-idf/issues/6269

[william.ferguson.au]

Thanks WiFive, that's looks like the 2nd issue.