Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

Fixed storing of a vaddr as a paddr for DROM flash bank (OCD-910) #318

Closed
wants to merge 1 commit into from
Closed

Fixed storing of a vaddr as a paddr for DROM flash bank (OCD-910) #318

wants to merge 1 commit into from

Conversation

SaturnFX
Copy link
Contributor

@SaturnFX SaturnFX commented Feb 24, 2024 •
edited
Loading

Description

Hi there, while experimenting with openocd-esp32 and my ESP32-S2-Saola-1 board I've noticed that during flashing an ELF image using the 'program_esp' command the program is failing at the erase stage at stub code as follows:

STUB_D: erase flash @ 0x3f000000, sz 28672
STUB_E: Failed to erase flash (1)
STUB_D: exit -1
Error: Failed to erase flash (-1)!

It turns out that is all because during the execution of the 'probe' command on esp32 DROM flash bank, after retrieving bank mapping from the stub, the virtual address of the bank is mistakenly stored as a physical address. What's more, after digging a little deeper I've been able to find the commit that introduced the bug - 6b6b7f3ec214664862dfd220e45ee1f39ec4f9ef.

Type of change

  • Bug fix (non-breaking change which fixes an issue)
  • New feature (non-breaking change which adds functionality)
  • Breaking change (fix or feature that would cause existing functionality not to work as expected)
  • This change requires a documentation update

User Impact

This PR fixes part of the code responsible for flashing ESP32 devices.

Performance Impact

No impact

How Has This Been Tested?

Before logs:

# openocd -f openocd.cfg -c "program_esp target/xtensa-esp32s2-none-elf/debug/esp32test verify reset exit"
Open On-Chip Debugger v0.12.0-snapshot (2024-02-22-20:49)
Licensed under GNU GPL v2
For bug reports, read
	http://openocd.org/doc/doxygen/bugs.html
Info : auto-selecting first available session transport "jtag". To override use 'transport select <transport>'.
custom1
** program_esp input args <verify reset exit> **
Info : clock speed 2000 kHz
Info : JTAG tap: esp32s2.cpu tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : [esp32s2] Examination succeed
Info : starting gdb server for esp32s2 on 3333
Info : Listening on port 3333 for gdb connections
Info : JTAG tap: esp32s2.cpu tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : [esp32s2] requesting target halt and executing a soft reset
Info : [esp32s2] Debug controller was reset.
Info : [esp32s2] Core was reset.
Info : [esp32s2] Target halted, PC=0x400853EE, debug_reason=00000000
Info : [esp32s2] Reset cause (1) - (Power on reset)
Info : [esp32s2] Debug controller was reset.
Info : [esp32s2] Core was reset.
Info : [esp32s2] Target halted, PC=0x4000F375, debug_reason=00000000
Info : [esp32s2] Reset cause (3) - (Software core reset)
Info : [esp32s2] Core was reset.
Info : [esp32s2] Target halted, PC=0x40000400, debug_reason=00000000
Info : [esp32s2] Reset cause (3) - (Software core reset)
Info : [esp32s2] Target halted, PC=0x40029EA6, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f000020, 26 KB
Info : Flash mapping 1: 0x20020 -> 0x40080020, 109 KB
Info : [esp32s2] Target halted, PC=0x40029EA6, debug_reason=00000001
Info : Auto-detected flash bank 'esp32s2.flash' size 4096 KB
Info : Using flash bank 'esp32s2.flash' size 4096 KB
** Programming Started **
Info : [esp32s2] Target halted, PC=0x40029EA6, debug_reason=00000001
Info : [esp32s2] Stub logs enabled!
Info : [esp32s2] Target halted, PC=0x40029EA6, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f000020, 26 KB
Info : Flash mapping 1: 0x20020 -> 0x40080020, 109 KB
Info : Using flash bank 'esp32s2.irom' size 112 KB
Info : [esp32s2] Target halted, PC=0x40029EA6, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f000020, 26 KB
Info : Flash mapping 1: 0x20020 -> 0x40080020, 109 KB
Info : Using flash bank 'esp32s2.drom' size 28 KB
Warn : Adding extra erase range, 0x3f000000 .. 0x3f00001f
Info : [esp32s2] Target halted, PC=0x4002AB06, debug_reason=00000001
STUB_D: cpu_freq:240 Mhz
STUB_D: DATA 0x3ffbc000..0x3ffbd05c
STUB_D: BSS 0x3ffbd05c..0x3ffbe174
STUB_D: cmd 2:FLASH_ERASE
STUB_D: stub_flash_handler arg1 3f000000, arg2 28672
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 1540ef, cs 400000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 16405e
STUB_D: Flash ID 16, size 4096 KB
STUB_D: erase flash @ 0x3f000000, sz 28672
STUB_E: Failed to erase flash (1)
STUB_D: exit -1
Error: Failed to erase flash (-1)!
Error: failed erasing sectors 0 to 6
** Programming Failed **
shutdown command invoked
/usr/local/bin/../share/openocd/scripts/target/esp_common.cfg:9: Error:
at file "/usr/local/bin/../share/openocd/scripts/target/esp_common.cfg", line 9

