ESP32 not logging stack trace during panic
Posted: Thu Jun 22, 2023 5:54 pm
I'm developing firmware for an ESP32-S3 (after switching from an ESP32-WROOM) and ever since switching to the new chip I'm unable to see stack traces for panics, which makes debugging very difficult. I've tested this out by intentionally causing a panic by accessing a member of an uninstantiated class (I'm using C++).
[Codebox]
vTaskDelay(pdMS_TO_TICKS(10000));
// intentionally cause panic due to invalid memory access
Tuneshine *fakeTs = NULL;
ESP_LOGI(TAG, "causing panic in 5s");
vTaskDelay(pdMS_TO_TICKS(5000));
fakeTs->start();
[/Codebox]
Here's the full log output when I run this firmware.
[Codebox]
10:45:39.595 > ESP-ROM:esp32s3-20210327
10:45:39.595 > Build:Mar 27 2021
10:45:39.597 > rst:0xc (RTC_SW_CPU_RST),boot:0x2b (SPI_FAST_FLASH_BOOT)
10:45:39.598 > Saved PC:0x40376550
10:45:39.598 > SPIWP:0xee
10:45:39.599 > mode:DIO, clock div:1
10:45:39.600 > load:0x3fce3808,len:0x165c
10:45:39.603 > load:0x403c9700,len:0xbb8
10:45:39.605 > load:0x403cc700,len:0x2e84
10:45:39.613 > SHA-256 comparison failed:
10:45:39.615 > Calculated: d0040eee866fbccf6a1b8e78c26aebb7ea471b5bb8d55efc9a18d86200762b2e
10:45:39.630 > Expected: 95962ea03cc6d427c2d645d5d598f0d57f6904ee2309dad105af5a43e35dc6be
10:45:39.630 > Attempting to boot anyway...
10:45:39.630 > entry 0x403c9954
10:45:39.637 > I (42) boot: ESP-IDF 4.4.2 2nd stage bootloader
10:45:39.637 > I (42) boot: compile time 10:44:38
10:45:39.638 > I (43) boot: chip revision: 0
10:45:39.643 > I (44) boot.esp32s3: Boot SPI Speed : 80MHz
10:45:39.648 > I (49) boot.esp32s3: SPI Mode : DIO
10:45:39.652 > I (54) boot.esp32s3: SPI Flash Size : 4MB
10:45:39.658 > I (58) boot: Enabling RNG early entropy source...
10:45:39.661 > I (64) boot: Partition Table:
10:45:39.667 > I (67) boot: ## Label Usage Type ST Offset Length
10:45:39.674 > I (75) boot: 0 nvs WiFi data 01 02 00009000 00005000
10:45:39.682 > I (82) boot: 1 otadata OTA data 01 00 0000e000 00002000
10:45:39.689 > I (89) boot: 2 app0 OTA app 00 10 00010000 001c0000
10:45:39.697 > I (97) boot: 3 app1 OTA app 00 11 001d0000 001c0000
10:45:39.704 > I (104) boot: 4 spiffs Unknown data 01 82 00390000 00070000
10:45:39.710 > I (112) boot: End of partition table
10:45:39.716 > I (116) esp_image: segment 0: paddr=00010020 vaddr=3c0e0020 size=572d8h (357080) map
10:45:39.783 > I (189) esp_image: segment 1: paddr=00067300 vaddr=3fc993f0 size=07ea4h ( 32420) load
10:45:39.790 > I (196) esp_image: segment 2: paddr=0006f1ac vaddr=40374000 size=00e6ch ( 3692) load
10:45:39.794 > I (197) esp_image: segment 3: paddr=00070020 vaddr=42000020 size=d441ch (869404) map
10:45:39.954 > I (359) esp_image: segment 4: paddr=00144444 vaddr=40374e6c size=14578h ( 83320) load
10:45:39.977 > I (378) esp_image: segment 5: paddr=001589c4 vaddr=50000000 size=00010h ( 16) load
10:45:39.982 > I (387) boot: Loaded app from partition at offset 0x10000
10:45:39.982 > I (387) boot: Disabling RNG early entropy source...
10:45:39.994 > I (399) opi psram: vendor id : 0x0d (AP)
10:45:39.994 > I (399) opi psram: dev id : 0x02 (generation 3)
10:45:39.997 > I (399) opi psram: density : 0x03 (64 Mbit)
10:45:40.002 > I (403) opi psram: good-die : 0x01 (Pass)
10:45:40.007 > I (408) opi psram: Latency : 0x01 (Fixed)
10:45:40.011 > I (413) opi psram: VCC : 0x01 (3V)
10:45:40.017 > I (417) opi psram: SRF : 0x01 (Fast Refresh)
10:45:40.022 > I (423) opi psram: BurstType : 0x01 (Hybrid Wrap)
10:45:40.027 > I (428) opi psram: BurstLen : 0x01 (32 Byte)
10:45:40.033 > I (433) opi psram: Readlatency : 0x02 (10 cycles@Fixed)
10:45:40.038 > I (439) opi psram: DriveStrength: 0x00 (1/1)
10:45:40.043 > I (444) spiram: Found 64MBit SPI RAM device
10:45:40.047 > I (449) spiram: SPI RAM mode: sram 40m
10:45:40.053 > I (453) spiram: PSRAM initialized, cache is in normal (1-core) mode.
10:45:40.058 > I (460) cpu_start: Pro cpu up.
10:45:40.064 > I (464) cpu_start: Starting app cpu, entry point is 0x40376070
10:45:40.068 > I (439) cpu_start: App cpu up.
10:45:40.796 > I (1201) spiram: SPI SRAM memory test OK
10:45:40.808 > I (1210) cpu_start: Pro cpu start user code
10:45:40.808 > I (1210) cpu_start: cpu freq: 160000000
10:45:40.808 > I (1211) cpu_start: Application information:
10:45:40.813 > I (1213) cpu_start: Project name: tuneshine-esp-idf
10:45:40.820 > I (1219) cpu_start: App version: 6b819a3-dirty
10:45:40.825 > I (1225) cpu_start: Compile time: Jun 22 2023 10:44:20
10:45:40.831 > I (1231) cpu_start: ELF file SHA256: a10778ed7ed47dc0...
10:45:40.836 > I (1237) cpu_start: ESP-IDF: 4.4.2
10:45:40.842 > I (1242) heap_init: Initializing. RAM available for dynamic allocation:
10:45:40.849 > I (1249) heap_init: At 3FCA9708 len 00040008 (256 KiB): D/IRAM
10:45:40.856 > I (1256) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
10:45:40.862 > I (1263) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
10:45:40.869 > I (1269) heap_init: At 600FE000 len 00002000 (8 KiB): RTCRAM
10:45:40.876 > I (1275) spiram: Adding pool of 8192K of external SPI memory to heap allocator
10:45:40.882 > I (1284) spi_flash: detected chip: gd
10:45:40.886 > I (1288) spi_flash: flash io: dio
10:45:40.891 > W (1292) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
10:45:40.904 > I (1306) sleep: Configure to isolate all GPIO pins in sleep state
10:45:40.911 > I (1312) sleep: Enable automatic switching of GPIO sleep configuration
10:45:40.918 > I (1319) coexist: coexist rom version e7ae62f
10:45:40.924 > I (1324) cpu_start: Starting scheduler on PRO CPU.
10:45:40.929 > I (0) cpu_start: Starting scheduler on APP CPU.
10:45:40.934 > I (1334) spiram: Reserving pool of 32K of internal memory for DMA/internal allocations
10:45:50.929 > I (11344) Main: causing panic in 5s
10:45:56.003 > ESP-ROM:esp32s3-20210327
10:45:56.003 > Build:Mar 27 2021
10:45:56.004 > rst:0xc (RTC_SW_CPU_RST),boot:0x2b (SPI_FAST_FLASH_BOOT)
10:45:56.004 > Saved PC:0x40376550
10:45:56.008 > SPIWP:0xee
....
[/Codebox]
As you can see, the ESP32 silently reboots after logging "causing panic in 5s." However, my menuconfig configuration should prevent this. Here's the relevant section of my config.
[Codebox]
#
# ESP System Settings
#
# CONFIG_ESP_SYSTEM_PANIC_PRINT_HALT is not set
CONFIG_ESP_SYSTEM_PANIC_PRINT_REBOOT=y
# CONFIG_ESP_SYSTEM_PANIC_SILENT_REBOOT is not set
# CONFIG_ESP_SYSTEM_PANIC_GDBSTUB is not set
# CONFIG_ESP_SYSTEM_GDBSTUB_RUNTIME is not set
CONFIG_ESP_SYSTEM_RTC_FAST_MEM_AS_HEAP_DEPCHECK=y
CONFIG_ESP_SYSTEM_ALLOW_RTC_FAST_MEM_AS_HEAP=y
[/Codebox]
When using CONFIG_ESP_SYSTEM_PANIC_PRINT_HALT the same behavior is observed (without the restart).
Any idea why I'm not getting the stack trace and registers in this case?
[Codebox]
vTaskDelay(pdMS_TO_TICKS(10000));
// intentionally cause panic due to invalid memory access
Tuneshine *fakeTs = NULL;
ESP_LOGI(TAG, "causing panic in 5s");
vTaskDelay(pdMS_TO_TICKS(5000));
fakeTs->start();
[/Codebox]
Here's the full log output when I run this firmware.
[Codebox]
10:45:39.595 > ESP-ROM:esp32s3-20210327
10:45:39.595 > Build:Mar 27 2021
10:45:39.597 > rst:0xc (RTC_SW_CPU_RST),boot:0x2b (SPI_FAST_FLASH_BOOT)
10:45:39.598 > Saved PC:0x40376550
10:45:39.598 > SPIWP:0xee
10:45:39.599 > mode:DIO, clock div:1
10:45:39.600 > load:0x3fce3808,len:0x165c
10:45:39.603 > load:0x403c9700,len:0xbb8
10:45:39.605 > load:0x403cc700,len:0x2e84
10:45:39.613 > SHA-256 comparison failed:
10:45:39.615 > Calculated: d0040eee866fbccf6a1b8e78c26aebb7ea471b5bb8d55efc9a18d86200762b2e
10:45:39.630 > Expected: 95962ea03cc6d427c2d645d5d598f0d57f6904ee2309dad105af5a43e35dc6be
10:45:39.630 > Attempting to boot anyway...
10:45:39.630 > entry 0x403c9954
10:45:39.637 > I (42) boot: ESP-IDF 4.4.2 2nd stage bootloader
10:45:39.637 > I (42) boot: compile time 10:44:38
10:45:39.638 > I (43) boot: chip revision: 0
10:45:39.643 > I (44) boot.esp32s3: Boot SPI Speed : 80MHz
10:45:39.648 > I (49) boot.esp32s3: SPI Mode : DIO
10:45:39.652 > I (54) boot.esp32s3: SPI Flash Size : 4MB
10:45:39.658 > I (58) boot: Enabling RNG early entropy source...
10:45:39.661 > I (64) boot: Partition Table:
10:45:39.667 > I (67) boot: ## Label Usage Type ST Offset Length
10:45:39.674 > I (75) boot: 0 nvs WiFi data 01 02 00009000 00005000
10:45:39.682 > I (82) boot: 1 otadata OTA data 01 00 0000e000 00002000
10:45:39.689 > I (89) boot: 2 app0 OTA app 00 10 00010000 001c0000
10:45:39.697 > I (97) boot: 3 app1 OTA app 00 11 001d0000 001c0000
10:45:39.704 > I (104) boot: 4 spiffs Unknown data 01 82 00390000 00070000
10:45:39.710 > I (112) boot: End of partition table
10:45:39.716 > I (116) esp_image: segment 0: paddr=00010020 vaddr=3c0e0020 size=572d8h (357080) map
10:45:39.783 > I (189) esp_image: segment 1: paddr=00067300 vaddr=3fc993f0 size=07ea4h ( 32420) load
10:45:39.790 > I (196) esp_image: segment 2: paddr=0006f1ac vaddr=40374000 size=00e6ch ( 3692) load
10:45:39.794 > I (197) esp_image: segment 3: paddr=00070020 vaddr=42000020 size=d441ch (869404) map
10:45:39.954 > I (359) esp_image: segment 4: paddr=00144444 vaddr=40374e6c size=14578h ( 83320) load
10:45:39.977 > I (378) esp_image: segment 5: paddr=001589c4 vaddr=50000000 size=00010h ( 16) load
10:45:39.982 > I (387) boot: Loaded app from partition at offset 0x10000
10:45:39.982 > I (387) boot: Disabling RNG early entropy source...
10:45:39.994 > I (399) opi psram: vendor id : 0x0d (AP)
10:45:39.994 > I (399) opi psram: dev id : 0x02 (generation 3)
10:45:39.997 > I (399) opi psram: density : 0x03 (64 Mbit)
10:45:40.002 > I (403) opi psram: good-die : 0x01 (Pass)
10:45:40.007 > I (408) opi psram: Latency : 0x01 (Fixed)
10:45:40.011 > I (413) opi psram: VCC : 0x01 (3V)
10:45:40.017 > I (417) opi psram: SRF : 0x01 (Fast Refresh)
10:45:40.022 > I (423) opi psram: BurstType : 0x01 (Hybrid Wrap)
10:45:40.027 > I (428) opi psram: BurstLen : 0x01 (32 Byte)
10:45:40.033 > I (433) opi psram: Readlatency : 0x02 (10 cycles@Fixed)
10:45:40.038 > I (439) opi psram: DriveStrength: 0x00 (1/1)
10:45:40.043 > I (444) spiram: Found 64MBit SPI RAM device
10:45:40.047 > I (449) spiram: SPI RAM mode: sram 40m
10:45:40.053 > I (453) spiram: PSRAM initialized, cache is in normal (1-core) mode.
10:45:40.058 > I (460) cpu_start: Pro cpu up.
10:45:40.064 > I (464) cpu_start: Starting app cpu, entry point is 0x40376070
10:45:40.068 > I (439) cpu_start: App cpu up.
10:45:40.796 > I (1201) spiram: SPI SRAM memory test OK
10:45:40.808 > I (1210) cpu_start: Pro cpu start user code
10:45:40.808 > I (1210) cpu_start: cpu freq: 160000000
10:45:40.808 > I (1211) cpu_start: Application information:
10:45:40.813 > I (1213) cpu_start: Project name: tuneshine-esp-idf
10:45:40.820 > I (1219) cpu_start: App version: 6b819a3-dirty
10:45:40.825 > I (1225) cpu_start: Compile time: Jun 22 2023 10:44:20
10:45:40.831 > I (1231) cpu_start: ELF file SHA256: a10778ed7ed47dc0...
10:45:40.836 > I (1237) cpu_start: ESP-IDF: 4.4.2
10:45:40.842 > I (1242) heap_init: Initializing. RAM available for dynamic allocation:
10:45:40.849 > I (1249) heap_init: At 3FCA9708 len 00040008 (256 KiB): D/IRAM
10:45:40.856 > I (1256) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
10:45:40.862 > I (1263) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
10:45:40.869 > I (1269) heap_init: At 600FE000 len 00002000 (8 KiB): RTCRAM
10:45:40.876 > I (1275) spiram: Adding pool of 8192K of external SPI memory to heap allocator
10:45:40.882 > I (1284) spi_flash: detected chip: gd
10:45:40.886 > I (1288) spi_flash: flash io: dio
10:45:40.891 > W (1292) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
10:45:40.904 > I (1306) sleep: Configure to isolate all GPIO pins in sleep state
10:45:40.911 > I (1312) sleep: Enable automatic switching of GPIO sleep configuration
10:45:40.918 > I (1319) coexist: coexist rom version e7ae62f
10:45:40.924 > I (1324) cpu_start: Starting scheduler on PRO CPU.
10:45:40.929 > I (0) cpu_start: Starting scheduler on APP CPU.
10:45:40.934 > I (1334) spiram: Reserving pool of 32K of internal memory for DMA/internal allocations
10:45:50.929 > I (11344) Main: causing panic in 5s
10:45:56.003 > ESP-ROM:esp32s3-20210327
10:45:56.003 > Build:Mar 27 2021
10:45:56.004 > rst:0xc (RTC_SW_CPU_RST),boot:0x2b (SPI_FAST_FLASH_BOOT)
10:45:56.004 > Saved PC:0x40376550
10:45:56.008 > SPIWP:0xee
....
[/Codebox]
As you can see, the ESP32 silently reboots after logging "causing panic in 5s." However, my menuconfig configuration should prevent this. Here's the relevant section of my config.
[Codebox]
#
# ESP System Settings
#
# CONFIG_ESP_SYSTEM_PANIC_PRINT_HALT is not set
CONFIG_ESP_SYSTEM_PANIC_PRINT_REBOOT=y
# CONFIG_ESP_SYSTEM_PANIC_SILENT_REBOOT is not set
# CONFIG_ESP_SYSTEM_PANIC_GDBSTUB is not set
# CONFIG_ESP_SYSTEM_GDBSTUB_RUNTIME is not set
CONFIG_ESP_SYSTEM_RTC_FAST_MEM_AS_HEAP_DEPCHECK=y
CONFIG_ESP_SYSTEM_ALLOW_RTC_FAST_MEM_AS_HEAP=y
[/Codebox]
When using CONFIG_ESP_SYSTEM_PANIC_PRINT_HALT the same behavior is observed (without the restart).
Any idea why I'm not getting the stack trace and registers in this case?