Add milliseconds to logging output#380
Conversation
There was a problem hiding this comment.
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.
| 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); | ||
|
|
There was a problem hiding this comment.
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.
| 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"); | |
| } |
There was a problem hiding this comment.
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.
1d899e1 to
9dd23bc
Compare
|
Since |
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.