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

Why in this simple sample, my logs are not written in logfile ? Or Is there a way to control the flushing period of the log files ?

asked 2015-01-08 02:10:33 -0500

Hello,

The following code is a very simple roscpp node :

#include <ros/ros.h>
#include "std_msgs/String.h"   

int main(int argc, char **argv)
{
    ROS_DEBUG("Hello Listen DEBUG");
    ROS_INFO("Hello Listen INFO");
    ROS_WARN("Hello Listen WARN");
    ros::init(argc, argv, "listener");    
    ros::NodeHandle n;
    ros::Rate r(1.0);
    while(ros::ok())
    {
        r.sleep();
        ROS_INFO("Hello Rate INFO");
    }
    return 0;
}

I launch this node with the following launch file :

<launch>
    <env name="ROSCONSOLE_CONFIG_FILE" value="$(find hello_listen)/launch/rosconsole.config"/>
    <node pkg="hello_listen" type="hello_listen_node" name="listen"/>
</launch>

And with the following rosconsole.config :

log4j.logger.ros=INFO
log4j.logger.ros.roscpp.superdebug=WARN
log4j.logger.ros.hello_listen=DEBUG

If Logs are output to screen

In this use case, there is no problem, I launch my node with the following line :

roslaunch --screen hello_listen listen.launch

And I can see the following output on my screen :

process[listen-2]: started with pid [9741]
[DEBUG] [1420702977.006649815]: Hello Listen DEBUG
[ INFO] [1420702977.006703278]: Hello Listen INFO
[ WARN] [1420702977.006713664]: Hello Listen WARN
[ INFO] [1420702978.010808820]: Hello Rate INFO
[ INFO] [1420702979.010663079]: Hello Rate INFO

If Logs are output to a file :

Now, If I launch my node with :

roslaunch hello_listen listen.launch

I can see that the following files are created in my log directory :

aba@aba-PC:~/.ros/log/4436aba2-970a-11e4-8008-0090f5eb88dd$ ll
total 108
drwxrwxr-x   2 aba aba  4096 janv.  8 08:45 ./
drwxrwxr-x 521 aba aba 65536 janv.  8 08:45 ../
-rw-rw-r--   1 aba aba     0 janv.  8 08:45 listen-2-stdout.log
-rw-rw-r--   1 aba aba  1713 janv.  8 08:45 master.log
-rw-rw-r--   1 aba aba 22965 janv.  8 08:45 roslaunch-aba-PC-9771.log
-rw-rw-r--   1 aba aba   149 janv.  8 08:45 rosout-1-stdout.log
-rw-rw-r--   1 aba aba  2704 janv.  8 08:45 rosout.log

In the rosout.log file, I can see the "Hello Rate INFO" but not the "Hello Listen XXX". This is normal behaviour because, when I display "Hello Listen XXX", node can't publish to /rosout because the nodehandle is not created. This is well documented here with the following sentence :

Everything enabled is sent to the /rosout topic. Note that until the node is fully started, messages will not be sent, so you may not see initial messages.

But in the same documentation webpage there is in section 2 "Output", the following sentence :

Everything enabled goes into the log file.

So, I guess that in my log folder it should be a file corresponding to my node with all the logs (even data logged before the node handle is instanciated). I have a file called listen-2-stdout.log but this file is empty.

Now, If I kill my node, files are flushed, and listen-2-stdout.log contain everything I Need. (even data logged before the node handle is instanciated).

My question is : Is there a way to control the flushing period of the log files ?

Regards,

edit retag flag offensive close merge delete

Comments

I would also like to know if there's any way to flush the stdout file to disk. It's causing me some headaches not being able to see what a node's doing at runtime.

nwb gravatar image nwb  ( 2015-06-17 00:20:59 -0500 )edit

Looks like a perm fix for this is tracked in https://github.com/ros/rosconsole/iss...

130s gravatar image 130s  ( 2020-03-31 21:16:31 -0500 )edit

1 Answer

Sort by ยป oldest newest most voted
2

answered 2016-04-20 08:01:04 -0500

Michael Johnson gravatar image

I was having a similar issue to what you described above. This is quite an old question but as it's still the top search result it seems worth answering anyway.

I did a little digging into the rosconsole logging and it seems that it doesn't actually use the default log4cxx file appenders but instead just outputs the logging to stdout where it is piped to a file.

This means normal methods to control stdout work with ROS_INFO etc. On linux an easy way to enable line buffering is to use the command stdbuf before calling roslaunch

stdbuf -o L roslaunch <launchfile>

In code you can also use methods to flush streams/files or set stdout to line buffered

// C++
setvbuf(stdout, NULL, _IOLBF, 4096);        //  Set line buffering
...
fflush(stdout);                             // Flush stdout

.

# Python
sys.stdout = os.fdopen(sys.stdout.fileno(), 'w', 1)  # Set line buffering
...
sys.stdout.flush()                                   # Flush stdout

Hope that helps someone in the future.

edit flag offensive delete link more

Question Tools

1 follower

Stats

Asked: 2015-01-08 02:10:33 -0500

Seen: 8,339 times

Last updated: Jan 08 '15