Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Verbose logging results in panic on ESP32-C3 (IDFGH-7652) #9203

Closed
driftregion opened this issue Jun 22, 2022 · 4 comments
Closed

Verbose logging results in panic on ESP32-C3 (IDFGH-7652) #9203

driftregion opened this issue Jun 22, 2022 · 4 comments
Assignees
@ESP-Marius
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally

Comments

@driftregion
Copy link

Environment

  • Development Kit: None
  • Module or chip used:
    • ESP32-C3-WROOM -- panic
    • ESP32-C3-MINI -- panic
    • ESP32-WROOM-32 -- No problem
  • IDF version (run git describe --tags to find it): v5.0-dev-3424-gbb23d783c0
  • Build System: idf.py
  • Compiler version (run xtensa-esp32-elf-gcc --version to find it):
    xtensa-esp32-elf-gcc (crosstool-NG esp-2022r1-RC1) 11.2.0
    riscv32-esp-elf-gcc (crosstool-NG esp-2022r1-RC1) 11.2.0
  • Operating System: Linux
  • Using an IDE?: No
  • Power Supply: USB

Problem Description

Expected Behavior

Verbose logging does not result in panic

Actual Behavior

Enabling verbose logging results in panic on ESP32-C3

Steps to reproduce

Using examples/get-started/hello_world,

  1. Enable verbose logging via idf.py menuconfig Component config -> Log output -> Default log verbosity->Verbose
  2. Observe panic on ESP32-C3.

Debug Logs

ESP32C3

Rebooting...
ESP-ROM:esp32c3-api1-20210207
Build:Feb  7 2021
rst:0x3 (RTC_SW_SYS_RST),boot:0xc (SPI_FAST_FLASH_BOOT)
Saved PC:0x403805aa
0x403805aa: esp_restart_noos_dig at /home/user/esp/esp-idf/components/esp_system/esp_system.c:46 (discriminator 1)

SPIWP:0xee
mode:DIO, clock div:1
load:0x3fcd6108,len:0x1990
load:0x403ce000,len:0x8f8
load:0x403cf600,len:0x2e28
entry 0x403ce000
I (35) boot: ESP-IDF v5.0-dev-3424-gbb23d783c0 2nd stage bootloader
I (35) boot: compile time 14:14:36
I (35) boot: chip revision: 3
I (38) boot.esp32c3: SPI Speed      : 80MHz
I (43) boot.esp32c3: SPI Mode       : DIO
I (48) boot.esp32c3: SPI Flash Size : 2MB
I (53) boot: Enabling RNG early entropy source...
I (58) boot: Partition Table:
I (62) boot: ## Label            Usage          Type ST Offset   Length
I (69) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (76) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (84) boot:  2 factory          factory app      00 00 00010000 00100000
I (91) boot: End of partition table
I (95) esp_image: segment 0: paddr=00010020 vaddr=3c020020 size=07a70h ( 31344) map
I (109) esp_image: segment 1: paddr=00017a98 vaddr=3fc8a800 size=015cch (  5580) load
I (113) esp_image: segment 2: paddr=0001906c vaddr=40380000 size=06fach ( 28588) load
I (126) esp_image: segment 3: paddr=00020020 vaddr=42000020 size=16858h ( 92248) map
I (143) esp_image: segment 4: paddr=00036880 vaddr=40386fac size=03764h ( 14180) load
I (146) esp_image: segment 5: paddr=00039fec vaddr=50000010 size=00010h (    16) load
I (152) boot: Loaded app from partition at offset 0x10000
I (155) boot: Disabling RNG early entropy source...
I (172) cpu_start: Pro cpu up.
D (172) efuse: In EFUSE_BLK1__DATA3_REG is used 3 bits starting with 18 bit
D (172) efuse: In EFUSE_BLK1__DATA5_REG is used 5 bits starting with 5 bit
D (178) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 7 bit
D (185) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 14 bit
D (192) efuse: In EFUSE_BLK1__DATA4_REG is used 8 bits starting with 21 bit
D (199) efuse: In EFUSE_BLK1__DATA4_REG is used 3 bits starting with 29 bit
D (206) efuse: In EFUSE_BLK1__DATA5_REG is used 5 bits starting with 0 bit
D (221) clk: RTC_SLOW_CLK calibration value: 3797658
V CACHE_ERR: access error intr clr & ena mask is: 0x3f
V CACHE_ERR: illegal error intr clr & ena mask is: 0x23
I (230) cpu_start: Pro cpu start user code
I (233) cpu_start: cpu freq: 160000000 Hz
I (238) cpu_start: Application information:
I (242) cpu_start: Project name:     hello_world
I (248) cpu_start: App version:      v5.0-dev-3424-gbb23d783c0
I (254) cpu_start: Compile time:     Jun 22 2022 14:14:29
I (260) cpu_start: ELF file SHA256:  36143df4d9f3500d...
I (266) cpu_start: ESP-IDF:          v5.0-dev-3424-gbb23d783c0
V (273) memory_layout: reserved range is 0x3c027980 - 0x3c027998
D (279) memory_layout: Checking 4 reserved memory ranges:
D (284) memory_layout: Reserved memory range 0x3fc80000 - 0x3fc8a800
D (291) memory_layout: Reserved memory range 0x3fc8a800 - 0x3fc8cc40
D (297) memory_layout: Reserved memory range 0x3fcdf060 - 0x3fce0000
D (304) memory_layout: Reserved memory range 0x50000000 - 0x50000020
D (310) memory_layout: Building list of available memory regions:
V (316) memory_layout: Examining memory region 0x3fc80000 - 0x3fca0000
V (323) memory_layout: Start of region 0x3fc80000 - 0x3fca0000 overlaps reserved 0x3fc80000 - 0x3fc8a800
V (332) memory_layout: Start of region 0x3fc8a800 - 0x3fca0000 overlaps reserved 0x3fc8a800 - 0x3fc8cc40
D (342) memory_layout: Available memory region 0x3fc8cc40 - 0x3fca0000
V (348) memory_layout: Examining memory region 0x3fca0000 - 0x3fcc0000
D (355) memory_layout: Available memory region 0x3fca0000 - 0x3fcc0000
V (362) memory_layout: Examining memory region 0x3fcc0000 - 0x3fce0000
V (368) memory_layout: End of region 0x3fcc0000 - 0x3fce0000 overlaps reserved 0x3fcdf060 - 0x3fce0000
D (378) memory_layout: Available memory region 0x3fcc0000 - 0x3fcdf060
V (384) memory_layout: Examining memory region 0x50000000 - 0x50002000
V (391) memory_layout: Start of region 0x50000000 - 0x50002000 overlaps reserved 0x50000000 - 0x50000020
D (400) memory_layout: Available memory region 0x50000020 - 0x50002000
I (407) heap_init: Initializing. RAM available for dynamic allocation:
D (414) heap_init: New heap initialised at 0x3fc8cc40
I (419) heap_init: At 3FC8CC40 len 000333C0 (204 KiB): DRAM
I (426) heap_init: At 3FCC0000 len 0001F060 (124 KiB): STACK/DRAM
D (432) heap_init: New heap initialised at 0x50000020
I (437) heap_init: At 50000020 len 00001FE0 (7 KiB): RTCRAM
V (444) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (450) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (458) intr_alloc: Connected src 27 to int 2 (cpu 0)
V (464) Guru Meditation Error: Core  0 panic'ed (Cache error). 
access to cache while dbus or cache is disabled

