esp-idf: NVS write crashes with "Cache disabled but cached memory region accessed" (IDFGH-8634)

Answers checklist.

• I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

ESP-IDF v4.4.2-378-g9269a536ac

Operating System used.

Linux

How did you build your project?

Command line with idf.py

If you are using Windows, please specify command line type.

No response

Development Kit.

Custom board with ESP32-WROOM-32E-N8

Power Supply used.

External 3.3V

What is the expected behavior?

The NVS write should succeed.

What is the actual behavior?

Writing to NVS causes a (rare) crash

Steps to reproduce.

A little hard to share my full environment because it involves external hardware peripherals and I’m not sure what are the trigger conditions.

Debug Logs.

Guru Meditation Error: Core  0 panic'ed (Cache disabled but cached memory region accessed). 

Core  0 register dump:
PC      : 0x400fa6d4  PS      : 0x00060034  A0      : 0x8008220c  A1      : 0x3ffb0b50  
0x400fa6d4: i2c_hal_get_intsts_mask at /opt/esp/idf/components/hal/i2c_hal.c:68

A2      : 0x3ffb8648  A3      : 0x3ffb1484  A4      : 0x00000000  A5      : 0x3ffb69e0  
A6      : 0x3ffb6a30  A7      : 0x3ffb69f0  A8      : 0x80083fac  A9      : 0x00000000  
A10     : 0x3ffb1484  A11     : 0x3ffb0b50  A12     : 0x00000010  A13     : 0x00060023  
A14     : 0x40085cec  A15     : 0x3ffb6bf0  SAR     : 0x00000020  EXCCAUSE: 0x00000007  
0x40085cec: flash_end_flush_cache at /opt/esp/idf/components/spi_flash/esp_flash_api.c:166

EXCVADDR: 0x00000000  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff  


Backtrace: 0x400fa6d1:0x3ffb0b50 0x40082209:0x3ffb0b90 0x40082bed:0x3ffb0bb0 0x4000bfed:0x3ffb6ab0 0x40085889:0x3ffb6ac0 0x40085c47:0x3ffb6af0 0x4008eb3a:0x3ffb6b20 0x40085d19:0x3ffb6b40 0x4008649b:0x3ffb6b60 0x400e1dbf:0x3ffb6bb0 0x400e33f2:0x3ffb6bd0 0x400fa4a9:0x3ffb6bf0 0x400e3a2e:0x3ffb6c20 0x400e3c67:0x3ffb6c40 0x400e2e1d:0x3ffb6cb0 0x400e31fa:0x3ffb6d20 0x400fa2ab:0x3ffb6d40 0x400e221e:0x3ffb6d70 0x400e2241:0x3ffb6da0 0x400d5f13:0x3ffb6dc0 0x400d6015:0x3ffb6e40 0x400faf00:0x3ffb6f70 0x4008b6f5:0x3ffb6f90
0x400fa6d1: i2c_hal_disable_intr_mask at ??:?

0x40082209: shared_intr_isr at /opt/esp/idf/components/esp_hw_support/intr_alloc.c:407

0x40082bed: _xt_lowint1 at /opt/esp/idf/components/freertos/port/xtensa/xtensa_vectors.S:1111

0x40085889: is_page_mapped_in_cache at /opt/esp/idf/components/spi_flash/flash_mmap.c:497

0x40085c47: spi_flash_check_and_flush_cache at /opt/esp/idf/components/spi_flash/flash_mmap.c:516

0x4008eb3a: memspi_host_flush_cache at /opt/esp/idf/components/spi_flash/memspi_host_driver.c:134

0x40085d19: flash_end_flush_cache at /opt/esp/idf/components/spi_flash/esp_flash_api.c:176

0x4008649b: esp_flash_write at /opt/esp/idf/components/spi_flash/esp_flash_api.c:929 (discriminator 1)

0x400e1dbf: esp_partition_write_raw at /opt/esp/idf/components/spi_flash/partition.c:517

0x400e33f2: nvs::NVSPartition::write_raw(unsigned int, void const*, unsigned int) at /opt/esp/idf/components/nvs_flash/src/nvs_partition.cpp:50

0x400fa4a9: nvs::Page::alterEntryState(unsigned int, nvs::Page::EntryState) at /opt/esp/idf/components/nvs_flash/src/nvs_page.cpp:821 (discriminator 2)

0x400e3a2e: nvs::Page::writeEntry(nvs::Item const&) at /opt/esp/idf/components/nvs_flash/src/nvs_page.cpp:109

0x400e3c67: nvs::Page::writeItem(unsigned char, nvs::ItemType, char const*, void const*, unsigned int, unsigned char) at /opt/esp/idf/components/nvs_flash/src/nvs_page.cpp:237

0x400e2e1d: nvs::Storage::writeItem(unsigned char, nvs::ItemType, char const*, void const*, unsigned int) at /opt/esp/idf/components/nvs_flash/src/nvs_storage.cpp:358 (discriminator 4)

0x400e31fa: nvs::NVSHandleSimple::set_typed_item(nvs::ItemType, char const*, void const*, unsigned int) at /opt/esp/idf/components/nvs_flash/src/nvs_handle_simple.cpp:29

0x400fa2ab: int nvs::NVSHandle::set_item<int>(char const*, int) at /opt/esp/idf/components/nvs_flash/include/nvs_handle.hpp:270

0x400e221e: int nvs_set<int>(unsigned int, char const*, int) at /opt/esp/idf/components/nvs_flash/src/nvs_api.cpp:349

0x400e2241: nvs_set_i32 at /opt/esp/idf/components/nvs_flash/src/nvs_api.cpp:374

0x400d5f13: sm::markHome(signed char) at /workspaces/project/main/sm.hpp:61
 (inlined by) processLine(char*) at /workspaces/project/main/main.cpp:95

0x400d6015: app_main at /workspaces/project/main/main.cpp:132

0x400faf00: main_task at /opt/esp/idf/components/freertos/port/port_common.c:141 (discriminator 2)

0x4008b6f5: vPortTaskWrapper at /opt/esp/idf/components/freertos/port/xtensa/port.c:131

More Information.

Based on the crash, it appears to be related to the I2C peripheral, which is enabled with

i2c_driver_install(I2C_PORT, I2C_MODE_MASTER, 0, 0, ESP_INTR_FLAG_SHARED | ESP_INTR_FLAG_IRAM)

Is the issue here that i2c_isr_handler_default calls functions like i2c_hal_get_intsts_mask which arn’t placed in IRAM (and may not be inlined)?

static void IRAM_ATTR i2c_isr_handler_default(void *arg)
{
    i2c_obj_t *p_i2c = (i2c_obj_t *) arg;
    int i2c_num = p_i2c->i2c_num;
    // Interrupt protection.
    // On C3 and S3 targets, the I2C may trigger a spurious interrupt,
    // in order to detect these false positive, check the I2C's hardware interrupt mask
    uint32_t int_mask;
    i2c_hal_get_intsts_mask(&(i2c_context[i2c_num].hal), &int_mask);
    ....