Merge pull request #3680 from lightpanda-io/page-context-logs

ops: Introduce Page Context logs

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;
 

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

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

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

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

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

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

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;
 

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;

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

src/network/HttpClient.zig

@@ -2307,6 +2307,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.
@@ -2797,6 +2804,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()
@@ -2806,6 +2818,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,
@@ -2922,6 +2937,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, &.{
@@ -4106,6 +4124,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;

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.