search

espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.85k stars 7.32k forks source link

Filesystem FatFS debug error with PSRAM Enabled (IDFGH-9675) #11016

Open Duolabs opened 1 year ago

Duolabs commented 1 year ago

Answers checklist.

IDF version.

ESP-IDF v5.0.1-dirty

Operating System used.

Linux

How did you build your project?

Eclipse IDE

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

None

Development Kit.

ESP32-S3-WROOM-1U-N8R2

Power Supply used.

USB

What is the expected behavior?

Regular debugging with PSRAM enabled.

What is the actual behavior?

When we start debugging using Internal Built-in JTag when function esp_vfs_fat_spiflash_mount_rw_wl is called you get stuck at spinlock_acquire(). If you do not enalbe and use the Support for external, SPI-connected RAM everything works fine. As soon as you enable it you won't be able to DEBUG. Please note that in RUN mode the application works fine, just debugging as metioned above is not working.

Steps to reproduce.

  1. Take example: examples/storage/fatfsgen from IDF examples.
  2. Activate PSRAM by setting Support for external, SPI-connected RAM is sdkconfig ESP PSRAM
  3. Set Clock speed at 80Mhz
  4. Set option Make RAM allocatable using malloc() as well
  5. Start debugging and you will land in spinlock_acquire() error

Debug Logs.

Stop when **esp_vfs_fat_spiflash_mount_rw_wl** function at **ff_memalloc()** 

Thread #3 [main] 1070545212 (Name: main, State: Running @CPU0) (Suspended : Signal : SIGTRAP:Trace/breakpoint trap) 
    spinlock_acquire() at spinlock.h:89 0x403808c9  
    xPortEnterCriticalTimeout() at port.c:311 0x403808c9    
    vPortEnterCritical() at portmacro.h:573 0x40382fd8  
    multi_heap_internal_lock() at multi_heap.c:162 0x40382fd8   
    multi_heap_malloc_impl() at multi_heap.c:206 0x40383002 
    heap_caps_malloc_base() at heap_caps.c:145 0x40376544   
    heap_caps_malloc_prefer() at heap_caps.c:260 0x4037668a 
    ff_memalloc() at ffsystem.c:20 0x4201019c   
    esp_vfs_fat_register() at vfs_fat.c:161 0x42011760  
    esp_vfs_fat_spiflash_mount_rw_wl() at vfs_fat_spiflash.c:60 0x4200caa4  
    <...more frames...>

More Information.

We need to use external in-module PSRAM for our application. We've tried other options rather than "Make RAM allocatable using malloc() as well" in PSRAM usage but the other part of the application fails. As mentioned above it RUN mode the application works fine. Our suspect is that there is a lack of heap during debug. Please help us!

igrr commented 1 year ago

Hi @Duolabs, IDF release v5.0.1 is using OpenOCD version v0.11.0-esp32-20221026, which didn't have support for debugging when PSRAM is used on ESP32-S3. This was implemented in OpenOCD release v0.12.0-esp32-20230221. We'll update the OpenOCD version used in IDF in the next bugfix release, v5.0.2.

Duolabs commented 1 year ago

@igrr Hi Igrr and thank you for your prompt reply. I am using OPENOCD_SCRIPTS: /root/.espressif/tools/openocd-esp32/v0.11.0-esp32-20221026/openocd-esp32/share/openocd/scripts I can can debug the remaining part of the code without any problem if I leave the ESP PSRAM Active as mentioned before. So I need to disagree with the fact that is not supported, I'd better say that it is not bug free or either it may lead to failures.

Well I will try to install OpenOCD release v0.12.0-esp32-20230221 manually instead of waiting for new IDF. QUESTION: Do I simply need to copy the new OpenOCD onto the existing ones or what? Can you help me in that before I crash on it for days? :)

This is my today's configuration:

_Executing /usr/bin/python3 /home/ubuntu/esp/esp-idf-v5.0.1/tools/idf_tools.py list

