Rosconsole: log files not flushed

[dirk-thomas]

From @nwbirnie on September 28, 2015 15:13

I'm seeing an issue where output to log files appears to be buffered. The process is running in the background (created by roslaunch), and will be generating output. I know there is output because when run in the foreground, the logs get flushed to stdout immediately. However, the text file logs are always about 10/20 lines behind the process.

This makes debugging particularly difficult, since the logs don't necessarily reflect the state of the system, or what has happened in a previous run, since for small logs they sometimes never get written!

Is there anyway to force the log files to be flushed more frequently?

I looked at log4cxx, and there's an option on the appender "immediateFlush" which appears to do what I want. However, I don't know how to configure this for the rosconsole appender since I don't know its name, or indeed if my logs are being created by rosconsole directly or whether they're going to log4cxx first.

Any help would be greatly appreciated.

Copied from original issue: ros/ros_comm#675

[dirk-thomas]

From @chris-smith on January 19, 2016 22:39

I'm also trying to figure this out - I found someone else had asked a question on ros answers about this too. No response though...

[dirk-thomas]

From @rethink-imcmahon on January 19, 2016 22:42

I agree, this is a pretty interesting issue. @dirk-thomas do you know who might have enough ROS logging system knowledge to be able to explain how this flushing works?

[dirk-thomas]

From @MJohnson459 on April 20, 2016 12:54

I was having the same issue as described above. After a little digging it seems that ros logging doesn't use the default log4cxx file appenders but instead just outputs 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

[Hugal31]

Since lunar, setting the environment variable ROSCONSOLE_STDOUT_LINE_BUFFERED to 1 makes the logger flush after each log line.