Application hangs during boot in function esp_intr_alloc_intrstatus

[Laurent Louf]

Hello,

I have a weird random bug with my ESP32. Some time (this time after flashing, but I think it also happens on normal reboots), the ESP32 will just perform the first steps of the boot and hang and never go any further. This isn't an UART configuration problem since all messages that I get are those after the initial messages ((re)boot reason and some other stuff). In such a case, this is the log I get :

--- Terminal on /dev/ttyACM0 - 115200,8,N,1 ---
I (29) boot: ESP-IDF v3.1.2-dirty 2nd stage bootloader
I (29) boot: compile time 18:14:30
I (29) boot: Enabling RNG early entropy source...
I (30) boot: SPI Speed : 40MHz
I (33) boot: SPI Mode : DIO
I (36) boot: SPI Flash Size : 8MB
I (39) boot: Partition Table:
I (42) boot: ## Label Usage Type ST Offset Length
I (48) boot: 0 nvs WiFi data 01 02 00009000 00003000
I (55) boot: 1 phy_init RF data 01 01 0000f000 00001000
I (61) boot: 2 otadata_esp OTA data 01 00 00010000 00002000
I (68) boot: 3 otametadata_esp WiFi data 01 02 00012000 00004000
I (74) boot: 4 security WiFi data 01 02 00016000 00008000
I (81) boot: 5 ota_esp_0 OTA app 00 10 00020000 001c0000
I (87) boot: 6 ota_esp_1 OTA app 00 11 001e0000 001c0000
I (94) boot: 7 ota_stm_0 WiFi data 01 02 003a0000 00041000
I (100) boot: End of partition table
I (104) boot: No factory image, trying OTA 0
I (108) esp_image: segment 0: paddr=0x00020020 vaddr=0x3f400020 size=0x5a274 (369268) map
I (244) esp_image: segment 1: paddr=0x0007a29c vaddr=0x3ffc0000 size=0x03664 ( 13924) load
I (249) esp_image: segment 2: paddr=0x0007d908 vaddr=0x3ffc3664 size=0x00000 ( 0) load
I (249) esp_image: segment 3: paddr=0x0007d910 vaddr=0x40080000 size=0x00400 ( 1024) load
I (257) esp_image: segment 4: paddr=0x0007dd18 vaddr=0x40080400 size=0x022f8 ( 8952) load
I (268) esp_image: segment 5: paddr=0x00080018 vaddr=0x400d0018 size=0x114808 (1132552) map
I (665) esp_image: segment 6: paddr=0x00194828 vaddr=0x400826f8 size=0x1634c ( 90956) load
I (701) esp_image: segment 7: paddr=0x001aab7c vaddr=0x400c0000 size=0x00000 ( 0) load
I (701) esp_image: segment 8: paddr=0x001aab84 vaddr=0x50000000 size=0x00000 ( 0) load
I (720) boot: Loaded app from partition at offset 0x20000
I (720) boot: Disabling RNG early entropy source...
I (720) cpu_start: Pro cpu up.
I (721) cpu_start: Starting app cpu, entry point is 0x40081394
I (0) cpu_start: App cpu up.
I (730) heap_init: Initializing. RAM available for dynamic allocation:
D (735) heap_init: New heap initialised at 0x3ffaff10
I (740) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
D (745) heap_init: New heap initialised at 0x3ffd1c28
I (750) heap_init: At 3FFD1C28 len 0000E3D8 (56 KiB): DRAM
I (755) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (761) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
D (766) heap_init: New heap initialised at 0x40098a44
I (771) heap_init: At 40098A44 len 000075BC (29 KiB): IRAM
I (776) cpu_start: Pro cpu start user code
D (787) clk: RTC_SLOW_CLK calibration value: 3319514
V (125) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (125) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (130) intr_alloc: Connected src 46 to int 2 (cpu 0)
V (135) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (140) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xC0E
D (148) intr_alloc: Connected src 57 to int 3 (cpu 0)
V (153) esp_dbg_stubs: esp_dbg_stubs_init stubs 3ffc4988
D (159) stack_chk: Intialize random stack guard
V (162) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (168) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (176) intr_alloc: Connected src 24 to int 9 (cpu 0)
I (181) esp_core_dump: Init core dump to UART
I (185) cpu_start: Starting scheduler on PRO CPU.
V (0) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (0) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E
D (10) intr_alloc: Connected src 25 to int 2 (cpu 1)
I (10) cpu_start: Starting scheduler on APP CPU.
D (232) heap_init: New heap initialised at 0x3ffe0440
D (232) heap_init: New heap initialised at 0x3ffe4350
D (242) nvs: nvs_flash_init_custom partition=nvs start=9 count=3
V (262) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (262) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E

Meanwhile, when everything goes fine, I get the following :

--- Terminal on /dev/ttyACM0 - 115200,8,N,1 ---

