Can't write launch tests with composable nodes

[jacobperron]

Bug report

Required Info:

• Operating System:
  • Ubuntu 18.04
• Installation type:
  • Eloquent binaries or from source
• Version or commit hash:
  • c37340d
• DDS implementation:
  • N/A
• Client library (if applicable):
  • N/A

Steps to reproduce issue

Example launch test file:

import sys 
import unittest

from launch import LaunchDescription
from launch.actions import OpaqueFunction

from launch_ros.actions import ComposableNodeContainer
from launch_ros.descriptions import ComposableNode

import pytest


@pytest.mark.rostest
def generate_test_description(ready_fn):

    return LaunchDescription([
        ComposableNodeContainer(
            package='rclcpp_components',
            node_executable='component_container',
            node_name='my_node_container',
            node_namespace='',
            composable_node_descriptions=[
                ComposableNode(
                    package='composition',
                    node_plugin='composition::Talker'
                )
            ],
            output='screen'
        ),
        OpaqueFunction(function=lambda context: ready_fn()),
    ])  


class TestMyNode(unittest.TestCase):

    def test_something(self):
        print('We do not see this message', file=sys.stderr)

Expected behavior

The tests runs and passes without errors.

Actual behavior

Different runtime errors depending how you run the test.

launch_test

[INFO] [launch]: All log files can be found below /home/jacob/.ros/log/2019-12-16-17-23-38-303988-warner-30644
[INFO] [launch]: Default logging verbosity is set to INFO
test_something (example_launch_test.TestMyNode) ... We do not see this message
ok

Ran 1 test in 0.000s
OK

[INFO] [component_container-1]: process started with pid [30649]

[ERROR] [launch]: Caught exception in launch (see debug for traceback): context.locals does not contain attribute 'launch_ros_node', it contains: [event]

[INFO] [component_container-1]: sending signal 'SIGINT' to process[component_container-1]

[ERROR] [component_container-1]: process has died [pid 30649, exit code -2, cmd '/opt/ros/eloquent/lib/rclcpp_components/component_container --ros-args -r __node:=my_node_container'].

Ran 0 tests in 0.000s
OK

ros2 test

[INFO] [launch]: All log files can be found below /home/jacob/.ros/log/2019-12-16-17-21-29-265673-warner-30543
[INFO] [launch]: Default logging verbosity is set to INFO
test_something (example_launch_test.TestMyNode) ... We do not see this message
ok

Ran 1 test in 0.000s
OK

Task exception was never retrieved

future: <Task finished coro=<LaunchService._process_one_event() done, defined at /opt/ros/eloquent/lib/python3.6/site-packages/launch/launch_service.py:289> exception=RuntimeError('Signal event received before subprocess transport available.',)>

Traceback (most recent call last):

File "/opt/ros/eloquent/lib/python3.6/site-packages/launch/launch_service.py", line 291, in _process_one_event

await self.__process_event(next_event)

File "/opt/ros/eloquent/lib/python3.6/site-packages/launch/launch_service.py", line 311, in __process_event

visit_all_entities_and_collect_futures(entity, self.__context))

File "/opt/ros/eloquent/lib/python3.6/site-packages/launch/utilities/visit_all_entities_and_collect_futures_impl.py", line 38, in visit_all_entities_and_collect_futures

sub_entities = entity.visit(context)

File "/opt/ros/eloquent/lib/python3.6/site-packages/launch/action.py", line 108, in visit

return self.execute(context)

File "/opt/ros/eloquent/lib/python3.6/site-packages/launch/actions/opaque_function.py", line 75, in execute

return self.__function(context, *self.__args, **self.__kwargs)

File "/opt/ros/eloquent/lib/python3.6/site-packages/launch/actions/execute_process.py", line 383, in __on_signal_process_event

raise RuntimeError('Signal event received before subprocess transport available.')

RuntimeError: Signal event received before subprocess transport available.

[INFO] [component_container-1]: process started with pid [30555]

Task exception was never retrieved

future: <Task finished coro=<LaunchService._process_one_event() done, defined at /opt/ros/eloquent/lib/python3.6/site-packages/launch/launch_service.py:289> exception=InvalidHandle('Tried to use a handle that has been destroyed.',)>

Traceback (most recent call last):

File "/opt/ros/eloquent/lib/python3.6/site-packages/launch/launch_service.py", line 291, in _process_one_event

await self.__process_event(next_event)

File "/opt/ros/eloquent/lib/python3.6/site-packages/launch/launch_service.py", line 311, in __process_event

visit_all_entities_and_collect_futures(entity, self.__context))

File "/opt/ros/eloquent/lib/python3.6/site-packages/launch/utilities/visit_all_entities_and_collect_futures_impl.py", line 38, in visit_all_entities_and_collect_futures

sub_entities = entity.visit(context)

File "/opt/ros/eloquent/lib/python3.6/site-packages/launch/action.py", line 108, in visit

return self.execute(context)

File "/opt/ros/eloquent/lib/python3.6/site-packages/launch_ros/actions/load_composable_nodes.py", line 167, in execute

self.__target_container.node_name

File "/opt/ros/eloquent/lib/python3.6/site-packages/rclpy/node.py", line 1201, in create_client

with self.handle as node_capsule:

File "/opt/ros/eloquent/lib/python3.6/site-packages/rclpy/handle.py", line 150, in enter

return self._get_capsule()

File "/opt/ros/eloquent/lib/python3.6/site-packages/rclpy/handle.py", line 132, in _get_capsule

raise InvalidHandle('Tried to use a handle that has been destroyed.')

rclpy.handle.InvalidHandle: Tried to use a handle that has been destroyed.

[ERROR] [component_container-1]: process[component_container-1] failed to terminate '5' seconds after receiving 'SIGINT', escalating to 'SIGTERM'

[INFO] [component_container-1]: sending signal 'SIGTERM' to process[component_container-1]

[ERROR] [component_container-1]: process has died [pid 30555, exit code -15, cmd '/opt/ros/eloquent/lib/rclcpp_components/component_container --ros-args -r __node:=my_node_container'].

Ran 0 tests in 0.000s
OK

Additional information

The first error (running with launch_test) is because launch_ros_node is not added to the launch context, which LoadComposableNode action assumes exists:

launch_ros/launch_ros/launch_ros/actions/load_composable_nodes.py

Lines 186 to 190 in c37340d

	self.__rclpy_load_node_client = context.locals.launch_ros_node.create_client(
	composition_interfaces.srv.LoadNode, '{}/_container/load_node'.format(
	self.__final_target_container_name
	)
	)

This is closely related to #97.

I'm not sure about the second error.

[hidmic]

The first error is expected, launch_test is ROS agnostic and will not automatically prepend the default launch description that's required for many launch_ros actions to work. One may argue that actions should be somewhat more verbose about their preconditions not being met instead of crashing.

The second error, which doesn't actually result in a test failure, is a combination of things. The test does run but it finishes so quickly that even though the container action is executed it doesn't have enough time to wrap up initialization and a signal gets sent "...before subprocess transport available". The second exception is somewhat peculiar, and I'd be inclined to think it's the result of not handling the first exception correctly.