From c3f3eea7fb096e150b56ca9afb1d780483fca570 Mon Sep 17 00:00:00 2001 From: Karl Seguin Date: Sat, 31 May 2025 20:02:23 +0800 Subject: [PATCH 1/6] Improve logging 1 - Make log_level a runtime option (not a build-time) 2 - Make log_format a runtime option 3 - In Debug mode, allow for log scope filtering Improve the general usability of scopes. Previously, the scope was more or less based on the file that the log was in. Now they are more logically grouped. Consider the case where you want to silence HTTP request information, previously you'd have to filter out the `page`, `xhr` and `http_client` scopes, but that would also elimiate other page, xhr and http_client logs. Now, you can just filter out the `http` scope. --- build.zig | 15 -- src/browser/console/console.zig | 2 +- src/browser/dom/element.zig | 2 +- src/browser/dom/intersection_observer.zig | 6 +- src/browser/dom/mutation_observer.zig | 8 +- src/browser/dom/node.zig | 2 +- src/browser/dom/nodelist.zig | 2 +- src/browser/dom/token_list.zig | 6 +- src/browser/events/event.zig | 8 +- src/browser/html/document.zig | 5 + src/browser/html/window.zig | 14 +- src/browser/page.zig | 40 ++-- src/browser/polyfill/polyfill.zig | 2 +- src/browser/session.zig | 4 +- src/browser/storage/cookie.zig | 2 +- src/browser/xhr/form_data.zig | 4 +- src/browser/xhr/xhr.zig | 32 ++- src/http/client.zig | 2 +- src/log.zig | 128 +++++++----- src/main.zig | 242 +++++++++++++++------- src/notification.zig | 3 +- src/runtime/js.zig | 19 +- src/server.zig | 22 +- 23 files changed, 371 insertions(+), 199 deletions(-) diff --git a/build.zig b/build.zig index 65c3bef60..6f3906f31 100644 --- a/build.zig +++ b/build.zig @@ -44,21 +44,6 @@ pub fn build(b: *std.Build) !void { b.option([]const u8, "git_commit", "Current git commit") orelse "dev", ); - { - 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, - "log_unknown_properties", - b.option(bool, "log_unknown_properties", "Log access to unknown properties") orelse false, - ); - const target = b.standardTargetOptions(.{}); const optimize = b.standardOptimizeOption(.{}); diff --git a/src/browser/console/console.zig b/src/browser/console/console.zig index 1edbc6128..2d8571033 100644 --- a/src/browser/console/console.zig +++ b/src/browser/console/console.zig @@ -278,7 +278,7 @@ const TestCapture = struct { inline for (@typeInfo(@TypeOf(args)).@"struct".fields) |f| { try buf.appendSlice(allocator, f.name); try buf.append(allocator, '='); - try @import("../../log.zig").writeValue(false, @field(args, f.name), buf.writer(allocator)); + try @import("../../log.zig").writeValue(.pretty, @field(args, f.name), buf.writer(allocator)); 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 c3a7e545b..f640686d3 100644 --- a/src/browser/dom/element.zig +++ b/src/browser/dom/element.zig @@ -147,7 +147,7 @@ pub const Element = struct { while (true) { if (try select.match(current)) { if (!current.isElement()) { - log.err(.element, "closest invalid type", .{ .type = try current.tag() }); + log.err(.browser, "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 12de3bae4..c14c5faac 100644 --- a/src/browser/dom/intersection_observer.zig +++ b/src/browser/dom/intersection_observer.zig @@ -86,7 +86,11 @@ pub const IntersectionObserver = struct { var result: Env.Function.Result = undefined; self.callback.tryCall(void, .{self.observed_entries.items}, &result) catch { - log.debug(.int_obs, "callback error", .{ .err = result.exception, .stack = result.stack }); + log.debug(.user_script, "callback error", .{ + .err = result.exception, + .stack = result.stack, + .source = "intersection observer", + }); }; } diff --git a/src/browser/dom/mutation_observer.zig b/src/browser/dom/mutation_observer.zig index c651c851f..f5394ba8d 100644 --- a/src/browser/dom/mutation_observer.zig +++ b/src/browser/dom/mutation_observer.zig @@ -114,7 +114,11 @@ pub const MutationObserver = struct { const records = [_]MutationRecord{r.*}; var result: Env.Function.Result = undefined; self.cbk.tryCall(void, .{records}, &result) catch { - log.debug(.mut_obs, "callback error", .{ .err = result.exception, .stack = result.stack }); + log.debug(.user_script, "callback error", .{ + .err = result.exception, + .stack = result.stack, + .source = "mutation observer", + }); }; } } @@ -242,7 +246,7 @@ 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 }); + log.err(.web_api, "handle error", .{ .err = err, .source = "mutation observer" }); }; } diff --git a/src/browser/dom/node.zig b/src/browser/dom/node.zig index 90ee72d01..78a9e1f09 100644 --- a/src/browser/dom/node.zig +++ b/src/browser/dom/node.zig @@ -269,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(.node, "not implemented", .{ .feature = "getRootNode composed" }); + log.warn(.web_api, "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 602419ecf..56194c2fa 100644 --- a/src/browser/dom/nodelist.zig +++ b/src/browser/dom/nodelist.zig @@ -145,7 +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.debug(.node_list, "forEach callback", .{ .err = result.exception, .stack = result.stack }); + log.debug(.user_script, "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 532b91096..6f12c4065 100644 --- a/src/browser/dom/token_list.zig +++ b/src/browser/dom/token_list.zig @@ -142,7 +142,11 @@ 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.debug(.token_list, "foreach callback error", .{ .err = result.exception, .stack = result.stack }); + log.debug(.user_script, "callback error", .{ + .err = result.exception, + .stack = result.stack, + .soure = "tokenList foreach", + }); }; } } diff --git a/src/browser/events/event.zig b/src/browser/events/event.zig index fcbede39f..1a75f116b 100644 --- a/src/browser/events/event.zig +++ b/src/browser/events/event.zig @@ -237,14 +237,18 @@ pub const EventHandler = struct { fn handle(node: *parser.EventNode, event: *parser.Event) void { const ievent = Event.toInterface(event) catch |err| { - log.err(.event, "toInterface error", .{ .err = err }); + log.err(.app, "toInterface error", .{ .err = err }); return; }; const self: *EventHandler = @fieldParentPtr("node", node); var result: Function.Result = undefined; self.callback.tryCall(void, .{ievent}, &result) catch { - log.debug(.event, "handle callback error", .{ .err = result.exception, .stack = result.stack }); + log.debug(.user_script, "callback error", .{ + .err = result.exception, + .stack = result.stack, + .source = "event handler", + }); }; if (self.once) { diff --git a/src/browser/html/document.zig b/src/browser/html/document.zig index 85926a65e..5c74fe7ee 100644 --- a/src/browser/html/document.zig +++ b/src/browser/html/document.zig @@ -18,6 +18,7 @@ const std = @import("std"); +const log = @import("../../log.zig"); const parser = @import("../netsurf.zig"); const Page = @import("../page.zig").Page; @@ -276,6 +277,10 @@ pub const HTMLDocument = struct { const evt = try parser.eventCreate(); defer parser.eventDestroy(evt); + log.debug(.script_event, "dispatch event", .{ + .type = "DOMContentLoaded", + .source = "document", + }); try parser.eventInit(evt, "DOMContentLoaded", .{ .bubbles = true, .cancelable = true }); _ = try parser.eventTargetDispatchEvent(parser.toEventTarget(parser.DocumentHTML, html_doc), evt); } diff --git a/src/browser/html/window.zig b/src/browser/html/window.zig index afc274102..bd28ed49e 100644 --- a/src/browser/html/window.zig +++ b/src/browser/html/window.zig @@ -174,7 +174,11 @@ 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.debug(.window, "requestAnimationFrame error", .{ .err = result.exception, .stack = result.stack }); + log.debug(.user_script, "callback error", .{ + .err = result.exception, + .stack = result.stack, + .source = "requestAnimationFrame", + }); }; return 99; // not unique, but user cannot make assumptions about it. cancelAnimationFrame will be too late anyway. } @@ -215,7 +219,7 @@ pub const Window = struct { fn createTimeout(self: *Window, cbk: Function, delay_: ?u32, page: *Page, comptime repeat: bool) !u32 { const delay = delay_ orelse 0; if (delay > 5000) { - log.warn(.window, "long timeout ignored", .{ .delay = delay, .interval = repeat }); + log.warn(.user_script, "long timeout ignored", .{ .delay = delay, .interval = repeat }); // self.timer_id is u30, so the largest value we can generate is // 1_073_741_824. Returning 2_000_000_000 makes sure that clients // can call cancelTimer/cancelInterval without breaking anything. @@ -288,7 +292,11 @@ const TimerCallback = struct { var result: Function.Result = undefined; self.cbk.tryCall(void, .{}, &result) catch { - log.debug(.window, "timeout callback error", .{ .err = result.exception, .stack = result.stack }); + log.debug(.user_script, "callback error", .{ + .err = result.exception, + .stack = result.stack, + .source = "window timeout", + }); }; if (self.repeat) |r| { diff --git a/src/browser/page.zig b/src/browser/page.zig index 3e05d5773..5366fb7a7 100644 --- a/src/browser/page.zig +++ b/src/browser/page.zig @@ -164,12 +164,12 @@ pub const Page = struct { try self.session.browser.app.loop.run(); if (try_catch.hasCaught() == false) { - log.debug(.page, "wait complete", .{}); + log.debug(.browser, "page wait complete", .{}); return; } const msg = (try try_catch.err(self.arena)) orelse "unknown"; - log.err(.page, "wait error", .{ .err = msg }); + log.err(.browser, "page wait error", .{ .err = msg }); } pub fn origin(self: *const Page, arena: Allocator) ![]const u8 { @@ -184,7 +184,7 @@ pub const Page = struct { const session = self.session; const notification = session.browser.notification; - log.debug(.page, "navigate", .{ .url = request_url, .reason = opts.reason }); + log.debug(.http, "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)) { @@ -233,7 +233,7 @@ pub const Page = struct { break :blk Mime.sniff(try response.peek()); } orelse .unknown; - log.info(.page, "navigation", .{ + log.info(.http, "navigation", .{ .status = header.status, .content_type = content_type, .charset = mime.charset, @@ -257,7 +257,9 @@ pub const Page = struct { .url = &self.url, .timestamp = timestamp(), }); - log.debug(.page, "navigation complete", .{}); + log.debug(.http, "navigation complete", .{ + .url = request_url, + }); } // https://html.spec.whatwg.org/#read-html @@ -383,6 +385,7 @@ pub const Page = struct { const loadevt = try parser.eventCreate(); defer parser.eventDestroy(loadevt); + log.debug(.script_event, "dispatch event", .{ .type = "load", .source = "page" }); try parser.eventInit(loadevt, "load", .{}); _ = try parser.eventTargetDispatchEvent( parser.toEventTarget(Window, &self.window), @@ -392,7 +395,7 @@ pub const Page = struct { fn evalScript(self: *Page, script: *const Script) void { self.tryEvalScript(script) catch |err| { - log.err(.page, "eval script error", .{ .err = err }); + log.err(.js, "eval script error", .{ .err = err, .src = script.src }); }; } @@ -404,7 +407,7 @@ pub const Page = struct { try parser.documentHTMLSetCurrentScript(html_doc, @ptrCast(script.element)); defer parser.documentHTMLSetCurrentScript(html_doc, null) catch |err| { - log.err(.page, "clear document script", .{ .err = err }); + log.err(.browser, "clear document script", .{ .err = err }); }; const src = script.src orelse { @@ -457,8 +460,8 @@ pub const Page = struct { var origin_url = &self.url; const url = try origin_url.resolve(arena, res_src); - log.debug(.page, "fetching script", .{ .url = url }); - errdefer |err| log.err(.page, "fetch error", .{ .err = err, .url = url }); + log.debug(.http, "fetching script", .{ .url = url }); + errdefer |err| log.err(.http, "fetch error", .{ .err = err, .url = url }); var request = try self.newHTTPRequest(.GET, &url, .{ .origin_uri = &origin_url.uri, @@ -486,7 +489,7 @@ pub const Page = struct { return null; } - log.info(.page, "fetch complete", .{ + log.info(.http, "fetch complete", .{ .url = url, .status = header.status, .content_length = arr.items.len, @@ -542,7 +545,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(.page, "click handler error", .{ .err = err }); + log.err(.browser, "click handler error", .{ .err = err }); }; } @@ -675,7 +678,7 @@ const DelayedNavigation = struct { _ = repeat_delay; const self: *DelayedNavigation = @fieldParentPtr("navigate_node", node); self.session.pageNavigate(self.url, self.opts) catch |err| { - log.err(.page, "delayed navigation error", .{ .err = err, .url = self.url }); + log.err(.browser, "delayed navigation error", .{ .err = err, .url = self.url }); }; } }; @@ -787,14 +790,17 @@ const Script = struct { switch (try page.scope.module(body, src)) { .value => |v| break :blk v, .exception => |e| { - log.warn(.page, "eval module", .{ .src = src, .err = try e.exception(page.arena) }); + log.warn(.user_script, "eval module", .{ + .src = src, + .err = try e.exception(page.arena), + }); return error.JsErr; }, } }, } catch { if (try try_catch.err(page.arena)) |msg| { - log.warn(.page, "eval script", .{ .src = src, .err = msg }); + log.warn(.user_script, "eval script", .{ .src = src, .err = msg }); } try self.executeCallback("onerror", page); return error.JsErr; @@ -811,7 +817,7 @@ const Script = struct { defer try_catch.deinit(); _ = page.scope.exec(str, typ) catch { if (try try_catch.err(page.arena)) |msg| { - log.warn(.page, "script callback", .{ + log.warn(.user_script, "script callback", .{ .src = self.src, .err = msg, .type = typ, @@ -827,7 +833,7 @@ const Script = struct { var result: Env.Function.Result = undefined; f.tryCall(void, .{try Event.toInterface(loadevt)}, &result) catch { - log.warn(.page, "script callback", .{ + log.warn(.user_script, "script callback", .{ .src = self.src, .type = typ, .err = result.exception, @@ -869,7 +875,7 @@ fn timestamp() u32 { pub export fn scriptAddedCallback(ctx: ?*anyopaque, element: ?*parser.Element) callconv(.C) void { const self: *Page = @alignCast(@ptrCast(ctx.?)); var script = Script.init(element.?, self) catch |err| { - log.warn(.page, "script added init error", .{ .err = err }); + log.warn(.browser, "script added init error", .{ .err = err }); return; } orelse return; diff --git a/src/browser/polyfill/polyfill.zig b/src/browser/polyfill/polyfill.zig index 03175b123..5fc41c5d5 100644 --- a/src/browser/polyfill/polyfill.zig +++ b/src/browser/polyfill/polyfill.zig @@ -39,7 +39,7 @@ pub fn load(allocator: Allocator, scope: *Env.Scope) !void { _ = scope.exec(m.source, m.name) catch |err| { if (try try_catch.err(allocator)) |msg| { defer allocator.free(msg); - log.err(.polyfill, "exec error", .{ .name = m.name, .err = msg }); + log.fatal(.app, "polyfill error", .{ .name = m.name, .err = msg }); } return err; }; diff --git a/src/browser/session.zig b/src/browser/session.zig index 532a39078..edc818dbc 100644 --- a/src/browser/session.zig +++ b/src/browser/session.zig @@ -95,7 +95,7 @@ pub const Session = struct { const page = &self.page.?; try Page.init(page, page_arena.allocator(), self); - log.debug(.session, "create page", .{}); + log.debug(.browser, "create page", .{}); // start JS env // 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); @@ -116,7 +116,7 @@ pub const Session = struct { // clear netsurf memory arena. parser.deinit(); - log.debug(.session, "remove page", .{}); + log.debug(.browser, "remove page", .{}); } pub fn currentPage(self: *Session) ?*Page { diff --git a/src/browser/storage/cookie.zig b/src/browser/storage/cookie.zig index c944e8f91..bdd93e3f7 100644 --- a/src/browser/storage/cookie.zig +++ b/src/browser/storage/cookie.zig @@ -155,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(.cookie, "parse failed", .{ .raw = set_cookie, .err = err }); + log.warn(.web_api, "cookie parse failed", .{ .raw = set_cookie, .err = err }); continue; }; try self.add(c, now); diff --git a/src/browser/xhr/form_data.zig b/src/browser/xhr/form_data.zig index ed9e1ebe7..25f31bb54 100644 --- a/src/browser/xhr/form_data.zig +++ b/src/browser/xhr/form_data.zig @@ -148,7 +148,7 @@ pub const FormData = struct { return urlEncode(self, writer); } - log.warn(.form_data, "encoding not supported", .{ .encoding = encoding }); + log.warn(.web_api, "not implemented", .{ .feature = "form data encoding", .encoding = encoding }); return error.EncodingNotSupported; } }; @@ -334,7 +334,7 @@ fn collectForm(form: *parser.Form, submitter_: ?*parser.ElementHTML, page: *Page } }, else => { - log.warn(.form_data, "unsupported element", .{ .tag = @tagName(tag) }); + log.warn(.web_api, "unsupported form element", .{ .tag = @tagName(tag) }); continue; }, } diff --git a/src/browser/xhr/xhr.zig b/src/browser/xhr/xhr.zig index 04cecb72f..d65f9db83 100644 --- a/src/browser/xhr/xhr.zig +++ b/src/browser/xhr/xhr.zig @@ -334,9 +334,9 @@ pub const XMLHttpRequest = struct { // dispatch request event. // errors are logged only. fn dispatchEvt(self: *XMLHttpRequest, typ: []const u8) void { - log.debug(.xhr, "dispatch event", .{ .type = typ }); + log.debug(.script_event, "dispatch event", .{ .type = typ, .source = "xhr" }); self._dispatchEvt(typ) catch |err| { - log.err(.xhr, "dispatch event error", .{ .err = err, .type = typ }); + log.err(.app, "dispatch event error", .{ .err = err, .type = typ, .source = "xhr" }); }; } @@ -354,9 +354,9 @@ pub const XMLHttpRequest = struct { typ: []const u8, opts: ProgressEvent.EventInit, ) void { - log.debug(.xhr, "dispatch progress event", .{ .type = typ }); + log.debug(.script_event, "dispatch progress event", .{ .type = typ, .source = "xhr" }); self._dispatchProgressEvent(typ, opts) catch |err| { - log.err(.xhr, "dispatch progress event error", .{ .err = err, .type = typ }); + log.err(.app, "dispatch progress event error", .{ .err = err, .type = typ, .source = "xhr" }); }; } @@ -419,7 +419,7 @@ pub const XMLHttpRequest = struct { if (self.state != .opened) return DOMError.InvalidState; if (self.send_flag) return DOMError.InvalidState; - log.debug(.xhr, "request", .{ .method = self.method, .url = self.url }); + log.debug(.http, "request", .{ .method = self.method, .url = self.url, .source = "xhr" }); self.send_flag = true; @@ -469,7 +469,11 @@ pub const XMLHttpRequest = struct { if (progress.first) { const header = progress.header; - log.debug(.xhr, "request header", .{ .status = header.status }); + log.debug(.http, "request header", .{ + .source = "xhr", + .url = self.url, + .status = header.status, + }); for (header.headers.items) |hdr| { try self.response_headers.append(hdr.name, hdr.value); } @@ -515,7 +519,8 @@ pub const XMLHttpRequest = struct { return; } - log.info(.xhr, "request complete", .{ + log.info(.http, "request complete", .{ + .source = "xhr", .url = self.url, .status = progress.header.status, }); @@ -541,7 +546,12 @@ pub const XMLHttpRequest = struct { self.dispatchProgressEvent("error", .{}); self.dispatchProgressEvent("loadend", .{}); - log.warn(.xhr, "error", .{ .method = self.method, .url = self.url, .err = err }); + const level: log.Level = if (err == DOMError.Abort) .debug else .err; + log.log(.http, level, "error", .{ + .url = self.url, + .err = err, + .source = "xhr", + }); } pub fn _abort(self: *XMLHttpRequest) void { @@ -646,7 +656,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(.xhr, "not implemented", .{ .feature = "ArrayBuffer resposne type" }); + log.err(.web_api, "not implemented", .{ .feature = "XHR ArrayBuffer resposne type" }); return null; } @@ -655,7 +665,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(.xhr, "not implemented", .{ .feature = "Blog resposne type" }); + log.err(.web_api, "not implemented", .{ .feature = "XHR Blob resposne type" }); return null; } @@ -730,7 +740,7 @@ pub const XMLHttpRequest = struct { self.response_bytes.items, .{}, ) catch |e| { - log.warn(.xhr, "invalid json", .{ .err = e }); + log.warn(.http, "invalid json", .{ .err = e, .url = self.url, .source = "xhr" }); self.response_obj = .{ .Failure = {} }; return; }; diff --git a/src/http/client.zig b/src/http/client.zig index 4aba5fb2e..81b11cd72 100644 --- a/src/http/client.zig +++ b/src/http/client.zig @@ -647,7 +647,7 @@ pub const Request = struct { // to a GET. self.method = .GET; } - log.debug(.http_client, "redirecting", .{ .method = self.method, .url = self.request_uri }); + log.debug(.http, "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 diff --git a/src/log.zig b/src/log.zig index 51764ee97..2bc15e126 100644 --- a/src/log.zig +++ b/src/log.zig @@ -18,30 +18,64 @@ const std = @import("std"); const builtin = @import("builtin"); -const build_config = @import("build_config"); const Thread = std.Thread; const Allocator = std.mem.Allocator; -const log_evel: Level = blk: { - if (builtin.is_test) break :blk .err; - break :blk @enumFromInt(@intFromEnum(build_config.log_level)); +const is_debug = builtin.mode == .Debug; + +pub const Scope = enum { + app, + browser, + cdp, + console, + http, + http_client, + js, + loop, + script_event, + telemetry, + user_script, + unknown_prop, + web_api, + xhr, }; -const format: Format = blk: { - if (builtin.is_test or builtin.mode != .Debug) break :blk .logfmt; - break :blk .pretty; + +const Opts = struct { + format: Format = if (is_debug) .pretty else .logfmt, + level: Level = if (is_debug) .info else .warn, + filter_scopes: []const Scope = &.{.unknown_prop}, }; +pub var opts = Opts{}; + // 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(log_evel); +pub fn enabled(comptime scope: Scope, level: Level) bool { + if (@intFromEnum(level) < @intFromEnum(opts.level)) { + return false; + } + + if (comptime builtin.mode == .Debug) { + for (opts.filter_scopes) |fs| { + if (fs == scope) { + return false; + } + } + } + + return true; +} + +// Ugliness to support complex debug parameters. Could add better support for +// this directly in writeValue, but we [currently] only need this in one place +// and I kind of don't want to encourage / make this easy. +pub fn separator() []const u8 { + return if (opts.format == .pretty) "\n " else "; "; } pub const Level = enum { @@ -57,28 +91,28 @@ pub const Format = enum { pretty, }; -pub fn debug(comptime scope: @Type(.enum_literal), comptime msg: []const u8, data: anytype) void { +pub fn debug(comptime scope: Scope, 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 { +pub fn info(comptime scope: Scope, 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 { +pub fn warn(comptime scope: Scope, 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 { +pub fn err(comptime scope: Scope, 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 { +pub fn fatal(comptime scope: Scope, 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) { +pub fn log(comptime scope: Scope, level: Level, comptime msg: []const u8, data: anytype) void { + if (enabled(scope, level) == false) { return; } @@ -90,14 +124,11 @@ pub fn log(comptime scope: @Type(.enum_literal), comptime level: Level, comptime }; } -fn logTo(comptime scope: @Type(.enum_literal), comptime level: Level, comptime msg: []const u8, data: anytype, out: anytype) !void { +fn logTo(comptime scope: Scope, level: Level, comptime msg: []const u8, data: anytype, out: 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', '_', '-', '.', '{', '}' => {}, @@ -107,39 +138,41 @@ fn logTo(comptime scope: @Type(.enum_literal), comptime level: Level, comptime m } var bw = std.io.bufferedWriter(out); - switch (format) { + switch (opts.format) { .logfmt => try logLogfmt(scope, level, msg, data, bw.writer()), .pretty => try logPretty(scope, level, msg, data, bw.writer()), } bw.flush() catch return; } -fn logLogfmt(comptime scope: @Type(.enum_literal), comptime level: Level, comptime msg: []const u8, data: anytype, writer: anytype) !void { +fn logLogfmt(comptime scope: Scope, level: Level, comptime msg: []const u8, data: anytype, writer: anytype) !void { try writer.writeAll("$time="); try writer.print("{d}", .{timestamp()}); try writer.writeAll(" $scope="); try writer.writeAll(@tagName(scope)); - const level_and_msg = comptime blk: { - const l = if (level == .err) "error" else @tagName(level); + try writer.writeAll(" $level="); + try writer.writeAll(if (level == .err) "error" else @tagName(level)); + + const full_msg = comptime blk: { // only wrap msg in quotes if it contains a space - const lm = " $level=" ++ l ++ " $msg="; + const prefix = " $msg="; if (std.mem.indexOfScalar(u8, msg, ' ') == null) { - break :blk lm ++ msg; + break :blk prefix ++ msg; } - break :blk lm ++ "\"" ++ msg ++ "\""; + break :blk prefix ++ "\"" ++ msg ++ "\""; }; - try writer.writeAll(level_and_msg); + try writer.writeAll(full_msg); inline for (@typeInfo(@TypeOf(data)).@"struct".fields) |f| { const key = " " ++ f.name ++ "="; try writer.writeAll(key); - try writeValue(true, @field(data, f.name), writer); + try writeValue(.logfmt, @field(data, f.name), writer); } try writer.writeByte('\n'); } -fn logPretty(comptime scope: @Type(.enum_literal), comptime level: Level, comptime msg: []const u8, data: anytype, writer: anytype) !void { +fn logPretty(comptime scope: Scope, level: Level, comptime msg: []const u8, data: anytype, writer: anytype) !void { try writer.writeAll(switch (level) { .debug => "\x1b[0;36mDEBUG\x1b[0m ", .info => "\x1b[0;32mINFO\x1b[0m ", @@ -168,18 +201,18 @@ fn logPretty(comptime scope: @Type(.enum_literal), comptime level: Level, compti inline for (@typeInfo(@TypeOf(data)).@"struct".fields) |f| { const key = " " ++ f.name ++ " = "; try writer.writeAll(key); - try writeValue(false, @field(data, f.name), writer); + try writeValue(.pretty, @field(data, f.name), writer); try writer.writeByte('\n'); } try writer.writeByte('\n'); } -pub fn writeValue(escape_string: bool, value: anytype, writer: anytype) !void { +pub fn writeValue(comptime format: Format, value: anytype, writer: anytype) !void { const T = @TypeOf(value); switch (@typeInfo(T)) { .optional => { if (value) |v| { - return writeValue(escape_string, v, writer); + return writeValue(format, v, writer); } return writer.writeAll("null"); }, @@ -191,15 +224,15 @@ pub fn writeValue(escape_string: bool, value: anytype, writer: anytype) !void { }, .error_set => return writer.writeAll(@errorName(value)), .@"enum" => return writer.writeAll(@tagName(value)), - .array => return writeValue(escape_string, &value, writer), + .array => return writeValue(format, &value, writer), .pointer => |ptr| switch (ptr.size) { .slice => switch (ptr.child) { - u8 => return writeString(escape_string, value, writer), + u8 => return writeString(format, value, writer), else => {}, }, .one => switch (@typeInfo(ptr.child)) { .array => |arr| if (arr.child == u8) { - return writeString(escape_string, value, writer); + return writeString(format, value, writer); }, else => return writer.print("{}", .{value}), }, @@ -209,11 +242,12 @@ pub fn writeValue(escape_string: bool, value: anytype, writer: anytype) !void { .@"struct" => return writer.print("{}", .{value}), else => {}, } + @compileError("cannot log a: " ++ @typeName(T)); } -fn writeString(escape: bool, value: []const u8, writer: anytype) !void { - if (escape == false) { +fn writeString(comptime format: Format, value: []const u8, writer: anytype) !void { + if (format == .pretty) { return writer.writeAll(value); } @@ -297,8 +331,8 @@ test "log: data" { defer buf.deinit(testing.allocator); { - try logTo(.t_scope, .err, "nope", .{}, buf.writer(testing.allocator)); - try testing.expectEqual("$time=1739795092929 $scope=t_scope $level=error $msg=nope\n", buf.items); + try logTo(.browser, .err, "nope", .{}, buf.writer(testing.allocator)); + try testing.expectEqual("$time=1739795092929 $scope=browser $level=error $msg=nope\n", buf.items); } { @@ -306,7 +340,7 @@ test "log: data" { const string = try testing.allocator.dupe(u8, "spice_must_flow"); defer testing.allocator.free(string); - try logTo(.scope_2, .warn, "a msg", .{ + try logTo(.http, .warn, "a msg", .{ .cint = 5, .cfloat = 3.43, .int = @as(i16, -49), @@ -321,7 +355,7 @@ test "log: data" { .level = Level.warn, }, buf.writer(testing.allocator)); - try testing.expectEqual("$time=1739795092929 $scope=scope_2 $level=warn $msg=\"a msg\" " ++ + try testing.expectEqual("$time=1739795092929 $scope=http $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); @@ -332,15 +366,15 @@ test "log: string escape" { var buf: std.ArrayListUnmanaged(u8) = .{}; defer buf.deinit(testing.allocator); - const prefix = "$time=1739795092929 $scope=scope $level=error $msg=test "; + const prefix = "$time=1739795092929 $scope=app $level=error $msg=test "; { - try logTo(.scope, .err, "test", .{ .string = "hello world" }, buf.writer(testing.allocator)); + try logTo(.app, .err, "test", .{ .string = "hello world" }, buf.writer(testing.allocator)); try testing.expectEqual(prefix ++ "string=\"hello world\"\n", buf.items); } { buf.clearRetainingCapacity(); - try logTo(.scope, .err, "test", .{ .string = "\n \thi \" \" " }, buf.writer(testing.allocator)); + try logTo(.app, .err, "test", .{ .string = "\n \thi \" \" " }, buf.writer(testing.allocator)); try testing.expectEqual(prefix ++ "string=\"\\n \thi \\\" \\\" \"\n", buf.items); } } diff --git a/src/main.zig b/src/main.zig index 765523ec2..753e84fab 100644 --- a/src/main.zig +++ b/src/main.zig @@ -33,7 +33,7 @@ pub fn main() !void { // allocator // - in Debug mode we use the General Purpose Allocator to detect memory leaks // - in Release mode we use the c allocator - var gpa = std.heap.GeneralPurposeAllocator(.{}){}; + var gpa: std.heap.DebugAllocator(.{}) = .init; const alloc = if (builtin.mode == .Debug) gpa.allocator() else std.heap.c_allocator; defer if (builtin.mode == .Debug) { @@ -41,7 +41,7 @@ pub fn main() !void { }; run(alloc) catch |err| { - log.fatal(.main, "exit", .{ .err = err }); + log.fatal(.app, "exit", .{ .err = err }); std.posix.exit(1); }; } @@ -63,6 +63,16 @@ fn run(alloc: Allocator) !void { else => {}, } + if (args.logLevel()) |ll| { + log.opts.level = ll; + } + if (args.logFormat()) |lf| { + log.opts.format = lf; + } + if (args.logFilterScopes()) |lfs| { + log.opts.filter_scopes = lfs; + } + const platform = try Platform.init(); defer platform.deinit(); @@ -76,20 +86,20 @@ fn run(alloc: Allocator) !void { switch (args.mode) { .serve => |opts| { - log.debug(.main, "startup", .{ .mode = "serve" }); + log.debug(.app, "startup", .{ .mode = "serve" }); const address = std.net.Address.parseIp4(opts.host, opts.port) catch |err| { - log.fatal(.main, "server address", .{ .err = err, .host = opts.host, .port = opts.port }); + log.fatal(.app, "invalid 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.fatal(.main, "server run", .{ .err = err }); + log.fatal(.app, "server run error", .{ .err = err }); return err; }; }, .fetch => |opts| { - log.debug(.main, "startup", .{ .mode = "fetch", .dump = opts.dump, .url = opts.url }); + log.debug(.app, "startup", .{ .mode = "fetch", .dump = opts.dump, .url = opts.url }); const url = try @import("url.zig").URL.parse(opts.url, null); // browser @@ -103,11 +113,11 @@ fn run(alloc: Allocator) !void { _ = page.navigate(url, .{}) catch |err| switch (err) { error.UnsupportedUriScheme, error.UriMissingHost => { - log.fatal(.main, "fetch invalid URL", .{ .err = err, .url = url }); + log.fatal(.app, "invalid fetch URL", .{ .err = err, .url = url }); return args.printUsageAndExit(false); }, else => { - log.fatal(.main, "fetch error", .{ .err = err, .url = url }); + log.fatal(.app, "fetch error", .{ .err = err, .url = url }); return err; }, }; @@ -129,15 +139,36 @@ const Command = struct { fn tlsVerifyHost(self: *const Command) bool { return switch (self.mode) { - inline .serve, .fetch => |opts| opts.tls_verify_host, - else => true, + inline .serve, .fetch => |opts| opts.common.tls_verify_host, + else => unreachable, }; } fn httpProxy(self: *const Command) ?std.Uri { return switch (self.mode) { - inline .serve, .fetch => |opts| opts.http_proxy, - else => null, + inline .serve, .fetch => |opts| opts.common.http_proxy, + else => unreachable, + }; + } + + fn logLevel(self: *const Command) ?log.Level { + return switch (self.mode) { + inline .serve, .fetch => |opts| opts.common.log_level, + else => unreachable, + }; + } + + fn logFormat(self: *const Command) ?log.Format { + return switch (self.mode) { + inline .serve, .fetch => |opts| opts.common.log_format, + else => unreachable, + }; + } + + fn logFilterScopes(self: *const Command) ?[]const log.Scope { + return switch (self.mode) { + inline .serve, .fetch => |opts| opts.common.log_filter_scopes, + else => unreachable, }; } @@ -152,18 +183,47 @@ const Command = struct { host: []const u8, port: u16, timeout: u16, - tls_verify_host: bool, - http_proxy: ?std.Uri, + common: Common, }; const Fetch = struct { url: []const u8, dump: bool = false, - tls_verify_host: bool, - http_proxy: ?std.Uri, + common: Common, + }; + + const Common = struct { + http_proxy: ?std.Uri = null, + tls_verify_host: bool = true, + log_level: ?log.Level = null, + log_format: ?log.Format = null, + log_filter_scopes: ?[]log.Scope = null, }; fn printUsageAndExit(self: *const Command, success: bool) void { + const common_options = + \\ + \\--insecure_disable_tls_host_verification + \\ Disables host verification on all HTTP requests. + \\ This is an advanced option which should only be + \\ set if you understand and accept the risk of + \\ disabling host verification. + \\ + \\--http_proxy The HTTP proxy to use for all HTTP requests. + \\ Defaults to none. + \\ + \\--log_level The log level: debug, info, warn, error or fatal. + \\ Defaults to + ++ (if (builtin.mode == .Debug) " info." else "warn.") ++ + \\ + \\ + \\--log_format The log format: pretty or logfmt. + \\ Defaults to + ++ (if (builtin.mode == .Debug) " pretty." else " logfmt.") ++ + \\ + \\ + ; + const usage = \\usage: {s} command [options] [URL] \\ @@ -177,14 +237,7 @@ const Command = struct { \\--dump Dumps document to stdout. \\ Defaults to false. \\ - \\--insecure_disable_tls_host_verification - \\ Disables host verification on all HTTP requests. - \\ This is an advanced option which should only be - \\ set if you understand and accept the risk of - \\ disabling host verification. - \\ - \\--http_proxy The HTTP proxy to use for all HTTP requests. - \\ Defaults to none. + ++ common_options ++ \\ \\serve command \\Starts a websocket CDP server @@ -200,14 +253,7 @@ const Command = struct { \\--timeout Inactivity timeout in seconds before disconnecting clients \\ Defaults to 3 (seconds) \\ - \\--insecure_disable_tls_host_verification - \\ Disables host verification on all HTTP requests. - \\ This is an advanced option which should only be - \\ set if you understand and accept the risk of - \\ disabling host verification. - \\ - \\--http_proxy The HTTP proxy to use for all HTTP requests. - \\ Defaults to none. + ++ common_options ++ \\ \\version command \\Displays the version of {s} @@ -293,13 +339,12 @@ fn parseServeArgs( var host: []const u8 = "127.0.0.1"; var port: u16 = 9222; var timeout: u16 = 3; - var tls_verify_host = true; - var http_proxy: ?std.Uri = null; + var common: Command.Common = .{}; while (args.next()) |opt| { if (std.mem.eql(u8, "--host", opt)) { const str = args.next() orelse { - log.fatal(.main, "missing argument value", .{ .arg = "--host" }); + log.fatal(.app, "missing argument value", .{ .arg = "--host" }); return error.InvalidArgument; }; host = try allocator.dupe(u8, str); @@ -308,12 +353,12 @@ fn parseServeArgs( if (std.mem.eql(u8, "--port", opt)) { const str = args.next() orelse { - log.fatal(.main, "missing argument value", .{ .arg = "--port" }); + log.fatal(.app, "missing argument value", .{ .arg = "--port" }); return error.InvalidArgument; }; port = std.fmt.parseInt(u16, str, 10) catch |err| { - log.fatal(.main, "invalid argument value", .{ .arg = "--port", .err = err }); + log.fatal(.app, "invalid argument value", .{ .arg = "--port", .err = err }); return error.InvalidArgument; }; continue; @@ -321,40 +366,30 @@ fn parseServeArgs( if (std.mem.eql(u8, "--timeout", opt)) { const str = args.next() orelse { - log.fatal(.main, "missing argument value", .{ .arg = "--timeout" }); + log.fatal(.app, "missing argument value", .{ .arg = "--timeout" }); return error.InvalidArgument; }; timeout = std.fmt.parseInt(u16, str, 10) catch |err| { - log.fatal(.main, "invalid argument value", .{ .arg = "--timeout", .err = err }); + log.fatal(.app, "invalid argument value", .{ .arg = "--timeout", .err = err }); return error.InvalidArgument; }; continue; } - if (std.mem.eql(u8, "--insecure_disable_tls_host_verification", opt)) { - tls_verify_host = false; + if (try parseCommonArg(allocator, opt, args, &common)) { continue; } - if (std.mem.eql(u8, "--http_proxy", opt)) { - const str = args.next() orelse { - 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.fatal(.main, "unknown argument", .{ .mode = "serve", .arg = opt }); + log.fatal(.app, "unknown argument", .{ .mode = "serve", .arg = opt }); return error.UnkownOption; } return .{ .host = host, .port = port, + .common = common, .timeout = timeout, - .http_proxy = http_proxy, - .tls_verify_host = tls_verify_host, }; } @@ -364,8 +399,7 @@ fn parseFetchArgs( ) !Command.Fetch { var dump: bool = false; var url: ?[]const u8 = null; - var tls_verify_host = true; - var http_proxy: ?std.Uri = null; + var common: Command.Common = .{}; while (args.next()) |opt| { if (std.mem.eql(u8, "--dump", opt)) { @@ -373,45 +407,111 @@ fn parseFetchArgs( continue; } - if (std.mem.eql(u8, "--insecure_disable_tls_host_verification", opt)) { - tls_verify_host = false; - continue; - } - - if (std.mem.eql(u8, "--http_proxy", opt)) { - const str = args.next() orelse { - log.fatal(.main, "missing argument value", .{ .arg = "--http_proxy" }); - return error.InvalidArgument; - }; - http_proxy = try std.Uri.parse(try allocator.dupe(u8, str)); + if (try parseCommonArg(allocator, opt, args, &common)) { continue; } if (std.mem.startsWith(u8, opt, "--")) { - log.fatal(.main, "unknown argument", .{ .mode = "fetch", .arg = opt }); + log.fatal(.app, "unknown argument", .{ .mode = "fetch", .arg = opt }); return error.UnkownOption; } if (url != null) { - log.fatal(.main, "duplicate fetch url", .{ .help = "only 1 URL can be specified" }); + log.fatal(.app, "duplicate fetch url", .{ .help = "only 1 URL can be specified" }); return error.TooManyURLs; } url = try allocator.dupe(u8, opt); } if (url == null) { - log.fatal(.main, "duplicate fetch url", .{ .help = "URL to fetch must be provided" }); + log.fatal(.app, "missing fetch url", .{ .help = "URL to fetch must be provided" }); return error.MissingURL; } return .{ .url = url.?, .dump = dump, - .http_proxy = http_proxy, - .tls_verify_host = tls_verify_host, + .common = common, }; } +fn parseCommonArg( + allocator: Allocator, + opt: []const u8, + args: *std.process.ArgIterator, + common: *Command.Common, +) !bool { + if (std.mem.eql(u8, "--insecure_disable_tls_host_verification", opt)) { + common.tls_verify_host = false; + return true; + } + + if (std.mem.eql(u8, "--http_proxy", opt)) { + const str = args.next() orelse { + log.fatal(.app, "missing argument value", .{ .arg = "--http_proxy" }); + return error.InvalidArgument; + }; + common.http_proxy = try std.Uri.parse(try allocator.dupe(u8, str)); + return true; + } + + if (std.mem.eql(u8, "--log_level", opt)) { + const str = args.next() orelse { + log.fatal(.app, "missing argument value", .{ .arg = "--log_level" }); + return error.InvalidArgument; + }; + + common.log_level = std.meta.stringToEnum(log.Level, str) orelse blk: { + if (std.mem.eql(u8, str, "error")) { + break :blk .err; + } + log.fatal(.app, "invalid option choice", .{ .arg = "--log_level", .value = str }); + return error.InvalidArgument; + }; + return true; + } + + if (std.mem.eql(u8, "--log_format", opt)) { + const str = args.next() orelse { + log.fatal(.app, "missing argument value", .{ .arg = "--log_format" }); + return error.InvalidArgument; + }; + + common.log_format = std.meta.stringToEnum(log.Format, str) orelse { + log.fatal(.app, "invalid option choice", .{ .arg = "--log_format", .value = str }); + return error.InvalidArgument; + }; + return true; + } + + if (std.mem.eql(u8, "--log_filter_scopes", opt)) { + if (builtin.mode != .Debug) { + log.fatal(.app, "experimental", .{ .help = "log scope filtering is only available in debug builds" }); + return false; + } + + const str = args.next() orelse { + // disables the default filters + common.log_filter_scopes = &.{}; + return true; + }; + + var arr: std.ArrayListUnmanaged(log.Scope) = .empty; + + var it = std.mem.splitScalar(u8, str, ','); + while (it.next()) |part| { + try arr.append(allocator, std.meta.stringToEnum(log.Scope, part) orelse { + log.fatal(.app, "invalid option choice", .{ .arg = "--log_scope_filter", .value = part }); + return false; + }); + } + common.log_filter_scopes = arr.items; + return true; + } + + return false; +} + test { std.testing.refAllDecls(@This()); } @@ -419,6 +519,8 @@ test { var test_wg: std.Thread.WaitGroup = .{}; test "tests:beforeAll" { try parser.init(); + log.opts.level = .err; + log.opts.format = .logfmt; test_wg.startMany(3); _ = try Platform.init(); diff --git a/src/notification.zig b/src/notification.zig index 8ccce0a3c..5cb198f77 100644 --- a/src/notification.zig +++ b/src/notification.zig @@ -206,9 +206,10 @@ pub const Notification = struct { const listener = n.data; const func: EventFunc(event) = @alignCast(@ptrCast(listener.func)); func(listener.receiver, data) catch |err| { - log.err(.notification, "dispatch error", .{ + log.err(.app, "dispatch error", .{ .err = err, .event = event, + .source = "notification", .listener = listener.struct_name, }); }; diff --git a/src/runtime/js.zig b/src/runtime/js.zig index 7165e3601..9e10a2c83 100644 --- a/src/runtime/js.zig +++ b/src/runtime/js.zig @@ -1851,7 +1851,7 @@ pub fn Env(comptime State: type, comptime WebApis: type) type { fn generateNamedIndexer(comptime Struct: type, template_proto: v8.ObjectTemplate) void { if (@hasDecl(Struct, "named_get") == false) { - if (comptime @import("build_config").log_unknown_properties) { + if (builtin.mode == .Debug and log.enabled(.unknown_prop, .debug)) { generateDebugNamedIndexer(Struct, template_proto); } return; @@ -1899,7 +1899,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(.js, "unkown named property", .{ .@"struct" = @typeName(Struct), .property = property }); + log.debug(.unknown_prop, "unkown property", .{ .@"struct" = @typeName(Struct), .property = property }); return v8.Intercepted.No; } }.callback, @@ -2635,9 +2635,9 @@ 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 (log.enabled(.js, .debug)) { - const args_dump = self.dumpFunctionArgs(info) catch "failed to serialize args"; - log.debug(.js, "function call error", .{ + errdefer |err| if (builtin.mode == .Debug and log.enabled(.js, .warn)) { + const args_dump = self.serializeFunctionArgs(info) catch "failed to serialize args"; + log.warn(.js, "function call error", .{ .name = named_function.full_name, .err = err, .args = args_dump, @@ -2706,7 +2706,7 @@ fn Caller(comptime E: type, comptime State: type) type { return T == State or T == Const_State; } - fn dumpFunctionArgs(self: *const Self, info: anytype) ![]const u8 { + fn serializeFunctionArgs(self: *const Self, info: anytype) ![]const u8 { const isolate = self.isolate; const context = self.context; const arena = self.call_arena; @@ -2717,7 +2717,12 @@ fn Caller(comptime E: type, comptime State: type) type { const js_value = info.getArg(@intCast(i)); const value_string = try valueToDetailString(arena, js_value, isolate, context); const value_type = try jsStringToZig(arena, try js_value.typeOf(isolate), isolate); - try std.fmt.format(arr.writer(arena), "{d}: {s} ({s})\n", .{ i + 1, value_string, value_type }); + try std.fmt.format(arr.writer(arena), "{s}{d}: {s} ({s})", .{ + log.separator(), + i + 1, + value_string, + value_type, + }); } return arr.items; } diff --git a/src/server.zig b/src/server.zig index f365da0d6..a14ff305e 100644 --- a/src/server.zig +++ b/src/server.zig @@ -66,7 +66,7 @@ const Server = struct { } fn queueAccept(self: *Server) void { - log.debug(.server, "accepting connection", .{}); + log.debug(.app, "accepting connection", .{}); self.loop.io.accept( *Server, self, @@ -83,7 +83,7 @@ const Server = struct { ) void { std.debug.assert(completion == &self.accept_completion); self.doCallbackAccept(result) catch |err| { - log.err(.server, "accept error", .{ .err = err }); + log.err(.app, "server accept error", .{ .err = err }); self.queueAccept(); }; } @@ -97,11 +97,11 @@ const Server = struct { client.* = Client.init(socket, self); client.start(); - if (log.enabled(.server, .info)) { + if (log.enabled(.app, .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 }); + log.info(.app, "client connected", .{ .ip = address }); } } @@ -223,7 +223,7 @@ pub const Client = struct { } fn close(self: *Self) void { - log.info(.server, "client disconected", .{}); + log.info(.app, "client disconected", .{}); self.connected = false; // recv only, because we might have pending writes we'd like to get // out (like the HTTP error response) @@ -256,7 +256,7 @@ pub const Client = struct { } const size = result catch |err| { - log.err(.server, "read error", .{ .err = err }); + log.err(.app, "server read error", .{ .err = err }); self.close(); return; }; @@ -319,7 +319,7 @@ pub const Client = struct { error.InvalidVersionHeader => self.writeHTTPErrorResponse(400, "Invalid websocket version"), error.InvalidConnectionHeader => self.writeHTTPErrorResponse(400, "Invalid connection header"), else => { - log.err(.server, "http 500", .{ .err = err }); + log.err(.app, "server 500", .{ .err = err, .req = request[0..@min(100, request.len)] }); self.writeHTTPErrorResponse(500, "Internal Server Error"); }, } @@ -600,7 +600,7 @@ pub const Client = struct { if (result) |_| { if (now().since(self.last_active) >= self.server.timeout) { - log.info(.server, "connection timeout", .{}); + log.info(.app, "client connection timeout", .{}); if (self.mode == .websocket) { self.send(null, &CLOSE_TIMEOUT) catch {}; } @@ -608,7 +608,7 @@ pub const Client = struct { return; } } else |err| { - log.err(.server, "timeout error", .{ .err = err }); + log.err(.app, "server timeout error", .{ .err = err }); } self.queueTimeout(); @@ -657,7 +657,7 @@ pub const Client = struct { } const sent = result catch |err| { - log.warn(.server, "send error", .{ .err = err }); + log.warn(.app, "server send error", .{ .err = err }); self.close(); return; }; @@ -1043,7 +1043,7 @@ pub fn run( // accept an connection server.queueAccept(); - log.info(.server, "running", .{ .address = address }); + log.info(.app, "server running", .{ .address = address }); // infinite loop on I/O events, either: // - cmd from incoming connection on server socket From 6e80b03faa91b8e43d182ea285725950276027d0 Mon Sep 17 00:00:00 2001 From: Karl Seguin Date: Sat, 31 May 2025 21:23:02 +0800 Subject: [PATCH 2/6] Improve script logging 1 - Add a custom console.lp function to make our debug logs stand out from script logs. 2 - In some cases, significantly improve how JavaScript values are serialized in debug logs and in console.log. --- src/browser/console/console.zig | 25 ++++++++++++++---- src/log.zig | 20 ++++++++------ src/runtime/js.zig | 47 ++++++++++++++++++++++++--------- 3 files changed, 66 insertions(+), 26 deletions(-) diff --git a/src/browser/console/console.zig b/src/browser/console/console.zig index 2d8571033..980c6aaa4 100644 --- a/src/browser/console/console.zig +++ b/src/browser/console/console.zig @@ -19,8 +19,9 @@ const std = @import("std"); const builtin = @import("builtin"); -const JsObject = @import("../env.zig").Env.JsObject; +const Allocator = std.mem.Allocator; const Page = @import("../page.zig").Page; +const JsObject = @import("../env.zig").Env.JsObject; const log = if (builtin.is_test) &test_capture else @import("../../log.zig"); @@ -29,6 +30,13 @@ pub const Console = struct { timers: std.StringHashMapUnmanaged(u32) = .{}, counts: std.StringHashMapUnmanaged(u32) = .{}, + pub fn _lp(_: *const Console, values: []JsObject, page: *Page) !void { + if (values.len == 0) { + return; + } + log.fatal(.console, "lightpanda", .{ .args = try serializeValues(values, page) }); + } + pub fn _log(_: *const Console, values: []JsObject, page: *Page) !void { if (values.len == 0) { return; @@ -134,12 +142,19 @@ pub const Console = struct { } fn serializeValues(values: []JsObject, page: *Page) ![]const u8 { + if (values.len == 0) { + return ""; + } + const arena = page.call_arena; + const separator = log.separator(); var arr: std.ArrayListUnmanaged(u8) = .{}; - try arr.appendSlice(arena, try values[0].toString()); - for (values[1..]) |value| { - try arr.append(arena, ' '); - try arr.appendSlice(arena, try value.toString()); + + for (values, 1..) |value, i| { + try arr.appendSlice(arena, separator); + try arr.writer(arena).print("{d}: ", .{i}); + const serialized = if (builtin.mode == .Debug) value.toDetailString() else value.toString(); + try arr.appendSlice(arena, try serialized); } return arr.items; } diff --git a/src/log.zig b/src/log.zig index 2bc15e126..93df4c481 100644 --- a/src/log.zig +++ b/src/log.zig @@ -173,13 +173,17 @@ fn logLogfmt(comptime scope: Scope, level: Level, comptime msg: []const u8, data } fn logPretty(comptime scope: Scope, level: Level, comptime msg: []const u8, data: anytype, writer: anytype) !void { - try writer.writeAll(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 ", - }); + if (scope == .console and level == .fatal and comptime std.mem.eql(u8, msg, "lightpanda")) { + try writer.writeAll("\x1b[0;104mWARN "); + } else { + try writer.writeAll(switch (level) { + .debug => "\x1b[0;36mDEBUG\x1b[0m ", + .info => "\x1b[0;32mINFO\x1b[0m ", + .warn => "\x1b[0;33mWARN\x1b[0m ", + .err => "\x1b[0;31mERROR ", + .fatal => "\x1b[0;35mFATAL ", + }); + } const prefix = @tagName(scope) ++ " : " ++ msg; try writer.writeAll(prefix); @@ -194,7 +198,7 @@ fn logPretty(comptime scope: Scope, level: Level, comptime msg: []const u8, data if (@mod(padding, 2) == 1) { try writer.writeByte(' '); } - try writer.print(" [+{d}ms]", .{elapsed()}); + try writer.print(" \x1b[0m[+{d}ms]", .{elapsed()}); try writer.writeByte('\n'); } diff --git a/src/runtime/js.zig b/src/runtime/js.zig index 9e10a2c83..e73b65940 100644 --- a/src/runtime/js.zig +++ b/src/runtime/js.zig @@ -1373,6 +1373,12 @@ pub fn Env(comptime State: type, comptime WebApis: type) type { return valueToString(scope.call_arena, js_value, scope.isolate, scope.context); } + pub fn toDetailString(self: JsObject) ![]const u8 { + const scope = self.scope; + const js_value = self.js_obj.toValue(); + return valueToDetailString(scope.call_arena, js_value, scope.isolate, scope.context); + } + pub fn format(self: JsObject, comptime _: []const u8, _: std.fmt.FormatOptions, writer: anytype) !void { return writer.writeAll(try self.toString()); } @@ -2493,6 +2499,15 @@ fn Caller(comptime E: type, comptime State: type) type { } fn handleError(self: *Self, comptime Struct: type, comptime named_function: NamedFunction, err: anyerror, info: anytype) void { + if (builtin.mode == .Debug and log.enabled(.js, .warn) and @hasDecl(@TypeOf(info), "length")) { + const args_dump = self.serializeFunctionArgs(info) catch "failed to serialize args"; + log.warn(.js, "function call error", .{ + .name = named_function.full_name, + .err = err, + .args = args_dump, + }); + } + const isolate = self.isolate; var js_err: ?v8.Value = switch (err) { error.InvalidArgument => createTypeException(isolate, "invalid argument"), @@ -2635,15 +2650,6 @@ 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 (builtin.mode == .Debug and log.enabled(.js, .warn)) { - const args_dump = self.serializeFunctionArgs(info) catch "failed to serialize args"; - log.warn(.js, "function call error", .{ - .name = named_function.full_name, - .err = err, - .args = args_dump, - }); - }; - { // This is going to get complicated. If the last Zig paremeter // is a slice AND the corresponding javascript parameter is @@ -2710,6 +2716,7 @@ fn Caller(comptime E: type, comptime State: type) type { const isolate = self.isolate; const context = self.context; const arena = self.call_arena; + const separator = log.separator(); const js_parameter_count = info.length(); var arr: std.ArrayListUnmanaged(u8) = .{}; @@ -2718,7 +2725,7 @@ fn Caller(comptime E: type, comptime State: type) type { const value_string = try valueToDetailString(arena, js_value, isolate, context); const value_type = try jsStringToZig(arena, try js_value.typeOf(isolate), isolate); try std.fmt.format(arr.writer(arena), "{s}{d}: {s} ({s})", .{ - log.separator(), + separator, i + 1, value_string, value_type, @@ -3057,9 +3064,23 @@ const TaggedAnyOpaque = struct { subtype: ?SubType, }; -fn valueToDetailString(allocator: Allocator, value: v8.Value, isolate: v8.Isolate, context: v8.Context) ![]u8 { - const str = try value.toDetailString(context); - return jsStringToZig(allocator, str, isolate); +fn valueToDetailString(arena: Allocator, value: v8.Value, isolate: v8.Isolate, context: v8.Context) ![]u8 { + var str: ?v8.String = null; + if (value.isObject() and !value.isFunction()) { + str = try v8.Json.stringify(context, value, null); + + if (str.?.lenUtf8(isolate) == 2) { + // {} isn't useful, null this so that we can get the toDetailString + // (which might also be useless, but maybe not) + str = null; + } + } + + if (str == null) { + str = try value.toDetailString(context); + } + + return jsStringToZig(arena, str.?, isolate); } fn valueToString(allocator: Allocator, value: v8.Value, isolate: v8.Isolate, context: v8.Context) ![]u8 { From 625fa03c221b232c5e55fcf33a9f6b94dc3953fc Mon Sep 17 00:00:00 2001 From: Karl Seguin Date: Sat, 31 May 2025 21:38:24 +0800 Subject: [PATCH 3/6] fix tests --- src/browser/console/console.zig | 21 +++++++++++++++++---- 1 file changed, 17 insertions(+), 4 deletions(-) diff --git a/src/browser/console/console.zig b/src/browser/console/console.zig index 980c6aaa4..20148b8a5 100644 --- a/src/browser/console/console.zig +++ b/src/browser/console/console.zig @@ -180,8 +180,8 @@ test "Browser.Console" { }, .{}); const captured = test_capture.captured.items; - try testing.expectEqual("[info] args=a", captured[0]); - try testing.expectEqual("[warn] args=hello world 23 true [object Object]", captured[1]); + try testing.expectEqual("[info] args= 1: a", captured[0]); + try testing.expectEqual("[warn] args= 1: hello world 2: 23 3: true 4: #", captured[1]); } { @@ -222,13 +222,17 @@ test "Browser.Console" { const captured = test_capture.captured.items; 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]); + try testing.expectEqual("[assertion failed] values= 1: x 2: true", captured[1]); + try testing.expectEqual("[assertion failed] values= 1: x", captured[2]); } } const TestCapture = struct { captured: std.ArrayListUnmanaged([]const u8) = .{}, + fn separator(_: *const TestCapture) []const u8 { + return " "; + } + fn reset(self: *TestCapture) void { self.captured = .{}; } @@ -269,6 +273,15 @@ const TestCapture = struct { self.capture(scope, msg, args); } + fn fatal( + 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), From 021fc8fb591d94e8fdfdde33d763834bd57e6761 Mon Sep 17 00:00:00 2001 From: Karl Seguin Date: Sun, 1 Jun 2025 18:49:13 +0800 Subject: [PATCH 4/6] experiment with reducing retained arena size --- src/browser/session.zig | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/browser/session.zig b/src/browser/session.zig index edc818dbc..9f8c14247 100644 --- a/src/browser/session.zig +++ b/src/browser/session.zig @@ -89,7 +89,7 @@ pub const Session = struct { try parser.init(); const page_arena = &self.browser.page_arena; - _ = page_arena.reset(.{ .retain_with_limit = 1 * 1024 * 1024 }); + _ = page_arena.reset(.{ .retain_with_limit = 128 * 1024 }); self.page = @as(Page, undefined); const page = &self.page.?; @@ -133,7 +133,7 @@ pub const Session = struct { // If, while loading the page, we intend to navigate to another // page, then we need to keep the transfer_arena around, as this // sub-navigation is probably using it. - _ = self.browser.transfer_arena.reset(.{ .retain_with_limit = 1 * 1024 * 1024 }); + _ = self.browser.transfer_arena.reset(.{ .retain_with_limit = 64 * 1024 }); } }; From 9e834e0db5a2a64f0a82003af4bddd77e273f9ba Mon Sep 17 00:00:00 2001 From: Karl Seguin Date: Sun, 1 Jun 2025 18:56:02 +0800 Subject: [PATCH 5/6] Revert "experiment with reducing retained arena size" This reverts commit 2f6b4c04da3e4659a3ebe8bcb9195f4625feaa16. --- src/browser/session.zig | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/browser/session.zig b/src/browser/session.zig index 9f8c14247..b128d14b0 100644 --- a/src/browser/session.zig +++ b/src/browser/session.zig @@ -89,7 +89,7 @@ pub const Session = struct { try parser.init(); const page_arena = &self.browser.page_arena; - _ = page_arena.reset(.{ .retain_with_limit = 128 * 1024 }); + _ = page_arena.reset(.{ .retain_with_limit = 1 * 1024 * 1024 }); self.page = @as(Page, undefined); const page = &self.page.?; From a000dfe67662c91a485831ca07b00d6eb89a4b5a Mon Sep 17 00:00:00 2001 From: Karl Seguin Date: Mon, 2 Jun 2025 15:09:18 +0800 Subject: [PATCH 6/6] include stack trace in JS function call log errors --- src/runtime/js.zig | 44 ++++++++++++++++++++++++++++++++++---------- 1 file changed, 34 insertions(+), 10 deletions(-) diff --git a/src/runtime/js.zig b/src/runtime/js.zig index e73b65940..a9ee587c9 100644 --- a/src/runtime/js.zig +++ b/src/runtime/js.zig @@ -1857,8 +1857,10 @@ pub fn Env(comptime State: type, comptime WebApis: type) type { fn generateNamedIndexer(comptime Struct: type, template_proto: v8.ObjectTemplate) void { if (@hasDecl(Struct, "named_get") == false) { - if (builtin.mode == .Debug and log.enabled(.unknown_prop, .debug)) { - generateDebugNamedIndexer(Struct, template_proto); + if (comptime builtin.mode == .Debug) { + if (log.enabled(.unknown_prop, .debug)) { + generateDebugNamedIndexer(Struct, template_proto); + } } return; } @@ -2499,16 +2501,20 @@ fn Caller(comptime E: type, comptime State: type) type { } fn handleError(self: *Self, comptime Struct: type, comptime named_function: NamedFunction, err: anyerror, info: anytype) void { - if (builtin.mode == .Debug and log.enabled(.js, .warn) and @hasDecl(@TypeOf(info), "length")) { - const args_dump = self.serializeFunctionArgs(info) catch "failed to serialize args"; - log.warn(.js, "function call error", .{ - .name = named_function.full_name, - .err = err, - .args = args_dump, - }); + const isolate = self.isolate; + + if (comptime builtin.mode == .Debug and @hasDecl(@TypeOf(info), "length")) { + if (log.enabled(.js, .warn)) { + const args_dump = self.serializeFunctionArgs(info) catch "failed to serialize args"; + log.warn(.js, "function call error", .{ + .name = named_function.full_name, + .err = err, + .args = args_dump, + .stack = stackForLogs(self.call_arena, isolate) catch |err1| @errorName(err1), + }); + } } - const isolate = self.isolate; var js_err: ?v8.Value = switch (err) { error.InvalidArgument => createTypeException(isolate, "invalid argument"), error.OutOfMemory => createException(isolate, "out of memory"), @@ -3105,6 +3111,24 @@ fn jsStringToZig(allocator: Allocator, str: v8.String, isolate: v8.Isolate) ![]u return buf; } +fn stackForLogs(arena: Allocator, isolate: v8.Isolate) !?[]const u8 { + std.debug.assert(builtin.mode == .Debug); + + const separator = log.separator(); + var buf: std.ArrayListUnmanaged(u8) = .empty; + var writer = buf.writer(arena); + + const stack_trace = v8.StackTrace.getCurrentStackTrace(isolate, 30); + const frame_count = stack_trace.getFrameCount(); + + for (0..frame_count) |i| { + const frame = stack_trace.getFrame(isolate, @intCast(i)); + const script = try jsStringToZig(arena, frame.getScriptName(), isolate); + try writer.print("{s}{s}:{d}", .{ separator, script, frame.getLineNumber() }); + } + return buf.items; +} + const NoopInspector = struct { pub fn onInspectorResponse(_: *anyopaque, _: u32, _: []const u8) void {} pub fn onInspectorEvent(_: *anyopaque, _: []const u8) void {}