Skip to content

Add milliseconds to logging output #380

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
matteius merged 1 commit into from
Apr 13, 2026
+15 −39
Merged

Add milliseconds to logging output #380

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
54 changes: 15 additions & 39 deletions src/core/logger.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -373,59 +373,32 @@ static void build_ctx_prefix(char *buf, size_t bufsz,
static void do_log_internal(log_level_t level,
const char *component, const char *stream,
const char *format, va_list args) {
// Copy va_list: a va_list may only be traversed once; copying satisfies
// static-analysis tools (clang-analyzer-valist.Uninitialized).
va_list args_copy;
va_copy(args_copy, args);

// CRITICAL: Check if logger is shutting down or destroyed.
// Write directly to console without the mutex to avoid use-after-destroy.
if (logger.shutdown) {
char message[4096];
vsnprintf(message, sizeof(message), format, args_copy); // NOLINT(clang-analyzer-valist.Uninitialized)
va_end(args_copy);

time_t now;
struct tm tm_buf;
char timestamp[32];
time(&now);
strftime(timestamp, sizeof(timestamp), "%Y-%m-%d %H:%M:%S",
localtime_r(&now, &tm_buf));

char ctx_prefix[224] = {0};
build_ctx_prefix(ctx_prefix, sizeof(ctx_prefix), component, stream);

FILE *console = (level == LOG_LEVEL_ERROR) ? stderr : stdout;
fprintf(console, "[%s] [%s] %s%s\n",
timestamp, log_level_strings[level], ctx_prefix, message);
fflush(console);
return;
}

// Only log messages at or below the configured log level.
if (level > logger.log_level) {
va_end(args_copy);
return;
}

time_t now;
// Create timestamp
struct timespec now;
clock_gettime(CLOCK_REALTIME, &now);

struct tm tm_buf;
localtime_r(&now.tv_sec, &tm_buf);

char timestamp[32];
char iso_timestamp[32];
size_t offset = strftime(timestamp, sizeof(timestamp), "%Y-%m-%d %H:%M:%S", &tm_buf);

time(&now);
localtime_r(&now, &tm_buf);
strftime(timestamp, sizeof(timestamp), "%Y-%m-%d %H:%M:%S", &tm_buf);
strftime(iso_timestamp, sizeof(iso_timestamp), "%Y-%m-%dT%H:%M:%S", &tm_buf);
unsigned int msec = (unsigned int)(now.tv_nsec / 1000000UL);
snprintf(timestamp + offset, sizeof(timestamp) - offset, ".%03u", msec);

Comment on lines +383 to +393
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

@dpw13 dpw13 Apr 13, 2026

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.

char message[4096];
vsnprintf(message, sizeof(message), format, args_copy); // NOLINT(clang-analyzer-valist.Uninitialized)
va_end(args_copy);
vsnprintf(message, sizeof(message), format, args);

char ctx_prefix[224] = {0};
build_ctx_prefix(ctx_prefix, sizeof(ctx_prefix), component, stream);

// Double-check shutdown before acquiring mutex.
// CRITICAL: Check if logger is shutting down or destroyed.
// Write directly to console without the mutex to avoid use-after-destroy.
if (logger.shutdown) {
FILE *console = (level == LOG_LEVEL_ERROR) ? stderr : stdout;
fprintf(console, "[%s] [%s] %s%s\n",
Expand Down Expand Up @@ -462,6 +435,9 @@ static void do_log_internal(log_level_t level,
pthread_mutex_unlock(&logger.mutex);

if (write_json_log) {
char iso_timestamp[32];

strftime(iso_timestamp, sizeof(iso_timestamp), "%Y-%m-%dT%H:%M:%S", &tm_buf);
write_json_log(level, iso_timestamp, message);
}
}
Expand Down
Loading