colcon event handler which print stdout on error

[jpsamper2009]

Description

• As a developer, it would be easier to find broken tests in terminal logs if there was an option to only dump stdout of tests that failed.

Current Behavior

• Currently, I can either run my builds with colcon test --event-handlers console_cohesion+ and then scroll through the terminal to find the broken test OR I can run colcon test and then have to go to log/latest_test/my_pkg/stdout.log to find the broken test.

• The first option is too noisy

• The second option has the disadvantage that in (our) CI, these logs aren't easily accessible

  • As far as I can tell, there is no simple way to say,

  for each failing package:
      print file log/latest_test/<pkg>/stdout.log
  

Desired Behavior

• An option like console test --event-handlers console_stdout_on_fail+ where:
  • If a package succeeds, the output looks like console test
  • If a package fails, the output looks like console test --event-handlers console_cohesion+

[dirk-thomas]

Usually you don't want to see the stdout output of the tests but the actually reported content. Depending on the test framework that might be some part of stdout and/or stderr or not even being printed in full on the console at all.

Have you tried using the colcon test-result verb? By default it enumerates all tests with errors / failures. By additionally passing --verbose it will output the content from the failing tests as they are being reported in the xUnit formatted result files.

[dirk-thomas]

Please let me know if my previous reply was helpful and answered / resolved your question so that the ticket can eventually be closed.

[jpsamper2009]

@dirk-thomas Maybe the problem is with how the failing tests are reported to xUnit files... I'll need to investigate. I'll report back

[jpsamper2009]

@dirk-thomas The issue is some packages don't really report much: e.g. when demo_nodes_cpp fails, all I see is:

$ colcon test ...
...
--- stderr: demo_nodes_cpp                                                                                                                                   
Errors while running CTest
---
Finished <<< demo_nodes_cpp [51.4s]	[ with test failures ]

Then

$ colcon test-result --verbose
...
build/demo_nodes_cpp/test_results/demo_nodes_cpp/test_tutorial_add_two_ints_server_add_two_ints_client__rmw_fastrtps_cpp.xunit.xml: 1 test, 0 errors, 1 failure, 0 skipped
- demo_nodes_cpp test_tutorial_add_two_ints_server_add_two_ints_client__rmw_fastrtps_cpp.xunit.missing_result
  <<< failure message
    The test did not generate a result file.
  >>>
...

when what I really want to see is

$ cat log/latest_test/demo_nodes_cpp/stdout.log
8: Test command: /usr/bin/python3 "-u" "/home/jp.samper/ros2_ws/install/ament_cmake_test/share/ament_cmake_test/cmake/run_test.py" "/home/jp.samper/ros2_ws/build/demo_nodes_cpp/test_re
sults/demo_nodes_cpp/test_tutorial_add_two_ints_server_add_two_ints_client__rmw_fastrtps_cpp.xunit.xml" "--package-name" "demo_nodes_cpp" "--output-file" "/home/jp.samper/ros2_ws/build/de
mo_nodes_cpp/ament_cmake_pytest/test_tutorial_add_two_ints_server_add_two_ints_client__rmw_fastrtps_cpp.txt" "--env" "RCL_ASSERT_RMW_ID_MATCHES=rmw_fastrtps_cpp" "RMW_IMPLEMENTATION=rmw_fast
rtps_cpp" "--command" "/usr/bin/python3" "-u" "-m" "pytest" "/home/jp.samper/ros2_ws/build/demo_nodes_cpp/test_add_two_ints_server_add_two_ints_client__rmw_fastrtps_cpp_Coverage.py" "-o" 
"cache_dir=/home/jp.samper/ros2_ws/build/demo_nodes_cpp/ament_cmake_pytest/test_tutorial_add_two_ints_server_add_two_ints_client__rmw_fastrtps_cpp/.cache" "--junit-xml=/home/jp.samper/ros2_ws/build/demo_nodes_cpp/test_results/demo_nodes_cpp/test_tutorial_add_two_ints_server_add_two_ints_client__rmw_fastrtps_cpp.xunit.xml" "--junit-prefix=demo_nodes_cpp"
8: Test timeout computed to be: 30
8: -- run_test.py: extra environment variables:
8:  - RCL_ASSERT_RMW_ID_MATCHES=rmw_fastrtps_cpp
8:  - RMW_IMPLEMENTATION=rmw_fastrtps_cpp
8: -- run_test.py: invoking following command in '/home/jp.samper/ros2_ws/src/ros2/demos/demo_nodes_cpp':
8:  - /usr/bin/python3 -u -m pytest /home/jp.samper/ros2_ws/build/demo_nodes_cpp/test_add_two_ints_server_add_two_ints_client__rmw_fastrtps_cpp_Coverage.py -o cache_dir=/home/jp.samper/ros2_ws/build/demo_nodes_cpp/ament_cmake_pytest/test_tutorial_add_two_ints_server_add_two_ints_client__rmw_fastrtps_cpp/.cache --junit-xml=/home/jp.samper/ros2_ws/build/demo_nodes_cpp/test_results/demo_nodes_cpp/test_tutorial_add_two_ints_server_add_two_ints_client__rmw_fastrtps_cpp.xunit.xml --junit-prefix=demo_nodes_cpp
8: ============================= test session starts ==============================
8: platform linux -- Python 3.5.2, pytest-3.8.0, py-1.6.0, pluggy-0.7.1
8: rootdir: /home/jp.samper/ros2_ws, inifile:
8: plugins: rerunfailures-4.1, repeat-0.7.0, cov-2.6.0
8: collected 1 item
8: 
 8/16 Test  #8: test_tutorial_add_two_ints_server_add_two_ints_client__rmw_fastrtps_cpp .........***Timeout  30.01 sec

[dirk-thomas]

If you imagine a package with numerous tests I don't think you want to see the full stdout output in case one of the tests fails. Therefore I don't think a new event handler like "console-stdout-on-fail" is desired here.

Instead you want a concise output which just mentions the failed test - probably with as much information about the test as possible.

I am not sure how that can be achieved. Maybe the pytest invocation can be modified? Or maybe the result file generation can be altered?

[jpsamper2009]

@dirk-thomas I think improving the result file may be the way to go, no? In that case, we would need to improve ament_cmake_test/cmake/run_test.py?

[dirk-thomas]

In your output snippet above it looks like that you are running the tested with pytest and that uses the argument --junit-xml. So pytest is generating the xml file the colcon test result verb uses.

[dirk-thomas]

@jpsamper2009 were you able to make any progress on your use case?

[dirk-thomas]

@jpsamper2009 Friendly ping.

[jpsamper2009]

@dirk-thomas Thanks for the reminder! I got busy with other stuff. I'll get back to you

[dirk-thomas]

@jpsamper2009 Friendly ping.

[dirk-thomas]

I am going to close the ticket for now due to inactivity. Please feel free to comment and if necessary the ticket can be reopened.

[russkel]

Why can't a flag be added to test-result verb that spits out log/latest_test/demo_nodes_cpp/stdout.log ?