add logging API and macros #23

dirk-thomas · 2017-05-31T20:14:14Z

This is the patch moved from ros2/rcl#138.

I will have to remove the usage of time and with that the THROTTLE macros since that is a concept introduced in rcl and not available here. That will imply that the macros containing THROTTLE can only be implemented in rcl and will therefore require a different #include directive.

I assume the throttle specific macros then use the RCL_ prefix while all the macros from this package use RCUTILS_... 😒

wjwwood · 2017-05-31T21:20:00Z

You could consider moving the "time source" struct, the system time source, and the steady time source to rcutils as well, leaving only the ROS time source in rcl.

wjwwood · 2017-05-31T21:26:35Z

Another option would be to make the throttle macros just take a function pointer to a "get now" function that returned something like nanoseconds as uint64_t. Then you could provide integration with the rcl_time_source_t in the rcl package.

dirk-thomas · 2017-06-01T18:17:47Z

Another option would be to make the throttle macros just take a function pointer to a "get now" function that returned something like nanoseconds as uint64_t. Then you could provide integration with the rcl_time_source_t in the rcl package.

This is pretty different to how get_now currently behaves. I don't think I will perform such a refactoring just for the logging API. This should be considered separately.

The following PR moves the time stuff from rcl to rcutils: #25. I will rebase this once that PR has been merged.

wjwwood · 2017-06-01T18:58:02Z

This is pretty different to how get_now currently behaves. I don't think I will perform such a refactoring just for the logging API. This should be considered separately.

I wasn't suggesting you refactor the existing get_now. I was suggesting you make the time related logging macros require a function of that signature. It would then be up to the caller to provide a function that matches it. That would decouple those logging macros from the time source concept.

You could still provide convenience macros that used a static global "system" and/or "steady" time source for the user so they don't have to provide such a function.

dirk-thomas · 2017-06-01T19:14:51Z

I wasn't suggesting you refactor the existing get_now. I was suggesting you make the time related logging macros require a function of that signature. It would then be up to the caller to provide a function that matches it. That would decouple those logging macros from the time source concept.

That would imply that the "get now" function pointer can't report errors anymore, correct? What happens if the specific rcl time source returns an error code? How does the wrapping function handle that?

wjwwood · 2017-06-01T19:22:52Z

That would imply that the "get now" function pointer can't report errors anymore, correct? What happens if the specific rcl time source returns an error code? How does the wrapping function handle that?

How does the logging macro report errors right now? I guess the function could do the same. Or the get_now function could be more sophisticated, with a signature like:

bool (* get_now)(uint64_t * time_out, const char * error_out)

Or similar.

dirk-thomas · 2017-06-02T05:31:25Z

Rebased and updated:

Linux
Linux-aarch64
macOS
Windows

Ready for review.

clalancette · 2017-06-02T20:22:58Z

I'll take a look.

clalancette

I have some nits, questions, and some things that might be nice cleanups, but looks pretty good overall to me.

clalancette · 2017-06-02T20:24:36Z

src/logging.c

+
+rcl_logging_output_handler_t g_rcl_logging_output_handler = NULL;
+
+int g_rcl_logging_severity_threshold = 0;


static for all of these?

