Merge pull request #1126 from lightpanda-io/add_debug_context

Attempt to add more context to debug logs.

Author: karlseguin

build.zig.zon

@@ -5,8 +5,8 @@
     .fingerprint = 0xda130f3af836cea0,
     .dependencies = .{
         .v8 = .{
-            .url = "https://github.com/lightpanda-io/zig-v8-fork/archive/7a1beb016efcb2bd66c0b46b5fc6bcd04fa72db8.tar.gz",
-            .hash = "v8-0.0.0-xddH6_PFAwAqwLMWbF7S0rAZzRbN8zmf2GhLH_ThdMSR",
+            .url = "https://github.com/lightpanda-io/zig-v8-fork/archive/5ce9ade6c6d7f7ab9ab4582a6b1b36fdc8e246e2.tar.gz",
+            .hash = "v8-0.0.0-xddH6yTGAwA__kfiDozsVXL2_jnycrtDUfR8kIADQFUz",
         },
         //.v8 = .{ .path = "../zig-v8-fork" }
     },

src/browser/ScriptManager.zig

@@ -131,7 +131,7 @@ fn clearList(_: *const ScriptManager, list: *OrderList) void {
     std.debug.assert(list.first == null);
 }
 
-pub fn addFromElement(self: *ScriptManager, element: *parser.Element) !void {
+pub fn addFromElement(self: *ScriptManager, element: *parser.Element, comptime ctx: []const u8) !void {
     if (try parser.elementGetAttribute(element, "nomodule") != null) {
         // these scripts should only be loaded if we don't support modules
         // but since we do support modules, we can just skip them.
@@ -219,7 +219,11 @@ pub fn addFromElement(self: *ScriptManager, element: *parser.Element) !void {
         self.scripts.append(&pending_script.node);
         return;
     } else {
-        log.debug(.http, "script queue", .{ .url = remote_url.? });
+        log.debug(.http, "script queue", .{
+            .ctx = ctx,
+            .url = remote_url.?,
+            .stack = page.js.stackTrace() catch "???",
+        });
     }
 
     pending_script.getList().append(&pending_script.node);
@@ -244,40 +248,7 @@ pub fn addFromElement(self: *ScriptManager, element: *parser.Element) !void {
     });
 }
 
-// @TODO: Improving this would have the simplest biggest performance improvement
-// for most sites.
-//
-// For JS imports (both static and dynamic), we currently block to get the
-// result (the content of the file).
-//
-// For static imports, this is necessary, since v8 is expecting the compiled module
-// as part of the function return. (we should try to pre-load the JavaScript
-// source via module.GetModuleRequests(), but that's for a later time).
-//
-// For dynamic dynamic imports, this is not strictly necessary since the v8
-// call returns a Promise; we could make this a normal get call, associated with
-// the promise, and when done, resolve the promise.
-//
-// In both cases, for now at least, we just issue a "blocking" request. We block
-// by ticking the http client until the script is complete.
-//
-// This uses the client.blockingRequest call which has a dedicated handle for
-// these blocking requests. Because they are blocking, we're guaranteed to have
-// only 1 at a time, thus the 1 reserved handle.
-//
-// You almost don't need the http client's blocking handle. In most cases, you
-// should always have 1 free handle whenever you get here, because we always
-// release the handle before executing the doneCallback. So, if a module does:
-//    import * as x from 'blah'
-// And we need to load 'blah', there should always be 1 free handle - the handle
-// of the http GET we just completed before executing the module.
-// The exception to this, and the reason we need a special blocking handle, is
-// for inline modules within the HTML page itself:
-//    <script type=module>import ....</script>
-// Unlike external modules which can only ever be executed after releasing an
-// http handle, these are executed without there necessarily being a free handle.
-// Thus, Http/Client.zig maintains a dedicated handle for these calls.
-pub fn getModule(self: *ScriptManager, url: [:0]const u8) !void {
+pub fn getModule(self: *ScriptManager, url: [:0]const u8, referrer: []const u8) !void {
     const gop = try self.sync_modules.getOrPut(self.allocator, url);
     if (gop.found_existing) {
         // already requested
@@ -294,6 +265,13 @@ pub fn getModule(self: *ScriptManager, url: [:0]const u8) !void {
     var headers = try self.client.newHeaders();
     try self.page.requestCookie(.{}).headersForRequest(self.page.arena, url, &headers);
 
+    log.debug(.http, "script queue", .{
+        .url = url,
+        .ctx = "module",
+        .referrer = referrer,
+        .stack = self.page.js.stackTrace() catch "???",
+    });
+
     try self.client.request(.{
         .url = url,
         .ctx = sync,
@@ -340,7 +318,7 @@ pub fn waitForModule(self: *ScriptManager, url: [:0]const u8) !GetResult {
     }
 }
 
-pub fn getAsyncModule(self: *ScriptManager, url: [:0]const u8, cb: AsyncModule.Callback, cb_data: *anyopaque) !void {
+pub fn getAsyncModule(self: *ScriptManager, url: [:0]const u8, cb: AsyncModule.Callback, cb_data: *anyopaque, referrer: []const u8) !void {
     const async = try self.async_module_pool.create();
     errdefer self.async_module_pool.destroy(async);
 
@@ -353,6 +331,13 @@ pub fn getAsyncModule(self: *ScriptManager, url: [:0]const u8, cb: AsyncModule.C
     var headers = try self.client.newHeaders();
     try self.page.requestCookie(.{}).headersForRequest(self.page.arena, url, &headers);
 
+    log.debug(.http, "script queue", .{
+        .url = url,
+        .ctx = "dynamic module",
+        .referrer = referrer,
+        .stack = self.page.js.stackTrace() catch "???",
+    });
+
     try self.client.request(.{
         .url = url,
         .method = .GET,

src/browser/html/elements.zig

@@ -887,7 +887,7 @@ pub const HTMLScriptElement = struct {
             //    s.src = '...';
             // This should load the script.
             // addFromElement protects against double execution.
-            try page.script_manager.addFromElement(@ptrCast(@alignCast(self)));
+            try page.script_manager.addFromElement(@ptrCast(@alignCast(self)), "dynamic");
         }
     }
 

src/browser/js/Context.zig

@@ -262,7 +262,7 @@ pub fn module(self: *Context, comptime want_result: bool, src: []const u8, url:
                 const owned_specifier = try self.arena.dupeZ(u8, normalized_specifier);
                 gop.key_ptr.* = owned_specifier;
                 gop.value_ptr.* = .{};
-                try self.script_manager.?.getModule(owned_specifier);
+                try self.script_manager.?.getModule(owned_specifier, src);
             }
         }
     }
@@ -995,7 +995,10 @@ fn debugValueToString(self: *const Context, js_obj: v8.Object) ![]u8 {
 }
 
 pub fn stackTrace(self: *const Context) !?[]const u8 {
-    std.debug.assert(@import("builtin").mode == .Debug);
+    if (comptime @import("builtin").mode != .Debug) {
+        return "not available";
+    }
+
     const isolate = self.isolate;
     const separator = log.separator();
 
@@ -1005,6 +1008,10 @@ pub fn stackTrace(self: *const Context) !?[]const u8 {
     const stack_trace = v8.StackTrace.getCurrentStackTrace(isolate, 30);
     const frame_count = stack_trace.getFrameCount();
 
+    if (v8.StackTrace.getCurrentScriptNameOrSourceUrl(isolate)) |script| {
+        try writer.print("{s}<{s}>", .{ separator, try self.jsStringToZig(script, .{}) });
+    }
+
     for (0..frame_count) |i| {
         const frame = stack_trace.getFrame(isolate, @intCast(i));
         if (frame.getScriptName()) |name| {
@@ -1130,7 +1137,7 @@ pub fn dynamicModuleCallback(
         return @constCast(self.rejectPromise("Out of memory").handle);
     };
 
-    const promise = self._dynamicModuleCallback(normalized_specifier) catch |err| blk: {
+    const promise = self._dynamicModuleCallback(normalized_specifier, resource) catch |err| blk: {
         log.err(.js, "dynamic module callback", .{
             .err = err,
         });
@@ -1190,7 +1197,7 @@ fn _resolveModuleCallback(self: *Context, referrer: v8.Module, specifier: []cons
         // harm in handling this case.
         @branchHint(.unlikely);
         gop.value_ptr.* = .{};
-        try self.script_manager.?.getModule(normalized_specifier);
+        try self.script_manager.?.getModule(normalized_specifier, referrer_path);
     }
 
     var fetch_result = try self.script_manager.?.waitForModule(normalized_specifier);
@@ -1226,7 +1233,7 @@ const DynamicModuleResolveState = struct {
     resolver: v8.Persistent(v8.PromiseResolver),
 };
 
-fn _dynamicModuleCallback(self: *Context, specifier: [:0]const u8) !v8.Promise {
+fn _dynamicModuleCallback(self: *Context, specifier: [:0]const u8, referrer: []const u8) !v8.Promise {
     const isolate = self.isolate;
     const gop = try self.module_cache.getOrPut(self.arena, specifier);
     if (gop.found_existing and gop.value_ptr.resolver_promise != null) {
@@ -1266,7 +1273,7 @@ fn _dynamicModuleCallback(self: *Context, specifier: [:0]const u8) !v8.Promise {
         };
 
         // Next, we need to actually load it.
-        self.script_manager.?.getAsyncModule(specifier, dynamicModuleSourceCallback, state) catch |err| {
+        self.script_manager.?.getAsyncModule(specifier, dynamicModuleSourceCallback, state, referrer) catch |err| {
             const error_msg = v8.String.initUtf8(isolate, @errorName(err));
             _ = resolver.reject(self.v8_context, error_msg.toValue());
         };

src/browser/page.zig

@@ -785,7 +785,7 @@ pub const Page = struct {
                         // ignore non-js script.
                         continue;
                     }
-                    try self.script_manager.addFromElement(@ptrCast(node));
+                    try self.script_manager.addFromElement(@ptrCast(node), "page");
                 }
 
                 self.script_manager.staticScriptsDone();
@@ -1250,7 +1250,7 @@ pub export fn scriptAddedCallback(ctx: ?*anyopaque, element: ?*parser.Element) c
     // here, else the script_manager will flag it as already-processed.
     _ = parser.elementGetAttribute(element.?, "src") catch return orelse return;
 
-    self.script_manager.addFromElement(element.?) catch |err| {
+    self.script_manager.addFromElement(element.?, "dynamic") catch |err| {
         log.warn(.browser, "dynamic script", .{ .err = err });
     };
 }

src/browser/polyfill/polyfill.zig

@@ -69,6 +69,7 @@ pub const Loader = struct {
         if (comptime builtin.mode == .Debug) {
             log.debug(.unknown_prop, "unkown global property", .{
                 .info = "but the property can exist in pure JS",
+                .stack = js_context.stackTrace() catch "???",
                 .property = name,
             });
         }