CDT Build environment variables PATH: /root/.espressif/tools/xtensa-esp-elf-gdb/11.2_20220823/xtensa-esp-elf-gdb/bin:/root/.espressif/tools/riscv32-esp-elf-gdb/11.2_20220823/riscv32-esp-elf-gdb/bin:/root/.espressif/tools/xtensa-esp32-elf/esp-2022r1-11.2.0/xtensa-esp32-elf/bin:/root/.espressif/tools/xtensa-esp32s2-elf/esp-2022r1-11.2.0/xtensa-esp32s2-elf/bin:/root/.espressif/tools/xtensa-esp32s3-elf/esp-2022r1-11.2.0/xtensa-esp32s3-elf/bin:/root/.espressif/tools/xtensa-clang/14.0.0-38679f0333/xtensa-esp32-elf-clang/bin:/root/.espressif/tools/riscv32-esp-elf/esp-2022r1-11.2.0/riscv32-esp-elf/bin:/root/.espressif/tools/esp32ulp-elf/2.35_20220830/esp32ulp-elf/bin:/root/.espressif/tools/openocd-esp32/v0.11.0-esp32-20221026/openocd-esp32/bin:/root/.espressif/tools/ninja/1.10.2/:/root/.espressif/python_env/idf5.0_py3.8_env/bin:/home/ubuntu/esp/esp-idf-v5.0.1/tools:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin XAUTHORITY: /run/user/1000/gdm/Xauthority OXYGEN_DISABLE_INNER_SHADOWS_HACK: 1 TERM: xterm-256color LANG: en_US.UTF-8 ESP_IDF_VERSION: 5.0 SUDO_USER: ubuntu OPENOCD_SCRIPTS: /root/.espressif/tools/openocd-esp32/v0.11.0-esp32-20221026/openocd-esp32/share/openocd/scripts SUDO_GID: 1000 DISPLAY: :0 IDF_DEACTIVATE_FILE_PATH: /tmp/tmpa0pw_28ridf_5445 MAIL: /var/mail/root COLORTERM: truecolor LOGNAME: root SUDO_UID: 1000 SHELL: /bin/bash LIBOVERLAY_SCROLLBAR: 0 IDF_PATH: /home/ubuntu/esp/esp-idf-v5.0.1 GDK_CORE_DEVICE_EVENTS: 1 USER: root SUDO_COMMAND: /home/ubuntu/eclipse/cpp-2022-09/eclipse/eclipse IDF_COMPONENT_MANAGER: 1 IDF_MAINTAINER: 1 LS_COLORS: .. IDF_PYTHON_ENV_PATH: /root/.espressif/python_env/idf5.0_py3.8_env HOME: /root ESP_ROM_ELF_DIR: /root/.espressif/tools/esp-rom-elfs/20220823/

Operating System: linux Java Runtime Version: 17.0.5+8 Eclipse Version: 4.25.0.v20220831-1800 Eclipse CDT Version: 10.7.1.202208160035 IDF Eclipse Plugin Version: 2.7.0.202211101524 ESP-IDF v5.0.1-dirty Python set for IDF_PYTHONENV: Python 3.8.10

Thank you

igrr commented 1 year ago

So I need to disagree with the fact that is not supported, I'd better say that it is not bug free or either it may lead to failures.

That's fair, let's agree on that being a bug in v0.11.0-esp32-20221026 release.

Do I simply need to copy the new OpenOCD onto the existing ones or what?

Unfortunately it's not quite straightforward.

  1. In Eclipse, go to workspace preferences and find "Espressif" > "Workspace OpenOCD path" page.
  2. Set the path to the location where you have extracted the new release. (I highly recommend to not overwrite the old installation. Make a new directory somewhere, instead.)
  3. Save the preferences.
  4. Now go to "C++" > "Build" > "Environment" in workspace preferences, and remove the OPENOCD_SCRIPTS variable.
  5. Close Eclipse.
  6. Run Eclipse and open the same workspace again.
  7. Go to the debug launch configuration window and verify that the new path to OpenOCD is shown.
  8. You can now start debugging.

Another user has reported an issue with this process, but in that case it was solved by step 4: https://github.com/espressif/openocd-esp32/issues/276

If that doesn't work, then I'm afraid the simplest solution is to wait for the next IDF release where OpenOCD version will be updated.

Duolabs commented 1 year ago

Awesome! In the meanwhile I did it myself in a manual way, sorry for making you posting it again but it might help others too. In this case as quick guide for newbies:

  1. Download the latest version of OpenOCD from EspressIf OCD repo.

  2. From console:

cd ~/esp
tar -xzf ~/Downloads/openocd-esp32-linux64-<version>.tar.gz
  1. In your Debug Configuration:

