Timestamps in log messages

Does anyone have an example of including timestamps in log messages when using std.log, or any recommendations on the best way to achieve this?

That sounds like something that would make sense to have as a built-in option in the stdlib.

Aside from that, I guess the best way today is to copy the default handler implementation in std.log and to add in there the timestamp in your preferred format. If you define a log function in your root file you can override the default behavior. The comments are really clear about how to do that.

zig-datetime can help you manipolate the date

zig-tzif can help you get the local time on the machine (surprisingly annoying to do otherwise)

leroycep is also working on another datetime lib but afaik is still WIP

Thanks for the detailed reply :slight_smile:

I’ve gone for a basic reimplementation of the log() function as you suggested, where I’m actually logging time since startup rather than a full timestamp (this is a crude method of identifying bottlenecks in the code!):

var start_milli_time: u64 = 0;

pub const log_level = .info;

pub fn log(
    comptime message_level: std.log.Level,
    comptime scope: @Type(.EnumLiteral),
    comptime format: []const u8,
    args: anytype,
) void {
    if (@enumToInt(message_level) <= @enumToInt(std.log.level)) {
        const milli_time = @intCast(u64, std.time.milliTimestamp()) - start_milli_time;
        const level_txt = switch (message_level) {
            // zig fmt: off
            .emerg  => "EMERG",
            .alert  => "ALERT",
            .crit   => " CRIT",
            .err    => "ERROR",
            .warn   => " WARN",
            .notice => " NOTE",
            .info   => " INFO",
            .debug  => "DEBUG",
            // zig fmt: on
        };
        const prefix2 = if (scope == .default) ": " else "(" ++ @tagName(scope) ++ "): ";
        const held = std.debug.getStderrMutex().acquire();
        defer held.release();
        nosuspend stderr.print("{d:>2}.{d:0>3} ", .{ milli_time / 1000, milli_time % 1000 }) catch return;
        nosuspend stderr.print("[" ++ level_txt ++ "]" ++ prefix2 ++ format ++ "\n", args) catch return;
    }
}

pub fn main() !u8 {
    start_milli_time = @intCast(u64, std.time.milliTimestamp());
    ...
    std.log.info("Finished", .{});
    return 0;
}

Output:

$./zig-out/bin/zig-main <args>
 0.060 [ WARN]: Omitting large full matrix output
 0.070 [ WARN]: Omitting large RREF matrix output
 0.070 [ INFO]: Initialising solver with 30 x 16 board
 0.120 [ INFO]: Initial matrix is 388 x 75
 0.178 [ INFO]: Reduced matrix to groups, 52 columns
 0.178 [ INFO]: Reduced matrix to RREF
 0.178 [ INFO]: Removed zero-rows from matrix, 42 rows
 0.186 [ INFO]: Using free val maximums: { 2, 2, 2, 2, 1, 2, 1, 2, 0 } (2916 combinations)
 1.128 [ INFO]: Found 60 mine configurations
 1.165 [ INFO]: Finished

It might be nice to have a way to customise the log format without having to override the full log() function, although I’m not sure quite what that would look like, and this will do for me.

Nice!

It’s though to find a good balance when it comes to the standard library. From my perspective a good choice would be to have a “log-goodies” 3rd party package that implements all the common use cases.