[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.

[wjwwood]

Unfortunately, this setting is not on by default yet, as it causes all kinds of other issues, but you can enable it yourself and probably fix the problem. If using emulate_tty=True in the Node/ExecuteProcess actions of your Python launch does not fix the problem, then it's probably something else.

[wjwwood]

This is the pr which is stalled at the moment because I don't have time to pursue it which enables emulate_tty by default, which would "convince" subprocesses that they're attached to a terminal and do line buffering without any configuration:

#286

We should address all the issues that cause this, but honestly even if we could enable it by default, I'm worried about the performance in a large system. As was the conclusion in other threads, e.g. ros2/rcutils#169 (comment), we may want to leave this off by default or use some heuristic like: only turning it on if output=screen, or just for stderr, or maybe only if there are a small number of subprocesses or something. And then provide a convenient way to enable/disable it globally or selectively.

[rotu]

@wjwwood, that's the wrong fix. User-readable debug output should go to stderr. If you're worried about performance, that's what log_level is for

[wjwwood]

Which fix? I don't think I said debug output shouldn't go to stderr. Of course you can do things to fix performance on the application side (print less or adjust the log level), but there's no reason for launch to log stdout/stderr to file with line buffering instead of full buffering...

[rotu]

Sorry, nevermind. I thought you were aiming to fix the similar issue ros2/rcutils#168.

[wjwwood]

No, that probably needs to change as you guys have advocated. Just don't have time to push on it atm.

[jdlangs]

Confirmed that enabling emulate_tty myself fixed my issue. I would support changing the default to prefer usability over performance, especially now that it's configurable on the user's end.

[lorepieri8]

Solution given the above discussion:

launch_ros.actions.Node(
            package='demo_nodes_py', 
            node_executable='talker', 
            output='screen',
            emulate_tty=True
    )