esp_vfs_read call the wrong reading function and freeze a thread (IDFGH-3463)

Environment

Development Kit: [none]
Kit version (for WroverKit/PicoKit/DevKitC): [none]
Module or chip used: [ESP32-WROVER-B]
IDF version (run git describe --tags to find it): v4.0.1 (LTS)
Build System: [Make]
Compiler version (run xtensa-esp32-elf-gcc --version to find it): (crosstool-NG esp-2019r2) 8.2.0
Operating System: [Linux]
Power Supply: [external 5V]

Problem Description

On the same project as that described here: #5122.

I have an esp32 using wifi and bluetooth:

A lot of datas are received via the BLE.

Then, these data are send to a server with mqtt.

This device is also able to play music. The music is saved in a SPI flash.

All works fine, but, sometimes the music thread freeze. The crash happens faster if I have a device connect to the bluetooth.

When the music crash, I see in the back trace that esp_vfs_read is call with the wrong file descriptor fd=0 in stead of fd=3. So the wrong read function is called. The music task try to read the music with uart_read in stead of vfs_fat_read.

(I have the same issue IDF v4.0, v4.1-beta1 and v4.1-beta2 (always with xtensa 2019r2)).

Music task bt when all works fine (see fd=3 => vfs_fat_read):

#0  0x400984b4 in xQueueGenericReceive (xQueue=0x3f8066fc, pvBuffer=0x3ffee400, 
    xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
#1  0x4019e8e8 in spi_device_get_trans_result (handle=0x3ffdf3f8, trans_desc=0x3ffee430, 
    ticks_to_wait=4294967295)
    at /home/pierre/my_project/common/esp-idf/components/driver/spi_master.c:933
#2  0x4019e917 in spi_device_transmit (handle=0x3ffdf3f8, trans_desc=0x3ffc0630 <static_trans>)
    at /home/pierre/my_project/common/esp-idf/components/driver/spi_master.c:956
#3  0x401254c8 in spi_transfer (spi=0x3ffdf3f8, tx_buff=0x3ffee490 "\003\002", tx_len=4, 
    rx_buff=0x3f82a244 "\317\001\326\001\326\001\332\001\331\001\322\001\314\001\313\001\277\001\277\001\264\001\253\001\244\001\236\001\225\001\210\001\177\001|\001l\001a\001^\001T\001F\001\067\001.\001\034\001\v\001", rx_len=512)
    at /home/pierre/my_project/components/spi_manager/spi_manager.c:51
#4  0x4010cd0d in read_data_in_cache (
    buff=0x3f82a244 "\317\001\326\001\326\001\332\001\331\001\322\001\314\001\313\001\277\001\277\001\264\001\253\001\244\001\236\001\225\001\210\001\177\001|\001l\001a\001^\001T\001F\001\067\001.\001\034\001\v\001", nb_byte=512, addr=...)
    at /home/pierre/my_project/components/micron_spi_nand_flash_memory/spi_nand_flash.c:323
#5  read_memory_from_pbpb (nb_byte=512, 
    buff=buff@entry=0x3f82a244 "\317\001\326\001\326\001\332\001\331\001\322\001\314\001\313\001\277\001\277\001\264\001\253\001\244\001\236\001\225\001\210\001\177\001|\001l\001a\001^\001T\001F\001\067\001.\001\034\001\v\001", addr=...)
    at /home/pierre/my_project/components/micron_spi_nand_flash_memory/spi_nand_flash.c:336
#6  0x4010cdb6 in read_memory_from_addr (addr=<optimized out>, nb_byte=512, 
    buff=0x3f82a244 "\317\001\326\001\326\001\332\001\331\001\322\001\314\001\313\001\277\001\277\001\264\001\253\001\244\001\236\001\225\001\210\001\177\001|\001l\001a\001^\001T\001F\001\067\001.\001\034\001\v\001")
    at /home/pierre/my_project/components/micron_spi_nand_flash_memory/spi_nand_flash.c:357
#7  0x401a3fd9 in read_ext_file (pdrv=<optimized out>, buff=<optimized out>, sector=<optimized out>, 
    count=<optimized out>)
    at /home/pierre/my_project/components/external_storage_manager/external_flash_manager.c:135
#8  0x401a4a78 in ff_disk_read (pdrv=0 '\000', 
    buff=0x3f82a244 "\317\001\326\001\326\001\332\001\331\001\322\001\314\001\313\001\277\001\277\001\264\001\253\001\244\001\236\001\225\001\210\001\177\001|\001l\001a\001^\001T\001F\001\067\001.\001\034\001\v\001", sector=8317, count=1)
    at /home/pierre/my_project/common/esp-idf/components/fatfs/diskio/diskio.c:70
#9  0x401a78d5 in f_read (fp=0x3f82a21c, buff=<optimized out>, btr=116, br=0x3ffee5a0)
    at /home/pierre/my_project/common/esp-idf/components/fatfs/src/ff.c:3811
#10 0x401a5428 in vfs_fat_read (ctx=0x3f8289b4, fd=<optimized out>, dst=0x3fffaa28, size=128)
    at /home/pierre/my_project/common/esp-idf/components/fatfs/vfs/vfs_fat.c:356
#11 0x4012867d in esp_vfs_read (r=<optimized out>, fd=3, dst=0x3fffaa28, size=128)
    at /home/pierre/my_project/common/esp-idf/components/vfs/vfs.c:446
