System crashes when we try to enter deep sleep after terminating the BLE( Properly Terminating the BLE as per docs ) (IDFGH-10369)

ABIoTsConnected commented 1 year ago

Answers checklist.

[X] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
[X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
[X] I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

5.2.0

Operating System used.

Windows

How did you build your project?

Eclipse IDE

If you are using Windows, please specify command line type.

None

Development Kit.

ESP32S3

Power Supply used.

USB

What is the expected behavior?

The system must enter the deep sleep without any crash.

We first terminate the ble using the following commands as mentioned in the docs:
esp_bluedroid_disable(); esp_bluedroid_deinit(); esp_bt_controller_disable(); esp_bt_controller_deinit();
Then after a small delay of few seconds enter in deep sleep mode.
Now the system must disable ble and enter the deep sleep.

What is the actual behavior?

The system crashes at an random place: 0x40375aca: panic_abort at C:/Users/suhas/esp/esp-idf/components/esp_system/panic.c:452

0x40381a75: esp_system_abort at C:/Users/suhas/esp/esp-idf/components/esp_system/port/esp_system_chip.c:90

0x403876ea: abort at C:/Users/suhas/esp/esp-idf/components/newlib/abort.c:38

0x4037705b: lock_acquire_generic at C:/Users/suhas/esp/esp-idf/components/newlib/locks.c:130

0x40377171: _lock_acquire_recursive at C:/Users/suhas/esp/esp-idf/components/newlib/locks.c:158

0x40377240: __retarget_lock_acquire_recursive at C:/Users/suhas/esp/esp-idf/components/newlib/locks.c:314 (discriminator 3)

0x4208dde1: __env_lock at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/envlock.c:43

0x4208e871: _findenv_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/getenv_r.c:84

0x4208e8f5: _getenv_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/getenv_r.c:125

0x4208927f: _tzset_unlocked_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s3-elf/src/newlib/newlib/libc/time/tzset_r.c:28

0x4208924d: _tzset_unlocked at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s3-elf/src/newlib/newlib/libc/time/tzset.c:115

0x4207d90c: localtime_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s3-elf/src/newlib/newlib/libc/time/lcltime_r.c:34 (discriminator 8)

0x42097908: esp_log_system_timestamp at C:/Users/suhas/esp/esp-idf/components/log/log_freertos.c:84

0x4206eb78: temperature_sensor_power_release at C:/Users/suhas/esp/esp-idf/components/esp_hw_support/sar_periph_ctrl_common.c:50

0x42008609: phy_set_tsens_power at C:/Users/suhas/esp/esp-idf/components/esp_phy/src/phy_override.c:70

0x4037cea9: phy_xpd_tsens at ??:?

0x4037ca37: misc_modules_sleep_prepare at C:/Users/suhas/esp/esp-idf/components/esp_hw_support/sleep_modes.c:484 (inlined by) esp_sleep_start at C:/Users/suhas/esp/esp-idf/components/esp_hw_support/sleep_modes.c:598

0x4037cbcf: esp_deep_sleep_start at C:/Users/suhas/esp/esp-idf/components/esp_hw_support/sleep_modes.c:830

0x4200ae2b: NM52_enter_deepsleep() at D:/abiotsWorkspace/Lumen-electronics/NM52-Device/components/NM52_Sleep/NM52_Sleep.cpp:66

0x4200a360: Configmode_Task(void*) at D:/abiotsWorkspace/Lumen-electronics/NM52-Device/main/NM52-Device_main.cpp:624

0x403842ee: vPortTaskWrapper at C:/Users/suhas/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

Steps to reproduce.

Enable the ble
After some time disable the BLE and enter deep sleep.

Debug Logs.

â†�[0;33m--- idf_monitor on \\.\COM3 115200 ---â†�[0m
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x1 (POWERON),boot:0x18 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
Octal Flash Mode Enabled
For OPI Flash, Use Default Flash Boot Mode
mode:SLOW_RD, clock div:1
load:0x3fce3820,len:0x1140
load:0x403c9700,len:0xa1c
load:0x403cc700,len:0x2ce4
entry 0x403c9888
I (266) cpu_start: Multicore app
I (267) cpu_start: Pro cpu up.
I (272) cpu_start: Starting app cpu, entry point is 0x4037557c
0x4037557c: call_start_cpu1 at C:/Users/suhas/esp/esp-idf/components/esp_system/port/cpu_start.c:154

I (0) cpu_start: App cpu up.
I (286) cpu_start: Pro cpu start user code
I (286) cpu_start: cpu freq: 160000000 Hz
I (286) cpu_start: Application information:
I (289) cpu_start: Project name:     NM52-Device
I (294) cpu_start: App version:      f03791b-dirty
I (300) cpu_start: Compile time:     Jun  9 2023 06:43:12
I (306) cpu_start: ELF file SHA256:  61a7bb1e5...
I (311) cpu_start: ESP-IDF:          v5.2-dev-974-g9f9bd8c033
I (318) cpu_start: Min chip rev:     v0.0
I (322) cpu_start: Max chip rev:     v0.99 
I (327) cpu_start: Chip rev:         v0.1
I (332) heap_init: Initializing. RAM available for dynamic allocation:
I (339) heap_init: At 3FCA2760 len 00046FB0 (283 KiB): DRAM
I (345) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (352) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (358) heap_init: At 600FE070 len 00001F90 (7 KiB): RTCRAM
I (365) spi_flash: detected chip: mxic (opi)
I (369) spi_flash: flash io: opi_str
I (374) sleep: Configure to isolate all GPIO pins in sleep state
I (381) sleep: Enable automatic switching of GPIO sleep configuration
I (388) coexist: coex firmware version: ebddf30
I (393) coexist: coexist rom version e7ae62f
I (398) app_start: Starting scheduler on CPU0
I (0) app_start: Starting scheduler on CPU1
I (00:00:00.122) main_task: Started on CPU0
I (00:00:00.132) main_task: Calling app_main()
W (00:00:00.137) NM52_WAKE: Reset Cause: Power On
W (00:00:00.142) NM52_WAKE: Wakeup Cause: Undefined
W (00:00:00.147) MAIN: Power On Reset, Initialise ULP !
I (13:59:30.011) NM52_SETTINGS: nm52_settings_nvs_init() OK
I (13:59:30.012) NM52_SETTINGS_NVS: Stats for partition:
I (13:59:30.033) NM52_SETTINGS: Device ID: NM52_05009
I (13:59:30.143) NM52_Sleep: Time to sleep is 30000 ms
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x5 (DSLEEP),boot:0x18 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
Octal Flash Mode Enabled
For OPI Flash, Use Default Flash Boot Mode
mode:SLOW_RD, clock div:1
load:0x3fce3820,len:0x1140
load:0x403c9700,len:0xa1c
load:0x403cc700,len:0x2ce4
entry 0x403c9888
I (266) cpu_start: Multicore app
I (266) cpu_start: Pro cpu up.
I (272) cpu_start: Starting app cpu, entry point is 0x4037557c
0x4037557c: call_start_cpu1 at C:/Users/suhas/esp/esp-idf/components/esp_system/port/cpu_start.c:154

I (0) cpu_start: App cpu up.
I (286) cpu_start: Pro cpu start user code
I (286) cpu_start: cpu freq: 160000000 Hz
I (286) cpu_start: Application information:
I (289) cpu_start: Project name:     NM52-Device
I (294) cpu_start: App version:      f03791b-dirty
I (300) cpu_start: Compile time:     Jun  9 2023 06:43:12
I (306) cpu_start: ELF file SHA256:  61a7bb1e5...
I (311) cpu_start: ESP-IDF:          v5.2-dev-974-g9f9bd8c033
I (318) cpu_start: Min chip rev:     v0.0
I (322) cpu_start: Max chip rev:     v0.99 
I (327) cpu_start: Chip rev:         v0.1
I (332) heap_init: Initializing. RAM available for dynamic allocation:
I (339) heap_init: At 3FCA2760 len 00046FB0 (283 KiB): DRAM
I (345) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (352) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (358) heap_init: At 600FE070 len 00001F90 (7 KiB): RTCRAM
I (365) spi_flash: detected chip: mxic (opi)
I (369) spi_flash: flash io: opi_str
I (374) sleep: Configure to isolate all GPIO pins in sleep state
I (380) sleep: Enable automatic switching of GPIO sleep configuration
I (387) coexist: coex firmware version: ebddf30
I (393) coexist: coexist rom version e7ae62f
I (398) app_start: Starting scheduler on CPU0
I (0) app_start: Starting scheduler on CPU1
I (13:59:30.564) main_task: Started on CPU0
I (13:59:30.574) main_task: Calling app_main()
W (13:59:30.579) NM52_WAKE: Reset Cause: Deep Sleep Exit
W (13:59:30.585) NM52_WAKE: Wakeup Cause: Ext RTC_CNTL
I (13:59:30.603) NM52_SETTINGS: nm52_settings_nvs_init() OK
I (13:59:30.603) NM52_SETTINGS_NVS: Stats for partition:
I (13:59:30.604) NM52_SETTINGS_NVS: Used entries: 11
I (13:59:30.610) NM52_SETTINGS_NVS: Free entries: 997
I (13:59:30.615) NM52_SETTINGS_NVS: Total entries: 1008
I (13:59:30.625) NM52_SETTINGS: Device ID: NM52_05009
I (13:59:30.716) NM52_SETTINGS: FTP file path: /
I (13:59:30.721) NM52_SETTINGS: FTP file name: default_firmware.bin
I (13:59:30.728) NM52_SETTINGS: Settings_NVS_Init: success
I (13:59:30.734) main_task: Returned from app_main()
I (13:59:30.910) MAIN: Starting the BLE_task , millis: 749
I (13:59:30.911) BLE_INIT: BT controller compile version [a186b41]
I (13:59:30.913) phy_init: phy_version 601,fe52df4,May 10 2023,17:26:54
I (13:59:30.940) BLE_INIT: Bluetooth MAC: f4:12:fa:e8:6d:06

I (14:00:30.990) DEBUG: Heap Stats, Before Cleanup:
I (14:00:30.990) DEBUG: free heap size: 198228
I (14:00:30.994) DEBUG: minimum free heap size: 198228
I (14:00:31.000) DEBUG: free internal heap size: 198228
W (67600) BT_APPL: bta_dm_disable BTA_DISABLE_DELAY set to 200 ms
I (14:00:31.709) DEBUG: Heap Stats, After Cleanup:
I (14:00:31.710) DEBUG: free heap size: 273056
I (14:00:31.710) DEBUG: minimum free heap size: 198136
I (14:00:31.715) DEBUG: free internal heap size: 273056
I (14:00:35.799) NM52_Sleep: Time to sleep is 25000 ms

abort() was called at PC 0x4037705b on core 0
0x4037705b: lock_acquire_generic at C:/Users/suhas/esp/esp-idf/components/newlib/locks.c:130

Backtrace: 0x40375aca:0x3fcab7e0 0x40381a75:0x3fcab800 0x403876ea:0x3fcab820 0x4037705b:0x3fcab890 0x40377171:0x3fcab8c0 0x40377240:0x3fcab8e0 0x4208dde1:0x3fcab910 0x4208e871:0x3fcab930 0x4208e8f5:0x3fcab960 0Backtrace: 0x40375aca:0x3fcab7e0 0x40381a75:0x3fcab800 0x403876ea:0x3fcab820 0x4037705b:0x3fcab890 0x40377171:0x3fcab8c0 0x40377240:0x3fcab8e0 0x4208dde1:0x3fcab910 0x4208e871:0x3fcab930 0x4208e8f5:0x3fcab960 0x4208927f:0x3fcab990 0x4208924d:0x3fcab9f0 0x4207d90c:0x3fcaba10 0x42097908:0x3fcaba30 0x4206eb78:0x3fcabaa0 0x42008609:0x3fcabac0 0x4037cea9:0x3fcabae0 0x4037ca37:0x3fcabb00 0x4037cbcf:0x3fcabb50 0x4200ae2b:0x3fcabb70 0x4200a360:0x3fcabba0 0x403842ee:0x3fcabbe0
0x40375aca: panic_abort at C:/Users/suhas/esp/esp-idf/components/esp_system/panic.c:452

0x40381a75: esp_system_abort at C:/Users/suhas/esp/esp-idf/components/esp_system/port/esp_system_chip.c:90

0x403876ea: abort at C:/Users/suhas/esp/esp-idf/components/newlib/abort.c:38

0x4037705b: lock_acquire_generic at C:/Users/suhas/esp/esp-idf/components/newlib/locks.c:130

0x40377171: _lock_acquire_recursive at C:/Users/suhas/esp/esp-idf/components/newlib/locks.c:158

0x40377240: __retarget_lock_acquire_recursive at C:/Users/suhas/esp/esp-idf/components/newlib/locks.c:314 (discriminator 3)

0x4208dde1: __env_lock at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/envlock.c:43

0x4208e871: _findenv_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/getenv_r.c:84

0x4208e8f5: _getenv_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/getenv_r.c:125

0x4208927f: _tzset_unlocked_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s3-elf/src/newlib/newlib/libc/time/tzset_r.c:28

0x4208924d: _tzset_unlocked at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s3-elf/src/newlib/newlib/libc/time/tzset.c:115

0x4207d90c: localtime_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s3-elf/src/newlib/newlib/libc/time/lcltime_r.c:34 (discriminator 8)

0x42097908: esp_log_system_timestamp at C:/Users/suhas/esp/esp-idf/components/log/log_freertos.c:84

0x4206eb78: temperature_sensor_power_release at C:/Users/suhas/esp/esp-idf/components/esp_hw_support/sar_periph_ctrl_common.c:50

0x42008609: phy_set_tsens_power at C:/Users/suhas/esp/esp-idf/components/esp_phy/src/phy_override.c:70

0x4037cea9: phy_xpd_tsens at ??:?

0x4037ca37: misc_modules_sleep_prepare at C:/Users/suhas/esp/esp-idf/components/esp_hw_support/sleep_modes.c:484
 (inlined by) esp_sleep_start at C:/Users/suhas/esp/esp-idf/components/esp_hw_support/sleep_modes.c:598

0x4037cbcf: esp_deep_sleep_start at C:/Users/suhas/esp/esp-idf/components/esp_hw_support/sleep_modes.c:830

0x4200ae2b: NM52_enter_deepsleep() at D:/abiotsWorkspace/Lumen-electronics/NM52-Device/components/NM52_Sleep/NM52_Sleep.cpp:66

0x4200a360: Configmode_Task(void*) at D:/abiotsWorkspace/Lumen-electronics/NM52-Device/main/NM52-Device_main.cpp:624

0x403842ee: vPortTaskWrapper at C:/Users/suhas/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

ELF file SHA256: 61a7bb1e5

Rebooting...
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x3 (RTC_SW_SYS_RST),boot:0x18 (SPI_FAST_FLASH_BOOT)
Saved PC:0x4037594c
0x4037594c: esp_restart_noos_dig at C:/Users/suhas/esp/esp-idf/components/esp_system/port/esp_system_chip.c:63 (discriminator 1)

SPIWP:0xee
Octal Flash Mode Enabled
For OPI Flash, Use Default Flash Boot Mode
mode:SLOW_RD, clock div:1
load:0x3fce3820,len:0x1140
load:0x403c9700,len:0xa1c
load:0x403cc700,len:0x2ce4
entry 0x403c9888
I (271) cpu_start: Multicore app
I (271) cpu_start: Pro cpu up.
I (271) cpu_start: Starting app cpu, entry point is 0x4037557c
0x4037557c: call_start_cpu1 at C:/Users/suhas/esp/esp-idf/components/esp_system/port/cpu_start.c:154

I (0) cpu_start: App cpu up.
I (289) cpu_start: Pro cpu start user code
I (289) cpu_start: cpu freq: 160000000 Hz
I (289) cpu_start: Application information:
I (292) cpu_start: Project name:     NM52-Device
I (297) cpu_start: App version:      f03791b-dirty
I (303) cpu_start: Compile time:     Jun  9 2023 06:43:12
I (309) cpu_start: ELF file SHA256:  61a7bb1e5...
I (314) cpu_start: ESP-IDF:          v5.2-dev-974-g9f9bd8c033
I (321) cpu_start: Min chip rev:     v0.0
I (325) cpu_start: Max chip rev:     v0.99 
I (330) cpu_start: Chip rev:         v0.1
I (335) heap_init: Initializing. RAM available for dynamic allocation:
I (342) heap_init: At 3FCA2760 len 00046FB0 (283 KiB): DRAM
I (348) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (355) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (361) heap_init: At 600FE070 len 00001F90 (7 KiB): RTCRAM
I (368) spi_flash: detected chip: mxic (opi)
I (372) spi_flash: flash io: opi_str
I (377) sleep: Configure to isolate all GPIO pins in sleep state
I (383) sleep: Enable automatic switching of GPIO sleep configuration
I (390) coexist: coex firmware version: ebddf30
I (396) coexist: coexist rom version e7ae62f
I (401) app_start: Starting scheduler on CPU0
I (0) app_start: Starting scheduler on CPU1
I (14:00:36.314) main_task: Started on CPU0
I (14:00:36.324) main_task: Calling app_main()
W (14:00:36.328) NM52_WAKE: Reset Cause: Exception/Panic
W (14:00:36.334) NM52_WAKE: Wakeup Cause: Undefined
W (14:00:36.340) MAIN: Unknown Wakep Source!
I (13:59:30.011) NM52_SETTINGS: nm52_settings_nvs_init() OK
I (13:59:30.012) NM52_SETTINGS_NVS: Stats for partition:

More Information.

No response

patrickmagee commented 1 year ago

I am also working on this project. To add some info:

Crash does not happen on light sleep, or without sleep.
If we do not call esp_bluedroid_disable(); esp_bluedroid_deinit(); esp_bt_controller_disable(); esp_bt_controller_deinit(); then we can enter and wake deep sleep without any issue. However the device will crash if we attempt to enable BT again, even after deep sleep.

KaeLL commented 1 year ago

I think #10649 was supposed to have fixed this error.

ABIoTsConnected commented 1 year ago

Hi KaeLL, i tried this with master branch and with latest commit. The issue still exists.

ABIoTsConnected commented 1 year ago

This was tested with master branch where the head was commit 9f9bd8c0331a584b3933d9ba215f013ac1889c84.

igrr commented 1 year ago

I think https://github.com/espressif/esp-idf/pull/10649 was supposed to have fixed this error.

While the backtrace does look similar, I think the root cause is different in this case. This is because an RTOS mutex is being acquired inside a critical section, due to an ESP_LOGE call, which in turn is due to a recent regression which we will soon fix!

ABIoTsConnected commented 1 year ago

Thank you @igrr.

patrickmagee commented 1 year ago

Is it known in which commit the regression happened? Is there a 5.2 commit that does not have this issue?

ESP-Marius commented 1 year ago

Is it known in which commit the regression happened?

Looks like it might have been e304db558b8d20bc20150dede2f035d12e39e2dd

espressif / esp-idf