Force a write of all user-space buffered data for stdout in Formatter::print #1012

lamerman · 2017-03-03T06:48:46Z

On Android under certain conditions, when user runs binary applications using
ros_comm from within APK, he/she cannot see stdout messages if they are few
lines.

The proposal is to forcibly flush stdout with fflush in this case, as \n in the
end implicitly flushes it on most platforms.

I personally faced this problem on Android when running binaries from within APK. It was impossible to see logs and trace your programs if the logs were a few lines. Though stderr was visible, stdout was not visible. Once I applied this patch it became visible.

If you know how to do it better, please tell me, I'm ready to redo something if it's wrong.

dirk-thomas · 2017-03-03T15:34:30Z

Forcing a flush after every line of output results in a significant performance overhead when printing more information to the console. Therefore I don't think this can be merged as a default behavior. I could imagine an environment variable (like in Python using the env var PYTHONUNBUFFERED) to toggle the behavior.

lamerman · 2017-03-03T22:14:20Z

So I read a little bit more about the problem. Just to be more exact, I observe this behaviour because the program has stdout as PIPE not TTY. On the same machine (android) when I run the same program from terminal, it works well.

But in my usecase I cannot do it from terminal as I do not have one inside of Android application. Currently I print the output of my ros application to the log of Android, then I wanted to show it in the user GUI. So as I understand there is not possibility to setup TTY in my case.

As it's written in the scripture:

stdin	input	line-buffered
stdout (TTY)	output	line-buffered
stdout (not a TTY)	output	fully-buffered
stderr	output	unbuffered

Stdout without tty is fully-buffered, this is why I cannot see the output until it reaches certain threshold.

For the similar case grep has --line-buffered option which is implemented under the hood like this:

prline (char *beg, char *lim, char sep)
{
....
if (!only_matching && lim > beg)
    fwrite_errno (beg, 1, lim - beg);

  if (line_buffered)
    fflush_errno ();

  if (stdout_errno)
    die (EXIT_TROUBLE, stdout_errno, _("write error"));
...
}

So if line_buffered is set then it flushes. And implementation of the fflush_errno

static void
fflush_errno (void)
{
  if (fflush (stdout) != 0)
    stdout_errno = errno;
}

So it seems like in some cases people actually need line-buffered output for pipes, like the example of grep shows. So maybe as you proposed we should do environment variable which makes logs written to stdout flush on every line. I will do it then.

lamerman · 2017-03-09T21:58:49Z

@dirk-thomas I created an environment variable in the updated pull request. I have not yet finished it completely, there is something to do still, but just to get the general idea I think it's ok. Could you have a look that in principle it's ok or not and what would you change?

What is not finished yet is correct parsing of "true" with lexical cast.

dirk-thomas · 2017-03-10T16:39:03Z

Instead of explicitly flushing each line which will only affect the ROS logging messages I would consider changing the buffering of stdout globally which would affect any output. E.g. like this:

#include <cstdio>
setvbuf(stdout, NULL, _IONBF, BUFSIZ);

Based on that the environment variable could be named ROS_UNBUFFERED_STDOUT. I would also not bother with the lexical cast and simply enable this option when the environment variable is not empty and not 0.

Since the suggested behavior is not specific to rosconsole anymore it could be placed in the ros::init function instead.

lamerman · 2017-03-11T15:42:55Z

Ok, I agree, I also thought about it at some point. In this case user will be able to force line buffering for any app built on top of ROS, even if it does not log everything with logger. About drawbacks, probably there are no drawbacks. We override stdout policy globally for both ROS and some application that uses it, but we do so only when user explicitly ask us, then probably it's ok.
About lexical cast, I would prefer to do it strictly. I think there is no reason for user or script to put garbage to the value, except for his own error which he would like to detect as fast as possible. I would frankly just stop if the value is wrong. But I'll look how it's implemented in other parts of the library and do the same for similar behaviour across all ROS.

lamerman · 2017-03-11T15:59:56Z

@dirk-thomas why did you write _IONBF? It stands for completely unbuffered stream. Should we make linebuffering instead _IOLBF?
In python they made also completely unbuffered, while for grep it's only forcing linebuffering. Maybe there is some discussion in python why they did so,

dirk-thomas · 2017-03-11T16:27:42Z

The snippet was just an example. Line buffered sounds indeed better.

lamerman · 2017-03-12T09:57:00Z

@dirk-thomas , implementation is clear except for one thing, which I am concerned now about.