They are currently defined as extern (https://github.com/ros2/rcutils/pull/23/files#diff-f1d39d4e841937fde043a8e49b7e6c2aR87) to be globally accessible.

It seems to me that all of these are either implementation details (initialized), or already have getters and setters (output_handler, threshold), so we could get rid of the extern on all of them and make them static here.

I don't see a reason to hide them. In ROS 1 all of these global variables are exposed - usually because at some point that was requested.

Usually I just want to keep implementations as hidden as possible; it makes it easier to change later if we want. That being said, I don't feel that strongly about this particular one, so I'll leave it up to you.

clalancette · 2017-06-02T20:29:33Z

src/logging.c

+extern "C"
+{
+#endif
+


Is wrapping the entire C file in "extern "C"" really required? I think that would only make a difference if we tried to compile the C files with a C++ compiler, not a C compiler.

I don't know if this is the reason, but if you compile this with a c++ compiler by accident then the extern C prevents name mangling, which also prevent implicit overloading (if you change parameters in the header but forget to change the source file).

We are doing the same in various other files.

clalancette · 2017-06-02T20:35:49Z

src/logging.c

+void rcl_logging_console_output_handler(
+  rcl_log_location_t * location,
+  int severity, const char * name, const char * format, va_list * args)
+{


Would it make sense to make severity an "enum RCUTILS_LOG_SEVERITY" instead of an int (here and elsewhere)? It won't make a huge difference to the code, but would make it clear to anyone implementing their own output handler what the types they can expect are.

I would rather not restrict the valid severity levels. Currently the numbers are consecutive but I would suggest to diverge from that in the future and leave room for "in between" levels for users to define.

OK, that makes sense.

clalancette · 2017-06-02T20:40:08Z

resource/logging_macros.h.em

+ */
+# define RCUTILS_UNLIKELY(x) (x)
+#endif
+


It seems to me that it would be better to move all of the RCUTILS LIKELY/UNLIKELY stuff into a separate header file. It is not logging specific, it will de-clutter logging_macros.h a bit, and will probably be useful to other users at some point.

I would rather keep it close to the code where it is being used atm. If it turns out that it is useful elsewhere it can be refactored to a common location.

clalancette · 2017-06-02T20:45:25Z

resource/logging_macros.h.em

+#define RCUTILS_LOG_CONDITION_THROTTLE_AFTER } \
+  }
+///@@}
+


Actually, it also might be nice to move all of the above macros into a separate header file as well. That way, when users of the logging API just want to know what they can call, they just have the generated list of macros (below). The implementation details (all of the stuff above) would be hidden unless they go looking for it. What do you think?

I am not sure what you mean with "hidden unless they go looking for it". The doxygen documentation will contain the API of the generated code.

I was mostly talking about having a "logging_macros.h" and a "logging_macros-impl.h", or something like that. But thinking about it further, since this is a generated file most people will probably be just looking at the documentation anyway, so this is fine as it is.

clalancette · 2017-06-02T20:54:59Z

resource/logging_macros.h.em

+///@@{
+#if (RCUTILS_LOG_MIN_SEVERITY > RCUTILS_LOG_SEVERITY_@(severity))
+// empty logging macros for severity @(severity) when being disabled at compile time
+@[for suffix in feature_combinations]@


Could we indent this for loop (and everything else inside of the "for severity in severities" loop)? It would make it a bit easier to read.

I would say no, since the goal is that the generated code is correctly indented which would not be the case if indentation is added based on the template logic. The template parts (if, else) etc. use indentation to make the nesting more obvious.

Yeah, understood about the generated code. I was talking about the template parts in particular; the line "@[for suffix in feature_combinations]@" seems like it should be indented, since it is inside of the severity loop above.

I added spaces for the two nested @[ for loops.

clalancette · 2017-06-02T20:57:32Z

resource/logging_macros.h.em

+ \
+    if (RCUTILS_LIKELY(__rcutils_logging_condition)) { \
+      __rcutils_logging_last_logged = __rcutils_logging_now;
+


A question more than a review comment. I see here where we store the duration, and determine the last_logged time. But I don't see where we conditionally print if it has been at least duration. How does that work?

I few lines above the variable __rcutils_logging_condition contains the condition. The actual if is directly above this comment.

Oh, I see now. Because this is the "before" condition, when we generate the print line we are still inside of the if condition. That detail is a bit subtle; it might be worthwhile to put a comment explaining that.

The doc block mentions how the "before" and "after" condition macros are being used: https://github.com/ros2/rcutils/pull/23/files#diff-16a8c3749d32285b558137f65c5c60d2R81

Please feel free to suggest a specific improvement what you would like to see in the docs.

I tried to come up with something, but I couldn't really improve it very much. So never mind this :).

clalancette · 2017-06-02T21:01:52Z

test/test_logging.cpp

+  g_log_calls = 0;
+  rcl_log(&location, RCUTILS_LOG_SEVERITY_DEBUG, "name1", "message %d", 11);
+  EXPECT_EQ(g_log_calls, 1u);
+  EXPECT_TRUE(g_last_log_event.location != NULL);


You could use ASSERT_TRUE here and get rid of the if condition below.

Since I want the following checks to be performed independently of the result of this check I think this should be EXPECT.

That's fine.

wjwwood · 2017-06-06T17:41:26Z

This added a flakey test (only on macOS so far): #27

Notifying @dirk-thomas and @clalancette according to https://github.com/ros2/ros2/wiki/Build-Cop-and-Build-Farmer-Guide#new-failure-actions (Important Failures).

mikaelarguedas · 2017-08-09T21:31:19Z

src/logging.c

+    fprintf(stream, "[%s] [%s]: %s\n", severity_string, name, message_buffer);
+  } else {
+    fprintf(
+      stream, "[%s] [%s]: %s (%s() at %s:%zu)\n", severity_string, name, message_buffer,


this assumes that we pass a name. So, for example:
RCUTILS_LOG_INFO("foo") results in:
[INFO] []: foo ...

@dirk-thomas was that the original intent ?
Slightly related, is it expected that by default function_name, file_name and line_number are printed ?

this assumes that we pass a name

Yes, if desired the code could leave the brackets around empty name out.

is it expected that by default function_name, file_name and line_number are printed

Yes, for now that was the intent. In the future this should be configurable (as many other things).

ok thanks for clarifying
That's something to keep in mind given that the executables tested using regex/string matching on console output can NOT use these macros as is. We would need to add more complex regex logic for the console output to be matched properly

dirk-thomas added the in progress Actively being worked on (Kanban column) label May 31, 2017

dirk-thomas self-assigned this May 31, 2017

dirk-thomas force-pushed the logging branch from ae98ba7 to ddc58dd Compare May 31, 2017 21:21

dirk-thomas mentioned this pull request Jun 1, 2017

add logging API and macros ros2/rcl#138

Closed

wjwwood mentioned this pull request Jun 1, 2017

move time files from rcl #25

Merged

dirk-thomas force-pushed the logging branch from ddc58dd to 191da94 Compare June 2, 2017 05:20

dirk-thomas added in review Waiting for review (Kanban column) and removed in progress Actively being worked on (Kanban column) labels Jun 2, 2017

clalancette self-requested a review June 2, 2017 20:23

clalancette reviewed Jun 2, 2017

View reviewed changes

add logging API and macros

8ef5ffc

dirk-thomas force-pushed the logging branch from 191da94 to 8ef5ffc Compare June 5, 2017 16:56

clalancette approved these changes Jun 5, 2017

View reviewed changes

dirk-thomas merged commit b5a7a12 into master Jun 5, 2017

dirk-thomas deleted the logging branch June 5, 2017 18:20

dirk-thomas removed the in review Waiting for review (Kanban column) label Jun 5, 2017

wjwwood mentioned this pull request Jun 6, 2017

log throttle tests are failing on macOS #27

Closed

mikaelarguedas reviewed Aug 9, 2017

View reviewed changes


		rcl_logging_output_handler_t g_rcl_logging_output_handler = NULL;

		int g_rcl_logging_severity_threshold = 0;

add logging API and macros #23

add logging API and macros #23

Conversation

dirk-thomas commented May 31, 2017

wjwwood commented May 31, 2017

wjwwood commented May 31, 2017

dirk-thomas commented Jun 1, 2017

wjwwood commented Jun 1, 2017 • edited Loading

dirk-thomas commented Jun 1, 2017

wjwwood commented Jun 1, 2017

dirk-thomas commented Jun 2, 2017 • edited Loading

clalancette commented Jun 2, 2017

clalancette 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

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

Choose a reason for hiding this comment

dirk-thomas Jun 2, 2017 • edited Loading

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

wjwwood commented Jun 6, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

wjwwood commented Jun 1, 2017 •

edited

Loading

dirk-thomas commented Jun 2, 2017 •

edited

Loading

dirk-thomas Jun 2, 2017 •

edited

Loading