test_ros2trace tests hang on nightly Linux jobs

[christophebedard]

Operating System:

Latest Linux (Ubuntu + RHEL) target platforms

ROS version or commit hash:

Latest Rolling from source + Kilted (osrf/buildfarm-tools#183 (comment))

RMW implementation (if applicable):

(not directly involved in this)

RMW Configuration (if applicable):

No response

Client library (if applicable):

(not directly involved in this)

'ros2 doctor --report' output

N/A

Steps to reproduce issue

This can't really be reproduced locally, but it's been happening regularly in nightly Linux CI jobs:

1. https://ci.ros2.org/job/nightly_linux-rhel_release/2237/
2. https://ci.ros2.org/job/nightly_linux_debug/3391/
3. https://ci.ros2.org/job/nightly_linux-aarch64_release/3069/
4. https://ci.ros2.org/job/nightly_linux_release/3430/
5. https://ci.ros2.org/job/nightly_linux_repeated/3799/

Note that tests are run in parallel here.

Expected behavior

Tests pass or time out after a reasonable amount of time.

Actual behavior

test_ros2trace tests hang and never time out. There is no test result ("The test invocation failed without generating a result file.").

Additional information

CLI test flakiness or hanging is definitely not something we've never seen. However, these specific tests could probably be improved.

It's hard to say where the tests are hanging. However, they do wait for a certain output here:

ros2_tracing/test_ros2trace/test/test_ros2trace/test_trace.py

Lines 198 to 203 in 619b236

	# If needed, wait until tracing has started by waiting until 'ros2 trace' is ready to stop
	if wait_for_start:
	assert process.stdout
	stdout = ''
	while 'press enter to stop...' not in stdout:
	stdout += process.stdout.read(1)

We should look into other, more reliable ways to wait until ros2 trace has started tracing.

Overall, though, we could start by adding a timeout.

[Crola1702]

This issue happened twice in a row in nightly_linux_repeated:

• https://ci.ros2.org/job/nightly_linux_repeated/4012/
• https://ci.ros2.org/job/nightly_linux_repeated/4013/

And twice in a day with: https://ci.ros2.org/job/nightly_linux-rhel_repeated/2448/ (today)

[christophebedard]

The hard part is that we're getting no logs/test output at all, at least not from the job/console output. Are we able to (manually) retrieve the test logs from the job, e.g., log/latest_test/test_ros2trace/**? Maybe the next time we see it hanging?

[Crola1702]

Hi @christophebedard. We just saw another error in https://ci.ros2.org/job/nightly_linux-rhel_repeated/2466/.

This is the log output you requested: test_ros2trace.tar.gz

[christophebedard]

Thank you! Unfortunately, it doesn't show anything :(

�[1m============================= test session starts ==============================�[0m
platform linux -- Python 3.9.21, pytest-6.2.2, py-1.10.0, pluggy-0.13.1
cachedir: /home/jenkins-agent/workspace/nightly_linux-rhel_repeated/ws/build/test_ros2trace/.pytest_cache
rootdir: /home/jenkins-agent/workspace/nightly_linux-rhel_repeated/ws/src/ros2/ros2_tracing, configfile: pytest.ini
plugins: launch-testing-ros-0.29.3, launch-testing-3.9.4, ament-mypy-0.20.2, ament-xmllint-0.20.2, ament-copyright-0.20.2, ament-pep257-0.20.2, ament-flake8-0.20.2, ament-lint-0.20.2, mock-3.6.1, timeout-1.4.2, colcon-core-0.20.1, cov-4.0.0, rerunfailures-9.1.1, repeat-0.9.3
�[1mcollecting ... �[0m�[1m
collecting 0 items                                                             �[0m�[1m
collected 30 items / 15 deselected / 15 selected                               �[0m

However, it's kind of interesting that it's not listing any test. This is the output (== what the log contains) when I run the tests locally (using the same options as the nightly CI job):

$ colcon test --packages-select test_ros2trace --event-handlers console_cohesion+ --retest-until-fail 2 --pytest-args -m "not linter and not xfail"
Starting >>> test_ros2trace
--- output: test_ros2trace                     
============================= test session starts ==============================
platform linux -- Python 3.12.3, pytest-7.4.4, pluggy-1.4.0
cachedir: /home/christophe.bedard/ros2_ws/build/test_ros2trace/.pytest_cache
rootdir: /home/christophe.bedard/ros2_ws/src/ros2/ros2_tracing
configfile: pytest.ini
plugins: launch-testing-ros-0.29.4, launch-testing-3.9.5, ament-mypy-0.20.2, ament-xmllint-0.20.2, ament-copyright-0.20.2, ament-pep257-0.20.2, ament-flake8-0.20.2, ament-lint-0.20.2, repeat-0.9.3, cov-4.1.0, mock-3.12.0, rerunfailures-12.0, colcon-core-0.20.1, timeout-2.2.0
collecting ... 
collecting 0 items                                                             
collected 30 items / 15 deselected / 15 selected                               

test/test_ros2trace/test_trace.py ...............                        [100%]

- generated xml file: /home/christophe.bedard/ros2_ws/build/test_ros2trace/pytest.xml -
====================== 15 passed, 15 deselected in 36.03s ======================
---
Finished <<< test_ros2trace [37.0s]

Summary: 1 package finished [38.5s]

I wonder if it's because no tests run, or if it's because the very first test hung (maybe it prints the test file name after the first test is over?).

I think I should probably look into having each test file spawn its own session daemon (and kill it when it's done), which would completely(ish?) isolate tests from each other from LTTng's point of view. I think we could skip the test/test_ros2trace/test_trace.py tests for now, and re-enable them after I make those changes. What do you think?

[Crola1702]

I think we could skip the test/test_ros2trace/test_trace.py tests for now, and re-enable them after I make those changes. What do you think?

Sounds reasonable to me!