Log call from rcl_init (i.e. before logging is initialized)

[jrutgeer]

This is not correct: call to RCUTILS_LOG_DEBUG_NAMED during initialization of the context.
Logging is not initialized yet, it is initialized after context initialization.

rcl/rcl/src/rcl/init.c

Lines 71 to 73 in 7bb8d4d

	RCUTILS_LOG_DEBUG_NAMED(
	ROS_PACKAGE_NAME,
	"Initializing ROS client library, for context at address: %p", (void *) context);

RCUTILS_LOG_DEBUG_NAMED does call RCUTILS_LOGGING_AUTOINIT but that is not intended at this point, see also #1036.

[jrutgeer]

There's another one here:

rcl/rcl/src/rcl/arguments.c

Line 353 in 4eccc3c

RCUTILS_LOG_DEBUG_NAMED(

Called from rcl_init():

rcl/rcl/src/rcl/init.c

Line 127 in 4eccc3c

ret = rcl_parse_arguments(argc, argv, allocator, &context->global_arguments);

EDIT: actually there's several more

Not sure what the best solution is.

Given that:

• Default loglevel is INFO, and
• User-specified loglevels are not set by RCUTILS_LOGGING_AUTOINIT,

so it seems that none of these log messages have ever been shown.

So one option would be to just delete those calls.

The better option is probably to use the RCL_SET_ERROR_MSG macros, which seem intended for this purpose?

[clalancette]

So there's a couple of things we could do here (these options are non-exclusive):

• Move the logging initialization earlier
• Delete some of these logging calls
• Move the logging calls until after logging initialization has happened

If you'd like to take a closer look and open a PR to do some of that, we'd be happy to review.

[jrutgeer]

@clalancette

Ok I had another look.

The major issue of having a log call in rcl_init is that the log call calls RCUTILS_LOGGING_AUTOINIT with the default allocator.
I guess this could be solved, e.g. by:

• Setting the g_rcutils_logging_allocator at the start of rcl_init, and
• Change this to check if g_rcutils_logging_allocator is valid and
• Remove this.

This has the benefit that all debug log calls can remain.
And it would solve #1036

The drawback is:

• Command line arguments are parsed later on, so you can´t specify the default loglevel. So to actually see these debug messages, you have to change the default loglevel in code and recompile.
  • Possible alternative: define default loglevel as an environment variable instead (or as well as) command line argument?
• These messages only go to console, not to the file as this is not configured yet.
  • This has always been like that, but given people are now used to the log files, as opposed to in the early days, they might not realize that part of the log is not in the file.

[clalancette]

Personally, I think that those drawbacks are acceptable for now. It isn't perfect, but it is an improvement over the situation today.

[fujitatomoya]

@jrutgeer your proposal sounds reasonable, logging allocator should be set before.

What about having rcutils_logging_initialize_allocator and rcl_logging_initialize_allocator to initialize global allocator for rcl and rcutils? and we can keep rcutils_logging_initialize_with_allocator and rcl_logging_initialize_with_allocator but check if global allocator has been set, and if not, set the global allocator accordingly?

Command line arguments are parsed later on, so you can´t specify the default loglevel. So to actually see these debug messages, you have to change the default loglevel in code and recompile.

I think this case applies, probably we can just remove the logging.

[jrutgeer]

What about having rcutils_logging_initialize_allocator and rcl_logging_initialize_allocator to initialize global allocator for rcl and rcutils?

Sounds good to me.

probably we can just remove the logging.

I would be inclined to leave them as they are. They don't harm, and they might be useful if somebody ever needs to make changes to the arguments parsing logic.

[fujitatomoya]

I would be inclined to leave them as they are. They don't harm, and they might be useful if somebody ever needs to make changes to the arguments parsing logic.

I do not have strong opinion here, just thought that deleting logging never be effective... i am good to leave them as they are.

[jrutgeer]

Well, they can be enabled, but you need to change the default loglevel and recompile.
But I don't have a strong opinion either; I'l leave the choice up to the one who writes the patch. :-)

[fujitatomoya]

@jrutgeer are you willing to address this? if that is so, we are happy to review 😄

[fujitatomoya]

@iuhilnehc-ynos @Barry-Xu-2018 any other proposals other than #1037 (comment)?

[iuhilnehc-ynos]

any other proposals other than #1037 (comment)?

Sound good to me.

