From c3f3eea7fb096e150b56ca9afb1d780483fca570 Mon Sep 17 00:00:00 2001 From: Karl Seguin Date: Sat, 31 May 2025 20:02:23 +0800 Subject: [PATCH] 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 65c3bef6..6f3906f3 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 1edbc612..2d857103 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 c3a7e545..f640686d 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 12de3bae..c14c5faa 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 c651c851..f5394ba8 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 90ee72d0..78a9e1f0 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 602419ec..56194c2f 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 532b9109..6f12c406 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 fcbede39..1a75f116 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 85926a65..5c74fe7e 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 afc27410..bd28ed49 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 3e05d577..5366fb7a 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 03175b12..5fc41c5d 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 532a3907..edc818db 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 c944e8f9..bdd93e3f 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 ed9e1ebe..25f31bb5 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 04cecb72..d65f9db8 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 4aba5fb2..81b11cd7 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 51764ee9..2bc15e12 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 765523ec..753e84fa 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 8ccce0a3..5cb198f7 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 7165e360..9e10a2c8 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 f365da0d..a14ff305 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