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.

Understanding the Greentea Test Runner

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:

1. CTest runs a small shim CMake script (<build dir>/hal/tests/TESTS/mbed_hal/reset_reason/mbed-run-greentea-mbed-hal-reset-reason.cmake) which runs the other test commands.
2. The code is built and flashed onto the device using the Mbed build system: ninja flash-mbed-hal-reset-reason. In my configuration, this calls openocd to flash the binary.
3. The MCU resets and the code boots. The code waits for the sync string from the host.
4. 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
5. mbedhtrun resets the device, sends the sync string, and the test starts running.
6. The device sends the message {{__host_test_name;reset_reason}}, which tells mbedhtrun to load rtc_reason.py from the host test folder I:/RPL/mbed-os/hal/tests/TESTS/mbed_hal/reset_reason/../../host_tests
7. The host test file is loaded and begins communicating with the test suite
8. The tests run and, eventually, all of them pass
9. 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

$ 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
[1663529369.89][HTST][INF] host test executor ver. 1.8.14
[1663529369.89][HTST][INF] copy image onto target... SKIPPED!
[1663529369.89][HTST][INF] starting host test process...
[1663529370.71][CONN][INF] starting connection process...
[1663529370.71][CONN][INF] notify event queue about extra 60 sec timeout for serial port pooling
[1663529370.71][CONN][INF] initializing serial port listener...
[1663529370.71][HTST][INF] setting timeout to: 60 sec
[1663529370.71][SERI][INF] using specified port 'COM3'
[1663529370.71][SERI][INF] serial(port=COM3, baudrate=9600, read_timeout=0.01, write_timeout=5)
[1663529370.71][SERI][INF] reset device using 'default' plugin...
[1663529370.96][SERI][INF] waiting 1.00 sec after reset
[1663529371.96][SERI][INF] wait for it...
[1663529371.99][SERI][TXD] mbedmbedmbedmbedmbedmbedmbedmbedmbedmbed
[1663529371.99][CONN][INF] sending up to 2 __sync packets (specified with --sync=2)
[1663529371.99][CONN][INF] sending preamble 'f751be28-8dad-4430-93e8-0a05df878024'
[1663529372.03][SERI][TXD] {{__sync;f751be28-8dad-4430-93e8-0a05df878024}}
[1663529372.10][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
[1663529372.15][CONN][INF] found SYNC in stream: {{__sync;f751be28-8dad-4430-93e8-0a05df878024}} it is #0 sent, queued...
[1663529372.15][HTST][INF] sync KV found, uuid=f751be28-8dad-4430-93e8-0a05df878024, timestamp=1663529372.147684
[1663529372.17][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
[1663529372.17][HTST][INF] DUT greentea-client version: 1.3.0
[1663529372.18][CONN][INF] found KV pair in stream: {{__timeout;90}}, queued...
[1663529372.18][HTST][INF] setting timeout to: 90 sec
[1663529372.22][CONN][INF] found KV pair in stream: {{__host_test_name;reset_reason}}, queued...
[1663529372.22][HTST][INF] host test class: '<class 'reset_reason.ResetReasonTest'>'
[1663529372.22][HTST][INF] host test setup() call...
[1663529372.22][HTST][INF] CALLBACKs updated
[1663529372.22][HTST][INF] host test detected: reset_reason
[1663529372.24][CONN][INF] found KV pair in stream: {{ready;0000001a,1}}, queued...
[1663529372.27][SERI][TXD] {{reason_raw;get}}
[1663529372.31][CONN][INF] found KV pair in stream: {{reason_raw;24000600}}, queued...
[1663529372.31][SERI][TXD] {{reason;get}}
[1663529372.34][CONN][INF] found KV pair in stream: {{reason;4}}, queued...
[1663529372.36][SERI][TXD] {{reason;clear}}
[1663529372.40][CONN][INF] found KV pair in stream: {{reason;cleared}}, queued...
[1663529372.40][SERI][TXD] {{reset;nvic}}
[1663529372.43][CONN][INF] found KV pair in stream: {{reset;ack}}, queued...
[1663529373.44][SERI][TXD] {{__sync;0}}
[1663529373.49][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
[1663529373.51][CONN][INF] found KV pair in stream: {{__sync;0}}, queued...
[1663529373.51][HTST][ERR] orphan event in main phase: {{__sync;0}}, timestamp=1663529373.513048
[1663529373.54][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
[1663529373.54][HTST][ERR] orphan event in main phase: {{__version;1.3.0}}, timestamp=1663529373.535987
[1663529373.55][CONN][INF] found KV pair in stream: {{__timeout;90}}, queued...
[1663529373.55][HTST][ERR] orphan event in main phase: {{__timeout;90}}, timestamp=1663529373.548952
[1663529373.58][CONN][INF] found KV pair in stream: {{__host_test_name;reset_reason}}, queued...
[1663529373.58][HTST][ERR] orphan event in main phase: {{__host_test_name;reset_reason}}, timestamp=1663529373.584856
[1663529373.61][CONN][INF] found KV pair in stream: {{ready;0000001a,1}}, queued...
[1663529373.62][SERI][TXD] {{reason_raw;get}}
[1663529373.66][CONN][INF] found KV pair in stream: {{reason_raw;14000600}}, queued...
[1663529373.66][SERI][TXD] {{reason;get}}
[1663529373.69][CONN][INF] found KV pair in stream: {{reason;3}}, queued...
[1663529373.71][SERI][TXD] {{reason;clear}}
[1663529373.75][CONN][INF] found KV pair in stream: {{reason;cleared}}, queued...
[1663529373.76][CONN][INF] received special event '__reset', resetting dut
[1663529373.76][SERI][INF] reset device using 'default' plugin...
[1663529374.01][SERI][INF] waiting 1.00 sec after reset
[1663529375.02][SERI][INF] wait for it...
[1663529376.03][SERI][TXD] {{__sync;0}}
[1663529376.09][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
[1663529376.10][CONN][INF] found KV pair in stream: {{__sync;0}}, queued...
[1663529376.10][HTST][ERR] orphan event in main phase: {{__sync;0}}, timestamp=1663529376.101190
[1663529376.12][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
[1663529376.12][HTST][ERR] orphan event in main phase: {{__version;1.3.0}}, timestamp=1663529376.123131
[1663529376.13][CONN][INF] found KV pair in stream: {{__timeout;90}}, queued...
[1663529376.13][HTST][ERR] orphan event in main phase: {{__timeout;90}}, timestamp=1663529376.133610
[1663529376.17][CONN][INF] found KV pair in stream: {{__host_test_name;reset_reason}}, queued...
[1663529376.17][HTST][ERR] orphan event in main phase: {{__host_test_name;reset_reason}}, timestamp=1663529376.171509
[1663529376.19][CONN][INF] found KV pair in stream: {{ready;0000001a,1}}, queued...
[1663529376.21][SERI][TXD] {{reason_raw;get}}
[1663529376.25][CONN][INF] found KV pair in stream: {{reason_raw;04000600}}, queued...
[1663529376.25][SERI][TXD] {{reason;get}}
[1663529376.28][CONN][INF] found KV pair in stream: {{reason;1}}, queued...
[1663529376.30][SERI][TXD] {{reason;clear}}
[1663529376.32][CONN][INF] found KV pair in stream: {{reason;cleared}}, queued...
[1663529376.34][SERI][TXD] {{reset;watchdog}}
[1663529376.36][CONN][INF] found KV pair in stream: {{reset;ack}}, queued...
[1663529377.37][SERI][TXD] {{__sync;0}}
[1663529377.42][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
[1663529377.44][CONN][INF] found KV pair in stream: {{__sync;0}}, queued...
[1663529377.44][HTST][ERR] orphan event in main phase: {{__sync;0}}, timestamp=1663529377.444106
[1663529377.46][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
[1663529377.46][HTST][ERR] orphan event in main phase: {{__version;1.3.0}}, timestamp=1663529377.457072
[1663529377.48][CONN][INF] found KV pair in stream: {{__timeout;90}}, queued...
[1663529377.48][HTST][ERR] orphan event in main phase: {{__timeout;90}}, timestamp=1663529377.483002
[1663529377.52][CONN][INF] found KV pair in stream: {{__host_test_name;reset_reason}}, queued...
[1663529377.52][HTST][ERR] orphan event in main phase: {{__host_test_name;reset_reason}}, timestamp=1663529377.517908
[1663529377.54][CONN][INF] found KV pair in stream: {{ready;0000001a,1}}, queued...
[1663529377.56][SERI][TXD] {{reason_raw;get}}
[1663529377.60][CONN][INF] found KV pair in stream: {{reason_raw;24000600}}, queued...
[1663529377.60][SERI][TXD] {{reason;get}}
[1663529377.63][CONN][INF] found KV pair in stream: {{reason;4}}, queued...
[1663529377.63][HTST][INF] __notify_complete(True)
[1663529377.63][HTST][INF] __exit_event_queue received
[1663529377.63][HTST][INF] test suite run finished after 5.45 sec...
[1663529377.64][CONN][INF] received special event '__host_test_finished' value='True', finishing
[1663529377.70][HTST][INF] CONN exited with code: 0
[1663529377.70][HTST][INF] No events in queue
[1663529377.70][HTST][INF] stopped consuming events
[1663529377.70][HTST][INF] host test result() call skipped, received: True
[1663529377.70][HTST][WRN] missing __exit event from DUT
[1663529377.70][HTST][INF] calling blocking teardown()
[1663529377.70][HTST][INF] teardown() finished
[1663529377.70][HTST][INF] {{result;success}}