#12 0x40092104 in __sread (ptr=0x3ffee7b4, cookie=0x3f804e64, buf=0x3fffaa28 "\022", n=128)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/stdio.c:47
#13 0x400919cd in __srefill_r (ptr=<optimized out>, fp=0x3f804e64)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/refill.c:117
#14 0x4010e4e1 in _fread_r (ptr=0x3ffee7b4, buf=<optimized out>, size=1, count=1024, fp=0x3f804e64)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/fread.c:228
#15 0x4010e580 in fread (buf=0x3f844ae4, size=1, count=1024, fp=0x3f804e64)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/fread.c:266
#16 0x401a4755 in spi_ext_flash_read_with_offset (
    file_path=0x3ffc7080 <played_music_path> "/music_files/brahms.raw", modes=<optimized out>, 
    offset=4611339809705843188, 
    buff=0x3f844ae4 "TU\204?v\006 \006\275\005J\005\342\004v\004\371\003}\003\006\003\212\002\371\001x", <incomplete sequence \354>, buff_len=1024)
    at /home/pierre/my_project/components/external_storage_manager/external_flash_manager.c:567
#17 0x4010daca in load_music_from_flash_task ()
    at /home/pierre/my_project/components/music_manager/music_manager.c:83
(gdb)

Music task bt when the music crash (see fd=0 => uart_read):

#0  0x400984b4 in xQueueGenericReceive (xQueue=0x3ffbd0b0, pvBuffer=0x0, xTicksToWait=<optimized out>, 
    xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
#1  0x40098564 in xQueueTakeMutexRecursive (xMutex=0x3ffbd0b0, xTicksToWait=4294967295)
    at /home/pierre/my_project/common/esp-idf/components/freertos/queue.c:635
#2  0x40087819 in lock_acquire_generic (lock=0x3ffc3664 <s_context+8>, delay=4294967295, 
    mutex_type=4 '\004')
    at /home/pierre/my_project/common/esp-idf/components/newlib/locks.c:157
#3  0x400878ec in _lock_acquire_recursive (lock=0x3ffc3664 <s_context+8>)
    at /home/pierre/my_project/common/esp-idf/components/newlib/locks.c:171
#4  0x40127eb1 in uart_read (fd=0, data=0x3fffa9f8, size=128)
    at /home/pierre/my_project/common/esp-idf/components/vfs/vfs_uart.c:238
#5  0x40128688 in esp_vfs_read (r=<optimized out>, fd=0, dst=0x3fffa9f8, size=128)
    at /home/pierre/my_project/common/esp-idf/components/vfs/vfs.c:446
#6  0x40092104 in __sread (ptr=0x3ffee7b4, cookie=0x3f804e64, 
    buf=0x3fffa9f8 "\370\377\377?\371\372P\372\270\371\064\371\277\370Y\370\006\370\306\367\214\367^\367\062\367", <incomplete sequence \367>, n=128)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/stdio.c:47
#7  0x400919cd in __srefill_r (ptr=<optimized out>, fp=0x3f804e64)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/refill.c:117
#8  0x4010e4e1 in _fread_r (ptr=0x3ffee7b4, buf=<optimized out>, size=1, count=1024, fp=0x3f804e64)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/fread.c:228
#9  0x4010e580 in fread (buf=0x3f846ecc, size=1, count=1024, fp=0x3f804e64)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/fread.c:266
#10 0x401a4755 in spi_ext_flash_read_with_offset (
    file_path=0x3ffc7080 <played_music_path> "/music_files/brahms.raw", modes=<optimized out>, 
    offset=4611589347307370472, 
    buff=0x3f846ecc "l\201\204?\260\375\220\375u\375[\375E\375*\375\022\375\377\374\022\375\377\374\320\374\301\374\272\374\267\374\264\374\262\374\252\374\246\374\252\374\273\374\274\374\310\374\314\374\335\374\360\374\005\375\035\375B\375\\\375x\375\227\375\274\375\341\375\r\376>\376s\376\234\376\306\376\375\376\066\377o\377\256\377\342\377\030", buff_len=1024)
    at /home/pierre/my_project/components/external_storage_manager/external_flash_manager.c:567
#11 0x4010daca in load_music_from_flash_task ()
    at /home/pierre/my_project/components/music_manager/music_manager.c:83
(gdb)

Here another occurrence but with v4.1-beta1.

We see again that uart_read is called in stead of vfs_fat_rea.

Thread list

Thread 1 received signal SIGINT, Interrupt.
[Switching to Thread 1073435524]
0x40199637 in r_rwip_sleep ()
(gdb) i thread
  Id   Target Id         Frame 
