Abort on automatic light sleep at high log levels (IDFGH-3075)

[boarchuz]

With Power Management configured to enable automatic light sleep, and Default Log Verbosity >= Debug, the ESP32 aborts and restarts:

abort() was called at PC 0x40082bc6 on core 0
0x40082bc6: lock_acquire_generic at /home/boarchuz/Espressif/IDF/master/esp-idf/components/newlib/locks.c:142

Following the log output (included below) shows that ESP_LOGD is being called here

esp-idf/components/esp32/sleep_modes.c

Lines 677 to 680 in 2e14149

	ESP_LOGD(TAG, "RTC_PERIPH: %s, RTC_SLOW_MEM: %s, RTC_FAST_MEM: %s",
	option_str[s_config.pd_options[ESP_PD_DOMAIN_RTC_PERIPH]],
	option_str[s_config.pd_options[ESP_PD_DOMAIN_RTC_SLOW_MEM]],
	option_str[s_config.pd_options[ESP_PD_DOMAIN_RTC_FAST_MEM]]);

from within a critical section in vApplicationSleep

esp-idf/components/esp32/pm_esp32.c

Lines 514 to 516 in 2e14149

	void IRAM_ATTR vApplicationSleep( TickType_t xExpectedIdleTime )
	{
	portENTER_CRITICAL(&s_switch_lock);

IDF: v4.2-dev-701-g0ae960f2f

Full Log

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0030,len:4
load:0x3fff0034,len:6128
ho 0 tail 12 room 4
load:0x40078000,len:15444
load:0x40080400,len:4656
0x40080400: _init at ??:?

entry 0x400806a4
I (85) cpu_start: Pro cpu up.
I (85) cpu_start: Application information:
I (85) cpu_start: Project name: template-app
I (87) cpu_start: App version: 1858107-dirty
I (93) cpu_start: Compile time: Apr 11 2020 05:27:54
I (99) cpu_start: ELF file SHA256: 3d231a41de0f627d...
I (105) cpu_start: ESP-IDF: v4.2-dev-701-g0ae960f2f
I (111) cpu_start: Starting app cpu, entry point is 0x4008114c
0x4008114c: call_start_cpu1 at /home/boarchuz/Espressif/IDF/master/esp-idf/components/esp32/cpu_start.c:273

I (0) cpu_start: App cpu up.
D (121) memory_layout: Checking 7 reserved memory ranges:
D (126) memory_layout: Reserved memory range 0x3ffae000 - 0x3ffae6e0
D (133) memory_layout: Reserved memory range 0x3ffb0000 - 0x3ffb2aa0
D (139) memory_layout: Reserved memory range 0x3ffe0000 - 0x3ffe0440
D (146) memory_layout: Reserved memory range 0x3ffe3f20 - 0x3ffe4350
D (152) memory_layout: Reserved memory range 0x40070000 - 0x40078000
D (159) memory_layout: Reserved memory range 0x40078000 - 0x40080000
0x40080000: _WindowOverflow4 at /home/boarchuz/Espressif/IDF/master/esp-idf/components/freertos/xtensa/xtensa_vectors.S:1817

D (165) memory_layout: Reserved memory range 0x40080000 - 0x4008ab18
0x40080000: _WindowOverflow4 at /home/boarchuz/Espressif/IDF/master/esp-idf/components/freertos/xtensa/xtensa_vectors.S:1817

D (171) memory_layout: Building list of available memory regions:
D (178) memory_layout: Available memory region 0x3ffae6e0 - 0x3ffb0000
D (184) memory_layout: Available memory region 0x3ffb2aa0 - 0x3ffb8000
D (191) memory_layout: Available memory region 0x3ffb8000 - 0x3ffc0000
D (197) memory_layout: Available memory region 0x3ffc0000 - 0x3ffc2000
D (204) memory_layout: Available memory region 0x3ffc2000 - 0x3ffc4000
D (211) memory_layout: Available memory region 0x3ffc4000 - 0x3ffc6000
D (217) memory_layout: Available memory region 0x3ffc6000 - 0x3ffc8000
D (224) memory_layout: Available memory region 0x3ffc8000 - 0x3ffca000
D (230) memory_layout: Available memory region 0x3ffca000 - 0x3ffcc000
D (237) memory_layout: Available memory region 0x3ffcc000 - 0x3ffce000
D (244) memory_layout: Available memory region 0x3ffce000 - 0x3ffd0000
D (250) memory_layout: Available memory region 0x3ffd0000 - 0x3ffd2000
D (257) memory_layout: Available memory region 0x3ffd2000 - 0x3ffd4000
D (263) memory_layout: Available memory region 0x3ffd4000 - 0x3ffd6000
D (270) memory_layout: Available memory region 0x3ffd6000 - 0x3ffd8000
D (277) memory_layout: Available memory region 0x3ffd8000 - 0x3ffda000
D (283) memory_layout: Available memory region 0x3ffda000 - 0x3ffdc000
D (290) memory_layout: Available memory region 0x3ffdc000 - 0x3ffde000
D (296) memory_layout: Available memory region 0x3ffde000 - 0x3ffe0000
D (303) memory_layout: Available memory region 0x3ffe0440 - 0x3ffe3f20
D (310) memory_layout: Available memory region 0x3ffe4350 - 0x3ffe8000
D (316) memory_layout: Available memory region 0x3ffe8000 - 0x3fff0000
D (323) memory_layout: Available memory region 0x3fff0000 - 0x3fff8000
D (329) memory_layout: Available memory region 0x3fff8000 - 0x3fffc000
D (336) memory_layout: Available memory region 0x3fffc000 - 0x40000000
D (343) memory_layout: Available memory region 0x4008ab18 - 0x4008c000
D (349) memory_layout: Available memory region 0x4008c000 - 0x4008e000
D (356) memory_layout: Available memory region 0x4008e000 - 0x40090000
D (362) memory_layout: Available memory region 0x40090000 - 0x40092000
D (369) memory_layout: Available memory region 0x40092000 - 0x40094000
D (375) memory_layout: Available memory region 0x40094000 - 0x40096000
D (382) memory_layout: Available memory region 0x40096000 - 0x40098000
D (389) memory_layout: Available memory region 0x40098000 - 0x4009a000
D (395) memory_layout: Available memory region 0x4009a000 - 0x4009c000
D (402) memory_layout: Available memory region 0x4009c000 - 0x4009e000
D (408) memory_layout: Available memory region 0x4009e000 - 0x400a0000
I (415) heap_init: Initializing. RAM available for dynamic allocation:
D (422) heap_init: New heap initialised at 0x3ffae6e0
I (427) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
D (433) heap_init: New heap initialised at 0x3ffb2aa0
I (439) heap_init: At 3FFB2AA0 len 0002D560 (181 KiB): DRAM
I (445) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (451) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
D (458) heap_init: New heap initialised at 0x4008ab18
I (463) heap_init: At 4008AB18 len 000154E8 (85 KiB): IRAM
I (469) cpu_start: Pro cpu start user code
D (481) clk: RTC_SLOW_CLK calibration value: 3397926
D (490) intr_alloc: Connected src 46 to int 2 (cpu 0)
D (491) intr_alloc: Connected src 17 to int 3 (cpu 0)
D (491) intr_alloc: Connected src 24 to int 9 (cpu 0)
D (496) FLASH_HAL: extra_dummy: 2
D (500) spi_flash: trying chip: issi
D (503) spi_flash: trying chip: gd
D (507) spi_flash: trying chip: generic
I (511) spi_flash: detected chip: generic
I (515) spi_flash: flash io: qio
D (519) chip_generic: set_io_mode: status before 0x200
I (524) cpu_start: Starting scheduler on PRO CPU.
D (0) intr_alloc: Connected src 25 to int 2 (cpu 1)
I (0) cpu_start: Starting scheduler on APP CPU.
D (540) heap_init: New heap initialised at 0x3ffe0440
D (550) heap_init: New heap initialised at 0x3ffe4350
D (560) intr_alloc: Connected src 16 to int 12 (cpu 0)
I (560) pm_esp32: Frequency switching config: CPU_MAX: 240, APB_MAX: 240, APB_MIN: 160, Light sleep: ENABLED
abort() was called at PC 0x40082bc6 on core 0
0x40082bc6: lock_acquire_generic at /home/boarchuz/Espressif/IDF/master/esp-idf/components/newlib/locks.c:142

ELF file SHA256: 3d231a41de0f627de9a8ac49a3982c7e2b7b047388c2499a284dcfb549383129

Backtrace: 0x40084f9d:0x3ffb55e0 0x4008532d:0x3ffb5600 0x40082bc6:0x3ffb5620 0x40082ce9:0x3ffb5650 0x400dc0b2:0x3ffb5670 0x400df0c1:0x3ffb5980 0x400e3145:0x3ffb59b0 0x400844fd:0x3ffb59e0 0x400d178d:0x3ffb5a30 0x400d1a70:0x3ffb5a70 0x40081d28:0x3ffb5aa0 0x400893b2:0x3ffb5ac0 0x4008807d:0x3ffb5ae0
0x40084f9d: invoke_abort at /home/boarchuz/Espressif/IDF/master/esp-idf/components/esp32/panic.c:157

0x4008532d: abort at /home/boarchuz/Espressif/IDF/master/esp-idf/components/esp32/panic.c:174

0x40082bc6: lock_acquire_generic at /home/boarchuz/Espressif/IDF/master/esp-idf/components/newlib/locks.c:142

0x40082ce9: _lock_acquire_recursive at /home/boarchuz/Espressif/IDF/master/esp-idf/components/newlib/locks.c:170

0x400dc0b2: _vfprintf_r at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vfprintf.c:853 (discriminator 2)

0x400df0c1: vprintf at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vprintf.c:34

0x400e3145: esp_log_writev at /home/boarchuz/Espressif/IDF/master/esp-idf/components/log/log.c:189

0x400844fd: esp_log_write at /home/boarchuz/Espressif/IDF/master/esp-idf/components/log/log.c:199

0x400d178d: get_power_down_flags at /home/boarchuz/Espressif/IDF/master/esp-idf/components/esp32/sleep_modes.c:676

0x400d1a70: esp_light_sleep_start at /home/boarchuz/Espressif/IDF/master/esp-idf/components/esp32/sleep_modes.c:294

0x40081d28: vApplicationSleep at /home/boarchuz/Espressif/IDF/master/esp-idf/components/esp32/pm_esp32.c:534

0x400893b2: prvIdleTask at /home/boarchuz/Espressif/IDF/master/esp-idf/components/freertos/tasks.c:3424

0x4008807d: vPortTaskWrapper at /home/boarchuz/Espressif/IDF/master/esp-idf/components/freertos/xtensa/port.c:143

Rebooting...

[Alvin1Zhang]

@boarchuz Thanks for reporting, we will look into.

[robert-alfaro]

same result in release/v4.0 branch. I am using Compiler option Release configuration and then light sleep broke because of the ESP_LOGD line in sleep_modes.c

[mikisch81]

Also happens in the v4.1-beta1 release. I can reproduce it easily with the light_sleep example when default log verbosity is Debug.

[cristovao-trevisan]

+1, same on v4.2-dev

[AxelLin]

@o-marshmallow
#7942

This is fixed in v4.3 e615a95, v4.4 2ca86a3 and master c676b83 .
But v4.1 and v4.2 still need fix. (v4.0 is EOL).

[esp-lis]

But v4.1 and v4.2 still need fix. (v4.0 is EOL).

The fixes for v4.2 and v4.1 refer to the link below:
v4.2: 84effb1
v4.1: 73f56bb

[o-marshmallow]

Thanks @AxelLin and @esp-lis, closing this issue