also looking at this
feat(log): --log-file, and a logger that survives being used
#78
5 files
+691
-37
| @@ -8,6 +8,47 @@ const io_context = craft.io_context; | ||
| 8 | 8 | // `craft`, and macos.zig already owns it there. |
| 9 | 9 | const timing = craft.startup_timing; |
| 10 | 10 | |
| 11 | /// Craft's log handler. | |
| 12 | /// | |
| 13 | /// One declaration in the executable's root, and every `std.log` call in the | |
| 14 | /// program routes through it — across module boundaries, because `std.log` | |
| 15 | /// resolves its handler from the compilation root rather than from the calling | |
| 16 | /// module. That is what makes `--log-file` worth having: without it the flag | |
| 17 | /// opens a file that only `devmode.zig` and `hotreload.zig` ever write to, | |
| 18 | /// which is to say an empty one. | |
| 19 | /// | |
| 20 | /// `log_level = .debug` was already here and is load-bearing. `std.log.debug` | |
| 21 | /// is compiled out at comptime below the threshold, and most of craft's | |
| 22 | /// `std.log` calls are debug level; releases build ReleaseSafe, so without it | |
| 23 | /// `--log-level debug` would be a flag that could not do anything. | |
| 24 | /// | |
| 25 | /// Not captured: `std.debug.print`, which craft uses in far more places than | |
| 26 | /// `std.log`. Those go through `std.Options.debug_io` rather than the log | |
| 27 | /// handler, and most sit behind `if (builtin.mode == .debug)`. Said plainly in | |
| 28 | /// `--help`, rather than left for someone to work out from a log file that is | |
| 29 | /// quieter than they expected. | |
| 30 | pub const std_options: std.Options = .{ | |
| 31 | .log_level = .debug, | |
| 32 | .logFn = craftLogFn, | |
| 33 | }; | |
| 34 | ||
| 35 | fn craftLogFn( | |
| 36 | comptime message_level: std.log.Level, | |
| 37 | comptime scope: @EnumLiteral(), | |
| 38 | comptime format: []const u8, | |
| 39 | args: anytype, | |
| 40 | ) void { | |
| 41 | // The scope is prefixed rather than dropped: `std.log.scoped(...)` is used | |
| 42 | // throughout craft, and the scope is most of what makes a line findable. | |
| 43 | const prefix = if (scope == .default) "" else "[" ++ @tagName(scope) ++ "] "; | |
| 44 | craft.Log.log(switch (message_level) { | |
| 45 | .debug => .Debug, | |
| 46 | .info => .Info, | |
| 47 | .warn => .Warning, | |
| 48 | .err => .Error, | |
| 49 | }, prefix ++ format, args); | |
| 50 | } | |
| 51 | ||
| 11 | 52 | pub fn main(init: std.process.Init) !void { |
| 12 | 53 | io_context.init(init.io); |
| 13 | 54 | const allocator = init.gpa; |
| @@ -57,6 +98,18 @@ pub fn main(init: std.process.Init) !void { | ||
| 57 | 98 | std.process.exit(1); |
| 58 | 99 | } |
| 59 | 100 | |
| 101 | // Configure logging before anything else that might have something to | |
| 102 | // say. Both startup paths flow through here, and `--log-file` is only | |
| 103 | // useful if it is open before the interesting part of startup runs. | |
| 104 | // | |
| 105 | // Safe to do with strings the caller will free: `log.init` copies them. | |
| 106 | // It did not until now, and nothing had ever configured it, which is the | |
| 107 | // only reason that was not already a use-after-free. | |
| 108 | configureLogging(options) catch |err| { | |
| 109 | std.debug.print("Error: could not open --log-file '{s}': {s}\n", .{ options.log_file orelse "", @errorName(err) }); | |
| 110 | std.process.exit(1); | |
| 111 | }; | |
| 112 | ||
| 60 | 113 | // Whether closing the last window ends the process. Decided here, before |
| 61 | 114 | // either startup path, because both need the same answer and only this |
| 62 | 115 | // scope knows the shape of the app. See `lifecycle_policy.zig` for the |
| @@ -388,6 +441,86 @@ pub fn main(init: std.process.Init) !void { | ||
| 388 | 441 | |
| 389 | 442 | /// Run with system tray using a modified App flow |
| 390 | 443 | /// Key difference: we create the system tray BEFORE calling initPlatform |
| 444 | /// Turn the logging flags into a configured sink. | |
| 445 | /// | |
| 446 | /// A bad path is fatal rather than ignored. Someone who passed `--log-file` | |
| 447 | /// is going to go looking in that file, and a run that silently logged | |
| 448 | /// nowhere is worse than one that refused to start — the whole point of the | |
| 449 | /// flag is to be able to find out what happened afterwards. | |
| 450 | fn configureLogging(options: cli.WindowOptions) !void { | |
| 451 | const wants_file = options.log_file != null; | |
| 452 | const wants_level = options.log_level != null; | |
| 453 | if (!wants_file and !wants_level and !options.log_json and !options.log_quiet) return; | |
| 454 | ||
| 455 | const level: craft.Log.LogLevel = if (options.log_level) |name| blk: { | |
| 456 | break :blk parseLogLevel(name) orelse { | |
| 457 | std.debug.print( | |
| 458 | "Error: unknown --log-level '{s}' (expected debug, info, warn, error or fatal)\n", | |
| 459 | .{name}, | |
| 460 | ); | |
| 461 | std.process.exit(1); | |
| 462 | }; | |
| 463 | } else .Info; | |
| 464 | ||
| 465 | try craft.Log.init(.{ | |
| 466 | .min_level = level, | |
| 467 | .output_file = options.log_file, | |
| 468 | .json_output = options.log_json, | |
| 469 | // Colour codes in a file are noise; on a terminal they are not. | |
| 470 | .enable_colors = !options.log_json and !wants_file, | |
| 471 | // --log-quiet only makes sense with somewhere else for records to go. | |
| 472 | .mirror_to_stderr = !(options.log_quiet and wants_file), | |
| 473 | }); | |
| 474 | ||
| 475 | // The scoped front end (`logging.notification`, `logging.menu`, ...) feeds | |
| 476 | // the same sink through the callback it already had, so its call sites | |
| 477 | // reach the log file without any of them being touched. | |
| 478 | craft.Logging.init(.{ | |
| 479 | .target = .callback, | |
| 480 | .callback = forwardScopedLog, | |
| 481 | .level = switch (level) { | |
| 482 | .Debug => .debug, | |
| 483 | .Info => .info, | |
| 484 | .Warning => .warn, | |
| 485 | .Error => .err, | |
| 486 | .Fatal => .fatal, | |
| 487 | }, | |
| 488 | // Timestamp and colour are the outer sink's job now; doubling them | |
| 489 | // would put two of each on every line. | |
| 490 | .colored = false, | |
| 491 | .show_timestamp = false, | |
| 492 | }); | |
| 493 | } | |
| 494 | ||
| 495 | fn forwardScopedLog(level: craft.Logging.LogLevel, module: []const u8, message: []const u8) void { | |
| 496 | _ = module; // already present in the formatted message | |
| 497 | switch (level) { | |
| 498 | .trace, .debug => craft.Log.log(.Debug, "{s}", .{message}), | |
| 499 | .info => craft.Log.log(.Info, "{s}", .{message}), | |
| 500 | .warn => craft.Log.log(.Warning, "{s}", .{message}), | |
| 501 | .err => craft.Log.log(.Error, "{s}", .{message}), | |
| 502 | .fatal => craft.Log.log(.Fatal, "{s}", .{message}), | |
| 503 | .off => {}, | |
| 504 | } | |
| 505 | } | |
| 506 | ||
| 507 | /// Spellings accepted by `--log-level`. | |
| 508 | fn parseLogLevel(name: []const u8) ?craft.Log.LogLevel { | |
| 509 | const table = .{ | |
| 510 | .{ "debug", craft.Log.LogLevel.Debug }, | |
| 511 | .{ "info", craft.Log.LogLevel.Info }, | |
| 512 | .{ "warn", craft.Log.LogLevel.Warning }, | |
| 513 | .{ "warning", craft.Log.LogLevel.Warning }, | |
| 514 | .{ "error", craft.Log.LogLevel.Error }, | |
| 515 | .{ "err", craft.Log.LogLevel.Error }, | |
| 516 | .{ "fatal", craft.Log.LogLevel.Fatal }, | |
| 517 | }; | |
| 518 | inline for (table) |entry| { | |
| 519 | if (std.ascii.eqlIgnoreCase(name, entry[0])) return entry[1]; | |
| 520 | } | |
| 521 | return null; | |
| 522 | } | |
| 523 | ||
| 391 | 524 | fn runWithSystemTray(allocator: std.mem.Allocator, options: cli.WindowOptions) !void { |
| 392 | 525 | std.debug.print("\n⚡ Creating system tray application\n", .{}); |
| 393 | 526 | std.debug.print(" Title: {s}\n", .{options.title}); |