Light sleep problems IDF 3.3.1

[allard]

I'm having problems with light sleep. My application does the following:
1. POR
2. Do some things using WiFi (https posts) , I2S (ADF framework) and SPI slave.
3. When the things are done there is a task that is activated that:
- Suspends all user threads.
- Stops and deinits the WiFi
- Suspend the tcpip thread (see https://github.com/espressif/esp-idf/issues/4628 )
- Setup GPIO4 as wakeup IO.
- Blocks for portMAX_DELAY (waiting on a semaphore)
4. Because light sleep is enabled and all tasks are suspended the ESP enters light sleep
5. When its time to do the "things" again the external MCU wakes the ESP by pulsing GPIO4. In vApplicationSleep in pm_esp32.c i've added the following code:

Code: Select all

if(done_sleep == 1)
	{
		esp_sleep_wakeup_cause_t cause = esp_sleep_get_wakeup_cause();
		//ESP_LOGD(TAG, "WakeupFrom: %i", cause);
		if(cause == ESP_SLEEP_WAKEUP_GPIO)
		{
			esp_sleep_disable_wakeup_source(ESP_SLEEP_WAKEUP_GPIO);
			sleepManager_wakeNotify();
		}
	}

This code releases the semaphore, and takes the task (that suspended the rest) from suspend state.
6. The task resumes all tasks, things repeat from point 2.

This works great for most of the time. Previously I used IDF v3.3, and it seemed that the ESP sometimes doesn't wanted to sleep. The (last) debug messages when it went OK were:

Code: Select all

D (385761) event: SYSTEM_EVENT_STA_STOP
I (385771) wifi: flush txq
I (385771) wifi: stop sw txq
D (385771) phy_init: wifi mac time delta: 167
I (385781) wifi: lmac stop hw txq
D (385781) RTC_MODULE: Wi-Fi returns adc2 lock.
I (385791) wifi: Deinit lldesc rx mblock:10
D (385791) nvs: nvs_close 13
D (385801) nvs: nvs_close 12
D (385801) sleep: RTC_PERIPH: ON, RTC_SLOW_MEM: ON, RTC_FAST_MEM: ON
I (385901) gpio: GPIO[4]| InputEn: 1| OutputEn:

And when it went wrong:

Code: Select all

D (515440) event: SYSTEM_EVENT_STA_STOP
I (515450) wifi: flush txq
I (515450) wifi: stop sw txq
D (515450) phy_init: wifi mac time delta: 162
I (515460) wifi: lmac stop hw txq
D (515460) RTC_MODULE: Wi-Fi returns adc2 lock.
I (515460) wifi: Deinit lldesc rx mblock:10
D (515470) nvs: nvs_close 19
D (515480) nvs: nvs_close 18
I (515580) gpio: GPIO[4]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0

When it went wrong there was no way to resume operation by pulsing GPIO4, and there were no further debug messages outputted, the esp just froze. Note that the interrupt and task watchdog are both enabled.

When I upgraded to IDF v3.3.1 another problem occurred:

Code: Select all

I (71292) gpio: GPIO[4]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0
abort() was called at PC 0x400867b1 on core 0
0x400867b1: lock_acquire_generic at D:/msys32/home/Allard/esp/esp-idf/components/newlib/locks.c:143


ELF file SHA256: 01bbce1eb5119bc6daca3b430b58d1dde60e78b4fbc5c8e3e92adf4f52ed14ec

Backtrace: 0x40089610:0x3ffb2820 0x4008985d:0x3ffb2840 0x400867b1:0x3ffb2860 0x400868c9:0x3ffb2890 0x40116d8a:0x3ffb28b0 0x40119ff9:0x3ffb2bc0 0
x400866dd:0x3ffb2bf0 0x400d325f:0x3ffb2c40 0x400d3728:0x3ffb2c80 0x400821ca:0x3ffb2cb0 0x400900a6:0x3ffb2ce0 0x40090df5:0x3ffb2d00
0x40089610: invoke_abort at D:/msys32/home/Allard/esp/esp-idf/components/esp32/panic.c:715

0x4008985d: abort at D:/msys32/home/Allard/esp/esp-idf/components/esp32/panic.c:715

0x400867b1: lock_acquire_generic at D:/msys32/home/Allard/esp/esp-idf/components/newlib/locks.c:143

0x400868c9: _lock_acquire_recursive at D:/msys32/home/Allard/esp/esp-idf/components/newlib/locks.c:171

0x40116d8a: _vfprintf_r at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/lib
c/stdio/vfprintf.c:860 (discriminator 2)

0x40119ff9: vprintf at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/st
dio/vprintf.c:39

0x400866dd: esp_log_write at D:/msys32/home/Allard/esp/esp-idf/components/log/log.c:121

0x400d325f: get_power_down_flags at D:/msys32/home/Allard/esp/esp-idf/components/esp32/sleep_modes.c:603

0x400d3728: esp_light_sleep_start at D:/msys32/home/Allard/esp/esp-idf/components/esp32/sleep_modes.c:603

0x400821ca: vApplicationSleep at D:/msys32/home/Allard/esp/esp-idf/components/esp32/pm_esp32.c:549

0x400900a6: prvIdleTask at D:/msys32/home/Allard/esp/esp-idf/components/freertos/tasks.c:3507

0x40090df5: vPortTaskWrapper at D:/msys32/home/Allard/esp/esp-idf/components/freertos/port.c:403

Its seems like the printf/esp_log_write causes the esp to crash. When I disable the log output in get_power_down_flags:

Code: Select all

 /*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]]);
	*/

the error disappears, but the problem from v3.3 still exists, what can be the cause? Why does the esp just freeze, even with the watchdogs enabled? What could keep the ESP from entering light sleep when there are no tasks that could run? Could the problem somehow be related to the printf problem that occurred in 3.3.1?

Another (related) question: Is it possible to debug this problem using JTAG, or does openOCD lose connection when the esp enters sleep mode?

Any help is greatly appreciated.