Skip to content

Add milliseconds to logging output#380

Merged
matteius merged 1 commit intoopensensor:mainfrom
dpw13:feat/logging-msec
Apr 13, 2026
Merged

Add milliseconds to logging output#380
matteius merged 1 commit intoopensensor:mainfrom
dpw13:feat/logging-msec

Conversation

@dpw13
Copy link
Copy Markdown
Contributor

@dpw13 dpw13 commented Apr 13, 2026

I'm debugging some shutdown timing issues, and having access to milliseconds in the log is extremely helpful to identify how much time things are taking. I'm currently only printing milliseconds and not microseconds to minimize the impact on log line length.

Note that I'm not adding the milliseconds to the JSON log. I'm not sure what that's used for and it didn't seem terribly worth it to change, but I can keep them consistent if desired.

Copy link
Copy Markdown
Contributor

Copilot AI left a comment

Choose a reason for hiding this comment

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

Pull request overview

This PR enhances the human-readable (console/file) logger timestamp precision by adding millisecond resolution to help debug shutdown timing behavior, while keeping the JSON log timestamp format unchanged.

Changes:

  • Switches timestamp acquisition to clock_gettime(CLOCK_REALTIME, ...) and appends .<mmm> to the formatted timestamp used in text logs.
  • Refactors timestamp creation to be shared across the shutdown fast-path and normal logging path.
  • Keeps JSON log timestamps at second-level precision (ISO-like format).

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comment on lines +383 to +392
clock_gettime(CLOCK_REALTIME, &now);

struct tm tm_buf;
char timestamp[32];
strftime(timestamp, sizeof(timestamp), "%Y-%m-%d %H:%M:%S",
localtime_r(&now.tv_sec, &tm_buf));
unsigned int msec = (unsigned int)(now.tv_nsec / 1000000UL);
size_t offset = strlen(timestamp);
snprintf(timestamp + offset, sizeof(timestamp) - offset, ".%03u", msec);

Copy link

Copilot AI Apr 13, 2026

Choose a reason for hiding this comment

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

localtime_r() can return NULL; passing its return value directly into strftime() will dereference a NULL pointer and crash. Also, if strftime() returns 0 (buffer too small), the contents of timestamp are indeterminate and may not be NUL-terminated, so strlen(timestamp) can read out of bounds. Split this into separate calls: check clock_gettime/localtime_r/strftime return values, and use the strftime return value as the offset (or fall back to a safe placeholder string) before appending milliseconds.

Suggested change
clock_gettime(CLOCK_REALTIME, &now);
struct tm tm_buf;
char timestamp[32];
strftime(timestamp, sizeof(timestamp), "%Y-%m-%d %H:%M:%S",
localtime_r(&now.tv_sec, &tm_buf));
unsigned int msec = (unsigned int)(now.tv_nsec / 1000000UL);
size_t offset = strlen(timestamp);
snprintf(timestamp + offset, sizeof(timestamp) - offset, ".%03u", msec);
struct tm tm_buf;
char timestamp[32];
size_t offset = 0;
unsigned int msec = 0;
if (clock_gettime(CLOCK_REALTIME, &now) == 0 &&
localtime_r(&now.tv_sec, &tm_buf) != NULL) {
offset = strftime(timestamp, sizeof(timestamp), "%Y-%m-%d %H:%M:%S", &tm_buf);
if (offset > 0) {
msec = (unsigned int)(now.tv_nsec / 1000000UL);
snprintf(timestamp + offset, sizeof(timestamp) - offset, ".%03u", msec);
} else {
snprintf(timestamp, sizeof(timestamp), "1970-01-01 00:00:00.000");
}
} else {
snprintf(timestamp, sizeof(timestamp), "1970-01-01 00:00:00.000");
}

Copilot uses AI. Check for mistakes.
Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

We can statically confirm that the buffer for strftime is big enough for this format string, but I'm definitely using the return of strftime instead of calling strlen.

@dpw13 dpw13 force-pushed the feat/logging-msec branch from 1d899e1 to 9dd23bc Compare April 13, 2026 17:30
@dpw13
Copy link
Copy Markdown
Contributor Author

dpw13 commented Apr 13, 2026

Since args now only gets used once to format the message, I've entirely removed the va_copy and associated linter exceptions. The linter that raised these concerns may need to be re-run.

@matteius matteius merged commit de4f0c7 into opensensor:main Apr 13, 2026
1 check passed
@dpw13 dpw13 deleted the feat/logging-msec branch April 13, 2026 21:05
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.

3 participants