Merge pull request #3599 from lightpanda-io/log-msg-limit

log: check the message rules at comptime

orderfile/tools/regen.sh

@@ -29,6 +29,8 @@
 #   OUT       scratch directory (default /tmp/orderfile-regen)
 #   RAMDIR    tmpfs the binary is benched from (default /dev/shm)
 set -euo pipefail
+# profile() runs in a command substitution, which otherwise drops set -e.
+shopt -s inherit_errexit
 
 DEMO_DIR=${DEMO_DIR:-../demo}
 RUNS=${RUNS:-100}
@@ -92,8 +94,12 @@ profile() {
     set_fault_around 4096
     "$ram" serve --insecure-disable-tls-host-verification > /dev/null 2>&1 &
     local pid=$!
+    # This subshell's own trap: the script's cleanup doesn't know this pid.
+    trap "kill $pid 2> /dev/null || true" EXIT
     sleep 1
     (cd "$DEMO_DIR" && RUNS=$RUNS node puppeteer/cdp.js > "$OUT/bench.out")
+    # A bench that dies early still leaves a resident set, just the wrong one.
+    grep -q '^total runs' "$OUT/bench.out" || { echo "bench did not complete, see $OUT/bench.out" >&2; exit 1; }
     sleep 2
     python3 "$TOOLS/pagemap.py" "$pid" "$resident" >&2
     local hwm

src/agent/auth/codex.zig

@@ -155,7 +155,7 @@ fn deviceLogin(allocator: std.mem.Allocator, interrupt: ?*zenai.http.Interrupt)
 
     const code_res = try post(a, interrupt, device_code_url, "application/json", "{\"client_id\":\"" ++ client_id ++ "\"}");
     if (code_res.status != .ok) {
-        log.warn(.app, "codex device-code request failed", .{ .status = @intFromEnum(code_res.status), .body = code_res.body });
+        log.warn(.app, "codex device-code failed", .{ .status = @intFromEnum(code_res.status), .body = code_res.body });
         return error.DeviceCodeRequestFailed;
     }
     const dc = try std.json.parseFromSliceLeaky(DeviceCode, a, code_res.body, .{ .ignore_unknown_fields = true });

src/browser/frame/observers.zig

@@ -171,7 +171,7 @@ pub fn scheduleIntersectionChecks(frame: *Frame) void {
     frame._intersection.check_scheduled = true;
     frame.js.queueIntersectionChecks() catch |err| {
         frame._intersection.check_scheduled = false;
-        log.err(.frame, "frame.scheduleIntersectionChecks", .{ .err = err, .type = frame._type, .url = frame.url });
+        log.err(.frame, "scheduleIntersectionChecks", .{ .err = err, .type = frame._type, .url = frame.url });
     };
 }
 

src/browser/js/Env.zig

@@ -443,7 +443,7 @@ pub fn hideServiceWorker(self: *const Env, comptime is_frame: bool, v8_context:
     var deleted: v8.MaybeBool = undefined;
     v8.v8__Object__Delete(global_obj, v8_context, @ptrCast(self.disabled_api_names.get(self.isolate.handle, "caches")), &deleted);
     if (deleted.has_value == false or deleted.value == false) {
-        log.warn(.js, "failed to hide experimental API", .{ .interface = "global", .member = "caches" });
+        log.warn(.js, "experimental API not hidden", .{ .interface = "global", .member = "caches" });
     }
 }
 
@@ -457,7 +457,7 @@ fn deletePrototypeMember(self: *const Env, v8_context: *const v8.Context, global
     var deleted: v8.MaybeBool = undefined;
     v8.v8__Object__Delete(@ptrCast(prototype), v8_context, @ptrCast(names.get(isolate, member)), &deleted);
     if (deleted.has_value == false or deleted.value == false) {
-        log.warn(.js, "failed to hide experimental API", .{ .interface = interface, .member = member });
+        log.warn(.js, "experimental API not hidden", .{ .interface = interface, .member = member });
     }
 }
 

src/browser/screenshot.zig

@@ -155,7 +155,7 @@ pub fn collect(arena: Allocator, state: RenderTree.State, frame: *Frame) ![]cons
 // Any non-zero rc means nothing usable was written, so the caller has to fail
 // rather than hand back a truncated file. WriteFailed is the only error
 // jsonStringify's signature can carry, hence the log line.
-fn renderFailed(what: []const u8, rc: i32) error{WriteFailed} {
+fn renderFailed(comptime what: []const u8, rc: i32) error{WriteFailed} {
     log.err(.browser, what, .{ .reason = switch (rc) {
         RC_WRITE_REFUSED => "write refused",
         RC_INVALID => "invalid options",

src/browser/webapi/Performance.zig

@@ -617,7 +617,7 @@ fn scheduleBufferFull(self: *Performance) !void {
                 const exec = perf._exec;
                 const event = try Event.initTrusted(.wrap(BUFFER_FULL), .{}, exec.page);
                 try exec.dispatch(perf.asEventTarget(), event, perf._on_buffer_full, .{
-                    .context = "Performance.resourcetimingbufferfull",
+                    .context = "Performance.bufferfull",
                 });
                 return null;
             }

src/browser/webapi/ServiceWorkerGlobalScope.zig

@@ -404,7 +404,7 @@ fn dispatchExtendable(
     self._pending_event = event;
     errdefer self.releasePendingEvent();
 
-    try wgs.dispatch(wgs.asEventTarget(), base, handler, .{ .context = "ServiceWorkerGlobalScope lifecycle" });
+    try wgs.dispatch(wgs.asEventTarget(), base, handler, .{ .context = "service worker lifecycle" });
 
     // Seal only after the handlers have run, so a synchronous waitUntil is
     // counted before an empty pending set can complete the phase.

src/browser/webapi/SharedWorkerGlobalScope.zig

@@ -319,7 +319,7 @@ fn releaseScriptArena(self: *SharedWorkerGlobalScope) void {
 fn drainPendingConnects(self: *SharedWorkerGlobalScope) void {
     for (self._pending_connects.items) |port| {
         self.scheduleConnect(port) catch |err| {
-            log.warn(.browser, "shared worker drain connect failed", .{ .err = err });
+            log.warn(.browser, "shared worker drain failed", .{ .err = err });
         };
     }
     self._pending_connects.clearRetainingCapacity();
@@ -382,7 +382,7 @@ const ConnectCallback = struct {
             .cancelable = false,
         }, wgs.page)).asEvent();
 
-        try wgs.dispatch(target, event, on_connect, .{ .context = "SharedWorkerGlobalScope.connect" });
+        try wgs.dispatch(target, event, on_connect, .{ .context = "shared worker connect" });
         return null;
     }
 };

src/browser/webapi/navigation/Navigation.zig

@@ -326,7 +326,7 @@ fn fireNavigateSuccess(self: *Navigation, frame: *Frame) !void {
         null,
         frame.page,
     ) catch |err| {
-        log.warn(.event, "Navigation.fireNavigateSuccess", .{ .err = err });
+        log.warn(.event, "Navigation.navigatesuccess", .{ .err = err });
         return;
     };
 
@@ -356,7 +356,7 @@ fn fireCurrentEntryChangeEvent(
             },
             frame,
         ) catch |err| {
-            log.warn(.event, "Navigation.fireCurrentEntryChange", .{ .err = err });
+            log.warn(.event, "Navigation.currententrychange", .{ .err = err });
             return;
         };
 

src/log.zig

@@ -140,27 +140,54 @@ pub const Format = enum {
     pretty,
 };
 
-pub fn debug(scope: Scope, msg: []const u8, data: anytype) void {
+// A message is a short, plain-text key; the detail belongs in the kvs.
+const max_msg_len = 30;
+
+/// The comptime form of the checks in logToErased. Those only fire in a debug
+/// build *and* only once the line actually runs, so a message on a rare path
+/// can ship and then panic on whoever first hits it. Every message below is a
+/// literal, so the same rules can be a build error instead.
+fn validateMsg(comptime msg: []const u8) void {
+    comptime {
+        if (msg.len > max_msg_len) {
+            @compileError("log msg cannot be more than 30 characters: " ++ msg);
+        }
+        for (msg) |b| {
+            switch (b) {
+                'A'...'Z', 'a'...'z', ' ', '0'...'9', '_', '-', '.', '{', '}' => {},
+                else => @compileError("log msg contains an invalid character: " ++ msg),
+            }
+        }
+    }
+}
+
+pub fn debug(scope: Scope, comptime msg: []const u8, data: anytype) void {
+    comptime validateMsg(msg);
     log(scope, .debug, msg, data);
 }
 
-pub fn info(scope: Scope, msg: []const u8, data: anytype) void {
+pub fn info(scope: Scope, comptime msg: []const u8, data: anytype) void {
+    comptime validateMsg(msg);
     log(scope, .info, msg, data);
 }
 
-pub fn warn(scope: Scope, msg: []const u8, data: anytype) void {
+pub fn warn(scope: Scope, comptime msg: []const u8, data: anytype) void {
+    comptime validateMsg(msg);
     log(scope, .warn, msg, data);
 }
 
-pub fn err(scope: Scope, msg: []const u8, data: anytype) void {
+pub fn err(scope: Scope, comptime msg: []const u8, data: anytype) void {
+    comptime validateMsg(msg);
     log(scope, .err, msg, data);
 }
 
-pub fn fatal(scope: Scope, msg: []const u8, data: anytype) void {
+pub fn fatal(scope: Scope, comptime msg: []const u8, data: anytype) void {
+    comptime validateMsg(msg);
     log(scope, .fatal, msg, data);
 }
 
-pub fn note(scope: Scope, msg: []const u8, data: anytype) void {
+pub fn note(scope: Scope, comptime msg: []const u8, data: anytype) void {
+    comptime validateMsg(msg);
     if (comptime lp.IS_TEST == false) {
         log(scope, .note, msg, data);
     }
@@ -236,7 +263,7 @@ fn logTo(scope: Scope, level: Level, msg: []const u8, data: anytype, out: *std.I
 
 fn logToErased(scope: Scope, level: Level, msg: []const u8, kvs: []const KV, out: *std.Io.Writer) !void {
     if (lp.IS_DEBUG) {
-        if (msg.len > 30) {
+        if (msg.len > max_msg_len) {
             std.debug.print("debug-only-panic: log msg cannot be more than 30 characters: {s}", .{msg});
             @panic("invalid log msg");
         }

src/network/Certificates.zig

@@ -102,14 +102,14 @@ fn storeFromSystemCA(allocator: Allocator) !*crypto.X509_STORE {
                 // advances `ptr` past it, so we just hand it the rest of the buffer.
                 var ptr: [*]const u8 = bytes.ptr + index.*;
                 const x509 = crypto.d2i_X509(null, &ptr, @intCast(bytes.len - index.*)) orelse {
-                    log.warn(.app, "Skipping unparseable system cert", .{});
+                    log.warn(.app, "Skipping unparseable cert", .{});
                     continue;
                 };
                 defer crypto.X509_free(x509); // add_cert takes its own ref; drop ours.
 
                 const result = crypto.X509_STORE_add_cert(store, x509);
                 if (result != 1) {
-                    log.warn(.app, "Failed to add X509 cert to store", .{});
+                    log.warn(.app, "Failed to add X509 cert", .{});
                 }
                 count += 1;
             }

src/network/RobotsGate.zig

@@ -284,14 +284,14 @@ const RobotsContext = struct {
             switch (options.outcome) {
                 .decision => |d| switch (d) {
                     .allowed => network.robot_store.putAllowed(self.robots_url) catch |err| {
-                        log.warn(.browser, "failed to cache robots decision", .{ .url = self.robots_url, .err = err });
+                        log.warn(.browser, "cache robots decision", .{ .url = self.robots_url, .err = err });
                     },
                     .blocked => network.robot_store.putDisallowed(self.robots_url) catch |err| {
-                        log.warn(.browser, "failed to cache robots decision", .{ .url = self.robots_url, .err = err });
+                        log.warn(.browser, "cache robots decision", .{ .url = self.robots_url, .err = err });
                     },
                 },
                 .robots => |r| network.robot_store.put(self.robots_url, r) catch |err| {
-                    log.warn(.browser, "failed to cache robots rules", .{ .url = self.robots_url, .err = err });
+                    log.warn(.browser, "cache robots rules", .{ .url = self.robots_url, .err = err });
                 },
             }
         }

src/server/cdp/domains/network.zig

@@ -105,7 +105,7 @@ fn emulateNetworkConditions(cmd: *CDP.Command) !void {
     }
     // -1 disables a throughput limit.
     if (params.latency > 0 or params.downloadThroughput > 0 or params.uploadThroughput > 0) {
-        log.warn(.not_implemented, "Network.emulateNetworkConditions", .{ .param = "throttling" });
+        log.warn(.not_implemented, "Network.emulateConditions", .{ .param = "throttling" });
     }
     return cmd.sendResult(null, .{});
 }

src/server/http.zig

@@ -1036,7 +1036,7 @@ pub fn buildJSONVersionResponse(app: *const App, port: u16) ![]const u8 {
         // advertiseHost() falls back to 127.0.0.1 so clients can still
         // connect locally. Surface the trade-off so users running
         // outside the same host know they have to opt in.
-        log.note(.cdp, "advertising loopback for wildcard bind", .{
+        log.note(.cdp, "wildcard bind advertise", .{
             .message = "--host is a wildcard (0.0.0.0 / ::) without --advertise-host; clients on other hosts will need --advertise-host to reach the CDP endpoint",
         });
     }