After logs:

# openocd -f openocd.cfg -c "program_esp target/xtensa-esp32s2-none-elf/debug/esp32test verify reset exit"
Open On-Chip Debugger v0.12.0-snapshot (2024-02-22-20:49)
Licensed under GNU GPL v2
For bug reports, read
	http://openocd.org/doc/doxygen/bugs.html
Info : auto-selecting first available session transport "jtag". To override use 'transport select <transport>'.
custom1
** program_esp input args <verify reset exit> **
Info : clock speed 2000 kHz
Info : JTAG tap: esp32s2.cpu tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : [esp32s2] Examination succeed
Info : starting gdb server for esp32s2 on 3333
Info : Listening on port 3333 for gdb connections
Info : JTAG tap: esp32s2.cpu tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : [esp32s2] requesting target halt and executing a soft reset
Info : [esp32s2] Debug controller was reset.
Info : [esp32s2] Core was reset.
Info : [esp32s2] Target halted, PC=0x4009A364, debug_reason=00000000
Info : [esp32s2] Reset cause (1) - (Power on reset)
Info : [esp32s2] Debug controller was reset.
Info : [esp32s2] Core was reset.
Info : [esp32s2] Target halted, PC=0x40007299, debug_reason=00000000
Info : [esp32s2] Reset cause (3) - (Software core reset)
Info : [esp32s2] Core was reset.
Info : [esp32s2] Target halted, PC=0x40000400, debug_reason=00000000
Info : [esp32s2] Reset cause (3) - (Software core reset)
Info : [esp32s2] Target halted, PC=0x40029EA6, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f000020, 26 KB
Info : Flash mapping 1: 0x20020 -> 0x40080020, 109 KB
Info : [esp32s2] Target halted, PC=0x40029EA6, debug_reason=00000001
Info : Auto-detected flash bank 'esp32s2.flash' size 4096 KB
Info : Using flash bank 'esp32s2.flash' size 4096 KB
** Programming Started **
Info : [esp32s2] Target halted, PC=0x40029EA6, debug_reason=00000001
Info : [esp32s2] Stub logs enabled!
Info : [esp32s2] Target halted, PC=0x40029EA6, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f000020, 26 KB
Info : Flash mapping 1: 0x20020 -> 0x40080020, 109 KB
Info : Using flash bank 'esp32s2.irom' size 112 KB
Info : [esp32s2] Target halted, PC=0x40029EA6, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f000020, 26 KB
Info : Flash mapping 1: 0x20020 -> 0x40080020, 109 KB
Info : Using flash bank 'esp32s2.drom' size 28 KB
Warn : Adding extra erase range, 0x3f000000 .. 0x3f00001f
Info : [esp32s2] Target halted, PC=0x4002AB06, debug_reason=00000001
STUB_D: cpu_freq:240 Mhz
STUB_D: DATA 0x3ffbc000..0x3ffbd05c
STUB_D: BSS 0x3ffbd05c..0x3ffbe174
STUB_D: cmd 2:FLASH_ERASE
STUB_D: stub_flash_handler arg1 10000, arg2 28672
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 1540ef, cs 400000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 16405e
STUB_D: Flash ID 16, size 4096 KB
STUB_D: erase flash @ 0x10000, sz 28672
STUB_D: Erased 28672 bytes @ 0x10000 in 400 ms
STUB_D: exit 0
Info : PROF: Erased 28672 bytes in 573.61 ms
Info : PROF: Compressed 28640 bytes to 8399 bytes in 2.276000ms
Info : PROF: Data transferred in 87.358 ms @ 93.8912 KB/s
Info : [esp32s2] Target halted, PC=0x4002AB06, debug_reason=00000001
STUB_D: cpu_freq:240 Mhz
STUB_D: DATA 0x3ffbc000..0x3ffbd05c
STUB_D: BSS 0x3ffbd05c..0x3ffbe174
STUB_D: cmd 9:FLASH_WRITE_DEFLATED
STUB_D: stub_flash_handler arg1 3ffc906c, arg2 0
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 1540ef, cs 400000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 16405e
STUB_D: Flash ID 16, size 4096 KB
STUB_D: Start writing 8399 bytes @ 0x10020 opt 0
STUB_I: Init apptrace module
STUB_I: Init apptrace module down buffer 65536 bytes @ 0x3ffc9088
STUB_I: Uncompressed data size 28640 bytes
STUB_V: Req trace down buf 8399 bytes 8399-0
STUB_V: Got trace down buf 8399 bytes @ 0x3ffc9088 in 178382 us
STUB_V: tinfl_decompress in(8399) out(28640) (2981)us
STUB_D: flash_encryption_mode: 0
STUB_D: Write flash @ 0x10020 sz 28640 in 67393 us
STUB_D: Wrote 28640 bytes @ 0x10020
STUB_D: exit 0
Info : PROF: Wrote 28640 bytes in 425.566 ms (data transfer time included)
Warn : no flash bank found for address 0x40022000
Warn : no flash bank found for address 0x40022400
Warn : Adding extra erase range, 0x40080000 .. 0x4008001f
Info : [esp32s2] Target halted, PC=0x4002AB06, debug_reason=00000001
STUB_D: cpu_freq:240 Mhz
STUB_D: DATA 0x3ffbc000..0x3ffbd05c
STUB_D: BSS 0x3ffbd05c..0x3ffbe174
STUB_D: cmd 2:FLASH_ERASE
STUB_D: stub_flash_handler arg1 20000, arg2 114688
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 1540ef, cs 400000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 16405e
STUB_D: Flash ID 16, size 4096 KB
STUB_D: erase flash @ 0x20000, sz 114688
STUB_D: Erased 114688 bytes @ 0x20000 in 1298 ms
STUB_D: exit 0
Info : PROF: Erased 114688 bytes in 1470.9 ms
Info : PROF: Compressed 114656 bytes to 55724 bytes in 13.325000ms
Info : PROF: Data transferred in 548.572 ms @ 99.1993 KB/s
Info : [esp32s2] Target halted, PC=0x4002AB06, debug_reason=00000001
STUB_D: cpu_freq:240 Mhz
STUB_D: DATA 0x3ffbc000..0x3ffbd05c
STUB_D: BSS 0x3ffbd05c..0x3ffbe174
STUB_D: cmd 9:FLASH_WRITE_DEFLATED
STUB_D: stub_flash_handler arg1 3ffc906c, arg2 0
STUB_D: stub_flash_get_size: ENTER
STUB_D: flash 1540ef, cs 400000, bs 10000, ss 1000, ps 100, sm ffff
STUB_D: Flash ID read 16405e
STUB_D: Flash ID 16, size 4096 KB
STUB_D: Start writing 55724 bytes @ 0x20020 opt 0
STUB_I: Init apptrace module
STUB_I: Init apptrace module down buffer 65536 bytes @ 0x3ffc9088
STUB_I: Uncompressed data size 114656 bytes
STUB_V: Req trace down buf 55724 bytes 55724-0
STUB_V: Got trace down buf 16382 bytes @ 0x3ffc9088 in 249995 us
STUB_V: tinfl_decompress in(16382) out(26569) (4781)us
STUB_V: Req trace down buf 39342 bytes 55724-16382
STUB_V: Got trace down buf 16382 bytes @ 0x3ffcd086 in 154179 us
STUB_V: tinfl_decompress in(2896) out(6199) (778)us
STUB_D: flash_encryption_mode: 0
STUB_D: Write flash @ 0x20020 sz 32768 in 78910 us
STUB_V: tinfl_decompress in(12843) out(32768) (3746)us
STUB_D: Write flash @ 0x28020 sz 32768 in 78939 us
STUB_V: tinfl_decompress in(643) out(1483) (184)us
STUB_V: Req trace down buf 22960 bytes 55724-32764
STUB_V: Got trace down buf 16382 bytes @ 0x3ffd1084 in 84 us
STUB_V: tinfl_decompress in(16382) out(31147) (4605)us
STUB_V: Req trace down buf 6578 bytes 55724-49146
STUB_V: Got trace down buf 6578 bytes @ 0x3ffd5082 in 62811 us
STUB_V: tinfl_decompress in(87) out(138) (22)us
STUB_D: Write flash @ 0x30020 sz 32768 in 78860 us
STUB_V: tinfl_decompress in(6491) out(16352) (1743)us
STUB_D: Write flash @ 0x38020 sz 16352 in 36569 us
STUB_D: Wrote 114656 bytes @ 0x20020
STUB_D: exit 0
Info : PROF: Wrote 114656 bytes in 941.622 ms (data transfer time included)
** Programming Finished in 4115 ms **
** Verify Started **
Warn : File content exceeds flash bank size. Only comparing the first 4194304 bytes of the file
Info : [esp32s2] Target halted, PC=0x4002AB06, debug_reason=00000001

