From 1b4195384524e8cbf0f881776bc4c9077f300d18 Mon Sep 17 00:00:00 2001 From: robobun <117481402+robobun@users.noreply.github.com> Date: Sat, 25 Jul 2026 14:54:55 +0000 Subject: [PATCH 1/6] inspector: fix Runtime.consoleAPICalled timestamp unit and emit count/time events over the DevTools WebSocket Two fixes for the DevTools-protocol server that inspector.open() / --inspect exposes: - Runtime.consoleAPICalled.timestamp (and Runtime.exceptionThrown.timestamp) was forwarded verbatim from JSC's Console.messageAdded, which reports WallTime::secondsSinceEpoch(). CDP's Runtime.Timestamp is milliseconds since epoch, so the adapter now multiplies by 1000. A frontend that treated the old value as milliseconds rendered Jan-1970 timestamps. - console.count/countReset/time/timeLog/timeEnd never reached the inspector console agent: ConsoleObject.cpp forwarded messageWithTypeAndLevel and profile/profileEnd to inspectorController().consoleClient() but not the counter/timer entry points, so a connected DevTools saw no event at all for those calls. They are now forwarded the same way, which surfaces them as Runtime.consoleAPICalled (count as CDP type "debug", timeLog/timeEnd as "timeEnd"). --- src/js/internal/inspector/cdp.ts | 7 +- src/jsc/bindings/ConsoleObject.cpp | 25 +++++++ test/js/node/inspector/inspector.test.ts | 92 ++++++++++++++++++++++++ 3 files changed, 122 insertions(+), 2 deletions(-) diff --git a/src/js/internal/inspector/cdp.ts b/src/js/internal/inspector/cdp.ts index 69729d3845eb..4ea00859d861 100644 --- a/src/js/internal/inspector/cdp.ts +++ b/src/js/internal/inspector/cdp.ts @@ -666,10 +666,13 @@ class InspectorCDPAdapter { #translateConsoleMessage(message: AnyObject): void { const level = message.level ?? "log"; const args = message.parameters?.length ? message.parameters : [{ type: "string", value: message.text ?? "" }]; + // JSC's Console.messageAdded timestamp is WallTime::secondsSinceEpoch(); + // CDP Runtime.Timestamp is milliseconds since epoch. + const timestamp = typeof message.timestamp === "number" ? message.timestamp * 1000 : Date.now(); if (message.source !== "console-api" && level === "error") { this.#emitToClient("Runtime.exceptionThrown", { - timestamp: message.timestamp ?? Date.now(), + timestamp, exceptionDetails: { exceptionId: this.#nextExceptionId++, text: message.text ?? "Uncaught", @@ -690,7 +693,7 @@ class InspectorCDPAdapter { type, args, executionContextId: EXECUTION_CONTEXT_ID, - timestamp: message.timestamp ?? Date.now(), + timestamp, stackTrace: this.#translateStackTrace(message.stackTrace), }); } diff --git a/src/jsc/bindings/ConsoleObject.cpp b/src/jsc/bindings/ConsoleObject.cpp index 6d8fddae56b7..f2d8942f8e04 100644 --- a/src/jsc/bindings/ConsoleObject.cpp +++ b/src/jsc/bindings/ConsoleObject.cpp @@ -59,12 +59,22 @@ void ConsoleObject::messageWithTypeAndLevel(MessageType type, MessageLevel level } void ConsoleObject::count(JSGlobalObject* globalObject, const String& label) { + if (globalObject->inspectable()) { + if (auto client = globalObject->inspectorController().consoleClient()) { + client->count(globalObject, label); + } + } auto input = label.tryGetUTF8().value(); Bun__ConsoleObject__count(this->m_client, globalObject, reinterpret_cast(input.data()), input.length()); } void ConsoleObject::countReset(JSGlobalObject* globalObject, const String& label) { + if (globalObject->inspectable()) { + if (auto client = globalObject->inspectorController().consoleClient()) { + client->countReset(globalObject, label); + } + } auto input = label.tryGetUTF8().value(); Bun__ConsoleObject__countReset(this->m_client, globalObject, reinterpret_cast(input.data()), input.length()); } @@ -76,12 +86,22 @@ void ConsoleObject::takeHeapSnapshot(JSC::JSGlobalObject* globalObject, const St } void ConsoleObject::time(JSGlobalObject* globalObject, const String& label) { + if (globalObject->inspectable()) { + if (auto client = globalObject->inspectorController().consoleClient()) { + client->time(globalObject, label); + } + } auto input = label.tryGetUTF8().value(); Bun__ConsoleObject__time(this->m_client, globalObject, reinterpret_cast(input.data()), input.length()); } void ConsoleObject::timeLog(JSGlobalObject* globalObject, const String& label, Ref&& arguments) { + if (globalObject->inspectable()) { + if (auto client = globalObject->inspectorController().consoleClient()) { + client->timeLog(globalObject, label, arguments.copyRef()); + } + } auto input = label.tryGetUTF8().value(); auto args = arguments.ptr(); @@ -96,6 +116,11 @@ void ConsoleObject::timeLog(JSGlobalObject* globalObject, const String& label, } void ConsoleObject::timeEnd(JSGlobalObject* globalObject, const String& label) { + if (globalObject->inspectable()) { + if (auto client = globalObject->inspectorController().consoleClient()) { + client->timeEnd(globalObject, label); + } + } auto input = label.tryGetUTF8().value(); Bun__ConsoleObject__timeEnd(this->m_client, globalObject, reinterpret_cast(input.data()), input.length()); } diff --git a/test/js/node/inspector/inspector.test.ts b/test/js/node/inspector/inspector.test.ts index 3be3c1812761..47e2e06cdc9b 100644 --- a/test/js/node/inspector/inspector.test.ts +++ b/test/js/node/inspector/inspector.test.ts @@ -254,6 +254,98 @@ test("inspector.open() serves the DevTools protocol and /json discovery endpoint expect(summary.urlAfterClose).toBeNull(); }, 30_000); +// CDP Runtime.Timestamp is milliseconds since epoch, and console.count / +// console.time{Log,End} must surface as Runtime.consoleAPICalled events over +// the DevTools WebSocket (Node emits type "count" / "timeEnd"; JSC reports +// count at level "debug" and timeEnd/timeLog as type "timing"). +const consoleTimestampAndCountersFixture = ` +import inspector from "node:inspector"; + +inspector.open(0, "127.0.0.1", false); +const ws = new WebSocket(inspector.url()); +const pending = new Map(); +const consoleEvents = []; +let nextId = 1; +let resolveDone; +const donePromise = new Promise(resolve => (resolveDone = resolve)); +ws.onmessage = event => { + const message = JSON.parse(event.data); + if (message.id) { + pending.get(message.id)?.(message); + pending.delete(message.id); + } else if (message.method === "Runtime.consoleAPICalled") { + consoleEvents.push(message.params); + if (message.params.args?.[0]?.value === "__done__") resolveDone(); + } +}; +const send = (method, params) => + new Promise(resolve => { + const id = nextId++; + pending.set(id, resolve); + ws.send(JSON.stringify({ id, method, params })); + }); +await new Promise(resolve => (ws.onopen = resolve)); +await send("Runtime.enable", {}); + +const beforeMs = Date.now(); +await send("Runtime.evaluate", { + expression: + 'console.log("first-log");' + + 'console.count("cnt"); console.count("cnt");' + + 'console.time("tm"); console.timeLog("tm", "mid"); console.timeEnd("tm");' + + 'console.log("__done__");', +}); +await donePromise; +const afterMs = Date.now(); +ws.close(); +inspector.close(); + +const types = consoleEvents.map(event => event.type); +const firstTimestamp = consoleEvents[0]?.timestamp; +const countTexts = consoleEvents + .filter(event => String(event.args?.[0]?.value ?? "").startsWith("cnt: ")) + .map(event => event.args[0].value); +const timingArgs = consoleEvents + .filter(event => event.type === "timeEnd") + .map(event => event.args?.[0]?.value ?? ""); +process.stdout.write( + JSON.stringify({ types, firstTimestamp, beforeMs, afterMs, countTexts, timingArgs }) + "\\n", +); +`; + +test("Runtime.consoleAPICalled over the DevTools WebSocket reports a millisecond timestamp and emits events for console.count/time*", async () => { + using dir = tempDir("inspector-console-ws", { + "fixture.mjs": consoleTimestampAndCountersFixture, + }); + + await using proc = Bun.spawn({ + cmd: [bunExe(), "fixture.mjs"], + env: injectedScriptChildEnv, + cwd: String(dir), + stderr: "pipe", + }); + const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]); + expect({ stderrIfFailed: exitCode === 0 ? "" : stderr, exitCode }).toEqual({ stderrIfFailed: "", exitCode: 0 }); + + const summary = JSON.parse(stdout.trim().split("\n").at(-1)!); + + // JSC sends Console.messageAdded.timestamp in seconds (~1e9). CDP wants + // milliseconds: the adapter must rescale so the value lands between the + // Date.now() readings that bracket the console call. + expect(summary.firstTimestamp).toBeGreaterThanOrEqual(summary.beforeMs - 1); + expect(summary.firstTimestamp).toBeLessThanOrEqual(summary.afterMs + 1); + + // console.count / console.timeLog / console.timeEnd reach + // InspectorConsoleAgent and emit events. JSC reports count at + // {type:"log", level:"debug"} (so CDP type "debug") and both timeLog and + // timeEnd as {type:"timing"} (so CDP type "timeEnd"). + expect(summary.types).toEqual(["log", "debug", "debug", "timeEnd", "timeEnd", "log"]); + expect(summary.countTexts).toEqual(["cnt: 1", "cnt: 2"]); + // JSC's timeLog forwards the caller's extra arguments as parameters while + // timeEnd has none, so the adapter falls back to the formatted text there. + expect(summary.timingArgs).toEqual(["mid", expect.stringMatching(/^tm: \d+(\.\d+)?ms$/)]); +}, 30_000); + // Node supports close() followed by open() again; a second open() while one is // active throws ERR_INSPECTOR_ALREADY_ACTIVATED. const reopenInspectorFixture = ` From 79e136a77b3a97af656e56f8a366e04e39f38edf Mon Sep 17 00:00:00 2001 From: robobun <117481402+robobun@users.noreply.github.com> Date: Sat, 25 Jul 2026 15:26:25 +0000 Subject: [PATCH 2/6] test: cover console.countReset forwarding so all five ConsoleObject forwards are load-bearing --- test/js/node/inspector/inspector.test.ts | 14 ++++++++------ 1 file changed, 8 insertions(+), 6 deletions(-) diff --git a/test/js/node/inspector/inspector.test.ts b/test/js/node/inspector/inspector.test.ts index 47e2e06cdc9b..8a727fd3f0a4 100644 --- a/test/js/node/inspector/inspector.test.ts +++ b/test/js/node/inspector/inspector.test.ts @@ -291,7 +291,7 @@ const beforeMs = Date.now(); await send("Runtime.evaluate", { expression: 'console.log("first-log");' + - 'console.count("cnt"); console.count("cnt");' + + 'console.count("cnt"); console.count("cnt"); console.countReset("cnt"); console.count("cnt");' + 'console.time("tm"); console.timeLog("tm", "mid"); console.timeEnd("tm");' + 'console.log("__done__");', }); @@ -335,12 +335,14 @@ test("Runtime.consoleAPICalled over the DevTools WebSocket reports a millisecond expect(summary.firstTimestamp).toBeGreaterThanOrEqual(summary.beforeMs - 1); expect(summary.firstTimestamp).toBeLessThanOrEqual(summary.afterMs + 1); - // console.count / console.timeLog / console.timeEnd reach - // InspectorConsoleAgent and emit events. JSC reports count at + // console.count / console.countReset / console.timeLog / console.timeEnd + // reach InspectorConsoleAgent and emit events. JSC reports count at // {type:"log", level:"debug"} (so CDP type "debug") and both timeLog and - // timeEnd as {type:"timing"} (so CDP type "timeEnd"). - expect(summary.types).toEqual(["log", "debug", "debug", "timeEnd", "timeEnd", "log"]); - expect(summary.countTexts).toEqual(["cnt: 1", "cnt: 2"]); + // timeEnd as {type:"timing"} (so CDP type "timeEnd"). countReset emits + // nothing itself; the third count reads "cnt: 1" only if the reset reached + // the inspector agent. + expect(summary.types).toEqual(["log", "debug", "debug", "debug", "timeEnd", "timeEnd", "log"]); + expect(summary.countTexts).toEqual(["cnt: 1", "cnt: 2", "cnt: 1"]); // JSC's timeLog forwards the caller's extra arguments as parameters while // timeEnd has none, so the adapter falls back to the formatted text there. expect(summary.timingArgs).toEqual(["mid", expect.stringMatching(/^tm: \d+(\.\d+)?ms$/)]); From aa8db45477f6af1cbbb50e017f9b9bb3851ac5dd Mon Sep 17 00:00:00 2001 From: robobun <117481402+robobun@users.noreply.github.com> Date: Sat, 25 Jul 2026 16:20:14 +0000 Subject: [PATCH 3/6] inspector: prepend the elapsed-time text to timeLog args so the timing string reaches DevTools JSC's InspectorConsoleAgent::logTiming puts the "label: N.NNNms" string in Console.messageAdded.text and only the caller's extra arguments in parameters. The adapter preferred parameters when present, so the timing was dropped from the Runtime.consoleAPICalled args for timeLog. Prepend the text as args[0] in that case, matching Node. --- src/js/internal/inspector/cdp.ts | 8 +++++++- test/js/node/inspector/inspector.test.ts | 10 ++++++---- 2 files changed, 13 insertions(+), 5 deletions(-) diff --git a/src/js/internal/inspector/cdp.ts b/src/js/internal/inspector/cdp.ts index 4ea00859d861..5a377c805103 100644 --- a/src/js/internal/inspector/cdp.ts +++ b/src/js/internal/inspector/cdp.ts @@ -665,7 +665,13 @@ class InspectorCDPAdapter { #translateConsoleMessage(message: AnyObject): void { const level = message.level ?? "log"; - const args = message.parameters?.length ? message.parameters : [{ type: "string", value: message.text ?? "" }]; + let args = message.parameters?.length ? message.parameters : [{ type: "string", value: message.text ?? "" }]; + // JSC's timeLog puts the elapsed-time string in `text` and only the + // caller's extra data in `parameters`; Node emits the timing string as + // args[0] followed by the extras. + if (message.type === "timing" && message.parameters?.length && message.text) { + args = [{ type: "string", value: message.text }, ...args]; + } // JSC's Console.messageAdded timestamp is WallTime::secondsSinceEpoch(); // CDP Runtime.Timestamp is milliseconds since epoch. const timestamp = typeof message.timestamp === "number" ? message.timestamp * 1000 : Date.now(); diff --git a/test/js/node/inspector/inspector.test.ts b/test/js/node/inspector/inspector.test.ts index 8a727fd3f0a4..a0a15971b9c4 100644 --- a/test/js/node/inspector/inspector.test.ts +++ b/test/js/node/inspector/inspector.test.ts @@ -307,7 +307,7 @@ const countTexts = consoleEvents .map(event => event.args[0].value); const timingArgs = consoleEvents .filter(event => event.type === "timeEnd") - .map(event => event.args?.[0]?.value ?? ""); + .map(event => (event.args ?? []).map(arg => arg.value)); process.stdout.write( JSON.stringify({ types, firstTimestamp, beforeMs, afterMs, countTexts, timingArgs }) + "\\n", ); @@ -343,9 +343,11 @@ test("Runtime.consoleAPICalled over the DevTools WebSocket reports a millisecond // the inspector agent. expect(summary.types).toEqual(["log", "debug", "debug", "debug", "timeEnd", "timeEnd", "log"]); expect(summary.countTexts).toEqual(["cnt: 1", "cnt: 2", "cnt: 1"]); - // JSC's timeLog forwards the caller's extra arguments as parameters while - // timeEnd has none, so the adapter falls back to the formatted text there. - expect(summary.timingArgs).toEqual(["mid", expect.stringMatching(/^tm: \d+(\.\d+)?ms$/)]); + // JSC's timeLog puts the elapsed-time string in `text` and only the caller's + // extra data in `parameters`; the adapter prepends the text so the timing is + // args[0] for both timeLog and timeEnd, matching Node. + const timingText = expect.stringMatching(/^tm: \d+(\.\d+)?ms$/); + expect(summary.timingArgs).toEqual([[timingText, "mid"], [timingText]]); }, 30_000); // Node supports close() followed by open() again; a second open() while one is From bdd6c98bff5468c0b8bc408a7f739a458f805dfd Mon Sep 17 00:00:00 2001 From: robobun <117481402+robobun@users.noreply.github.com> Date: Sat, 25 Jul 2026 18:29:11 +0000 Subject: [PATCH 4/6] lint: destructure Console.messageAdded once in translateConsoleMessage --- src/js/internal/inspector/cdp.ts | 15 ++++++--------- 1 file changed, 6 insertions(+), 9 deletions(-) diff --git a/src/js/internal/inspector/cdp.ts b/src/js/internal/inspector/cdp.ts index 5a377c805103..a976840b95f6 100644 --- a/src/js/internal/inspector/cdp.ts +++ b/src/js/internal/inspector/cdp.ts @@ -664,13 +664,13 @@ class InspectorCDPAdapter { } #translateConsoleMessage(message: AnyObject): void { - const level = message.level ?? "log"; - let args = message.parameters?.length ? message.parameters : [{ type: "string", value: message.text ?? "" }]; + const { level = "log", parameters, text, type: jscType } = message; + let args = parameters?.length ? parameters : [{ type: "string", value: text ?? "" }]; // JSC's timeLog puts the elapsed-time string in `text` and only the // caller's extra data in `parameters`; Node emits the timing string as // args[0] followed by the extras. - if (message.type === "timing" && message.parameters?.length && message.text) { - args = [{ type: "string", value: message.text }, ...args]; + if (jscType === "timing" && parameters?.length && text) { + args = [{ type: "string", value: text }, ...args]; } // JSC's Console.messageAdded timestamp is WallTime::secondsSinceEpoch(); // CDP Runtime.Timestamp is milliseconds since epoch. @@ -681,7 +681,7 @@ class InspectorCDPAdapter { timestamp, exceptionDetails: { exceptionId: this.#nextExceptionId++, - text: message.text ?? "Uncaught", + text: text ?? "Uncaught", lineNumber: Math.max((message.line ?? 1) - 1, 0), columnNumber: Math.max((message.column ?? 1) - 1, 0), url: toCdpUrl(message.url ?? ""), @@ -691,10 +691,7 @@ class InspectorCDPAdapter { return; } - const type = - message.type && CONSOLE_TYPE_MAP[message.type] - ? CONSOLE_TYPE_MAP[message.type] - : (CONSOLE_LEVEL_MAP[level] ?? "log"); + const type = (jscType && CONSOLE_TYPE_MAP[jscType]) || (CONSOLE_LEVEL_MAP[level] ?? "log"); this.#emitToClient("Runtime.consoleAPICalled", { type, args, From 71bbee0df3dc0a7fb1e8b4795112afe9832c24f2 Mon Sep 17 00:00:00 2001 From: robobun <117481402+robobun@users.noreply.github.com> Date: Sat, 25 Jul 2026 19:07:02 +0000 Subject: [PATCH 5/6] ci: retrigger gate (release smoke-test hit a transient 'Permission denied' on the freshly stripped binary) From 2ae31c0ba2e4d763f7ae5c78216eb17a30de8b63 Mon Sep 17 00:00:00 2001 From: robobun <117481402+robobun@users.noreply.github.com> Date: Sat, 25 Jul 2026 19:44:41 +0000 Subject: [PATCH 6/6] test: exit the consoleAPICalled fixture explicitly and give the waitForDebugger subprocess tests the same 30s budget as their neighbours --- test/js/node/inspector/inspector.test.ts | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/test/js/node/inspector/inspector.test.ts b/test/js/node/inspector/inspector.test.ts index a0a15971b9c4..28ddf6be675f 100644 --- a/test/js/node/inspector/inspector.test.ts +++ b/test/js/node/inspector/inspector.test.ts @@ -311,6 +311,7 @@ const timingArgs = consoleEvents process.stdout.write( JSON.stringify({ types, firstTimestamp, beforeMs, afterMs, countTexts, timingArgs }) + "\\n", ); +process.exit(0); `; test("Runtime.consoleAPICalled over the DevTools WebSocket reports a millisecond timestamp and emits events for console.count/time*", async () => { @@ -568,7 +569,7 @@ test("inspector.waitForDebugger() blocks until a client resumes the process", as expect(JSON.parse(stdout.trim().split("\n").at(-1)!)).toEqual({ resumedByClient: true }); expect(exitCode).toBe(0); -}); +}, 30_000); // A second waitForDebugger() must block again for a fresh // Runtime.runIfWaitingForDebugger — Node blocks on every call, and it must be @@ -658,7 +659,7 @@ test("inspector.waitForDebugger() blocks again on the second call after a fronte expect(JSON.parse(stdout.trim().split("\n").at(-1)!)).toEqual({ first: 1, second: 2 }); expect(exitCode).toBe(0); -}); +}, 30_000); test("Runtime.consoleAPICalled is emitted while the Runtime domain is enabled", () => { const session = new inspector.Session();