ESP32: Interrupts with ISRs in flash are not disabled during flash operations

[sam-golioth]

Describe the bug

When writing to SPI flash on the ESP32_DevKitC_WROVER, the device will crash when executing the UART interrupt (e.g. servicing the shell or logging system). The UART interrupt is located in SPI flash, so this is an execute-while-write exception (confirmed when looking at the EXCAUSE register that the reason is "Load Prohibited"). The Espressif HAL has a mechanism to keep track of which interrupts are located in flash when registering interrupts, and then disabling them when performing flash writes. This mechanism works in previous versions of Zephyr, but does not seem to be active in Zephyr 3.7. If I put a breakpoint on esp_intr_noniram_disable() in Zephyr 3.6, I can see this being called whenever there is a flash operation. In Zephyr 3.7, this function is never called.

Expected behavior

Interrupts with ISRs located in flash should be disabled during flash operations.

Impact
Anything that writes to SPI flash is unusable for Espressif platforms on Zephyr 3.7.

Logs and console output
Backtrace for the crash:

arch_system_halt (reason=0) at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/kernel/fatal.c:30
30              for (;;) {
(gdb) bt
#0  arch_system_halt (reason=0) at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/kernel/fatal.c:30
#1  0x40086336 in k_sys_fatal_error_handler (reason=0, esf=0x3ffd35a8 <z_interrupt_stacks+1768>)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/kernel/fatal.c:44
#2  0x400863eb in z_fatal_error (reason=0, esf=0x3ffd35a8 <z_interrupt_stacks+1768>) at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/kernel/fatal.c:118
#3  0x4008569c in xtensa_fatal_error (reason=0, esf=0x3ffd35a8 <z_interrupt_stacks+1768>)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/arch/xtensa/core/fatal.c:109
#4  0x400860fb in xtensa_excint1_c (esf=0x3ffd35a8 <z_interrupt_stacks+1768>)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/arch/xtensa/core/vector_handlers.c:442
#5  0x4008587a in _xstack_call0_5 () at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/arch/xtensa/core/xtensa_asm2_util.S:320
#6  0x40085865 in _do_call_3 () at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/arch/xtensa/core/xtensa_asm2_util.S:320
#7  0x4013d0a2 in ring_buf_put_claim (buf=0x3f416758 <__device_dts_ord_64>, data=0x3ffc2510 <shell_transport_uart_shell_uart>, size=1073558952)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/lib/utils/ring_buffer.c:28
#8  0x4013f22a in uart_esp32_isr (arg=0x3f416758 <__device_dts_ord_64>) at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/drivers/serial/uart_esp32.c:510
#9  0x40085ef0 in _xtensa_handle_one_int1 (mask=8) at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/soc/espressif/common/include/_soc_inthandlers.h:219
#10 xtensa_int1_c (interrupted_stack=0x3ffd3eb8 <z_main_stack+1016>) at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/arch/xtensa/core/vector_handlers.c:337
#11 xtensa_excint1_c (esf=0x3ffd3eb8 <z_main_stack+1016>) at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/arch/xtensa/core/vector_handlers.c:367
#12 0x4008587a in _xstack_call0_5 () at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/arch/xtensa/core/xtensa_asm2_util.S:320
#13 0x40085865 in _do_call_3 () at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/arch/xtensa/core/xtensa_asm2_util.S:320
#14 0x40081b4c in delay_us (arg=0x0, us=20) at /Users/samfriedman/golioth/test_cp_sdk_zephyr/modules/hal/espressif/components/spi_flash/spi_flash_os_func_noos.c:87
#15 0x40095004 in spi_flash_chip_generic_wait_idle (chip=0x3ffb2c04 <default_chip>, timeout_us=<optimized out>)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/modules/hal/espressif/components/spi_flash/spi_flash_chip_generic.c:471
#16 0x4009507c in spi_flash_chip_generic_page_program (length=<optimized out>, address=<optimized out>, buffer=<optimized out>, chip=0x3ffb2c04 <default_chip>)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/modules/hal/espressif/components/spi_flash/spi_flash_chip_generic.c:269
#17 spi_flash_chip_generic_page_program (chip=0x3ffb2c04 <default_chip>, buffer=<optimized out>, address=<optimized out>, length=<optimized out>)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/modules/hal/espressif/components/spi_flash/spi_flash_chip_generic.c:258
#18 0x40094a7d in spi_flash_chip_generic_write (chip=0x3ffb2c04 <default_chip>, buffer=0x3ffd40c0 <z_main_stack+1536>, address=<optimized out>,
    length=<optimized out>) at /Users/samfriedman/golioth/test_cp_sdk_zephyr/modules/hal/espressif/components/spi_flash/spi_flash_chip_generic.c:294