* 1    Thread 1073435524 (Name: btController, State: Running @CPU0) 0x40199637 in r_rwip_sleep ()
  2    Thread 1073460188 (Name: IDLE1, State: Running @CPU1) 0x401fd8c2 in esp_pm_impl_waiti ()
    at /home/pierre/my_project/common/esp-idf/components/esp32/pm_esp32.c:484
  3    Thread 1073458276 (Name: IDLE0) 0x401fd8c2 in esp_pm_impl_waiti ()
    at /home/pierre/my_project/common/esp-idf/components/esp32/pm_esp32.c:484
  4    Thread 1073653644 (Name: btuT) btm_bda_to_acl (
    bda=<error reading variable: Asked for position 64 of stack, stack only has 2 elements on it.>, 
    transport=<error reading variable: DWARF-2 expression error: `DW_OP_reg' operations must be used either alone or in conjunction with DW_OP_piece or DW_OP_bit_piece.>)
    at /home/pierre/my_project/common/esp-idf/components/bt/host/bluedroid/stack/btm/btm_acl.c:95
  5    Thread 1073625920 (Name: hciT) 0x4000bff0 in ?? ()
  6    Thread 1073674528 (Name: band_tmp_data_t) 0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  7    Thread 1073714856 (Name: mqtt_task) 0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  8    Thread 1073464660 (Name: Tmr Svc) 0x4009b03f in prvProcessTimerOrBlockTask (
    xListWasEmpty=<error reading variable: Unhandled dwarf expression opcode 0x0>, 
    xNextExpireTime=<error reading variable: Unhandled dwarf expression opcode 0x0>)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  9    Thread 1073703684 (Name: periodic_task) 0x4000bff0 in ?? ()
  10   Thread 1073541248 (Name: tiT) 0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  11   Thread 1073454656 (Name: ipc1) 0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  12   Thread 1073695880 (Name: update_manager) 0x4000bff0 in ?? ()
  13   Thread 1073679000 (Name: dl_task) 0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  14   Thread 1073624044 (Name: httpd) 0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  15   Thread 1073445924 (Name: ipc0) 0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  16   Thread 1073444044 (Name: esp_timer) 0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  17   Thread 1073555040 (Name: wifi) 0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  18   Thread 1073438080 (Name: BTC_TASK) 0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  19   Thread 1073661488 (Name: i2s_read_task) 0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  20   Thread 1073666984 (Name: music_play_task) 0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  21   Thread 1073609888 (Name: uart_event_task) 0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  22   Thread 1073546236 (Name: sys_evt) 0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  23   Thread 1073456364 (Name: main) 0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  24   Thread 1073706620 (Name: debug_task_core) 0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214

music_play_task

(gdb) thread 20
[Switching to thread 20 (Thread 1073666984)]
#0  0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
214     return id;
(gdb) bt
#0  0x40098454 in xQueueGenericReceive (
    xQueue=<error reading variable: Unhandled dwarf expression opcode 0x5>, 
    pvBuffer=<error reading variable: Asked for position 0 of stack, stack only has 0 elements on it.>, 
    xTicksToWait=<error reading variable: Unhandled dwarf expression opcode 0x1>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
#1  0x40098504 in xQueueTakeMutexRecursive (
    xMutex=<error reading variable: Unhandled dwarf expression opcode 0x0>, xTicksToWait=4294967295)
    at /home/pierre/my_project/common/esp-idf/components/freertos/queue.c:634
#2  0x400875e9 in lock_acquire_generic (
    lock=<error reading variable: Unhandled dwarf expression opcode 0x0>, 
    delay=<error reading variable: Unhandled dwarf expression opcode 0xc4>, mutex_type=4 '\004')
    at /home/pierre/my_project/common/esp-idf/components/newlib/locks.c:157
#3  0x400876bc in _lock_acquire_recursive (lock=0x3ffc3668 <s_context+8>)
    at /home/pierre/my_project/common/esp-idf/components/newlib/locks.c:171
#4  0x4012cd25 in uart_read (fd=<optimized out>, data=<optimized out>, size=128)
    at /home/pierre/my_project/common/esp-idf/components/vfs/vfs_uart.c:251
#5  0x4012d4fc in esp_vfs_read (
    r=<error reading variable: DWARF-2 expression error: `DW_OP_reg' operations must be used either alone or in conjunction with DW_OP_piece or DW_OP_bit_piece.>, fd=<optimized out>, dst=0x3fffa600, size=128)
    at /home/pierre/my_project/common/esp-idf/components/vfs/vfs.c:446
#6  0x40092a2c in __sread (ptr=<optimized out>, cookie=0x3f804e58, 
    buf=0x3fffa600 "D\247\377?S\005*\005\377\004\314\004\230\004]\004$\004\347\003\255\003l\003\035\003\320\002\207\002B\002\355\001\237\001M\001\002\001\247", n=128)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/stdio.c:47
#7  0x400917e5 in __srefill_r (ptr=<optimized out>, fp=<optimized out>)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/refill.c:117
#8  0x401142a5 in _fread_r (ptr=<optimized out>, buf=<optimized out>, 
    size=<error reading variable: Unhandled dwarf expression opcode 0x0>, 
    count=<error reading variable: Unhandled dwarf expression opcode 0x0>, 
    fp=<error reading variable: Unhandled dwarf expression opcode 0x0>)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/fread.c:228
#9  0x40114344 in fread (buf=<optimized out>, size=1, count=1024, fp=0x3f804e58)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/fread.c:266
#10 0x401a9dc1 in spi_ext_flash_read_with_offset (file_path=<optimized out>, 
    modes=<error reading variable: Unhandled dwarf expression opcode 0xe9>, offset=4611585499014405620, 
    buff=0x3f844814 "\bN\204?\263", buff_len=<optimized out>)
    at /home/pierre/my_project/components/external_storage_manager/external_flash_manager.c:567
#11 0x4011388e in load_music_from_flash_task ()
    at /home/pierre/my_project/components/music_manager/music_manager.c:83
(gdb)

btuT

