also looking at this
feat(log): --log-file, and a logger that survives being used
#78
5 files
+691
-37
| @@ -37,17 +37,65 @@ pub const LogConfig = struct { | ||
| 37 | 37 | enable_timestamps: bool = true, |
| 38 | 38 | output_file: ?[]const u8 = null, |
| 39 | 39 | json_output: bool = false, |
| 40 | /// Also write every record to stderr. | |
| 41 | /// | |
| 42 | /// On by default, which is what this logger has always done. A caller that | |
| 43 | /// wants a file and a quiet terminal — a packaged app, a headless run — | |
| 44 | /// had no way to ask, because the stderr write was unconditional. | |
| 45 | mirror_to_stderr: bool = true, | |
| 40 | 46 | filter_pattern: ?[]const u8 = null, |
| 41 | 47 | }; |
| 42 | 48 | |
| 43 | 49 | var current_config: LogConfig = .{}; |
| 44 | 50 | var log_file: ?std.Io.File = null; |
| 51 | ||
| 52 | /// Where the next record goes. | |
| 53 | /// | |
| 54 | /// `Io.Dir.CreateFileOptions` has no append flag in this Zig, and | |
| 55 | /// `writeStreamingAll` starts at position zero — so an existing log was | |
| 56 | /// overwritten from the beginning on every run, leaving whatever was longer | |
| 57 | /// than the new content stranded past the end as garbage. Seeded from the | |
| 58 | /// file's size at open and advanced by every write, with `writePositionalAll`, | |
| 59 | /// which is how appending is spelled here. | |
| 60 | var log_file_offset: u64 = 0; | |
| 61 | ||
| 62 | /// Storage for the configuration's strings. | |
| 63 | /// | |
| 64 | /// `LogConfig` carries `output_file` and `filter_pattern` as slices, and | |
| 65 | /// `init` used to keep the caller's. The path arrives from the command line | |
| 66 | /// and `minimal.zig` frees those strings during startup, so retaining them | |
| 67 | /// would leave this module reading freed memory on the first log call after | |
| 68 | /// argument parsing finished — a use-after-free that arrives only once | |
| 69 | /// something actually configures the logger, which nothing did until now. | |
| 70 | var output_file_storage: [std.fs.max_path_bytes]u8 = undefined; | |
| 71 | var filter_storage: [256]u8 = undefined; | |
| 45 | 72 | /// Guards `current_config`, `log_file`, and the final write to stderr+file |
| 46 | 73 | /// so concurrent loggers don't interleave bytes or race on config updates. |
| 47 | 74 | /// The previous module-level `var`s were read/written from every call site |
| 48 | 75 | /// without any synchronization. |
| 49 | 76 | var log_mutex: compat_mutex.Mutex = .{}; |
| 50 | 77 | |
| 78 | /// True while this thread is inside `log`. | |
| 79 | /// | |
| 80 | /// `compat_mutex` falls back to a spinlock when `std.Thread.Mutex` is absent, | |
| 81 | /// and it is absent in this Zig — so the lock is non-recursive and never | |
| 82 | /// yields. A `std.log` call made from inside `log` would spin against a lock | |
| 83 | /// this thread already holds, forever: a hard hang with no panic and no | |
| 84 | /// stack. That was unreachable while nothing configured the logger, and | |
| 85 | /// routing every `std.log` site through it is exactly what makes it reachable. | |
| 86 | /// | |
| 87 | /// Dropping the inner record is the right trade. The alternative is a process | |
| 88 | /// that stops responding because something logged while logging. | |
| 89 | threadlocal var in_log: bool = false; | |
| 90 | ||
| 91 | /// The `Io` to write through, captured at `init`. | |
| 92 | /// | |
| 93 | /// `io_context.get()` takes `global_state`'s own non-recursive spinlock, and | |
| 94 | /// `log` used to call it while holding `log_mutex` — two spinlocks nested in a | |
| 95 | /// fixed order, and a lazy `std.Io.Threaded` construction on the C allocator | |
| 96 | /// reachable from inside a log call. Captured once instead. | |
| 97 | var log_io: ?std.Io = null; | |
| 98 | ||
| 51 | 99 | pub fn init(config: LogConfig) !void { |
| 52 | 100 | log_mutex.lock(); |
| 53 | 101 | defer log_mutex.unlock(); |
| @@ -60,12 +108,35 @@ pub fn init(config: LogConfig) !void { | ||
| 60 | 108 | } |
| 61 | 109 | |
| 62 | 110 | current_config = config; |
| 111 | log_file_offset = 0; | |
| 112 | log_io = io_context.get(); | |
| 63 | 113 | |
| 114 | // Take copies before anything else can free the originals. | |
| 64 | 115 | if (config.output_file) |path| { |
| 65 | log_file = try std.Io.Dir.cwd().createFile(io_context.get(), path, .{ | |
| 116 | if (path.len > output_file_storage.len) return error.NameTooLong; | |
| 117 | @memcpy(output_file_storage[0..path.len], path); | |
| 118 | current_config.output_file = output_file_storage[0..path.len]; | |
| 119 | } | |
| 120 | if (config.filter_pattern) |pattern| { | |
| 121 | if (pattern.len > filter_storage.len) return error.NameTooLong; | |
| 122 | @memcpy(filter_storage[0..pattern.len], pattern); | |
| 123 | current_config.filter_pattern = filter_storage[0..pattern.len]; | |
| 124 | } | |
| 125 | ||
| 126 | if (current_config.output_file) |path| { | |
| 127 | const io = io_context.get(); | |
| 128 | const file = try std.Io.Dir.cwd().createFile(io, path, .{ | |
| 66 | 129 | .truncate = false, |
| 67 | 130 | .read = true, |
| 68 | 131 | }); |
| 132 | // Append rather than overwrite: a log that starts again from byte zero | |
| 133 | // on every launch loses the run that diagnosed the problem. | |
| 134 | const existing = file.stat(io) catch |stat_err| { | |
| 135 | file.close(io); | |
| 136 | return stat_err; | |
| 137 | }; | |
| 138 | log_file_offset = existing.size; | |
| 139 | log_file = file; | |
| 69 | 140 | } |
| 70 | 141 | } |
| 71 | 142 | |
| @@ -103,6 +174,32 @@ fn shouldLogLocked(level: LogLevel) bool { | ||
| 103 | 174 | return @backingInt(level) >= @backingInt(current_config.min_level); |
| 104 | 175 | } |
| 105 | 176 | |
| 177 | /// `std.fmt.bufPrint` that clips instead of failing. | |
| 178 | /// | |
| 179 | /// Returns as much of the formatted text as fits, ending with a marker so a | |
| 180 | /// reader can tell the difference between a short message and a clipped one. | |
| 181 | /// The alternative — what this code did before — was to return nothing at all | |
| 182 | /// and log no record, silently. | |
| 183 | fn formatTruncating(buf: []u8, comptime format: []const u8, args: anytype) []const u8 { | |
| 184 | if (std.fmt.bufPrint(buf, format, args)) |written| { | |
| 185 | return written; | |
| 186 | } else |_| {} | |
| 187 | ||
| 188 | const marker = "…[truncated]"; | |
| 189 | if (buf.len <= marker.len) return buf[0..0]; | |
| 190 | ||
| 191 | // Re-format into the space that is left, then stamp the marker on the end. | |
| 192 | // A second failure means even the clipped form does not fit, so keep | |
| 193 | // whatever was written and mark it. | |
| 194 | const room = buf.len - marker.len; | |
| 195 | var written_len: usize = room; | |
| 196 | if (std.fmt.bufPrint(buf[0..room], format, args)) |written| { | |
| 197 | written_len = written.len; | |
| 198 | } else |_| {} | |
| 199 | @memcpy(buf[written_len..][0..marker.len], marker); | |
| 200 | return buf[0 .. written_len + marker.len]; | |
| 201 | } | |
| 202 | ||
| 106 | 203 | pub fn log( |
| 107 | 204 | comptime level: LogLevel, |
| 108 | 205 | comptime format: []const u8, |
| @@ -113,14 +210,26 @@ pub fn log( | ||
| 113 | 210 | // prevents stderr interleaving between threads and makes config |
| 114 | 211 | // updates atomic with emission. Previously every call touched |
| 115 | 212 | // `current_config` and `log_file` unsynchronized. |
| 213 | // Before the lock, not after: the point is to never reach a lock this | |
| 214 | // thread already holds. | |
| 215 | if (in_log) return; | |
| 216 | in_log = true; | |
| 217 | defer in_log = false; | |
| 218 | ||
| 116 | 219 | log_mutex.lock(); |
| 117 | 220 | defer log_mutex.unlock(); |
| 118 | 221 | |
| 119 | 222 | if (!shouldLogLocked(level)) return; |
| 120 | 223 | |
| 121 | // Format message | |
| 224 | // Format the message, truncating rather than dropping it. | |
| 225 | // | |
| 226 | // This was `bufPrint(...) catch return`, which discarded the whole record | |
| 227 | // when it did not fit — so the longest messages, which are usually the | |
| 228 | // ones worth reading, were the only ones guaranteed to be missing. A log | |
| 229 | // that silently omits its biggest entries is worse than one that clips | |
| 230 | // them, because nothing indicates anything was lost. | |
| 122 | 231 | var msg_buf: [2048]u8 = undefined; |
| 123 | const message = std.fmt.bufPrint(&msg_buf, format, args) catch return; | |
| 232 | const message = formatTruncating(&msg_buf, format, args); | |
| 124 | 233 | |
| 125 | 234 | // Apply filter if configured |
| 126 | 235 | if (current_config.filter_pattern) |pattern| { |
| @@ -133,7 +242,7 @@ pub fn log( | ||
| 133 | 242 | var output_len: usize = 0; |
| 134 | 243 | |
| 135 | 244 | // Each call owns its own timestamp buffer — safe for concurrent logging. |
| 136 | var ts_buf: [8]u8 = undefined; | |
| 245 | var ts_buf: [timestamp_len]u8 = undefined; | |
| 137 | 246 | const timestamp = formatTimestamp(&ts_buf); |
| 138 | 247 | |
| 139 | 248 | if (current_config.json_output) { |
| @@ -142,7 +251,29 @@ pub fn log( | ||
| 142 | 251 | // `foo "bar"\nbaz` would corrupt every log consumer parsing the stream. |
| 143 | 252 | var esc_buf: [4096]u8 = undefined; |
| 144 | 253 | var esc_len: usize = 0; |
| 145 | for (message) |c| { | |
| 254 | var i: usize = 0; | |
| 255 | while (i < message.len) { | |
| 256 | const c = message[i]; | |
| 257 | ||
| 258 | // Anything outside ASCII is walked as a UTF-8 sequence rather than | |
| 259 | // byte by byte. Passing high bytes through individually is what | |
| 260 | // the previous loop did, and a message carrying invalid UTF-8 — a | |
| 261 | // filename, a truncated IPC frame — then produced a line that | |
| 262 | // `JSON.parse` rejects. A log format that a bad byte can make | |
| 263 | // unreadable is not a structured log format. | |
| 264 | if (c >= 0x80) { | |
| 265 | const seq_len = std.unicode.utf8ByteSequenceLength(c) catch 0; | |
| 266 | const valid = seq_len > 0 and i + seq_len <= message.len and | |
| 267 | std.unicode.utf8ValidateSlice(message[i..][0..seq_len]); | |
| 268 | const chunk: []const u8 = if (valid) message[i..][0..seq_len] else "\\ufffd"; | |
| 269 | if (esc_len + chunk.len > esc_buf.len) break; | |
| 270 | @memcpy(esc_buf[esc_len..][0..chunk.len], chunk); | |
| 271 | esc_len += chunk.len; | |
| 272 | i += if (valid) seq_len else 1; | |
| 273 | continue; | |
| 274 | } | |
| 275 | ||
| 276 | i += 1; | |
| 146 | 277 | const esc: []const u8 = switch (c) { |
| 147 | 278 | '"' => "\\\"", |
| 148 | 279 | '\\' => "\\\\", |
| @@ -165,36 +296,36 @@ pub fn log( | ||
| 165 | 296 | esc_len += esc.len; |
| 166 | 297 | } |
| 167 | 298 | |
| 168 | const result = std.fmt.bufPrint(&output_buf, "\n", .{ timestamp, level.toString(), esc_buf[0..esc_len] }) catch return; | |
| 169 | output_len = result.len; | |
| 299 | output_len = formatTruncating(&output_buf, "\n", .{ timestamp, level.toString(), esc_buf[0..esc_len] }).len; | |
| 170 | 300 | } else { |
| 171 | 301 | // Standard output |
| 172 | 302 | const reset = "\x1B[0m"; |
| 173 | 303 | const dim = "\x1B[2m"; |
| 174 | 304 | |
| 175 | 305 | if (current_config.enable_timestamps and current_config.enable_colors) { |
| 176 | const result = std.fmt.bufPrint(&output_buf, "{s}[{s}]{s} {s}{s}{s} {s}\n", .{ dim, timestamp, reset, level.color(), level.toString(), reset, message }) catch return; | |
| 177 | output_len = result.len; | |
| 306 | output_len = formatTruncating(&output_buf, "{s}[{s}]{s} {s}{s}{s} {s}\n", .{ dim, timestamp, reset, level.color(), level.toString(), reset, message }).len; | |
| 178 | 307 | } else if (current_config.enable_timestamps) { |
| 179 | const result = std.fmt.bufPrint(&output_buf, "[{s}] {s} {s}\n", .{ timestamp, level.toString(), message }) catch return; | |
| 180 | output_len = result.len; | |
| 308 | output_len = formatTruncating(&output_buf, "[{s}] {s} {s}\n", .{ timestamp, level.toString(), message }).len; | |
| 181 | 309 | } else if (current_config.enable_colors) { |
| 182 | const result = std.fmt.bufPrint(&output_buf, "{s}{s}{s} {s}\n", .{ level.color(), level.toString(), reset, message }) catch return; | |
| 183 | output_len = result.len; | |
| 310 | output_len = formatTruncating(&output_buf, "{s}{s}{s} {s}\n", .{ level.color(), level.toString(), reset, message }).len; | |
| 184 | 311 | } else { |
| 185 | const result = std.fmt.bufPrint(&output_buf, "{s} {s}\n", .{ level.toString(), message }) catch return; | |
| 186 | output_len = result.len; | |
| 312 | output_len = formatTruncating(&output_buf, "{s} {s}\n", .{ level.toString(), message }).len; | |
| 187 | 313 | } |
| 188 | 314 | } |
| 189 | 315 | |
| 190 | 316 | const output = output_buf[0..output_len]; |
| 191 | 317 | |
| 192 | // Write to stderr | |
| 193 | _ = std.Io.File.stderr().writeStreamingAll(io_context.get(), output) catch return; | |
| 318 | const io = log_io orelse io_context.get(); | |
| 319 | ||
| 320 | if (current_config.mirror_to_stderr) { | |
| 321 | _ = std.Io.File.stderr().writeStreamingAll(io, output) catch {}; | |
| 322 | } | |
| 194 | 323 | |
| 195 | // Write to file if configured | |
| 324 | // Appended at the tracked offset. `writeStreamingAll` writes from position | |
| 325 | // zero, which overwrote the previous run in place. | |
| 196 | 326 | if (log_file) |file| { |
| 197 | _ = file.writeStreamingAll(io_context.get(), output) catch return; | |
| 327 | file.writePositionalAll(io, output, log_file_offset) catch return; | |
| 328 | log_file_offset += output.len; | |
| 198 | 329 | } |
| 199 | 330 | } |
| 200 | 331 | |
| @@ -224,27 +355,309 @@ pub fn fatal(comptime format: []const u8, args: anytype) void { | ||
| 224 | 355 | /// reading live logs see their own wall-clock time instead of raw UTC. |
| 225 | 356 | /// `ts.sec` values below zero are clamped to 0 so pre-1970 clocks (e.g. |
| 226 | 357 | /// a VM booting with no RTC) can't panic in `@intCast`. |
| 227 | fn formatTimestamp(buf: *[8]u8) []const u8 { | |
| 228 | var ts: std.c.timespec = undefined; | |
| 229 | if (std.c.clock_gettime(.REALTIME, &ts) != 0) { | |
| 230 | @memcpy(buf, "00:00:00"); | |
| 358 | /// An ISO-8601 UTC timestamp: `YYYY-MM-DDTHH:MM:SSZ`. | |
| 359 | /// | |
| 360 | /// This used to emit `HH:MM:SS` and nothing else, which is fine for watching a | |
| 361 | /// terminal and useless for the thing `--log-file` exists to produce: a trail | |
| 362 | /// you read afterwards, possibly days afterwards, to work out what a | |
| 363 | /// long-running app did. A time with no date cannot answer that. | |
| 364 | /// | |
| 365 | /// UTC rather than local. The previous comment claimed it used `localtime_r`; | |
| 366 | /// the body did modular arithmetic on the epoch and left a dead `_ = t;` | |
| 367 | /// behind. `localtime_r` is not declared in `std.c` in this Zig, so honouring | |
| 368 | /// that comment would mean declaring the extern — and a log shared between a | |
| 369 | /// machine and whoever reads it later is better off unambiguous anyway. | |
| 370 | fn formatTimestamp(buf: *[timestamp_len]u8) []const u8 { | |
| 371 | const fallback = "0000-00-00T00:00:00Z"; | |
| 372 | ||
| 373 | // `compat.timestamp` rather than `std.c.clock_gettime`: the latter does not | |
| 374 | // compile for Windows in this Zig, and this file only ever built because | |
| 375 | // nothing instantiated `log` — wiring every std.log site through it is | |
| 376 | // what made the Windows path get analysed for the first time. | |
| 377 | const secs = .timestamp(); | |
| 378 | const epoch_seconds: std.time.epoch.EpochSeconds = .{ .secs = @intCast(@max(secs, 0)) }; | |
| 379 | const day = epoch_seconds.getEpochDay().calculateYearDay(); | |
| 380 | const month_day = day.calculateMonthDay(); | |
| 381 | const time = epoch_seconds.getDaySeconds(); | |
| 382 | ||
| 383 | const written = std.fmt.bufPrint(buf, "{d:0>4}-{d:0>2}-{d:0>2}T{d:0>2}:{d:0>2}:{d:0>2}Z", .{ | |
| 384 | day.year, | |
| 385 | month_day.month.numeric(), | |
| 386 | month_day.day_index + 1, | |
| 387 | time.getHoursIntoDay(), | |
| 388 | time.getMinutesIntoHour(), | |
| 389 | time.getSecondsIntoMinute(), | |
| 390 | }) catch { | |
| 391 | @memcpy(buf, fallback); | |
| 231 | 392 | return buf[0..]; |
| 393 | }; | |
| 394 | return written; | |
| 395 | } | |
| 396 | ||
| 397 | /// Width of `YYYY-MM-DDTHH:MM:SSZ`. | |
| 398 | const timestamp_len = 20; | |
| 399 | ||
| 400 | // ============================================================================= | |
| 401 | // Tests | |
| 402 | // ============================================================================= | |
| 403 | // | |
| 404 | // This module had none. It was written complete — levels, JSON, a filter, a | |
| 405 | // mutex, file output — and then never configured by anything, so every path | |
| 406 | // below the default was unexercised. Wiring `--log-file` in front of it | |
| 407 | // without first running it would have been the same mistake the rest of this | |
| 408 | // codebase keeps making: shipping code that looks right and has never run. | |
| 409 | ||
| 410 | const testing = std.testing; | |
| 411 | ||
| 412 | fn resetInLogForTesting() void { | |
| 413 | in_log = false; | |
| 414 | } | |
| 415 | ||
| 416 | test "a message longer than the buffer is clipped, not discarded" { | |
| 417 | // The defect: `bufPrint(...) catch return` dropped the entire record when | |
| 418 | // it did not fit, so the longest messages — usually the interesting ones — | |
| 419 | // were the only ones certain to be missing, with nothing to say so. | |
| 420 | var buf: [64]u8 = undefined; | |
| 421 | var long: [500]u8 = undefined; | |
| 422 | @memset(&long, 'x'); | |
| 423 | ||
| 424 | const out = formatTruncating(&buf, "{s}", .{long}); | |
| 425 | try testing.expect(out.len > 0); | |
| 426 | try testing.expect(out.len <= buf.len); | |
| 427 | try testing.expect(std.mem.endsWith(u8, out, "…[truncated]")); | |
| 428 | } | |
| 429 | ||
| 430 | test "a message that fits is untouched" { | |
| 431 | var buf: [64]u8 = undefined; | |
| 432 | const out = formatTruncating(&buf, "hello {s}", .{"world"}); | |
| 433 | try testing.expectEqualStrings("hello world", out); | |
| 434 | } | |
| 435 | ||
| 436 | test "a buffer too small even for the marker yields nothing rather than corrupting it" { | |
| 437 | var buf: [4]u8 = undefined; | |
| 438 | const out = formatTruncating(&buf, "{s}", .{"much longer than four"}); | |
| 439 | try testing.expectEqual(@as(usize, 0), out.len); | |
| 440 | } | |
| 441 | ||
| 442 | test "the configuration's strings are copied, not borrowed" { | |
| 443 | // `init` stored the caller's slices, and `minimal.zig` frees the | |
| 444 | // command-line strings during startup — so the first log call after | |
| 445 | // argument parsing would have read freed memory. Nothing had configured | |
| 446 | // the logger before, which is the only reason it never happened. | |
| 447 | var path_buf: [64]u8 = undefined; | |
| 448 | const scratch = try std.fmt.bufPrint(&path_buf, "{s}", .{"craft-log-borrow-test.txt"}); | |
| 449 | ||
| 450 | try init(.{ .output_file = scratch, .filter_pattern = "keepme", .mirror_to_stderr = false }); | |
| 451 | defer { | |
| 452 | deinit(); | |
| 453 | std.Io.Dir.cwd().deleteFile(io_context.get(), "craft-log-borrow-test.txt") catch {}; | |
| 232 | 454 | } |
| 233 | 455 | |
| 234 | const safe_sec = @max(ts.sec, 0); | |
| 235 | const t: std.c.time_t = @intCast(safe_sec); | |
| 456 | // Scribble over the caller's buffer. A borrowed slice would now be garbage. | |
| 457 | @memset(&path_buf, '!'); | |
| 236 | 458 | |
| 237 | _ = t; | |
| 238 | const slice = blk: { | |
| 239 | const total_seconds: u64 = @intCast(safe_sec); | |
| 240 | const seconds = @mod(total_seconds, 60); | |
| 241 | const minutes = @mod(@divFloor(total_seconds, 60), 60); | |
| 242 | const hours = @mod(@divFloor(total_seconds, 3600), 24); | |
| 243 | break :blk std.fmt.bufPrint(buf, "{d:0>2}:{d:0>2}:{d:0>2}", .{ hours, minutes, seconds }) catch null; | |
| 244 | }; | |
| 459 | try testing.expectEqualStrings("craft-log-borrow-test.txt", current_config.output_file.?); | |
| 460 | try testing.expectEqualStrings("keepme", current_config.filter_pattern.?); | |
| 461 | } | |
| 245 | 462 | |
| 246 | return slice orelse retry: { | |
| 247 | @memcpy(buf, "00:00:00"); | |
| 248 | break :retry buf[0..]; | |
| 249 | }; | |
| 463 | test "a second run appends instead of overwriting the first" { | |
| 464 | // `Io.Dir.CreateFileOptions` has no append flag and `writeStreamingAll` | |
| 465 | // starts at position zero, so every run rewrote the file from the | |
| 466 | // beginning — losing the run that diagnosed the problem and leaving any | |
| 467 | // longer previous content stranded past the end. | |
| 468 | const io = io_context.get(); | |
| 469 | const path = "craft-log-append-test.txt"; | |
| 470 | std.Io.Dir.cwd().deleteFile(io, path) catch {}; | |
| 471 | defer std.Io.Dir.cwd().deleteFile(io, path) catch {}; | |
| 472 | ||
| 473 | try init(.{ | |
| 474 | .output_file = path, | |
| 475 | .min_level = .Debug, | |
| 476 | .enable_colors = false, | |
| 477 | .enable_timestamps = false, | |
| 478 | .mirror_to_stderr = false, | |
| 479 | }); | |
| 480 | log(.Info, "first run {d}", .{1}); | |
| 481 | deinit(); | |
| 482 | ||
| 483 | try init(.{ | |
| 484 | .output_file = path, | |
| 485 | .min_level = .Debug, | |
| 486 | .enable_colors = false, | |
| 487 | .enable_timestamps = false, | |
| 488 | .mirror_to_stderr = false, | |
| 489 | }); | |
| 490 | log(.Info, "second run {d}", .{2}); | |
| 491 | deinit(); | |
| 492 | ||
| 493 | var read_buf: [4096]u8 = undefined; | |
| 494 | const file = try std.Io.Dir.cwd().openFile(io, path, .{}); | |
| 495 | defer file.close(io); | |
| 496 | const n = try file.readPositionalAll(io, &read_buf, 0); | |
| 497 | const contents = read_buf[0..n]; | |
| 498 | ||
| 499 | // Both runs are present, and in order. | |
| 500 | const first = std.mem.indexOf(u8, contents, "first run 1") orelse return error.FirstRunLost; | |
| 501 | const second = std.mem.indexOf(u8, contents, "second run 2") orelse return error.SecondRunLost; | |
| 502 | try testing.expect(first < second); | |
| 503 | } | |
| 504 | ||
| 505 | test "the level filter keeps quiet records out of the file" { | |
| 506 | const io = io_context.get(); | |
| 507 | const path = "craft-log-level-test.txt"; | |
| 508 | std.Io.Dir.cwd().deleteFile(io, path) catch {}; | |
| 509 | defer std.Io.Dir.cwd().deleteFile(io, path) catch {}; | |
| 510 | ||
| 511 | try init(.{ | |
| 512 | .output_file = path, | |
| 513 | .min_level = .Warning, | |
| 514 | .enable_colors = false, | |
| 515 | .enable_timestamps = false, | |
| 516 | .mirror_to_stderr = false, | |
| 517 | }); | |
| 518 | log(.Debug, "quiet", .{}); | |
| 519 | log(.Info, "also quiet", .{}); | |
| 520 | log(.Warning, "loud", .{}); | |
| 521 | deinit(); | |
| 522 | ||
| 523 | var read_buf: [4096]u8 = undefined; | |
| 524 | const file = try std.Io.Dir.cwd().openFile(io, path, .{}); | |
| 525 | defer file.close(io); | |
| 526 | const n = try file.readPositionalAll(io, &read_buf, 0); | |
| 527 | const contents = read_buf[0..n]; | |
| 528 | ||
| 529 | try testing.expect(std.mem.indexOf(u8, contents, "loud") != null); | |
| 530 | try testing.expect(std.mem.indexOf(u8, contents, "quiet") == null); | |
| 531 | } | |
| 532 | ||
| 533 | test "json output stays parseable when the message fights back" { | |
| 534 | const io = io_context.get(); | |
| 535 | const path = "craft-log-json-test.txt"; | |
| 536 | std.Io.Dir.cwd().deleteFile(io, path) catch {}; | |
| 537 | defer std.Io.Dir.cwd().deleteFile(io, path) catch {}; | |
| 538 | ||
| 539 | try init(.{ | |
| 540 | .output_file = path, | |
| 541 | .min_level = .Debug, | |
| 542 | .json_output = true, | |
| 543 | .mirror_to_stderr = false, | |
| 544 | }); | |
| 545 | log(.Error, "he said {s} then a newline{s}and a tab{s}", .{ "\"hi\"", "\n", "\t" }); | |
| 546 | deinit(); | |
| 547 | ||
| 548 | var read_buf: [4096]u8 = undefined; | |
| 549 | const file = try std.Io.Dir.cwd().openFile(io, path, .{}); | |
| 550 | defer file.close(io); | |
| 551 | const n = try file.readPositionalAll(io, &read_buf, 0); | |
| 552 | const line = std.mem.trimEnd(u8, read_buf[0..n], "\n"); | |
| 553 | ||
| 554 | const parsed = try std.json.parseFromSlice(std.json.Value, testing.allocator, line, .{}); | |
| 555 | defer parsed.deinit(); | |
| 556 | try testing.expectEqualStrings("ERROR", parsed.value.object.get("level").?.string); | |
| 557 | const msg = parsed.value.object.get("message").?.string; | |
| 558 | try testing.expect(std.mem.indexOf(u8, msg, "\"hi\"") != null); | |
| 559 | } | |
| 560 | ||
| 561 | test "mirroring to stderr can be turned off without losing the file" { | |
| 562 | // The stderr write was unconditional, so a packaged or headless app could | |
| 563 | // not ask for a file and a quiet terminal. | |
| 564 | const io = io_context.get(); | |
| 565 | const path = "craft-log-quiet-test.txt"; | |
| 566 | std.Io.Dir.cwd().deleteFile(io, path) catch {}; | |
| 567 | defer std.Io.Dir.cwd().deleteFile(io, path) catch {}; | |
| 568 | ||
| 569 | try init(.{ | |
| 570 | .output_file = path, | |
| 571 | .min_level = .Debug, | |
| 572 | .enable_colors = false, | |
| 573 | .enable_timestamps = false, | |
| 574 | .mirror_to_stderr = false, | |
| 575 | }); | |
| 576 | log(.Info, "written to the file only", .{}); | |
| 577 | deinit(); | |
| 578 | ||
| 579 | var read_buf: [1024]u8 = undefined; | |
| 580 | const file = try std.Io.Dir.cwd().openFile(io, path, .{}); | |
| 581 | defer file.close(io); | |
| 582 | const n = try file.readPositionalAll(io, &read_buf, 0); | |
| 583 | try testing.expect(std.mem.indexOf(u8, read_buf[0..n], "written to the file only") != null); | |
| 584 | } | |
| 585 | ||
| 586 | test "re-initialising closes the previous file rather than leaking it" { | |
| 587 | const io = io_context.get(); | |
| 588 | const a = "craft-log-reinit-a.txt"; | |
| 589 | const b = "craft-log-reinit-b.txt"; | |
| 590 | defer std.Io.Dir.cwd().deleteFile(io, a) catch {}; | |
| 591 | defer std.Io.Dir.cwd().deleteFile(io, b) catch {}; | |
| 592 | ||
| 593 | try init(.{ .output_file = a, .mirror_to_stderr = false }); | |
| 594 | try init(.{ .output_file = b, .mirror_to_stderr = false }); | |
| 595 | try testing.expectEqualStrings(b, current_config.output_file.?); | |
| 596 | deinit(); | |
| 597 | try testing.expect(log_file == null); | |
| 598 | } | |
| 599 | ||
| 600 | test "json survives a message that is not valid UTF-8" { | |
| 601 | // A filename, a truncated IPC frame, any raw byte over 0x7f: these used to | |
| 602 | // be copied into the JSON string verbatim, producing a line that | |
| 603 | // `JSON.parse` rejects. A structured log a single bad byte can make | |
| 604 | // unreadable is not structured. | |
| 605 | const io = io_context.get(); | |
| 606 | const path = "craft-log-utf8-test.txt"; | |
| 607 | std.Io.Dir.cwd().deleteFile(io, path) catch {}; | |
| 608 | defer std.Io.Dir.cwd().deleteFile(io, path) catch {}; | |
| 609 | ||
| 610 | try init(.{ | |
| 611 | .output_file = path, | |
| 612 | .min_level = .Debug, | |
| 613 | .json_output = true, | |
| 614 | .mirror_to_stderr = false, | |
| 615 | }); | |
| 616 | // 0xFF is never valid UTF-8; the é is, and must survive intact. | |
| 617 | log(.Warning, "bad byte {s} and caf\xc3\xa9", .{"\xff\xfe"}); | |
| 618 | deinit(); | |
| 619 | ||
| 620 | var read_buf: [4096]u8 = undefined; | |
| 621 | const file = try std.Io.Dir.cwd().openFile(io, path, .{}); | |
| 622 | defer file.close(io); | |
| 623 | const n = try file.readPositionalAll(io, &read_buf, 0); | |
| 624 | const line = std.mem.trimEnd(u8, read_buf[0..n], "\n"); | |
| 625 | ||
| 626 | const parsed = try std.json.parseFromSlice(std.json.Value, testing.allocator, line, .{}); | |
| 627 | defer parsed.deinit(); | |
| 628 | const msg = parsed.value.object.get("message").?.string; | |
| 629 | try testing.expect(std.mem.indexOf(u8, msg, "café") != null); | |
| 630 | try testing.expect(std.mem.indexOf(u8, msg, "\u{fffd}") != null); | |
| 631 | } | |
| 632 | ||
| 633 | test "a timestamp carries the date, not just the time" { | |
| 634 | // `--log-file` produces a trail read afterwards, sometimes days | |
| 635 | // afterwards. `HH:MM:SS` alone cannot say which day. | |
| 636 | var buf: [timestamp_len]u8 = undefined; | |
| 637 | const ts = formatTimestamp(&buf); | |
| 638 | try testing.expectEqual(timestamp_len, ts.len); | |
| 639 | try testing.expectEqual(@as(u8, '-'), ts[4]); | |
| 640 | try testing.expectEqual(@as(u8, '-'), ts[7]); | |
| 641 | try testing.expectEqual(@as(u8, 'T'), ts[10]); | |
| 642 | try testing.expectEqual(@as(u8, 'Z'), ts[timestamp_len - 1]); | |
| 643 | // A plausible year rather than the epoch fallback. | |
| 644 | const year = try std.fmt.parseInt(u16, ts[0..4], 10); | |
| 645 | try testing.expect(year >= 2020); | |
| 646 | } | |
| 647 | ||
| 648 | test "logging from inside logging drops the inner record instead of hanging" { | |
| 649 | // `compat_mutex` is a non-recursive spinlock here — `std.Thread.Mutex` | |
| 650 | // does not exist in this Zig — so a reentrant call would spin against a | |
| 651 | // lock this thread already holds, forever. Routing every std.log site | |
| 652 | // through this module is what made that reachable. | |
| 653 | resetInLogForTesting(); | |
| 654 | try testing.expect(!in_log); | |
| 655 | ||
| 656 | in_log = true; | |
| 657 | // Would deadlock without the guard; returns immediately with it. | |
| 658 | log(.Error, "reentrant", .{}); | |
| 659 | try testing.expect(in_log); | |
| 660 | ||
| 661 | resetInLogForTesting(); | |
| 662 | try testing.expect(!in_log); | |
| 250 | 663 | } |