OTA Guru Meditation WDT Triggered

[bretie]

This issue happens periodically and is not easily reproducible. At the end of OTA the image is verified and then seems to be locking up trigger the WDT. Any hints or help is greatly appreciated, thank you.

[Codebox]
I (61310) ota: HTTP_EVENT_ON_DATA (181)
I (61310) esp_image: segment 0: paddr=002c0020 vaddr=3f400020 size=24b6ch (150380) map
I (61354) esp_image: segment 1: paddr=002e4b94 vaddr=3ffbdb60 size=06344h ( 25412)
I (61362) esp_image: segment 2: paddr=002eaee0 vaddr=40080000 size=05138h ( 20792)
I (61370) esp_image: segment 3: paddr=002f0020 vaddr=400d0020 size=c1fa8h (794536) map
I (61578) esp_image: segment 4: paddr=003b1fd0 vaddr=40085138 size=15b1ch ( 88860)
I (61602) esp_image: segment 5: paddr=003c7af4 vaddr=50000000 size=00010h ( 16)
I (61606) esp_image: segment 6: paddr=003c7b0c vaddr=00000000 size=08474h ( 33908)
I (61626) esp_image: Verifying image signature...
I (62354) ota: HTTP EVENT 6
I (62358) ota: HTTP EVENT 6
I (62362) esp_image: segment 0: paddr=002c0020 vaddr=3f400020 size=24b6ch (150380) map
I (62406) esp_image: segment 1: paddr=002e4b94 vaddr=3ffbdb60 size=06344h ( 25412)
I (62414) esp_image: segment 2: paddr=002eaee0 vaddr=40080000 size=05138h ( 20792)
I (62422) esp_image: segment 3: paddr=002f0020 vaddr=400d0020 size=c1fa8h (794536) map
I (62630) esp_image: segment 4: paddr=003b1fd0 vaddr=40085138 size=15b1ch ( 88860)
I (62654) esp_image: segment 5: paddr=003c7af4 vaddr=50000000 size=00010h ( 16)
I (62658) app: Sent BB 01 00 00 00 00 00 00 00 00 FFGuru Meditation Error: Core 0 panic'ed (Interrupt wdt timeout on CPU0).

Core 0 register dump:
PC : 0x40093eaa PS : 0x00060635 A0 : 0x80092b96 A1 : 0x3ffbb340
A2 : 0x3ffd3228 A3 : 0x3ffbb8d0 A4 : 0x00000000 A5 : 0x00060623
A6 : 0x00000001 A7 : 0x00000028 A8 : 0x3ffbb8d0 A9 : 0x3ffbb8d0
A10 : 0x00000018 A11 : 0x00000018 A12 : 0x00000001 A13 : 0x00060623
A14 : 0x00000003 A15 : 0x00060023 SAR : 0x0000001e EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000 LBEG : 0x4000c2e0 LEND : 0x4000c2f6 LCOUNT : 0xffffffff


Backtrace:0x40093ea7:0x3ffbb3400x40092b93:0x3ffbb360 0x40091bfa:0x3ffbb380 0x4010a408:0x3ffbb3c0 0x4010ad4d:0x3ffbb400 0x400d58e3:0x3ffbb430 0x400d5885:0x3ffbb460 0x400d477b:0x3ffbb480 0x400d3d1b:0x3ffbb4a0 0x4000bd83:0x3ffbb4c0 0x4000117d:0x3ffbb4e0 0x400592fe:0x3ffbb500 0x4005937a:0x3ffbb520 0x40058ca4:0x3ffbb540 0x40057788:0x3ffbb560 0x400577d1:0x3ffbb580 0x40057902:0x3ffbb5a0 0x400569dd:0x3ffbb630 0x40191945:0x3ffbb660 0x40096499:0x3ffbb690 0x400d7d40:0x3ffbb6e0 0x400d8219:0x3ffbb780 0x400d7bdf:0x3ffbb7a0 0x40191639:0x3ffbb800 0x40093f7d:0x3ffbb820
[/Codebox]

Parsed backtrace:
[Codebox]
0x40093347: vListInsert at /opt/esp/idf/components/freertos/list.c:166
0x40092363: vTaskPlaceOnEventList at /opt/esp/idf/components/freertos/tasks.c:3566
0x400912de: xQueueSemaphoreTake at /opt/esp/idf/components/freertos/queue.c:1688
0x40091358: xQueueTakeMutexRecursive at /opt/esp/idf/components/freertos/queue.c:731
0x40082bc5: lock_acquire_generic at /opt/esp/idf/components/newlib/locks.c:153
0x40082ccd: _lock_acquire_recursive at /opt/esp/idf/components/newlib/locks.c:167
0x4000be35: ?? ??:0
0x4005789a: ?? ??:0
0x400569dd: ?? ??:0
0x40190891: esp_log_writev at /opt/esp/idf/components/log/log.c:200
0x400957a1: esp_log_write at /opt/esp/idf/components/log/log.c:210
0x400d7769: _send_down at /builds/a2575/FW_esp32_all/build/../main/app.c:502
0x400d7c16: APP_one_second_tick at /builds/a2575/FW_esp32_all/build/../main/app.c:720 (discriminator 1)
0x400d7637: app_main at /builds/a2575/FW_esp32_all/build/../main/main.c:352
0x40190587: main_task at /opt/esp/idf/components/freertos/port/port_common.c:129 (discriminator 2)
0x40093419: vPortTaskWrapper at /opt/esp/idf/components/freertos/port/xtensa/port.c:131
[/Codebox]

[ESP_Sprite]

Hard to say... is there any chance you can post your (if needed whittled down but still reproduces the issue) code here?

[bretie]

Hard to say... is there any chance you can post your (if needed whittled down but still reproduces the issue) code here?

I appreciate your interest in helping! My colleague will be posting a snippet of the code we are using.

[lcrocker]

That would take some serious whittling, but I'll look into it (I'm on the OP's team). I can tell you that the "Sent . . ." message you see toward the end of the report is an ESP_LOGI() that happens inside a timer that sends data out a UART (#2). It looks to me like the ESP_LOGI() is trying to grab a semaphore for some reason?

[ESP_Sprite]

Yep. That is because logging uses a mutex in order to make sure multiple tasks logging messages aren't mixed together on the output. I kinda suspect that the interrupt watchdog timeout is because there's a spinlock somewhere in the mutex code that gets deadlocked in some way.