Br�I (29) boot: ESP-IDF v3.1.2-dirty 2nd stage bootloader
I (29) boot: compile time 18:14:30
I (29) boot: Enabling RNG early entropy source...
I (30) boot: SPI Speed : 40MHz
I (33) boot: SPI Mode : DIO
I (36) boot: SPI Flash Size : 8MB
I (39) boot: Partition Table:
I (42) boot: ## Label Usage Type ST Offset Length
I (48) boot: 0 nvs WiFi data 01 02 00009000 00003000
I (55) boot: 1 phy_init RF data 01 01 0000f000 00001000
I (61) boot: 2 otadata_esp OTA data 01 00 00010000 00002000
I (68) boot: 3 otametadata_esp WiFi data 01 02 00012000 00004000
I (74) boot: 4 security WiFi data 01 02 00016000 00008000
I (81) boot: 5 ota_esp_0 OTA app 00 10 00020000 001c0000
I (87) boot: 6 ota_esp_1 OTA app 00 11 001e0000 001c0000
I (94) boot: 7 ota_stm_0 WiFi data 01 02 003a0000 00041000
I (100) boot: End of partition table
I (104) boot: No factory image, trying OTA 0
I (108) esp_image: segment 0: paddr=0x00020020 vaddr=0x3f400020 size=0x5a274 (369268) map
I (244) esp_image: segment 1: paddr=0x0007a29c vaddr=0x3ffc0000 size=0x03664 ( 13924) load
I (249) esp_image: segment 2: paddr=0x0007d908 vaddr=0x3ffc3664 size=0x00000 ( 0) load
I (249) esp_image: segment 3: paddr=0x0007d910 vaddr=0x40080000 size=0x00400 ( 1024) load
I (257) esp_image: segment 4: paddr=0x0007dd18 vaddr=0x40080400 size=0x022f8 ( 8952) load
I (268) esp_image: segment 5: paddr=0x00080018 vaddr=0x400d0018 size=0x114808 (1132552) map
I (665) esp_image: segment 6: paddr=0x00194828 vaddr=0x400826f8 size=0x1634c ( 90956) load
I (701) esp_image: segment 7: paddr=0x001aab7c vaddr=0x400c0000 size=0x00000 ( 0) load
I (701) esp_image: segment 8: paddr=0x001aab84 vaddr=0x50000000 size=0x00000 ( 0) load
I (720) boot: Loaded app from partition at offset 0x20000
I (720) boot: Disabling RNG early entropy source...
I (720) cpu_start: Pro cpu up.
I (721) cpu_start: Starting app cpu, entry point is 0x40081394
I (0) cpu_start: App cpu up.
I (730) heap_init: Initializing. RAM available for dynamic allocation:
D (735) heap_init: New heap initialised at 0x3ffaff10
I (740) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
D (745) heap_init: New heap initialised at 0x3ffd1c28
I (750) heap_init: At 3FFD1C28 len 0000E3D8 (56 KiB): DRAM
I (755) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (761) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
D (766) heap_init: New heap initialised at 0x40098a44
I (771) heap_init: At 40098A44 len 000075BC (29 KiB): IRAM
I (776) cpu_start: Pro cpu start user code
D (787) clk: RTC_SLOW_CLK calibration value: 3302758
V (125) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (125) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (130) intr_alloc: Connected src 46 to int 2 (cpu 0)
V (135) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (140) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xC0E
D (148) intr_alloc: Connected src 57 to int 3 (cpu 0)
V (153) esp_dbg_stubs: esp_dbg_stubs_init stubs 3ffc4988
D (159) stack_chk: Intialize random stack guard
V (162) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (168) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (176) intr_alloc: Connected src 24 to int 9 (cpu 0)
I (181) esp_core_dump: Init core dump to UART
I (185) cpu_start: Starting scheduler on PRO CPU.
V (0) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (0) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E
D (10) intr_alloc: Connected src 25 to int 2 (cpu 1)
I (10) cpu_start: Starting scheduler on APP CPU.
D (232) heap_init: New heap initialised at 0x3ffe0440
D (232) heap_init: New heap initialised at 0x3ffe4350
D (242) nvs: nvs_flash_init_custom partition=nvs start=9 count=3
V (262) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (262) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E
D (262) intr_alloc: Connected src 34 to int 3 (cpu 1)
I (332) gpio: GPIO[5]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (332) gpio: GPIO[18]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (332) gpio: GPIO[19]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (342) gpio: GPIO[23]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (352) gpio: GPIO[21]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (362) Main: Setup done in 160ms
....

I have used meld to try to spot some difference between the two logs, but the only one is the RTC_SLOW_CLK calibration value which is 3319514 in the hanging case, and 3302758 in the normal case. The ESP-IDF version I'm using is the following :

commit ed1304146bb379c0a8dcf141710b42364feb4734 (HEAD, tag: v3.1.2)
Merge: a18f92b09 1937bc2bd
Author: Angus Gratton <angus@espressif.com>
Date: Wed Jan 2 20:42:45 2019 +0800

Merge branch 'bugfix/timer_delete_dispatch_race_v3.1' into 'release/v3.1'

esp_timer: do not allow deleting timers while callbacks are dispatched (backport v3.1)

See merge request idf/esp-idf!3993

So it seems like the function esp_intr_alloc_intrstatus fails at some point, but the errors it can return are basically ESP_ERR_NO_MEM and ESP_ERR_NOT_FOUND. The no memory error seems pretty unlikely because with exactly the same memory usage (from the logs), the app can start without any issue most of the time. Looking at the second error description No free interrupt found with the specified flags it also seems quite unlikely since it happens before executing any user code.

Is this a known issue ? Any ideas ?