Merge pull request #443 from karlseguin/logging

Add a structured logger

src/log.zig

@@ -0,0 +1,377 @@
+const std = @import("std");
+const builtin = @import("builtin");
+
+const Allocator = std.mem.Allocator;
+
+// synchronizes writes to the output
+// in debug mode, also synchronizes the timestamp counter for a more human-
+// readable time display
+var mutex: std.Thread.Mutex = .{};
+
+const LogLevel: Log.Level = blk: {
+    const root = @import("root");
+    break :blk if (@hasDecl(root, "LogLevel")) root.LogLevel else .info;
+};
+
+pub const Log = LogT(std.fs.File, builtin.mode == .Debug);
+
+// Generic so that we can test it against an ArrayList
+fn LogT(comptime Out: type, comptime enhanced_readability: bool) type {
+    return struct {
+        out: Out,
+        inject: ?[]const u8,
+        allocator: Allocator,
+        buffer: std.ArrayListUnmanaged(u8),
+
+        const Self = @This();
+
+        pub const Level = enum {
+            debug,
+            info,
+            warn,
+            @"error",
+            fatal,
+        };
+
+        //
+        pub fn init(allocator: Allocator) !Self {
+            return initTo(allocator, std.io.getStdErr());
+        }
+
+        // Used for tests
+        fn initTo(allocator: Allocator, out: Out) !Self {
+            var buffer: std.ArrayListUnmanaged(u8) = .{};
+            try buffer.ensureTotalCapacity(allocator, 2048);
+
+            return .{
+                .out = out,
+                .inject = null,
+                .buffer = buffer,
+                .allocator = allocator,
+            };
+        }
+
+        pub fn deinit(self: *Self) void {
+            self.buffer.deinit(self.allocator);
+        }
+
+        pub fn enabled(comptime level: Level) bool {
+            return @intFromEnum(level) >= @intFromEnum(LogLevel);
+        }
+
+        pub fn debug(self: *Self, comptime msg: []const u8, data: anytype) void {
+            self.log(.debug, msg, data);
+        }
+
+        pub fn info(self: *Self, comptime msg: []const u8, data: anytype) void {
+            self.log(.info, msg, data);
+        }
+
+        pub fn warn(self: *Self, comptime msg: []const u8, data: anytype) void {
+            self.log(.warn, msg, data);
+        }
+
+        pub fn err(self: *Self, comptime msg: []const u8, data: anytype) void {
+            self.log(.@"error", msg, data);
+        }
+
+        pub fn fatal(self: *Self, comptime msg: []const u8, data: anytype) void {
+            self.log(.fatal, msg, data);
+        }
+
+        fn log(self: *Self, comptime level: Level, comptime msg: []const u8, data: anytype) void {
+            if (comptime enabled(level) == false) {
+                return;
+            }
+            defer self.buffer.clearRetainingCapacity();
+            self._log(level, msg, data) catch |e| {
+                std.debug.print("log error: {}  ({s} - {s})\n", .{ e, @tagName(level), msg });
+            };
+        }
+
+        fn _log(self: *Self, comptime level: Level, comptime msg: []const u8, data: anytype) !void {
+            const allocator = self.allocator;
+
+            // We use *AssumeCapacity here because we expect buffer to have
+            // a reasonable default size. We expect time + level + msg + inject
+            // to fit in the initial buffer;
+            var buffer = &self.buffer;
+
+            comptime {
+                if (msg.len > 512) {
+                    @compileError("log msg cannot be greater than 512 characters: '" ++ msg ++ "'");
+                }
+                for (msg) |b| {
+                    switch (b) {
+                        'A'...'Z', 'a'...'z', ' ', '0'...'9', '_', '-', '.', '{', '}' => {},
+                        else => @compileError("log msg contains an invalid character '" ++ msg ++ "'"),
+                    }
+                }
+            }
+
+            std.debug.assert(buffer.capacity >= 1024);
+
+            if (comptime enhanced_readability) {
+                // used when developing, and we prefer readability over having
+                // the output in logfmt
+
+                // write the level this way so that the column lines up.
+                switch (level) {
+                    .info => buffer.appendSliceAssumeCapacity("info  | "),
+                    .debug => buffer.appendSliceAssumeCapacity("debug | "),
+                    .warn => buffer.appendSliceAssumeCapacity("\x1b[33m warn\x1b[0m  | "),
+                    .@"error" => buffer.appendSliceAssumeCapacity("\x1b[31m error\x1b[0m | "),
+                    .fatal => buffer.appendSliceAssumeCapacity("\x1b[41m fatal\x1b[0m | "),
+                }
+
+                buffer.appendSliceAssumeCapacity(msg ++ " | ");
+                const since_last_log = msSinceLastLog();
+
+                if (since_last_log > 1000) {
+                    buffer.appendSliceAssumeCapacity("\x1b[35m");
+                }
+                try std.fmt.format(buffer.writer(allocator), "{d}\x1b[0m |", .{since_last_log});
+            } else {
+                buffer.appendSliceAssumeCapacity("_time=");
+                try std.fmt.format(buffer.writer(allocator), "{d}", .{getTime()});
+
+                const level_and_msg = comptime blk: {
+                    // only wrap msg in quotes if it contains a space
+                    const lm = " _level=" ++ @tagName(level) ++ " _msg=";
+                    if (std.mem.indexOfScalar(u8, msg, ' ') == null) {
+                        break :blk lm ++ msg;
+                    }
+                    break :blk lm ++ "\"" ++ msg ++ "\"";
+                };
+                buffer.appendSliceAssumeCapacity(level_and_msg);
+            }
+
+            if (self.inject) |inject| {
+                buffer.appendAssumeCapacity(' ');
+                buffer.appendSliceAssumeCapacity(inject);
+            }
+
+            inline for (@typeInfo(@TypeOf(data)).Struct.fields) |f| {
+                // + 2 for the leading space and the equal sign
+                // + 5 to save space for null/false/true common values
+                const key_len = f.name.len + 7;
+                try buffer.ensureUnusedCapacity(allocator, key_len);
+                buffer.appendAssumeCapacity(' ');
+                buffer.appendSliceAssumeCapacity(f.name);
+                buffer.appendAssumeCapacity('=');
+                try writeValue(allocator, buffer, @field(data, f.name));
+            }
+
+            if (comptime enhanced_readability) {
+                // reset any color
+                try buffer.appendSlice(allocator, "\x1b[0m");
+            }
+
+            try buffer.append(allocator, '\n');
+
+            mutex.lock();
+            defer mutex.unlock();
+            try self.out.writeAll(self.buffer.items);
+        }
+    };
+}
+
+fn writeValue(allocator: Allocator, buffer: *std.ArrayListUnmanaged(u8), value: anytype) !void {
+    const T = @TypeOf(value);
+    switch (@typeInfo(T)) {
+        .Optional => {
+            if (value) |v| {
+                return writeValue(allocator, buffer, v);
+            }
+            // in _log, we reserved space for a value of up to 5 bytes.
+            return buffer.appendSliceAssumeCapacity("null");
+        },
+        .ComptimeInt, .Int, .ComptimeFloat, .Float => {
+            return std.fmt.format(buffer.writer(allocator), "{d}", .{value});
+        },
+        .Bool => {
+            // in _log, we reserved space for a value of up to 5 bytes.
+            return buffer.appendSliceAssumeCapacity(if (value) "true" else "false");
+        },
+        .ErrorSet => return buffer.appendSlice(allocator, @errorName(value)),
+        .Enum => return buffer.appendSlice(allocator, @tagName(value)),
+        .Array => return writeValue(allocator, buffer, &value),
+        .Pointer => |ptr| switch (ptr.size) {
+            .Slice => switch (ptr.child) {
+                u8 => return writeString(allocator, buffer, value),
+                else => {},
+            },
+            .One => switch (@typeInfo(ptr.child)) {
+                .Array => |arr| if (arr.child == u8) {
+                    return writeString(allocator, buffer, value);
+                },
+                else => return false,
+            },
+            else => {},
+        },
+        else => {},
+    }
+    @compileError("cannot log a: " ++ @typeName(T));
+}
+
+fn writeString(allocator: Allocator, buffer: *std.ArrayListUnmanaged(u8), value: []const u8) !void {
+    var space_count: usize = 0;
+    var escape_count: usize = 0;
+    var binary_count: usize = 0;
+
+    for (value) |b| {
+        switch (b) {
+            '\r', '\n', '"' => escape_count += 1,
+            ' ' => space_count += 1,
+            '\t', '!', '#'...'~' => {}, // printable characters
+            else => binary_count += 1,
+        }
+    }
+
+    if (binary_count > 0) {
+        // TODO: use a different encoding if the ratio of binary data / printable
+        // is low
+        // TODO: Zig 0.14 adds an encodeWriter
+        return buffer.appendSlice(allocator, "\"<binary data> (will be supported once we move to Zig 0.14\"");
+        // return std.base64.standard_no_pad.Encoder.encodeWriter(buffer.writer(allocator), value);
+    }
+
+    if (escape_count == 0) {
+        if (space_count == 0) {
+            return buffer.appendSlice(allocator, value);
+        }
+        try buffer.ensureUnusedCapacity(allocator, 2 + value.len);
+        buffer.appendAssumeCapacity('"');
+        buffer.appendSliceAssumeCapacity(value);
+        buffer.appendAssumeCapacity('"');
+        return;
+    }
+
+    // + 2 for the quotes
+    // + escape_count because every character that needs escaping is + 1
+    try buffer.ensureUnusedCapacity(allocator, 2 + value.len + escape_count);
+
+    buffer.appendAssumeCapacity('"');
+
+    var rest = value;
+    while (rest.len > 0) {
+        const pos = std.mem.indexOfAny(u8, rest, "\r\n\"") orelse {
+            buffer.appendSliceAssumeCapacity(rest);
+            break;
+        };
+        buffer.appendSliceAssumeCapacity(rest[0..pos]);
+        buffer.appendAssumeCapacity('\\');
+        switch (rest[pos]) {
+            '"' => buffer.appendAssumeCapacity('"'),
+            '\r' => buffer.appendAssumeCapacity('r'),
+            '\n' => buffer.appendAssumeCapacity('n'),
+            else => unreachable,
+        }
+        rest = rest[pos + 1 ..];
+    }
+
+    buffer.appendAssumeCapacity('"');
+}
+
+fn getTime() i64 {
+    if (comptime @import("builtin").is_test) {
+        return 1739795092929;
+    }
+    return std.time.milliTimestamp();
+}
+
+var last_log_for_debug: i64 = 0;
+fn msSinceLastLog() i64 {
+    if (comptime builtin.mode != .Debug) {
+        @compileError("Log's enhanced_readability is not safe to use in non-Debug mode");
+    }
+    const now = getTime();
+
+    mutex.lock();
+    defer mutex.unlock();
+    defer last_log_for_debug = now;
+    if (last_log_for_debug == 0) {
+        return 0;
+    }
+    return now - last_log_for_debug;
+}
+
+const testing = std.testing;
+const TestLogger = LogT(std.ArrayListUnmanaged(u8).Writer, false);
+
+test "log: data" {
+    var buf: std.ArrayListUnmanaged(u8) = .{};
+    defer buf.deinit(testing.allocator);
+
+    var log = try TestLogger.initTo(testing.allocator, buf.writer(testing.allocator));
+    defer log.deinit();
+
+    {
+        log.err("nope", .{});
+        try testing.expectEqualStrings("_time=1739795092929 _level=error _msg=nope\n", buf.items);
+    }
+
+    {
+        buf.clearRetainingCapacity();
+        const string = try testing.allocator.dupe(u8, "spice_must_flow");
+        defer testing.allocator.free(string);
+
+        log.warn("a msg", .{
+            .cint = 5,
+            .cfloat = 3.43,
+            .int = @as(i16, -49),
+            .float = @as(f32, 0.0003232),
+            .bt = true,
+            .bf = false,
+            .nn = @as(?i32, 33),
+            .n = @as(?i32, null),
+            .lit = "over9000!",
+            .slice = string,
+            .err = error.Nope,
+            .level = Log.Level.warn,
+        });
+
+        try testing.expectEqualStrings("_time=1739795092929 _level=warn _msg=\"a msg\" " ++
+            "cint=5 cfloat=3.43 int=-49 float=0.0003232 bt=true bf=false " ++
+            "nn=33 n=null lit=over9000! slice=spice_must_flow " ++
+            "err=Nope level=warn\n", buf.items);
+    }
+}
+
+test "log: string escape" {
+    var buf: std.ArrayListUnmanaged(u8) = .{};
+    defer buf.deinit(testing.allocator);
+
+    var log = try TestLogger.initTo(testing.allocator, buf.writer(testing.allocator));
+    defer log.deinit();
+
+    const prefix = "_time=1739795092929 _level=error _msg=test ";
+    {
+        log.err("test", .{ .string = "hello world" });
+        try testing.expectEqualStrings(prefix ++ "string=\"hello world\"\n", buf.items);
+    }
+
+    {
+        buf.clearRetainingCapacity();
+        log.err("test", .{ .string = "\n \thi  \" \" " });
+        try testing.expectEqualStrings(prefix ++ "string=\"\\n \thi  \\\" \\\" \"\n", buf.items);
+    }
+
+    // TODO: Zig 0.14
+    // {
+    //     log.err("test", .{.string = [_]u8{0, 244, 55, 77}});
+    //     try testing.expectEqualStrings(prefix ++ "string=\"\\n \\thi  \\\" \\\" \"\n", buf.items);
+    // }
+}
+
+test "log: with inject" {
+    var buf: std.ArrayListUnmanaged(u8) = .{};
+    defer buf.deinit(testing.allocator);
+
+    var log = try TestLogger.initTo(testing.allocator, buf.writer(testing.allocator));
+    defer log.deinit();
+
+    log.inject = "conn_id=339494";
+    log.fatal("hit", .{ .over = 9000 });
+    try testing.expectEqualStrings("_time=1739795092929 _level=fatal _msg=hit conn_id=339494 over=9000\n", buf.items);
+}

src/unit_tests.zig

@@ -381,4 +381,5 @@ test {
     std.testing.refAllDecls(@import("iterator/iterator.zig"));
     std.testing.refAllDecls(@import("server.zig"));
     std.testing.refAllDecls(@import("cdp/cdp.zig"));
+    std.testing.refAllDecls(@import("log.zig"));
 }