authorgravatar for mail@isaacfreund.comIsaac Freund <mail@isaacfreund.com> 2021-10-24 13:13:06+02:00
committergravatar for andrew@ziglang.orgAndrew Kelley <andrew@ziglang.org> 2021-10-24 15:04:29-04:00
logf7b090d7076a20a614bf20cac05e5e18c06ad18a
tree72bb252c5352e48ea6d60914debdf5ccc1821dff
parent6cf5305e47dd8382508f867b04067be615448b41

std.log: simplify to 4 distinct log levels

Over the last year of using std.log in practice, it has become clear to me that having the current 8 distinct log levels does more harm than good. It is too subjective which level a given message should have which makes filtering based on log level weaker as not all messages will have been assigned the log level one might expect. Instead, more granular filtering should be achieved by leveraging the logging scope feature. Filtering based on a combination of scope and log level should be sufficiently powerful for all use-cases. Note that the self hosted compiler has already limited itself to 4 distinct log levels for many months and implemented granular filtering based on both log scope and level. This has worked very well in practice while working on the self hosted compiler.

5 files changed, 59 insertions(+), 138 deletions(-)

lib/std/heap/logging_allocator.zig+2-6
...@@ -40,12 +40,8 @@ pub fn ScopedLoggingAllocator(...@@ -40,12 +40,8 @@ pub fn ScopedLoggingAllocator(
40 // This function is required as the `std.log.log` function is not public40 // This function is required as the `std.log.log` function is not public
41 inline fn logHelper(comptime log_level: std.log.Level, comptime format: []const u8, args: anytype) void {41 inline fn logHelper(comptime log_level: std.log.Level, comptime format: []const u8, args: anytype) void {
42 switch (log_level) {42 switch (log_level) {
43 .emerg => log.emerg(format, args),
44 .alert => log.alert(format, args),
45 .crit => log.crit(format, args),
46 .err => log.err(format, args),43 .err => log.err(format, args),
47 .warn => log.warn(format, args),44 .warn => log.warn(format, args),
48 .notice => log.notice(format, args),
49 .info => log.info(format, args),45 .info => log.info(format, args),
50 .debug => log.debug(format, args),46 .debug => log.debug(format, args),
51 }47 }
...@@ -120,6 +116,6 @@ pub fn ScopedLoggingAllocator(...@@ -120,6 +116,6 @@ pub fn ScopedLoggingAllocator(
120/// This allocator is used in front of another allocator and logs to `std.log`116/// This allocator is used in front of another allocator and logs to `std.log`
121/// on every call to the allocator.117/// on every call to the allocator.
122/// For logging to a `std.io.Writer` see `std.heap.LogToWriterAllocator`118/// For logging to a `std.io.Writer` see `std.heap.LogToWriterAllocator`
123pub fn loggingAllocator(parent_allocator: *Allocator) LoggingAllocator(.debug, .crit) {119pub fn loggingAllocator(parent_allocator: *Allocator) LoggingAllocator(.debug, .err) {
124 return LoggingAllocator(.debug, .crit).init(parent_allocator);120 return LoggingAllocator(.debug, .err).init(parent_allocator);
125}121}
lib/std/log.zig+42-90
...@@ -18,8 +18,8 @@...@@ -18,8 +18,8 @@
18//! ```18//! ```
19//! const std = @import("std");19//! const std = @import("std");
20//!20//!
21//! // Set the log level to warning21//! // Set the log level to info
22//! pub const log_level: std.log.Level = .warn;22//! pub const log_level: std.log.Level = .info;
23//!23//!
24//! // Define root.log to override the std implementation24//! // Define root.log to override the std implementation
25//! pub fn log(25//! pub fn log(
...@@ -28,17 +28,17 @@...@@ -28,17 +28,17 @@
28//! comptime format: []const u8,28//! comptime format: []const u8,
29//! args: anytype,29//! args: anytype,
30//! ) void {30//! ) void {
31//! // Ignore all non-critical logging from sources other than31//! // Ignore all non-error logging from sources other than
32//! // .my_project, .nice_library and .default32//! // .my_project, .nice_library and .default
33//! const scope_prefix = "(" ++ switch (scope) {33//! const scope_prefix = "(" ++ switch (scope) {
34//! .my_project, .nice_library, .default => @tagName(scope),34//! .my_project, .nice_library, .default => @tagName(scope),
35//! else => if (@enumToInt(level) <= @enumToInt(std.log.Level.crit))35//! else => if (@enumToInt(level) <= @enumToInt(std.log.Level.err))
36//! @tagName(scope)36//! @tagName(scope)
37//! else37//! else
38//! return,38//! return,
39//! } ++ "): ";39//! } ++ "): ";
40//!40//!
41//! const prefix = "[" ++ @tagName(level) ++ "] " ++ scope_prefix;41//! const prefix = "[" ++ level.asText() ++ "] " ++ scope_prefix;
42//!42//!
43//! // Print the message to stderr, silently ignoring any errors43//! // Print the message to stderr, silently ignoring any errors
44//! const held = std.debug.getStderrMutex().acquire();44//! const held = std.debug.getStderrMutex().acquire();
...@@ -49,23 +49,23 @@...@@ -49,23 +49,23 @@
49//!49//!
50//! pub fn main() void {50//! pub fn main() void {
51//! // Using the default scope:51//! // Using the default scope:
52//! std.log.info("Just a simple informational log message", .{}); // Won't be printed as log_level is .warn52//! std.log.debug("A borderline useless debug log message", .{}); // Won't be printed as log_level is .info
53//! std.log.warn("Flux capacitor is starting to overheat", .{});53//! std.log.info("Flux capacitor is starting to overheat", .{});
54//!54//!
55//! // Using scoped logging:55//! // Using scoped logging:
56//! const my_project_log = std.log.scoped(.my_project);56//! const my_project_log = std.log.scoped(.my_project);
57//! const nice_library_log = std.log.scoped(.nice_library);57//! const nice_library_log = std.log.scoped(.nice_library);
58//! const verbose_lib_log = std.log.scoped(.verbose_lib);58//! const verbose_lib_log = std.log.scoped(.verbose_lib);
59//!59//!
60//! my_project_log.info("Starting up", .{}); // Won't be printed as log_level is .warn60//! my_project_log.debug("Starting up", .{}); // Won't be printed as log_level is .info
61//! nice_library_log.err("Something went very wrong, sorry", .{});61//! nice_library_log.warn("Something went very wrong, sorry", .{});
62//! verbose_lib_log.err("Added 1 + 1: {}", .{1 + 1}); // Won't be printed as it gets filtered out by our log function62//! verbose_lib_log.warn("Added 1 + 1: {}", .{1 + 1}); // Won't be printed as it gets filtered out by our log function
63//! }63//! }
64//! ```64//! ```
65//! Which produces the following output:65//! Which produces the following output:
66//! ```66//! ```
67//! [warn] (default): Flux capacitor is starting to overheat67//! [info] (default): Flux capacitor is starting to overheat
68//! [err] (nice_library): Something went very wrong, sorry68//! [warning] (nice_library): Something went very wrong, sorry
69//! ```69//! ```
7070
71const std = @import("std.zig");71const std = @import("std.zig");
...@@ -73,42 +73,29 @@ const builtin = @import("builtin");...@@ -73,42 +73,29 @@ const builtin = @import("builtin");
73const root = @import("root");73const root = @import("root");
7474
75pub const Level = enum {75pub const Level = enum {
76 /// Emergency: a condition that cannot be handled, usually followed by a76 /// Error: something has gone wrong. This might be recoverable or might
77 /// panic.77 /// be followed by the program exiting.
78 emerg,
79 /// Alert: a condition that should be corrected immediately (e.g. database
80 /// corruption).
81 alert,
82 /// Critical: A bug has been detected or something has gone wrong and it
83 /// will have an effect on the operation of the program.
84 crit,
85 /// Error: A bug has been detected or something has gone wrong but it is
86 /// recoverable.
87 err,78 err,
88 /// Warning: it is uncertain if something has gone wrong or not, but the79 /// Warning: it is uncertain if something has gone wrong or not, but the
89 /// circumstances would be worth investigating.80 /// circumstances would be worth investigating.
90 warn,81 warn,
91 /// Notice: non-error but significant conditions.82 /// Info: general messages about the state of the program.
92 notice,
93 /// Informational: general messages about the state of the program.
94 info,83 info,
95 /// Debug: messages only useful for debugging.84 /// Debug: messages only useful for debugging.
96 debug,85 debug,
9786
98 /// Returns a string literal of the given level in full text form.87 /// Returns a string literal of the given level in full text form.
99 pub fn asText(comptime self: Level) switch (self) {88 pub fn asText(comptime self: Level) switch (self) {
100 .emerg => @TypeOf("emergency"),
101 .crit => @TypeOf("critical"),
102 .err => @TypeOf("error"),89 .err => @TypeOf("error"),
103 .warn => @TypeOf("warning"),90 .warn => @TypeOf("warning"),
104 else => @TypeOf(@tagName(self)),91 .info => @TypeOf("info"),
92 .debug => @TypeOf("debug"),
105 } {93 } {
106 return switch (self) {94 return switch (self) {
107 .emerg => "emergency",
108 .crit => "critical",
109 .err => "error",95 .err => "error",
110 .warn => "warning",96 .warn => "warning",
111 else => @tagName(self),97 .info => "info",
98 .debug => "debug",
112 };99 };
113 }100 }
114};101};
...@@ -116,9 +103,8 @@ pub const Level = enum {...@@ -116,9 +103,8 @@ pub const Level = enum {
116/// The default log level is based on build mode.103/// The default log level is based on build mode.
117pub const default_level: Level = switch (builtin.mode) {104pub const default_level: Level = switch (builtin.mode) {
118 .Debug => .debug,105 .Debug => .debug,
119 .ReleaseSafe => .notice,106 .ReleaseSafe => .info,
120 .ReleaseFast => .err,107 .ReleaseFast, .ReleaseSmall => .err,
121 .ReleaseSmall => .err,
122};108};
123109
124/// The current log level. This is set to root.log_level if present, otherwise110/// The current log level. This is set to root.log_level if present, otherwise
...@@ -188,39 +174,18 @@ pub fn defaultLog(...@@ -188,39 +174,18 @@ pub fn defaultLog(
188/// provided here.174/// provided here.
189pub fn scoped(comptime scope: @Type(.EnumLiteral)) type {175pub fn scoped(comptime scope: @Type(.EnumLiteral)) type {
190 return struct {176 return struct {
191 /// Log an emergency message. This log level is intended to be used177 /// Deprecated. TODO: replace with @compileError() after 0.9.0 is released
192 /// for conditions that cannot be handled and is usually followed by a panic.178 pub const emerg = @This().err;
193 pub fn emerg(
194 comptime format: []const u8,
195 args: anytype,
196 ) void {
197 @setCold(true);
198 log(.emerg, scope, format, args);
199 }
200179
201 /// Log an alert message. This log level is intended to be used for180 /// Deprecated. TODO: replace with @compileError() after 0.9.0 is released
202 /// conditions that should be corrected immediately (e.g. database corruption).181 pub const alert = @This().err;
203 pub fn alert(
204 comptime format: []const u8,
205 args: anytype,
206 ) void {
207 @setCold(true);
208 log(.alert, scope, format, args);
209 }
210182
211 /// Log a critical message. This log level is intended to be used183 /// Deprecated. TODO: replace with @compileError() after 0.9.0 is released
212 /// when a bug has been detected or something has gone wrong and it will have184 pub const crit = @This().err;
213 /// an effect on the operation of the program.
214 pub fn crit(
215 comptime format: []const u8,
216 args: anytype,
217 ) void {
218 @setCold(true);
219 log(.crit, scope, format, args);
220 }
221185
222 /// Log an error message. This log level is intended to be used when186 /// Log an error message. This log level is intended to be used
223 /// a bug has been detected or something has gone wrong but it is recoverable.187 /// when something has gone wrong. This might be recoverable or might
188 /// be followed by the program exiting.
224 pub fn err(189 pub fn err(
225 comptime format: []const u8,190 comptime format: []const u8,
226 args: anytype,191 args: anytype,
...@@ -239,14 +204,8 @@ pub fn scoped(comptime scope: @Type(.EnumLiteral)) type {...@@ -239,14 +204,8 @@ pub fn scoped(comptime scope: @Type(.EnumLiteral)) type {
239 log(.warn, scope, format, args);204 log(.warn, scope, format, args);
240 }205 }
241206
242 /// Log a notice message. This log level is intended to be used for207 /// Deprecated. TODO: replace with @compileError() after 0.9.0 is released
243 /// non-error but significant conditions.208 pub const notice = @This().info;
244 pub fn notice(
245 comptime format: []const u8,
246 args: anytype,
247 ) void {
248 log(.notice, scope, format, args);
249 }
250209
251 /// Log an info message. This log level is intended to be used for210 /// Log an info message. This log level is intended to be used for
252 /// general messages about the state of the program.211 /// general messages about the state of the program.
...@@ -271,24 +230,18 @@ pub fn scoped(comptime scope: @Type(.EnumLiteral)) type {...@@ -271,24 +230,18 @@ pub fn scoped(comptime scope: @Type(.EnumLiteral)) type {
271/// The default scoped logging namespace.230/// The default scoped logging namespace.
272pub const default = scoped(.default);231pub const default = scoped(.default);
273232
274/// Log an emergency message using the default scope. This log level is233/// Deprecated. TODO: replace with @compileError() after 0.9.0 is released
275/// intended to be used for conditions that cannot be handled and is usually234pub const emerg = default.err;
276/// followed by a panic.
277pub const emerg = default.emerg;
278235
279/// Log an alert message using the default scope. This log level is intended to236/// Deprecated. TODO: replace with @compileError() after 0.9.0 is released
280/// be used for conditions that should be corrected immediately (e.g. database237pub const alert = default.err;
281/// corruption).
282pub const alert = default.alert;
283238
284/// Log a critical message using the default scope. This log level is intended239/// Deprecated. TODO: replace with @compileError() after 0.9.0 is released
285/// to be used when a bug has been detected or something has gone wrong and it240pub const crit = default.err;
286/// will have an effect on the operation of the program.
287pub const crit = default.crit;
288241
289/// Log an error message using the default scope. This log level is intended to242/// Log an error message using the default scope. This log level is intended to
290/// be used when a bug has been detected or something has gone wrong but it is243/// be used when something has gone wrong. This might be recoverable or might
291/// recoverable.244/// be followed by the program exiting.
292pub const err = default.err;245pub const err = default.err;
293246
294/// Log a warning message using the default scope. This log level is intended247/// Log a warning message using the default scope. This log level is intended
...@@ -296,9 +249,8 @@ pub const err = default.err;...@@ -296,9 +249,8 @@ pub const err = default.err;
296/// the circumstances would be worth investigating.249/// the circumstances would be worth investigating.
297pub const warn = default.warn;250pub const warn = default.warn;
298251
299/// Log a notice message using the default scope. This log level is intended to252/// Deprecated. TODO: replace with @compileError() after 0.9.0 is released
300/// be used for non-error but significant conditions.253pub const notice = default.info;
301pub const notice = default.notice;
302254
303/// Log an info message using the default scope. This log level is intended to255/// Log an info message using the default scope. This log level is intended to
304/// be used for general messages about the state of the program.256/// be used for general messages about the state of the program.
lib/std/zig/parser_test.zig+1-1
...@@ -4398,7 +4398,7 @@ test "zig fmt: regression test for #5722" {...@@ -4398,7 +4398,7 @@ test "zig fmt: regression test for #5722" {
4398 \\ while (it.next()) |node|4398 \\ while (it.next()) |node|
4399 \\ view_tags.append(node.view.current_tags) catch {4399 \\ view_tags.append(node.view.current_tags) catch {
4400 \\ c.wl_resource_post_no_memory(self.wl_resource);4400 \\ c.wl_resource_post_no_memory(self.wl_resource);
4401 \\ log.crit(.river_status, "out of memory", .{});4401 \\ log.err(.river_status, "out of memory", .{});
4402 \\ return;4402 \\ return;
4403 \\ };4403 \\ };
4404 \\}4404 \\}
src/main.zig+3-10
...@@ -27,7 +27,7 @@ const crash_report = @import("crash_report.zig");...@@ -27,7 +27,7 @@ const crash_report = @import("crash_report.zig");
27pub usingnamespace crash_report.root_decls;27pub usingnamespace crash_report.root_decls;
2828
29pub fn fatal(comptime format: []const u8, args: anytype) noreturn {29pub fn fatal(comptime format: []const u8, args: anytype) noreturn {
30 std.log.emerg(format, args);30 std.log.err(format, args);
31 process.exit(1);31 process.exit(1);
32}32}
3333
...@@ -94,7 +94,7 @@ const usage = if (debug_extensions_enabled) debug_usage else normal_usage;...@@ -94,7 +94,7 @@ const usage = if (debug_extensions_enabled) debug_usage else normal_usage;
94pub const log_level: std.log.Level = switch (builtin.mode) {94pub const log_level: std.log.Level = switch (builtin.mode) {
95 .Debug => .debug,95 .Debug => .debug,
96 .ReleaseSafe, .ReleaseFast => .info,96 .ReleaseSafe, .ReleaseFast => .info,
97 .ReleaseSmall => .crit,97 .ReleaseSmall => .err,
98};98};
9999
100var log_scopes: std.ArrayListUnmanaged([]const u8) = .{};100var log_scopes: std.ArrayListUnmanaged([]const u8) = .{};
...@@ -120,14 +120,7 @@ pub fn log(...@@ -120,14 +120,7 @@ pub fn log(
120 } else return;120 } else return;
121 }121 }
122122
123 // We only recognize 4 log levels in this application.123 const prefix1 = comptime level.asText();
124 const level_txt = switch (level) {
125 .emerg, .alert, .crit, .err => "error",
126 .warn => "warning",
127 .notice, .info => "info",
128 .debug => "debug",
129 };
130 const prefix1 = level_txt;
131 const prefix2 = if (scope == .default) ": " else "(" ++ @tagName(scope) ++ "): ";124 const prefix2 = if (scope == .default) ": " else "(" ++ @tagName(scope) ++ "): ";
132125
133 // Print the message to stderr, silently ignoring any errors126 // Print the message to stderr, silently ignoring any errors
test/compare_output.zig+11-31
...@@ -435,8 +435,8 @@ pub fn addCases(cases: *tests.CompareOutputContext) void {...@@ -435,8 +435,8 @@ pub fn addCases(cases: *tests.CompareOutputContext) void {
435 \\pub const log_level: std.log.Level = .debug;435 \\pub const log_level: std.log.Level = .debug;
436 \\436 \\
437 \\pub const scope_levels = [_]std.log.ScopeLevel{437 \\pub const scope_levels = [_]std.log.ScopeLevel{
438 \\ .{ .scope = .a, .level = .alert },438 \\ .{ .scope = .a, .level = .warn },
439 \\ .{ .scope = .c, .level = .emerg },439 \\ .{ .scope = .c, .level = .err },
440 \\};440 \\};
441 \\441 \\
442 \\const loga = std.log.scoped(.a);442 \\const loga = std.log.scoped(.a);
...@@ -452,10 +452,6 @@ pub fn addCases(cases: *tests.CompareOutputContext) void {...@@ -452,10 +452,6 @@ pub fn addCases(cases: *tests.CompareOutputContext) void {
452 \\ logb.info("", .{});452 \\ logb.info("", .{});
453 \\ logc.info("", .{});453 \\ logc.info("", .{});
454 \\454 \\
455 \\ loga.notice("", .{});
456 \\ logb.notice("", .{});
457 \\ logc.notice("", .{});
458 \\
459 \\ loga.warn("", .{});455 \\ loga.warn("", .{});
460 \\ logb.warn("", .{});456 \\ logb.warn("", .{});
461 \\ logc.warn("", .{});457 \\ logc.warn("", .{});
...@@ -463,18 +459,6 @@ pub fn addCases(cases: *tests.CompareOutputContext) void {...@@ -463,18 +459,6 @@ pub fn addCases(cases: *tests.CompareOutputContext) void {
463 \\ loga.err("", .{});459 \\ loga.err("", .{});
464 \\ logb.err("", .{});460 \\ logb.err("", .{});
465 \\ logc.err("", .{});461 \\ logc.err("", .{});
466 \\
467 \\ loga.crit("", .{});
468 \\ logb.crit("", .{});
469 \\ logc.crit("", .{});
470 \\
471 \\ loga.alert("", .{});
472 \\ logb.alert("", .{});
473 \\ logc.alert("", .{});
474 \\
475 \\ loga.emerg("", .{});
476 \\ logb.emerg("", .{});
477 \\ logc.emerg("", .{});
478 \\}462 \\}
479 \\pub fn log(463 \\pub fn log(
480 \\ comptime level: std.log.Level,464 \\ comptime level: std.log.Level,
...@@ -483,22 +467,18 @@ pub fn addCases(cases: *tests.CompareOutputContext) void {...@@ -483,22 +467,18 @@ pub fn addCases(cases: *tests.CompareOutputContext) void {
483 \\ args: anytype,467 \\ args: anytype,
484 \\) void {468 \\) void {
485 \\ const level_txt = comptime level.asText();469 \\ const level_txt = comptime level.asText();
486 \\ const prefix2 = if (scope == .default) ": " else "(" ++ @tagName(scope) ++ "): ";470 \\ const prefix2 = if (scope == .default) ": " else "(" ++ @tagName(scope) ++ "):";
487 \\ const stdout = std.io.getStdOut().writer();471 \\ const stdout = std.io.getStdOut().writer();
488 \\ nosuspend stdout.print(level_txt ++ prefix2 ++ format ++ "\n", args) catch return;472 \\ nosuspend stdout.print(level_txt ++ prefix2 ++ format ++ "\n", args) catch return;
489 \\}473 \\}
490 ,474 ,
491 \\debug(b): 475 \\debug(b):
492 \\info(b): 476 \\info(b):
493 \\notice(b): 477 \\warning(a):
494 \\warning(b): 478 \\warning(b):
495 \\error(b): 479 \\error(a):
496 \\critical(b): 480 \\error(b):
497 \\alert(a): 481 \\error(c):
498 \\alert(b):
499 \\emergency(a):
500 \\emergency(b):
501 \\emergency(c):
502 \\482 \\
503 );483 );
504484
...@@ -534,7 +514,7 @@ pub fn addCases(cases: *tests.CompareOutputContext) void {...@@ -534,7 +514,7 @@ pub fn addCases(cases: *tests.CompareOutputContext) void {
534 ,514 ,
535 \\debug: alloc - success - len: 10, ptr_align: 1, len_align: 0515 \\debug: alloc - success - len: 10, ptr_align: 1, len_align: 0
536 \\debug: shrink - success - 10 to 5, len_align: 0, buf_align: 1516 \\debug: shrink - success - 10 to 5, len_align: 0, buf_align: 1
537 \\critical: expand - failure: OutOfMemory - 5 to 20, len_align: 0, buf_align: 1517 \\error: expand - failure: OutOfMemory - 5 to 20, len_align: 0, buf_align: 1
538 \\debug: free - success - len: 5518 \\debug: free - success - len: 5
539 \\519 \\
540 );520 );