diff --git a/src/js/internal/inspector/cdp.ts b/src/js/internal/inspector/cdp.ts index 69729d3845eb..a976840b95f6 100644 --- a/src/js/internal/inspector/cdp.ts +++ b/src/js/internal/inspector/cdp.ts @@ -664,15 +664,24 @@ class InspectorCDPAdapter { } #translateConsoleMessage(message: AnyObject): void { - const level = message.level ?? "log"; - const 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 (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. + 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", + text: text ?? "Uncaught", lineNumber: Math.max((message.line ?? 1) - 1, 0), columnNumber: Math.max((message.column ?? 1) - 1, 0), url: toCdpUrl(message.url ?? ""), @@ -682,15 +691,12 @@ 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, 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..28ddf6be675f 100644 --- a/test/js/node/inspector/inspector.test.ts +++ b/test/js/node/inspector/inspector.test.ts @@ -254,6 +254,103 @@ 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.countReset("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 ?? []).map(arg => arg.value)); +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 () => { + 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.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"). 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 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 // active throws ERR_INSPECTOR_ALREADY_ACTIVATED. const reopenInspectorFixture = ` @@ -472,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 @@ -562,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();