[launch] not wiring python prints to stdout in realtime

[stonier]

Bug report

Required Info:

• Operating System:
  • Ubuntu 18.04
• Installation type:
  • binaries
• Version or commit hash:
  • Crystal
• DDS implementation:
  • Default
• Client library (if applicable):
  • rclpy

Steps to reproduce issue

• Put a cout equivalent of the logged message in demo_nodes_cpp/src/topics/talker.cpp
• Put a print equivalent of the logged message in demo_nodes_py/demo_nodes_py/talker.py

Add them both to a launcher:

#!/usr/bin/env python3
# -*- coding: utf-8 -*-

import launch
import launch_ros.actions

def generate_launch_description():
    launch_description = launch.LaunchDescription()
    launch_description.add_action(
        launch_ros.actions.Node(
            package='demo_nodes_cpp', node_executable='talker', output='screen'),
    )
    launch_description.add_action(
        launch_ros.actions.Node(
            package='demo_nodes_py', node_executable='talker', output='screen'),
    )
    return launch_description

and call ros2 launch ... on it.

Expected behavior

Both logged messages and cout/print messages make it in realtime to stdout.

Actual behavior

All make it there except the python print statements. They only show on stdout after interrupting the launch with CTRL-C.

[wjwwood]

I think the difference is that we intentionally flush the out when logging:

https://github.com/ros2/rcutils/blob/a7581a333444c2804f2b7c27dd0da1b2946bebff/src/logging.c#L702

There is inherent buffing of stdout when a process is not connected to a tty.

If you changed this:

import launch
import launch_ros.actions

def generate_launch_description():
    launch_description = launch.LaunchDescription()
    launch_description.add_action(
        launch_ros.actions.Node(
            package='demo_nodes_cpp', node_executable='talker', output='screen'),
    )
    launch_description.add_action(
        launch_ros.actions.Node(
            package='demo_nodes_py', node_executable='talker', output='screen',
            env={PYTHONUNBUFFERED : "1"}),
    )
    return launch_description

I expect that you'll see prompt printing.

---

It's possible that the emulate_tty option in osrf_pycommon's API could address this, but I didn't enable it by default. You could do it here:

launch/launch/launch/actions/execute_process.py

Line 439 in e870424

emulate_tty=False,

[stonier]

emulate_tty=True works if a bugfix goes into this code:

osrf_pycommon/process_utils/async_execute_process_asyncio/impl.py#L67-L68

so that keyword arguments are utilised (otherwise you'll get positional argument errors):

    return protocol_class(stdin=None, stdout=stdout_master, stderr=stderr_master)

Are there consequences of emulate_tty you are wary of or would you like me to send a couple of PR's your way for this?

[wjwwood]

emulate_tty does cause extra overhead, in that it needs to create a pty pair for stdout and stderr of each subprocess. So in situations like with catkin_tools you could run out of pty's on your system. This is usually configurable in kernel settings or similar, and I believe osrf_pycommon will gracefully degrade to not using emulate_tty when no more pty are available. There's also the possibility of pty's getting left over, if launch or Python were to segfault for instance. This can be annoying to notice and fix (usually just restart), but unless you're developing launch and causing new bugs, ideally that wouldn't be an issue.

That all being said, I think it's worth turning on by default and exposing a emulate_tty option in the ExecuteProcess action so people can turn it off if they want. It would also be good to have ExecuteProcess read a launch configuration, e.g. like emulate_tty_by_default, which if you set to false would globally avoid emulate_tty unless explicitly enabled. You can see an example of this here:

launch/launch/launch/actions/execute_process.py

Lines 162 to 164 in e870424

	:param: prefix a set of commands/arguments to preceed the cmd, used for
	things like gdb/valgrind and defaults to the LaunchConfiguration
	called 'launch-prefix'

In that case you can either specify a prefix manually for a single invocation of ExecuteProcess or set the prefix for an entire launch description (or part of one) using the launch-prefix Launch Configuration.

[mjcarroll]

@stonier What's the status of this? Did #52 provide any steps towards resolving this?

[stonier]

@mjcarroll you're pointing to a very old PR (2017). Was that intended?

I've got the bugfix PR in that enables the solution proposed by @wjwwood to be attempted but haven't had the cycles to contribute that PR yet.

[jdlangs]

I'm not totally sure but is this the same issue that's causing us to not see any stdout output at all while the node is running? (https://answers.ros.org/question/332829/no-stdout-logging-output-in-ros2-using-launch/) If so this seems like a serious problem that needs to be escalated.