Skip to content
Open
Show file tree
Hide file tree
Changes from 2 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
7 changes: 5 additions & 2 deletions src/js/internal/inspector/cdp.ts
Original file line number Diff line number Diff line change
Expand Up @@ -665,11 +665,14 @@

#translateConsoleMessage(message: AnyObject): void {
const level = message.level ?? "log";
const args = message.parameters?.length ? message.parameters : [{ type: "string", value: message.text ?? "" }];

Check warning on line 668 in src/js/internal/inspector/cdp.ts

View check run for this annotation

Claude / Claude Code Review

console.timeLog with extra args drops the elapsed-time text over the DevTools WebSocket

When `console.timeLog` is called with extra arguments (e.g. `console.timeLog("tm", "mid")`), the emitted `Runtime.consoleAPICalled` carries only `args: [{value:"mid"}]` — the label and elapsed time are dropped, whereas Node emits the timing string as `args[0]` followed by the extras. This path only became reachable with this PR's new `client->timeLog` forward, so it's a strict improvement over before (no event at all), but a one-line adapter tweak — for `message.type === "timing"` with non-empty
Comment thread
robobun marked this conversation as resolved.
Outdated
// 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",
Expand All @@ -690,7 +693,7 @@
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
94 changes: 94 additions & 0 deletions test/js/node/inspector/inspector.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -254,6 +254,100 @@ 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?.[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.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 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 = `
Expand Down
Loading