#19 0x40081857 in esp_flash_write (chip=<optimized out>, buffer=0x3ffd40c0 <z_main_stack+1536>, address=2442672, length=4)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/modules/hal/espressif/components/spi_flash/esp_flash_api.c:1080
#20 0x4008b7b9 in flash_esp32_write (dev=0x3f41676c <__device_dts_ord_69>, address=2442672, buffer=0x3ffd40c0 <z_main_stack+1536>, length=4)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/drivers/flash/flash_esp32.c:99
#21 0x400d6770 in z_impl_flash_write (len=<optimized out>, data=0x3ffd40c0 <z_main_stack+1536>, offset=2442672, dev=<optimized out>)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/include/zephyr/drivers/flash.h:274
#22 flash_write (len=<optimized out>, data=0x3ffd40c0 <z_main_stack+1536>, offset=2442672, dev=<optimized out>)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/modules/lib/golioth-firmware-sdk/build/zephyr/include/generated/zephyr/syscalls/flash.h:64
#23 nvs_flash_al_wrt (fs=<optimized out>, addr=<optimized out>, data=<optimized out>, len=<optimized out>)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/subsys/fs/nvs/nvs.c:136
#24 0x400d6e96 in nvs_flash_data_wrt (compute_crc=true, len=2, data=0x3ffc3a90 <default_settings_nvs+56>, fs=0x3ffc3a60 <default_settings_nvs+8>)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/subsys/fs/nvs/nvs.c:214
#25 nvs_flash_wrt_entry (len=2, data=0x3ffc3a90 <default_settings_nvs+56>, id=32768, fs=0x3ffc3a60 <default_settings_nvs+8>)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/subsys/fs/nvs/nvs.c:456
#26 nvs_write (fs=0x3ffc3a60 <default_settings_nvs+8>, id=32768, data=0x3ffc3a90 <default_settings_nvs+56>, len=2)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/subsys/fs/nvs/nvs.c:1164
#27 0x400d81b9 in settings_nvs_load (cs=0x3ffc3a58 <default_settings_nvs>, arg=0x3ffd41f0 <z_main_stack+1840>)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/subsys/settings/src/settings_nvs.c:187
#28 0x400d7d43 in settings_load_subtree (subtree=0x0) at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/subsys/settings/src/settings_store.c:58
#29 0x400d7d60 in settings_load () at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/subsys/settings/src/settings_store.c:39
#30 0x400dba5e in settings_autoload ()
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/modules/lib/golioth-firmware-sdk/examples/zephyr/common/settings_autoload.c:12
#31 0x40086421 in z_sys_init_run_level (level=<optimized out>) at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/kernel/init.c:372
#32 0x40086444 in bg_thread_main (unused1=<optimized out>, unused2=<optimized out>, unused3=0x0)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/kernel/init.c:440
#33 0x400d5aea in z_thread_entry (entry=0x40086428 <bg_thread_main>, p1=0x0, p2=0x0, p3=0x0)
    at /Users/samfriedman/golioth/test_cp_sdk_zephyr/zephyr/lib/os/thread_entry.c:48

[sylvioalves]

@sam-golioth, I did spot this and will get it fixed.

[sylvioalves]

@sam-golioth, I submitted a test patch on top of v3.7-branch. I will extend tests to make sure it won't break anything else. Would you be able to test it in your environment as well?
I will also make sure this change is available for all other ESP32 SoCs as well.

#78121

[sam-golioth]

@sam-golioth, I submitted a test patch on top of v3.7-branch. I will extend tests to make sure it won't break anything else. Would you be able to test it in your environment as well? I will also make sure this change is available for all other ESP32 SoCs as well.

#78121

So far I haven't been able to reproduce the issue with this fix! Of course, I could have just gotten lucky. I'll run more test runs over the next day or so and I'll let you know if anything pops up. Thanks, @sylvioalves!