diff --git a/src/log.zig b/src/log.zig new file mode 100644 index 00000000..360e17ec --- /dev/null +++ b/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, "\" (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); +} diff --git a/src/unit_tests.zig b/src/unit_tests.zig index 94c10913..b4dd9d05 100644 --- a/src/unit_tests.zig +++ b/src/unit_tests.zig @@ -377,4 +377,5 @@ test { std.testing.refAllDecls(@import("storage/storage.zig")); std.testing.refAllDecls(@import("iterator/iterator.zig")); std.testing.refAllDecls(@import("server.zig")); + std.testing.refAllDecls(@import("log.zig")); }