console: print [Circular] for %j of a cyclic value

RO
24d ago
+195-2

Problem

  • console.log("%j", value) throws TypeError: JSON.stringify cannot serialize cyclic structures. when value refers to itself. Node prints [Circular].
  • Cause: the ? on json_stringify_fast in the console's %j arm (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

  • %j is the JSON specifier of a console format string. Node catches the stringify error and compares err.name and err.message with the engine's text.
  • JSC gives the cycle error no kind: it is a plain TypeError, like the BigInt error. So the binding checks the ErrorInstance type and its own message slot.
  • test.each titles 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 %j runs the same instruction count as on main.
  • A cyclic %j still 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_label for test.each titles. Its write_json prints [Circular] for a cyclic %j row with its own compare of the error message. It does not change PercentTag::J in src/jsc/ConsoleObject.rs. The first revision of this PR also changed the test.each arm. That hunk is removed, so the two PRs do not conflict.
  • JSValue::json_stringify_for_format is available to that branch if one native rule for the cycle is wanted. It handles the cycle only, so write_json keeps 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__jsonStringifyForFormat is 461 bytes and JSValue::json_stringify_for_format is 187 bytes. write_with_formatting is 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_formatting runs 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 %j failure, 1000 times (a BigInt, and a throwing toJSON): JSC::Exception::create 1000 hits and JSC__VM__throwError 0 hits on both builds. The thrown value is the same object with the same .stack.
  • Reads of name and message on 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. 0 jsc-exception-lint findings on the new binding (run with --no-summaries). 0 new jsresult-swallow sites. The rust-externs cross-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 inside from_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:

valuetime per callRSS growth
{ a: 1, self }0.7 to 11 ms8 MB
a request and a response that refer to each other, 40 headers each19 to 45 ms93 MB
2000 keys of 50 characters and a self reference0.9 to 1.2 s1030 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.

valuenodethis 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 onsame
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 nulla TypeError about namenull passed on
engine cycle error with .name changedpassed 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.each and describe.each titles (format_label, src/runtime/test_runner/jest.rs:797): a cyclic %j row, a BigInt under %j, and %o. #44833 carries them.
  • A BigInt under %d, %i or %f and a Symbol under %s throw out of console.log (src/jsc/ConsoleObject.rs:2421-2558, the same match). Node prints 10n, 10n, 10 and Symbol(x). No tracker is open for these. #31777 is a different defect and #45337 covers a %s object with no toString.
  • %j of undefined, a function or a symbol prints nothing, where node prints undefined (#34239).
  • Formatter::print_json (src/jsc/ConsoleObject.rs:4193) and Tag::JSON (src/runtime/test_runner/pretty_format.rs:1817): plain console.log(x) calls a Date's own toJSON, 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:1430 and :1452). For console.log("a", "%j", cyclic) node prints a %j <ref *1> { a: 1, self: [Circular *1] }, main writes a and throws, and this PR prints a [Circular]. #33445 had the change. The stale bot closed it.
  • The JS util.format path (tryStringify in src/js/internal/util/inspect.js) is not changed. A stack overflow during its first failing %j can poison its cached message (inspect.js:2576). After that a cyclic %j throws there for the rest of the realm.
  • console.assert(false, "%j", c) is not in the spawned tests: a failing console.assert aborts 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).