Human Readable time in logs

[tonynajjar]

Is it currently possible to have human-readable timestamps like in ROS1? If not then this is a feature request. With some guidance I can contribute here

[fujitatomoya]

as far as i know, we do not have it currently. i think that we only have two options to represent the time. (both are not human readable though.)

https://github.com/ros2/rcutils/blob/c1623e7db620bf051cb539e3d4eb7029bb554bb2/src/logging.c#L701-L702

CC: @ivanpauno @wjwwood

[clalancette]

That's right, we currently don't support any human-readable timestamps; we only support {time} and {time_as_nanoseconds}.

We could certainly add something, though I'd wait until we land https://github.com/ros2/rcutils/pull/372 ; that should make it much more viable.

[tonynajjar]

Your PR is merged. Could you walk me through what would need to be done here? If the effort is small enough I can give it a shot

[clalancette]

Your PR is merged. Could you walk me through what would need to be done here? If the effort is small enough I can give it a shot

Just to give a bit of background (if you aren't familiar), the logging output format uses tokens of the form {time} to do replacements. When that is in the format string, then when a log message is produced, we'll replace that token with the results of some processing. There are individual callbacks that deal with generating different data for different tokens (one for time, one for line, etc). So the general idea with implementing this is to add in a new token (in the structure that @fujitatomoya pointed out), and an implementation.

There are two different ways the occur to me for the implementation:

1. The simpler way, which is to add a new token like {time_iso8601}, and then the implementation would generate a hard-coded strftime-like output. The advantage to this is that it is simple to implement and somewhat fast to produce at runtime (which is important). The disadvantage is that there is no way for the user to control what would be output; it would just be hard-coded to whatever we chose (probably ISO 8601).

2. The more complicated way, which would be to add a new token that accepts arbitrary strftime format strings. I'm thinking something like {time_format %H-%M-%S %F}. The advantage to this is it is configurable by the user. The downside is in implementation complexity (we'd need to change how we search for tokens besides implementing the callback), and the possible runtime performance implications (we'd have to parse the token carefully to make sure it is a valid strftime format, though maybe we can cache this). We also don't have any precedent for doing this, so there may be other problems that I'm not thinking about at the moment.

I could be convinced to go either way; I think they both have merit. @fujitatomoya @ros2/team does anyone have opinions on which way to go here?

[tfoote]

Another potential option would be to support tokens for the specific subfields of time and let the user choose a sequence of tokens {time} or {time_HH}:{time_MM}:{time_SS} to say get the timestamp. It's slightly less flexible, but hopefully less error prone. But the full strftime format strings we could consider doing it as long as we're quite robust to errors, and can cache the parsing to only happen at startup time.

[iuhilnehc-ynos]

Both https://github.com/ros2/rcutils/issues/371#issuecomment-1221036967 and https://github.com/ros2/rcutils/issues/371#issuecomment-1224540610 seem reasonable to me.

If I were the user, I don't like to configure the environment variable RCUTILS_CONSOLE_OUTPUT_FORMAT which seems a little complicated. (eg. the default setting "[{severity}] [{time}] [{name}]: {message}")

some extra methods:

• adding an extra boolean environment variable (eg. RCUTILS_LOG_TIME_EXPERIMENTAL=1) to show the readable time.
• expanding the {time} with some extra format string if users would like to custom a particular time. (eg. {time %Y-%m-%d %H:%M:%S})

[fujitatomoya]

I am okay with either environment variable or adding tokens.

If I were the user,

We Sony (including you) are actually user 😄

[clalancette]

• adding an extra boolean environment variable (eg. RCUTILS_LOG_TIME_EXPERIMENTAL=1) to show the readable time.

I'd really prefer not to add more configuration variables. There are already a bunch of them, they are not well documented (though I'm working on that), and adding more just makes it harder to explain.

• expanding the {time} with some extra format string if users would like to custom a particular time. (eg. {time %Y-%m-%d %H:%M:%S})

Yeah, this is similar to what I pointed out in https://github.com/ros2/rcutils/issues/371#issuecomment-1221036967 . I'll suggest, though, that we leave {time} as it is and use a new token, mostly to keep {time} fast.

[fujitatomoya]

There are already a bunch of them, they are not well documented (though I'm working on that), and adding more just makes it harder to explain.

agree.

[jrutgeer]

Fyi, there's an example implementation here.

[fmauch]

I guess, this can be closed, since https://github.com/ros2/rcutils/pull/441 has been merged?

TLDR:

$ export RCUTILS_CONSOLE_OUTPUT_FORMAT="[{severity} {date_time_with_ms}] [{name}]: {message}"
$ ros2 run examples_rclcpp_minimal_publisher publisher_member_function
[INFO 2024-06-11 09:13:56.318] [minimal_publisher]: Publishing: 'Hello, world! 0'
[INFO 2024-06-11 09:13:56.818] [minimal_publisher]: Publishing: 'Hello, world! 1'
[INFO 2024-06-11 09:13:57.318] [minimal_publisher]: Publishing: 'Hello, world! 2'

[clalancette]

Yeah, fair enough. We didn't go the full timespec thing, but I think what we have now is probably good enough.