zephyrproject-rtos / zephyr

Primary Git Repository for the Zephyr Project. Zephyr is a new generation, scalable, optimized, secure RTOS for multiple hardware architectures.
https://docs.zephyrproject.org
Apache License 2.0
10.86k stars 6.62k forks source link

west: rtt: console output is non-functional with openocd runner #81156

Open cfriedt opened 4 days ago

cfriedt commented 4 days ago

Describe the bug

RTT console support for openocd was added to west in 18f45b5f063 .

It wasn't immediately clear how to use it on any board. Luckily some folks on Discord provided some pointers.

The west rtt command should be used as a drop-in replacement for west debug (sort of). Although west debug drops you down into the gdb console, west debug simply sets up a gdb service on port 3333, and drops you down into a telnet session with RTT output.

There was some concensus that the documentation could be improved.

Aside from that, there are additional technical shortcomings:

  1. west build -t rtt does not work (requiring separate west build and west rtt steps)
  2. west rtt by itself does not attempt to see if any available runners support rtt, requiring a runner to be specified (west rtt -r openocd)
  3. west rtt -r openocd does not actually work due to a race condition (requiring the target to be running so that firmware can execute SEGGER_RTT_Init() and initialize the RTT control block).

To Reproduce

  1. west build -p -S rtt-console -b <board> samples/hello_world
  2. west rtt -r openocd

Expected behavior

To be honest, it would be great if twister used a built-in handler for the RTT console. It doesn't make sense to have every user come up with their own --device-serial-pty script.

Impact Showstopper for anyone who does not have a dedicated serial port for seeing RTT console output via west or for anyone wishing to use RTT for device testing with twister.

Logs and console output

No rtt runner available (although openocd is available, it just isn't enabled).

zephyr % west rtt
FATAL ERROR: no rtt runner available for board nucleo_l496zg/stm32l496xx. Check the board's documentation for instructions.
FAILED: zephyr/cmake/flash/CMakeFiles/rtt /Users/cfriedt/zephyrproject/zephyr/build/zephyr/cmake/flash/CMakeFiles/rtt 
cd /Users/cfriedt/zephyrproject/zephyr/build && /opt/homebrew/Cellar/cmake/3.29.0/bin/cmake -DTARGET=rtt -DDEPENDENCIES="" -P /Users/cfriedt/zephyrproject/zephyr/cmake/flash/check_runner_dependencies.cmake && /opt/homebrew/Cellar/cmake/3.29.0/bin/cmake -E env /opt/zephyr/.venv/bin/python3.12 -m west rtt

Cannot run rtt start before target is running.

% west rtt -r openocd 
-- west rtt: rebuilding
ninja: no work to do.
-- west rtt: using runner openocd
-- runners.openocd: OpenOCD GDB server running on port 3333; no thread info available
Open On-Chip Debugger 0.12.0
Licensed under GNU GPL v2
For bug reports, read
        http://openocd.org/doc/doxygen/bugs.html
Info : The selected transport took over low-level target control. The results might differ compared to plain JTAG/SWD
Info : clock speed 500 kHz
Info : STLINK V2J35M26 (API v2) VID:PID 0483:374B
Info : Target voltage: 3.233202
ERROR: runners.openocd: [Errno 22] Invalid argument
Info : [stm32l4x.cpu] Cortex-M4 r0p1 processor detected
Info : [stm32l4x.cpu] target has 6 breakpoints, 4 watchpoints
Info : starting gdb server for stm32l4x.cpu on 3333
Info : Listening on port 3333 for gdb connections
    TargetName         Type       Endian TapName            State       
--  ------------------ ---------- ------ ------------------ ------------
 0* stm32l4x.cpu       hla_target little stm32l4x.cpu       running

Info : Unable to match requested speed 500 kHz, using 480 kHz
Info : Unable to match requested speed 500 kHz, using 480 kHz
[stm32l4x.cpu] halted due to debug-request, current mode: Thread 
xPSR: 0x01000000 pc: 0x08000888 msp: 0x20001180
Info : Listening on port 5555 for rtt connections
Info : rtt: Searching for control block 'SEGGER RTT'
Info : rtt: No control block found
Info : Listening on port 6333 for tcl connections
Info : Listening on port 4444 for telnet connections
shutdown command invoked

Environment (please complete the following information):

Additional context Script I used for testing twister with --device-serial-pty /tmp/rtt.sh

#!/bin/sh

set -e

OPENOCD_PID=""

cleanup() {
  if [ "$OPENOCD_PID" != "" ]; then
    kill $OPENOCD_PID >/dev/null 2>&1 || true
    wait $OPENOCD_PID >/dev/null 2>&1 || true
  fi
  exit 0
}

trap cleanup EXIT

# let the openocd flashing process proceed first, otherwise it will fail with "Device Flash Error"
sleep 2

openocd \
  -s /Users/cfriedt/zephyrproject/zephyr/boards/st/nucleo_l496zg/support \
  -s /opt/zephyr/zephyr-sdk-0.16.5-1/sysroots/arm64-pokysdk-linux/usr/share/openocd/scripts \
  -f /Users/cfriedt/zephyrproject/zephyr/boards/st/nucleo_l496zg/support/openocd.cfg \
  -c 'tcl_port 6333' -c 'telnet_port 4444' -c 'gdb_port 3333' \
  -c init \
  -c targets \
  -c 'rtt setup 0x20001010 0x10 "SEGGER RTT"' \
  -c 'rtt server start 5555 0' \
  -c 'reset run' \
  -c 'rtt start' \
  >/dev/null &
OPENOCD_PID=$!

# let the rtt server begin
sleep 1

# cat output of the RTT channel
nc localhost 5555

Changes needed to get both west and twister to work

diff --git a/cmake/flash/CMakeLists.txt b/cmake/flash/CMakeLists.txt
index 8fe7380695b..36eb3a33df6 100644
--- a/cmake/flash/CMakeLists.txt
+++ b/cmake/flash/CMakeLists.txt
@@ -154,7 +154,7 @@ endif()

 # Generate the flash, debug, debugserver, attach targets within the build
 # system itself.
-foreach(target flash debug debugserver attach)
+foreach(target flash debug debugserver attach rtt)
   if(target STREQUAL flash)
     set(comment "Flashing ${BOARD}")
   elseif(target STREQUAL debug)
@@ -168,6 +168,8 @@ foreach(target flash debug debugserver attach)
     endif()
   elseif(target STREQUAL attach)
     set(comment "Debugging ${BOARD}")
+  elseif(target STREQUAL rtt)
+    set(comment "Debugging ${BOARD}")
   endif()
   string(TOUPPER ${target} TARGET_UPPER)

diff --git a/scripts/west_commands/runners/openocd.py b/scripts/west_commands/runners/openocd.py
index 2569371ff9b..7c9e78f9ff5 100644
--- a/scripts/west_commands/runners/openocd.py
+++ b/scripts/west_commands/runners/openocd.py
@@ -418,6 +418,7 @@ class OpenOcdBinaryRunner(ZephyrBinaryRunner):
         rtt_cmds = [
             '-c', f'rtt setup 0x{rtt_address:x} 0x10 "SEGGER RTT"',
             '-c', f'rtt server start {self.rtt_port} 0',
+            '-c', 'reset run',
             '-c', 'rtt start',
         ]

@@ -426,31 +427,13 @@ class OpenOcdBinaryRunner(ZephyrBinaryRunner):
                        '-c', f'telnet_port {self.telnet_port}',
                        '-c', f'gdb_port {self.gdb_port}'] +
                       pre_init_cmd + self.init_arg + self.targets_arg +