The documentation of setvbuf states http://man7.org/linux/man-pages/man3/setvbuf.3p.html that

The setvbuf() function may be used after the stream pointed to by
stream is associated with an open file but before any other operation
(other than an unsuccessful call to setvbuf()) is performed on the
stream.

So as I understand it means that no write to stdout should happen before setvbuf. While ros documentation is not so strict here:

Before calling any other roscpp functions in a node you must call one of the ros::init() functions

So it does not state that ros::init() should be the very first function in main and before it the user can easily put

std::out << "Starting ROS initialization" << std::endl

In my view in could cause side effects in such situations. What do you think?

dirk-thomas · 2017-03-12T15:52:59Z

I agree that this is a possibility. Trying to influence the buffering of a compiler executable is not as easy as for Python. I don't see a better approach though. You might want to try what happens in that case.

lamerman · 2017-03-12T17:06:55Z

@dirk-thomas I think it's implementation specific and undefined behaviour.
I looked at the code of grep, sed, tail all of them use fflush. From standard text processing utilities I found AWK using setvbuf, but it's an app, not a library as ROS and they fully control what happens and can just, as they do, do it in the very beginning.
Are you completely against fflush? Yes we do not cure all the possible problems, but we fix ROS logging system in those cases. It will work for everything that uses standard ROS logger. It works out of box for stderr and will not work just for the output to stdout which does not go to the logger. And this solution does not break any contract (as in case of setvbuf).

dirk-thomas · 2017-03-13T21:17:44Z

tools/rosconsole/src/rosconsole/rosconsole.cpp

@@ -425,6 +435,25 @@ void initialize()
    backend::function_notifyLoggerLevelsChanged = notifyLoggerLevelsChanged;
    backend::function_print = _print;

+    char* line_buffered = NULL;
+#ifdef _MSC_VER
+    _dupenv_s(&line_buffered, NULL, "ROSCONSOLE_STDOUT_LINE_BUFFERED");


In the Windows case you must free the allocated memory (line_buffered) afterwards.

Actually please use get_environment_variable() which encapsulates the logic already: https://github.com/ros/roscpp_core/blob/5820d0672cb9d5fcd1c8cb4a159d04ff20115ff3/cpp_common/include/ros/platform.h#L63

dirk-thomas · 2017-03-13T21:18:33Z

tools/rosconsole/src/rosconsole/rosconsole.cpp

