ROS Resources: Documentation | Support | Discussion Forum | Index | Service Status | ros @ Robotics Stack Exchange
Ask Your Question
0

[ROS2] [launch_pytest] node outputting to stderr instead of stdout

asked 2022-06-15 02:34:57 -0500

LoicF gravatar image

As asked by @clalancette, I am reposting launch issue #619 here.

  • Operating System:
    • Ubuntu 20.04.4
  • ROS2 Distro:
    • foxy
  • Version or commit hash:
    • launch: 1.1.0
    • (launch_ros: 0.20.0)
    • (pytest: 7.1.2)
  • DDS implementation:
    • rmw_cyclonedds_cpp
  • Client library (if applicable):
    • rclpy

Steps to reproduce issue

copy-paste the following in test_confusing.py, then run pytest test_confusing.py

import launch
import launch_pytest
import launch_ros
import pytest

@pytest.fixture
def foo_node_process() -> launch.actions.ExecuteProcess:
  return launch_ros.actions.Node(
      package='examples_rclpy_minimal_client', executable='client', name='client', output='screen', cached_output=True
  )

@launch_pytest.fixture
def foo_launch_description(foo_node_process) -> launch.LaunchDescription:
  return launch.LaunchDescription([foo_node_process])

@pytest.mark.launch(fixture=foo_launch_description)
def test_read_foo_stdout(foo_node_process, launch_context):
  assert launch_pytest.tools.wait_for_start_sync(launch_context, foo_node_process, timeout=5)

  def validate_output(output: str):
    assert len(output) > 0, 'Output is empty'

  # passes
  launch_pytest.tools.assert_stderr_sync(launch_context, foo_node_process, validate_output, timeout=5)
  # fails
  launch_pytest.tools.assert_output_sync(launch_context, foo_node_process, validate_output, timeout=5)

Expected behavior

The output of the launched node (logging info messages "service not available, waiting again...") should be in stdout.

Actual behavior

The output is in stderr, causing a confusing fail of the test.

Additional information

I am a bit confused by the output='screen' argument and the fact that the pytest_hello_world.py is using assert_output_sync. However, it is maybe intended behavior, as running ros2 run examples_rclpy_minimal_client client also outputs to stderr. Is it normal? Could you help me understand?

Thanks!

edit retag flag offensive close merge delete

1 Answer

Sort by ยป oldest newest most voted
1

answered 2022-06-15 07:30:23 -0500

clalancette gravatar image

In short, it is by design that all output from RCLCPP_{DEBUG,INFO,WARN,ERROR,FATAL} macros (and their equivalent logger.{debug,info,warn,error,fatal} in rclpy) goes to stderr.

Back in Dashing and Eloquent, we used to output DEBUG and INFO messages to stdout, and all of the other ones to stderr. However, this caused confusion and made it hard to handle log messages at every level since you would have to capture both stdout and stderr.

Between Eloquent and Foxy, I did some pretty exhaustive research into the logging systems in languages like Python, Ruby, Rust, etc. (see https://github.com/ros2/rcutils/pull/...). What I found out was that all logging systems pick a single stream and log to that. Most of them log to stdout by default, but some log to stderr by default. We decided to log everything to stderr, to keep stdout available for use by the application.

I'll point out that this is configurable; if you set the environment variable RCUTILS_LOGGING_USE_STDOUT to 1, it will use stdout by default.

edit flag offensive delete link more

Question Tools

Stats

Asked: 2022-06-15 02:32:35 -0500

Seen: 546 times

Last updated: Jun 15 '22