diff --git a/src/runtime/bake/client/inspect.ts b/src/runtime/bake/client/inspect.ts index 522725bb6da8..8d86cef44835 100644 --- a/src/runtime/bake/client/inspect.ts +++ b/src/runtime/bake/client/inspect.ts @@ -15,6 +15,11 @@ const inspectSymbol = Symbol.for("nodejs.util.inspect.custom"); +const threwWhilePrinting = "[threw while printing]"; + +// The values that print now. A console call from page code that one of them runs shares the list. +const printing: any[] = []; + export interface InspectOptions { showHidden?: boolean; depth?: number; @@ -55,7 +60,7 @@ const defaultOptions: InspectOptions = { export function inspect(obj: any, options: InspectOptions = {}) { // Set up context with merged options const ctx: InspectContext = { - seen: [], + seen: printing, currentDepth: 0, ...defaultOptions, ...options, @@ -76,40 +81,49 @@ function formatValue(ctx: InspectContext, value: any, recurseTimes: number) { if (value === null) return "null"; if (value === undefined) return "undefined"; - // Check for custom inspect implementation - if ( - ctx.customInspect !== false && - value !== null && - typeof value === "object" && - typeof value[inspectSymbol] === "function" && - value[inspectSymbol] !== inspect - ) { - return String(value[inspectSymbol](recurseTimes, { ...ctx })); - } - - // Check for circular references - if (ctx.seen.includes(value)) { - return "[Circular]"; - } - - // Format based on type - switch (typeof value) { - case "string": - return formatString(ctx, value); - case "number": - return formatNumber(value, ctx.numericSeparator!); - case "bigint": - return `${value}n`; - case "boolean": - return `${value}`; - case "symbol": - return formatSymbol(value); - case "function": - return formatFunction(value); - case "object": - return formatObject(ctx, value, recurseTimes); - default: - return String(value); + // Reading a page value can throw: a revoked Proxy, a cross-origin Window, a custom inspect function. + const seenLength = ctx.seen.length; + try { + // Check for custom inspect implementation + if ( + ctx.customInspect !== false && + value !== null && + typeof value === "object" && + typeof value[inspectSymbol] === "function" && + value[inspectSymbol] !== inspect + ) { + // A copy of `seen`: every call shares the list, and this function is page code. + return String(value[inspectSymbol](recurseTimes, { ...ctx, seen: ctx.seen.slice() })); + } + + // Check for circular references. A loop and not `includes`: a page can replace that method, and Svelte 5 does in development. + for (let i = 0; i < ctx.seen.length; i++) { + if (ctx.seen[i] === value) return "[Circular]"; + } + + // Format based on type + switch (typeof value) { + case "string": + return formatString(ctx, value); + case "number": + return formatNumber(value, ctx.numericSeparator!); + case "bigint": + return `${value}n`; + case "boolean": + return `${value}`; + case "symbol": + return formatSymbol(value); + case "function": + return formatFunction(value); + case "object": + return formatObject(ctx, value, recurseTimes); + default: + return String(value); + } + } catch { + // formatObject did not remove the value from `seen` + ctx.seen.length = seenLength; + return threwWhilePrinting; } } @@ -262,10 +276,14 @@ function formatArray(ctx: InspectContext, value: any[], recurseTimes: number) { const output: string[] = []; for (let i = 0; i < maxLength; i++) { - if (Object.prototype.hasOwnProperty.call(value, i)) { - output.push(formatValue(ctx, value[i], recurseTimes)); - } else { - output.push("empty"); + try { + if (Object.prototype.hasOwnProperty.call(value, i)) { + output.push(formatValue(ctx, value[i], recurseTimes)); + } else { + output.push("empty"); + } + } catch { + output.push(threwWhilePrinting); } } @@ -281,7 +299,11 @@ function formatArray(ctx: InspectContext, value: any[], recurseTimes: number) { if (keys.length > 0) { for (const key of keys) { - output.push(`${key}: ${formatValue(ctx, value[key], recurseTimes)}`); + try { + output.push(`${key}: ${formatValue(ctx, value[key], recurseTimes)}`); + } catch { + output.push(`${key}: ${threwWhilePrinting}`); + } } } @@ -331,7 +353,7 @@ function formatPlainObject(ctx: InspectContext, value: any, recurseTimes: number } } } catch (err) { - output.push(`${formatPropertyKey(key)}: undefined`); + output.push(`${formatPropertyKey(key)}: ${threwWhilePrinting}`); } } @@ -375,7 +397,7 @@ function formatWithPrototype(ctx: InspectContext, value: any, recurseTimes: numb // Add prototype prefix to distinguish from own properties output.push(`${formatPropertyKey(key)}: ${formatValue(ctx, value[key], recurseTimes)}`); } catch (err) { - output.push(`${formatPropertyKey(key)}: undefined`); + output.push(`${formatPropertyKey(key)}: ${threwWhilePrinting}`); } } @@ -499,7 +521,8 @@ function formatRegExp(value) { * @returns {string} Formatted error */ function formatError(value: Error) { - return value?.stack || value + ""; + // `stack` can be any value + return String(value?.stack || value + ""); } /** diff --git a/src/runtime/bake/hmr-runtime-client.ts b/src/runtime/bake/hmr-runtime-client.ts index bbffce06ba18..b597f46c2fd7 100644 --- a/src/runtime/bake/hmr-runtime-client.ts +++ b/src/runtime/bake/hmr-runtime-client.ts @@ -336,17 +336,39 @@ if (config.console) { ws.sendBuffered(str); } + // Console calls in progress, counted from before the browser's own call. Page code that a call runs can call console again. + let depth = 0; + if (typeof originalLog === "function") { console.log = function log(...args: any[]) { - originalLog(...args); - websocketInspect("l", args); + depth++; + try { + originalLog(...args); + // Only two levels are forwarded. A throw from here on only drops the forwarded line. + if (depth <= 2) { + try { + websocketInspect("l", args); + } catch {} + } + } finally { + depth--; + } }; } if (typeof consoleErrorWithoutInspector === "function") { console.error = function error(...args: any[]) { - consoleErrorWithoutInspector(...args); - websocketInspect("e", args); + depth++; + try { + consoleErrorWithoutInspector(...args); + if (depth <= 2) { + try { + websocketInspect("e", args); + } catch {} + } + } finally { + depth--; + } }; } } diff --git a/test/bake/dev/esm.test.ts b/test/bake/dev/esm.test.ts index 82f69cf6f377..4302a67229b4 100644 --- a/test/bake/dev/esm.test.ts +++ b/test/bake/dev/esm.test.ts @@ -1,7 +1,8 @@ // ESM tests are about various esm features in development mode. import { expect } from "bun:test"; import { isWindows } from "harness"; -import { devTest, emptyHtmlFile, minimalFramework } from "../bake-harness"; +import { once } from "node:events"; +import { Dev, devTest, emptyHtmlFile, minimalFramework } from "../bake-harness"; const liveBindingTest = devTest("live bindings with `var`", { framework: minimalFramework, @@ -431,6 +432,470 @@ devTest("function that is assigned to should become a live binding", { }, }); +// With `development.console`, console.log and console.error of the page also format their +// arguments in the page and send the text to the dev server. The tests below hold that the +// page's call returns for a value that cannot print, and that code of the page that logs while +// a line is forwarded does not start a recursion. +const consoleForwardingFiles = (script: string) => ({ + "index.html": emptyHtmlFile({ + scripts: ["index.ts"], + }), + "bun.app.ts": ` + import html from "./index.html"; + export default { + static: { + "/": html, + }, + development: { + console: true, + }, + fetch(req) { + return new Response("Not Found", { status: 404 }); + }, + }; + `, + "index.ts": ` + const custom = Symbol.for("nodejs.util.inspect.custom"); + // The test client sends the arguments of console.log to the test as JSON, which reads the + // value too. JSON reads nothing of a value that has this method. + const hidden = value => Object.defineProperty(value, "toJSON", { value: () => null }); + globalThis.results = {}; + globalThis.probe = function probe(name, value, method = "log", ...after) { + try { + console[method](name, value, ...after); + globalThis.results[name] = "returned"; + } catch (e) { + globalThis.results[name] = "threw " + e; + } + }; + ${script} + `, +}); + +// The text of every line that the page forwarded to the terminal. A value that prints on more +// than one line gives only its first line. +function forwardedLines(dev: Dev) { + return dev.output.lines + .filter(line => line.includes("[browser]")) + .map(line => Bun.stripANSI(line).slice("[browser] ".length)); +} + +devTest("browser console forwarding does not throw into the page", { + files: consoleForwardingFiles(` + probe("custom inspect function that throws", { [custom]() { throw new Error("thrown by the function"); } }); + probe("getter of an array that throws", hidden(Object.defineProperty([1, 2, 3], 1, { + get() { throw new Error("thrown by the getter"); }, + enumerable: true, + }))); + probe("getter of a class that throws", new (class Foo { + get bar() { throw new Error("thrown by the getter"); } + })()); + const revoked = Proxy.revocable({}, {}); + revoked.revoke(); + // JSON does not read the elements of a Set. + probe("revoked Proxy", new Set([revoked.proxy])); + const throwsForA = { + get(target, key, receiver) { + if (key === "a") throw new Error("thrown by the trap"); + return Reflect.get(target, key, receiver); + }, + }; + probe("Proxy that throws for one key", new Set([new Proxy({ a: 1, b: 2 }, throwsForA)])); + probe("Proxy of an array that throws for one key", new Set([new Proxy(Object.assign([1, 2], { a: 3, b: 4 }), throwsForA)])); + const revokedFunction = Proxy.revocable(function () {}, {}); + revokedFunction.revoke(); + probe("revoked Proxy of a function", new Set([revokedFunction.proxy])); + // The shape of a remote object of a library such as comlink: every property is the Proxy. + const remote = new Proxy(function () {}, { get: () => remote, apply: () => ({}) }); + probe("Proxy of a function", remote); + probe("Proxy of a Map", new Proxy(new Map([["k", 1]]), {})); + probe("object that inherits from Map.prototype", Object.create(Map.prototype)); + const throws = new Proxy({}, { getPrototypeOf() { throw new Error("thrown by the trap"); } }); + probe("value that throws twice", { a: throws, b: throws, c: [7] }); + probe("error whose stack is a symbol", Object.defineProperty(new Error("e"), "stack", { value: Symbol("s") })); + probe("error", new TypeError("with a stack")); + probe("value before another argument", { [custom]() { throw new Error("thrown by the function"); } }, "log", "after"); + // The console of the test client throws for a BigInt. The page still sees that. + probe("console that throws", 1n); + // The forwarder counts the console calls in progress. The count goes down when the console + // throws, so a line that is two calls deep is still forwarded. + probe("getter that logs after the console threw", new (class After { + get a() { + console.log("second call after the console threw"); + return 1; + } + })()); + console.log("done"); + `), + htmlFiles: [], + async test(dev) { + await using c = await dev.client("/"); + await dev.output.waitForLine(/\[browser\].* done/); + const returned = [ + "custom inspect function that throws", + "getter of an array that throws", + "getter of a class that throws", + "revoked Proxy", + "Proxy that throws for one key", + "Proxy of an array that throws for one key", + "revoked Proxy of a function", + "Proxy of a function", + "Proxy of a Map", + "object that inherits from Map.prototype", + "value that throws twice", + "error whose stack is a symbol", + "error", + "value before another argument", + "getter that logs after the console threw", + ]; + expect(await c.js`results`).toEqual({ + ...Object.fromEntries(returned.map(name => [name, "returned"])), + "console that throws": "threw TypeError: Do not know how to serialize a BigInt", + }); + // Every call that returned reached the console of the test client. + await c.expectMessage(...returned, "second call after the console threw", "done"); + + expect(forwardedLines(dev)).toEqual([ + "custom inspect function that throws [threw while printing]", + "getter of an array that throws [ 1, [threw while printing], 3 ]", + "getter of a class that throws Foo { bar: [threw while printing] }", + // One value that cannot print does not take the line, or the values beside it. + "revoked Proxy Set { [threw while printing] }", + "Proxy that throws for one key Set { { a: [threw while printing], b: 2 } }", + "Proxy of an array that throws for one key Set { [ 1, 2, a: [threw while printing], b: 4 ] }", + "revoked Proxy of a function Set { [threw while printing] }", + "Proxy of a function [threw while printing]", + "Proxy of a Map [threw while printing]", + "object that inherits from Map.prototype [threw while printing]", + "value that throws twice { a: [threw while printing], b: [threw while printing], c: [ 7 ] }", + "error whose stack is a symbol Symbol(s)", + "error TypeError: with a stack", + "value before another argument [threw while printing] after", + "second call after the console threw", + "getter that logs after the console threw After { a: 1 }", + "done", + ]); + expect(Bun.stripANSI(dev.output.lines.join("\n"))).toMatch(/\[browser\] error TypeError: with a stack\n\s+at /); + }, +}); + +// The forwarder sends each line on the socket of the dev server, and a page can replace send(). +// This test logs strings only, so it does not depend on the formatter. +devTest("browser console forwarding returns for a send() that throws or logs", { + files: consoleForwardingFiles(`console.log("loaded");`), + htmlFiles: [], + async test(dev) { + // `errors` lets the page call console.error. + await using c = await dev.client("/", { errors: [] }); + await c.expectMessage("loaded"); + // The line arrives when the socket is open, so the next lines go to send(). + await dev.output.waitForLine(/\[browser\].* loaded/); + + const threw = await c.js` + const send = WebSocket.prototype.send; + WebSocket.prototype.send = () => { + throw new Error("thrown by send"); + }; + try { + console.log("send that throws"); + console.error("send that throws"); + return "returned"; + } catch (e) { + return "threw " + e; + } finally { + WebSocket.prototype.send = send; + } + `; + expect(threw).toBe("returned"); + await c.expectMessage("send that throws"); + + // The line that send() logs is two console calls deep, and it is forwarded. Its own send() + // logs a line that is three calls deep, and that one is not. The limit of 100 only keeps a + // build that forwards every line from running until the stack is full. + const sends = await c.js` + const send = WebSocket.prototype.send; + let sends = 0; + WebSocket.prototype.send = function (data) { + if (sends++ < 100) console.log("send", data); + return send.call(this, data); + }; + try { + console.log("send that logs"); + } finally { + WebSocket.prototype.send = send; + } + console.log("line after"); + return sends; + `; + expect(sends).toBe(2); + await c.expectMessage("send that logs", "send", "send", "line after"); + await dev.output.waitForLine(/\[browser\].* line after/); + expect(forwardedLines(dev)).toEqual(["loaded", "send llsend that logs", "send that logs", "line after"]); + }, +}); + +// Code of the page runs while a line is forwarded: a trap of a Proxy, a getter, a custom inspect +// function, a built-in that the page replaced. The console of the test client runs code of the +// page too. That code can log. The forwarder forwards a console call that is at most two calls +// deep. Each limit below only keeps a build that forwards every call from running until the +// stack is full. +devTest("browser console forwarding returns for a value that logs while it prints", { + files: consoleForwardingFiles(` + globalThis.calls = { trap: 0, functionTrap: 0, getter: 0, hook: 0, builtIn: 0, element: 0, has: 0 }; + const logs = new Proxy({ a: 1 }, { + getPrototypeOf(target) { + if (calls.trap++ < 1000) console.log("trap", logs, { self: logs }); + return Reflect.getPrototypeOf(target); + }, + }); + probe("trap that logs its Proxy", logs); + + class Store { + get a() { + if (calls.getter++ < 1000) console.log("getter a", this); + return 1; + } + get b() { + if (calls.getter++ < 1000) console.log("getter b", { of: this }, Store); + return 2; + } + } + probe("getters that log their object", new Store()); + + // A function is not in the list of the values that print, and a custom inspect function + // runs before its object is in the list. Each of them logs again in the nested call, three + // calls deep. + const logsFunction = new Proxy(function f() {}, { + getPrototypeOf(target) { + if (calls.functionTrap++ < 1000) console.log("function trap", logsFunction); + return Reflect.getPrototypeOf(target); + }, + }); + probe("trap that logs its Proxy of a function", logsFunction); + + const hooked = { + [custom]() { + if (calls.hook++ < 1000) console.log("hook", hooked, null, 2); + return "text of the function"; + }, + }; + probe("custom inspect function that logs its object", hooked); + + // A custom inspect function gets the options of the formatter. It cannot add to the list. + const added = { added: 1 }; + probe("custom inspect function that adds to the list", { + [custom](depth, options) { + options.seen.push(added); + return "text of the function"; + }, + }); + probe("value that the function added", added); + + // A number prints through Object.is, and a page can replace a built-in. + const is = Object.is; + Object.is = function (a, b) { + if (calls.builtIn++ < 1000) console.log("Object.is", 7); + return is(a, b); + }; + probe("built-in that logs a number", 5); + Object.is = is; + + // The console of the test client reads each element of an array, as the console of Chrome + // does. So this getter also logs from inside the console's own call. + const elements = [1, 2, 3]; + let nesting = 0; + Object.defineProperty(elements, 0, { + get() { + calls.element++; + if (nesting < 8) { + nesting++; + try { + console.log("element getter", elements); + } finally { + nesting--; + } + } + return 1; + }, + enumerable: true, + }); + probe("array whose element getter logs it", elements); + + // Svelte replaces includes like this in development: after a miss, it asks each element of + // the array for a key. The formatter does not give it the list of the values that print. + const includes = Array.prototype.includes; + const state = Symbol("state"); + Array.prototype.includes = function (item, from) { + const found = includes.call(this, item, from); + if (!found) { + for (const element of this) { + if (typeof element === "object" && element !== null && state in element) break; + } + } + return found; + }; + probe("Proxy whose has trap logs, with includes replaced", new Set([new Proxy({ a: 1 }, { + has(target, key) { + calls.has++; + console.log("has trap"); + return Reflect.has(target, key); + }, + })])); + Array.prototype.includes = includes; + console.log("done"); + `), + htmlFiles: [], + async test(dev) { + await using c = await dev.client("/"); + await dev.output.waitForLine(/\[browser\].* done/); + // formatObject calls the trap of "logs" 9 times, once for each `instanceof`. + expect(await c.js`({ results, calls })`).toEqual({ + results: { + "trap that logs its Proxy": "returned", + "getters that log their object": "returned", + "trap that logs its Proxy of a function": "returned", + "custom inspect function that logs its object": "returned", + "custom inspect function that adds to the list": "returned", + "value that the function added": "returned", + "built-in that logs a number": "returned", + "array whose element getter logs it": "returned", + "Proxy whose has trap logs, with includes replaced": "returned", + }, + calls: { trap: 9, getter: 2, functionTrap: 2, hook: 2, builtIn: 2, element: 26, has: 0 }, + }); + + const lines = forwardedLines(dev); + expect(lines).toEqual([ + // A value that prints now is [Circular] in a call from the code that it runs. + ...Array.from({ length: 9 }, () => "trap [Circular] { self: [Circular] }"), + "trap that logs its Proxy { a: 1 }", + "getter a [Circular]", + "getter b { of: [Circular] } [Function: Store]", + "getters that log their object Store { a: 1, b: 2 }", + "function trap [Function: f]", + "trap that logs its Proxy of a function [Function: f]", + "hook text of the function null 2", + "custom inspect function that logs its object text of the function", + "custom inspect function that adds to the list text of the function", + "value that the function added { added: 1 }", + "Object.is 7", + "built-in that logs a number 5", + // The first line is from the console's own call, where the array does not print yet. + "element getter [ 1, 2, 3 ]", + "element getter [Circular]", + "array whose element getter logs it [ 1, 2, 3 ]", + "Proxy whose has trap logs, with includes replaced Set { { a: 1 } }", + "done", + ]); + // The console of the test client got every one of these calls, each before its line was + // sent. It also got the calls that are three or more calls deep. + const names = + /^(function trap|getter [ab]|hook|trap( that logs its Proxy( of a function)?)?|getters that log their object|custom inspect function that (logs its object|adds to the list)|value that the function added|Object\.is|built-in that logs a number|element getter|array whose element getter logs it|Proxy whose has trap logs, with includes replaced|done)/; + await c.expectMessageInAnyOrder( + ...lines.map(line => names.exec(line)![0]), + "function trap", + "hook", + "Object.is", + ...Array.from({ length: 21 }, () => "element getter"), + ); + }, +}); + +// A line of console.error goes to stderr of the dev server and a line of console.log to stdout, +// so one ordered list cannot hold both. +devTest("browser console forwarding does not make console.error throw", { + files: consoleForwardingFiles(` + const revoked = Proxy.revocable({}, {}); + revoked.revoke(); + probe("revoked Proxy", new Set([revoked.proxy]), "error"); + probe("Proxy of a Map", new Proxy(new Map([["k", 1]]), {}), "error"); + // A console.error from a getter that the forwarder runs still prints its error. + probe("getter that logs an error", new (class Cart { + get total() { + try { + throw new RangeError("no items"); + } catch (e) { + console.error("total failed", e); + return 0; + } + } + })(), "error"); + // console.log and console.error count their calls together, so the third call here is not + // forwarded. + probe("getters that call console.log and console.error", new (class First { + get a() { + console.log("second call", new (class Second { + get b() { + console.error("third call"); + return 2; + } + })()); + return 1; + } + })(), "error"); + // The console of the test client calls this function and throws. The page still sees that. + probe("console that throws", { [custom]() { throw new Error("thrown by the function"); } }, "error"); + // The console of the test client calls this function too, so it logs from inside the + // console's own call. console.error and console.log count their calls together. + globalThis.hookCalls = 0; + let nesting = 0; + const logsAnError = { + [custom]() { + hookCalls++; + if (nesting < 4) { + nesting++; + try { + console.error("hook", logsAnError); + } finally { + nesting--; + } + } + return "text of the function"; + }, + }; + probe("custom inspect function that logs an error", logsAnError, "error"); + console.error("done"); + `), + htmlFiles: [], + async test(dev) { + // `errors` lets the page call console.error. + await using c = await dev.client("/", { errors: [] }); + await dev.output.waitForLine(/\[browser\].* done/); + expect(await c.js`({ results, hookCalls })`).toEqual({ + results: { + "revoked Proxy": "returned", + "Proxy of a Map": "returned", + "getter that logs an error": "returned", + "getters that call console.log and console.error": "returned", + "console that throws": "threw Error: thrown by the function", + "custom inspect function that logs an error": "returned", + }, + hookCalls: 18, + }); + await c.expectMessage("second call"); + const secondCall = () => forwardedLines(dev).filter(line => line.startsWith("second call")); + expect(forwardedLines(dev).filter(line => !line.startsWith("second call"))).toEqual([ + "revoked Proxy Set { [threw while printing] }", + "Proxy of a Map [threw while printing]", + "total failed RangeError: no items", + "getter that logs an error Cart { total: 0 }", + "getters that call console.log and console.error First { a: 1 }", + "hook text of the function", + "hook text of the function", + "custom inspect function that logs an error text of the function", + "done", + ]); + // The line of console.log is on the other pipe of the dev server, so it can arrive before + // or after "done". waitForLine starts after the last line that it matched, so it can miss + // a line that arrived before. This wait looks at every line, and it ends when the dev + // server exits. + const exited = new AbortController(); + dev.output.once("close", () => exited.abort(new Error("the dev server exited"))); + while (secondCall().length === 0) await once(dev.output, "line", { signal: exited.signal }); + expect(secondCall()).toEqual(["second call Second { b: 2 }"]); + }, +}); + devTest("browser field is used", { files: { // Ensure the package.json gets parsed before the HTML is bundled.