From 2feba3182a36b8e50dc9b7c37d3edb41b8baa058 Mon Sep 17 00:00:00 2001 From: Karl Seguin Date: Sun, 25 May 2025 19:23:53 +0800 Subject: [PATCH] Replace std.log with a structured logger Outputs in logfmt in release and a "pretty" print in debug mode. The format along with the log level will become arguments to the binary at some point in the future. --- build.zig | 13 +- src/app.zig | 7 +- src/browser/console/console.zig | 130 ++++-- src/browser/dom/element.zig | 9 +- src/browser/dom/intersection_observer.zig | 6 +- src/browser/dom/mutation_observer.zig | 36 +- src/browser/dom/node.zig | 5 +- src/browser/dom/nodelist.zig | 6 +- src/browser/dom/token_list.zig | 6 +- src/browser/events/event.zig | 8 +- src/browser/html/window.zig | 9 +- src/browser/page.zig | 68 ++- src/browser/polyfill/polyfill.zig | 13 +- src/browser/session.zig | 7 +- src/browser/storage/cookie.zig | 5 +- src/browser/storage/storage.zig | 7 +- src/browser/xhr/event_target.zig | 9 - src/browser/xhr/form_data.zig | 5 +- src/browser/xhr/xhr.zig | 69 ++-- src/cdp/Node.zig | 5 +- src/cdp/cdp.zig | 26 +- src/cdp/domains/target.zig | 5 +- src/http/client.zig | 28 +- src/log.zig | 480 ++++++++++++++++++++++ src/main.zig | 72 ++-- src/notification.zig | 9 +- src/runtime/js.zig | 24 +- src/runtime/loop.zig | 7 +- src/server.zig | 25 +- src/telemetry/lightpanda.zig | 6 +- src/telemetry/telemetry.zig | 12 +- 31 files changed, 792 insertions(+), 325 deletions(-) create mode 100644 src/log.zig diff --git a/build.zig b/build.zig index a2fef6b6..65c3bef6 100644 --- a/build.zig +++ b/build.zig @@ -44,11 +44,14 @@ pub fn build(b: *std.Build) !void { b.option([]const u8, "git_commit", "Current git commit") orelse "dev", ); - opts.addOption( - std.log.Level, - "log_level", - b.option(std.log.Level, "log_level", "The log level") orelse std.log.Level.info, - ); + { + const log = @import("src/log.zig"); + opts.addOption( + log.Level, + "log_level", + b.option(log.Level, "log_level", "The log level") orelse .info, + ); + } opts.addOption( bool, diff --git a/src/app.zig b/src/app.zig index d4e05a5c..2501d832 100644 --- a/src/app.zig +++ b/src/app.zig @@ -1,13 +1,12 @@ const std = @import("std"); const Allocator = std.mem.Allocator; +const log = @import("log.zig"); const Loop = @import("runtime/loop.zig").Loop; const HttpClient = @import("http/client.zig").Client; const Telemetry = @import("telemetry/telemetry.zig").Telemetry; const Notification = @import("notification.zig").Notification; -const log = std.log.scoped(.app); - // Container for global state / objects that various parts of the system // might need. pub const App = struct { @@ -84,7 +83,7 @@ fn getAndMakeAppDir(allocator: Allocator) ?[]const u8 { return allocator.dupe(u8, "/tmp") catch unreachable; } const app_dir_path = std.fs.getAppDataDir(allocator, "lightpanda") catch |err| { - log.warn("failed to get lightpanda data dir: {}", .{err}); + log.warn(.app, "get data dir", .{ .err = err }); return null; }; @@ -92,7 +91,7 @@ fn getAndMakeAppDir(allocator: Allocator) ?[]const u8 { error.PathAlreadyExists => return app_dir_path, else => { allocator.free(app_dir_path); - log.warn("failed to create lightpanda data dir: {}", .{err}); + log.warn(.app, "create data dir", .{ .err = err, .path = app_dir_path }); return null; }, }; diff --git a/src/browser/console/console.zig b/src/browser/console/console.zig index 55a2585e..c2aba944 100644 --- a/src/browser/console/console.zig +++ b/src/browser/console/console.zig @@ -22,7 +22,7 @@ const builtin = @import("builtin"); const JsObject = @import("../env.zig").Env.JsObject; const SessionState = @import("../env.zig").SessionState; -const log = if (builtin.is_test) &test_capture else std.log.scoped(.console); +const log = if (builtin.is_test) &test_capture else @import("../../log.zig"); pub const Console = struct { // TODO: configurable writer @@ -33,7 +33,7 @@ pub const Console = struct { if (values.len == 0) { return; } - log.info("{s}", .{try serializeValues(values, state)}); + log.info(.console, "info", .{ .args = try serializeValues(values, state) }); } pub fn _info(console: *const Console, values: []JsObject, state: *SessionState) !void { @@ -44,21 +44,21 @@ pub const Console = struct { if (values.len == 0) { return; } - log.debug("{s}", .{try serializeValues(values, state)}); + log.debug(.console, "debug", .{ .args = try serializeValues(values, state) }); } pub fn _warn(_: *const Console, values: []JsObject, state: *SessionState) !void { if (values.len == 0) { return; } - log.warn("{s}", .{try serializeValues(values, state)}); + log.warn(.console, "warn", .{ .args = try serializeValues(values, state) }); } pub fn _error(_: *const Console, values: []JsObject, state: *SessionState) !void { if (values.len == 0) { return; } - log.err("{s}", .{try serializeValues(values, state)}); + log.info(.console, "error", .{ .args = try serializeValues(values, state) }); } pub fn _clear(_: *const Console) void {} @@ -77,17 +77,16 @@ pub const Console = struct { const count = current + 1; gop.value_ptr.* = count; - log.info("{s}: {d}", .{ label, count }); + log.info(.console, "count", .{ .label = label, .count = count }); } pub fn _countReset(self: *Console, label_: ?[]const u8) !void { const label = label_ orelse "default"; const kv = self.counts.fetchRemove(label) orelse { - log.warn("Counter \"{s}\" doesn't exist.", .{label}); + log.info(.console, "invalid counter", .{ .label = label }); return; }; - - log.info("{s}: {d}", .{ label, kv.value }); + log.info(.console, "count reset", .{ .label = label, .count = kv.value }); } pub fn _time(self: *Console, label_: ?[]const u8, state: *SessionState) !void { @@ -95,7 +94,7 @@ pub const Console = struct { const gop = try self.timers.getOrPut(state.arena, label); if (gop.found_existing) { - log.warn("Timer \"{s}\" already exists.", .{label}); + log.info(.console, "duplicate timer", .{ .label = label }); return; } gop.key_ptr.* = try state.arena.dupe(u8, label); @@ -106,22 +105,21 @@ pub const Console = struct { const elapsed = timestamp(); const label = label_ orelse "default"; const start = self.timers.get(label) orelse { - log.warn("Timer \"{s}\" doesn't exist.", .{label}); + log.info(.console, "invalid timer", .{ .label = label }); return; }; - - log.info("\"{s}\": {d}ms", .{ label, elapsed - start }); + log.info(.console, "timer", .{ .label = label, .elapsed = elapsed - start }); } pub fn _timeStop(self: *Console, label_: ?[]const u8) void { const elapsed = timestamp(); const label = label_ orelse "default"; const kv = self.timers.fetchRemove(label) orelse { - log.warn("Timer \"{s}\" doesn't exist.", .{label}); + log.info(.console, "invalid timer", .{ .label = label }); return; }; - log.info("\"{s}\": {d}ms - timer ended", .{ label, elapsed - kv.value }); + log.warn(.console, "timer stop", .{ .label = label, .elapsed = elapsed - kv.value }); } pub fn _assert(_: *Console, assertion: JsObject, values: []JsObject, state: *SessionState) !void { @@ -132,7 +130,7 @@ pub const Console = struct { if (values.len > 0) { serialized_values = try serializeValues(values, state); } - log.err("Assertion failed: {s}", .{serialized_values}); + log.info(.console, "assertion failed", .{ .values = serialized_values }); } fn serializeValues(values: []JsObject, state: *SessionState) ![]const u8 { @@ -155,11 +153,11 @@ fn timestamp() u32 { var test_capture = TestCapture{}; const testing = @import("../../testing.zig"); test "Browser.Console" { + defer testing.reset(); + var runner = try testing.jsRunner(testing.tracking_allocator, .{}); defer runner.deinit(); - defer testing.reset(); - { try runner.testCases(&.{ .{ "console.log('a')", "undefined" }, @@ -167,8 +165,8 @@ test "Browser.Console" { }, .{}); const captured = test_capture.captured.items; - try testing.expectEqual("a", captured[0]); - try testing.expectEqual("hello world 23 true [object Object]", captured[1]); + try testing.expectEqual("[info] args=a", captured[0]); + try testing.expectEqual("[warn] args=hello world 23 true [object Object]", captured[1]); } { @@ -186,15 +184,15 @@ test "Browser.Console" { }, .{}); const captured = test_capture.captured.items; - try testing.expectEqual("Counter \"default\" doesn't exist.", captured[0]); - try testing.expectEqual("default: 1", captured[1]); - try testing.expectEqual("teg: 1", captured[2]); - try testing.expectEqual("teg: 2", captured[3]); - try testing.expectEqual("teg: 3", captured[4]); - try testing.expectEqual("default: 2", captured[5]); - try testing.expectEqual("teg: 3", captured[6]); - try testing.expectEqual("default: 2", captured[7]); - try testing.expectEqual("default: 1", captured[8]); + try testing.expectEqual("[invalid counter] label=default", captured[0]); + try testing.expectEqual("[count] label=default count=1", captured[1]); + try testing.expectEqual("[count] label=teg count=1", captured[2]); + try testing.expectEqual("[count] label=teg count=2", captured[3]); + try testing.expectEqual("[count] label=teg count=3", captured[4]); + try testing.expectEqual("[count] label=default count=2", captured[5]); + try testing.expectEqual("[count reset] label=teg count=3", captured[6]); + try testing.expectEqual("[count reset] label=default count=2", captured[7]); + try testing.expectEqual("[count] label=default count=1", captured[8]); } { @@ -208,12 +206,11 @@ test "Browser.Console" { }, .{}); const captured = test_capture.captured.items; - try testing.expectEqual("Assertion failed: ", captured[0]); - try testing.expectEqual("Assertion failed: x true", captured[1]); - try testing.expectEqual("Assertion failed: x", captured[2]); + try testing.expectEqual("[assertion failed] values=", captured[0]); + try testing.expectEqual("[assertion failed] values=x true", captured[1]); + try testing.expectEqual("[assertion failed] values=x", captured[2]); } } - const TestCapture = struct { captured: std.ArrayListUnmanaged([]const u8) = .{}, @@ -221,20 +218,69 @@ const TestCapture = struct { self.captured = .{}; } - fn debug(self: *TestCapture, comptime fmt: []const u8, args: anytype) void { - const str = std.fmt.allocPrint(testing.arena_allocator, fmt, args) catch unreachable; - self.captured.append(testing.arena_allocator, str) catch unreachable; + fn debug( + self: *TestCapture, + comptime scope: @Type(.enum_literal), + comptime msg: []const u8, + args: anytype, + ) void { + self.capture(scope, msg, args); } - fn info(self: *TestCapture, comptime fmt: []const u8, args: anytype) void { - self.debug(fmt, args); + fn info( + self: *TestCapture, + comptime scope: @Type(.enum_literal), + comptime msg: []const u8, + args: anytype, + ) void { + self.capture(scope, msg, args); } - fn warn(self: *TestCapture, comptime fmt: []const u8, args: anytype) void { - self.debug(fmt, args); + fn warn( + self: *TestCapture, + comptime scope: @Type(.enum_literal), + comptime msg: []const u8, + args: anytype, + ) void { + self.capture(scope, msg, args); } - fn err(self: *TestCapture, comptime fmt: []const u8, args: anytype) void { - self.debug(fmt, args); + fn err( + self: *TestCapture, + comptime scope: @Type(.enum_literal), + comptime msg: []const u8, + args: anytype, + ) void { + self.capture(scope, msg, args); + } + + fn capture( + self: *TestCapture, + comptime scope: @Type(.enum_literal), + comptime msg: []const u8, + args: anytype, + ) void { + self._capture(scope, msg, args) catch unreachable; + } + + fn _capture( + self: *TestCapture, + comptime scope: @Type(.enum_literal), + comptime msg: []const u8, + args: anytype, + ) !void { + std.debug.assert(scope == .console); + + const allocator = testing.arena_allocator; + var buf: std.ArrayListUnmanaged(u8) = .empty; + try buf.appendSlice(allocator, "[" ++ msg ++ "] "); + + inline for (@typeInfo(@TypeOf(args)).@"struct".fields) |f| { + try buf.appendSlice(allocator, f.name); + try buf.append(allocator, '='); + try @import("../../log.zig").writeValue(allocator, &buf, false, @field(args, f.name)); + try buf.append(allocator, ' '); + } + self.captured.append(testing.arena_allocator, std.mem.trimRight(u8, buf.items, " ")) catch unreachable; } }; diff --git a/src/browser/dom/element.zig b/src/browser/dom/element.zig index 6ab4dbfd..976025d6 100644 --- a/src/browser/dom/element.zig +++ b/src/browser/dom/element.zig @@ -21,9 +21,10 @@ const std = @import("std"); const parser = @import("../netsurf.zig"); const SessionState = @import("../env.zig").SessionState; -const collection = @import("html_collection.zig"); -const dump = @import("../dump.zig"); const css = @import("css.zig"); +const log = @import("../../log.zig"); +const dump = @import("../dump.zig"); +const collection = @import("html_collection.zig"); const Node = @import("node.zig").Node; const Walker = @import("walker.zig").WalkerDepthFirst; @@ -31,8 +32,6 @@ const NodeList = @import("nodelist.zig").NodeList; const HTMLElem = @import("../html/elements.zig"); pub const Union = @import("../html/elements.zig").Union; -const log = std.log.scoped(.element); - // WEB IDL https://dom.spec.whatwg.org/#element pub const Element = struct { pub const Self = parser.Element; @@ -148,7 +147,7 @@ pub const Element = struct { while (true) { if (try select.match(current)) { if (!current.isElement()) { - log.err("closest: is not an element: {s}", .{try current.tag()}); + log.err(.element, "closest invalid type", .{ .type = try current.tag() }); return null; } return parser.nodeToElement(current.node); diff --git a/src/browser/dom/intersection_observer.zig b/src/browser/dom/intersection_observer.zig index 6510087a..18b02508 100644 --- a/src/browser/dom/intersection_observer.zig +++ b/src/browser/dom/intersection_observer.zig @@ -18,6 +18,7 @@ const std = @import("std"); +const log = @import("../../log.zig"); const parser = @import("../netsurf.zig"); const SessionState = @import("../env.zig").SessionState; @@ -29,8 +30,6 @@ pub const Interfaces = .{ IntersectionObserverEntry, }; -const log = std.log.scoped(.events); - // This is supposed to listen to change between the root and observation targets. // However, our rendered stores everything as 1 pixel sized boxes in a long row that never changes. // As such, there are no changes to intersections between the root and any target. @@ -87,8 +86,7 @@ pub const IntersectionObserver = struct { var result: Env.Function.Result = undefined; self.callback.tryCall(void, .{self.observed_entries.items}, &result) catch { - log.err("intersection observer callback error: {s}", .{result.exception}); - log.debug("stack:\n{s}", .{result.stack orelse "???"}); + log.debug(.int_obs, "callback error", .{ .err = result.exception, .stack = result.stack }); }; } diff --git a/src/browser/dom/mutation_observer.zig b/src/browser/dom/mutation_observer.zig index a7b05a89..e838394b 100644 --- a/src/browser/dom/mutation_observer.zig +++ b/src/browser/dom/mutation_observer.zig @@ -19,6 +19,7 @@ const std = @import("std"); const Allocator = std.mem.Allocator; +const log = @import("../../log.zig"); const parser = @import("../netsurf.zig"); const SessionState = @import("../env.zig").SessionState; @@ -32,8 +33,6 @@ pub const Interfaces = .{ const Walker = @import("../dom/walker.zig").WalkerChildren; -const log = std.log.scoped(.events); - // WEB IDL https://dom.spec.whatwg.org/#interface-mutationobserver pub const MutationObserver = struct { cbk: Env.Function, @@ -115,8 +114,7 @@ pub const MutationObserver = struct { const records = [_]MutationRecord{r.*}; var result: Env.Function.Result = undefined; self.cbk.tryCall(void, .{records}, &result) catch { - log.err("mutation observer callback error: {s}", .{result.exception}); - log.debug("stack:\n{s}", .{result.stack orelse "???"}); + log.debug(.mut_obs, "callback error", .{ .err = result.exception, .stack = result.stack }); }; } } @@ -243,15 +241,16 @@ const Observer = struct { fn handle(en: *parser.EventNode, event: *parser.Event) void { const self: *Observer = @fieldParentPtr("event_node", en); + self._handle(event) catch |err| { + log.err(.mut_obs, "handle error", .{ .err = err }); + }; + } + fn _handle(self: *Observer, event: *parser.Event) !void { var mutation_observer = self.mutation_observer; const node = blk: { - const event_target = parser.eventTarget(event) catch |e| { - log.err("mutation observer event target: {any}", .{e}); - return; - } orelse return; - + const event_target = try parser.eventTarget(event) orelse return; break :blk parser.eventTargetToNode(event_target); }; @@ -260,10 +259,7 @@ const Observer = struct { } const event_type = blk: { - const t = parser.eventType(event) catch |e| { - log.err("mutation observer event type: {any}", .{e}); - return; - }; + const t = try parser.eventType(event); break :blk std.meta.stringToEnum(MutationEventType, t) orelse return; }; @@ -273,9 +269,7 @@ const Observer = struct { .target = self.node, .type = event_type.recordType(), }; - mutation_observer.observed.append(arena, &self.record.?) catch |err| { - log.err("mutation_observer append: {}", .{err}); - }; + try mutation_observer.observed.append(arena, &self.record.?); } var record = &self.record.?; @@ -295,18 +289,12 @@ const Observer = struct { }, .DOMNodeInserted => { if (parser.mutationEventRelatedNode(mutation_event) catch null) |related_node| { - record.added_nodes.append(arena, related_node) catch |e| { - log.err("mutation event handler error: {any}", .{e}); - return; - }; + try record.added_nodes.append(arena, related_node); } }, .DOMNodeRemoved => { if (parser.mutationEventRelatedNode(mutation_event) catch null) |related_node| { - record.removed_nodes.append(arena, related_node) catch |e| { - log.err("mutation event handler error: {any}", .{e}); - return; - }; + try record.removed_nodes.append(arena, related_node); } }, } diff --git a/src/browser/dom/node.zig b/src/browser/dom/node.zig index 14bfe136..ea55fa5f 100644 --- a/src/browser/dom/node.zig +++ b/src/browser/dom/node.zig @@ -18,6 +18,7 @@ const std = @import("std"); +const log = @import("../../log.zig"); const parser = @import("../netsurf.zig"); const generate = @import("../../runtime/generate.zig"); @@ -41,8 +42,6 @@ const Walker = @import("walker.zig").WalkerDepthFirst; const HTML = @import("../html/html.zig"); const HTMLElem = @import("../html/elements.zig"); -const log = std.log.scoped(.node); - // Node interfaces pub const Interfaces = .{ Attr, @@ -270,7 +269,7 @@ pub const Node = struct { // - An Element that is not attached to a document or a shadow tree will return the root of the DOM tree it belongs to pub fn _getRootNode(self: *parser.Node, options: ?struct { composed: bool = false }) !Union { if (options) |options_| if (options_.composed) { - log.warn("getRootNode composed is not implemented yet", .{}); + log.warn(.node, "not implemented", .{ .feature = "getRootNode composed" }); }; return try Node.toInterface(try parser.nodeGetRootNode(self)); } diff --git a/src/browser/dom/nodelist.zig b/src/browser/dom/nodelist.zig index 56cb3e47..602419ec 100644 --- a/src/browser/dom/nodelist.zig +++ b/src/browser/dom/nodelist.zig @@ -18,6 +18,7 @@ const std = @import("std"); +const log = @import("../../log.zig"); const parser = @import("../netsurf.zig"); const JsThis = @import("../env.zig").JsThis; @@ -28,8 +29,6 @@ const Node = @import("node.zig").Node; const U32Iterator = @import("../iterator/iterator.zig").U32Iterator; -const log = std.log.scoped(.nodelist); - const DOMException = @import("exceptions.zig").DOMException; pub const Interfaces = .{ @@ -146,8 +145,7 @@ pub const NodeList = struct { const ii: u32 = @intCast(i); var result: Function.Result = undefined; cbk.tryCall(void, .{ n, ii, self }, &result) catch { - log.err("callback error: {s}", .{result.exception}); - log.debug("stack:\n{s}", .{result.stack orelse "???"}); + log.debug(.node_list, "forEach callback", .{ .err = result.exception, .stack = result.stack }); }; } } diff --git a/src/browser/dom/token_list.zig b/src/browser/dom/token_list.zig index 83e48256..532b9109 100644 --- a/src/browser/dom/token_list.zig +++ b/src/browser/dom/token_list.zig @@ -18,6 +18,7 @@ const std = @import("std"); +const log = @import("../../log.zig"); const parser = @import("../netsurf.zig"); const iterator = @import("../iterator/iterator.zig"); @@ -25,8 +26,6 @@ const Function = @import("../env.zig").Function; const JsObject = @import("../env.zig").JsObject; const DOMException = @import("exceptions.zig").DOMException; -const log = std.log.scoped(.token_list); - pub const Interfaces = .{ DOMTokenList, DOMTokenListIterable, @@ -143,8 +142,7 @@ pub const DOMTokenList = struct { while (try entries._next()) |entry| { var result: Function.Result = undefined; cbk.tryCallWithThis(void, this_arg, .{ entry.@"1", entry.@"0", self }, &result) catch { - log.err("callback error: {s}", .{result.exception}); - log.debug("stack:\n{s}", .{result.stack orelse "???"}); + log.debug(.token_list, "foreach callback error", .{ .err = result.exception, .stack = result.stack }); }; } } diff --git a/src/browser/events/event.zig b/src/browser/events/event.zig index 1dfa1b5a..59f1db0e 100644 --- a/src/browser/events/event.zig +++ b/src/browser/events/event.zig @@ -19,6 +19,7 @@ const std = @import("std"); const Allocator = std.mem.Allocator; +const log = @import("../../log.zig"); const parser = @import("../netsurf.zig"); const Function = @import("../env.zig").Function; const generate = @import("../../runtime/generate.zig"); @@ -30,8 +31,6 @@ const EventTargetUnion = @import("../dom/event_target.zig").Union; const CustomEvent = @import("custom_event.zig").CustomEvent; const ProgressEvent = @import("../xhr/progress_event.zig").ProgressEvent; -const log = std.log.scoped(.events); - // Event interfaces pub const Interfaces = .{ Event, @@ -157,15 +156,14 @@ pub const EventHandler = struct { fn handle(node: *parser.EventNode, event: *parser.Event) void { const ievent = Event.toInterface(event) catch |err| { - log.err("Event.toInterface: {}", .{err}); + log.err(.event, "toInterface error", .{ .err = err }); return; }; const self: *EventHandler = @fieldParentPtr("node", node); var result: Function.Result = undefined; self.callback.tryCall(void, .{ievent}, &result) catch { - log.err("event handler error: {s}", .{result.exception}); - log.debug("stack:\n{s}", .{result.stack orelse "???"}); + log.debug(.event, "handle callback error", .{ .err = result.exception, .stack = result.stack }); }; } }; diff --git a/src/browser/html/window.zig b/src/browser/html/window.zig index d15d834a..164e220a 100644 --- a/src/browser/html/window.zig +++ b/src/browser/html/window.zig @@ -18,6 +18,7 @@ const std = @import("std"); +const log = @import("../../log.zig"); const parser = @import("../netsurf.zig"); const Function = @import("../env.zig").Function; const SessionState = @import("../env.zig").SessionState; @@ -35,8 +36,6 @@ const CSSStyleDeclaration = @import("../cssom/css_style_declaration.zig").CSSSty const storage = @import("../storage/storage.zig"); -const log = std.log.scoped(.window); - // https://dom.spec.whatwg.org/#interface-window-extensions // https://html.spec.whatwg.org/multipage/nav-history-apis.html#window pub const Window = struct { @@ -171,8 +170,7 @@ pub const Window = struct { // Since: When multiple callbacks queued by requestAnimationFrame() begin to fire in a single frame, each receives the same timestamp even though time has passed during the computation of every previous callback's workload. var result: Function.Result = undefined; callback.tryCall(void, .{self.performance._now()}, &result) catch { - log.err("Window.requestAnimationFrame(): {s}", .{result.exception}); - log.debug("stack:\n{s}", .{result.stack orelse "???"}); + log.debug(.window, "requestAnimationFrame error", .{ .err = result.exception, .stack = result.stack }); }; return 99; // not unique, but user cannot make assumptions about it. cancelAnimationFrame will be too late anyway. } @@ -277,8 +275,7 @@ const TimerCallback = struct { var result: Function.Result = undefined; self.cbk.tryCall(void, .{}, &result) catch { - log.err("timeout callback error: {s}", .{result.exception}); - log.debug("stack:\n{s}", .{result.stack orelse "???"}); + log.debug(.window, "timeout callback error", .{ .err = result.exception, .stack = result.stack }); }; if (self.repeat) |r| { diff --git a/src/browser/page.zig b/src/browser/page.zig index d2c2ced9..ed2a2cbd 100644 --- a/src/browser/page.zig +++ b/src/browser/page.zig @@ -35,14 +35,13 @@ const HTMLDocument = @import("html/document.zig").HTMLDocument; const URL = @import("../url.zig").URL; +const log = @import("../log.zig"); const parser = @import("netsurf.zig"); const http = @import("../http/client.zig"); const storage = @import("storage/storage.zig"); const polyfill = @import("polyfill/polyfill.zig"); -const log = std.log.scoped(.page); - // Page navigates to an url. // You can navigates multiple urls with the same page, but you have to call // end() to stop the previous navigation before starting a new one. @@ -130,9 +129,6 @@ pub const Page = struct { pub fn fetchModuleSource(ctx: *anyopaque, specifier: []const u8) !?[]const u8 { const self: *Page = @ptrCast(@alignCast(ctx)); - - log.debug("fetch module: specifier: {s}", .{specifier}); - const base = if (self.current_script) |s| s.src else null; const file_src = blk: { @@ -156,12 +152,12 @@ pub const Page = struct { try self.session.browser.app.loop.run(); if (try_catch.hasCaught() == false) { - log.debug("wait: OK", .{}); + log.debug(.page, "wait complete", .{}); return; } const msg = (try try_catch.err(self.arena)) orelse "unknown"; - log.info("wait error: {s}", .{msg}); + log.err(.page, "wait error", .{ .err = msg }); } pub fn origin(self: *const Page, arena: Allocator) ![]const u8 { @@ -176,7 +172,7 @@ pub const Page = struct { const session = self.session; const notification = session.browser.notification; - log.debug("starting GET {s}", .{request_url}); + log.info(.page, "navigate", .{ .url = request_url, .reason = opts.reason }); // if the url is about:blank, nothing to do. if (std.mem.eql(u8, "about:blank", request_url.raw)) { @@ -215,8 +211,6 @@ pub const Page = struct { // TODO handle fragment in url. try self.window.replaceLocation(.{ .url = try self.url.toWebApi(arena) }); - log.info("GET {any} {d}", .{ self.url, header.status }); - const content_type = header.get("content-type"); const mime: Mime = blk: { @@ -226,12 +220,13 @@ pub const Page = struct { break :blk Mime.sniff(try response.peek()); } orelse .unknown; + log.info(.page, "navigation header", .{ .status = header.status, .content_type = content_type, .charset = mime.charset }); + if (mime.isHTML()) { self.raw_data = null; try self.loadHTMLDoc(&response, mime.charset orelse "utf-8"); try self.processHTMLDoc(); } else { - log.info("non-HTML document: {s}", .{content_type orelse "null"}); var arr: std.ArrayListUnmanaged(u8) = .{}; while (try response.next()) |data| { try arr.appendSlice(arena, try arena.dupe(u8, data)); @@ -244,12 +239,11 @@ pub const Page = struct { .url = &self.url, .timestamp = timestamp(), }); + log.info(.page, "navigation complete", .{}); } // https://html.spec.whatwg.org/#read-html fn loadHTMLDoc(self: *Page, reader: anytype, charset: []const u8) !void { - log.debug("parse html with charset {s}", .{charset}); - const ccharset = try self.arena.dupeZ(u8, charset); const html_doc = try parser.documentHTMLParse(reader, ccharset); @@ -341,13 +335,17 @@ pub const Page = struct { // > page. // https://developer.mozilla.org/en-US/docs/Web/HTML/Element/script#notes try parser.documentHTMLSetCurrentScript(html_doc, @ptrCast(e)); - self.evalScript(&script) catch |err| log.warn("evaljs: {any}", .{err}); + self.evalScript(&script) catch |err| { + log.err(.page, "eval script error", .{ .err = err }); + }; try parser.documentHTMLSetCurrentScript(html_doc, null); } - for (defer_scripts.items) |s| { - try parser.documentHTMLSetCurrentScript(html_doc, @ptrCast(s.element)); - self.evalScript(&s) catch |err| log.warn("evaljs: {any}", .{err}); + for (defer_scripts.items) |script| { + try parser.documentHTMLSetCurrentScript(html_doc, @ptrCast(script.element)); + self.evalScript(&script) catch |err| { + log.err(.page, "eval script error", .{ .err = err }); + }; try parser.documentHTMLSetCurrentScript(html_doc, null); } // dispatch DOMContentLoaded before the transition to "complete", @@ -357,9 +355,11 @@ pub const Page = struct { try HTMLDocument.documentIsLoaded(html_doc, &self.state); // eval async scripts. - for (async_scripts.items) |s| { - try parser.documentHTMLSetCurrentScript(html_doc, @ptrCast(s.element)); - self.evalScript(&s) catch |err| log.warn("evaljs: {any}", .{err}); + for (async_scripts.items) |script| { + try parser.documentHTMLSetCurrentScript(html_doc, @ptrCast(script.element)); + self.evalScript(&script) catch |err| { + log.err(.page, "eval script error", .{ .err = err }); + }; try parser.documentHTMLSetCurrentScript(html_doc, null); } @@ -392,8 +392,6 @@ pub const Page = struct { self.current_script = script; defer self.current_script = null; - log.debug("starting GET {s}", .{src}); - // https://html.spec.whatwg.org/multipage/webappapis.html#fetch-a-classic-script const body = (try self.fetchData(src, null)) orelse { // TODO If el's result is null, then fire an event named error at @@ -415,8 +413,6 @@ pub const Page = struct { // If a base path is given, src is resolved according to the base first. // the caller owns the returned string fn fetchData(self: *const Page, src: []const u8, base: ?[]const u8) !?[]const u8 { - log.debug("starting fetch {s}", .{src}); - const arena = self.arena; // Handle data URIs. @@ -434,6 +430,9 @@ pub const Page = struct { var origin_url = &self.url; const url = try origin_url.resolve(arena, res_src); + log.info(.page, "fetching script", .{ .url = url }); + errdefer |err| log.err(.page, "fetch error", .{ .err = err }); + var request = try self.newHTTPRequest(.GET, &url, .{ .origin_uri = &origin_url.uri, .navigation = false, @@ -444,8 +443,6 @@ pub const Page = struct { var header = response.header; try self.session.cookie_jar.populateFromResponse(&url.uri, &header); - log.info("fetch {any}: {d}", .{ url, header.status }); - if (header.status != 200) { return error.BadStatusCode; } @@ -462,6 +459,7 @@ pub const Page = struct { return null; } + log.info(.page, "fetch complete", .{ .status = header.status, .content_length = arr.items.len }); return arr.items; } @@ -513,7 +511,7 @@ pub const Page = struct { fn windowClicked(node: *parser.EventNode, event: *parser.Event) void { const self: *Page = @fieldParentPtr("window_clicked_event_node", node); self._windowClicked(event) catch |err| { - log.err("window click handler: {}", .{err}); + log.err(.page, "click handler error", .{ .err = err }); }; } @@ -543,15 +541,16 @@ pub const Page = struct { } const DelayedNavigation = struct { - navigate_node: Loop.CallbackNode = .{ .func = DelayedNavigation.delay_navigate }, + navigate_node: Loop.CallbackNode = .{ .func = DelayedNavigation.delayNavigate }, session: *Session, href: []const u8, - fn delay_navigate(node: *Loop.CallbackNode, repeat_delay: *?u63) void { + fn delayNavigate(node: *Loop.CallbackNode, repeat_delay: *?u63) void { _ = repeat_delay; const self: *DelayedNavigation = @fieldParentPtr("navigate_node", node); self.session.pageNavigate(self.href) catch |err| { - log.err("Delayed navigation error {}", .{err}); // TODO: should we trigger a specific event here? + // TODO: should we trigger a specific event here? + log.err(.page, "delayed navigation error", .{ .err = err }); }; } }; @@ -632,17 +631,14 @@ pub const Page = struct { switch (try page.scope.module(body, src)) { .value => |v| break :blk v, .exception => |e| { - log.info("eval module {s}: {s}", .{ - src, - try e.exception(page.arena), - }); + log.warn(.page, "eval module", .{ .src = src, .err = try e.exception(page.arena) }); return error.JsErr; }, } }, } catch { if (try try_catch.err(page.arena)) |msg| { - log.info("eval script {s}: {s}", .{ src, msg }); + log.warn(.page, "eval script", .{ .src = src, .err = msg }); } return error.JsErr; }; @@ -651,7 +647,7 @@ pub const Page = struct { if (self.onload) |onload| { _ = page.scope.exec(onload, "script_on_load") catch { if (try try_catch.err(page.arena)) |msg| { - log.info("eval script onload {s}: {s}", .{ src, msg }); + log.warn(.page, "eval onload", .{ .src = src, .err = msg }); } return error.JsErr; }; diff --git a/src/browser/polyfill/polyfill.zig b/src/browser/polyfill/polyfill.zig index 5ac4a806..03175b12 100644 --- a/src/browser/polyfill/polyfill.zig +++ b/src/browser/polyfill/polyfill.zig @@ -19,11 +19,10 @@ const std = @import("std"); const builtin = @import("builtin"); +const log = @import("../../log.zig"); const Allocator = std.mem.Allocator; const Env = @import("../env.zig").Env; -const log = std.log.scoped(.polyfill); - const modules = [_]struct { name: []const u8, source: []const u8, @@ -37,18 +36,12 @@ pub fn load(allocator: Allocator, scope: *Env.Scope) !void { defer try_catch.deinit(); for (modules) |m| { - const res = scope.exec(m.source, m.name) catch |err| { + _ = scope.exec(m.source, m.name) catch |err| { if (try try_catch.err(allocator)) |msg| { defer allocator.free(msg); - log.err("load {s}: {s}", .{ m.name, msg }); + log.err(.polyfill, "exec error", .{ .name = m.name, .err = msg }); } return err; }; - - if (builtin.mode == .Debug) { - const msg = try res.toString(allocator); - defer allocator.free(msg); - log.debug("load {s}: {s}", .{ m.name, msg }); - } } } diff --git a/src/browser/session.zig b/src/browser/session.zig index 972bff81..28432498 100644 --- a/src/browser/session.zig +++ b/src/browser/session.zig @@ -24,11 +24,10 @@ const Env = @import("env.zig").Env; const Page = @import("page.zig").Page; const Browser = @import("browser.zig").Browser; +const log = @import("../log.zig"); const parser = @import("netsurf.zig"); const storage = @import("storage/storage.zig"); -const log = std.log.scoped(.session); - // Session is like a browser's tab. // It owns the js env and the loader for all the pages of the session. // You can create successively multiple pages for a session, but you must @@ -95,8 +94,8 @@ pub const Session = struct { const page = &self.page.?; try Page.init(page, page_arena.allocator(), self); + log.debug(.session, "create page", .{}); // start JS env - log.debug("start new js scope", .{}); // Inform CDP the main page has been created such that additional context for other Worlds can be created as well self.browser.notification.dispatch(.page_created, page); @@ -115,6 +114,8 @@ pub const Session = struct { // clear netsurf memory arena. parser.deinit(); + + log.debug(.session, "remove page", .{}); } pub fn currentPage(self: *Session) ?*Page { diff --git a/src/browser/storage/cookie.zig b/src/browser/storage/cookie.zig index dc483cf7..a25935ad 100644 --- a/src/browser/storage/cookie.zig +++ b/src/browser/storage/cookie.zig @@ -3,12 +3,11 @@ const Uri = std.Uri; const Allocator = std.mem.Allocator; const ArenaAllocator = std.heap.ArenaAllocator; +const log = @import("../../log.zig"); const http = @import("../../http/client.zig"); const DateTime = @import("../../datetime.zig").DateTime; const public_suffix_list = @import("../../data/public_suffix_list.zig").lookup; -const log = std.log.scoped(.cookie); - pub const LookupOpts = struct { request_time: ?i64 = null, origin_uri: ?*const Uri = null, @@ -156,7 +155,7 @@ pub const Jar = struct { var it = header.iterate("set-cookie"); while (it.next()) |set_cookie| { const c = Cookie.parse(self.allocator, uri, set_cookie) catch |err| { - log.warn("Couldn't parse cookie '{s}': {}\n", .{ set_cookie, err }); + log.warn(.cookie, "parse failed", .{ .raw = set_cookie, .err = err }); continue; }; try self.add(c, now); diff --git a/src/browser/storage/storage.zig b/src/browser/storage/storage.zig index 90a15584..7b00a223 100644 --- a/src/browser/storage/storage.zig +++ b/src/browser/storage/storage.zig @@ -20,8 +20,6 @@ const std = @import("std"); const DOMError = @import("../netsurf.zig").DOMError; -const log = std.log.scoped(.storage); - pub const cookie = @import("cookie.zig"); pub const Cookie = cookie.Cookie; pub const CookieJar = cookie.Jar; @@ -149,10 +147,7 @@ pub const Bottle = struct { } pub fn _setItem(self: *Bottle, k: []const u8, v: []const u8) !void { - const gop = self.map.getOrPut(self.alloc, k) catch |e| { - log.debug("set item: {any}", .{e}); - return DOMError.QuotaExceeded; - }; + const gop = try self.map.getOrPut(self.alloc, k); if (gop.found_existing == false) { gop.key_ptr.* = try self.alloc.dupe(u8, k); diff --git a/src/browser/xhr/event_target.zig b/src/browser/xhr/event_target.zig index 981dd69a..cb6e36e0 100644 --- a/src/browser/xhr/event_target.zig +++ b/src/browser/xhr/event_target.zig @@ -27,8 +27,6 @@ const EventHandler = @import("../events/event.zig").EventHandler; const parser = @import("../netsurf.zig"); const SessionState = @import("../env.zig").SessionState; -const log = std.log.scoped(.xhr); - pub const XMLHttpRequestEventTarget = struct { pub const prototype = *EventTarget; @@ -118,11 +116,4 @@ pub const XMLHttpRequestEventTarget = struct { try self.register(state.arena, "loadend", handler); self.onloadend_cbk = handler; } - - pub fn deinit(self: *XMLHttpRequestEventTarget, state: *SessionState) void { - const arena = state.arena; - parser.eventTargetRemoveAllEventListeners(@as(*parser.EventTarget, @ptrCast(self)), arena) catch |e| { - log.err("remove all listeners: {any}", .{e}); - }; - } }; diff --git a/src/browser/xhr/form_data.zig b/src/browser/xhr/form_data.zig index 14e302ca..ae8a3023 100644 --- a/src/browser/xhr/form_data.zig +++ b/src/browser/xhr/form_data.zig @@ -20,12 +20,11 @@ const std = @import("std"); const Allocator = std.mem.Allocator; +const log = @import("../../log.zig"); const parser = @import("../netsurf.zig"); const iterator = @import("../iterator/iterator.zig"); const SessionState = @import("../env.zig").SessionState; -const log = std.log.scoped(.form_data); - pub const Interfaces = .{ FormData, KeyIterable, @@ -267,7 +266,7 @@ fn collectForm(arena: Allocator, form: *parser.Form, submitter_: ?*parser.Elemen } }, else => { - log.warn("unsupported form element: {s}\n", .{@tagName(tag)}); + log.warn(.form_data, "unsupported element", .{ .tag = @tagName(tag) }); continue; }, } diff --git a/src/browser/xhr/xhr.zig b/src/browser/xhr/xhr.zig index 4dfbc281..9dc71036 100644 --- a/src/browser/xhr/xhr.zig +++ b/src/browser/xhr/xhr.zig @@ -24,6 +24,7 @@ const DOMError = @import("../netsurf.zig").DOMError; const ProgressEvent = @import("progress_event.zig").ProgressEvent; const XMLHttpRequestEventTarget = @import("event_target.zig").XMLHttpRequestEventTarget; +const log = @import("../../log.zig"); const URL = @import("../../url.zig").URL; const Mime = @import("../mime.zig").Mime; const parser = @import("../netsurf.zig"); @@ -31,8 +32,6 @@ const http = @import("../../http/client.zig"); const SessionState = @import("../env.zig").SessionState; const CookieJar = @import("../storage/storage.zig").CookieJar; -const log = std.log.scoped(.xhr); - // XHR interfaces // https://xhr.spec.whatwg.org/#interface-xmlhttprequest pub const Interfaces = .{ @@ -82,8 +81,6 @@ pub const XMLHttpRequest = struct { arena: Allocator, request: ?http.Request = null, - priv_state: PrivState = .new, - method: http.Request.Method, state: State, url: ?URL = null, @@ -272,8 +269,6 @@ pub const XMLHttpRequest = struct { self.response_status = 0; self.send_flag = false; - - self.priv_state = .new; } pub fn get_readyState(self: *XMLHttpRequest) u16 { @@ -323,8 +318,6 @@ pub const XMLHttpRequest = struct { const arena = self.arena; self.url = try self.origin_url.resolve(arena, url); - - log.debug("open url ({s})", .{self.url.?}); self.sync = if (asyn) |b| !b else false; self.state = .opened; @@ -334,19 +327,19 @@ pub const XMLHttpRequest = struct { // dispatch request event. // errors are logged only. fn dispatchEvt(self: *XMLHttpRequest, typ: []const u8) void { - const evt = parser.eventCreate() catch |e| { - return log.err("dispatch event create: {any}", .{e}); + log.debug(.xhr, "dispatch event", .{ .type = typ }); + self._dispatchEvt(typ) catch |err| { + log.err(.xhr, "dispatch event error", .{ .err = err, .type = typ }); }; + } + fn _dispatchEvt(self: *XMLHttpRequest, typ: []const u8) !void { + const evt = try parser.eventCreate(); // We can we defer event destroy once the event is dispatched. defer parser.eventDestroy(evt); - parser.eventInit(evt, typ, .{ .bubbles = true, .cancelable = true }) catch |e| { - return log.err("dispatch event init: {any}", .{e}); - }; - _ = parser.eventTargetDispatchEvent(@as(*parser.EventTarget, @ptrCast(self)), evt) catch |e| { - return log.err("dispatch event: {any}", .{e}); - }; + try parser.eventInit(evt, typ, .{ .bubbles = true, .cancelable = true }); + _ = try parser.eventTargetDispatchEvent(@as(*parser.EventTarget, @ptrCast(self)), evt); } fn dispatchProgressEvent( @@ -354,22 +347,28 @@ pub const XMLHttpRequest = struct { typ: []const u8, opts: ProgressEvent.EventInit, ) void { - log.debug("dispatch progress event: {s}", .{typ}); - var evt = ProgressEvent.constructor(typ, .{ + log.debug(.xhr, "dispatch progress event", .{ .type = typ }); + self._dispatchProgressEvent(typ, opts) catch |err| { + log.err(.xhr, "dispatch progress event error", .{ .err = err, .type = typ }); + }; + } + + fn _dispatchProgressEvent( + self: *XMLHttpRequest, + typ: []const u8, + opts: ProgressEvent.EventInit, + ) !void { + var evt = try ProgressEvent.constructor(typ, .{ // https://xhr.spec.whatwg.org/#firing-events-using-the-progressevent-interface .lengthComputable = opts.total > 0, .total = opts.total, .loaded = opts.loaded, - }) catch |e| { - return log.err("construct progress event: {any}", .{e}); - }; + }); - _ = parser.eventTargetDispatchEvent( + _ = try parser.eventTargetDispatchEvent( @as(*parser.EventTarget, @ptrCast(self)), @as(*parser.Event, @ptrCast(&evt)), - ) catch |e| { - return log.err("dispatch progress event: {any}", .{e}); - }; + ); } const methods = [_]struct { @@ -413,10 +412,9 @@ pub const XMLHttpRequest = struct { if (self.state != .opened) return DOMError.InvalidState; if (self.send_flag) return DOMError.InvalidState; - log.debug("{any} {any}", .{ self.method, self.url }); + log.info(.xhr, "request", .{ .method = self.method, .url = self.url }); self.send_flag = true; - self.priv_state = .open; self.request = try session_state.request_factory.create(self.method, &self.url.?.uri); var request = &self.request.?; @@ -460,10 +458,8 @@ pub const XMLHttpRequest = struct { if (progress.first) { const header = progress.header; - log.info("{any} {any} {d}", .{ self.method, self.url, header.status }); - - self.priv_state = .done; + log.info(.xhr, "request header", .{ .status = header.status }); for (header.headers.items) |hdr| { try self.response_headers.append(hdr.name, hdr.value); } @@ -509,6 +505,8 @@ pub const XMLHttpRequest = struct { return; } + log.info(.xhr, "request complete", .{}); + self.state = .done; self.send_flag = false; self.dispatchEvt("readystatechange"); @@ -520,16 +518,13 @@ pub const XMLHttpRequest = struct { } fn onErr(self: *XMLHttpRequest, err: anyerror) void { - self.priv_state = .done; - - self.err = err; self.state = .done; self.send_flag = false; self.dispatchEvt("readystatechange"); self.dispatchProgressEvent("error", .{}); self.dispatchProgressEvent("loadend", .{}); - log.debug("{any} {any} {any}", .{ self.method, self.url, self.err }); + log.warn(.xhr, "error", .{ .method = self.method, .url = self.url, .err = err }); } pub fn _abort(self: *XMLHttpRequest) void { @@ -633,7 +628,7 @@ pub const XMLHttpRequest = struct { // response object to a new ArrayBuffer object representing this’s // received bytes. If this throws an exception, then set this’s // response object to failure and return null. - log.err("response type ArrayBuffer not implemented", .{}); + log.err(.xhr, "not implemented", .{ .feature = "ArrayBuffer resposne type" }); return null; } @@ -642,7 +637,7 @@ pub const XMLHttpRequest = struct { // response object to a new Blob object representing this’s // received bytes with type set to the result of get a final MIME // type for this. - log.err("response type Blob not implemented", .{}); + log.err(.xhr, "not implemented", .{ .feature = "Blog resposne type" }); return null; } @@ -717,7 +712,7 @@ pub const XMLHttpRequest = struct { self.response_bytes.items, .{}, ) catch |e| { - log.err("parse JSON: {}", .{e}); + log.warn(.xhr, "invalid json", .{ .err = e }); self.response_obj = .{ .Failure = {} }; return; }; diff --git a/src/cdp/Node.zig b/src/cdp/Node.zig index 44b8c9f2..81ddc00d 100644 --- a/src/cdp/Node.zig +++ b/src/cdp/Node.zig @@ -19,12 +19,11 @@ const std = @import("std"); const Allocator = std.mem.Allocator; +const log = @import("../log.zig"); const parser = @import("../browser/netsurf.zig"); pub const Id = u32; -const log = std.log.scoped(.cdp_node); - const Node = @This(); id: Id, @@ -213,7 +212,7 @@ pub const Writer = struct { // The only error our jsonStringify method can return is // @TypeOf(w).Error. In other words, our code can't return its own // error, we can only return a writer error. Kinda sucks. - log.err("json stringify: {}", .{err}); + log.err(.cdp, "json stringify", .{ .err = err }); return error.OutOfMemory; }; } diff --git a/src/cdp/cdp.zig b/src/cdp/cdp.zig index e4962b3c..53644410 100644 --- a/src/cdp/cdp.zig +++ b/src/cdp/cdp.zig @@ -20,6 +20,7 @@ const std = @import("std"); const Allocator = std.mem.Allocator; const json = std.json; +const log = @import("../log.zig"); const App = @import("../app.zig").App; const Env = @import("../browser/env.zig").Env; const asUint = @import("../str/parser.zig").asUint; @@ -30,8 +31,6 @@ const Inspector = @import("../browser/env.zig").Env.Inspector; const Incrementing = @import("../id.zig").Incrementing; const Notification = @import("../notification.zig").Notification; -const log = std.log.scoped(.cdp); - pub const URL_BASE = "chrome://newtab/"; pub const LOADER_ID = "LOADERID24DD2FD56CF1EF33C965C79C"; @@ -463,36 +462,25 @@ pub fn BrowserContext(comptime CDP_T: type) type { } pub fn onInspectorResponse(ctx: *anyopaque, _: u32, msg: []const u8) void { - if (std.log.defaultLogEnabled(.debug)) { - // msg should be {"id":,... - std.debug.assert(std.mem.startsWith(u8, msg, "{\"id\":")); - - const id_end = std.mem.indexOfScalar(u8, msg, ',') orelse { - log.warn("invalid inspector response message: {s}", .{msg}); - return; - }; - const id = msg[6..id_end]; - log.debug("Res (inspector) > id {s}", .{id}); - } sendInspectorMessage(@alignCast(@ptrCast(ctx)), msg) catch |err| { - log.err("Failed to send inspector response: {any}", .{err}); + log.err(.cdp, "send inspector response", .{ .err = err }); }; } pub fn onInspectorEvent(ctx: *anyopaque, msg: []const u8) void { - if (std.log.defaultLogEnabled(.debug)) { + if (log.enabled(.cdp, .debug)) { // msg should be {"method":,... std.debug.assert(std.mem.startsWith(u8, msg, "{\"method\":")); const method_end = std.mem.indexOfScalar(u8, msg, ',') orelse { - log.warn("invalid inspector event message: {s}", .{msg}); + log.err(.cdp, "invalid inspector event", .{ .msg = msg }); return; }; const method = msg[10..method_end]; - log.debug("Event (inspector) > method {s}", .{method}); + log.debug(.cdp, "inspector event", .{ .method = method }); } sendInspectorMessage(@alignCast(@ptrCast(ctx)), msg) catch |err| { - log.err("Failed to send inspector event: {any}", .{err}); + log.err(.cdp, "send inspector event", .{ .err = err }); }; } @@ -518,7 +506,7 @@ pub fn BrowserContext(comptime CDP_T: type) type { var buf: std.ArrayListUnmanaged(u8) = .{}; buf.ensureTotalCapacity(arena.allocator(), message_len) catch |err| { - log.err("Failed to expand inspector buffer: {any}", .{err}); + log.err(.cdp, "inspector buffer", .{ .err = err }); return; }; diff --git a/src/cdp/domains/target.zig b/src/cdp/domains/target.zig index fca78351..f6c197ce 100644 --- a/src/cdp/domains/target.zig +++ b/src/cdp/domains/target.zig @@ -17,8 +17,7 @@ // along with this program. If not, see . const std = @import("std"); - -const log = std.log.scoped(.cdp); +const log = @import("../../log.zig"); // TODO: hard coded IDs const LOADER_ID = "LOADERID42AA389647D702B4D805F49A"; @@ -301,7 +300,7 @@ fn sendMessageToTarget(cmd: anytype) !void { }; cmd.cdp.dispatch(cmd.arena, &capture, params.message) catch |err| { - log.err("send message {d} ({s}): {any}", .{ cmd.input.id orelse -1, params.message, err }); + log.err(.cdp, "internal dispatch error", .{ .err = err, .id = cmd.input.id, .message = params.message }); return err; }; diff --git a/src/http/client.zig b/src/http/client.zig index ab8a139f..e4ffde83 100644 --- a/src/http/client.zig +++ b/src/http/client.zig @@ -27,12 +27,11 @@ const MemoryPool = std.heap.MemoryPool; const ArenaAllocator = std.heap.ArenaAllocator; const tls = @import("tls"); +const log = @import("../log.zig"); const IO = @import("../runtime/loop.zig").IO; const Loop = @import("../runtime/loop.zig").Loop; const Notification = @import("../notification.zig").Notification; -const log = std.log.scoped(.http_client); - // We might need to peek at the body to try and sniff the content-type. // While we only need a few bytes, in most cases we need to ignore leading // whitespace, so we want to get a reasonable-sized chunk. @@ -352,7 +351,7 @@ pub const Request = struct { self._client.connection_manager.keepIdle(connection) catch |err| { self.destroyConnection(connection); - log.err("failed to release connection to pool: {}", .{err}); + log.err(.http_client, "release to pool error", .{ .err = err }); }; } @@ -457,7 +456,12 @@ pub const Request = struct { var handler = SyncHandler{ .request = self }; return handler.send() catch |err| { - log.warn("HTTP error: {any} ({any} {any} {d})", .{ err, self.method, self.request_uri, self._redirect_count }); + log.warn(.http_client, "sync error", .{ + .err = err, + .method = self.method, + .url = self.request_uri, + .redirects = self._redirect_count, + }); return err; }; } @@ -526,7 +530,7 @@ pub const Request = struct { .host = self._connect_host, .root_ca = self._client.root_ca, .insecure_skip_verify = self._tls_verify_host == false, - .key_log_callback = tls.config.key_log.callback, + // .key_log_callback = tls.config.key_log.callback, }), }; @@ -603,7 +607,7 @@ pub const Request = struct { // to a GET. self.method = .GET; } - log.info("redirecting to: {any} {any}", .{ self.method, self.request_uri }); + log.debug(.http_client, "redirecting", .{ .method = self.method, .url = self.request_uri }); if (self.body != null and self.method == .GET) { // If we have a body and the method is a GET, then we must be following @@ -1076,7 +1080,12 @@ fn AsyncHandler(comptime H: type, comptime L: type) type { } fn handleError(self: *Self, comptime msg: []const u8, err: anyerror) void { - log.err(msg ++ ": {any} ({any} {any})", .{ err, self.request.method, self.request.request_uri }); + log.err(.http_client, msg, .{ + .err = err, + .method = self.request.method, + .url = self.request.request_uri, + }); + self.handler.onHttpResponse(err) catch {}; // just to be safe self.request._keepalive = false; @@ -1297,7 +1306,10 @@ const SyncHandler = struct { // See CompressedReader for an explanation. This isn't great code. Sorry. if (reader.response.get("content-encoding")) |ce| { if (std.ascii.eqlIgnoreCase(ce, "gzip") == false) { - log.warn("unsupported content encoding '{s}' for: {}", .{ ce, request.request_uri }); + log.warn(.http_client, "unsupported content encoding", .{ + .content_encoding = ce, + .uri = request.request_uri, + }); return error.UnsupportedContentEncoding; } diff --git a/src/log.zig b/src/log.zig new file mode 100644 index 00000000..4fe91324 --- /dev/null +++ b/src/log.zig @@ -0,0 +1,480 @@ +const std = @import("std"); +const builtin = @import("builtin"); +const build_config = @import("build_config"); + +const Thread = std.Thread; +const Allocator = std.mem.Allocator; + +const LogLevel: Level = blk: { + if (builtin.is_test) break :blk .err; + break :blk @enumFromInt(@intFromEnum(build_config.log_level)); +}; + +var pool: Pool = undefined; +pub fn init(allocator: Allocator, opts: Opts) !void { + pool = try Pool.init(allocator, 3, opts); +} + +pub fn deinit(allocator: Allocator) void { + pool.deinit(allocator); +} + +// synchronizes writes to the output +var out_lock: Thread.Mutex = .{}; + +// synchronizes access to last_log +var last_log_lock: Thread.Mutex = .{}; + +pub fn enabled(comptime scope: @Type(.enum_literal), comptime level: Level) bool { + // TODO scope disabling + _ = scope; + return @intFromEnum(level) >= @intFromEnum(LogLevel); +} + +pub const Level = enum { + debug, + info, + warn, + err, + fatal, +}; + +const Opts = struct { + format: Format = if (!builtin.is_test and builtin.mode == .Debug) .pretty else .logfmt, +}; + +pub const Format = enum { + logfmt, + pretty, +}; + +pub fn debug(comptime scope: @Type(.enum_literal), comptime msg: []const u8, data: anytype) void { + log(scope, .debug, msg, data); +} + +pub fn info(comptime scope: @Type(.enum_literal), comptime msg: []const u8, data: anytype) void { + log(scope, .info, msg, data); +} + +pub fn warn(comptime scope: @Type(.enum_literal), comptime msg: []const u8, data: anytype) void { + log(scope, .warn, msg, data); +} + +pub fn err(comptime scope: @Type(.enum_literal), comptime msg: []const u8, data: anytype) void { + log(scope, .err, msg, data); +} + +pub fn fatal(comptime scope: @Type(.enum_literal), comptime msg: []const u8, data: anytype) void { + log(scope, .fatal, msg, data); +} + +pub fn log(comptime scope: @Type(.enum_literal), comptime level: Level, comptime msg: []const u8, data: anytype) void { + if (comptime enabled(scope, level) == false) { + return; + } + const logger = pool.acquire(); + defer pool.release(logger); + logger.log(scope, level, msg, data) catch |log_err| { + std.debug.print("$time={d} $level=fatal $scope={s} $msg=\"log err\" err={s} log_msg=\"{s}\"", .{ timestamp(), @errorName(log_err), @tagName(scope), msg }); + }; +} + +// Generic so that we can test it against an ArrayList +fn LogT(comptime Out: type) type { + return struct { + out: Out, + format: Format, + allocator: Allocator, + buffer: std.ArrayListUnmanaged(u8), + + const Self = @This(); + + fn init(allocator: Allocator, opts: Opts) !Self { + return initTo(allocator, opts, std.io.getStdOut()); + } + + // Used for tests + fn initTo(allocator: Allocator, opts: Opts, out: Out) !Self { + var buffer: std.ArrayListUnmanaged(u8) = .{}; + try buffer.ensureTotalCapacity(allocator, 2048); + + return .{ + .out = out, + .buffer = buffer, + .format = opts.format, + .allocator = allocator, + }; + } + + fn deinit(self: *Self) void { + self.buffer.deinit(self.allocator); + } + + fn log(self: *Self, comptime scope: @Type(.enum_literal), comptime level: Level, comptime msg: []const u8, data: anytype) !void { + comptime { + if (msg.len > 30) { + @compileError("log msg cannot be more than 30 characters: '" ++ msg ++ "'"); + } + if (@tagName(scope).len > 15) { + @compileError("log scope cannot be more than 15 characters: '" ++ @tagName(scope) ++ "'"); + } + for (msg) |b| { + switch (b) { + 'A'...'Z', 'a'...'z', ' ', '0'...'9', '_', '-', '.', '{', '}' => {}, + else => @compileError("log msg contains an invalid character '" ++ msg ++ "'"), + } + } + } + + defer self.buffer.clearRetainingCapacity(); + switch (self.format) { + .logfmt => try self.logfmt(scope, level, msg, data), + .pretty => try self.pretty(scope, level, msg, data), + } + + out_lock.lock(); + defer out_lock.unlock(); + try self.out.writeAll(self.buffer.items); + } + + fn logfmt(self: *Self, comptime scope: @Type(.enum_literal), comptime level: Level, comptime msg: []const u8, data: anytype) !void { + const buffer = &self.buffer; + const allocator = self.allocator; + + buffer.appendSliceAssumeCapacity("$time="); + try std.fmt.format(buffer.writer(allocator), "{d}", .{timestamp()}); + + buffer.appendSliceAssumeCapacity(" $scope="); + buffer.appendSliceAssumeCapacity(@tagName(scope)); + + const level_and_msg = comptime blk: { + const l = if (level == .err) "error" else @tagName(level); + // only wrap msg in quotes if it contains a space + const lm = " $level=" ++ l ++ " $msg="; + if (std.mem.indexOfScalar(u8, msg, ' ') == null) { + break :blk lm ++ msg; + } + break :blk lm ++ "\"" ++ msg ++ "\""; + }; + buffer.appendSliceAssumeCapacity(level_and_msg); + inline for (@typeInfo(@TypeOf(data)).@"struct".fields) |f| { + const key = " " ++ f.name ++ "="; + + // + 5 covers null/true/false + try buffer.ensureUnusedCapacity(allocator, key.len + 5); + buffer.appendSliceAssumeCapacity(key); + try writeValue(allocator, buffer, true, @field(data, f.name)); + } + try buffer.append(allocator, '\n'); + } + + fn pretty(self: *Self, comptime scope: @Type(.enum_literal), comptime level: Level, comptime msg: []const u8, data: anytype) !void { + const buffer = &self.buffer; + const allocator = self.allocator; + + buffer.appendSliceAssumeCapacity(switch (level) { + .debug => "\x1b[0;36mDEBUG\x1b[0m ", + .info => "\x1b[0;32mINFO\x1b[0m ", + .warn => "\x1b[0;33mWARN\x1b[0m ", + .err => "\x1b[0;31mERROR\x1b[0m ", + .fatal => "\x1b[0;35mFATAL\x1b[0m ", + }); + + const prefix = @tagName(scope) ++ " : " ++ msg; + buffer.appendSliceAssumeCapacity(prefix); + + { + // msg.len cannot be > 30, and @tagName(scope).len cannot be > 15 + // so this is safe + const padding = 55 - prefix.len; + for (0..padding / 2) |_| { + buffer.appendSliceAssumeCapacity(" ."); + } + if (@mod(padding, 2) == 1) { + buffer.appendAssumeCapacity(' '); + } + try buffer.writer(allocator).print(" [+{d}ms]", .{elapsed()}); + buffer.appendAssumeCapacity('\n'); + } + + inline for (@typeInfo(@TypeOf(data)).@"struct".fields) |f| { + const key = " " ++ f.name ++ " = "; + + // + 5 covers null/true/false + try buffer.ensureUnusedCapacity(allocator, key.len + 5); + buffer.appendSliceAssumeCapacity(key); + try writeValue(allocator, buffer, false, @field(data, f.name)); + try buffer.append(allocator, '\n'); + } + try buffer.append(allocator, '\n'); + } + }; +} + +const Pool = struct { + loggers: []*Log, + available: usize, + mutex: Thread.Mutex, + cond: Thread.Condition, + + const Self = @This(); + const Log = LogT(std.fs.File); + + pub fn init(allocator: Allocator, count: usize, opts: Opts) !Self { + const loggers = try allocator.alloc(*Log, count); + errdefer allocator.free(loggers); + + var started: usize = 0; + errdefer for (0..started) |i| { + loggers[i].deinit(); + allocator.destroy(loggers[i]); + }; + + const out = std.io.getStdOut(); + for (0..count) |i| { + const logger = try allocator.create(Log); + errdefer allocator.destroy(logger); + logger.* = try Log.initTo(allocator, opts, out); + loggers[i] = logger; + started += 1; + } + + return .{ + .cond = .{}, + .mutex = .{}, + .loggers = loggers, + .available = count, + }; + } + + pub fn deinit(self: *Self, allocator: Allocator) void { + for (self.loggers) |logger| { + logger.deinit(); + allocator.destroy(logger); + } + allocator.free(self.loggers); + } + + pub fn acquire(self: *Self) *Log { + self.mutex.lock(); + while (true) { + const loggers = self.loggers; + const available = self.available; + if (available == 0) { + self.cond.wait(&self.mutex); + continue; + } + const index = available - 1; + const logger = loggers[index]; + self.available = index; + self.mutex.unlock(); + return logger; + } + } + + pub fn release(self: *Self, logger: *Log) void { + self.mutex.lock(); + var loggers = self.loggers; + const available = self.available; + loggers[available] = logger; + self.available = available + 1; + self.mutex.unlock(); + self.cond.signal(); + } +}; + +pub fn writeValue(allocator: Allocator, buffer: *std.ArrayListUnmanaged(u8), escape_string: bool, value: anytype) !void { + const T = @TypeOf(value); + switch (@typeInfo(T)) { + .optional => { + if (value) |v| { + return writeValue(allocator, buffer, escape_string, v); + } + // in _log, we reserved space for a value of up to 5 bytes. + return buffer.appendSliceAssumeCapacity("null"); + }, + .comptime_int, .int, .comptime_float, .float => { + return std.fmt.format(buffer.writer(allocator), "{d}", .{value}); + }, + .bool => { + // in _log, we reserved space for a value of up to 5 bytes. + return buffer.appendSliceAssumeCapacity(if (value) "true" else "false"); + }, + .error_set => return buffer.appendSlice(allocator, @errorName(value)), + .@"enum" => return buffer.appendSlice(allocator, @tagName(value)), + .array => return writeValue(allocator, buffer, escape_string, &value), + .pointer => |ptr| switch (ptr.size) { + .slice => switch (ptr.child) { + u8 => return writeString(allocator, buffer, escape_string, value), + else => {}, + }, + .one => switch (@typeInfo(ptr.child)) { + .array => |arr| if (arr.child == u8) { + return writeString(allocator, buffer, escape_string, value); + }, + else => { + var writer = buffer.writer(allocator); + return writer.print("{}", .{value}); + }, + }, + else => {}, + }, + .@"union" => { + var writer = buffer.writer(allocator); + return writer.print("{}", .{value}); + }, + .@"struct" => { + var writer = buffer.writer(allocator); + return writer.print("{}", .{value}); + }, + else => {}, + } + @compileError("cannot log a: " ++ @typeName(T)); +} + +fn writeString(allocator: Allocator, buffer: *std.ArrayListUnmanaged(u8), escape: bool, value: []const u8) !void { + if (escape == false) { + return buffer.appendSlice(allocator, value); + } + + var space_count: usize = 0; + var escape_count: usize = 0; + var binary_count: usize = 0; + + for (value) |b| { + switch (b) { + '\r', '\n', '"' => escape_count += 1, + ' ' => space_count += 1, + '\t', '!', '#'...'~' => {}, // printable characters + else => binary_count += 1, + } + } + + if (binary_count > 0) { + // TODO: use a different encoding if the ratio of binary data / printable is low + return std.base64.standard_no_pad.Encoder.encodeWriter(buffer.writer(allocator), value); + } + + if (escape_count == 0) { + if (space_count == 0) { + return buffer.appendSlice(allocator, value); + } + try buffer.ensureUnusedCapacity(allocator, 2 + value.len); + buffer.appendAssumeCapacity('"'); + buffer.appendSliceAssumeCapacity(value); + buffer.appendAssumeCapacity('"'); + return; + } + + // + 2 for the quotes + // + escape_count because every character that needs escaping is + 1 + try buffer.ensureUnusedCapacity(allocator, 2 + value.len + escape_count); + + buffer.appendAssumeCapacity('"'); + + var rest = value; + while (rest.len > 0) { + const pos = std.mem.indexOfAny(u8, rest, "\r\n\"") orelse { + buffer.appendSliceAssumeCapacity(rest); + break; + }; + buffer.appendSliceAssumeCapacity(rest[0..pos]); + buffer.appendAssumeCapacity('\\'); + switch (rest[pos]) { + '"' => buffer.appendAssumeCapacity('"'), + '\r' => buffer.appendAssumeCapacity('r'), + '\n' => buffer.appendAssumeCapacity('n'), + else => unreachable, + } + rest = rest[pos + 1 ..]; + } + + buffer.appendAssumeCapacity('"'); +} + +fn timestamp() i64 { + if (comptime @import("builtin").is_test) { + return 1739795092929; + } + return std.time.milliTimestamp(); +} + +var last_log: i64 = 0; +fn elapsed() i64 { + const now = timestamp(); + + last_log_lock.lock(); + const previous = last_log; + last_log = now; + last_log_lock.unlock(); + + if (previous == 0) { + return 0; + } + if (previous > now) { + return 0; + } + return now - previous; +} + +const testing = @import("testing.zig"); +test "log: data" { + var buf: std.ArrayListUnmanaged(u8) = .{}; + defer buf.deinit(testing.allocator); + + var logger = try TestLogger.initTo(testing.allocator, .{ .format = .logfmt }, buf.writer(testing.allocator)); + defer logger.deinit(); + + { + try logger.log(.t_scope, .err, "nope", .{}); + try testing.expectEqual("$time=1739795092929 $scope=t_scope $level=error $msg=nope\n", buf.items); + } + + { + buf.clearRetainingCapacity(); + const string = try testing.allocator.dupe(u8, "spice_must_flow"); + defer testing.allocator.free(string); + + try logger.log(.scope_2, .warn, "a msg", .{ + .cint = 5, + .cfloat = 3.43, + .int = @as(i16, -49), + .float = @as(f32, 0.0003232), + .bt = true, + .bf = false, + .nn = @as(?i32, 33), + .n = @as(?i32, null), + .lit = "over9000!", + .slice = string, + .err = error.Nope, + .level = Level.warn, + }); + + try testing.expectEqual("$time=1739795092929 $scope=scope_2 $level=warn $msg=\"a msg\" " ++ + "cint=5 cfloat=3.43 int=-49 float=0.0003232 bt=true bf=false " ++ + "nn=33 n=null lit=over9000! slice=spice_must_flow " ++ + "err=Nope level=warn\n", buf.items); + } +} + +test "log: string escape" { + var buf: std.ArrayListUnmanaged(u8) = .{}; + defer buf.deinit(testing.allocator); + + var logger = try TestLogger.initTo(testing.allocator, .{ .format = .logfmt }, buf.writer(testing.allocator)); + defer logger.deinit(); + + const prefix = "$time=1739795092929 $scope=scope $level=error $msg=test "; + { + try logger.log(.scope, .err, "test", .{ .string = "hello world" }); + try testing.expectEqual(prefix ++ "string=\"hello world\"\n", buf.items); + } + + { + buf.clearRetainingCapacity(); + try logger.log(.scope, .err, "test", .{ .string = "\n \thi \" \" " }); + try testing.expectEqual(prefix ++ "string=\"\\n \thi \\\" \\\" \"\n", buf.items); + } +} + +const TestLogger = LogT(std.ArrayListUnmanaged(u8).Writer); diff --git a/src/main.zig b/src/main.zig index 1245d741..7dce2ea9 100644 --- a/src/main.zig +++ b/src/main.zig @@ -20,6 +20,7 @@ const std = @import("std"); const builtin = @import("builtin"); const Allocator = std.mem.Allocator; +const log = @import("log.zig"); const server = @import("server.zig"); const App = @import("app.zig").App; const Platform = @import("runtime/js.zig").Platform; @@ -28,16 +29,6 @@ const Browser = @import("browser/browser.zig").Browser; const build_config = @import("build_config"); const parser = @import("browser/netsurf.zig"); -const log = std.log.scoped(.cli); - -pub const std_options = std.Options{ - // Set the log level to info - .log_level = @enumFromInt(@intFromEnum(build_config.log_level)), - - // Define logFn to override the std implementation - .logFn = logFn, -}; - pub fn main() !void { // allocator // - in Debug mode we use the General Purpose Allocator to detect memory leaks @@ -49,6 +40,16 @@ pub fn main() !void { if (gpa.detectLeaks()) std.posix.exit(1); }; + try log.init(alloc, .{}); + defer log.deinit(alloc); + + run(alloc) catch |err| { + log.fatal(.main, "exit", .{ .err = err }); + std.posix.exit(1); + }; +} + +fn run(alloc: Allocator) !void { var args_arena = std.heap.ArenaAllocator.init(alloc); defer args_arena.deinit(); const args = try parseArgs(args_arena.allocator()); @@ -78,19 +79,20 @@ pub fn main() !void { switch (args.mode) { .serve => |opts| { + log.debug(.main, "startup", .{ .mode = "serve" }); const address = std.net.Address.parseIp4(opts.host, opts.port) catch |err| { - log.err("address (host:port) {any}\n", .{err}); + log.fatal(.main, "server address", .{ .err = err, .host = opts.host, .port = opts.port }); return args.printUsageAndExit(false); }; const timeout = std.time.ns_per_s * @as(u64, opts.timeout); server.run(app, address, timeout) catch |err| { - log.err("Server error", .{}); + log.fatal(.main, "server run", .{ .err = err }); return err; }; }, .fetch => |opts| { - log.debug("Fetch mode: url {s}, dump {any}", .{ opts.url, opts.dump }); + log.debug(.main, "startup", .{ .mode = "fetch", .dump = opts.dump, .url = opts.url }); const url = try @import("url.zig").URL.parse(opts.url, null); // browser @@ -104,11 +106,11 @@ pub fn main() !void { _ = page.navigate(url, .{}) catch |err| switch (err) { error.UnsupportedUriScheme, error.UriMissingHost => { - log.err("'{s}' is not a valid URL ({any})\n", .{ url, err }); + log.fatal(.main, "fetch invalid URL", .{ .err = err, .url = url }); return args.printUsageAndExit(false); }, else => { - log.err("'{s}' fetching error ({any})\n", .{ url, err }); + log.fatal(.main, "fetch error", .{ .err = err, .url = url }); return err; }, }; @@ -300,7 +302,7 @@ fn parseServeArgs( while (args.next()) |opt| { if (std.mem.eql(u8, "--host", opt)) { const str = args.next() orelse { - log.err("--host argument requires an value", .{}); + log.fatal(.main, "missing argument value", .{ .arg = "--host" }); return error.InvalidArgument; }; host = try allocator.dupe(u8, str); @@ -309,12 +311,12 @@ fn parseServeArgs( if (std.mem.eql(u8, "--port", opt)) { const str = args.next() orelse { - log.err("--port argument requires an value", .{}); + log.fatal(.main, "missing argument value", .{ .arg = "--port" }); return error.InvalidArgument; }; port = std.fmt.parseInt(u16, str, 10) catch |err| { - log.err("--port value is invalid: {}", .{err}); + log.fatal(.main, "invalid argument value", .{ .arg = "--port", .err = err }); return error.InvalidArgument; }; continue; @@ -322,12 +324,12 @@ fn parseServeArgs( if (std.mem.eql(u8, "--timeout", opt)) { const str = args.next() orelse { - log.err("--timeout argument requires an value", .{}); + log.fatal(.main, "missing argument value", .{ .arg = "--timeout" }); return error.InvalidArgument; }; timeout = std.fmt.parseInt(u16, str, 10) catch |err| { - log.err("--timeout value is invalid: {}", .{err}); + log.fatal(.main, "invalid argument value", .{ .arg = "--timeout", .err = err }); return error.InvalidArgument; }; continue; @@ -340,14 +342,13 @@ fn parseServeArgs( if (std.mem.eql(u8, "--http_proxy", opt)) { const str = args.next() orelse { - log.err("--http_proxy argument requires an value", .{}); + log.fatal(.main, "missing argument value", .{ .arg = "--http_proxy" }); return error.InvalidArgument; }; http_proxy = try std.Uri.parse(try allocator.dupe(u8, str)); continue; } - - log.err("Unknown option to serve command: '{s}'", .{opt}); + log.fatal(.main, "unknown argument", .{ .mode = "serve", .arg = opt }); return error.UnkownOption; } @@ -382,7 +383,7 @@ fn parseFetchArgs( if (std.mem.eql(u8, "--http_proxy", opt)) { const str = args.next() orelse { - log.err("--http_proxy argument requires an value", .{}); + log.fatal(.main, "missing argument value", .{ .arg = "--http_proxy" }); return error.InvalidArgument; }; http_proxy = try std.Uri.parse(try allocator.dupe(u8, str)); @@ -390,19 +391,19 @@ fn parseFetchArgs( } if (std.mem.startsWith(u8, opt, "--")) { - log.err("Unknown option to serve command: '{s}'", .{opt}); + log.fatal(.main, "unknown argument", .{ .mode = "fetch", .arg = opt }); return error.UnkownOption; } if (url != null) { - log.err("Can only fetch 1 URL", .{}); + log.fatal(.main, "duplicate fetch url", .{ .help = "only 1 URL can be specified" }); return error.TooManyURLs; } url = try allocator.dupe(u8, opt); } if (url == null) { - log.err("A URL must be provided to the fetch command", .{}); + log.fatal(.main, "duplicate fetch url", .{ .help = "URL to fetch must be provided" }); return error.MissingURL; } @@ -414,21 +415,6 @@ fn parseFetchArgs( }; } -var verbose: bool = builtin.mode == .Debug; // In debug mode, force verbose. -fn logFn( - comptime level: std.log.Level, - comptime scope: @Type(.enum_literal), - comptime format: []const u8, - args: anytype, -) void { - if (!verbose) { - // hide all messages with level greater of equal to debug level. - if (@intFromEnum(level) >= @intFromEnum(std.log.Level.debug)) return; - } - // default std log function. - std.log.defaultLog(level, scope, format, args); -} - test { std.testing.refAllDecls(@This()); } @@ -436,6 +422,8 @@ test { var test_wg: std.Thread.WaitGroup = .{}; test "tests:beforeAll" { try parser.init(); + try log.init(std.testing.allocator, .{}); + test_wg.startMany(3); _ = try Platform.init(); diff --git a/src/notification.zig b/src/notification.zig index 2e5e8cf6..8ccce0a3 100644 --- a/src/notification.zig +++ b/src/notification.zig @@ -1,13 +1,12 @@ const std = @import("std"); +const log = @import("log.zig"); const URL = @import("url.zig").URL; const page = @import("browser/page.zig"); const http_client = @import("http/client.zig"); const Allocator = std.mem.Allocator; -const log = std.log.scoped(.notification); - const List = std.DoublyLinkedList(Listener); const Node = List.Node; @@ -207,7 +206,11 @@ pub const Notification = struct { const listener = n.data; const func: EventFunc(event) = @alignCast(@ptrCast(listener.func)); func(listener.receiver, data) catch |err| { - log.err("{s} '{s}' dispatch error: {}", .{ listener.struct_name, @tagName(event), err }); + log.err(.notification, "dispatch error", .{ + .err = err, + .event = event, + .listener = listener.struct_name, + }); }; node = n.next; } diff --git a/src/runtime/js.zig b/src/runtime/js.zig index 92b96d66..56c5d8f8 100644 --- a/src/runtime/js.zig +++ b/src/runtime/js.zig @@ -20,13 +20,12 @@ const std = @import("std"); const builtin = @import("builtin"); const v8 = @import("v8"); +const log = @import("../log.zig"); const SubType = @import("subtype.zig").SubType; const Allocator = std.mem.Allocator; const ArenaAllocator = std.heap.ArenaAllocator; -const log = std.log.scoped(.js); - const CALL_ARENA_RETAIN = 1024 * 16; const SCOPE_ARENA_RETAIN = 1024 * 64; @@ -1189,17 +1188,14 @@ pub fn Env(comptime State: type, comptime WebApis: type) type { const self: *Scope = @ptrFromInt(context.getEmbedderData(1).castTo(v8.BigInt).getUint64()); - var buf: [1024]u8 = undefined; - var fba = std.heap.FixedBufferAllocator.init(&buf); - // build the specifier value. const specifier = valueToString( - fba.allocator(), + self.call_arena, .{ .handle = c_specifier.? }, self.isolate, context, ) catch |e| { - log.err("resolveModuleCallback: get ref str: {any}", .{e}); + log.err(.js, "resolve module specifier", .{ .err = e }); return null; }; @@ -1207,12 +1203,12 @@ pub fn Env(comptime State: type, comptime WebApis: type) type { // const referrer_module = if (referrer) |ref| v8.Module{ .handle = ref } else null; const module_loader = self.module_loader; const source = module_loader.func(module_loader.ptr, specifier) catch |err| { - log.err("fetchModuleSource for '{s}' fetch error: {}", .{ specifier, err }); + log.err(.js, "resolve module fetch error", .{ .specifier = specifier, .err = err }); return null; } orelse return null; const m = compileModule(self.isolate, source, specifier) catch |err| { - log.err("fetchModuleSource for '{s}' compile error: {}", .{ specifier, err }); + log.err(.js, "resolve module compile error", .{ .specifier = specifier, .err = err }); return null; }; return m.handle; @@ -1875,7 +1871,7 @@ pub fn Env(comptime State: type, comptime WebApis: type) type { const scope: *Scope = @ptrFromInt(context.getEmbedderData(1).castTo(v8.BigInt).getUint64()); const property = valueToString(scope.call_arena, .{ .handle = c_name.? }, isolate, context) catch "???"; - log.debug("unknwon named property {s}.{s}", .{ @typeName(Struct), property }); + log.debug(.js, "unkown named property", .{ .@"struct" = @typeName(Struct), .property = property }); return v8.Intercepted.No; } }.callback, @@ -2605,9 +2601,13 @@ fn Caller(comptime E: type, comptime State: type) type { const last_js_parameter = params_to_map.len - 1; var is_variadic = false; - errdefer |err| if (std.log.logEnabled(.debug, .js)) { + errdefer |err| if (log.enabled(.js, .debug)) { const args_dump = self.dumpFunctionArgs(info) catch "failed to serialize args"; - log.debug("Failed to call '{s}'. Error: {}.\nArgs:\n{s}", .{ named_function.full_name, err, args_dump }); + log.debug(.js, "function call error", .{ + .name = named_function.full_name, + .err = err, + .args = args_dump, + }); }; { diff --git a/src/runtime/loop.zig b/src/runtime/loop.zig index ae9e1206..0a954e18 100644 --- a/src/runtime/loop.zig +++ b/src/runtime/loop.zig @@ -20,10 +20,9 @@ const std = @import("std"); const builtin = @import("builtin"); const MemoryPool = std.heap.MemoryPool; +const log = @import("../log.zig"); pub const IO = @import("tigerbeetle-io").IO; -const log = std.log.scoped(.loop); - // SingleThreaded I/O Loop based on Tigerbeetle io_uring loop. // On Linux it's using io_uring. // On MacOS and Windows it's using kqueue/IOCP with a ring design. @@ -81,7 +80,7 @@ pub const Loop = struct { // contexts are correcly free. while (self.eventsNb() > 0) { self.io.run_for_ns(10 * std.time.ns_per_ms) catch |err| { - log.err("deinit run tail events: {any}", .{err}); + log.err(.loop, "deinit", .{ .err = err }); break; }; } @@ -176,7 +175,7 @@ pub const Loop = struct { result catch |err| { switch (err) { error.Canceled => {}, - else => log.err("timeout callback: {any}", .{err}), + else => log.err(.loop, "timeout callback error", .{ .err = err }), } return; }; diff --git a/src/server.zig b/src/server.zig index b07adef6..e5b360de 100644 --- a/src/server.zig +++ b/src/server.zig @@ -25,6 +25,7 @@ const posix = std.posix; const Allocator = std.mem.Allocator; const ArenaAllocator = std.heap.ArenaAllocator; +const log = @import("log.zig"); const IO = @import("runtime/loop.zig").IO; const Completion = IO.Completion; const AcceptError = IO.AcceptError; @@ -38,8 +39,6 @@ const CDP = @import("cdp/cdp.zig").CDP; const TimeoutCheck = std.time.ns_per_ms * 100; -const log = std.log.scoped(.server); - const MAX_HTTP_REQUEST_SIZE = 2048; // max message size @@ -67,7 +66,7 @@ const Server = struct { } fn queueAccept(self: *Server) void { - log.info("accepting new conn...", .{}); + log.debug(.server, "accepting connection", .{}); self.loop.io.accept( *Server, self, @@ -84,7 +83,7 @@ const Server = struct { ) void { std.debug.assert(completion == &self.accept_completion); self.doCallbackAccept(result) catch |err| { - log.err("accept error: {any}", .{err}); + log.err(.server, "accept error", .{ .err = err }); self.queueAccept(); }; } @@ -97,7 +96,13 @@ const Server = struct { const client = try self.allocator.create(Client); client.* = Client.init(socket, self); client.start(); - log.info("client connected", .{}); + + if (log.enabled(.server, .info)) { + var address: std.net.Address = undefined; + var socklen: posix.socklen_t = @sizeOf(net.Address); + try std.posix.getsockname(socket, &address.any, &socklen); + log.info(.server, "client connected", .{ .ip = address }); + } } fn releaseClient(self: *Server, client: *Client) void { @@ -250,7 +255,7 @@ pub const Client = struct { } const size = result catch |err| { - log.err("read error: {any}", .{err}); + log.err(.server, "read error", .{ .err = err }); self.close(); return; }; @@ -313,7 +318,7 @@ pub const Client = struct { error.InvalidVersionHeader => self.writeHTTPErrorResponse(400, "Invalid websocket version"), error.InvalidConnectionHeader => self.writeHTTPErrorResponse(400, "Invalid connection header"), else => { - log.err("error processing HTTP request: {any}", .{err}); + log.err(.server, "http 500", .{ .err = err }); self.writeHTTPErrorResponse(500, "Internal Server Error"); }, } @@ -594,6 +599,7 @@ pub const Client = struct { if (result) |_| { if (now().since(self.last_active) >= self.server.timeout) { + log.info(.server, "connection timeout", .{}); if (self.mode == .websocket) { self.send(null, &CLOSE_TIMEOUT) catch {}; } @@ -601,7 +607,7 @@ pub const Client = struct { return; } } else |err| { - log.err("timeout error: {any}", .{err}); + log.err(.server, "timeout error", .{ .err = err }); } self.queueTimeout(); @@ -650,7 +656,7 @@ pub const Client = struct { } const sent = result catch |err| { - log.info("send error: {any}", .{err}); + log.warn(.server, "send error", .{ .err = err }); self.close(); return; }; @@ -1036,6 +1042,7 @@ pub fn run( // accept an connection server.queueAccept(); + log.info(.server, "running", .{ .address = address }); // infinite loop on I/O events, either: // - cmd from incoming connection on server socket diff --git a/src/telemetry/lightpanda.zig b/src/telemetry/lightpanda.zig index 3a336a53..cb7df2df 100644 --- a/src/telemetry/lightpanda.zig +++ b/src/telemetry/lightpanda.zig @@ -5,11 +5,11 @@ const build_config = @import("build_config"); const Thread = std.Thread; const Allocator = std.mem.Allocator; +const log = @import("../log.zig"); const App = @import("../app.zig").App; const telemetry = @import("telemetry.zig"); const HttpClient = @import("../http/client.zig").Client; -const log = std.log.scoped(.telemetry); const URL = "https://telemetry.lightpanda.io"; const MAX_BATCH_SIZE = 20; @@ -83,7 +83,7 @@ pub const LightPanda = struct { const b = self.collectBatch(&batch); self.mutex.unlock(); self.postEvent(b, &arr) catch |err| { - log.warn("Telementry reporting error: {}", .{err}); + log.warn(.telemetry, "post error", .{ .err = err }); }; self.mutex.lock(); } @@ -110,7 +110,7 @@ pub const LightPanda = struct { var res = try req.sendSync(.{}); while (try res.next()) |_| {} if (res.header.status != 200) { - log.warn("server error status: {d}", .{res.header.status}); + log.warn(.telemetry, "server error", .{ .status = res.header.status }); } } diff --git a/src/telemetry/telemetry.zig b/src/telemetry/telemetry.zig index 0a46b6cb..b3bc6b06 100644 --- a/src/telemetry/telemetry.zig +++ b/src/telemetry/telemetry.zig @@ -3,11 +3,11 @@ const builtin = @import("builtin"); const Allocator = std.mem.Allocator; +const log = @import("../log.zig"); const App = @import("../app.zig").App; const Notification = @import("../notification.zig").Notification; const uuidv4 = @import("../id.zig").uuidv4; -const log = std.log.scoped(.telemetry); const IID_FILE = "iid"; pub const Telemetry = TelemetryT(blk: { @@ -32,7 +32,7 @@ fn TelemetryT(comptime P: type) type { pub fn init(app: *App, run_mode: App.RunMode) Self { const disabled = std.process.hasEnvVarConstant("LIGHTPANDA_DISABLE_TELEMETRY"); if (builtin.mode != .Debug and builtin.is_test == false) { - log.info("telemetry {s}", .{if (disabled) "disabled" else "enabled"}); + log.info(.telemetry, "telemetry status", .{ .disabled = disabled }); } return .{ @@ -53,7 +53,7 @@ fn TelemetryT(comptime P: type) type { } const iid: ?[]const u8 = if (self.iid) |*iid| iid else null; self.provider.send(iid, self.run_mode, event) catch |err| { - log.warn("failed to record event: {}", .{err}); + log.warn(.telemetry, "record error", .{ .err = err, .type = @tagName(std.meta.activeTag(event)) }); }; } @@ -94,7 +94,7 @@ fn getOrCreateId(app_dir_path_: ?[]const u8) ?[36]u8 { var buf: [37]u8 = undefined; var dir = std.fs.openDirAbsolute(app_dir_path, .{}) catch |err| { - log.warn("failed to open data directory '{s}': {}", .{ app_dir_path, err }); + log.warn(.telemetry, "data directory open error", .{ .path = app_dir_path, .err = err }); return null; }; defer dir.close(); @@ -102,7 +102,7 @@ fn getOrCreateId(app_dir_path_: ?[]const u8) ?[36]u8 { const data = dir.readFile(IID_FILE, &buf) catch |err| switch (err) { error.FileNotFound => &.{}, else => { - log.warn("failed to open id file: {}", .{err}); + log.warn(.telemetry, "ID read error", .{ .path = app_dir_path, .err = err }); return null; }, }; @@ -115,7 +115,7 @@ fn getOrCreateId(app_dir_path_: ?[]const u8) ?[36]u8 { uuidv4(&id); dir.writeFile(.{ .sub_path = IID_FILE, .data = &id }) catch |err| { - log.warn("failed to write to id file: {}", .{err}); + log.warn(.telemetry, "ID write error", .{ .path = app_dir_path, .err = err }); return null; }; return id;