public/browser
1
0
Fork 0
mirror of https://github.com/lightpanda-io/browser.git synced 2026-03-28 07:33:16 +00:00
Code Issues Actions 5 Packages Projects Releases Wiki Activity

Merge pull request #735 from lightpanda-io/improved_logging
Some checks failed
e2e-test / zig build release (push) Has been cancelled
Details
e2e-test / puppeteer-perf (push) Has been cancelled
Details
e2e-test / demo-scripts (push) Has been cancelled
Details
e2e-test / cdp-and-hyperfine-bench (push) Has been cancelled
Details
e2e-test / perf-fmt (push) Has been cancelled
Details
zig-test / zig build dev (push) Has been cancelled
Details
zig-test / browser fetch (push) Has been cancelled
Details
zig-test / zig test (push) Has been cancelled
Details
zig-test / perf-fmt (push) Has been cancelled
Details
nightly build / build-linux-x86_64 (push) Has been cancelled
Details
nightly build / build-linux-aarch64 (push) Has been cancelled
Details
nightly build / build-macos-aarch64 (push) Has been cancelled
Details
nightly build / build-macos-x86_64 (push) Has been cancelled
Details
wpt / web platform tests json output (push) Has been cancelled
Details
wpt / perf-fmt (push) Has been cancelled
Details

Browse Source 
Improved logging
This commit is contained in:
Karl Seguin
2025-06-02 21:53:51 +08:00
committed by GitHub
parent 47da5e0338 a000dfe676
commit 1ac23ce191
23 changed files with 476 additions and 227 deletions
Download Patch File Download Diff File Expand all files Collapse all files

15
build.zig
View File

@@ -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(.{});

48
src/browser/console/console.zig
View File

@@ -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;
}
@@ -165,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: #<Object>", captured[1]);
}
{
@@ -207,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 = .{};
}
@@ -254,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),
@@ -278,7 +306,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;

2
src/browser/dom/element.zig
View File

@@ -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);

6
src/browser/dom/intersection_observer.zig
View File

@@ -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",
});
};
}

8
src/browser/dom/mutation_observer.zig
View File

@@ -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" });
};
}

2
src/browser/dom/node.zig
View File

@@ -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));
}

2
src/browser/dom/nodelist.zig
View File

@@ -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 });
};
}
}

6
src/browser/dom/token_list.zig
View File

@@ -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",
});
};
}
}

8
src/browser/events/event.zig
View File

@@ -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) {

5
src/browser/html/document.zig
View File

@@ -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);
}

14
src/browser/html/window.zig
View File

@@ -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| {

40
src/browser/page.zig
View File

@@ -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;

2
src/browser/polyfill/polyfill.zig
View File

@@ -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;
};

6
src/browser/session.zig
View File

@@ -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 {
@@ -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 });
}
};

2
src/browser/storage/cookie.zig
View File

@@ -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);

4
src/browser/xhr/form_data.zig
View File

@@ -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;
},
}

32
src/browser/xhr/xhr.zig
View File

@@ -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;
};

2
src/http/client.zig
View File

@@ -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

148
src/log.zig
View File

@@ -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,46 +138,52 @@ 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 {
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 ",
});
fn logPretty(comptime scope: Scope, level: Level, comptime msg: []const u8, data: anytype, writer: anytype) !void {
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);
@@ -161,25 +198,25 @@ fn logPretty(comptime scope: @Type(.enum_literal), comptime level: Level, compti
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');
}
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 +228,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 +246,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 +335,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 +344,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 +359,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 +370,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);
}
}

242
src/main.zig
View File

@@ -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();

3
src/notification.zig
View File

@@ -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,
});
};

84
src/runtime/js.zig
View File

@@ -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());
}
@@ -1851,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 (comptime @import("build_config").log_unknown_properties) {
generateDebugNamedIndexer(Struct, template_proto);
if (comptime builtin.mode == .Debug) {
if (log.enabled(.unknown_prop, .debug)) {
generateDebugNamedIndexer(Struct, template_proto);
}
}
return;
}
@@ -1899,7 +1907,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,
@@ -2494,6 +2502,19 @@ 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 {
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),
});
}
}
var js_err: ?v8.Value = switch (err) {
error.InvalidArgument => createTypeException(isolate, "invalid argument"),
error.OutOfMemory => createException(isolate, "out of memory"),
@@ -2635,15 +2656,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 (log.enabled(.js, .debug)) {
const args_dump = self.dumpFunctionArgs(info) catch "failed to serialize args";
log.debug(.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
@@ -2706,10 +2718,11 @@ 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;
const separator = log.separator();
const js_parameter_count = info.length();
var arr: std.ArrayListUnmanaged(u8) = .{};
@@ -2717,7 +2730,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})", .{
separator,
i + 1,
value_string,
value_type,
});
}
return arr.items;
}
@@ -3052,9 +3070,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 {
@@ -3079,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 {}

22
src/server.zig
View File

@@ -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