search

bloombloombloom / Bloom

A debug interface for AVR-based embedded systems development on GNU/Linux.
https://bloom.oscillate.io/
Other
64 stars 3 forks source link

RSP kill command 'k' is silently ignored #105

Closed ccrause closed 2 months ago

ccrause commented 2 months ago

Currently Bloom silently ignores the remote serial protocol 'k' kill command. Support for the 'k' command is not mandatory, however silently ignoring an unsupported command causes complications on the debugger side. The remote protocol specifies the following response for unsupported commands:

For any command not supported by the stub, an empty response (‘$#00’) should be returned.

Returning an empty response informs a debugger that the command was received but not supported, while silently ignoring a command appears like a communication error.

navnavnav commented 2 months ago

Hey @ccrause

Hmm, are you sure it's being ignored?

We should be responding with an empty response packet for unsupported commands:

https://github.com/bloombloombloom/Bloom/blob/55d3fe76e00770f81fff363f746e3962e66b74d8/src/DebugServer/Gdb/CommandPackets/CommandPacket.cpp#L23-L54

Could you please attach Bloom's debug log output. It should log the responses it sends to GDB, so that would be helpful to see.

navnavnav commented 2 months ago

Also, just FYI, that command packet appears to be specific to "extended mode":

The kill request is used in extended mode before a restart or request to run a new program (vRun packet).

From https://www.embecosm.com/appnotes/ean4/embecosm-howto-rsp-server-ean4-issue-2.html

Bloom doesn't support the "extended mode". You shouldn't use target extended-remote ... to connect to Bloom. You should be using target remote ...

ccrause commented 2 months ago

Below the Lazarus trace of communication with Bloom:

RSP -> vMustReplyEmpty
RSP <- ^@
RSP -> ?
RSP <- T05
RSP -> g
RSP <- b700f4bffa9fff4f37c32d2ff3b9bffefb7f20dbd29b78d8a600f309f601da0000ff08007e0000
RSP -> s
RSP <- T05
RSP -> c
RSP -> k
RSP <- ^@

Note the last response received is actually the NULL character, displayed as ^@. Below the Bloom output :

$ bloom 
2024-04-09 21:55:27.946 SAST [MT]: [INFO] Selected environment: "default"
2024-04-09 21:55:27.947 SAST [TC]: [INFO] Starting TargetController
2024-04-09 21:55:27.972 SAST [TC]: [INFO] Connecting to debug tool
2024-04-09 21:55:28.027 SAST [TC]: [INFO] Debug tool connected
2024-04-09 21:55:28.027 SAST [TC]: [INFO] Debug tool name: MPLAB Snap
2024-04-09 21:55:28.065 SAST [TC]: [INFO] Debug tool serial: 
2024-04-09 21:55:28.117 SAST [TC]: [INFO] Activating target
2024-04-09 21:55:29.377 SAST [TC]: [INFO] Target activated
2024-04-09 21:55:29.378 SAST [TC]: [INFO] Target ID: 0x1e950f
2024-04-09 21:55:29.378 SAST [TC]: [INFO] Target name: ATmega328P
2024-04-09 21:55:29.378 SAST [TC]: [INFO] Available hardware breakpoints: 0
2024-04-09 21:55:29.461 SAST [DS]: [INFO] Starting DebugServer
2024-04-09 21:55:29.465 SAST [DS]: [INFO] Selected DebugServer: AVR GDB Remote Serial Protocol Debug Server
2024-04-09 21:55:29.465 SAST [DS]: [INFO] GDB RSP address: 127.0.0.1
2024-04-09 21:55:29.465 SAST [DS]: [INFO] GDB RSP port: 1234
2024-04-09 21:55:29.468 SAST [DS]: [INFO] DebugServer ready
2024-04-09 21:55:29.468 SAST [DS]: [INFO] Waiting for GDB RSP connection
2024-04-09 21:55:29.796 SAST [DS]: [INFO] Accepted GDP RSP connection from 127.0.0.1
2024-04-09 21:55:30.383 SAST [DS]: [INFO] Handling vMustReplyEmpty
2024-04-09 21:55:30.484 SAST [DS]: [INFO] Handling ReadRegisters packet
2024-04-09 21:55:30.684 SAST [DS]: [INFO] Handling StepExecution packet
2024-04-09 21:55:30.841 SAST [DS]: [INFO] Handling ContinueExecution packet

This is after receiving the 0x00 reply from Bloom, so it did not (yet?) react to the 'k' command.

navnavnav commented 2 months ago

Ah...

It's sending 0x00 as the empty response. I can't remember why I did that. Shockingly, it's not caused many problems as it would have been noticed sooner.

When I get some time, I will test a new build with the fix for this. But it won't be a while before I push a new release. I'm knee deep in a large refactor for RISC-V support, with many months of development to go.

BTW you can enable debug logging in Bloom via the debugLogging parameter in the root node of your bloom.yaml:

debugLogging: true

environments:
    # ...

The debug logs should include the responses we send to GDB.

ccrause commented 2 months ago

Also, just FYI, that command packet appears to be specific to "extended mode":

The kill request is used in extended mode before a restart or request to run a new program (vRun packet).

From https://www.embecosm.com/appnotes/ean4/embecosm-howto-rsp-server-ean4-issue-2.html

Bloom doesn't support the "extended mode". You shouldn't use target extended-remote ... to connect to Bloom. You should be using target remote ...

It is always a bit of a challenge to decipher standards. On Packets the description of 'k' is:

Kill request.

The exact effect of this packet is not specified.

For a bare-metal target, it may power cycle or reset the target system. For that reason, the ‘k’ packet has no reply.

For a single-process target, it may kill that process if possible.

A multiple-process target may choose to kill just one process, or all that are under GDB’s control. For more precise control, use the vKill packet (see vKill packet).

If the target system immediately closes the connection in response to ‘k’, GDB does not consider the lack of packet acknowledgment to be an error, and assumes the kill was successful.

_If connected using target extended-remote, and the target does not close the connection in response to a kill request, GDB probes the target state as if a new connection was opened (see ? packet)._

My problem seems to be detecting whether this is command supported or not. Testing from GDB suggest that the vKill command is supported, so I can fall back to that, or even call Detach.

ccrause commented 2 months ago

BTW you can enable debug logging in Bloom via the debugLogging parameter in the root node of your bloom.yaml:

debugLogging: true

environments:
    # ...

The debug logs should include the responses we send to GDB.

I was about to ask how to generate the debug log :smiley: The last bit of the log:

024-04-09 22:19:35.322 SAST [DS]: [DEBUG] Delivering response for EndAtomicSession command (ID: 7) 2024-04-09 22:19:35.322 SAST [DS]: [DEBUG] Writing GDB packet: $b700f4bffa9fff4f37c32d2ff3b9bffefb7f20dbd29b78d8bd00e201f601da0000ff08007e0000#75 2024-04-09 22:19:35.368 SAST [DS]: [DEBUG] Read GDB packet: $s#73 2024-04-09 22:19:35.368 SAST [DS]: [INFO] Handling StepExecution packet 2024-04-09 22:19:35.368 SAST [DS]: [DEBUG] Issuing StepTargetExecution command (ID: 8) to TargetController 2024-04-09 22:19:35.440 SAST [TC]: [DEBUG] Event "TargetExecutionResumed" (6) registered for listener DebugServerEventListener 2024-04-09 22:19:35.441 SAST [DS]: [DEBUG] Delivering response for StepTargetExecution command (ID: 8) 2024-04-09 22:19:35.441 SAST [DS]: [DEBUG] Dispatching event TargetExecutionResumed (6). 2024-04-09 22:19:35.442 SAST [TC]: [DEBUG] Target state changed - STOPPED 2024-04-09 22:19:35.481 SAST [TC]: [DEBUG] Event "TargetExecutionStopped" (7) registered for listener DebugServerEventListener 2024-04-09 22:19:35.482 SAST [DS]: [DEBUG] GDB RSP interrupted 2024-04-09 22:19:35.482 SAST [DS]: [DEBUG] Dispatching event TargetExecutionStopped (7). 2024-04-09 22:19:35.482 SAST [DS]: [DEBUG] Target stopped at byte address: 0x00007e02 2024-04-09 22:19:35.482 SAST [DS]: [DEBUG] Writing GDB packet: $T05#b9 2024-04-09 22:19:35.528 SAST [DS]: [DEBUG] Read GDB packet: $c#63 2024-04-09 22:19:35.528 SAST [DS]: [INFO] Handling ContinueExecution packet 2024-04-09 22:19:35.529 SAST [DS]: [DEBUG] Issuing ResumeTargetExecution command (ID: 9) to TargetController 2024-04-09 22:19:35.570 SAST [TC]: [DEBUG] Event "TargetExecutionResumed" (8) registered for listener DebugServerEventListener 2024-04-09 22:19:35.570 SAST [DS]: [DEBUG] Delivering response for ResumeTargetExecution command (ID: 9) 2024-04-09 22:19:35.571 SAST [DS]: [DEBUG] Dispatching event TargetExecutionResumed (8). 2024-04-09 22:19:50.097 SAST [DS]: [DEBUG] Read GDB packet: $k#6B 2024-04-09 22:19:50.098 SAST [DS]: [DEBUG] Unknown GDB RSP packet: k - returning empty response 2024-04-09 22:19:50.099 SAST [DS]: [DEBUG] Writing GDB packet: $#00

ccrause commented 2 months ago

Ah...

It's sending 0x00 as the empty response. I can't remember why I did that. Shockingly, it's not caused many problems as it would have been noticed sooner.

When I get some time, I will test a new build with the fix for this. But it won't be a while before I push a new release. I'm knee deep in a large refactor for RISC-V support, with many months of development to go.

OK, no problem. For now I can add a check for 0x00 and interpret it the same as an empty response.

navnavnav commented 2 months ago

Hmm, I'm not sure if the null byte in the "empty" response is your problem. GDB seems to tolerate it for every other command. Maybe it's forced to be more strict with responses to the k command.

I've just compiled an unofficial v1.0.1 build for you. That one will send empty response packets without the null byte. Have attached a DEB, RPM and PKGBUILD package:

DEB: https://bloom-public-bucket.s3.eu-west-1.amazonaws.com/Bloom-1.0.1-Linux-x86_64.deb RPM: https://bloom-public-bucket.s3.eu-west-1.amazonaws.com/Bloom-1.0.1-Linux-x86_64.rpm PKGBUILD: https://bloom-public-bucket.s3.eu-west-1.amazonaws.com/Bloom-1.0.1-Linux-x86_64.pkg.tar.gz

Can you give it a go and let me know if it helps?

Either way, this is an issue as the GDB documentation does not mention a null byte and I have no idea why I put it there. So it needs fixing.

ccrause commented 2 months ago

Another thing I noticed is that I need to first pause (interrupt/ctrl+c) the remote process, else detach does nothing. See log below where I send a kill then detach command while the remote is running. Bloom does not proceed to shut down:

2024-04-09 22:37:51.879 SAST [DS]: [DEBUG] Writing GDB packet: $T05#b9 2024-04-09 22:37:51.924 SAST [DS]: [DEBUG] Read GDB packet: $c#63 2024-04-09 22:37:51.924 SAST [DS]: [INFO] Handling ContinueExecution packet 2024-04-09 22:37:51.925 SAST [DS]: [DEBUG] Issuing ResumeTargetExecution command (ID: 9) to TargetController 2024-04-09 22:37:51.966 SAST [TC]: [DEBUG] Event "TargetExecutionResumed" (8) registered for listener DebugServerEventListener 2024-04-09 22:37:51.967 SAST [DS]: [DEBUG] Delivering response for ResumeTargetExecution command (ID: 9) 2024-04-09 22:37:51.967 SAST [DS]: [DEBUG] Dispatching event TargetExecutionResumed (8). 2024-04-09 22:37:58.460 SAST [DS]: [DEBUG] Read GDB packet: $k#6B 2024-04-09 22:37:58.460 SAST [DS]: [DEBUG] Unknown GDB RSP packet: k - returning empty response 2024-04-09 22:37:58.460 SAST [DS]: [DEBUG] Writing GDB packet: $#00 2024-04-09 22:37:58.504 SAST [DS]: [DEBUG] Read GDB packet: $vKill;1#6E 2024-04-09 22:37:58.504 SAST [DS]: [DEBUG] Unknown GDB RSP packet: vKill;1 - returning empty response 2024-04-09 22:37:58.504 SAST [DS]: [DEBUG] Writing GDB packet: $#00 2024-04-09 22:37:58.592 SAST [DS]: [DEBUG] Read GDB packet: $D#44 2024-04-09 22:37:58.592 SAST [DS]: [INFO] Handling Detach packet 2024-04-09 22:37:58.592 SAST [DS]: [DEBUG] Writing GDB packet: $OK#9a

First pausing execution, then kill then detach works as expected:

2024-04-09 22:41:40.708 SAST [DS]: [INFO] Handling InterruptExecution packet 2024-04-09 22:41:40.709 SAST [DS]: [DEBUG] Issuing GetTargetState command (ID: 10) to TargetController 2024-04-09 22:41:40.712 SAST [DS]: [DEBUG] Delivering response for GetTargetState command (ID: 10) 2024-04-09 22:41:40.712 SAST [DS]: [DEBUG] Issuing StopTargetExecution command (ID: 11) to TargetController 2024-04-09 22:41:40.893 SAST [TC]: [DEBUG] Event "TargetExecutionStopped" (9) registered for listener DebugServerEventListener 2024-04-09 22:41:40.893 SAST [DS]: [DEBUG] Delivering response for StopTargetExecution command (ID: 11) 2024-04-09 22:41:40.894 SAST [DS]: [DEBUG] Writing GDB packet: $T02#b6 2024-04-09 22:41:40.895 SAST [DS]: [DEBUG] Dispatching event TargetExecutionStopped (9). 2024-04-09 22:41:40.898 SAST [DS]: [DEBUG] Read GDB packet: $g#67 2024-04-09 22:41:40.899 SAST [DS]: [INFO] Handling ReadRegisters packet 2024-04-09 22:41:40.899 SAST [DS]: [DEBUG] Issuing StartAtomicSession command (ID: 12) to TargetController 2024-04-09 22:41:40.900 SAST [DS]: [DEBUG] Delivering response for StartAtomicSession command (ID: 12) 2024-04-09 22:41:40.900 SAST [DS]: [DEBUG] Issuing ReadTargetRegisters command (ID: 13) to TargetController 2024-04-09 22:41:41.016 SAST [DS]: [DEBUG] Delivering response for ReadTargetRegisters command (ID: 13) 2024-04-09 22:41:41.017 SAST [DS]: [DEBUG] Issuing GetTargetProgramCounter command (ID: 14) to TargetController 2024-04-09 22:41:41.056 SAST [DS]: [DEBUG] Delivering response for GetTargetProgramCounter command (ID: 14) 2024-04-09 22:41:41.057 SAST [DS]: [DEBUG] Issuing EndAtomicSession command (ID: 15) to TargetController 2024-04-09 22:41:41.057 SAST [DS]: [DEBUG] Delivering response for EndAtomicSession command (ID: 15) 2024-04-09 22:41:41.058 SAST [DS]: [DEBUG] Writing GDB packet: $b700f4bffa9fff4f37c32d2ff3b9bffefb7f20dbd29b78d8be010207f601da0000fd08d0000000#3e 2024-04-09 22:41:41.104 SAST [DS]: [DEBUG] Read GDB packet: $mD0,0A#7E 2024-04-09 22:41:41.104 SAST [DS]: [INFO] Handling ReadMemory packet 2024-04-09 22:41:41.105 SAST [DS]: [DEBUG] Issuing ReadTargetMemory command (ID: 16) to TargetController 2024-04-09 22:41:41.105 SAST [TC]: [DEBUG] Program memory cache miss at 0x000000d0, 10 bytes 2024-04-09 22:41:41.260 SAST [DS]: [DEBUG] Delivering response for ReadTargetMemory command (ID: 16) 2024-04-09 22:41:41.260 SAST [DS]: [DEBUG] Writing GDB packet: $1197f1f70197d1f70895#df 2024-04-09 22:41:41.305 SAST [DS]: [DEBUG] Read GDB packet: $m800286,02#33 2024-04-09 22:41:41.305 SAST [DS]: [INFO] Handling ReadMemory packet 2024-04-09 22:41:41.306 SAST [DS]: [DEBUG] Issuing ReadTargetMemory command (ID: 17) to TargetController 2024-04-09 22:41:41.343 SAST [DS]: [DEBUG] Delivering response for ReadTargetMemory command (ID: 17) 2024-04-09 22:41:41.344 SAST [DS]: [DEBUG] Writing GDB packet: $6955#d9 2024-04-09 22:41:41.397 SAST [DS]: [DEBUG] Read GDB packet: $m80098F,02#4A 2024-04-09 22:41:41.397 SAST [DS]: [INFO] Handling ReadMemory packet 2024-04-09 22:41:41.398 SAST [DS]: [DEBUG] GDB requested access to memory which is outside the target's memory range - returning error response 2024-04-09 22:41:41.398 SAST [DS]: [DEBUG] Writing GDB packet: $E01#a6 2024-04-09 22:41:41.484 SAST [DS]: [DEBUG] Read GDB packet: $m98,38#75 2024-04-09 22:41:41.485 SAST [DS]: [INFO] Handling ReadMemory packet 2024-04-09 22:41:41.486 SAST [DS]: [DEBUG] Issuing ReadTargetMemory command (ID: 18) to TargetController 2024-04-09 22:41:41.486 SAST [TC]: [DEBUG] Program memory cache miss at 0x00000098, 56 bytes 2024-04-09 22:41:41.639 SAST [DS]: [DEBUG] Delivering response for ReadTargetMemory command (ID: 18) 2024-04-09 22:41:41.640 SAST [DS]: [DEBUG] Writing GDB packet: $e1f70c944f000e94610020e224b92d982d9a84efa1e09a2f0e9463002d9884efa1e09a2f0e946300f3cf0895ffcf8115910531f0afe9bfe0#0b 2024-04-09 22:41:41.688 SAST [DS]: [DEBUG] Read GDB packet: $mD0,3C#83 2024-04-09 22:41:41.689 SAST [DS]: [INFO] Handling ReadMemory packet 2024-04-09 22:41:41.690 SAST [DS]: [DEBUG] Issuing ReadTargetMemory command (ID: 19) to TargetController 2024-04-09 22:41:41.690 SAST [DS]: [DEBUG] Delivering response for ReadTargetMemory command (ID: 19) 2024-04-09 22:41:41.691 SAST [DS]: [DEBUG] Writing GDB packet: $1197f1f70197d1f70895ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff209168002395209368002091#fc 2024-04-09 22:41:46.667 SAST [DS]: [DEBUG] Read GDB packet: $k#6B 2024-04-09 22:41:46.668 SAST [DS]: [DEBUG] Unknown GDB RSP packet: k - returning empty response 2024-04-09 22:41:46.669 SAST [DS]: [DEBUG] Writing GDB packet: $#00 2024-04-09 22:41:46.757 SAST [DS]: [DEBUG] Read GDB packet: $vKill;1#6E 2024-04-09 22:41:46.757 SAST [DS]: [DEBUG] Unknown GDB RSP packet: vKill;1 - returning empty response 2024-04-09 22:41:46.758 SAST [DS]: [DEBUG] Writing GDB packet: $#00 2024-04-09 22:41:46.844 SAST [DS]: [DEBUG] Read GDB packet: $D#44 2024-04-09 22:41:46.845 SAST [DS]: [INFO] Handling Detach packet 2024-04-09 22:41:46.845 SAST [DS]: [DEBUG] Writing GDB packet: $OK#9a 2024-04-09 22:41:47.188 SAST [DS]: [INFO] GDB RSP client disconnected 2024-04-09 22:41:47.189 SAST [DS]: [DEBUG] Event "DebugSessionFinished" (10) registered for listener ApplicationEventListener 2024-04-09 22:41:47.189 SAST [DS]: [DEBUG] Event "DebugSessionFinished" (10) registered for listener TargetControllerEventListener 2024-04-09 22:41:47.189 SAST [TC]: [DEBUG] Dispatching event DebugSessionFinished (10). 2024-04-09 22:41:47.189 SAST [DS]: [INFO] Waiting for GDB RSP connection 2024-04-09 22:41:47.227 SAST [MT]: [DEBUG] Dispatching event DebugSessionFinished (10). 2024-04-09 22:41:47.228 SAST [MT]: [INFO] Shutting down Bloom

Of course just issuing a detach command while the target is running does shut down Bloom.

ccrause commented 2 months ago

I've just compiled an unofficial v1.0.1 build for you. That one will send empty response packets without the null byte. Have attached a DEB, RPM and PKGBUILD package:

DEB: https://bloom-public-bucket.s3.eu-west-1.amazonaws.com/Bloom-1.0.1-Linux-x86_64.deb RPM: https://bloom-public-bucket.s3.eu-west-1.amazonaws.com/Bloom-1.0.1-Linux-x86_64.rpm PKGBUILD: https://bloom-public-bucket.s3.eu-west-1.amazonaws.com/Bloom-1.0.1-Linux-x86_64.pkg.tar.gz

Can you give it a go and let me know if it helps?

I will test this probably towards the weekend, thank you. But I think the immediate problem of handling 0x00 as empty is manageable on my side.

navnavnav commented 2 months ago

else detach does nothing

Hmm, that's because the documentation implies that GDB will disconnect from Bloom, not the other way around:

It is sent to the remote target before GDB disconnects via the detach command.

From: https://sourceware.org/gdb/current/onlinedocs/gdb.html/Packets.html#Packets

In your second example, the client (GDB) closed the connection:

2024-04-09 22:41:47.188 SAST [DS]: [INFO] GDB RSP client disconnected

With client->server connections, the client is typically responsible for closing the connection. Bloom should only do it when it encounters a fatal error of some sort.

How are you even sending the detach command whilst the target is running? GDB should not send any other command to Bloom whilst the target is running, unless it's to interrupt execution. Can you confirm that you're not running in "extended mode"? If you are running in that mode, Bloom will likely misbehave as it simply doesn't support that mode of operation.

I can add a check for 0x00 and interpret it the same as an empty response.

Are you writing your own GDB client? Or some other program that requires access to the target via Bloom's GDB server? I ask because I've been pondering on a similar idea for an automated testing framework. But that's all it is at the moment - just an idea.

navnavnav commented 2 months ago

If you are writing your own GDB client, and you just want a way to terminate the debug session, all you have to do is send the detach packet and then close the connection. That should be sufficient. Bloom will then shutdown (or prepare itself for another session, if shutdownPostDebugSession is set to false).

ccrause commented 2 months ago

My apologies, I neglected to mention that I'm working on a remote debugger addin for the Lazarus IDE.

The main focus currently is on embedded targets like AVR and Xtensa (specifically the ESP32), so I only need a subset of the remote protocol commands to cover the debugging needs. I try to be compatible with several servers such as qemu (AVR and ESP32), fp-avrsim, debugwire-gdb-bridge and now Bloom.

With client->server connections, the client is typically responsible for closing the connection.

Currently the approach is to ensure that the kill or detach commands complete successfully before terminating the connection. I will change the behaviour to ensure that the connection is closed regardless.

ccrause commented 2 months ago

Thank you for your attention to this issue. I have updated the Lazarus debugger and confirm that v1.0.1 works great with Lazarus now.