STUB_D: start_page: 128 map_src: 3b0000 map_size: 10000 page_cnt: 1 flash_page: 59 map_ptr: 3f008000
STUB_D: start_page: 128 map_src: 3c0000 map_size: 8000 page_cnt: 1 flash_page: 60 map_ptr: 3f000000
STUB_D: start_page: 128 map_src: 3c0000 map_size: 10000 page_cnt: 1 flash_page: 60 map_ptr: 3f008000
STUB_D: start_page: 128 map_src: 3d0000 map_size: 8000 page_cnt: 1 flash_page: 61 map_ptr: 3f000000
STUB_D: start_page: 128 map_src: 3d0000 map_size: 10000 page_cnt: 1 flash_page: 61 map_ptr: 3f008000
STUB_D: start_page: 128 map_src: 3e0000 map_size: 8000 page_cnt: 1 flash_page: 62 map_ptr: 3f000000
STUB_D: start_page: 128 map_src: 3e0000 map_size: 10000 page_cnt: 1 flash_page: 62 map_ptr: 3f008000
STUB_D: start_page: 128 map_src: 3f0000 map_size: 8000 page_cnt: 1 flash_page: 63 map_ptr: 3f000000
STUB_D: start_page: 128 map_src: 3f0000 map_size: 10000 page_cnt: 1 flash_page: 63 map_ptr: 3f008000
STUB_D: hash: 1f346...891d97
STUB_D: exit 0
Info : PROF: Flash verified in 2212.88 ms
Error: **** Verification failure! ****
Error: target_hash 1f346...891d97
Error: file_hash: 20b35f...30b789
** Verify Failed **
shutdown command invoked
/usr/local/bin/../share/openocd/scripts/target/esp_common.cfg:9: Error:
at file "/usr/local/bin/../share/openocd/scripts/target/esp_common.cfg", line 9

