| @@ -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 | } |