All logging to the same stream #196

clalancette · 2019-12-13T14:51:07Z

This PR is a rehash of the now-closed #181. In particular, this PR proposes to make it so that all output from all logging levels go to the same stream. This replicates the behavior of basically all other logging systems; see #181 (comment) for details.

Compared to #181, this PR is now rebased on master, and has made it so that the stream that all output goes to is configurable. The default is stderr/unbuffered (so that error messages go out right away), but if users want a very minor performance improvement, they can switch it to stdout/buffered by setting RCUTILS_CONSOLE_LINE_BUFFERED=1.

Unfortunately, the change to stderr by default means that a lot of tests in the ROS 2 core (and probably beyond) are going to start failing. That's because those tests are typically trying to capture stdout output, and there is no longer any output there. Solutions I can think of:

Make the default stream stdout (failing tests isn't a great reason to do this, in my opinion).
Change all of the failing tests to set RCUTILS_CONSOLE_LINE_BUFFERED=1 (this will fix it in the core, but still leave downstream consumers with failing tests).
Change launch_testing to capture stderr along with stdout.
???

@ros2/team Opinions on how to proceed with fixing tests appreciated.

@rotu FYI

Fixes #168

dirk-thomas · 2019-12-13T15:42:15Z

switch it to stdout/buffered by setting RCUTILS_CONSOLE_LINE_BUFFERED=1.

With the change in semantic the option name doesn't reflect what it does anymore. I would suggest to change the env var name to something indicating that it changes the default logging stream from stderr to stdout (or mixed if we want to allow the original behavior using a severity specific stream).

Opinions on how to proceed with fixing tests appreciated.

Options 1 and 2 sound like hacks to me. I think we should a) certainly support option 3. in launch_testing and b) use that throughout our tests.

clalancette · 2019-12-13T21:30:11Z

Another option that came to mind is to always use the stdout stream, but have the command-line option toggle between buffered and unbuffered mode. Bonus points for making it 4 way configurable with stdout/stderr choice and buffered/unbuffered choice, with the default being stdout/unbuffered.

wjwwood · 2019-12-13T22:57:28Z

I agree that the env var name no longer makes sense.

Why not update the tests to match output to stderr (and also set an environment variable to ensure that's the logger's behavior)?

It's possible to route stderr to stdout so they are captured together, but that option isn't exposed at the moment to the ExecuteProcess action:

https://github.com/ros2/launch/blob/7b6f4e021a8987baa4e7ccb957c6e1eace1339cb/launch/launch/actions/execute_process.py#L645

It looks like launch_testing was never built with support for checking output from stderr...

https://github.com/ros2/launch/blob/f73bc56caa9c7b3c53b264475728392d0e1ce9cf/launch_testing/launch_testing/io_handler.py#L163

@pbaughman can you comment on that?

But it should be possible, as launch generates events for each line of stderr as well as stdout, so it can be captured.

pbaughman · 2019-12-14T00:38:20Z

@wjwwood I am happy to comment!

launch_testing actually captures both stdout and stderr in the proc_output handler but currently only has built-in support for asserting about stdout

It would be a pretty simple improvement to add built-in assertions for stderr too.

jacobperron · 2019-12-16T17:32:37Z

+1 for fixing our tests and launch_testing to work with stderr.

clalancette · 2020-02-10T21:57:31Z

All right, I've done a bunch of work here to fix this up. Besides this PR, we need (at least):

Full Linux CI: * Linux

src/logging.c

clalancette · 2020-02-12T22:43:04Z

I've responded to all of the comments, and I've also added a message about backwards compatibility. I'm going to run a full Linux CI on this again to see where we are at.

Linux CI:

src/logging.c

clalancette · 2020-02-13T17:55:05Z

More review fixes, and one more test fix. Another Linux CI:

Linux CI:

clalancette · 2020-02-14T00:01:48Z

With ros2/ros2#869 , this should be much closer to green. I'm going to kick off a full round of CI on all platforms to see if there is anything else I missed:

Linux
Linux-aarch64
macOS
Windows
Windows-container