Hardware Configuration:

  • Development Kit: ESP32-S2-Saola-1
  • Module or Chip Used: ESP32-S2
  • Debug Adapter: FT232H as a JTAG-USB adapter

Software Configuration:

  • OpenOCD version: commit c400745
  • Branch: main
  • ESP_IDF version: commit 68e5d9d585492163712b9cbb4a488abc82a0b795
  • Operating System: Debian 12 (inside docker)
  • openocd.cfg: 
    source [find interface/ftdi/esp32_devkitj_v1.cfg]
source [find target/esp32s2.cfg]

adapter speed 2000

ONE LAST NOTE: I'm flashing this image on top of correctly flashed ELF (in my case by espflash), so I could rely on partition table and mappings generated previously. Also since the 'erase' option in the 'program_esp' removes the necessary headers and as of now openocd has been unable to recreate it - I have tested flashing with this option removed and everything works fine then.

Checklist:

  • My code follows the style guidelines of this project
  • I have performed a self-review of my own code
  • I have commented my code, particularly in hard-to-understand areas
  • My changes generate no new warnings

@github-actions github-actions bot changed the title Fixed storing of a vaddr as a paddr for DROM flash bank Fixed storing of a vaddr as a paddr for DROM flash bank (OCD-910) Feb 24, 2024
@erhankur
Copy link
Collaborator

@SaturnFX Waww. What a mistake I made. We have been living with it for over a year. Thanks for digging out and creating the PR. I will be merging internally first. Then It will be synced here.

@erhankur
Copy link
Collaborator

Merged. 70919ce

Thanks again.

@erhankur erhankur closed this Feb 26, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
Resolution: Done Status: Done
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
3 participants
@SaturnFX @erhankur @espressif-bot