-
Notifications
You must be signed in to change notification settings - Fork 18
Debugging Failing Greentea Tests
Got a Greentea test that's failing? This page will show you how to debug it and see what's going on.
First thing's first: We need to go over some basics of how the Greentea test runner works. Essentially, Greentea is a system that can flash a test suite onto a device, run it, and facilitate communication with a host script. At minimum, the host script receives test results from the device over a serial port and reports success or failure. However, it can also do other things, like running USB transfers or resetting the device.
Greentea works by using a serial port to transfer information, in the form of key-value pairs, between the host and the MCU under test. When it boots, the MCU code waits until it sees a special "sync string" (which looks like {{__sync;0dad4a9d-59a3-4aec-810d-d5fb09d852c1}}) from the host. Then, it begins executing tests and reporting information to the host. This means that if you run a test in the debugger, it won't do anything without the correct communication from the host test runner.
As an example in this guide, let's look at the mbed-hal-reset-reason test. This test is relatively simple, but has a host script that interacts with the embedded code. Let's say you run this test from the build directory: ctest -R mbed-hal-reset-reason (the -R argument tells CTest to only run tests which match a regex):
$ ctest -R mbed-hal-reset-reason
Test project I:/RPL/mbed-os/cmake-build-nucleo-l452re-p-greentea
Start 13: mbed-hal-reset-reason
1/1 Test #13: mbed-hal-reset-reason ............ Passed 12.19 sec
100% tests passed, 0 tests failed out of 1
Total Test time (real) = 12.44 sec
Under the hood, when you run the test, the following sequence of things happens:
- CTest runs a small shim CMake script (
<build dir>/hal/tests/TESTS/mbed_hal/reset_reason/mbed-run-greentea-test-mbed-hal-reset-reason.cmake) which runs the other test commands. - The code is built and flashed onto the device using the Mbed build system:
ninja flash-test-mbed-hal-reset-reason. In my configuration, this calls openocd to flash the binary. - The MCU resets and the code boots. The code waits for the sync string from the host.
- The test script starts mbedhtrun, which communicates with the MCU:
mbedhtrun --skip-flashing -p COM3 -e I:/RPL/mbed-os/hal/tests/TESTS/mbed_hal/reset_reason/../../host_tests -m NUCLEO_L452RE_P --baud-rate=9600 - mbedhtrun resets the device, sends the sync string, and the test starts running.
- The device sends the message
{{__host_test_name;reset_reason}}, which tells mbedhtrun to load rtc_reason.py from the host test folderI:/RPL/mbed-os/hal/tests/TESTS/mbed_hal/reset_reason/../../host_tests - The host test file is loaded and begins communicating with the test suite
- The tests run and, eventually, all of them pass
- mbedhtrun exits with a 0 exit code, indicating to CTest that the tests passed.
For reference, here's the full command line output (from ctest -V) from the above process. See if you can spot where each thing is happening!
Full output of running the reset reason test
$ ctest -V -R mbed-hal-reset-reason
UpdateCTestConfiguration from :I:/RPL/mbed-os/cmake-build-nucleo-l452re-p-greentea/DartConfiguration.tcl
Parse Config file:I:/RPL/mbed-os/cmake-build-nucleo-l452re-p-greentea/DartConfiguration.tcl
UpdateCTestConfiguration from :I:/RPL/mbed-os/cmake-build-nucleo-l452re-p-greentea/DartConfiguration.tcl
Parse Config file:I:/RPL/mbed-os/cmake-build-nucleo-l452re-p-greentea/DartConfiguration.tcl
Test project I:/RPL/mbed-os/cmake-build-nucleo-l452re-p-greentea
Constructing a list of tests
Done constructing a list of tests
Updating test list for fixtures
Added 0 tests to meet fixture requirements
Checking test dependency graph...
Checking test dependency graph end
test 13
Start 13: mbed-hal-reset-reason
13: Test command: "C:\Program Files\CMake\bin\cmake.exe" "-P" "mbed-run-greentea-mbed-hal-reset-reason.cmake"
13: Test timeout computed to be: 1500
13: [1/1] Flashing mbed-hal-reset-reason with OpenOCD...
13: Open On-Chip Debugger 0.11.0 (2021-03-07-12:52)
13: Licensed under GNU GPL v2
13: For bug reports, read
13: http://openocd.org/doc/doxygen/bugs.html
13: DEPRECATED! use 'adapter driver' not 'interface'
13: Info : The selected transport took over low-level target control. The results might differ compared to plain JTAG/SWD
13: Info : clock speed 500 kHz
13: Info : STLINK V2J39M27 (API v2) VID:PID 0483:374B
13: Info : Target voltage: 3.240553
13: Info : stm32l4x.cpu: hardware has 6 breakpoints, 4 watchpoints
13: Info : starting gdb server for stm32l4x.cpu on 3333
13: Info : Listening on port 3333 for gdb connections
13: Info : Unable to match requested speed 500 kHz, using 480 kHz
13: Info : Unable to match requested speed 500 kHz, using 480 kHz
13: target halted due to debug-request, current mode: Thread
13: xPSR: 0x01000000 pc: 0x0800c544 msp: 0x10000698
13: ** Programming Started **
13: Info : device idcode = 0x20016462 (STM32L45/L46xx - Rev Y : 0x2001)
13: Info : flash size = 512kbytes
13: Info : flash mode : single-bank
13: Warn : Adding extra erase range, 0x0800b208 .. 0x0800b7ff
13: ** Programming Finished **
13: ** Resetting Target **
13: Info : Unable to match requested speed 500 kHz, using 480 kHz
13: Info : Unable to match requested speed 500 kHz, using 480 kHz
13: shutdown command invoked
13: Executing: mbedhtrun --skip-flashing -f mbed-hal-reset-reason.bin -p COM3 -e I:/RPL/mbed-os/hal/tests/TESTS/mbed_hal/reset_reason/../../host_tests -m NUCLEO_L452RE_P --baud-rate=9600
13: [1663528497.02][HTST][INF] host test executor ver. 1.8.14
13: [1663528497.02][HTST][INF] copy image onto target... SKIPPED!
13: [1663528497.02][HTST][INF] starting host test process...
13: [1663528497.91][CONN][INF] starting connection process...
13: [1663528497.91][CONN][INF] notify event queue about extra 60 sec timeout for serial port pooling
13: [1663528497.91][CONN][INF] initializing serial port listener...
13: [1663528497.91][SERI][INF] using specified port 'COM3'
13: [1663528497.91][SERI][INF] serial(port=COM3, baudrate=9600, read_timeout=0.01, write_timeout=5)
13: [1663528497.91][HTST][INF] setting timeout to: 60 sec
13: [1663528497.91][SERI][INF] reset device using 'default' plugin...
13: [1663528498.16][SERI][INF] waiting 1.00 sec after reset
13: [1663528499.17][SERI][INF] wait for it...
13: [1663528499.20][SERI][TXD] mbedmbedmbedmbedmbedmbedmbedmbedmbedmbed
13: [1663528499.20][CONN][INF] sending up to 2 __sync packets (specified with --sync=2)
13: [1663528499.20][CONN][INF] sending preamble '961010d9-ba4a-4deb-b8ae-fbee15709516'
13: [1663528499.24][SERI][TXD] {{__sync;961010d9-ba4a-4deb-b8ae-fbee15709516}}
13: [1663528499.30][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
13: [1663528499.35][CONN][INF] found SYNC in stream: {{__sync;961010d9-ba4a-4deb-b8ae-fbee15709516}} it is #0 sent, queued...
13: [1663528499.35][HTST][INF] sync KV found, uuid=961010d9-ba4a-4deb-b8ae-fbee15709516, timestamp=1663528499.354804
13: [1663528499.38][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
13: [1663528499.38][HTST][INF] DUT greentea-client version: 1.3.0
13: [1663528499.39][CONN][INF] found KV pair in stream: {{__timeout;90}}, queued...
13: [1663528499.39][HTST][INF] setting timeout to: 90 sec
13: [1663528499.43][CONN][INF] found KV pair in stream: {{__host_test_name;reset_reason}}, queued...
13: [1663528499.43][HTST][INF] host test class: '<class 'reset_reason.ResetReasonTest'>'
13: [1663528499.43][HTST][INF] host test setup() call...
13: [1663528499.43][HTST][INF] CALLBACKs updated
13: [1663528499.43][HTST][INF] host test detected: reset_reason
13: [1663528499.45][CONN][INF] found KV pair in stream: {{ready;0000001a,1}}, queued...
13: [1663528499.48][SERI][TXD] {{reason_raw;get}}
13: [1663528499.51][CONN][INF] found KV pair in stream: {{reason_raw;1c000600}}, queued...
13: [1663528499.53][SERI][TXD] {{reason;get}}
13: [1663528499.56][CONN][INF] found KV pair in stream: {{reason;3}}, queued...
13: [1663528499.59][SERI][TXD] {{reason;clear}}
13: [1663528499.62][CONN][INF] found KV pair in stream: {{reason;cleared}}, queued...
13: [1663528499.63][SERI][TXD] {{reset;nvic}}
13: [1663528499.67][CONN][INF] found KV pair in stream: {{reset;ack}}, queued...
13: [1663528500.68][SERI][TXD] {{__sync;0}}
13: [1663528500.74][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
13: [1663528500.75][CONN][INF] found KV pair in stream: {{__sync;0}}, queued...
13: [1663528500.75][HTST][ERR] orphan event in main phase: {{__sync;0}}, timestamp=1663528500.748583
13: [1663528500.76][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
13: [1663528500.76][HTST][ERR] orphan event in main phase: {{__version;1.3.0}}, timestamp=1663528500.761548
13: [1663528500.78][CONN][INF] found KV pair in stream: {{__timeout;90}}, queued...
13: [1663528500.78][HTST][ERR] orphan event in main phase: {{__timeout;90}}, timestamp=1663528500.784486
13: [1663528500.82][CONN][INF] found KV pair in stream: {{__host_test_name;reset_reason}}, queued...
13: [1663528500.82][HTST][ERR] orphan event in main phase: {{__host_test_name;reset_reason}}, timestamp=1663528500.821387
13: [1663528500.85][CONN][INF] found KV pair in stream: {{ready;0000001a,1}}, queued...
13: [1663528500.88][SERI][TXD] {{reason_raw;get}}
13: [1663528500.91][CONN][INF] found KV pair in stream: {{reason_raw;14000600}}, queued...
13: [1663528500.92][SERI][TXD] {{reason;get}}
13: [1663528500.96][CONN][INF] found KV pair in stream: {{reason;3}}, queued...
13: [1663528500.99][SERI][TXD] {{reason;clear}}
13: [1663528501.01][CONN][INF] found KV pair in stream: {{reason;cleared}}, queued...
13: [1663528501.02][CONN][INF] received special event '__reset', resetting dut
13: [1663528501.02][SERI][INF] reset device using 'default' plugin...
13: [1663528501.28][SERI][INF] waiting 1.00 sec after reset
13: [1663528502.28][SERI][INF] wait for it...
13: [1663528503.29][SERI][TXD] {{__sync;0}}
13: [1663528503.35][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
13: [1663528503.36][CONN][INF] found KV pair in stream: {{__sync;0}}, queued...
13: [1663528503.36][HTST][ERR] orphan event in main phase: {{__sync;0}}, timestamp=1663528503.362141
13: [1663528503.39][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
13: [1663528503.39][HTST][ERR] orphan event in main phase: {{__version;1.3.0}}, timestamp=1663528503.386077
13: [1663528503.40][CONN][INF] found KV pair in stream: {{__timeout;90}}, queued...
13: [1663528503.40][HTST][ERR] orphan event in main phase: {{__timeout;90}}, timestamp=1663528503.399042
13: [1663528503.44][CONN][INF] found KV pair in stream: {{__host_test_name;reset_reason}}, queued...
13: [1663528503.44][HTST][ERR] orphan event in main phase: {{__host_test_name;reset_reason}}, timestamp=1663528503.435943
13: [1663528503.46][CONN][INF] found KV pair in stream: {{ready;0000001a,1}}, queued...
13: [1663528503.49][SERI][TXD] {{reason_raw;get}}
13: [1663528503.52][CONN][INF] found KV pair in stream: {{reason_raw;04000600}}, queued...
13: [1663528503.54][SERI][TXD] {{reason;get}}
13: [1663528503.58][CONN][INF] found KV pair in stream: {{reason;1}}, queued...
13: [1663528503.60][SERI][TXD] {{reason;clear}}
13: [1663528503.63][CONN][INF] found KV pair in stream: {{reason;cleared}}, queued...
13: [1663528503.66][SERI][TXD] {{reset;watchdog}}
13: [1663528503.68][CONN][INF] found KV pair in stream: {{reset;ack}}, queued...
13: [1663528504.69][SERI][TXD] {{__sync;0}}
13: [1663528504.75][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
13: [1663528504.76][CONN][INF] found KV pair in stream: {{__sync;0}}, queued...
13: [1663528504.76][HTST][ERR] orphan event in main phase: {{__sync;0}}, timestamp=1663528504.763899
13: [1663528504.79][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
13: [1663528504.79][HTST][ERR] orphan event in main phase: {{__version;1.3.0}}, timestamp=1663528504.788339
13: [1663528504.80][CONN][INF] found KV pair in stream: {{__timeout;90}}, queued...
13: [1663528504.80][HTST][ERR] orphan event in main phase: {{__timeout;90}}, timestamp=1663528504.800307
13: [1663528504.83][CONN][INF] found KV pair in stream: {{__host_test_name;reset_reason}}, queued...
13: [1663528504.83][HTST][ERR] orphan event in main phase: {{__host_test_name;reset_reason}}, timestamp=1663528504.834729
13: [1663528504.86][CONN][INF] found KV pair in stream: {{ready;0000001a,1}}, queued...
13: [1663528504.89][SERI][TXD] {{reason_raw;get}}
13: [1663528504.92][CONN][INF] found KV pair in stream: {{reason_raw;24000600}}, queued...
13: [1663528504.94][SERI][TXD] {{reason;get}}
13: [1663528504.97][CONN][INF] found KV pair in stream: {{reason;4}}, queued...
13: [1663528504.97][HTST][INF] __notify_complete(True)
13: [1663528504.97][HTST][INF] __exit_event_queue received
13: [1663528504.97][HTST][INF] test suite run finished after 5.58 sec...
13: [1663528504.98][CONN][INF] received special event '__host_test_finished' value='True', finishing
13: [1663528505.04][HTST][INF] CONN exited with code: 0
13: [1663528505.04][HTST][INF] No events in queue
13: [1663528505.04][HTST][INF] stopped consuming events
13: [1663528505.04][HTST][INF] host test result() call skipped, received: True
13: [1663528505.04][HTST][WRN] missing __exit event from DUT
13: [1663528505.04][HTST][INF] calling blocking teardown()
13: [1663528505.04][HTST][INF] teardown() finished
13: [1663528505.04][HTST][INF] {{result;success}}
1/1 Test #13: mbed-hal-reset-reason ............ Passed 12.24 sec
The following tests passed:
mbed-hal-reset-reason
100% tests passed, 0 tests failed out of 1
Total Test time (real) = 12.54 sec
Now, we can look at how to run the debugger on a test. Let's say that the mbed-hal-reset-reason test is failing, and I wanted to observe it in the debugger.
The first thing to do is make sure the test is flashed to the device: ninja flash-mbed-hal-reset-reason
Then, run a gdbserver in one terminal (ninja gdbserver), and connect to it in another terminal (ninja debug-mbed-hal-reset-reason). I'll set a breakpoint on the test: b test_reset_reason, but it won't be hit yet, because it's still waiting for the host to connect. Then, I'll let the test continue running with the c command.
Finally, in a third terminal, I'll start the host test. The easiest way to find this command is to run the test with ctest -V -R <your test name> (see previous section), and then look for the line that starts with "Executing: mbedhtrun". Take this command, add --skip-reset to it (so that it won't reset the device and break the debugger), and then run it. For example, the line in the ctest output is:
13: Executing: mbedhtrun --skip-flashing -p COM3 -e I:/RPL/mbed-os/hal/tests/TESTS/mbed_hal/reset_reason/../../host_tests -m NUCLEO_L452RE_P --baud-rate=9600
So I'll run
mbedhtrun --skip-flashing -p COM3 -e I:/RPL/mbed-os/hal/tests/TESTS/mbed_hal/reset_reason/../../host_tests -m NUCLEO_L452RE_P --baud-rate=9600 --skip-reset
Then, the test will start and the GDB breakpoint is hit! You can now step through the test in the debugger.
Each test has a timeout configured -- after the timeout elapses, the host-side test runner will give up and assume the device is hung. This is very useful for CI tests, but unless you're very speedy, it will likely cause problems for debugging. To prevent tests from timing out, edit the main.cpp of the test and find the call to GREENTEA_SETUP(). Change the first number, which is the timeout in seconds, to something very large.