clalancette · 2020-02-14T18:24:53Z

All right. All of the reported failures in the CI job were also on the buildfarm, so I don't think this series of PRs is causing the problem. This is ready for another round of review, along with the connected PRs.

brawner · 2020-02-14T20:18:46Z

Not sure if you caught this, but there are new MSBuild warnings with this build:

https://ci.ros2.org/job/ci_windows-container/130/warnings43Result/new/package.-1236367313/

clalancette · 2020-02-14T21:09:40Z

Not sure if you caught this, but there are new MSBuild warnings with this build:

I always miss them. Thanks for pointing it out, I'll look to see what we do elsewhere.

clalancette · 2020-02-15T00:10:41Z

All right, this is getting to be a bit of an octopus, but I believe I've solved the Windows errors now. Let's try another CI:

Linux
Linux-aarch64
macOS
Windows
Windows-container

hidmic

Looking good, pending green CI

hidmic · 2020-02-18T18:41:18Z

src/logging.c

+// something we don't understand.  Return RCUTILS_GET_ENV_ZERO if the value in the
+// environment variable is "0", RCUTILS_GET_ENV_ONE if the value in the environment
+// variable is "1", or RCUTILS_GET_ENV_DEFAULT if the environment variables is empty.
+static enum rcutils_get_env_retval rcutils_get_env_var_zero_or_one(


@clalancette nit: any reason not to use Doxygen syntax?

@clalancette nit: any reason not to use Doxygen syntax?

Not particularly. This is an internal function, so I didn't think it was necessary, but I'll claim ignorance on what our policy is for comments on internal functions.

hidmic · 2020-02-18T18:43:50Z

include/rcutils/strerror.h

+
+RCUTILS_PUBLIC
+void
+rcutils_safe_strerror(char * buffer, size_t buffer_length);


@clalancette missing docblock

Oops, yeah, good call. Added in 9200c9f

How about removing safe from the name of the function?

I took the name from https://github.com/ros2/rclcpp/blob/2d9c6ea3a77103b91f7984269d163037961a4c04/rclcpp/src/rclcpp/signal_handler.cpp#L164 . But I don't have a strong opinion, so we can just switch it to rcutils_strerror if you prefer.

src/logging.c

clalancette · 2020-02-19T16:00:47Z

CI for new code:

Linux
Linux-aarch64
macOS
Windows
Windows-container

dirk-thomas · 2020-02-19T18:25:47Z

Nitpick: each sentence in a comment / docblock should start on a new line.

src/logging.c

dirk-thomas · 2020-02-19T18:33:36Z

Regarding the env var names: I am not convinced the prefix RCUTILS_CONSOLE_ is a good choice (I understand it has been used for the previous env vars already). I am missing some kind of hint that these options are affecting logging.

src/logging.c

dirk-thomas · 2020-02-19T18:44:08Z

include/rcutils/strerror.h

+
+RCUTILS_PUBLIC
+void
+rcutils_safe_strerror(char * buffer, size_t buffer_length);


How about removing safe from the name of the function?

include/rcutils/strerror.h

clalancette · 2020-02-19T19:17:39Z

Regarding the env var names: I am not convinced the prefix RCUTILS_CONSOLE_ is a good choice (I understand it has been used for the previous env vars already). I am missing some kind of hint that these options are affecting logging.

That's true. I think I'll go with something like RCUTILS_LOGGING_USE_STDOUT and RCUTILS_LOGGING_BUFFERED_STREAM.

src/logging.c

include/rcutils/strerror.h

src/logging.c

include/rcutils/strerror.h

wjwwood · 2020-02-20T21:46:21Z

src/logging.c

+          stderr, "Invalid return from environment fetch\n");
+        RCUTILS_SET_ERROR_MSG(
+          "Invalid return from environment fetch");
+        return RCUTILS_RET_ERROR;


I'm not a huge fan of setting the error state and printing to stderr. In my opinion, libraries shouldn't print to stderr unless there's no other way to raise an issue. This function can raise an issue with the return code and error state.

