raspberrypi/openocd

Semihosting unusable due to excesive verbosity

ilg-ul opened this issue · 14 comments

ilg-ul commented

I edited the blink example to write some semihosting messages, but a target halted due to debug-request... message is displayed with each semihosting command, making the output unreadable:

ilg@berry:~/pico/pico-examples/build/blink $ openocd -f interface/cmsis-dap.cfg -c "adapter speed 5000" -f target/rp2040.cfg -c "program blink.elf verify" -c "arm semihosting enable" -c "arm semihosting_cmdline test one two" -c "reset"
Open On-Chip Debugger 0.11.0-g8e3c38f-dirty (2023-06-27-20:56)
Licensed under GNU GPL v2
For bug reports, read
       http://openocd.org/doc/doxygen/bugs.html
adapter speed: 5000 kHz

Info : auto-selecting first available session transport "swd". To override use 'transport select <transport>'.
Info : Hardware thread awareness created
Info : Hardware thread awareness created
Info : RP2040 Flash Bank Command
Info : Using CMSIS-DAPv2 interface with VID:PID=0x2e8a:0x000c, serial=E6616407E339502C
Info : CMSIS-DAP: SWD  Supported
Info : CMSIS-DAP: FW Version = 2.0.0
Info : CMSIS-DAP: Interface Initialised (SWD)
Info : SWCLK/TCK = 0 SWDIO/TMS = 0 TDI = 0 TDO = 0 nTRST = 0 nRESET = 0
Info : CMSIS-DAP: Interface ready
Info : clock speed 5000 kHz
Info : SWD DPIDR 0x0bc12477
Info : SWD DLPIDR 0x00000001
Info : SWD DPIDR 0x0bc12477
Info : SWD DLPIDR 0x10000001
Info : rp2040.core0: hardware has 4 breakpoints, 2 watchpoints
Info : rp2040.core1: hardware has 4 breakpoints, 2 watchpoints
Info : starting gdb server for rp2040.core0 on 3333
Info : Listening on port 3333 for gdb connections
target halted due to debug-request, current mode: Thread 
xPSR: 0xf1000000 pc: 0x000000ea msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0xf1000000 pc: 0x000000ea msp: 0x20041f00
** Programming Started **
Info : RP2040 B0 Flash Probe: 2097152 bytes @10000000, in 512 sectors

target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
Info : Writing 12288 bytes starting at 0x0
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
** Programming Finished **
** Verify Started **
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
** Verified OK **
semihosting is enabled

semihosting command line is [test one two]

Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
Hello target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
World!
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
cmdline: target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
test one twotarget halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00

target halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00
ilg@berry:~/pico/pico-examples/build/blink $

With a newer openocd (0.12.0), the output for the same elf is:

ilg@wksi ~ % /Users/ilg/Library/xPacks/@xpack-dev-tools/openocd/0.12.0-1.1/.content/bin/openocd -f interface/cmsis-dap.cfg -c "adapter speed 5000" -f target/rp2040.cfg -c "program /Users/ilg/Downloads/blink.elf verify reset" -c "arm semihosting enable" -c "arm semihosting_cmdline test one two" -c "reset"
xPack Open On-Chip Debugger 0.12.0-01004-g9ea7f3d64-dirty (2023-01-30-17:05)
Licensed under GNU GPL v2
For bug reports, read
	http://openocd.org/doc/doxygen/bugs.html
adapter speed: 5000 kHz

Info : Using CMSIS-DAPv2 interface with VID:PID=0x2e8a:0x000c, serial=E6616407E339502C
Info : CMSIS-DAP: SWD supported
Info : CMSIS-DAP: Atomic commands supported
Info : CMSIS-DAP: Test domain timer supported
Info : CMSIS-DAP: FW Version = 2.0.0
Info : CMSIS-DAP: Interface Initialised (SWD)
Info : SWCLK/TCK = 0 SWDIO/TMS = 0 TDI = 0 TDO = 0 nTRST = 0 nRESET = 0
Info : CMSIS-DAP: Interface ready
Info : clock speed 5000 kHz
Info : SWD DPIDR 0x0bc12477, DLPIDR 0x00000001
Info : SWD DPIDR 0x0bc12477, DLPIDR 0x10000001
Info : [rp2040.core0] Cortex-M0+ r0p1 processor detected
Info : [rp2040.core0] target has 4 breakpoints, 2 watchpoints
Info : [rp2040.core1] Cortex-M0+ r0p1 processor detected
Info : [rp2040.core1] target has 4 breakpoints, 2 watchpoints
Info : starting gdb server for rp2040.core0 on 3333
Info : Listening on port 3333 for gdb connections
Info : starting gdb server for rp2040.core1 on 3334
Info : Listening on port 3334 for gdb connections
[rp2040.core0] halted due to debug-request, current mode: Thread 
xPSR: 0xf1000000 pc: 0x000000ea msp: 0x20041f00
[rp2040.core1] halted due to debug-request, current mode: Thread 
xPSR: 0xf1000000 pc: 0x000000ea msp: 0x20041f00
** Programming Started **
Info : Found flash device 'win w25q16jv' (ID 0x001540ef)
Info : RP2040 B0 Flash Probe: 2097152 bytes @0x10000000, in 32 sectors

