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

No stdout logging output in ROS2 using launch

asked 2019-09-11 13:48:53 -0500

jdlangs gravatar image

Hi all,

I am unable to see any logging output from stdout when using ros2 launch, and I need some help figuring out what's going on / if this is expected. For example this cpp file:

int main(int argc, char** argv)
{
  rclcpp::init(argc, argv);
  auto node = std::make_shared<rclcpp::Node>("a_test_node");

  RCLCPP_DEBUG(node->get_logger(), "test log debug");
  RCLCPP_INFO(node->get_logger(), "test log info");
  RCLCPP_WARN(node->get_logger(), "test log warn");
  RCLCPP_ERROR(node->get_logger(), "test log error");

  rclcpp::spin(node);

  return 0;
}

and this launch file:

import launch
import launch_ros.actions

def generate_launch_description():
    return launch.LaunchDescription([
        launch_ros.actions.Node(
            package='test_pkg',
            node_executable='test_node',
            node_name='test_node',
            output={
                'stdout': 'screen',
                'stderr': 'screen',
            }
        ),
    ])

only outputs:

jlangsfeld@swri-jlangsfeld-thinkpad-T560:~/Workspaces/ros2$ ros2 launch test_pkg log_test.launch.py
[INFO] [launch]: All log files can be found below /home/jlangsfeld/.ros/log/2019-09-11-13-45-19-657412-swri-jlangsfeld-thinkpad-T560-18153
[INFO] [launch]: Default logging verbosity is set to INFO
[INFO] [test_node-1]: process started with pid [18163]
[test_node-1] [WARN] [test_node]: test log warn
[test_node-1] [ERROR] [test_node]: test log error

I've tried other output options too with no luck. For example, using own_log for both stdout and stderr means separate log files are created but the stdout one always is completely empty. Any thoughts / suggestions?

Thanks, Josh

edit retag flag offensive close merge delete

Comments

can you try output="screen" without the json? That's what I usually do

ex. https://github.com/ros-planning/navig...

I see the warn and error, but not info, perhaps because you didnt set to screen in general

stevemacenski gravatar image stevemacenski  ( 2019-09-11 15:04:50 -0500 )edit

Yes, I've tried the single string, which should just be a shortcut for setting both stdout and stderr directly. Are you saying you don't see info outputs either when you run launch files?

jdlangs gravatar image jdlangs  ( 2019-09-11 15:20:48 -0500 )edit

No, I do see them with just the simple string

stevemacenski gravatar image stevemacenski  ( 2019-09-11 15:28:04 -0500 )edit

in foxy, log can output to ~/.ros/log.

but i found there is a delay time to log file than screen, i found log file will increase 4096kb every time, so is it flush when buffer is fulled ?

how to set immedialy output every line ?

942951641@qq.com gravatar image 942951641@qq.com  ( 2021-06-22 07:36:25 -0500 )edit

3 Answers

Sort by ยป oldest newest most voted
12

answered 2019-09-16 11:36:05 -0500

jdlangs gravatar image

This turned out to be connected with the known issue of subprocesses from launch having their stdout streams buffered (https://github.com/ros2/launch/issues...). There is a emulate_tty flag that has recently been added to the ExecuteProcess action that defaults to False. Setting it to True in my launch file (through the Node action constructor) fixes the problem. Eventually it may default to True. (https://github.com/ros2/launch/pull/286)

edit flag offensive delete link more

Comments

2

Could you share your snippet reaches emulate_tty, please?

khassanov gravatar image khassanov  ( 2019-10-10 08:45:51 -0500 )edit

I added the emulate_tty=True flag here and the outputs worked for me again.

Node(
    package='package_name',
    node_executable='package_exec',
    output='screen',
    emulate_tty=True,
    arguments=[('__log_level:=debug')]
)
mvoellmy gravatar image mvoellmy  ( 2019-12-13 06:54:58 -0500 )edit

Does this work with Dashing or only newer versions?
I'm getting: [ERROR] [launch]: Caught exception in launch (see debug for traceback): __init__() got an unexpected keyword argument 'emulate_tty'

MrCheesecake gravatar image MrCheesecake  ( 2020-07-15 07:54:15 -0500 )edit
2

The keyword was added during Eloquent development. But as of Foxy, this problem should be gone because all logging now comes out on stderr which won't buffer output.

jdlangs gravatar image jdlangs  ( 2020-07-16 12:37:56 -0500 )edit

i have same problem in dashing version.[ERROR] [launch]: Caught exception in launch (see debug for traceback): __init__() got an unexpected keyword argument 'emulate_tty'. how can you solve it?

mantangL gravatar image mantangL  ( 2020-10-21 23:03:02 -0500 )edit
3

answered 2019-11-06 11:29:13 -0500

mschickler gravatar image

updated 2019-11-06 11:33:17 -0500

gvdhoorn gravatar image

You can use the following to set the buffering policy to line buffering:

stdbuf -o L ros2 launch pkg pkg.launch.py

I would personally prefer this over setting an option in the launch file since it gives you some flexibility without having to modify the launch file.

edit flag offensive delete link more

Comments

This worked for me. I would prefer that the default is set to line buffering since I think that is what the majority of users expect when printing output to screen. If not, how can I set the default to be line buffered?

Aravind gravatar image Aravind  ( 2020-08-10 18:22:24 -0500 )edit
1

I had same problem in dashing version. I added the prefix=['stdbuf -o L'] to Node. This worked for me.

Node(
    package='package_name',
    node_executable='package_exec',
    prefix=['stdbuf -o L'],
    output='screen'
)
ntrlmt gravatar image ntrlmt  ( 2021-02-01 10:54:20 -0500 )edit

@ntrimt it looks that it doesn't work in Dashing in Windows 10. I'm getting a traceback.

andrestoga gravatar image andrestoga  ( 2021-02-19 12:30:11 -0500 )edit

@ntrlmt answer worked for me ROS2 foxy, thanks

askkvn gravatar image askkvn  ( 2021-12-12 17:06:18 -0500 )edit
1

answered 2019-09-13 16:22:08 -0500

jacobperron gravatar image

With your example, I do see the INFO output, but it comes after terminating the program (e.g SIGINT):

[INFO] [launch]: Default logging verbosity is set to INFO
[INFO] [test_node-1]: process started with pid [18943]
[test_node-1] [WARN] [test_node]: test log warn
[test_node-1] [ERROR] [test_node]: test log error
^C[WARNING] [launch]: user interrupted with ctrl-c (SIGINT)
[test_node-1] [INFO] [test_node]: test log info

It's possible there's some buffer funny-business happening in launch. It might be worth opening a issue describing the problem.

I wouldn't expect you to be able to see the DEBUG log, without setting the verbosity level accordingly.

edit flag offensive delete link more

Comments

I never noticed but the same thing is happening for me too. I'll go ahead and open an issue then.

jdlangs gravatar image jdlangs  ( 2019-09-13 16:53:30 -0500 )edit

Question Tools

2 followers

Stats

Asked: 2019-09-11 13:48:53 -0500

Seen: 14,070 times

Last updated: Jun 22 '21