1. add RCUTILS_LOGGING_AUTOINIT_WITH_ALLOCATOR(allocator); after

   rcl/rcl/src/rcl/init.c

   Line 69 in 4eccc3c

   RCL_CHECK_ARGUMENT_FOR_NULL(context, RCL_RET_INVALID_ARGUMENT);

2. add an environment variable RCUTILS_DEFAULT_LOGGER_DEFAULT_LEVEL to update the default log level in https://github.com/ros2/rcutils/blob/1db1f16a49378f4693b74296449ee920ff53cffe/src/logging.c#L526.

[fujitatomoya]

@iuhilnehc-ynos

add an environment variable RCUTILS_DEFAULT_LOGGER_DEFAULT_LEVEL to update the default log level in https://github.com/ros2/rcutils/blob/1db1f16a49378f4693b74296449ee920ff53cffe/src/logging.c#L526.

Is that too late to initialize the default level here? for example, during rcl_init we cannot enable debug level at all, since default is not set yet. So we need to set the default logging level when the process started? i might be mistaken...

[iuhilnehc-ynos]

Is that too late to initialize the default level here? for example, during rcl_init we cannot enable debug level at all, since default is not set yet. So we need to set the default logging level when the process started? i might be mistaken...

That's why I add the second step in #1037 (comment)

rcl_init -> RCUTILS_LOGGING_AUTOINIT_WITH_ALLOCATOR -> rcutils_logging_initialize_with_allocator
-> if there is an environment variable setting RCUTILS_DEFAULT_LOGGER_DEFAULT_LEVEL, use the value instead of macro (RCUTILS_DEFAULT_LOGGER_DEFAULT_LEVEL).

BTW, I don't think we need a new function rcl_logging_allocator_initialize.

[jrutgeer]

@fujitatomoya

@jrutgeer are you willing to address this?

Due to time constraints unfortunately not, but I am willing to think along and provide feedback.

Is that too late to initialize the default level here?

No, see this description: any log call will call RCUTILS_LOGGING_AUTOINIT, which eventually calls rcutils_logging_initialize_with_allocator(rcutils_allocator_t). So even for log calls in rcl_init this will be executed first.

However, if it is the intention to configure the loglevel through an environment variable, a code section similar to this should be added in front of this line.

@iuhilnehc-ynos

add RCUTILS_LOGGING_AUTOINIT_WITH_ALLOCATOR(allocator); after RCL_CHECK_ARGUMENT_FOR_NULL(context, RCL_RET_INVALID_ARGUMENT);

This isn't really necessary, as each log macro does call RCUTILS_LOGGING_AUTOINIT anyway.

[iuhilnehc-ynos]

This isn't really necessary, as each log macro does call RCUTILS_LOGGING_AUTOINIT anyway.

RCUTILS_LOGGING_AUTOINIT can't set the allocator with the external custom allocator.

[jrutgeer]

@iuhilnehc-ynos

RCUTILS_LOGGING_AUTOINIT can't set the allocator with the external custom allocator

Ok I see.

My suggestion was to set g_rcutils_logging_allocator to the specified allocator before any call to RCUTILS_LOGGING_AUTOINIT (i.e. at the beginning of rcl_init), and adapt RCUTILS_LOGGING_AUTOINIT to use g_rcutils_logging_allocator if it is valid, or the default allocator if not.

But your solution might be better: that way RCUTILS_LOGGING_AUTOINIT can be removed from the log macros, as logging will always be initialized at the start of rcl_init. So that's one if clause per log call less.

[iuhilnehc-ynos]

Keeping the RCUTILS_LOGGING_AUTOINIT during calling RCUTILS_LOG_DEBUG_NAMED is reasonable because users might not care about allocator for rcutils log, they might call RCUTILS_LOG_{X} directly,

#include <rcutils/logging_macros.h>

int main() {
  RCUTILS_LOG_DEBUG_NAMED("test", "debug message");
  RCUTILS_LOG_INFO_NAMED("test", "info message");
  return 0;
}


RCUTILS_DEFAULT_LOGGER_DEFAULT_LEVEL=10 ./a.out               # after adding the environment variable

The RCUTILS_LOGGING_AUTOINIT can be removed from RCUTILS_LOG_COND_NAMED because RCUTILS_LOGGING_AUTOINIT is called at rcutils_logging_logger_is_enabled_for as well, but I don't mind whether to remove the RCUTILS_LOGGING_AUTOINIT from the RCUTILS_LOG_COND_NAMED or not as it is not harmful.