diff --git a/src/browser/Frame.zig b/src/browser/Frame.zig index 55bc76786..0f29379ac 100644 --- a/src/browser/Frame.zig +++ b/src/browser/Frame.zig @@ -657,13 +657,23 @@ pub fn navigate(self: *Frame, request_url: [:0]const u8, opts: NavigateOpts) !vo self._load_state = .parsing; self._last_navigate_error = null; - log.info(.frame, "navigate", .{ + const page = self.page; + const page_scope = page.logScope(); + defer page_scope.exit(); + + const is_root = self == &page.frame; + const log_data = .{ .url = request_url, .method = opts.method, .reason = opts.reason, .body = opts.body != null, .type = self._type, - }); + }; + if (is_root) { + log.info(.frame, "navigation start", log_data); + } else { + log.info(.frame, "navigate", log_data); + } const http_client = &session.browser.http_client; diff --git a/src/browser/Page.zig b/src/browser/Page.zig index 60a764650..f1c6900c4 100644 --- a/src/browser/Page.zig +++ b/src/browser/Page.zig @@ -40,6 +40,7 @@ const AnimatedTransformList = @import("webapi/svg/AnimatedTransformList.zig"); const ServiceWorkerGlobalScope = @import("webapi/ServiceWorkerGlobalScope.zig"); const AnimatedPreserveAspectRatio = @import("webapi/svg/AnimatedPreserveAspectRatio.zig"); +const log = lp.log; const Allocator = std.mem.Allocator; // A Page is the container for a root Frame and all of its descendants @@ -80,6 +81,9 @@ broadcast_sequence: u64 = 0, // Not exhaustive: some swallowed-callback paths aren't routed here. js_error_count: usize = 0, +// Entered (logScope) around any work done on this Page's behalf. +log_context: log.PageContext, + // DOM object factory scoped to this Page's documents. factory: Factory, @@ -257,15 +261,25 @@ pub fn init(self: *Page, session: *Session, frame_id: u32) !void { .frame_arena = frame_arena.allocator(), .factory = Factory.init(self, frame_arena.allocator(), &session.browser.documents), .globals = .init(session.browser.app.allocator), + .log_context = .{ .id = log.nextPageId(), .url = &self.frame.url }, }; self.queued_navigation = &self.queued_navigation_1; try Frame.init(&self.frame, frame_id, self, .{}); } +pub fn logScope(self: *Page) log.PageScope { + return log.enterPage(&self.log_context); +} + // Tear down the Page and its root Frame. Equivalent to the old // Session.removePage + Session.resetFrameResources. pub fn deinit(self: *Page) void { + const page_scope = self.logScope(); + defer page_scope.exit(); + + log.log(.frame, self.log_context.max_level, "navigation done", .{ .url = self.frame.url }); + for (self.popups.items) |popup| { popup.deinit(); } diff --git a/src/browser/Session.zig b/src/browser/Session.zig index 1f23a8f7e..c74dd7b7d 100644 --- a/src/browser/Session.zig +++ b/src/browser/Session.zig @@ -276,6 +276,9 @@ pub fn processDestroyQueues(self: *Session) void { const queue = self._page_destruction_queue.items; if (queue.len > 0) { for (queue) |page| { + if (comptime lp.IS_DEBUG) { + std.debug.assert(log.currentPage() != &page.log_context); + } page.deinit(); self.browser.page_pool.destroy(page); } diff --git a/src/browser/global_scope.zig b/src/browser/global_scope.zig index cd2904bbd..21b752494 100644 --- a/src/browser/global_scope.zig +++ b/src/browser/global_scope.zig @@ -186,6 +186,7 @@ pub const GlobalScope = union(enum) { .frame_id = frame._frame_id, .document_frame_id = frame._frame_id, .loader_id = frame._loader_id, + .log_page = &frame.page.log_context, }, .worker => |worker| .{ .scope = self, @@ -194,6 +195,7 @@ pub const GlobalScope = union(enum) { .frame_id = worker._frame_id, .document_frame_id = worker._frame._frame_id, .loader_id = worker._loader_id, + .log_page = &worker.page.log_context, }, }; } diff --git a/src/browser/js/Context.zig b/src/browser/js/Context.zig index 55cf81416..d3ef6154b 100644 --- a/src/browser/js/Context.zig +++ b/src/browser/js/Context.zig @@ -288,6 +288,7 @@ pub fn localScope(self: *Context, ls: *js.Local.Scope) void { .handle = local_v8_context, .call_arena = self.call_arena, }; + ls.page_scope = self.page.logScope(); } pub fn toLocal(self: *Context, global: anytype) js.Local.ToLocalReturnType(@TypeOf(global)) { @@ -1075,7 +1076,13 @@ pub fn enter(self: *Context, hs: *js.HandleScope) Entered { const handle: *const v8.Context = @ptrCast(v8.v8__Global__Get(&self.handle, isolate.handle)); v8.v8__Context__Enter(handle); - return .{ .original = original, .handle = handle, .handle_scope = hs, .global = self.global }; + return .{ + .original = original, + .handle = handle, + .handle_scope = hs, + .global = self.global, + .page_scope = self.page.logScope(), + }; } const Entered = struct { @@ -1089,7 +1096,10 @@ const Entered = struct { global: lp.GlobalScope, + page_scope: log.PageScope, + pub fn exit(self: Entered) void { + self.page_scope.exit(); self.global.setJs(self.original); v8.v8__Context__Exit(self.handle); self.handle_scope.deinit(); diff --git a/src/browser/js/Env.zig b/src/browser/js/Env.zig index edd99d786..96824e5f6 100644 --- a/src/browser/js/Env.zig +++ b/src/browser/js/Env.zig @@ -503,7 +503,9 @@ pub fn runMicrotasks(self: *Env) void { var i: usize = 0; while (i < self.contexts.items.len) : (i += 1) { const ctx = self.contexts.items[i]; + const page_scope = ctx.page.logScope(); v8.v8__MicrotaskQueue__PerformCheckpoint(ctx.microtask_queue, v8_isolate); + page_scope.exit(); if (self.terminatePending()) { if (v8.v8__Isolate__IsExecutionTerminating(v8_isolate)) { diff --git a/src/browser/js/Local.zig b/src/browser/js/Local.zig index 1dc926183..7b9d27990 100644 --- a/src/browser/js/Local.zig +++ b/src/browser/js/Local.zig @@ -1642,8 +1642,10 @@ fn createFinalizerCallback( pub const Scope = struct { local: Local, handle_scope: js.HandleScope, + page_scope: log.PageScope, pub fn deinit(self: *Scope) void { + self.page_scope.exit(); v8.v8__Context__Exit(self.local.handle); self.handle_scope.deinit(); } diff --git a/src/browser/webapi/net/WebSocket.zig b/src/browser/webapi/net/WebSocket.zig index e6276ca7e..463778e66 100644 --- a/src/browser/webapi/net/WebSocket.zig +++ b/src/browser/webapi/net/WebSocket.zig @@ -355,6 +355,9 @@ pub fn deliverEvents(self: *WebSocket) void { // alive even when a terminal event releases the base reference. defer self.releaseRef(self._exec.page); + const page_scope = self._exec.page.logScope(); + defer page_scope.exit(); + self._delivering = true; defer self._delivering = false; diff --git a/src/crash_handler.zig b/src/crash_handler.zig index 781b1c1b8..e73488921 100644 --- a/src/crash_handler.zig +++ b/src/crash_handler.zig @@ -63,6 +63,7 @@ pub noinline fn crash( writer.print("OS: {s}\n", .{@tagName(builtin.os.tag)}) catch abort(); writer.print("mode: {s}\n", .{@tagName(builtin.mode)}) catch abort(); writer.print("version: {s}\n", .{lp.build_config.version}) catch abort(); + writeCurrentPage(writer); inline for (@typeInfo(@TypeOf(args)).@"struct".fields) |f| { writer.writeAll(f.name ++ ": ") catch break; lp.log.writeValue(.pretty, @field(args, f.name), writer) catch abort(); @@ -281,10 +282,24 @@ fn handleFatalSignal(sig: std.posix.SIG, info: *const std.posix.siginfo_t, ctx_p writeBacktrace(ctx); } + // Last: reads the Page, which the fault may have corrupted. + { + var page_writer: std.Io.Writer = .fixed(&buffer); + writeCurrentPage(&page_writer); + writeRecord(page_writer.buffered()); + } + _ = std.c.raise(sig); std.c._exit(@intCast(128 + @intFromEnum(sig))); } +// The page this thread was working on. Local output only (never sent to the +// crash report) +fn writeCurrentPage(writer: *std.Io.Writer) void { + const page = lp.log.currentPage() orelse return; + writer.print("page: {d}\nurl: {s}\n", .{ page.id, page.url.* }) catch {}; +} + fn writeRecord(record: []const u8) void { if (record.len == 0) { return; diff --git a/src/log.zig b/src/log.zig index e487c1c14..0c03c5836 100644 --- a/src/log.zig +++ b/src/log.zig @@ -19,6 +19,8 @@ const std = @import("std"); const lp = @import("lightpanda"); +threadlocal var current_page: ?*PageContext = null; + pub const Scope = enum { app, bidi, @@ -225,6 +227,12 @@ pub fn logKVs(scope: Scope, level: Level, msg: []const u8, kvs: []const KV) void return; } + if (current_page) |page| { + if (level != .note and @intFromEnum(level) > @intFromEnum(page.max_level)) { + page.max_level = level; + } + } + if (comptime lp.IS_TEST) { const expected = &expected_logs[@intFromEnum(scope)]; if (expected.* > 0) { @@ -312,10 +320,17 @@ fn logLogFmtPrefix(scope: Scope, level: Level, msg: []const u8, writer: *std.Io. try writer.writeAll(" $msg=\""); try writer.writeAll(msg); try writer.writeByte('"'); + + if (current_page) |page| { + try writer.print(" $page={d}", .{page.id}); + } } fn logPretty(scope: Scope, level: Level, msg: []const u8, kvs: []const KV, writer: *std.Io.Writer) !void { try logPrettyPrefix(scope, level, msg, writer); + if (current_page) |page| { + try writer.print(" $page = {d}\n", .{page.id}); + } for (kvs) |kv| { try writer.print(" {s} = ", .{kv.key}); try writeErased(.pretty, kv.value, writer); @@ -627,6 +642,41 @@ fn timestamp(comptime clock: std.Io.Clock) u64 { return datetime.milliTimestamp(clock); } +pub const PageContext = struct { + id: u64, + url: *const [:0]const u8, + max_level: Level = .info, +}; + +var page_id_gen = std.atomic.Value(u64).init(0); + +pub fn nextPageId() u64 { + return page_id_gen.fetchAdd(1, .monotonic) + 1; +} + +pub const PageScope = struct { + page: ?*PageContext, + previous: ?*PageContext, + + pub fn exit(self: PageScope) void { + if (comptime lp.IS_DEBUG) { + // enter/exit must nest + std.debug.assert(current_page == self.page); + } + current_page = self.previous; + } +}; + +pub fn enterPage(page: ?*PageContext) PageScope { + const previous = current_page; + current_page = page; + return .{ .page = page, .previous = previous }; +} + +pub fn currentPage() ?*const PageContext { + return current_page; +} + const testing = @import("testing.zig"); test "log: colored" { opts.format = .logfmt; @@ -702,6 +752,54 @@ test "log: string escape" { } } +test "log: page context" { + opts.format = .logfmt; + defer opts.format = .pretty; + + var aw = std.Io.Writer.Allocating.init(testing.allocator); + defer aw.deinit(); + + const url: [:0]const u8 = "https://lightpanda.io/"; + var page: PageContext = .{ .id = 42, .url = &url }; + + const page_scope = enterPage(&page); + { + try logTo(.frame, .info, "tagged", .{}, &aw.writer); + try testing.expectEqual("$time=1739795092929 $scope=frame $level=info $msg=\"tagged\" $page=42\n", aw.written()); + } + + { + expectLog(&.{ .http, .http }); + err(.http, "first", .{}); + warn(.http, "second", .{}); + try testing.expectEqual(.err, page.max_level); + } + + page_scope.exit(); + try testing.expectEqual(null, currentPage()); + + { + var other: PageContext = .{ .id = 43, .url = &url }; + const outer = enterPage(&page); + const inner = enterPage(&other); + try testing.expectEqual(&other, currentPage().?); + inner.exit(); + try testing.expectEqual(&page, currentPage().?); + outer.exit(); + try testing.expectEqual(null, currentPage()); + } + + { + aw.clearRetainingCapacity(); + try logTo(.frame, .info, "untagged", .{}, &aw.writer); + try testing.expectEqual("$time=1739795092929 $scope=frame $level=info $msg=\"untagged\"\n", aw.written()); + + expectLog(&.{.http}); + fatal(.http, "not this page", .{}); + try testing.expectEqual(.err, page.max_level); + } +} + test "log: resolveFilters" { // No directives: everything enabled. { diff --git a/src/network/HttpClient.zig b/src/network/HttpClient.zig index decf406a4..cdd2cb104 100644 --- a/src/network/HttpClient.zig +++ b/src/network/HttpClient.zig @@ -2282,6 +2282,13 @@ pub const Owner = struct { document_frame_id: u32, loader_id: u32, + // Entered around delivery, so the consumer's callbacks log as its page. + log_page: ?*log.PageContext = null, + + fn logScope(self: *const Owner) log.PageScope { + return log.enterPage(self.log_page); + } + const Blob = @import("../browser/webapi/Blob.zig"); /// The URL of the document this owner's requests belong to. @@ -2770,6 +2777,11 @@ pub const Transfer = struct { self.abort(error.TransferCanceled); } + fn logScope(self: *const Transfer) log.PageScope { + const owner = self.owner orelse return log.enterPage(null); + return owner.logScope(); + } + // Fail this transfer with `err`. Fires error_callback once (latched // via _notified_fail), then either deinits synchronously or, if // deliver() is running our callbacks, detaches and lets deliver() @@ -2779,6 +2791,9 @@ pub const Transfer = struct { // to end a transfer. Don't reach for kill() or requestFailed() directly — // they're internal helpers. pub fn abort(self: *Transfer, err: anyerror) void { + const page_scope = self.logScope(); + defer page_scope.exit(); + // error_callback can run JS that tears this transfer down again // (e.g. an XHR abort handler navigates -> abortRequests -> kill). // Hold the state at .delivering so the re-entrant teardown defers, @@ -2895,6 +2910,9 @@ pub const Transfer = struct { // abortRequests when a Frame / WGS is being torn down. Any buffered, // undelivered events are dropped — the consumer is going away with us. fn kill(self: *Transfer) void { + const page_scope = self.logScope(); + defer page_scope.exit(); + if (self._notify_cdp and !self._notified_fail) { self._notified_fail = true; self.notify(.http_request_fail, &.{ @@ -4067,6 +4085,9 @@ pub const Transfer = struct { // batch and stays inflight between batches, until a terminal event // (done / err) or an abort. fn deliver(transfer: *Transfer) void { + const page_scope = transfer.logScope(); + defer page_scope.exit(); + // A streaming batch is delivered while the conn is still inflight; // that state is restored after the batch unless it turned terminal. const was_inflight = transfer.state == .inflight; diff --git a/src/server/cdp/domains/page.zig b/src/server/cdp/domains/page.zig index e2d5c66ed..d2a51fb66 100644 --- a/src/server/cdp/domains/page.zig +++ b/src/server/cdp/domains/page.zig @@ -2535,8 +2535,9 @@ test "cdp.frame: anchor click sends Referer matching the originating page" { f.js.localScope(&ls); defer ls.deinit(); _ = try ls.local.exec("document.getElementById('link').click()", null); - try testing.waitForPage(bc); } + // Outside the scope: the navigation destroys the page it's entered on. + try testing.waitForPage(bc); // After the click navigation completes, the loaded page is /echo_referer // and its body echoes the Referer header the server actually saw.