console: print [Circular] for %j of a cyclic value
Problem
console.log("%j", value)throwsTypeError: JSON.stringify cannot serialize cyclic structures.whenvaluerefers to itself. Node prints[Circular].- Cause: the
?onjson_stringify_fastin the console's%jarm (src/jsc/ConsoleObject.rs:2594). - No user reported it. An audit against node found it.
Fix
- The arm calls a new format-only binding,
JSC__JSValue__jsonStringifyForFormat(src/jsc/bindings/UtilInspect.cpp). It clears JSC's own cycle error and returns[Circular]. - Every other failure is passed on unchanged. The check reads engine state only: no user code runs.
- Verified:
test/js/web/console/console-log.test.ts(7 new tests, all fail on bun 1.4.3). - Self-reviewed: 20 concerns raised, 18 addressed. Not taken: widening to the other specifiers and to
util.format(Notes).
Background
%jis the JSON specifier of a console format string. Node catches the stringify error and compareserr.nameanderr.messagewith the engine's text.- JSC gives the cycle error no kind: it is a plain
TypeError, like the BigInt error. So the binding checks theErrorInstancetype and its ownmessageslot. test.eachtitles throw the same way. #44833 rewrites that arm, so this PR leaves it alone.- Considered #34607's arm-local compare: it runs getters on the thrown value and rethrows every other failure.
Downsides
- Release binary: text +768 bytes (first revision, Notes). A successful
%jruns the same instruction count as on main. - A cyclic
%jstill pays JSC's late cycle detection (#40974): about 1 s and 1 GB of RSS for a 2000-key object. Main pays it and then throws. - 7 of 21 hand-made thrown values differ from node (Notes). Maintainers: accept that, or port node's reads?
Notes
Repro (node v26.3.0, bun 1.4.3, main f841e36709, this branch)
const c = { a: 1 }; c.self = c;
console.log("%j", c); // node: [Circular] bun 1.4.3 and main: throws TypeError this PR: [Circular]
console.log("user %s: %j", "x", c); // node: user x: [Circular] main: writes "user x: ", then throws this PR: user x: [Circular]
console.log("%j", { toJSON() { throw new Error("tj"); } }); // all: the Error is passed on
console.log("%j", 10n); // all: TypeError
Every console method that takes a format string reaches the same arm: log, info, debug, warn, error, trace, assert, group, groupCollapsed, dirxml. The tests cover all of them but assert. The realistic trigger is a handler that logs a request or a response object with %j. The process exits 1 on bun where node prints one line.
The parity claim is for a format string in the first argument. See "Not in this PR" for a format string in a later argument.
Related work
- #44833 (draft, which folded #44830) rewrites
format_labelfortest.eachtitles. Itswrite_jsonprints[Circular]for a cyclic%jrow with its own compare of the error message. It does not changePercentTag::Jinsrc/jsc/ConsoleObject.rs. The first revision of this PR also changed thetest.eacharm. That hunk is removed, so the two PRs do not conflict. JSValue::json_stringify_for_formatis available to that branch if one native rule for the cycle is wanted. It handles the cycle only, sowrite_jsonkeeps its BigInt branch.
Kind check or string compare
JSC throws the cycle with a plain throwTypeError in Stringifier::appendStringifiedValue. ErrorInstance has kind bits for stack overflow, out of memory and parse errors. It has none for a cycle. So the binding checks what the engine exposes without entering script: the thrown cell is an ErrorInstance, errorType() is TypeError, and the own message slot holds the engine's text.
A kind bit set at JSC's throw site is a different rule, not a cleanup of this one. A bit is never on a user-made error. So new TypeError(<engine text>) and a TypeError subclass stop printing [Circular], where node prints it for both. The engine error with its message changed or deleted starts printing it. The bit also needs a merged oven-sh/WebKit change before bun can pin it. Whether to add it is a second question for a maintainer, beside the one in Downsides.
Measurements
Release builds of main f841e36709 and of the first revision of this PR (744daf9fea), same WebKit pin (3d3257150c), Linux x64. That revision also changed the test.each call site. The binding and the console arm are the same code in this revision. The builds were not repeated after the test.each hunk was removed.
- Release binary: text +768 bytes (
size: 106,141,927 to 106,142,695).JSC__JSValue__jsonStringifyForFormatis 461 bytes andJSValue::json_stringify_for_formatis 187 bytes.write_with_formattingis 3,156 bytes per instantiation on both builds. New exported symbols: 0 (692 on both). Host functions: 0. - Successful
console.log('%j', o):write_with_formattingruns 145 instructions and 16 conditional branches on both builds. The binding runs 45 instructions and 6 conditional branches on both builds. These are gdb single-step counts in the function's own frame, identical over 3 runs. - Per successful
%j: 1 binding call, 3 malloc, 3 free, 1 write on both builds. These are gdb hit counts, differenced over 100 and 300 calls. - Passed-on
%jfailure, 1000 times (a BigInt, and a throwingtoJSON):JSC::Exception::create1000 hits andJSC__VM__throwError0 hits on both builds. The thrown value is the same object with the same.stack. - Reads of
nameandmessageon the thrown value per failing%j: 0 and 0 (node v26.3.0: 1 and 1). - Exception checks: 0 validator reports in the test file under
BUN_JSC_validateExceptionChecks=1. 0jsc-exception-lintfindings on the new binding (run with--no-summaries). 0 newjsresult-swallowsites. Therust-externscross-check was not run: it needs the summary pass over the pinned WebKit sources, which were not on the machine. The extern is called only insidefrom_js_host_call_generic, like its twin.
Cost of a cyclic %j
The binding makes the same JSONStringify call as before. JSC reports a cycle late (#40974, oven-sh/WebKit#540, #40983). JSON.stringify(value) on bun 1.4.3, 5 calls each:
| value | time per call | RSS growth |
|---|---|---|
{ a: 1, self } | 0.7 to 11 ms | 8 MB |
| a request and a response that refer to each other, 40 headers each | 19 to 45 ms | 93 MB |
| 2000 keys of 50 characters and a self reference | 0.9 to 1.2 s | 1030 MB |
Main pays this and then throws. After this change the call succeeds at the same cost, each time it runs.
Thrown values against node v26.3.0
One process per row, console.log("%j", v). Each forged row uses the text of the engine it runs on. 7 of 21 rows differ. Real cycles and the controls: 0 differ.
| value | node | this PR |
|---|---|---|
object cycle, array cycle, cycle made by toJSON, cycle made by a getter, JSON.stringify(cycle) inside toJSON | [Circular] | same |
toJSON throws an Error, a BigInt, an Error with the engine text, the engine error with its message changed or deleted, thrown 1, thrown 'str' | passed on | same |
new TypeError(<engine text>), a TypeError subclass with that text | [Circular] | same |
plain { name: "TypeError", message } | [Circular] | passed on |
| RangeError renamed to TypeError | [Circular] | passed on |
engine error with an accessor message | [Circular] | passed on |
TypeError with a rope message | [Circular] | passed on |
| Proxy of a TypeError | [Circular] | passed on |
thrown null | a TypeError about name | null passed on |
engine cycle error with .name changed | passed on | [Circular] |
On main the six "passed on" rows already pass the value on. Only the last row changes against main.
Not in this PR
test.eachanddescribe.eachtitles (format_label,src/runtime/test_runner/jest.rs:797): a cyclic%jrow, a BigInt under%j, and%o. #44833 carries them.- A BigInt under
%d,%ior%fand a Symbol under%sthrow out ofconsole.log(src/jsc/ConsoleObject.rs:2421-2558, the samematch). Node prints10n,10n,10andSymbol(x). No tracker is open for these. #31777 is a different defect and #45337 covers a%sobject with notoString. %jofundefined, a function or a symbol prints nothing, where node printsundefined(#34239).Formatter::print_json(src/jsc/ConsoleObject.rs:4193) andTag::JSON(src/runtime/test_runner/pretty_format.rs:1817): plainconsole.log(x)calls a Date's owntoJSON, and a generator object with a self reference throws the same TypeError. The binding must not be used there: it would print[Circular]for the whole value. #44268 rewrites both formatters.- A format string in a later argument. bun substitutes specifiers in every later string argument (
src/jsc/ConsoleObject.rs:1430and:1452). Forconsole.log("a", "%j", cyclic)node printsa %j <ref *1> { a: 1, self: [Circular *1] }, main writesaand throws, and this PR printsa [Circular]. #33445 had the change. The stale bot closed it. - The JS
util.formatpath (tryStringifyinsrc/js/internal/util/inspect.js) is not changed. A stack overflow during its first failing%jcan poison its cached message (inspect.js:2576). After that a cyclic%jthrows there for the rest of the realm. console.assert(false, "%j", c)is not in the spawned tests: a failingconsole.assertaborts under the exception validator on main (#44950). Run by hand, it prints[Circular].- bun writes the text before a failing specifier and then throws (node writes nothing). That is not changed.
Suites run on the debug build
console-log.test.ts, test/regression/issue/24234.test.ts, test/js/bun/spawn/spawn.ipc.test.ts, test/js/web/console/, test/js/bun/console/, test/js/node/console/, test/internal/source-lints/. One test timed out locally: console-table.test.ts, "cell values survive a full GC". It runs 64 full GCs, takes 6.4 s in this ASAN debug build, and does not reach the changed code.
Each guard of the binding has a test row. Removing the errorType() check or the text compare makes "passes every other failure on unchanged" fail (checked by mutation).