Again, I know this is the case already in this file, but I felt I should bring it up as long as we're looking at this file.

This follows the convention for human-readable diagnostic output on Linux systems. fix #168 Make the stream configurable. We default the stream to stderr, but allow the user to change it to stdout by setting RCUTILS_CONSOLE_LINE_BUFFERED to 1. Signed-off-by: Dan Rose <dan@digilabs.io> Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>

And switch to using 'setvbuf', which allows us to get rid of flush semantic during runtime. Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>

Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>

Used in the logging stuff, and elsewhere in the codebase. Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>

Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>

clalancette · 2020-02-21T13:50:36Z

I've now responded to most of the open comments. The ones remaining are as follows:

Change rcutils_safe_strerror -> rcutils_strerror. I think having the safe in here is a good additional hint that this is a thread-safe version of strerror, so I'm going to leave it.
Don't use fprintf directly, and instead use RCUTILS_SAFE_FWRITE_TO_STDERR. As I see it, this whole file violates that, so I'd rather not make this (already getting large) PR any larger, and file an issue for a follow-up to fix it.
Don't both print to stderr and return an error, and instead just set and return an error. Again, this whole file violates that, so I'd rather keep it internally consistent and then file an issue to follow-up to fix it.

So with that, I think this is ready for another round of review.

clalancette · 2020-02-21T14:18:37Z

Another CI:

Linux
Linux-aarch64
macOS
Windows
Windows-container

dirk-thomas

Change rcutils_safe_strerror -> rcutils_strerror. I think having the safe in here is a good additional hint that this is a thread-safe version of strerror, so I'm going to leave it.

I think it would be good to remove it now since other thread-safe API doesn't contain that as part of their name either.

and 3.

👍 to keep those changes separate.

Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>

clalancette · 2020-02-28T17:59:32Z

All right, all PRs approved. One more CI to make sure everything is happy, then I'll merge:

Linux
Linux-aarch64
macOS
Windows
Windows-container

wjwwood assigned clalancette Jan 2, 2020

dirk-thomas mentioned this pull request Jan 3, 2020

arguments = [--ros-args --log-level WARN] has not expected behavior ros2/launch_ros#109

Closed

clalancette force-pushed the log_to_stderr branch 2 times, most recently from a3f04b1 to 5c882db Compare February 10, 2020 21:49

This was referenced Feb 10, 2020

Fix pendulum_control tests to use stdout stream. ros2/demos#430

Merged

Add the ability to assert in stdout or stderr. ros2/launch#378

Merged

clalancette mentioned this pull request Feb 11, 2020

Specify stdout as the stream to look at. ros2/system_tests#398

Merged

hidmic reviewed Feb 11, 2020

View reviewed changes

clalancette force-pushed the log_to_stderr branch 2 times, most recently from d3538f7 to a16b5cc Compare February 12, 2020 22:38

hidmic reviewed Feb 13, 2020

View reviewed changes

src/logging.c Show resolved Hide resolved

src/logging.c Show resolved Hide resolved

src/logging.c Show resolved Hide resolved

src/logging.c Outdated Show resolved Hide resolved

This was referenced Feb 14, 2020

Use the new rcutils_strerror function. ros2/geometry2#239

Merged

Switch to using new rcutils_strerror. ros2/rclcpp#993

Merged

hidmic approved these changes Feb 18, 2020

View reviewed changes

clalancette force-pushed the log_to_stderr branch from 5dc1b09 to 9200c9f Compare February 19, 2020 15:16

dirk-thomas reviewed Feb 19, 2020

View reviewed changes

src/logging.c Outdated Show resolved Hide resolved

dirk-thomas reviewed Feb 19, 2020

View reviewed changes

wjwwood reviewed Feb 20, 2020

View reviewed changes

src/logging.c Outdated Show resolved Hide resolved

include/rcutils/strerror.h Outdated Show resolved Hide resolved

src/logging.c Show resolved Hide resolved

src/logging.c Show resolved Hide resolved

src/logging.c Show resolved Hide resolved

wjwwood reviewed Feb 20, 2020