(gdb) thread 4
[Switching to thread 4 (Thread 1073653644)]
#0  btm_bda_to_acl (
    bda=<error reading variable: Asked for position 64 of stack, stack only has 2 elements on it.>, 
    transport=<error reading variable: DWARF-2 expression error: `DW_OP_reg' operations must be used either alone or in conjunction with DW_OP_piece or DW_OP_bit_piece.>)
    at /home/pierre/my_project/common/esp-idf/components/bt/host/bluedroid/stack/btm/btm_acl.c:95
95      tACL_CONN   *p = &btm_cb.acl_db[0];
(gdb) bt
#0  btm_bda_to_acl (
    bda=<error reading variable: Asked for position 64 of stack, stack only has 2 elements on it.>, 
    transport=<error reading variable: DWARF-2 expression error: `DW_OP_reg' operations must be used either alone or in conjunction with DW_OP_piece or DW_OP_bit_piece.>)
    at /home/pierre/my_project/common/esp-idf/components/bt/host/bluedroid/stack/btm/btm_acl.c:95
#1  0x4015f174 in l2cble_notify_le_connection (
    bda=<error reading variable: Unhandled dwarf expression opcode 0x2>)
    at /home/pierre/my_project/common/esp-idf/components/bt/host/bluedroid/stack/l2cap/l2c_ble.c:239
#2  0x4015cf06 in l2c_rcv_acl_data (p_msg=<optimized out>)
    at /home/pierre/my_project/common/esp-idf/components/bt/host/bluedroid/stack/l2cap/l2c_main.c:193
#3  0x4015252f in btu_hci_msg_process (param=0x3f844dec)
    at /home/pierre/my_project/common/esp-idf/components/bt/host/bluedroid/stack/btu/btu_task.c:144
#4  0x40167bf2 in osi_thread_run (
    arg=<error reading variable: Not enough elements for DW_OP_swap.  Need 2, have 0.>)
    at /home/pierre/my_project/common/esp-idf/components/bt/common/osi/thread.c:68
(gdb)

And another with v4.1-beta2

Thread list

[Switching to Thread 1073458276]
0x401f755a in esp_pm_impl_waiti ()
    at /home/pierre/my_project/common/esp-idf/components/esp32/pm_esp32.c:484
484     asm("waiti 0");
(gdb) i thread
  Id   Target Id         Frame 