[OpenOCD Setup:

[Config Options:] -s /home/ubuntu/esp/openocd-esp32/share/openocd/scripts -f board/esp32s3-builtin.cfg

Enjoy it! Note in my case the starting path is /home/ubuntu/esp/ when I extracted the tar archive.

4 all you'd better follow igrr's instructions that are more accurate and act on PATHS directly...

So far I tested the really latest version (later than the suggested one) openocd-esp32-linux-amd64-0.12.0-esp32-20230313 of OpenOCD and the problem is magically gone and I can finally debug! What a great day I can finally keep on going. TBH it has been a nightmare trying to trace it all down thinking it was my fault! Dang!

@igrr You made my day dude! I do really appreciate your help & support! Long life to EspressIf!

Duolabs commented 1 year ago

Hi... Too early to speak:

ISSUE 1

I followed the OpenOCD installation and the OPENOCD_SCRIPTS has disappered from the Environment and the "Flash After everytime application binaries" is gone too from "Startup" is Debug Configuration. I added it manually with the old path: /root/.espressif/tools/openocd-esp32/v0.11.0-esp32-20221026/openocd-esp32/share/openocd/scripts This should not be right I guess...

ISSUE 2

The old code is working but when I try to debug it I always get:

Error in services launch sequence Starting OpenOCD timed out.

If I unplug the board and plug it in again the code works OK. If I short the code with a while (1) after a few instructions I am able to debug but of course this is not a feasable work around.

I had similar problems when I had partition errors. Here is my partition.cvs

# Name,   Type, SubType, Offset,  Size, Flags
# Note: if you have increased the bootloader size, make sure to update the offsets to avoid overlap
nvs,      data, nvs,     ,  0x6000,
phy_init, data, phy,     ,  0x1000,
factory,  app,  factory, , 4M,
storage,  data, fat,     , 1M,
app_data, data, nvs,  , 100k,

and in my CMakeList.txt

fatfs_create_spiflash_image(storage ../Application_Filesystem FLASH_IN_PROJECT PRESERVE_TIME)

IF I DO NOT FLASH IT IN PROJECT I CAN DEBUG

I get this OpenOCD Log:

Info : only one transport option; autoselecting 'jtag'
Info : esp_usb_jtag: VID set to 0x303a and PID to 0x1001
Info : esp_usb_jtag: capabilities descriptor set to 0x2000
Warn : Transport "jtag" was already selected
Info : esp_usb_jtag: serial (F4:12:FA:C0:A5:5C)
Info : esp_usb_jtag: Device found. Base speed 40000KHz, div range 1 to 255
Info : clock speed 40000 kHz
Info : JTAG tap: esp32s3.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32s3.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : starting gdb server for esp32s3.cpu0 on 3333
Info : Listening on port 3333 for gdb connections
Info : JTAG tap: esp32s3.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32s3.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : [esp32s3.cpu0] requesting target halt and executing a soft reset
Info : [esp32s3.cpu0] Target halted, PC=0x4037AF4A, debug_reason=00000000
Info : [esp32s3.cpu0] Reset cause (3) - (Software core reset)
Info : Set GDB target to 'esp32s3.cpu0'
Info : [esp32s3.cpu1] Target halted, PC=0x4037AF4A, debug_reason=00000000
Info : [esp32s3.cpu1] Reset cause (3) - (Software core reset)
Info : [esp32s3.cpu0] Debug controller was reset.
Info : [esp32s3.cpu0] Core was reset.
Info : [esp32s3.cpu0] Target halted, PC=0x500000EF, debug_reason=00000000
Info : [esp32s3.cpu0] Reset cause (3) - (Software core reset)
Info : [esp32s3.cpu1] requesting target halt and executing a soft reset
Info : [esp32s3.cpu0] Core was reset.
Info : [esp32s3.cpu0] Target halted, PC=0x40000400, debug_reason=00000000
Info : [esp32s3.cpu1] Debug controller was reset.
Info : [esp32s3.cpu1] Core was reset.
Info : [esp32s3.cpu1] Target halted, PC=0x40000400, debug_reason=00000000
Info : [esp32s3.cpu1] Reset cause (3) - (Software core reset)
Info : [esp32s3.cpu0] Reset cause (3) - (Software core reset)
Info : [esp32s3.cpu0] Stub logs enabled!
Info : [esp32s3.cpu0] Target halted, PC=0x403B244A, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3c040020, 85 KB
Info : Flash mapping 1: 0x30020 -> 0x42000020, 252 KB
Info : Using flash bank 'esp32s3.cpu0.irom' size 256 KB
Info : [esp32s3.cpu0] Target halted, PC=0x403B244A, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3c040020, 85 KB
Info : Flash mapping 1: 0x30020 -> 0x42000020, 252 KB
Info : Using flash bank 'esp32s3.cpu0.drom' size 88 KB
Info : [esp32s3.cpu0] Target halted, PC=0x403B244A, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3c040020, 85 KB
Info : Flash mapping 1: 0x30020 -> 0x42000020, 252 KB
Info : [esp32s3.cpu0] Target halted, PC=0x403B244A, debug_reason=00000001
Info : Auto-detected flash bank 'esp32s3.cpu0.flash' size 8192 KB
Info : Using flash bank 'esp32s3.cpu0.flash' size 8192 KB
Info : [esp32s3.cpu1] Stub logs enabled!
Info : [esp32s3.cpu0] Target halted, PC=0x403B244A, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3c040020, 85 KB
Info : Flash mapping 1: 0x30020 -> 0x42000020, 252 KB
Info : Using flash bank 'esp32s3.cpu1.irom' size 256 KB
Info : [esp32s3.cpu0] Target halted, PC=0x403B244A, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3c040020, 85 KB
Info : Flash mapping 1: 0x30020 -> 0x42000020, 252 KB
Info : Using flash bank 'esp32s3.cpu1.drom' size 88 KB
Info : [esp32s3.cpu0] Target halted, PC=0x403B244A, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3c040020, 85 KB
Info : Flash mapping 1: 0x30020 -> 0x42000020, 252 KB
Info : [esp32s3.cpu0] Target halted, PC=0x403B244A, debug_reason=00000001
Info : Auto-detected flash bank 'esp32s3.cpu1.flash' size 8192 KB
Info : Using flash bank 'esp32s3.cpu1.flash' size 8192 KB
Flashing /home/ubuntu/Desktop/_ESP32_WORKSPACE_/ESP32_Basic_Project_0.1.13_beta/build/bootloader/bootloader.bin at 0x0
** program_esp input args <0x0 verify> **
Info : JTAG tap: esp32s3.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32s3.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : [esp32s3.cpu0] requesting target halt and executing a soft reset
Info : [esp32s3.cpu0] Debug controller was reset.
Info : [esp32s3.cpu0] Core was reset.
Info : [esp32s3.cpu0] Target halted, PC=0x500000EF, debug_reason=00000000
Info : [esp32s3.cpu0] Reset cause (3) - (Software core reset)
Info : [esp32s3.cpu1] requesting target halt and executing a soft reset
Info : [esp32s3.cpu0] Core was reset.
Info : [esp32s3.cpu0] Target halted, PC=0x40000400, debug_reason=00000000
Info : [esp32s3.cpu1] Debug controller was reset.
Info : [esp32s3.cpu1] Core was reset.
Info : [esp32s3.cpu1] Target halted, PC=0x40000400, debug_reason=00000000
Info : [esp32s3.cpu1] Reset cause (3) - (Software core reset)
Info : [esp32s3.cpu0] Reset cause (3) - (Software core reset)
** Programming Started **
Info : [esp32s3.cpu0] Target halted, PC=0x403B30C2, debug_reason=00000001
STUB_D: cpu_freq:160 Mhz
STUB_D: dcache_ctrl1_reg: 0x3
STUB_D: DATA 0x3fca0000..0x3fca1121
STUB_D: BSS 0x3fca1124..0x3fca223c
STUB_D: cmd 11:CLOCK_CONFIGURE
STUB_D: stub_flash_handler arg1 ffffffff, arg2 0
STUB_I: Cache needs to be enabled for CPU0
STUB_D: stub_cache_init
STUB_I: Attach spi flash...
STUB_I: Flash state prepared...
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 204017, cs 800000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 174020
STUB_D: Flash ID 17, size 8192 KB
STUB_D: exit 20
Info : [esp32s3.cpu0] Target halted, PC=0x403B30C2, debug_reason=00000001
STUB_D: cpu_freq:160 Mhz
STUB_D: dcache_ctrl1_reg: 0x2
STUB_D: DATA 0x3fca0000..0x3fca1121
STUB_D: BSS 0x3fca1124..0x3fca223c
STUB_D: cmd 2:FLASH_ERASE
STUB_D: stub_flash_handler arg1 0, arg2 24576
STUB_I: Flash state prepared...
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 204017, cs 800000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 174020
STUB_D: Flash ID 17, size 8192 KB
STUB_D: erase flash @ 0x0, sz 24576
STUB_D: Erased 24576 bytes @ 0x0 in 418 ms
STUB_D: exit 0
Info : PROF: Erased 24576 bytes in 629.234 ms
Info : PROF: Data transferred in 255.826 ms @ 93.8138 KB/s
Info : [esp32s3.cpu0] Target halted, PC=0x403B30C2, debug_reason=00000001
STUB_D: cpu_freq:160 Mhz
STUB_D: dcache_ctrl1_reg: 0x2
STUB_D: DATA 0x3fca0000..0x3fca1121
STUB_D: BSS 0x3fca1124..0x3fca223c
STUB_D: cmd 1:FLASH_WRITE
STUB_D: stub_flash_handler arg1 3fcaa63c, arg2 0
STUB_I: Flash state prepared...
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 204017, cs 800000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 174020
STUB_D: Flash ID 17, size 8192 KB
STUB_D: Start writing 24576 bytes @ 0x0 opt 0
STUB_I: Init apptrace module
STUB_I: Init apptrace module down buffer 65536 bytes @ 0x3fcaa658
STUB_V: Req trace down buf 24576 bytes 24576-0
STUB_V: Got trace down buf 16382 bytes @ 0x3fcaa658 in 258762 us
STUB_V: Req trace down buf 8194 bytes 24576-16382
STUB_V: Got trace down buf 8194 bytes @ 0x3fcae656 in 88836 us
STUB_D: flash_encryption_mode: 0
STUB_D: Write flash @ 0x0 sz 32768 in 85411 us
STUB_D: Wrote 24576 bytes @ 0x0
STUB_D: exit 0
Info : PROF: Wrote 24576 bytes in 647.164 ms (data transfer time included)
** Programming Finished in 1701 ms **
** Verify Started **
Info : [esp32s3.cpu0] Target halted, PC=0x403B30C2, debug_reason=00000001
STUB_D: cpu_freq:160 Mhz
STUB_D: dcache_ctrl1_reg: 0x2
STUB_D: DATA 0x3fca0000..0x3fca1121
STUB_D: BSS 0x3fca1124..0x3fca223c
STUB_D: cmd 10:FLASH_CALC_HASH
STUB_D: stub_flash_handler arg1 0, arg2 24528
STUB_I: Flash state prepared...
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 204017, cs 800000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 174020
STUB_D: Flash ID 17, size 8192 KB
STUB_D: stub_flash_calc_hash 24528 bytes @ 0x0
STUB_D: start_page: 4 map_src: 0 map_size: 5fd0 page_cnt: 1 flash_page: 0 map_ptr: 3c040000
STUB_D: hash: 2d48f6...4a6ffc
STUB_D: exit 0
Info : PROF: Flash verified in 229.869 ms 
** Verify OK **
** Flashing done for bootloader/bootloader.bin in 1936 ms **
Flashing /home/ubuntu/Desktop/_ESP32_WORKSPACE_/ESP32_Basic_Project_0.1.13_beta/build/ESP32_Basic_Project_0.bin at 0x10000
** program_esp input args <0x10000 verify> **
Info : JTAG tap: esp32s3.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32s3.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : [esp32s3.cpu0] requesting target halt and executing a soft reset
Info : [esp32s3.cpu0] Debug controller was reset.
Info : [esp32s3.cpu0] Core was reset.
Info : [esp32s3.cpu0] Target halted, PC=0x500000EF, debug_reason=00000000
Info : [esp32s3.cpu0] Reset cause (3) - (Software core reset)
Info : [esp32s3.cpu1] requesting target halt and executing a soft reset
Info : [esp32s3.cpu0] Core was reset.
Info : [esp32s3.cpu0] Target halted, PC=0x40000400, debug_reason=00000000
Info : [esp32s3.cpu1] Debug controller was reset.
Info : [esp32s3.cpu1] Core was reset.
Info : [esp32s3.cpu1] Target halted, PC=0x40000400, debug_reason=00000000
Info : [esp32s3.cpu1] Reset cause (3) - (Software core reset)
Info : [esp32s3.cpu0] Reset cause (3) - (Software core reset)
** Programming Started **
Info : [esp32s3.cpu0] Target halted, PC=0x403B30C2, debug_reason=00000001
STUB_D: cpu_freq:160 Mhz
STUB_D: dcache_ctrl1_reg: 0x3
STUB_D: DATA 0x3fca0000..0x3fca1121
STUB_D: BSS 0x3fca1124..0x3fca223c
STUB_D: cmd 11:CLOCK_CONFIGURE
STUB_D: stub_flash_handler arg1 ffffffff, arg2 0
STUB_I: Cache needs to be enabled for CPU0
STUB_D: stub_cache_init
STUB_I: Attach spi flash...
STUB_I: Flash state prepared...
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 204017, cs 800000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 174020
STUB_D: Flash ID 17, size 8192 KB
STUB_D: exit 20
Info : [esp32s3.cpu0] Target halted, PC=0x403B30C2, debug_reason=00000001
STUB_D: cpu_freq:160 Mhz
STUB_D: dcache_ctrl1_reg: 0x2
STUB_D: DATA 0x3fca0000..0x3fca1121
STUB_D: BSS 0x3fca1124..0x3fca223c
STUB_D: cmd 2:FLASH_ERASE
STUB_D: stub_flash_handler arg1 10000, arg2 782336
STUB_I: Flash state prepared...
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 204017, cs 800000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 174020
STUB_D: Flash ID 17, size 8192 KB
STUB_D: erase flash @ 0x10000, sz 782336
STUB_D: Erased 782336 bytes @ 0x10000 in 4179 ms
STUB_D: exit 0
Info : PROF: Erased 782336 bytes in 4393.49 ms
Info : PROF: Data transferred in 7495.71 ms @ 101.925 KB/s
Info : [esp32s3.cpu0] Target halted, PC=0x403B30C2, debug_reason=00000001
t trace down buf 16294 bytes @ 0x3fcaa658 in 1 us
STUB_V: Req trace down buf 45146 bytes 782336-737190
STUB_V: Got trace down buf 16382 bytes @ 0x3fcae5fe in 66742 us
STUB_V: Req trace down buf 28764 bytes 782336-753572
STUB_V: Got trace down buf 16382 bytes @ 0x3fcb25fc in 169421 us
STUB_D: Write flash @ 0xc0000 sz 32768 in 95647 us
STUB_V: Req trace down buf 12382 bytes 782336-769954
STUB_V: Got trace down buf 12382 bytes @ 0x3fcb65fa in 24185 us
STUB_D: Write flash @ 0xc8000 sz 32768 in 83848 us
STUB_D: Wrote 782336 bytes @ 0x10000
STUB_D: exit 0
Info : PROF: Wrote 782336 bytes in 7883.19 ms (data transfer time included)
** Programming Finished in 12699 ms **
** Verify Started **
Info : [esp32s3.cpu0] Target halted, PC=0x403B30C2, debug_reason=00000001
STUB_D: cpu_freq:160 Mhz
STUB_D: dcache_ctrl1_reg: 0x2
STUB_D: DATA 0x3fca0000..0x3fca1121
STUB_D: BSS 0x3fca1124..0x3fca223c
STUB_D: cmd 10:FLASH_CALC_HASH
STUB_D: stub_flash_handler arg1 10000, arg2 780400
STUB_I: Flash state prepared...
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 204017, cs 800000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 174020
STUB_D: Flash ID 17, size 8192 KB
STUB_D: stub_flash_calc_hash 780400 bytes @ 0x10000
STUB_D: start_page: 4 map_src: 10000 map_size: 8000 page_cnt: 1 flash_page: 1 map_ptr: 3c040000
STUB_D: start_page: 4 map_src: 10000 map_size: 10000 page_cnt: 1 flash_page: 1 map_ptr: 3c048000
STUB_D: start_page: 4 map_src: 20000 map_size: 8000 page_cnt: 1 flash_page: 2 map_ptr: 3c040000
STUB_D: start_page: 4 map_src: 20000 map_size: 10000 page_cnt: 1 flash_page: 2 map_ptr: 3c048000
STUB_D: start_page: 4 map_src: 30000 map_size: 8000 page_cnt: 1 flash_page: 3 map_ptr: 3c040000
STUB_D: start_page: 4 map_src: 30000 map_size: 10000 page_cnt: 1 flash_page: 3 map_ptr: 3c048000
STUB_D: start_page: 4 map_src: 40000 map_size: 8000 page_cnt: 1 flash_page: 4 map_ptr: 3c040000
STUB_D: start_page: 4 map_src: 40000 map_size: 10000 page_cnt: 1 flash_page: 4 map_ptr: 3c048000
STUB_D: start_page: 4 map_src: 50000 map_size: 8000 page_cnt: 1 flash_page: 5 map_ptr: 3c040000
STUB_D: start_page: 4 map_src: 50000 map_size: 10000 page_cnt: 1 flash_page: 5 map_ptr: 3c048000
STUB_D: start_page: 4 map_src: 60000 map_size: 8000 page_cnt: 1 flash_page: 6 map_ptr: 3c040000
STUB_D: start_page: 4 map_src: 60000 map_size: 10000 page_cnt: 1 flash_page: 6 map_ptr: 3c048000
STUB_D: start_page: 4 map_src: 70000 map_size: 8000 page_cnt: 1 flash_page: 7 map_ptr: 3c040000
STUB_D: start_page: 4 map_src: 70000 map_size: 10000 page_cnt: 1 flash_page: 7 map_ptr: 3c048000
STUB_D: start_page: 4 map_src: 80000 map_size: 8000 page_cnt: 1 flash_page: 8 map_ptr: 3c040000
STUB_D: start_page: 4 map_src: 80000 map_size: 10000 page_cnt: 1 flash_page: 8 map_ptr: 3c048000
STUB_D: start_page: 4 map_src: 90000 map_size: 8000 page_cnt: 1 flash_page: 9 map_ptr: 3c040000
STUB_D: start_page: 4 map_src: 90000 map_size: 10000 page_cnt: 1 flash_page: 9 map_ptr: 3c048000
STUB_D: start_page: 4 map_src: a0000 map_size: 8000 page_cnt: 1 flash_page: 10 map_ptr: 3c040000
STUB_D: start_page: 4 map_src: a0000 map_size: 10000 page_cnt: 1 flash_page: 10 map_ptr: 3c048000
STUB_D: start_page: 4 map_src: b0000 map_size: 8000 page_cnt: 1 flash_page: 11 map_ptr: 3c040000
STUB_D: start_page: 4 map_src: b0000 map_size: 10000 page_cnt: 1 flash_page: 11 map_ptr: 3c048000
STUB_D: start_page: 4 map_src: c0000 map_size: 8000 page_cnt: 1 flash_page: 12 map_ptr: 3c040000
STUB_D: start_page: 4 map_src: c0000 map_size: e870 page_cnt: 1 flash_page: 12 map_ptr: 3c048000
STUB_D: hash: e0a34f...96624b
STUB_D: exit 0
Info : PROF: Flash verified in 664.628 ms 
** Verify OK **
** Flashing done for ESP32_Basic_Project_0.bin in 13373 ms **
Flashing /home/ubuntu/Desktop/_ESP32_WORKSPACE_/ESP32_Basic_Project_0.1.13_beta/build/partition_table/partition-table.bin at 0x8000
** program_esp input args <0x8000 verify> **
Info : JTAG tap: esp32s3.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32s3.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : [esp32s3.cpu0] requesting target halt and executing a soft reset
Info : [esp32s3.cpu0] Debug controller was reset.
Info : [esp32s3.cpu0] Core was reset.
Info : [esp32s3.cpu0] Target halted, PC=0x500000EF, debug_reason=00000000
Info : [esp32s3.cpu0] Reset cause (3) - (Software core reset)
Info : [esp32s3.cpu1] requesting target halt and executing a soft reset
Info : [esp32s3.cpu0] Core was reset.
Info : [esp32s3.cpu0] Target halted, PC=0x40000400, debug_reason=00000000
Info : [esp32s3.cpu1] Debug controller was reset.
Info : [esp32s3.cpu1] Core was reset.
Info : [esp32s3.cpu1] Target halted, PC=0x40000400, debug_reason=00000000
Info : [esp32s3.cpu1] Reset cause (3) - (Software core reset)
Info : [esp32s3.cpu0] Reset cause (3) - (Software core reset)
** Programming Started **
Info : [esp32s3.cpu0] Target halted, PC=0x403B30C2, debug_reason=00000001
STUB_D: cpu_freq:160 Mhz
STUB_D: dcache_ctrl1_reg: 0x3
STUB_D: DATA 0x3fca0000..0x3fca1121
STUB_D: BSS 0x3fca1124..0x3fca223c
STUB_D: cmd 11:CLOCK_CONFIGURE
STUB_D: stub_flash_handler arg1 ffffffff, arg2 0
STUB_I: Cache needs to be enabled for CPU0
STUB_D: stub_cache_init
STUB_I: Attach spi flash...
STUB_I: Flash state prepared...
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 204017, cs 800000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 174020
STUB_D: Flash ID 17, size 8192 KB
STUB_D: exit 20
Info : [esp32s3.cpu0] Target halted, PC=0x403B30C2, debug_reason=00000001
STUB_D: cpu_freq:160 Mhz
STUB_D: dcache_ctrl1_reg: 0x2
STUB_D: DATA 0x3fca0000..0x3fca1121
STUB_D: BSS 0x3fca1124..0x3fca223c
STUB_D: cmd 2:FLASH_ERASE
STUB_D: stub_flash_handler arg1 8000, arg2 4096
STUB_I: Flash state prepared...
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 204017, cs 800000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 174020
STUB_D: Flash ID 17, size 8192 KB
STUB_D: erase flash @ 0x8000, sz 4096
STUB_D: Erased 4096 bytes @ 0x8000 in 66 ms
STUB_D: exit 0
Info : PROF: Erased 4096 bytes in 276.206 ms
Info : PROF: Data transferred in 41.348 ms @ 96.7399 KB/s
Info : [esp32s3.cpu0] Target halted, PC=0x403B30C2, debug_reason=00000001
STUB_D: cpu_freq:160 Mhz
STUB_D: dcache_ctrl1_reg: 0x2
STUB_D: DATA 0x3fca0000..0x3fca1121
STUB_D: BSS 0x3fca1124..0x3fca223c
STUB_D: cmd 1:FLASH_WRITE
STUB_D: stub_flash_handler arg1 3fcaa63c, arg2 0
STUB_I: Flash state prepared...
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 204017, cs 800000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 174020
STUB_D: Flash ID 17, size 8192 KB
STUB_D: Start writing 4096 bytes @ 0x8000 opt 0
STUB_I: Init apptrace module
STUB_I: Init apptrace module down buffer 65536 bytes @ 0x3fcaa658
STUB_V: Req trace down buf 4096 bytes 4096-0
STUB_V: Got trace down buf 4096 bytes @ 0x3fcaa658 in 133580 us
STUB_D: flash_encryption_mode: 0
STUB_D: Write flash @ 0x8000 sz 32768 in 43545 us
STUB_D: Wrote 4096 bytes @ 0x8000
STUB_D: exit 0
Info : PROF: Wrote 4096 bytes in 394.033 ms (data transfer time included)
** Programming Finished in 1098 ms **
** Verify Started **
Info : [esp32s3.cpu0] Target halted, PC=0x403B30C2, debug_reason=00000001
STUB_D: cpu_freq:160 Mhz
STUB_D: dcache_ctrl1_reg: 0x2
STUB_D: DATA 0x3fca0000..0x3fca1121
STUB_D: BSS 0x3fca1124..0x3fca223c
STUB_D: cmd 10:FLASH_CALC_HASH
STUB_D: stub_flash_handler arg1 8000, arg2 3072
STUB_I: Flash state prepared...
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 204017, cs 800000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 174020
STUB_D: Flash ID 17, size 8192 KB
STUB_D: stub_flash_calc_hash 3072 bytes @ 0x8000
STUB_D: start_page: 4 map_src: 0 map_size: 8c00 page_cnt: 1 flash_page: 0 map_ptr: 3c048000
STUB_D: hash: 2b9cfa...a8968
STUB_D: exit 0
Info : PROF: Flash verified in 213.934 ms 
** Verify OK **
** Flashing done for partition_table/partition-table.bin in 1316 ms **
Flashing /home/ubuntu/Desktop/_ESP32_WORKSPACE_/ESP32_Basic_Project_0.1.13_beta/build/storage.bin at 0x410000
** program_esp input args <0x410000 verify> **
Info : JTAG tap: esp32s3.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32s3.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : [esp32s3.cpu0] requesting target halt and executing a soft reset
Info : [esp32s3.cpu0] Debug controller was reset.
Info : [esp32s3.cpu0] Core was reset.
Info : [esp32s3.cpu0] Target halted, PC=0x500000EF, debug_reason=00000000
Info : [esp32s3.cpu0] Reset cause (3) - (Software core reset)
Info : [esp32s3.cpu1] requesting target halt and executing a soft reset
Info : [esp32s3.cpu0] Core was reset.
Info : [esp32s3.cpu0] Target halted, PC=0x40000400, debug_reason=00000000
Info : [esp32s3.cpu1] Debug controller was reset.
Info : [esp32s3.cpu1] Core was reset.
Info : [esp32s3.cpu1] Target halted, PC=0x40000400, debug_reason=00000000
Info : [esp32s3.cpu1] Reset cause (3) - (Software core reset)
Info : [esp32s3.cpu0] Reset cause (3) - (Software core reset)
** Programming Started **
Info : [esp32s3.cpu0] Target halted, PC=0x403B30C2, debug_reason=00000001
STUB_D: cpu_freq:160 Mhz
STUB_D: dcache_ctrl1_reg: 0x3
STUB_D: DATA 0x3fca0000..0x3fca1121
STUB_D: BSS 0x3fca1124..0x3fca223c
STUB_D: cmd 11:CLOCK_CONFIGURE
STUB_D: stub_flash_handler arg1 ffffffff, arg2 0
STUB_I: Cache needs to be enabled for CPU0
STUB_D: stub_cache_init
STUB_I: Attach spi flash...
STUB_I: Flash state prepared...
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 204017, cs 800000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 174020
STUB_D: Flash ID 17, size 8192 KB
STUB_D: exit 20
Info : [esp32s3.cpu0] Target halted, PC=0x403B30C2, debug_reason=00000001
STUB_D: cpu_freq:160 Mhz
STUB_D: dcache_ctrl1_reg: 0x2
STUB_D: DATA 0x3fca0000..0x3fca1121
STUB_D: BSS 0x3fca1124..0x3fca223c
STUB_D: cmd 2:FLASH_ERASE
STUB_D: stub_flash_handler arg1 410000, arg2 1048576
STUB_I: Flash state prepared...
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 204017, cs 800000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 174020
STUB_D: Flash ID 17, size 8192 KB
STUB_D: erase flash @ 0x410000, sz 1048576
STUB_D: Erased 1048576 bytes @ 0x410000 in 4619 ms
STUB_D: exit 0
Info : PROF: Erased 1048576 bytes in 4832.32 ms

QUESTION

Is there any way to prevent the MCU from automatically restart after flashing? Why? Because if there is any issue with the code (like a panic error) the debugger won't be able to get into the code and allow debugging. The OpenOCD startup timeout is a classic tedious problem that turns debugging into the biggest hurdle. Please HELP...

igrr commented 1 year ago

@Duolabs Regarding the issue 2: could you please try one of the similar IDF examples and see if you observe the same issue?

If you can reproduce this issue also with one of IDF examples, please follow the instructions in https://docs.espressif.com/projects/esp-idf/en/latest/esp32s3/api-guides/jtag-debugging/tips-and-quirks.html#reporting-issues-with-openocd-gdb for collecting the log files.

Duolabs commented 1 year ago

@igrr

Issue2:

  1. Tested fatfsgen with no problem in debugging.
  2. wear_levelling compiler was not able to find function esp_vfs_fat_spiflash_mount_rw_wl which is not in my 5.0.1 component.
  3. If I short the code with a while 1 before the Display Init and FLASH_IN_PROJECT when I try to init the UART after the FatFS in the debug I get stuck with this trace:
    Thread #2 [main] 1070545212 (Name: main, State: Running @CPU0) (Suspended : Signal : SIGTRAP:Trace/breakpoint trap) 
        find_desc_for_source() at intr_alloc.c:166 0x42003f74   
        get_available_int() at intr_alloc.c:323 0x420040b1  
        esp_intr_alloc_intrstatus() at intr_alloc.c:544 0x4200431e  
        esp_intr_alloc() at intr_alloc.c:662 0x42004568 
        uart_driver_install() at uart.c:1,623 0x42012f43    
        DUO_UART_Init() at ESP32_DUO_Framework_UART.c:127 0x42009da9    
        app_main() at main.c:208 0x42009558 
        main_task() at port_common.c:131 0x4202c466 
        vPortTaskWrapper() at port.c:154 0x4037e968 
    Thread #3 [IDLE] 1070548988 (Name: IDLE, State: Running @CPU1) (Suspended : Container)  
    Thread #4 [IDLE] 1070547100 (Name: IDLE) (Suspended : Container)    
    Thread #5 [ipc1] 1070536252 (Name: ipc1) (Suspended : Container)    
    Thread #6 [esp_timer] 1070540700 (Name: esp_timer) (Suspended : Container)  
    Thread #7 [ipc0] 1070534620 (Name: ipc0) (Suspended : Container)

If I do NOT FLASH_IN_PROJECT I can debug with no issues.

  1. I've made logs following your Reporting Issues with OpenOCD/GDB and _gdblog.txt was not generated in any circumstance because I always get the OpenOCD Timeout but with these differences:

4.1 If I put I get _fatfs_create_spiflash_image(storage ../Application_Filesystem FLASH_IN_PROJECT PRESERVETIME)

Error in services launch sequence Starting OpenOCD timed out.

and the application starts but no debug

4.2 If I remove the FLASH_IN_PROJECT I get the following error:

An internal error occurred during: "Starting OpenOCD". RequestMonitor: Sequence "", result for executing step #1 = Status ERROR: org.eclipse.cdt.dsf code=10005 Request for monitor: 'RequestMonitor (org.eclipse.embedcdt.debug.gdbjtag.core.dsf.GnuMcuGdbServerBackend$GdbServerStep$1@5f7cb40c): Status OK: unknown code=0 OK' resulted in a rejected execution exception., done() method called more than once

and the application does NOT start

PLEASE CONSIDER THAT 4.1 AND 4.2 HAVE SUCH BEHAVIORS SINCE I USED THE "Reporting Issues with OpenOCD/GDB" LOGGING. As a reminder: If I use the standard Debug Configuration (I repeat myself) I can Debug without FLASH_IN_PROJECT while I get a "Starting OpenOCD timed out " like in 4.2 if I FLASH_IN_PROJECT

Here comes the two logs:

openocd_log_NO_FLASH.txt

openocd_log_FLASH.txt

@igrr If you want I can send you the troublesome project privately.

igrr commented 1 year ago

For the Issue 1 you have reported, we have created a fix in the IDF Eclipse plugin: https://github.com/espressif/idf-eclipse-plugin/pull/720

For the Issue 2, we are investigating, I will get back to you soon.