Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
24 changes: 15 additions & 9 deletions src/js/internal/inspector/cdp.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Comment thread
robobun marked this conversation as resolved.
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.
Comment thread
robobun marked this conversation as resolved.
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 ?? ""),
Expand All @@ -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),
});
}
Expand Down
25 changes: 25 additions & 0 deletions src/jsc/bindings/ConsoleObject.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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<const unsigned char*>(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<const unsigned char*>(input.data()), input.length());
}
Expand All @@ -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<const unsigned char*>(input.data()), input.length());
}
void ConsoleObject::timeLog(JSGlobalObject* globalObject, const String& label,
Ref<ScriptArguments>&& 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();
Expand All @@ -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<const unsigned char*>(input.data()), input.length());
}
Expand Down
101 changes: 99 additions & 2 deletions test/js/node/inspector/inspector.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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__");',
});
Comment thread
robobun marked this conversation as resolved.
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 = `
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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();
Expand Down
Loading