* 1    Thread 1073458276 (Name: IDLE0, State: Running @CPU0) 0x401f755a in esp_pm_impl_waiti ()
    at /home/pierre/my_project/common/esp-idf/components/esp32/pm_esp32.c:484
  2    Thread 1073460188 (Name: IDLE1, State: Running @CPU1) 0x401f755a in esp_pm_impl_waiti ()
    at /home/pierre/my_project/common/esp-idf/components/esp32/pm_esp32.c:484
  3    Thread 1073717412 (Name: mqtt_task) 0x40097454 in xQueueGenericReceive (xQueue=0x3fffa218, 
    pvBuffer=0x0, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  4    Thread 1073676328 (Name: band_tmp_data_t) 0x40097454 in xQueueGenericReceive (xQueue=0x3f83b8bc, 
    pvBuffer=0x3ffefec0, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  5    Thread 1073464660 (Name: Tmr Svc) 0x4009a03f in prvProcessTimerOrBlockTask (
    xListWasEmpty=<optimized out>, xNextExpireTime=6749)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  6    Thread 1073541040 (Name: tiT) 0x40097454 in xQueueGenericReceive (xQueue=0x3f831a64, 
    pvBuffer=0x3ffcef10, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  7    Thread 1073705416 (Name: periodic_task) 0x4000bff0 in ?? ()
  8    Thread 1073454656 (Name: ipc1) 0x40097454 in xQueueGenericReceive (xQueue=0x3ffb7e58, 
    pvBuffer=0x0, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  9    Thread 1073697560 (Name: update_manager) 0x4000bff0 in ?? ()
  10   Thread 1073680800 (Name: dl_task) 0x40097454 in xQueueGenericReceive (xQueue=0x3f83fac4, 
    pvBuffer=0x3f83a8f8, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  11   Thread 1073624020 (Name: httpd) 0x40097454 in xQueueGenericReceive (xQueue=0x3ffe35a0, 
    pvBuffer=0x0, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  12   Thread 1073609868 (Name: uart_event_task) 0x40097454 in xQueueGenericReceive (xQueue=0x3f805f24, 
    pvBuffer=0x3ffdfbf0, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  13   Thread 1073445924 (Name: ipc0) 0x40097454 in xQueueGenericReceive (xQueue=0x3ffb77c0, 
    pvBuffer=0x0, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  14   Thread 1073444044 (Name: esp_timer) 0x40097454 in xQueueGenericReceive (
    xQueue=0x3ffc5c28 <s_timer_semaphore_memory>, pvBuffer=0x0, xTicksToWait=<optimized out>, 
    xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  15   Thread 1073435532 (Name: btController) 0x40097454 in xQueueGenericReceive (xQueue=0x3ffb5320, 
    pvBuffer=0x3ffe52d0, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  16   Thread 1073554832 (Name: wifi) 0x40097454 in xQueueGenericReceive (xQueue=0x3ffd04ec, 
    pvBuffer=0x3ffd24f0, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  17   Thread 1073438088 (Name: BTC_TASK) 0x40097454 in xQueueGenericReceive (xQueue=0x3ffb5c68, 
    pvBuffer=0x0, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  18   Thread 1073653624 (Name: btuT) 0x40097454 in xQueueGenericReceive (xQueue=0x3ffe84b4, 
    pvBuffer=0x0, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  19   Thread 1073625912 (Name: hciT) 0x40097454 in xQueueGenericReceive (xQueue=0x3ffe3a18, 
    pvBuffer=0x0, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  20   Thread 1073663288 (Name: i2s_read_task) 0x40097454 in xQueueGenericReceive (xQueue=0x3f83a870, 
    pvBuffer=0x3ffc7cc8 <i2s_tmp_buffer>, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  21   Thread 1073668784 (Name: music_play_task) 0x40097454 in xQueueGenericReceive (xQueue=0x3ffbd250, 
    pvBuffer=0x0, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  22   Thread 1073546028 (Name: sys_evt) 0x40097454 in xQueueGenericReceive (xQueue=0x3f831b44, 
    pvBuffer=0x3ffd0250, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  23   Thread 1073456364 (Name: main) 0x40097454 in xQueueGenericReceive (xQueue=0x3f805834, 
    pvBuffer=0x0, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
  24   Thread 1073708660 (Name: debug_task_core) 0x40097454 in xQueueGenericReceive (xQueue=0x3f83aba8, 
    pvBuffer=0x3fff7dd0, xTicksToWait=<optimized out>, xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214

music_play_task

(gdb) thread 21
[Switching to thread 21 (Thread 1073668784)]
#0  0x40097454 in xQueueGenericReceive (xQueue=0x3ffbd250, pvBuffer=0x0, xTicksToWait=<optimized out>, 
    xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
214     return id;
(gdb) bt
#0  0x40097454 in xQueueGenericReceive (xQueue=0x3ffbd250, pvBuffer=0x0, xTicksToWait=<optimized out>, 
    xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
#1  0x40097504 in xQueueTakeMutexRecursive (xMutex=0x3ffbd250, xTicksToWait=4294967295)
    at /home/pierre/my_project/common/esp-idf/components/freertos/queue.c:634
#2  0x40087599 in lock_acquire_generic (lock=0x3ffc3638 <s_context+8>, delay=4294967295, 
    mutex_type=4 '\004')
    at /home/pierre/my_project/common/esp-idf/components/newlib/locks.c:157
#3  0x4008766c in _lock_acquire_recursive (lock=0x3ffc3638 <s_context+8>)
    at /home/pierre/my_project/common/esp-idf/components/newlib/locks.c:171
#4  0x40126821 in uart_read (fd=0, data=0x3fffa5a8, size=128)
    at /home/pierre/my_project/common/esp-idf/components/vfs/vfs_uart.c:251
#5  0x40126ff8 in esp_vfs_read (r=<optimized out>, fd=0, dst=0x3fffa5a8, size=128)
    at /home/pierre/my_project/common/esp-idf/components/vfs/vfs.c:446
#6  0x40091d98 in __sread (ptr=0x3ffee324, cookie=0x3f804e58, 
    buf=0x3fffa5a8 "\370\377\377?\234\245\377?\371\377\377?\370\377\377?\352\b\023\b7\aa\006z\005\236\004\302\003\305\002\256\001\245", n=128)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/stdio.c:47
#7  0x40090fd5 in __srefill_r (ptr=<optimized out>, fp=0x3f804e58)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/refill.c:117
#8  0x4010de61 in _fread_r (ptr=0x3ffee324, buf=<optimized out>, size=1, count=1024, fp=0x3f804e58)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/fread.c:228
#9  0x4010df00 in fread (buf=0x3f847560, size=1, count=1024, fp=0x3f804e58)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/fread.c:266
#10 0x401a3791 in spi_ext_flash_read_with_offset (
    file_path=0x3ffc6840 <played_music_path> "/music_files/brahms.raw", modes=<optimized out>, 
    offset=4611585361575307264, 
    buff=0x3f847560 "\364\377\277?\\\001n\001x\001\204\001\206\001\221\001\221\001\222\001\207\001\204\001\203\001m\001]\001C\001\066\001&\001\r", <incomplete sequence \363>, buff_len=1024)
    at /home/pierre/my_project/components/external_storage_manager/external_flash_manager.c:567
#11 0x4010d44a in load_music_from_flash_task ()
    at /home/pierre/my_project/components/music_manager/music_manager.c:83
(gdb) 
#0  0x40097454 in xQueueGenericReceive (xQueue=0x3ffbd250, pvBuffer=0x0, xTicksToWait=<optimized out>, 
    xJustPeeking=0)
    at /home/pierre/my_project/common/esp-idf/components/freertos/include/freertos/portable.h:214
#1  0x40097504 in xQueueTakeMutexRecursive (xMutex=0x3ffbd250, xTicksToWait=4294967295)
    at /home/pierre/my_project/common/esp-idf/components/freertos/queue.c:634
#2  0x40087599 in lock_acquire_generic (lock=0x3ffc3638 <s_context+8>, delay=4294967295, 
    mutex_type=4 '\004')
    at /home/pierre/my_project/common/esp-idf/components/newlib/locks.c:157
#3  0x4008766c in _lock_acquire_recursive (lock=0x3ffc3638 <s_context+8>)
    at /home/pierre/my_project/common/esp-idf/components/newlib/locks.c:171
#4  0x40126821 in uart_read (fd=0, data=0x3fffa5a8, size=128)
    at /home/pierre/my_project/common/esp-idf/components/vfs/vfs_uart.c:251
#5  0x40126ff8 in esp_vfs_read (r=<optimized out>, fd=0, dst=0x3fffa5a8, size=128)
    at /home/pierre/my_project/common/esp-idf/components/vfs/vfs.c:446
#6  0x40091d98 in __sread (ptr=0x3ffee324, cookie=0x3f804e58, 
    buf=0x3fffa5a8 "\370\377\377?\234\245\377?\371\377\377?\370\377\377?\352\b\023\b7\aa\006z\005\236\004\302\003\305\002\256\001\245", n=128)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/stdio.c:47
#7  0x40090fd5 in __srefill_r (ptr=<optimized out>, fp=0x3f804e58)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/refill.c:117
#8  0x4010de61 in _fread_r (ptr=0x3ffee324, buf=<optimized out>, size=1, count=1024, fp=0x3f804e58)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/fread.c:228
#9  0x4010df00 in fread (buf=0x3f847560, size=1, count=1024, fp=0x3f804e58)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/fread.c:266
#10 0x401a3791 in spi_ext_flash_read_with_offset (
    file_path=0x3ffc6840 <played_music_path> "/music_files/brahms.raw", modes=<optimized out>, 
    offset=4611585361575307264, 
    buff=0x3f847560 "\364\377\277?\\\001n\001x\001\204\001\206\001\221\001\221\001\222\001\207\001\204\001\203\001m\001]\001C\001\066\001&\001\r", <incomplete sequence \363>, buff_len=1024)
    at /home/pierre/my_project/components/external_storage_manager/external_flash_manager.c:567
#11 0x4010d44a in load_music_from_flash_task ()
    at /home/pierre/my_project/components/music_manager/music_manager.c:83
(gdb)

Looks like fp=0x3f804e58, are you using PSRAM?

If yes, which chip revision are you using? You can find it in esptool.py output when flashing.

Yes, I'm not flashing with esptool.py but directly with openocd. But, at startup, I have in the log:

(32) boot: chip revision: 1

(The chip revision come from bootloader_common_get_chip_revision()).

What are you thinking of when you say:

Looks like fp=0x3f804e58

I was still using GNU Make to compile my project. Now, I convert all my project to be able to used 'Cmake' and the idf.py build tool in order to be sure to have the flag '-mfix-esp32-psram-cache-issue'.

Here my spiram sdkconfig (see: CONFIG_SPIRAM_CACHE_WORKAROUND=y):

CONFIG_ESP32_SPIRAM_SUPPORT=y
CONFIG_SPIRAM_BOOT_INIT=y
# CONFIG_SPIRAM_USE_MEMMAP is not set
# CONFIG_SPIRAM_USE_CAPS_ALLOC is not set
CONFIG_SPIRAM_USE_MALLOC=y
CONFIG_SPIRAM_TYPE_AUTO=y
# CONFIG_SPIRAM_TYPE_ESPPSRAM32 is not set
# CONFIG_SPIRAM_TYPE_ESPPSRAM64 is not set
CONFIG_SPIRAM_SIZE=-1
CONFIG_SPIRAM_SPEED_40M=y
CONFIG_SPIRAM_MEMTEST=y
CONFIG_SPIRAM_CACHE_WORKAROUND=y
CONFIG_SPIRAM_BANKSWITCH_ENABLE=y
CONFIG_SPIRAM_BANKSWITCH_RESERVE=8
CONFIG_SPIRAM_MALLOC_ALWAYSINTERNAL=128
CONFIG_SPIRAM_TRY_ALLOCATE_WIFI_LWIP=y
CONFIG_SPIRAM_MALLOC_RESERVE_INTERNAL=69632
# CONFIG_SPIRAM_ALLOW_STACK_EXTERNAL_MEMORY is not set
CONFIG_SPIRAM_ALLOW_BSS_SEG_EXTERNAL_MEMORY=y
CONFIG_D0WD_PSRAM_CLK_IO=17
CONFIG_D0WD_PSRAM_CS_IO=16
CONFIG_D2WD_PSRAM_CLK_IO=9
CONFIG_D2WD_PSRAM_CS_IO=10
CONFIG_PICO_PSRAM_CS_IO=10
CONFIG_SPIRAM_SPIWP_SD3_PIN=7
# CONFIG_SPIRAM_2T_MODE is not set

But I have the same issue. I did the test with Cmake and v4.0.1 LTS. I have the same bt as in the first comment (fd=0 and fp=0x3f804e58 is replaced by fp=0x3f804e64):

music_play_task

[Switching to thread 20 (Thread 1073668132)]
#0  0x40098cd0 in xQueueGenericReceive (xQueue=0x3ffbd0b0, pvBuffer=0x0, xTicksToWait=<optimized out>, 
    xJustPeeking=0) at ../common/esp-idf/components/freertos/include/freertos/portable.h:214
214     return id;
(gdb) bt
#0  0x40098cd0 in xQueueGenericReceive (xQueue=0x3ffbd0b0, pvBuffer=0x0, xTicksToWait=<optimized out>, 
    xJustPeeking=0) at ../common/esp-idf/components/freertos/include/freertos/portable.h:214
#1  0x40098d80 in xQueueTakeMutexRecursive (xMutex=0x3ffbd0b0, xTicksToWait=4294967295)
    at ../common/esp-idf/components/freertos/queue.c:635
#2  0x40084a11 in lock_acquire_generic (lock=0x3ffbef78 <s_context+8>, delay=4294967295, 
    mutex_type=4 '\004') at ../common/esp-idf/components/newlib/locks.c:157
#3  0x40084ae4 in _lock_acquire_recursive (lock=0x3ffbef78 <s_context+8>)
    at ../common/esp-idf/components/newlib/locks.c:171
#4  0x400d7f45 in uart_read (fd=0, data=0x3fffa9b4, size=128)
    at ../common/esp-idf/components/vfs/vfs_uart.c:238
#5  0x400d6d8c in esp_vfs_read (r=<optimized out>, fd=0, dst=0x3fffa9b4, size=128)
    at ../common/esp-idf/components/vfs/vfs.c:446
#6  0x40090ff0 in __sread (ptr=0x3ffee098, cookie=0x3f804e64, 
    buf=0x3fffa9b4 " \253\377?)\374J\374k\374\236\374\316\374\001\375?\375w\375\300\375\376\375I\376\215\376\323\376\025\377U\377\233\377\326\377\020", n=128)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/stdio.c:47
#7  0x4009319d in __srefill_r (ptr=<optimized out>, fp=0x3f804e64)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/refill.c:117
#8  0x401da199 in _fread_r (ptr=0x3ffee098, buf=<optimized out>, size=1, count=1024, fp=0x3f804e64)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/fread.c:228
#9  0x401da238 in fread (buf=0x3f847038, size=1, count=1024, fp=0x3f804e64)
    at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/fread.c:266
#10 0x400de209 in spi_ext_flash_read_with_offset (
    file_path=0x3ffc7978 <played_music_path> "/music_files/brahms.raw", modes=<optimized out>, 
    offset=4611590120397752058, 
    buff=0x3f847038 "\364t\204?\035\b!\b\037\b\f\b\366\a\333\a\275\a\212\aT\a\022\a\316\006\177\006)\006\323\005r\005\023\005\253\004F\004\330\003g\003\371\002\211\002\031\002\241\001\063", <incomplete sequence \304>, buff_len=1024) at ../components/external_storage_manager/external_flash_manager.c:567
#11 0x400e45b5 in load_music_from_flash_task () at ../components/music_manager/music_manager.c:83
(gdb)

@pbruynbroeckQuimesis It is possible that you are running into the PSRAM cache bug. I has been fixed in ESP32 revision 3. The compiler used in IDF 4.0.x (which is not an LTS version, by the way) and 4.1 does not fully work around the PSRAM cache bug on ESP32 revision 1.

Suggest trying a few things:

Try running the program on ESP32 revision 3 (WROVER-E module). If it doesn't exhibit the same behavior, then likely the issue was related to PSRAM cache bug.
Try building the program with a different toolchain version, 2020r2. It is used in master branch now. Releases 4.0 and 4.1 will be updated to use 2020r2 toolchain soon.
Try increasing CONFIG_SPIRAM_MALLOC_ALWAYSINTERNAL option. This may move the FILE structure from PSRAM into the internal memory, which could work around the issue.

Thank you, with 2020r2 I don't have anymore this kind of issue but I have another.

Now, after an random time (sometimes 5 min, sometimes 5 hours...), the ESP stop on 'tiT' thread with the backtrace:

[Switching to thread 1 (Thread 1073608748)]
#0  invoke_abort ()
    at /home/pierre/my_project/common/esp-idf/components/esp32/panic.c:162
162 in /home/pierre/my_project/common/esp-idf/components/esp32/panic.c
(gdb) bt
#0  invoke_abort ()
    at /home/pierre/my_project/common/esp-idf/components/esp32/panic.c:162
#1  0x40093d7c in abort ()
    at /home/pierre/my_project/common/esp-idf/components/esp32/panic.c:179
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

And the log:

esp32> assertion "pbuf_free: p->ref > 0" failed: file "/home/pierre/my_project/common/esp-idf/components/lwip/lwip/src/core/pbuf.c", line 757, function: pbuf_free
abort() was called at PC 0x4010e1c8 on core 1

Do you think that is linked to the PSRAM cache issue ?

(full_backtrace.log)

New occurrence with more informations about the tiT backtrace:

esp32> assertion "pbuf_free: p->ref > 0" failed: file "/home/my_project/common/esp-idf/components/lwip/lwip/src/core/pbuf.c", line 757, function: pbuf_free
abort() was called at PC 0x4010e1c8 on core 0
Task running on core  0 : tiT/nTask running on core  1 : IDLE1/n
ELF file SHA256: f2c09ae1dea277b1

Backtrace: 0x40093984:0x3ffd0690 0x40093d79:0x3ffd06b0 0x4010e1c8:0x3ffd06d0 0x401ae9c1:0x3ffd0700 0x401af1dc:0x3ffd0720 0x401b3b73:0x3ffd0770 0x401b880b:0x3ffd07a0 0x401a8f99:0x3ffd07c0

Rebooting...

0x40093984: invoke_abort at /home/my_project/common/esp-idf/components/esp32/panic.c:164
0x40093d79: abort at /home/my_project/common/esp-idf/components/esp32/panic.c:179
0x4010e1c8: __assert_func at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/newlib/newlib/libc/stdlib/assert.c:62 (discriminator 8)
0x401ae9c1: pbuf_free at /home/my_project/common/esp-idf/components/lwip/lwip/src/core/pbuf.c:767
0x401af1dc: udp_input at /home/my_project/common/esp-idf/components/lwip/lwip/src/core/udp.c:222
0x401b3b73: ip4_input at /home/my_project/common/esp-idf/components/lwip/lwip/src/core/ipv4/ip4.c:778
0x401b880b: ethernet_input at /home/my_project/common/esp-idf/components/lwip/lwip/src/netif/ethernet.c:186
0x401a8f99: tcpip_thread_handle_msg at /home/my_project/common/esp-idf/components/lwip/lwip/src/api/tcpip.c:180
 (inlined by) tcpip_thread at /home/my_project/common/esp-idf/components/lwip/lwip/src/api/tcpip.c:154

Thanks for the report @pbruynbroeckQuimesis, we have now met a similar issue in our tests. Will let you know when the fix is found.

@pbruynbroeckQuimesis The toolchain has been updated to 2020r3 release on the release/v4.0 branch in 6093407, this update should resolve the issue you are seeing.

So igrr - for those of us running v4.1, how do we pick up this toolchain? I tried downloading it and copying it to the correct location, but esp-idf-tools-setup-2.3 doesn't seem to add it, and the esp-idf command tool still uses r2.

Thanks...

@mzimmers For release/v4.1 branch, you need to update to commit c7ba54e or later. Then run install.bat to install new tools, export.bat to update the environment variables. Or use esp-idf-tools-setup-2.3.exe, pointing to your existing ESP-IDF directory, and let it download the tools (should be the same as running install.bat).

Hi igrr - I did all that, now get this during build:

[891/935] Performing configure step for 'bootloader' -- Project version: v4.1-352-g5d258af93 -- Building ESP-IDF components for target esp32 CMake Warning at C:/esp-idf/tools/cmake/crosstool_version_check.cmake:8 (message): Xtensa toolchain C:/esp32-toolchain/.espressif/tools/xtensa-esp32-elf/esp-2020r2-8.2.0/xtensa-esp32-elf/bin/xtensa-esp32-elf-gcc.exe version 8.2.0 is not the supported version 8.4.0. Check Getting Started documentation or proceed at own risk. Call Stack (most recent call first): C:/esp-idf/components/esp32/project_include.cmake:30 (gcc_version_check) C:/esp-idf/tools/cmake/build.cmake:306 (include) C:/esp-idf/tools/cmake/build.cmake:451 (__build_process_project_includes) C:/esp-idf/tools/cmake/project.cmake:396 (idf_build_process) CMakeLists.txt:27 (project)

Did I miss a step?

EDIT: I did a fullclean (instead of just a clean) and it worked. I'll test it to see if my GME problems go away. Thanks!

igrr: I'm still getting my GME problem. I'm about out of ideas on this, and time is running short.

@mzimmers Could you please describe your GME problem? It is possible that it isn't related to the PSRAM cache issue.

Every so often (interval varies between ~1-6 hours) a unit reports this via the console: `Guru Meditation Error: Core 0 panic'ed (IllegalInstruction). Exception was unhandled. Memory dump at 0x4008503c: fff72502 0000f01d d2004136 Core 0 register dump: PC : 0x40085040 PS : 0x00060130 A0 : 0x00040020 A1 : 0x3fff36e0 A2 : 0x3f8140f8 A3 : 0x00000005 A4 : 0x00000001 A5 : 0x00000156 A6 : 0x00000090 A7 : 0x00000003 A8 : 0x80085040 A9 : 0x3fff36b0 A10 : 0x3f8140f8 A11 : 0x3fffa47c A12 : 0xd5bb3203 A13 : 0xd613b8c4 A14 : 0x00000001 A15 : 0x00000000 SAR : 0x00000018 EXCCAUSE: 0x00000000 EXCVADDR: 0x00000000 LBEG : 0x40151ac8 LEND : 0x40151af3 LCOUNT : 0x00000007

ELF file SHA256: 0b31fee1d1ac8ee7

Backtrace: 0x4008503d:0x3fff36e0 0x0004001d:0x3fff3700 |<-CORRUPTED

Rebooting...`

I don't know what else to say about this, except it's a relatively recent occurrence (I think it might coincide with my move to v4.1). Would you like me to open a new issue for this?

Thanks for posting the panic handler output, @mzimmers. The issue you are seeing is this one: https://github.com/espressif/esp-idf/issues/5758. The sign of this issue is that A0 register is corrupted with a specific value: (A0 : 0x00040020). The issue has been fixed on the master branch in 52d93561, but the fix hasn't yet made it into release/v4.1. I'm attaching a patch which you can apply until the fix is merged. 10306.zip

Oh, that's a huge relief to hear...thanks so much, igrr. I don't know how to apply patches, though...can you direct me to a page that has instructions?

Thanks again.

EDIT: OK, applying a patch seems simple enough. I did get a warning about whitespace in the patch: $ git apply 10306.patch 10306.patch:42: trailing whitespace. * warning: 1 line adds whitespace errors. Is this anything I should be concerned with?

@mzimmers that whitespace warning should cause issues, i think. Did the patch fix the crash you have observed?

Hi igrr - yes, I've been running tests for nearly 24 hours now, without a crash, so I feel confident the problem is resolved.

The patch touched 4 files:

modified: components/cxx/test/test_cxx.cpp modified: components/freertos/xtensa_context.S added: components/freertos/test/test_context_save_clobber.c added: components/freertos/test/test_context_save_clobber_asm.S

Does that look right to you?

That looks right. The one in components/freertos/xtensa_context.S is the actual fix, rest of the files are just regression test cases. Good to know the problem is resolved!

espressif / esp-idf

esp_vfs_read call the wrong reading function and freeze a thread (IDFGH-3463) #5423

Environment

Problem Description