also looking at this
fix(log): keep the terminal's colour, and let logging be turned off
#81
4 files
+126
-16
| @@ -9,6 +9,15 @@ pub const LogLevel = enum { | ||
| 9 | 9 | Warning, |
| 10 | 10 | Error, |
| 11 | 11 | Fatal, |
| 12 | /// Record nothing. | |
| 13 | /// | |
| 14 | /// Last, so the existing `level >= min_level` comparison silences | |
| 15 | /// everything when it is the minimum — no branch anywhere else has to know | |
| 16 | /// about it. `logging.zig` has had an `off` for as long as it has existed; | |
| 17 | /// this side had no way to say the same thing, so an app that wanted | |
| 18 | /// quiet had to not configure logging at all, which is not the same as | |
| 19 | /// asking for it. | |
| 20 | Off, | |
| 12 | 21 | |
| 13 | 22 | pub fn toString(self: LogLevel) []const u8 { |
| 14 | 23 | return switch (self) { |
| @@ -17,6 +26,7 @@ pub const LogLevel = enum { | ||
| 17 | 26 | .Warning => "WARN", |
| 18 | 27 | .Error => "ERROR", |
| 19 | 28 | .Fatal => "FATAL", |
| 29 | .Off => "OFF", | |
| 20 | 30 | }; |
| 21 | 31 | } |
| 22 | 32 | |
| @@ -27,6 +37,8 @@ pub const LogLevel = enum { | ||
| 27 | 37 | .Warning => "\x1B[33m", // Yellow |
| 28 | 38 | .Error => "\x1B[31m", // Red |
| 29 | 39 | .Fatal => "\x1B[35m", // Magenta |
| 40 | // Never emitted; a record at this level is filtered before formatting. | |
| 41 | .Off => "", | |
| 30 | 42 | }; |
| 31 | 43 | } |
| 32 | 44 | }; |
| @@ -96,6 +108,12 @@ threadlocal var in_log: bool = false; | ||
| 96 | 108 | /// reachable from inside a log call. Captured once instead. |
| 97 | 109 | var log_io: ?std.Io = null; |
| 98 | 110 | |
| 111 | /// Whether stderr is a terminal, decided once at `init`. | |
| 112 | /// | |
| 113 | /// Per-record would mean an `isatty` on every line, and the answer cannot | |
| 114 | /// change for a running process anyway. | |
| 115 | var stderr_is_tty: bool = false; | |
| 116 | ||
| 99 | 117 | pub fn init(config: LogConfig) !void { |
| 100 | 118 | log_mutex.lock(); |
| 101 | 119 | defer log_mutex.unlock(); |
| @@ -110,6 +128,7 @@ pub fn init(config: LogConfig) !void { | ||
| 110 | 128 | current_config = config; |
| 111 | 129 | log_file_offset = 0; |
| 112 | 130 | log_io = io_context.get(); |
| 131 | stderr_is_tty = std.Io.File.stderr().isTty(log_io.?) catch false; | |
| 113 | 132 | |
| 114 | 133 | // Take copies before anything else can free the originals. |
| 115 | 134 | if (config.output_file) |path| { |
| @@ -297,28 +316,41 @@ pub fn log( | ||
| 297 | 316 | } |
| 298 | 317 | |
| 299 | 318 | output_len = formatTruncating(&output_buf, "\n", .{ timestamp, level.toString(), esc_buf[0..esc_len] }).len; |
| 319 | } else if (current_config.enable_timestamps) { | |
| 320 | output_len = formatTruncating(&output_buf, "[{s}] {s} {s}\n", .{ timestamp, level.toString(), message }).len; | |
| 300 | 321 | } else { |
| 301 | // Standard output | |
| 302 | const reset = "\x1B[0m"; | |
| 303 | const dim = "\x1B[2m"; | |
| 304 | ||
| 305 | if (current_config.enable_timestamps and current_config.enable_colors) { | |
| 306 | output_len = formatTruncating(&output_buf, "{s}[{s}]{s} {s}{s}{s} {s}\n", .{ dim, timestamp, reset, level.color(), level.toString(), reset, message }).len; | |
| 307 | } else if (current_config.enable_timestamps) { | |
| 308 | output_len = formatTruncating(&output_buf, "[{s}] {s} {s}\n", .{ timestamp, level.toString(), message }).len; | |
| 309 | } else if (current_config.enable_colors) { | |
| 310 | output_len = formatTruncating(&output_buf, "{s}{s}{s} {s}\n", .{ level.color(), level.toString(), reset, message }).len; | |
| 311 | } else { | |
| 312 | output_len = formatTruncating(&output_buf, "{s} {s}\n", .{ level.toString(), message }).len; | |
| 313 | } | |
| 322 | output_len = formatTruncating(&output_buf, "{s} {s}\n", .{ level.toString(), message }).len; | |
| 314 | 323 | } |
| 315 | 324 | |
| 316 | 325 | const output = output_buf[0..output_len]; |
| 317 | 326 | |
| 327 | // Colour is formatted separately, for stderr only. | |
| 328 | // | |
| 329 | // Both sinks used to receive the same bytes, so a run with `--log-file` | |
| 330 | // either put ANSI escapes in the file or — the workaround this replaces — | |
| 331 | // turned colour off for the terminal as well, to keep the file clean. A | |
| 332 | // log file full of `\x1b[2m` is unreadable to `grep`, and a terminal that | |
| 333 | // loses its colours because a file was requested is a strange trade. | |
| 334 | // | |
| 335 | // Only when stderr is a terminal, decided once at `init` rather than per | |
| 336 | // record: colour written into a redirected stderr is the same problem as | |
| 337 | // colour written into the file. | |
| 338 | var colour_buf: [4096]u8 = undefined; | |
| 339 | var colour_len: usize = 0; | |
| 340 | if (current_config.enable_colors and stderr_is_tty and !current_config.json_output) { | |
| 341 | const reset = "\x1B[0m"; | |
| 342 | const dim = "\x1B[2m"; | |
| 343 | colour_len = if (current_config.enable_timestamps) | |
| 344 | formatTruncating(&colour_buf, "{s}[{s}]{s} {s}{s}{s} {s}\n", .{ dim, timestamp, reset, level.color(), level.toString(), reset, message }).len | |
| 345 | else | |
| 346 | formatTruncating(&colour_buf, "{s}{s}{s} {s}\n", .{ level.color(), level.toString(), reset, message }).len; | |
| 347 | } | |
| 348 | ||
| 318 | 349 | const io = log_io orelse io_context.get(); |
| 319 | 350 | |
| 320 | 351 | if (current_config.mirror_to_stderr) { |
| 321 | _ = std.Io.File.stderr().writeStreamingAll(io, output) catch {}; | |
| 352 | const for_stderr = if (colour_len > 0) colour_buf[0..colour_len] else output; | |
| 353 | _ = std.Io.File.stderr().writeStreamingAll(io, for_stderr) catch {}; | |
| 322 | 354 | } |
| 323 | 355 | |
| 324 | 356 | // Appended at the tracked offset. `writeStreamingAll` writes from position |
| @@ -661,3 +693,72 @@ test "logging from inside logging drops the inner record instead of hanging" { | ||
| 661 | 693 | resetInLogForTesting(); |
| 662 | 694 | try testing.expect(!in_log); |
| 663 | 695 | } |
| 696 | ||
| 697 | test "off silences every level" { | |
| 698 | // `logging.zig` has always had an `off`; this side had no way to say the | |
| 699 | // same thing, so an app that wanted quiet had to not configure logging at | |
| 700 | // all — which is not the same as asking for it. | |
| 701 | const io = io_context.get(); | |
| 702 | const path = "craft-log-off-test.txt"; | |
| 703 | std.Io.Dir.cwd().deleteFile(io, path) catch {}; | |
| 704 | defer std.Io.Dir.cwd().deleteFile(io, path) catch {}; | |
| 705 | ||
| 706 | try init(.{ .output_file = path, .min_level = .Off, .mirror_to_stderr = false }); | |
| 707 | log(.Debug, "no", .{}); | |
| 708 | log(.Info, "no", .{}); | |
| 709 | log(.Warning, "no", .{}); | |
| 710 | log(.Error, "no", .{}); | |
| 711 | log(.Fatal, "not even this", .{}); | |
| 712 | deinit(); | |
| 713 | ||
| 714 | var read_buf: [256]u8 = undefined; | |
| 715 | const file = try std.Io.Dir.cwd().openFile(io, path, .{}); | |
| 716 | defer file.close(io); | |
| 717 | const n = try file.readPositionalAll(io, &read_buf, 0); | |
| 718 | try testing.expectEqual(@as(usize, 0), n); | |
| 719 | } | |
| 720 | ||
| 721 | test "off is the highest level, so the ordering check silences by itself" { | |
| 722 | // Placed last in the enum on purpose: `level >= min_level` then does the | |
| 723 | // work and no other branch has to know the concept exists. | |
| 724 | const values = std.enums.values(LogLevel); | |
| 725 | try testing.expectEqual(LogLevel.Off, values[values.len - 1]); | |
| 726 | for (values) |level| { | |
| 727 | if (level == .Off) continue; | |
| 728 | try testing.expect(@backingInt(level) < @backingInt(LogLevel.Off)); | |
| 729 | } | |
| 730 | } | |
| 731 | ||
| 732 | test "the file never receives colour, even when the terminal is getting it" { | |
| 733 | // Both sinks used to be handed the same bytes, so a run with --log-file | |
| 734 | // either wrote ANSI escapes into the file or turned colour off for the | |
| 735 | // terminal too. A log full of \x1b[2m is unreadable to grep. | |
| 736 | // | |
| 737 | // `stderr_is_tty` is forced, because a test process is piped and would | |
| 738 | // otherwise produce no coloured line at all — the first version of this | |
| 739 | // test passed against a deliberately reverted fix for exactly that reason. | |
| 740 | const io = io_context.get(); | |
| 741 | const path = "craft-log-colour-test.txt"; | |
| 742 | std.Io.Dir.cwd().deleteFile(io, path) catch {}; | |
| 743 | defer std.Io.Dir.cwd().deleteFile(io, path) catch {}; | |
| 744 | ||
| 745 | try init(.{ | |
| 746 | .output_file = path, | |
| 747 | .min_level = .Debug, | |
| 748 | .enable_colors = true, // asked for, and still must not reach the file | |
| 749 | .mirror_to_stderr = false, | |
| 750 | }); | |
| 751 | stderr_is_tty = true; // after init, which computes it | |
| 752 | defer stderr_is_tty = false; | |
| 753 | log(.Error, "a red line on a terminal", .{}); | |
| 754 | deinit(); | |
| 755 | ||
| 756 | var read_buf: [1024]u8 = undefined; | |
| 757 | const file = try std.Io.Dir.cwd().openFile(io, path, .{}); | |
| 758 | defer file.close(io); | |
| 759 | const n = try file.readPositionalAll(io, &read_buf, 0); | |
| 760 | const contents = read_buf[0..n]; | |
| 761 | ||
| 762 | try testing.expect(std.mem.indexOf(u8, contents, "a red line on a terminal") != null); | |
| 763 | try testing.expect(std.mem.indexOfScalar(u8, contents, 0x1B) == null); | |
| 764 | } | |