Info : Padding image section 1 at 0x10002474 with 140 bytes (bank write end alignment)
Warn : Adding extra erase range, 0x10002500 .. 0x1000ffff
** Programming Finished **
** Verify Started **
** Verified OK **
** Resetting Target **
[rp2040.core0] halted due to breakpoint, current mode: Thread 
xPSR: 0x01000000 pc: 0x1000037c msp: 0x20041fb8
semihosting is enabled

semihosting command line is [test one two]

Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
Hello World!
cmdline: test one two
ilg@wksi ~ % 

I don't know the reason why you still recommend in the documentation to use such an old openocd, but, for semihosted applications, the excessive verbosity makes it unusable.

lurch commented

I don't know the reason why you still recommend in the documentation to use such an old openocd

See e.g. #39 for some of the "fun" involved...

ilg-ul commented

I'm not surprised, maintaining an old fork is generally a big pain in the rear, both for the maintainers and for the users.

The faster the specific content is contributed upstream, the better for everybody.

P33M commented

Default branch is now 0.12.0

ilg-ul commented

The verbosity is no longer a problem, but with the openocd built from the default branch, exactly the same application as used in the initial report (the blinky with some semihosting writes) no longer runs:

ilg@berry:~/pico/pico-examples/build/blink $ openocd -f interface/cmsis-dap.cfg -c "adapter speed 5000" -f target/rp2040.cfg -c "program blink.elf verify" -c "arm semihosting enable" -c "arm semihosting_cmdline test one two" -c "reset"
Open On-Chip Debugger 0.12.0-g97d1e6e (2023-07-07-22:47)
Licensed under GNU GPL v2
For bug reports, read
	http://openocd.org/doc/doxygen/bugs.html
adapter speed: 5000 kHz

Info : Hardware thread awareness created
Info : Hardware thread awareness created
Info : Using CMSIS-DAPv2 interface with VID:PID=0x2e8a:0x000c, serial=E6616407E339502C
Info : CMSIS-DAP: SWD supported
Info : CMSIS-DAP: Atomic commands supported
Info : CMSIS-DAP: Test domain timer supported
Info : CMSIS-DAP: FW Version = 2.0.0
Info : CMSIS-DAP: Interface Initialised (SWD)
Info : SWCLK/TCK = 0 SWDIO/TMS = 0 TDI = 0 TDO = 0 nTRST = 0 nRESET = 0
Info : CMSIS-DAP: Interface ready
Info : clock speed 5000 kHz
Info : SWD DPIDR 0x0bc12477, DLPIDR 0x00000001
Info : SWD DPIDR 0x0bc12477, DLPIDR 0x10000001
Info : [rp2040.core0] Cortex-M0+ r0p1 processor detected
Info : [rp2040.core0] target has 4 breakpoints, 2 watchpoints
Info : [rp2040.core1] Cortex-M0+ r0p1 processor detected
Info : [rp2040.core1] target has 4 breakpoints, 2 watchpoints
Info : starting gdb server for rp2040.core0 on 3333
Info : Listening on port 3333 for gdb connections
[rp2040.core0] halted due to debug-request, current mode: Thread 
xPSR: 0xf1000000 pc: 0x000000ea msp: 0x20041f00
[rp2040.core1] halted due to debug-request, current mode: Thread 
xPSR: 0xf1000000 pc: 0x000000ea msp: 0x20041f00
** Programming Started **
Info : Found flash device 'win w25q16jv' (ID 0x001540ef)
Info : RP2040 B0 Flash Probe: 2097152 bytes @0x10000000, in 32 sectors

Info : Padding image section 1 at 0x10002474 with 140 bytes (bank write end alignment)
Warn : Adding extra erase range, 0x10002500 .. 0x1000ffff
** Programming Finished **
** Verify Started **
** Verified OK **
semihosting is enabled

semihosting command line is [test one two]

Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
Error: [rp2040.core1] target not halted
Warn : resume of a SMP target failed, trying to resume current one
Error: [rp2040.core0] resume failed
Error: Failed to resume target
Polling target rp2040.core0 failed, trying to reexamine
Info : [rp2040.core0] Cortex-M0+ r0p1 processor detected
Info : [rp2040.core0] target has 4 breakpoints, 2 watchpoints
[rp2040.core0] halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x10000394 msp: 0x20041fb8, semihosting
[rp2040.core1] halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000138 msp: 0x20041f00