View reviewed changes

rotu and others added 9 commits February 21, 2020 13:18

Allow the user to specify buffering mode of stream.

1125b4b

And switch to using 'setvbuf', which allows us to get rid of flush semantic during runtime. Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>

Add in backwards compatibility message.

35cfd09

Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>

More fixes from review.

a220086

Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>

Add an rcutils_safe_strerror function.

5f0b914

Used in the logging stuff, and elsewhere in the codebase. Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>

Add in doxygen comments.

e2d079d

Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>

Fix symbol visibility for Windows.

579ab72

Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>

Fixes from review.

51562b5

Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>

More fixes from review.

8abac20

Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>

clalancette force-pushed the log_to_stderr branch from 30d5add to 8abac20 Compare February 21, 2020 13:18

One more fix from review.

f21e226

Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>

dirk-thomas approved these changes Feb 21, 2020

View reviewed changes

Switch rcutils_safe_strerror -> rcutils_strerror

23df993

Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>

clalancette merged commit 2c1e933 into master Feb 28, 2020

delete-merged-branch bot deleted the log_to_stderr branch February 28, 2020 20:22

jacobperron mentioned this pull request Jun 22, 2020

Add message lost demo status event demo ros2/demos#453

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

All logging to the same stream #196

All logging to the same stream #196

clalancette commented Dec 13, 2019

dirk-thomas commented Dec 13, 2019

clalancette commented Dec 13, 2019

wjwwood commented Dec 13, 2019

pbaughman commented Dec 14, 2019

jacobperron commented Dec 16, 2019

clalancette commented Feb 10, 2020 •

edited

Loading

clalancette commented Feb 12, 2020 •

edited

Loading

clalancette commented Feb 13, 2020

clalancette commented Feb 14, 2020

clalancette commented Feb 14, 2020

brawner commented Feb 14, 2020

clalancette commented Feb 14, 2020

clalancette commented Feb 15, 2020

hidmic left a comment

hidmic Feb 18, 2020

clalancette Feb 19, 2020

hidmic Feb 18, 2020

clalancette Feb 19, 2020

dirk-thomas Feb 19, 2020

clalancette Feb 19, 2020

clalancette commented Feb 19, 2020

dirk-thomas commented Feb 19, 2020

dirk-thomas commented Feb 19, 2020

dirk-thomas Feb 19, 2020

clalancette commented Feb 19, 2020

wjwwood Feb 20, 2020

clalancette commented Feb 21, 2020

clalancette commented Feb 21, 2020 •

edited

Loading

dirk-thomas left a comment

clalancette commented Feb 28, 2020 •

edited

Loading

All logging to the same stream #196

All logging to the same stream #196

Conversation

clalancette commented Dec 13, 2019

dirk-thomas commented Dec 13, 2019

clalancette commented Dec 13, 2019

wjwwood commented Dec 13, 2019

pbaughman commented Dec 14, 2019

jacobperron commented Dec 16, 2019

clalancette commented Feb 10, 2020 • edited Loading

clalancette commented Feb 12, 2020 • edited Loading

clalancette commented Feb 13, 2020

clalancette commented Feb 14, 2020

clalancette commented Feb 14, 2020

brawner commented Feb 14, 2020

clalancette commented Feb 14, 2020

clalancette commented Feb 15, 2020

hidmic 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

Choose a reason for hiding this comment

clalancette commented Feb 19, 2020

dirk-thomas commented Feb 19, 2020

dirk-thomas commented Feb 19, 2020

Choose a reason for hiding this comment

clalancette commented Feb 19, 2020

Choose a reason for hiding this comment

clalancette commented Feb 21, 2020

clalancette commented Feb 21, 2020 • edited Loading

dirk-thomas left a comment

Choose a reason for hiding this comment

clalancette commented Feb 28, 2020 • edited Loading

clalancette commented Feb 10, 2020 •

edited

Loading

clalancette commented Feb 12, 2020 •

edited

Loading

clalancette commented Feb 21, 2020 •

edited

Loading

clalancette commented Feb 28, 2020 •

edited

Loading