take a timestamp when a console logging message happens #85

wjwwood · 2018-01-24T08:49:09Z

Also make it available for console formatting.

wjwwood · 2018-01-24T08:49:48Z

CI:

Linux
Linux-aarch64
macOS
Windows

wjwwood · 2018-01-24T19:03:31Z

Missed a change in rclcpp's tests, new CI:

Linux
Linux-aarch64
macOS
Windows

dhood · 2018-01-24T19:49:03Z

For posterity I'd like to mention an alternative that I wondered about but discarded. Rather than modifying the output handler signature to always include an rcutils timestamp (some handlers might want a different type of time to rcutils system time, or not care at all), the signature could instead be left as is and any output handlers interested in time would have to call now() themselves. The issue is that if multiple handlers are attached they might get called sequentially, in which case you want them to all have access to the time of the original call, not the time that the handler got called.

Similarly, handlers that use sim time, for example, will want the sim time of the original call as well, not when the handler was called. Since rcutils doesn't "know" about sim time, I imagine the sim timestamp would be passed to the log call in the 'context' dictionary that we have previously spoken about log calls including one day.

dhood

LGTM other than a small bug; could you add/extend a test to cover this? eg https://github.com/ros2/rcutils/pull/53/files#diff-4783eea3d9e98e3d3b03afdb62839106R36

dhood · 2018-01-24T21:37:29Z

src/logging.c

+    } else if (strcmp("seconds", token) == 0) {
+      if (snprintf(
+          numeric_storage, sizeof(numeric_storage),
+          "%f", timestamp / 1e9) == 0)


Think this should check for < 0

You're right, but maybe <= 0? If it returns zero then it means it wrote no bytes, which also seems like an issue.

I don't think I can test this case, since I get no feedback (other than output to stderr) when this occurs (there's no return code from the function).

I fixed the comparisons here: 7f1a17b

wjwwood · 2018-01-25T00:44:52Z

Rather than modifying the output handler signature to always include an rcutils timestamp (some handlers might want a different type of time to rcutils system time, or not care at all), the signature could instead be left as is and any output handlers interested in time would have to call now() themselves.

That's a good point, I sort of thought about that when I was deciding whether or not have a steady time stamp too. On the one hand you really want all timestamps to agree whether you log to file, console or rosout, so that would indicate take the timestamp at the time of the log call and pass it to the output handlers. On the other, someone might want, system time, steady time, or sim time. So this pr was sort of an incremental step between where we have system time and in the future we could add more timestamps or require the output handlers to get their own various timestamps themselves.

wjwwood · 2018-01-25T00:49:22Z

I'm happy to change this pr how ever you think would be best. I just opened it because I wanted to see how much time passed between logs.

I'll fix the failing tests (sort of fragile since they will break anytime the file has new lines added above a certain point, but unavoidable I think).

dhood · 2018-01-25T19:44:49Z

I agree that this is in the right direction. To me the contents of the PR are fine now, it's just the missing test coverage that I think should be addressed before merging

wjwwood · 2018-01-31T02:33:03Z

CI:

Linux
Linux-aarch64
macOS
Windows

dhood · 2018-01-31T16:57:36Z

The new output format tokens aren't currently tested: could you please add/extend a test to cover this? Here are the other ones that check formatting: https://github.com/ros2/rcutils/pull/53/files#diff-4783eea3d9e98e3d3b03afdb62839106R36

dirk-thomas · 2018-03-08T23:39:10Z

src/logging.c