-                       ['-c', self.reset_halt_cmd] +
                        rtt_cmds
                       )
         self.print_gdbserver_message()
         server_proc = self.popen_ignore_int(server_cmd)
-        # The target gets halted after all commands passed on the commandline are run.
-        # The only way to run resume here, to not have to connect a GDB, is to connect
-        # to the tcl port and run the command. When the TCL port comes up, initialization
-        # is done.
+
         try:
-            sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
-            # As long as the server process is still running, keep retrying the connection
-            while server_proc.poll() is None:
-                try:
-                    sock.connect(('localhost', self.tcl_port))
-                    break
-                except ConnectionRefusedError:
-                    time.sleep(0.1)
-            # \x1a is the command terminator for the openocd tcl rpc
-            sock.send(b'resume\x1a')
-            sock.shutdown(socket.SHUT_RDWR)
-            # Run the client. Since rtt is initialized before the tcl rpc comes up,
-            # the port is open now.
-            self.logger.info("Opening RTT")
-            time.sleep(0.1) # Give the server a moment to output log messages first
+            time.sleep(1) # Give the server a moment to output log messages first
             self.run_telnet_client('localhost', self.rtt_port)
         except Exception as e:
             self.logger.error(e)

Discussion on Discord

henrikbrixandersen commented 4 days ago

@cfriedt I get that this is annoying, but I do not think this is a medium priority bug.

cfriedt commented 4 days ago

@henrikbrixandersen - it affects multiple platforms. That was my main consideration for making it a medium. Currently, I'm looking at ARC, ARM, and RISC-V systems.

The fact that lots of users are also hitting this issue (but did not have a bug to comment on until now) was another consideration.

cc @dkalowsk @pdgendt @topisani