Stack dump detected
Core  0 register dump:
MEPC    : 0x400485e8  RA      : 0x400485e4  SP      : 0x3fcde0d0  GP      : 0x3fc8b000  
TP      : 0x00000000  T0      : 0x00000000  T1      : 0x00000000  T2      : 0x00000000  
S0/FP   : 0x00000000  S1      : 0x00000008  A0      : 0x00000043  A1      : 0x00000009  
A2      : 0x0000002e  A3      : 0x00000070  A4      : 0x00000000  A5      : 0x3fcde17c  
A6      : 0xa0000000  A7      : 0x0000000a  S2      : 0x00000000  S3      : 0x3c027a14  
S4      : 0x3fcde17c  S5      : 0x000001d0  S6      : 0x400481b0  S7      : 0x3fc8b6e5  
S8      : 0x00000000  S9      : 0x3fcde0e0  S10     : 0x00000000  S11     : 0x00000000  
T3      : 0x00000000  T4      : 0x00000000  T5      : 0x00000000  T6      : 0x00000000  
MSTATUS : 0x00001881  MTVEC   : 0x40380001  MCAUSE  : 0x00000019  MTVAL   : 0x02000793  
0x40380001: _vector_table at ??:?

MHARTID : 0x00000000  


Backtrace:


0x400485e8 in ?? ()
#0  0x400485e8 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
ELF file SHA256: 36143df4d9f3500d
@espressif-bot espressif-bot added the Status: Opened Issue is new label Jun 22, 2022
@github-actions github-actions bot changed the title Verbose logging results in panic on ESP32-C3 Verbose logging results in panic on ESP32-C3 (IDFGH-7652) Jun 22, 2022
@ESP-Marius
Copy link
Collaborator

Hi @driftregion

Thanks for reporting this. Looks like something that should be in IRAM/DRAM due to being accessed while the cache is disabled ends up in flash instead., causing a crash.

We'll take a look at it and fix it.

@igrr
Copy link
Member

igrr commented Jun 22, 2022

As a workaround, you can try the following:

  1. Reduce the default log level to Info or Debug (CONFIG_LOG_DEFAULT_LEVEL_INFO=y)
  2. Increase the maximum log level to Verbose (CONFIG_LOG_MAXIMUM_LEVEL_VERBOSE=y)
  3. In app_main, call esp_log_level_set("*", ESP_LOG_VERBOSE) (or use a specific tag instead of *) to increase the run-time log level to verbose.

@ESP-Marius
Copy link
Collaborator

ESP-Marius commented Jun 22, 2022 •
edited
Loading

Alternatively you can also update static const char TAG[] = "memspi"; to static const DRAM_ATTR char TAG[] = "memspi in memspi_host_driver.c while you wait for a fix to be merged.

@espressif-bot espressif-bot added Status: In Progress Work is in progress Status: Reviewing Issue is being reviewed Resolution: NA Issue resolution is unavailable Status: Done Issue is done internally Resolution: Done Issue is done internally and removed Status: Opened Issue is new Status: In Progress Work is in progress Status: Reviewing Issue is being reviewed Resolution: NA Issue resolution is unavailable labels Jun 22, 2022
@Alvin1Zhang
Copy link
Collaborator

Thanks for reporting, fix on master branch is at 827837d, we will also backport this fix to other release branches, feel free to reopen. Thanks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ESP-Marius ESP-Marius

Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@igrr @driftregion @Alvin1Zhang @ESP-Marius @espressif-bot