+        goto cleanup;
+      }
+      token_expansion = numeric_storage;
+    } else if (strcmp("nanoseconds", token) == 0) {


I guess users might use {seconds}.{nanoseconds} but then get confused by the variable nature of digits of the nanoseconds part. I think an additional placeholder is desired / necessary which pads the output with leasing zeros to a fixed length of 9 digits.

I think you're confusing the purpose of {nanoseconds}, it's the total timestamp in nanoseconds, not the nanoseconds part of time. {seconds} is floating point time. So, {seconds}.{nanoseconds} doesn't really make any sense. See the documentation:

https://github.com/ros2/rcutils/pull/85/files#diff-f1d39d4e841937fde043a8e49b7e6c2aR62

Oh, got it now. Thanks for clarifying.

that was how I also first interpreted it (as sec.nanosec), so if it's happened to a few people maybe there's a way we can rename it to avoid confusion. We could just do time like in ROS 1 and additionally time_ns? Then you'd be less likely to think {time}.{time_ns}, but 'time' is not as descriptive as we'd like moving forward..

It's a fair point, however, that the padding is never considered. So on the floating point on the seconds may not be consistent from machine to machine. I'll see what I can do about that, as ideally it would be similar.

I'm actually writing the missing test right now, I so I'll think if a fixed padding makes sense in either case.

It doesn't need to be concise I don't think, we could use timestamp and timestamp_as_nanoseconds.

@dhood and I talked about it offline and we decided on time and time_as_nanoseconds, using time rather than timestamp to be closer to what ROS 1 does, and using _as_nanoseconds to be maximumly specific without worrying about verbosity too much because we expect it to not be used that much in favor of the floating point seconds version.

wjwwood · 2018-03-12T08:37:41Z

I factored out the conversion of the timepoints to public functions with tests. They now print fixed width, so for the nanoseconds always 20 characters (19 digits and either a - if negative or a leading if positive), and the seconds is always 21 characters (same as nanoseconds, but with a decimal point .).

I also fixed the logging tests, only the last test case was being checked due to a logical bug in the test. I also fixed a cmake style (though lint_cmake made me indent it weird) and prevented some "error being overwritten" messages in some of the tests. Those aren't really an issue, but it's nice to search for them in the CI output periodically and these were false positives.

dhood · 2018-03-16T00:31:47Z

include/rcutils/time.h

+ * The number is always fixed width, with left padding zeros up to the maximum
+ * number of digits the timepoint can represent.
+ * Right now that is 19 digits (so 19 characters) for a signed 64-bit integer.
+ * Positive timepoint values will have a leading space, whereas negative values


I understand that the motivation for this is so that positive and negative outputs are aligned, but isn't that only going to be necessary in like 0.1% of use cases? I think the small use case of swapping between negative and positive timestamps and wanting them to be aligned doesn't warrant the extraneous space for 99.9% of use cases (I might be missing something though). Having the default output be [ 123.456] is surprising to me.

I understand that the motivation for this is so that positive and negative outputs are aligned, but isn't that only going to be necessary in like 0.1% of use cases?

That's right, I had reservations about it too, but given I made these changes in the first place in order to try and keep a fixed width I was placing extreme value on never having a different string length. However, the case pointed out for floats (variable mantissa) is far more likely and the case I'm optimizing for here should honestly never happen (that's why I originally made the timepoint unsigned 😛).

I can change this.

+1 for having the default misaligned for positive/negative numbers, if the misalignment bothers someone they can add an option for it 😄 I know we pad in some cases in ros1 e.g. [ERROR] vs [ INFO] but those are much more likely.

dhood · 2018-03-16T00:32:42Z

include/rcutils/time.h

+ *
+ * \param[in] timepoint the time to be made into a string
+ * \param[out] str the output string in which it is stored
+ * \param[in] str_size the output string in which it is stored


this doc line is copypasta (and below)

you missed this comment @wjwwood

Oops, 94dcf14 😄

dhood · 2018-03-16T00:40:43Z

src/time.c

+  RCUTILS_CHECK_ARGUMENT_FOR_NULL(str, RCUTILS_RET_INVALID_ARGUMENT, allocator)
+  if (*timepoint >= 0) {
+    // have an explicit leading space to align with negative values which start with `-`
+    if (rcutils_snprintf(str, str_size, " %.19" PRId64, *timepoint) <= 0) {


If str_size was specified as 1, the snprintf's return value will be 0 from my understanding ("The number of characters that would have been written if n had been sufficiently large, not counting the terminating null character."). I don't think we should error in that case anymore. However, there's a test below for str_size=1 that expects RCUTILS_RET_OK, is that test passing?

All of the tests are passing (and running 😄) from what I can tell. As well as on Windows where the snprintf like functions some times behave slightly differently.

I think that it will return 21 or whatever it would have been, regardless of the value of str_size, rather than returning how many it actually wrote based on truncating due to str_size being smaller than the result.

ohhh, I see. it will successfully put (0 chars + NUL) but won't return 0. good good, this clears it up, thanks

dhood · 2018-03-16T00:42:34Z

test/test_logging_output_timestamps.regex

@@ -0,0 +1 @@
+'[\s,-][0-9]{10}[.][0-9]{9}' '[\s,-][0-9]{19}'\n'[\s,-][0-9]{10}[.][0-9]{9}' '[\s,-][0-9]{19}'


\s instead of will also match other whitespace characters which seems unnecessarily loose. Was there a reason for not just using a space?

Nope, I can change that and rerun the tests.

no need now I was mostly just curious if there was regex trickery going on

wjwwood · 2018-03-16T01:42:10Z

Ok, I rebased and addressed the comments, waiting for re-review before CI.

wjwwood · 2018-03-16T01:47:49Z

Also have to make a new rclcpp pr because I messed that up, and fix rclpy warnings, before CI.

dhood

lgtm!

dhood · 2018-03-16T01:53:19Z

src/time.c

  }
+  // if (*time_point >= 0) {


leftover 😄

wjwwood · 2018-03-16T02:10:21Z

New CI:

Linux
Linux-aarch64
macOS
Windows

I didn't see the rclpy stuff locally, and I think it might be resolved by the rebase.

dirk-thomas

The PR mixes two different things:

adding a timestamp to the log event
various unrelated test changes / improvements

It would be good to have these changes in two separate commits for easier review as well as after the merge as separate commits for history.

dirk-thomas · 2018-03-17T00:36:51Z

include/rcutils/time.h

+ * Negative values will have a leading `-`, so they will be one character
+ * longer than the positive values.
+ *
+ * The recommended minimum size of the input string is 32 characters, but


How is this "recommended minimum size" relevant in the docblock? Isn't is sufficient to document the exact max size necessary? Also why 32?

Same below.

Because the usable block size on my machine is 16 bytes, and 32 is the smallest multiple of that in which the exact size of this string fits. Also, it gives us a little flexibility for the future, e.g. if we wanted to add + to the front of the time to distinguish it from -. Not saying we will, but if when you ask for 21 characters malloc gives you 32 anyways...

This is the program I used to check:

#include <cassert> #include <cstdio> #if __linux__ #include <malloc.h> #else #include <malloc/malloc.h> #endif int main() { uint8_t * bytes = (uint8_t *)malloc(1); assert(bytes); #if __linux__ printf("%zu\n", malloc_usable_size(bytes)); #else printf("%zu\n", malloc_size(bytes)); #endif return 0; }

I didn't try it on Windows.

dhood · 2018-03-20T15:53:51Z

there are failing windows tests in case you didn't notice @wjwwood

dhood · 2018-06-16T01:35:58Z

@wjwwood I rebased and addressed the two comments if you want to take a look at those commits at some point

Linux
Linux-aarch64
macOS
Windows

wjwwood · 2018-06-16T01:54:57Z

Changes lgtm, thanks @dhood!

wjwwood · 2018-06-17T05:04:48Z

Thanks for pushing this through @dhood!

dhood · 2018-06-18T04:34:17Z

nooo problem!

dhood · 2018-06-18T20:42:42Z

Wiki updates:
added to logger config demo
logger page references rcutils docs which will include this change in the bouncy release

wjwwood added enhancement New feature or request in review Waiting for review (Kanban column) labels Jan 24, 2018

wjwwood self-assigned this Jan 24, 2018

wjwwood requested a review from dhood January 24, 2018 08:49

wjwwood mentioned this pull request Jan 24, 2018

changes to console logging output handler signature ros2/rclcpp#434

Closed

dhood reviewed Jan 24, 2018

View reviewed changes

mikaelarguedas added in progress Actively being worked on (Kanban column) and removed in review Waiting for review (Kanban column) labels Feb 1, 2018

dirk-thomas reviewed Mar 8, 2018

View reviewed changes

wjwwood requested a review from dhood March 12, 2018 08:02

wjwwood added in review Waiting for review (Kanban column) and removed in progress Actively being worked on (Kanban column) labels Mar 12, 2018

dhood reviewed Mar 16, 2018

View reviewed changes

wjwwood force-pushed the timestamp_console_logging branch from dcff0da to 4c53fff Compare March 16, 2018 01:41

dhood previously approved these changes Mar 16, 2018

View reviewed changes

src/time.c Outdated

}

// if (*time_point >= 0) {

Copy link

Member

dhood Mar 16, 2018

Choose a reason for hiding this comment

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

leftover 😄

wjwwood reacted with thumbs up emoji

wjwwood mentioned this pull request Mar 16, 2018

fix tests due to changes in rcutils ros2/rclcpp#452

Merged

dirk-thomas reviewed Mar 17, 2018

View reviewed changes

wjwwood and others added 19 commits June 15, 2018 18:09

add functions to convert timepoints to strings

3befa26

use time and time_as_nanoseconds, add tests

60dea7e

fix usage of error handling in test

c02b1ce

support negative values

bcd5ae6

remove leading whitespace on positive numbers

1d493ae

fix mistake in rebasing

c3faf84

update name of environment dict

ae99b76

remove comment

89fa168

comment touch up

9d71d47

fix rcutils_snprintf to actually be a proper portable snprintf

d55422c

fix test_time and address Windows warnings

f195600

Update cppreference link to be to snprintf not vsnprintf

54db6d0

add rcutils_strncpy() helper

8e74505

use memmove rather than strncpy

85127ef

fix error handling and behavior in snprintf

63552df

fixup

ccdb391

missing word from docblocks

ba0b209

doc fixup

3250da5

Fixups from rebase

5404867

dhood force-pushed the timestamp_console_logging branch from f2256f7 to 5404867 Compare June 16, 2018 01:20

dhood added 2 commits June 15, 2018 18:27

Add test for (nullptr,0,..) case

4f9c69e

Update memmove to not use min

342a853

dhood merged commit 2f4efff into master Jun 16, 2018

dhood removed the in progress Actively being worked on (Kanban column) label Jun 16, 2018

dhood deleted the timestamp_console_logging branch June 16, 2018 20:29

		@@ -0,0 +1 @@
		'[\s,-][0-9]{10}[.][0-9]{9}' '[\s,-][0-9]{19}'\n'[\s,-][0-9]{10}[.][0-9]{9}' '[\s,-][0-9]{19}'

take a timestamp when a console logging message happens #85

take a timestamp when a console logging message happens #85

Conversation

wjwwood commented Jan 24, 2018

wjwwood commented Jan 24, 2018

wjwwood commented Jan 24, 2018

dhood commented Jan 24, 2018

dhood 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

wjwwood commented Jan 25, 2018

wjwwood commented Jan 25, 2018

dhood commented Jan 25, 2018

wjwwood commented Jan 31, 2018 • edited Loading

dhood commented Jan 31, 2018

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 Mar 12, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dhood Mar 16, 2018 • 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

wjwwood commented Mar 16, 2018

wjwwood commented Mar 16, 2018

dhood left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

wjwwood commented Mar 16, 2018

dirk-thomas left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dhood commented Mar 20, 2018

dhood commented Jun 16, 2018

wjwwood commented Jun 16, 2018

wjwwood commented Jun 17, 2018

dhood commented Jun 18, 2018

dhood commented Jun 18, 2018

wjwwood commented Jan 31, 2018 •

edited

Loading

dhood Mar 16, 2018 •

edited

Loading