Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

All logging to the same stream #196

Merged
merged 11 commits into from Feb 28, 2020
Merged

All logging to the same stream #196

merged 11 commits into from Feb 28, 2020

Conversation

clalancette
Copy link
Contributor

@clalancette clalancette commented Dec 13, 2019

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:

  1. Make the default stream stdout (failing tests isn't a great reason to do this, in my opinion).
  2. 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).
  3. Change launch_testing to capture stderr along with stdout.
  4. ???

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

@rotu FYI

Fixes #168

@dirk-thomas
Copy link
Member

dirk-thomas commented Dec 13, 2019

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
Copy link
Contributor Author

clalancette commented Dec 13, 2019

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
Copy link
Member

wjwwood commented Dec 13, 2019

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
Copy link
Contributor

pbaughman commented Dec 14, 2019

@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
Copy link
Member

jacobperron commented Dec 16, 2019

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

@clalancette
Copy link
Contributor Author

clalancette commented Feb 10, 2020

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 Build Status

src/logging.c Outdated Show resolved Hide resolved
src/logging.c Outdated Show resolved Hide resolved
src/logging.c Outdated Show resolved Hide resolved
src/logging.c Outdated Show resolved Hide resolved
src/logging.c Outdated Show resolved Hide resolved
src/logging.c Outdated Show resolved Hide resolved
@clalancette clalancette force-pushed the log_to_stderr branch 2 times, most recently from d3538f7 to a16b5cc Compare Feb 12, 2020
@clalancette
Copy link
Contributor Author

clalancette commented Feb 12, 2020

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: Build Status

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
@clalancette
Copy link
Contributor Author

clalancette commented Feb 13, 2020

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

Linux CI: Build Status

@clalancette
Copy link
Contributor Author

clalancette commented Feb 14, 2020

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 Build Status
  • Linux-aarch64 Build Status
  • macOS Build Status
  • Windows Build Status
  • Windows-container Build Status

@clalancette
Copy link
Contributor Author

clalancette commented Feb 14, 2020

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
Copy link
Contributor

brawner commented Feb 14, 2020

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
Copy link
Contributor Author

clalancette commented Feb 14, 2020

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
Copy link
Contributor Author

clalancette commented Feb 15, 2020

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 Build Status
  • Linux-aarch64 Build Status
  • macOS Build Status
  • Windows Build Status
  • Windows-container Build Status

hidmic
hidmic approved these changes Feb 18, 2020
Copy link
Contributor

@hidmic hidmic left a comment

Looking good, pending green CI

// 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(
Copy link
Contributor

@hidmic hidmic Feb 18, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

@clalancette clalancette Feb 19, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@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.


RCUTILS_PUBLIC
void
rcutils_safe_strerror(char * buffer, size_t buffer_length);
Copy link
Contributor

@hidmic hidmic Feb 18, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@clalancette missing docblock

Copy link
Contributor Author

@clalancette clalancette Feb 19, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oops, yeah, good call. Added in 9200c9f

Copy link
Member

@dirk-thomas dirk-thomas Feb 19, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How about removing safe from the name of the function?

Copy link
Contributor Author

@clalancette clalancette Feb 19, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 Outdated Show resolved Hide resolved
@clalancette
Copy link
Contributor Author

clalancette commented Feb 19, 2020

CI for new code:

  • Linux Build Status
  • Linux-aarch64 Build Status
  • macOS Build Status
  • Windows Build Status
  • Windows-container Build Status

@dirk-thomas
Copy link
Member

dirk-thomas commented Feb 19, 2020

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

src/logging.c Outdated Show resolved Hide resolved
@dirk-thomas
Copy link
Member

dirk-thomas commented Feb 19, 2020

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 Outdated Show resolved Hide resolved
src/logging.c Outdated Show resolved Hide resolved

RCUTILS_PUBLIC
void
rcutils_safe_strerror(char * buffer, size_t buffer_length);
Copy link
Member

@dirk-thomas dirk-thomas Feb 19, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How about removing safe from the name of the function?

include/rcutils/strerror.h Show resolved Hide resolved
@clalancette
Copy link
Contributor Author

clalancette commented Feb 19, 2020

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 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
include/rcutils/strerror.h Outdated Show resolved Hide resolved
stderr, "Invalid return from environment fetch\n");
RCUTILS_SET_ERROR_MSG(
"Invalid return from environment fetch");
return RCUTILS_RET_ERROR;
Copy link
Member

@wjwwood wjwwood Feb 20, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

rotu and others added 9 commits Feb 21, 2020
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>
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>
Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>
Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>
Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>
Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>
@clalancette
Copy link
Contributor Author

clalancette commented Feb 21, 2020

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

  1. 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.
  2. 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.
  3. 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
Copy link
Contributor Author

clalancette commented Feb 21, 2020

Another CI:

  • Linux Build Status
  • Linux-aarch64 Build Status
  • macOS Build Status
  • Windows Build Status
  • Windows-container Build Status

Copy link
Member

@dirk-thomas dirk-thomas left a comment

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.

  1. and 3.

👍 to keep those changes separate.

Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>
@clalancette
Copy link
Contributor Author

clalancette commented Feb 28, 2020

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

  • Linux Build Status
  • Linux-aarch64 Build Status
  • macOS Build Status
  • Windows Build Status
  • Windows-container Build Status

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

INFO and ERROR logging should come out in order by default
8 participants