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

[sloretz]

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?