And, BTW, the default branch in the repo might be rp2040-v0.12.0, but the Getting Started manual still recommends:

$ git clone https://github.com/raspberrypi/openocd.git --branch rp2040 --recursive --depth=1
ilg-ul commented

Please advice on how to proceed, since the current openocd is no longer functional.

P33M commented

Do you get the same result with the upstream development branch?

Clone this repository and do the same test.

https://github.com/openocd-org/openocd

ilg-ul commented

Clone this repository and do the same test. ...

The behaviour seems to be the same, i.e. it hangs:

ilg@berry:~/pico/pico-examples/build/blink $ openocd -f interface/cmsis-dap.cfg -c "adapter speed 5000" -f target/rp2040.cfg -c "program blink.elf verifsemihosting enable" -c "arm semihosting_cmdline test one two" -c "reset"
Open On-Chip Debugger 0.12.0+dev-g4a96776 (2023-07-10-13:11)
Licensed under GNU GPL v2
For bug reports, read
	http://openocd.org/doc/doxygen/bugs.html
adapter speed: 5000 kHz
Info : Hardware thread awareness created
Info : Hardware thread awareness created
Info : Using CMSIS-DAPv2 interface with VID:PID=0x2e8a:0x000c, serial=E6616407E339502C
Info : CMSIS-DAP: SWD supported
Info : CMSIS-DAP: Atomic commands supported
Info : CMSIS-DAP: Test domain timer supported
Info : CMSIS-DAP: FW Version = 2.0.0
Info : CMSIS-DAP: Interface Initialised (SWD)
Info : SWCLK/TCK = 0 SWDIO/TMS = 0 TDI = 0 TDO = 0 nTRST = 0 nRESET = 0
Info : CMSIS-DAP: Interface ready
Info : clock speed 5000 kHz
Info : SWD DPIDR 0x0bc12477, DLPIDR 0x00000001
Info : SWD DPIDR 0x0bc12477, DLPIDR 0x10000001
Info : [rp2040.core0] Cortex-M0+ r0p1 processor detected
Info : [rp2040.core0] target has 4 breakpoints, 2 watchpoints
Info : [rp2040.core1] Cortex-M0+ r0p1 processor detected
Info : [rp2040.core1] target has 4 breakpoints, 2 watchpoints
Info : starting gdb server for rp2040.core0 on 3333
Info : Listening on port 3333 for gdb connections
Warn : [rp2040.core1] target was in unknown state when halt was requested
[rp2040.core0] halted due to debug-request, current mode: Thread 
xPSR: 0xf1000000 pc: 0x000000ea msp: 0x20041f00
[rp2040.core1] halted due to debug-request, current mode: Thread 
xPSR: 0xf1000000 pc: 0x000000ea msp: 0x20041f00
** Programming Started **
Info : Found flash device 'win w25q16jv' (ID 0x001540ef)
Info : RP2040 B0 Flash Probe: 2097152 bytes @0x10000000, in 32 sectors

Info : Padding image section 1 at 0x10002474 with 140 bytes (bank write end alignment)
Warn : Adding extra erase range, 0x10002500 .. 0x1000ffff
** Programming Finished **
** Verify Started **
** Verified OK **
semihosting is enabled
semihosting command line is [test one two]
Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
Error: [rp2040.core1] target not halted
Warn : resume of a SMP target failed, trying to resume current one
Error: [rp2040.core0] resume failed
Error: Failed to resume target
Polling target rp2040.core0 failed, trying to reexamine
Info : [rp2040.core0] Cortex-M0+ r0p1 processor detected
Info : [rp2040.core0] target has 4 breakpoints, 2 watchpoints
[rp2040.core0] halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x10000394 msp: 0x20041fb8, semihosting
[rp2040.core1] halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x00000184 msp: 0x20041f00
^Cshutdown command invoked

ilg@berry:~/pico/pico-examples/build/blink $ 

Pretty bad from my point of view, since I was about to make a new binary release based on the latest upstream, but if this will break my tests, that's bad... :-(

I think that you should not only keep your fork up-to-date, but also keep the upstream functional for the Pico.

P33M commented

I can't replicate your failure with downstream or upstream versions. Upstream for reference:

openocd -f interface/cmsis-dap.cfg  -c "adapter speed 2000" -f target/rp2040.cfg -c "program pico/pico-examples/build/blink/blink.elf verify" -c "arm semihosting enable" -c "arm semihosting_cmdline test one two" -c "reset"
Open On-Chip Debugger 0.12.0+dev-01260-g4a9677617-dirty (2023-07-10-14:28)
Licensed under GNU GPL v2
For bug reports, read
        http://openocd.org/doc/doxygen/bugs.html
adapter speed: 2000 kHz
Info : Hardware thread awareness created
Info : Hardware thread awareness created
Info : Using CMSIS-DAPv2 interface with VID:PID=0x2e8a:0x000c, serial=E6617875035C6D34
Info : CMSIS-DAP: SWD supported
Info : CMSIS-DAP: Atomic commands supported
Info : CMSIS-DAP: Test domain timer supported
Info : CMSIS-DAP: FW Version = 2.0.0
Info : CMSIS-DAP: Interface Initialised (SWD)
Info : SWCLK/TCK = 0 SWDIO/TMS = 0 TDI = 0 TDO = 0 nTRST = 0 nRESET = 0
Info : CMSIS-DAP: Interface ready
Info : clock speed 2000 kHz
Info : SWD DPIDR 0x0bc12477, DLPIDR 0x00000001
Info : SWD DPIDR 0x0bc12477, DLPIDR 0x10000001
Info : [rp2040.core0] Cortex-M0+ r0p1 processor detected
Info : [rp2040.core0] target has 4 breakpoints, 2 watchpoints
Info : [rp2040.core1] Cortex-M0+ r0p1 processor detected
Info : [rp2040.core1] target has 4 breakpoints, 2 watchpoints
Info : starting gdb server for rp2040.core0 on 3333
Info : Listening on port 3333 for gdb connections
Warn : [rp2040.core1] target was in unknown state when halt was requested
[rp2040.core0] halted due to debug-request, current mode: Thread
xPSR: 0xf1000000 pc: 0x000000ee msp: 0x20041f00
[rp2040.core1] halted due to debug-request, current mode: Thread
xPSR: 0xf1000000 pc: 0x000000ee msp: 0x20041f00
** Programming Started **
Info : Found flash device 'win w25q16jv' (ID 0x001540ef)
Info : RP2040 B0 Flash Probe: 2097152 bytes @0x10000000, in 32 sectors

Info : Padding image section 1 at 0x100024f0 with 16 bytes (bank write end alignment)
Warn : Adding extra erase range, 0x10002500 .. 0x1000ffff
** Programming Finished **
** Verify Started **
** Verified OK **
semihosting is enabled
semihosting command line is [test one two]
Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
^Cshutdown command invoked

And I get a blinking LED.
Are you sure your rp2040.cfg is up to date?

ilg-ul commented

I can't replicate your failure with downstream or upstream versions.

Ah, sorry, I used the blink project as a starting point, now it is not blinking but exercising some semihosting calls.

Please replace the files in the sdk with the following:

blink-semihosting.tgz

The source code is a bit weird, it was copied from another project and patched, because I knew that the original was functional.

Are you sure your rp2040.cfg is up to date?

I don't know, it is the one provided by the openocd distribution, I did not change it.

P33M commented

The problem is that your code contains a breakpoint instruction, and -c "reset" sets the core(s) running after flash programming. If I omit the reset step, then attach GDB, I can run the example to completion (it hits semihosting_terminate(1), which also breakpoints, but is apparently handled by GDB.

I can also get successful execution if I disable SMP support by adding -c "set USE_CORE 0" before specifying the target config file.

ilg-ul commented

The problem is that your code contains a breakpoint instruction, and -c "reset" sets the core(s) running after flash programming.

I'm not sure I understand where the problem is. My code uses the breakpoint instruction to invoke the semihosting API.

How do you suggest to run a semihosted application without issuing a reset after flash programming?

If I omit the reset step, then attach GDB, I can run the example to completion (it hits semihosting_terminate(1), which also breakpoints, but is apparently handled by GDB.

It might be so, but the point is to run unit tests as standalone semihosted applications, i.e. without GDB and manual interventions. OpenOCD should be able to do this (I know this because several years ago I re-wrote the entire semihosting code in OpenOCD, I guess it is still functional).

I can also get successful execution if I disable SMP support by adding -c "set USE_CORE 0" before specifying the target config file.

For my current unit tests I don't need the second core, but for future tests I expected it to be available.

Can you summarise the current situation and suggest a solution or at least a workaround if things are not yet clear?

P33M commented

From more verbose debug, it looks like the swi breakpoint isn't being handled by openocd correctly. I would recommend disabling SMP as per above. I'm not sure why an unrelated configuration change apparently stops semihosting from working.

ilg-ul commented

Yes, I know, I opened that thread. :-)

But I'm not sure it is the same issue. I'll try to clarify that first and return to this one later.