⋯ 36 lines Show the 36 lines above this hunk 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(); ⋯ 6 lines Show the 6 lines above this hunk 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 ⋯ 31 lines Show the 31 lines above this hunk 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, ⋯ 4 lines Show the 4 lines above this hunk 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| { ⋯ 6 lines Show the 6 lines above this hunk 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) { ⋯ 2 lines Show the 2 lines above this hunk 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 '\\' => "\\\\", ⋯ 16 lines Show the 16 lines above this hunk 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 ⋯ 23 lines Show the 23 lines above this hunk 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 }