+  if (g_force_stdout_line_buffered && f == stdout) {
+    int flushResult = fflush(f);
+    if (flushResult != 0) {
+      fprintf(stderr, "Failed to perform fflush on stdout, return code is %d\n", flushResult);


If the flushing fails I don't think the repeated error message for every case is helpful. I would suggest to only print the error message for the first occurrence.

dirk-thomas · 2017-03-13T21:19:15Z

tools/rosconsole/src/rosconsole/rosconsole.cpp

@@ -393,6 +396,13 @@ void Formatter::print(void* logger_handle, ::ros::console::Level level, const ch
  ss << COLOR_NORMAL;

  fprintf(f, "%s\n", ss.str().c_str());
+
+  if (g_force_stdout_line_buffered && f == stdout) {
+    int flushResult = fflush(f);


Please follow the style for variable names which is lowercase-underscore.

dirk-thomas · 2017-03-13T21:27:47Z

tools/rosconsole/src/rosconsole/rosconsole.cpp

+    {
+      try
+      {
+        g_force_stdout_line_buffered = boost::lexical_cast<bool>(std::string(line_buffered));


Regarding the lexical cast. Similar existing checks don't bother with it and just check for a fixed value, e.g.:

ros_comm/clients/roscpp/src/libros/init.cpp

Lines 319 to 326 in 148178b

char* env_ipv6 = NULL;

#ifdef _MSC_VER

_dupenv_s(&env_ipv6, NULL, "ROS_IPV6");

#else

env_ipv6 = getenv("ROS_IPV6");

#endif

bool use_ipv6 = (env_ipv6 && strcmp(env_ipv6,"on") == 0);

ros_comm/tools/rosgraph/src/rosgraph/network.py

Line 244 in 148178b

return ROS_IPV6 in os.environ and os.environ[ROS_IPV6] == 'on'

ros_comm/tools/roslaunch/src/roslaunch/remoteprocess.py

Lines 106 to 107 in 148178b

override = os.environ.get('ROSLAUNCH_SSH_UNKNOWN', 0)

if override == '1':

And in case the value doesn't match the expectation they silently apply the default.

I removed lexical cast. In case the value does not equal 1, the default value 0 will be used. If the value provided is neither 0 nor 1, a warning is issued to notify user that something is wrong and he/she needs to check correctness of parameters.

dirk-thomas · 2017-03-14T22:09:05Z

tools/rosconsole/src/rosconsole/rosconsole.cpp

+      } else {
+        if (line_buffered != "0") {
+          fprintf(stderr, "Warning: unexpected value %s specified for ROSCONSOLE_STDOUT_LINE_BUFFERED. Default value 0 "
+          "will be used. Valid values are 1 or 0.\n", line_buffered.c_str());


Please indent this wrapped line with two extra space.

lamerman · 2017-03-14T22:14:07Z

I tested it locally,

buildfarm@008e46f9c83d:/tmp$ export ROSCONSOLE_STDOUT_LINE_BUFFERED=0
buildfarm@008e46f9c83d:/tmp$ rosbag record --all | grep INFO
^C
buildfarm@008e46f9c83d:/tmp$ export ROSCONSOLE_STDOUT_LINE_BUFFERED=1
buildfarm@008e46f9c83d:/tmp$ rosbag record --all | grep INFO
[ INFO] [1489529031.250242364]: Subscribing to /rosout
[ INFO] [1489529031.250477902]: Recording to 2017-03-14-23-03-51.bag.
[ INFO] [1489529031.259484219]: Subscribing to /rosout_agg

So it works for pipe if the flushing is enabled.

dirk-thomas · 2017-03-14T22:15:56Z

I tested it locally,

👍 Nice, thank you for your effort!

lamerman · 2017-03-14T22:16:36Z

:)

IanTheEngineer · 2017-03-14T22:17:02Z

tools/rosconsole/src/rosconsole/rosconsole.cpp

@@ -394,8 +397,11 @@ void Formatter::print(void* logger_handle, ::ros::console::Level level, const ch

  fprintf(f, "%s\n", ss.str().c_str());

-  if (f == stdout) {
-    fflush(f);
+  if (g_force_stdout_line_buffered && f == stdout) {


Should we have similar functionality for flushing stderr? Granted, stdout should be more common than stderr, but it seems odd to treat them differently.

@IanTheEngineer It seems like stderr has no buffering at all and does not need to be flushed, as far as I know.

lamerman · 2017-03-14T22:20:39Z

Currently the pull request contains multiple commits, I wanted to squash them to one finally, once we decide it's ok.

…::print When application output is connected to pipe a fully-buffered output is used by default. In this case the logs of application will not be visible for user until there are enough logs to fill the buffer. An example where such behaviour can be observed is launching binary ROS executable from within Android APK. There is not way to connect stdout to TTY and only pipe can be used. As a result the user cannot see the application output. The proposed solution is to force flushing of stdout on every line in ROS logger when a special environment variable is set.

lamerman · 2017-03-15T05:22:33Z

Guys, I squashed the commits to one and reworded the commit message.

dirk-thomas

While you can squash the commit GitHub also supports to squash them on merge. Whichever you prefer.

dirk-thomas · 2017-03-15T15:42:39Z

tools/rosconsole/src/rosconsole/rosconsole.cpp

+      if (line_buffered == "1") {
+        g_force_stdout_line_buffered = true;
+      } else {
+        if (line_buffered != "0") {


Last nitpick (sorry, didn't see it before): can you use else if for these two lines instead.

Sure, I will do it tomorrow. Currently I am quite far from my PC.

If you are ok with it I can just apply the change to your branch (thanks to the latest features in GitHub 😉).

Great, I changed it to else if in 52d9671 (plus some style adjustment to match the rest of the file since I was already in the editor 😉). Once CI has passed again this can be merged.

dirk-thomas · 2017-03-15T16:25:01Z

Thanks for your effort on this. It might be good to mention the new environment variable on http://wiki.ros.org/rosconsole with a remark that it is available as of Lunar (for now - it could be considered for backporting in the future).

lamerman · 2017-03-15T19:36:16Z

@dirk-thomas, I also thought about documentation. Should I somehow edit that wiki? How is it usually done?

dirk-thomas · 2017-03-15T19:54:01Z

Yes, it would be great if you could edit the wiki page and add the new information. You can annotate the new paragraph using the wiki macro Version to highlight that this is a new feature in ROS Lunar: <<Version(ROS Lunar)>>

lamerman · 2017-03-15T20:01:30Z

Ok I will do it in a couple of days. Thank you for reviewing. :)

lamerman · 2017-03-22T22:04:06Z

@dirk-thomas I edited the wiki http://wiki.ros.org/rosconsole#Force_line_buffering_for_ROS_logger , could you please review?

dirk-thomas · 2017-03-23T20:53:27Z

Thanks! The new paragraph looks great. I only did some little adjustments (see http://wiki.ros.org/action/diff/rosconsole?action=diff&rev1=73&rev2=74).

…::print (ros#1012) * Force a write of all user-space buffered data for stdout in Formatter::print When application output is connected to pipe a fully-buffered output is used by default. In this case the logs of application will not be visible for user until there are enough logs to fill the buffer. An example where such behaviour can be observed is launching binary ROS executable from within Android APK. There is not way to connect stdout to TTY and only pipe can be used. As a result the user cannot see the application output. The proposed solution is to force flushing of stdout on every line in ROS logger when a special environment variable is set. * minor style change

knorth55 · 2019-04-05T07:35:08Z

@dirk-thomas we want this new feature in Kinetic. Can we open the backport PR to kinetic-devel branch?
cc. @Affonso-Gui

dirk-thomas · 2020-02-03T21:25:46Z

we want this new feature in Kinetic. Can we open the backport PR to kinetic-devel branch?

Features are in general not backported to already released distros. The reason is a combination of effort and desire for stability / avoiding risk of regression.

dirk-thomas added the requires-changes label Mar 3, 2017

dirk-thomas reviewed Mar 13, 2017

View reviewed changes

dirk-thomas reviewed Mar 14, 2017

View reviewed changes

IanTheEngineer reviewed Mar 14, 2017

View reviewed changes

lamerman force-pushed the lunar-devel branch from df5e8a8 to 055410d Compare March 15, 2017 05:20

dirk-thomas reviewed Mar 15, 2017

View reviewed changes

minor style change

52d9671

dirk-thomas removed the requires-changes label Mar 15, 2017

dirk-thomas merged commit 71905d7 into ros:lunar-devel Mar 15, 2017

dirk-thomas added the enhancement label Mar 15, 2017

dirk-thomas mentioned this pull request Oct 26, 2017

changes between 1.12.7 and 1.13.4 for backporting #1205

Merged

dhood mentioned this pull request Nov 15, 2017

Force flush for rcutils logging ros2/rcutils#70

Closed

jacobperron mentioned this pull request Jul 15, 2019

default RCUTILS_CONSOLE_STDOUT_LINE_BUFFERED to 1 ros2/rcutils#169

Closed

	char* env_ipv6 = NULL;
	#ifdef _MSC_VER
	_dupenv_s(&env_ipv6, NULL, "ROS_IPV6");
	#else
	env_ipv6 = getenv("ROS_IPV6");
	#endif

	bool use_ipv6 = (env_ipv6 && strcmp(env_ipv6,"on") == 0);

	override = os.environ.get('ROSLAUNCH_SSH_UNKNOWN', 0)
	if override == '1':

Force a write of all user-space buffered data for stdout in Formatter::print #1012

Force a write of all user-space buffered data for stdout in Formatter::print #1012

Conversation

lamerman commented Mar 3, 2017

dirk-thomas commented Mar 3, 2017

lamerman commented Mar 3, 2017

lamerman commented Mar 9, 2017 • edited Loading

dirk-thomas commented Mar 10, 2017

lamerman commented Mar 11, 2017

lamerman commented Mar 11, 2017 • edited Loading

dirk-thomas commented Mar 11, 2017

lamerman commented Mar 12, 2017

dirk-thomas commented Mar 12, 2017

lamerman commented Mar 12, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lamerman commented Mar 14, 2017

dirk-thomas commented Mar 14, 2017

lamerman commented Mar 14, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lamerman commented Mar 14, 2017

lamerman commented Mar 15, 2017

dirk-thomas left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dirk-thomas commented Mar 15, 2017

lamerman commented Mar 15, 2017

dirk-thomas commented Mar 15, 2017

lamerman commented Mar 15, 2017

lamerman commented Mar 22, 2017

dirk-thomas commented Mar 23, 2017

knorth55 commented Apr 5, 2019

dirk-thomas commented Feb 3, 2020

lamerman commented Mar 9, 2017 •

edited

Loading

lamerman commented Mar 11, 2017 •

edited

Loading