ros2 / ros2/launch

launch_testing `@post_shutdown_test()` checking output and return codes is flaky

Open
#534 8 comments 0 reactions 1 assignee View on GitHub

@hidmic is already working on this.

Since Oct 18, 2021.

Dominant language
Python
Stars
155
Forks
182
Avg merge
2d 14h
Merged PRs (30d)
6

Description

Bug report

Required Info:

  • Operating System:
    • Ubuntu Focal
  • Installation type:
    • Source
  • Version or commit hash:
    • 026ab0e6c5a84c5d6fed2b643a83999b6e873dea
  • DDS implementation:
    • Default
  • Client library (if applicable):
    • N/A
Steps to reproduce issue

Save the following as mre.py

import unittest

from launch import LaunchDescription
from launch.actions import ExecuteProcess
from launch_testing.actions import ReadyToTest
from launch_testing import post_shutdown_test
from launch_testing.asserts import assertExitCodes
from launch_testing.asserts import assertInStdout
import pytest


@pytest.mark.rostest
def generate_test_description():
    put = ExecuteProcess(cmd=('echo', 'foobar'))
    return LaunchDescription([put, ReadyToTest()]), {'put': put}


@post_shutdown_test()
class TestAfterShutdown(unittest.TestCase):

    def test_error_message(self, proc_output, put):
        assertInStdout(proc_output, 'foobar', put)

    def test_exit(self, proc_info):
        assertExitCodes(proc_info, allowable_exit_codes=[0])

Use launch_test command to run it

$ launch_test mre.py
Expected behavior

The test would always succeeds

Actual behavior

The test fails most, but not all of the time (fails about 90% of the time on my machine)

Additional information

When it succeeds the output is:

$ launch_test mre.py 
[INFO] [launch]: All log files can be found below /home/osrf/.ros/log/2021-09-23-16-34-26-384599-shane-1662924
[INFO] [launch]: Default logging verbosity is set to INFO

----------------------------------------------------------------------
Ran 0 tests in 0.000s

OK
[INFO] [echo-1]: process started with pid [1662927]
[INFO] [echo-1]: sending signal 'SIGINT' to process[echo-1]
[INFO] [echo-1]: process has finished cleanly [pid 1662927]
test_error_message (mre.TestAfterShutdown) ... ok
test_exit (mre.TestAfterShutdown) ... ok

----------------------------------------------------------------------
Ran 2 tests in 0.000s

OK

When it fails the output is:

$ launch_test mre.py 
[INFO] [launch]: All log files can be found below /home/osrf/.ros/log/2021-09-23-16-34-25-739192-shane-1662919
[INFO] [launch]: Default logging verbosity is set to INFO

----------------------------------------------------------------------
Ran 0 tests in 0.000s

OK
[INFO] [echo-1]: process started with pid [1662922]
[INFO] [echo-1]: sending signal 'SIGINT' to process[echo-1]
[ERROR] [echo-1]: process has died [pid 1662922, exit code -2, cmd 'echo foobar'].
test_error_message (mre.TestAfterShutdown) ... ERROR
test_exit (mre.TestAfterShutdown) ... FAIL

======================================================================
ERROR: test_error_message (mre.TestAfterShutdown)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/osrf/ws/third_party/src/mre.py", line 22, in test_error_message
    assertInStdout(proc_output, 'foobar', put)
  File "/home/osrf/ws/ros2/install/launch_testing/lib/python3.8/site-packages/launch_testing/asserts/assert_output.py", line 121, in assertInStdout
    assertInStream(proc_output, expected_output, process, cmd_args, output_filter=output_filter,
  File "/home/osrf/ws/ros2/install/launch_testing/lib/python3.8/site-packages/launch_testing/asserts/assert_output.py", line 72, in assertInStream
    resolved_procs = resolveProcesses(
  File "/home/osrf/ws/ros2/install/launch_testing/lib/python3.8/site-packages/launch_testing/util/proc_lookup.py", line 112, in resolveProcesses
    raise NoMatchingProcessException(
launch_testing.util.proc_lookup.NoMatchingProcessException: No data recorded for proc echo-1 foobar

======================================================================
FAIL: test_exit (mre.TestAfterShutdown)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/osrf/ws/third_party/src/mre.py", line 25, in test_exit
    assertExitCodes(proc_info, allowable_exit_codes=[0])
  File "/home/osrf/ws/ros2/install/launch_testing/lib/python3.8/site-packages/launch_testing/asserts/assert_exit_codes.py", line 62, in assertExitCodes
    assert info.returncode in allowable_exit_codes, 'Proc {} exited with code {}'.format(
AssertionError: Proc echo-1 exited with code -2

----------------------------------------------------------------------
Ran 2 tests in 0.000s

FAILED (failures=1, errors=1)

Is the @post_shutdown_test() letting the test run before the process shuts down?

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.