One value formatter for console, Bun.inspect, the error printer and bun:test

Closed
DY
13d ago
+8254-4695

Problem

Bun prints JS values with two formatters. src/jsc/ConsoleObject.rs serves console.*, Bun.inspect, the uncaught-error printer and matcher messages. src/runtime/test_runner/pretty_format.rs was forked from it for bun:test snapshots and diffs. Both print whatever a program can build, and neither had one place where a value is checked before a printer descends into it:

  • The stack check, the cycle check and the classifier were per tag and per copy. Tag::JSX and Tag::Proxy had no guard in one copy, Tag::Error removed itself from the visited set before recursing, Formatter::new handed out a StackCheck that always says "safe".
  • Every printer read what it needed with ordinary property access, so a getter, a Proxy trap, a length, a size, a toString or an iterator supplied by the value could throw, hang or change the value mid-print.
  • Three C++ property walks each had their own copy of which keys are hidden, how a slot becomes a value, and in which order keys come.

Each instance has been fixed on its own, in one copy, for one tag. The list at the end has the open PRs that do that. The same shapes keep coming back because nothing stops the next printer, tag or call site from skipping the check.

mainthis PR
console.log of a JSX element that is its own childSIGSEGV[Circular] in place of the child
console.log of 100,000 nested ProxiesSIGSEGVprints the target
expect(v).toEqual(1), v a 50,000-deep arraySIGSEGVfails with a diff, 121 ms
expect(v).toEqual(1), v 24 levels of { l: v, r: v }no result in 180 s443 ms
Bun.inspect(e, { depth: 100 }), e a chain of 10 assigned causeslast error rendered 256 timesonce
Bun.inspect(map.entries())uses up the caller's iteratorleaves it alone

(debug build, linux x64)

The repros from the two issues with one, on release builds:

mainthis PR
#37310, expect(leaf).toBeNull(), happy-dom, 421 nodes2,236 ms52 ms
1,641 nodes8,547 ms143 ms
6,481 nodes28,518 ms, does not throw606 ms, throws
14,521 nodes38,246 ms, does not throw1,126 ms, throws
#40077 (first of its four), expect(container).toMatchSnapshot(), 20 list items in happy-dom58.8 GB and still running at 200 san error in 225 ms, 210 MB

Fix

One formatter, bun_jsc::Formatter, with a Style (Console or Jest) that only selects the text.

One gate (src/jsc/formatter/guard.rs). print_as calls enter, which checks the native stack, the path (cycles) and the shared-reference budget, and returns an Entered token or prints a placeholder. Every printer takes the token, and only enter can make one. Printing the same value under another tag goes through dispatch with the token, which replaces the remove_before_recurse dance. Tag::holds_values has no _ arm, so a new tag does not compile until someone decides. The error printer's cause and errors walks go through the same gate instead of a private copy of the visited set.

Named policies. Formatter::new is private. A caller states what it prints for: console, table_cell, error_handler, message, matcher_message, diff, snapshot. The policy decides whether a stack overflow throws or stops the print, and what happens past the budget. 108 call sites state one.

Shared-reference budget. The visited set now remembers what was printed, not only what is on the path. Bytes printed while repeating an already printed value count against a budget, and past it the value prints as [Object ...] / [Object]. Output that is linear in the size of the value is never cut. Every top-level value starts with the whole budget, and the "printed" marks are dropped at each garbage collection, because they do not keep their objects alive and a new object can get the address of a dead one.

sinkbudget for repeats
console.*, Bun.inspect, console.table, the error printer2^27 bytes, where util.inspect stops descending
diffs, matcher messages, values quoted in an error1 MiB
snapshots64 MiB, then an error: a stored snapshot is exact or it is nothing

util.inspect counts all output, so it also abbreviates a large value that repeats nothing. Counting repeats cuts only what was already printed in full. Where it matters the two agree: for 40 levels of { a: o, b: o } at depth: Infinity, release build: Bun prints 134,224,805 characters in 296 ms, Node v26.7.0 prints 134,402,654 in 483 ms.

One reader (src/jsc/formatter/reader.rs, src/jsc/bindings/FormatterReads.cpp). Own data properties, boxed primitives, RegExp source, native Event fields, array length, present indexes and Map/Set iterator contents come from internal state and run no user code. Listings are bounded by what the value holds or by a fixed budget, not by a length or a size it reports: a Map or Set ends after the entry count taken before the first entry printed, a subclass is listed by its own iterator for as many steps as it reports entries (quick-lru extends Map and keeps its entries elsewhere) and at most 2^20 past what it holds, an array is walked by its present indexes, and console.table and AggregateError.errors give any other iterable 1000 and 100 steps. "Hooks that still run" below has what is left.

One property walk. forEachProperty, forEachPropertyNonIndexed and forEachPropertyOrdered are one template over PropertyWalk. The sorted walk writes snapshots, so it keeps three differences: it does not ask the class for its property names (a module namespace and a global proxy list nothing), it lists a non-enumerable __esModule, and an accessor JSC cannot cache is null.

Printers outside bun_jsc (Response, Request, Blob, S3Client, Archive, BuildArtifact) take the concrete Formatter and the same byte writer as the built-in printers. The ConsoleFormatter and AsymmetricMatcherFormatter bridge traits and their adapters are gone, and the hook propagates a thrown error instead of discarding it.

A throw that was lost. BunString__toErrorInstance returned an empty value with no exception pending for a message longer than the longest string. The matcher's throw was then a no-op and the failed assertion passed, which is the second half of #37310. It returns JSC's out-of-memory error, like "x".repeat(2 ** 31).

Deleted: pretty_format.rs (2,935 lines; 225 lines that print asymmetric matchers remain as asymmetric_matcher_format.rs, 905 lines of layout are in src/jsc/formatter/jest.rs), both bridge traits, make_formatter, FormatterTestExt, JSValue::for_each_property*, for_each_with_context, TopExceptionScope::init, StackCheck::update, impl Default for StackCheck (the check that always says "safe"), Unaligned::get.

What keeps it fixed

  • The token, the private constructor and the exhaustive match are compile errors.
  • test/internal/source-lints/formatter-reads.test.ts is a ratchet on the reads that can run user code inside the printers.
  • "hostile values in every sink" at the end of test/js/bun/util/inspect.test.js checks 62 kinds of hostile value against 24 sinks, one process for each of the seven policies. A new kind of value or a new sink is one line. On main every one of the seven fails: six end in SIGSEGV and console.table in SIGABRT under a 16 GB limit.

Text that changes

Snapshots: nothing main could store, with three new errors. The snapshot policy keeps the classification, the reads, the cycle detection and the line-length bookkeeping of the formatter that wrote the stored ones, bugs included: <input type="text"value="foo" />, a trailing Response {} and BuildArtifact {}, a Proxy as raw JSON. So in a snapshot a getter, a replaced toString or the iterator of a subclass still runs, as on main. It gains the stack check, the budget and the bounds. All of it hangs off Formatter::is_stored_snapshot, for a follow-up to remove.

Compared with main, release builds of both:

snapshotsdiffer
1,243 values in 40 containers49,72058
the same values next to a Promise at 91 line lengths, 13 layouts16,15927
random trees of those values8,0000
random cyclic graphs2,9880

The 58 and 26 of the 27 are a WeakMap and a WeakSet with an own numeric size, where main throws Type error. The other one prints uninitialized memory (SlowBuffer). Main crashes on 12 more of the cyclic graphs, this branch on none. Six tests in snapshot.test.ts pin what differs from a diff. Five pass on main, four of them with expected text that main's binary wrote. The sixth has the bounds, which hang there.

New errors, for values main could store:

  • more than 64 MiB printed for repeated values (main wrote a 76 MB file for an 80 KB object referenced 900 times),
  • more than 2^20 array holes in a row,
  • a Map or Set whose iterator yields more than 2^20 entries and more than its size.

Diffs, which are not stored:

  • A Proxy prints as its target, in the normal layout. It was mis-indented raw JSON, a Proxy of a function printed [class ProxyObject], and a revoked or cyclic one replaced the assertion error with a TypeError from JSON.stringify. A revoked one prints <Revoked Proxy>.
  • arguments prints as Arguments [, as in Jest. A React 19 element prints as JSX. An iterator prints as Map Iterator {}, Array Iterator {}, Iterator Helper {}, RegExp String Iterator {}; they were {}.
  • JSX props are separated, five on the tag's line and the rest one to a line. Response and BuildArtifact print once.
  • A run of more than 8 array holes is one N x empty items, line.
  • [Circular] stands for a React element, an event, a Response or an asymmetric matcher that reaches itself. It printed the value once more first.
  • The internal-state reads under "Console" apply.
  • Three notes can follow a diff: repeated values were abbreviated, a value was too deep, or the two sides print the same.

Console:

  • Symbol keys print after string keys, whichever walk the object takes, as in Node.
  • An own enumerable Symbol.toStringTag prints. A non-enumerable __esModule is hidden and an enumerable one prints, own or inherited. sorted: true is as on main.
  • JSX: type, key, props, children and $$typeof are own data properties or they are not there, so an inherited one or a getter does not count. An accessor among the props prints [Getter]. <x {...{ children }} a="1" b="2" /> prints a="1" b="2", it printed a="1"b="2". A long run of holes in children is one line.
  • A boxed primitive, a RegExp and a native MessageEvent or ErrorEvent print their internal state, whatever toString, source, data or message a subclass or an own property puts in front. An Event that only has the type "message" or "error" prints as the object it is; it printed as MessageEvent { data: undefined }.
  • Function.prototype prints [Function]. It printed [Circular].
  • console.log(new String("a"), 1) prints [String: "a"] 1, as it already did for the last argument.
  • new Number(-0) prints [Number: -0].
  • A value that [inspect.custom] or toJSON returns and that holds the object it was called on says [Circular] there, as in Node. It nested until the depth limit.
  • The count in Map(2) is what it holds, whatever an own size says, and for a subclass whose size is not a number, which is not converted to one. A Map or Set without an iterator, such as one whose prototype was removed, lists what it holds; it printed Map {}. A subclass whose iterator yields more than its size ends with ... more items. A WeakMap subclass with a size prints WeakMap {}, it threw.
  • A Proxy in an error's property dump prints like its target does there (no inspect.custom, a Buffer as text).
  • Indentation stops growing at 32 levels, as it already did in snapshots.

console.table:

  • An array is walked by its own properties, like Object.keys in Node: a hole is not a row, and a named property is one. A replaced iterator on an array is not run.
  • Any other iterable gets 1000 rows, then ... more rows. A Map or Set subclass gets as many as its size getter says, so that getter runs, and what it throws propagates.
  • An error thrown while a cell prints propagates.

Errors:

  • An error that reaches itself renders once, with [Circular] under the key that closes the cycle.
  • An own cause that was assigned is queued like one from the constructor. It was printed in place and queued, which doubled the renders at every level.
  • An AggregateError reached as a cause prints itself, then its cause chain, then its members. The members were dropped.
  • The members are the elements the errors array holds: a hole prints nothing (it printed undefined) and a replaced iterator does not run. Another iterable gets 100 steps, then ... more errors.
  • Where the native stack ends a print for a sink that does not throw, the cut says [Object ...].

Hooks that still run

Same as on main, in console and in diffs. A throw from one still replaces the matcher's message.

  • an accessor on an array or arguments index,
  • toJSON of a Date, URLSearchParams, FormData or Headers, and [inspect.custom], which are asked for,
  • Symbol.iterator, next and size of a Map or Set subclass, or of one with an own Symbol.iterator,
  • message, stack, cause and errors getters of an Error in the error printer, which swallows what they throw,
  • the traps of a Proxy in a prototype chain, and getPrototypeOf of a Proxy,
  • what JSON.stringify runs for the values that go to it (a generator, %j), with no budget.

Decisions worth a second look

  1. Repeats are counted, not the whole output. util.inspect caps the whole output at 2^27, and #37311 caps a matcher message at 1 MiB. Both also cut a large value that repeats nothing. The blow-up in #37310 is shared references, which the budget fixes.
  2. A side of a diff can get more than 1 MiB. When one side shares an object and the other has copies of it, only the first would be abbreviated and every line of it would differ: 30 references to an 85 KB object against 30 copies is a 10-line diff on main, and was 34,063 lines. A side that is the only one abbreviated is printed again with the length of the other side for a budget, when that is more than the 1 MiB it had. Next to something small it is printed once.
  3. Caps on values the application controls: 1000 table rows and 100 errors for an iterable that is not an array, a typed array, a Map or a Set. They come from #42264.
  4. Snapshots error in the three cases above, and on a value too deep for the stack.
  5. Map and Set iterators are read from the collection, so a replaced next does not run and printing one does not use it up.
  6. The indentation cap changes console text for values nested more than 32 levels, console.group levels included.
  7. JSX ignores the depth option, as on main, so console.log of one nested deeper than the stack throws a RangeError. It crashed.

Cost

Release builds of the merge base and of this branch, linux x64. User-mode instructions and cycles for the whole process (perf stat), best of 3. The machine was shared and loaded, so wall time was not usable. "A/A" is a second copy of the base binary against the first.

instructions, mainthis PRA/AcyclesA/A
Bun.inspect, tree of 335,923 objects, depth Infinity5,944 M5,353 M-9.9%+0.2%-9.6%-4.6%
Bun.inspect, Map of 200,000 entries1,859 M1,621 M-12.8%+0.2%-24.6%-1.4%
Bun.inspect, Set of 200,000 strings1,059 M1,096 M+3.5%-0.2%+13.7%+6.4%
Bun.inspect, small object, 200,000 calls11,361 M11,058 M-2.7%+0.0%+1.9%+1.7%
Bun.inspect, a number, 600,000 calls2,324 M2,377 M+2.3%-0.1%+1.9%-2.7%
Bun.inspect, array of 100 strings, 30,000 calls8,086 M8,268 M+2.3%-0.0%-6.1%+9.0%
Bun.inspect, array of 100 numbers, 100,000 calls34,514 M34,430 M-0.2%+0.0%-6.9%-4.8%
console.log("hello world", i), 300,000 calls2,207 M2,264 M+2.6%-0.0%-1.2%+0.9%
Bun.inspect, Error with a cause, 5,000 calls1,656 M1,655 M-0.0%-0.0%-1.4%-1.1%
Bun.inspect, JSX tree of 19,531 elements535 M535 M-0.2%+1.3%+17.7%-3.4%
Bun.inspect, object with 200,000 object values3,856 M3,756 M-2.6%-0.0%+13.5%+2.7%
Bun.inspect, object with 800,000 object values15,418 M15,004 M-2.7%+0.0%+16.8%+2.2%
Bun.inspect.table, 1,000,000 numbers7,704 M7,930 M+2.9%+0.0%+5.1%-1.6%
Bun.inspect.table, 100,000 rows of { id, name }1,709 M1,743 M+2.0%+0.7%+2.1%+1.5%
Bun.inspect.table, 1,000 numbers, 100 calls726 M748 M+3.0%+0.0%+7.9%+11.0%
bun:test, five diff and message workloads17,159 M13,953 M-18.7%+0.1%
  • Instructions are steady (A/A within 1.3%). Cycles are not (A/A up to 11%), so only the large differences in that column mean anything.

  • A value that holds nothing (a number, a string, console.log("hello world", i)) costs 2% to 3.5% more instructions.

  • Past about 200,000 containers in one print, fewer instructions take 13% to 17% more cycles: the visited set holds every container printed instead of the current path, and no longer fits in cache. Storing each value's index on a path stack, so that leaving a value does not touch the set again, did not change that (+16.8% against +19.8% at 800,000), so it is not in here.

  • The JSX tree takes 18% more cycles. JSX had no cycle check, and now inserts into the visited set.

  • The visited set grows with the number of containers printed instead of the nesting depth. Peak RSS: 224 MB to 256 MB for the tree of 335,923 objects, 341 MB to 361 MB for 800,000 object values.

  • A cause chain prints 1,406 levels before the stack check stops it (main: 1,450).

  • inspect-error-leak.test.js, release: +4 MB on main, +5 MB here, limit 10 MB.

  • The binary is 28,672 bytes smaller.

  • test/js/bun/util/inspect.test.js: 11.3 s and 25.6 CPU-seconds on a debug build (main: 5.5 s and 6.4, with 57 fewer tests), 2.6 s on release (main: 0.1 s). The matrix is most of the difference, and no test in it takes 5 s on a debug build.

Verification

  • For each PR below I applied its test/ hunks alone and ran them against this branch. That found about ten gaps, all fixed here. The tests are included unless another test covers the same thing; where an expectation changed, the reason is in a comment next to it.
  • 112 tests in the touched files fail on main and pass here (release builds of both). error snapshots in snapshot.test.ts fails on both when colors are off.
  • Main against this branch, byte for byte: 9,480,348 matcher messages (82 matchers, release builds; 47,869 differ), 91,063 console value and sink pairs with a log of the hooks that ran (release; 6,548 differ), 18,920 error shape and entry point pairs (debug; 2,258 differ). The differences were sorted into the categories listed above and none was left over, apart from output that also differs between two runs of one binary. The 108 call sites were paired with what they replaced: none crossed between quoted and unquoted strings or lost a field.
  • The touched test files run clean on a debug build with ASAN under BUN_JSC_validateExceptionChecks=1.
  • Leave, the guard that undoes enter, holds raw pointers. A model of it passes Miri with Tree Borrows. The same model with the pointers taken from a &mut parameter, as they first were, does not.

Not measured: the stack-sensitive tests on a release build with ASAN, which only CI has.

Closes

GitHub closes the issues on merge. It links the pull requests but does not close them.

Issues:

Fixes #37310
Fixes #34178

#34178 has no repro. Its stack was symbolicated in the thread to the bun:test formatter under a failing toEqual, expanding shared references without bound, which is what the budget stops.

Pull requests whose own tests pass here unmodified:

Fixes #30373
Fixes #34179
Fixes #34884
Fixes #36404
Fixes #37270
Fixes #37402
Fixes #38586
Fixes #39045
Fixes #39054
Fixes #41119
Fixes #43963
Fixes #44174

Pull requests whose tests pass with an expectation changed, because the value now prints where it printed nothing, or because a hook no longer runs:

Fixes #29709
Fixes #36921
Fixes #42247
Fixes #42264

Pull requests whose code is gone, or whose fix is already on main:

Fixes #37331
Fixes #37334
Fixes #40534
Fixes #40919
Fixes #44139

The issue it fixes is fixed here another way (see decision 1):

Fixes #37311

Not closed

  • #35816, #38934, #38957, #40319: done for console and diffs. A snapshot reads and prints as on main, which is now one switch to remove.
  • #40077: the first of its four bugs.
  • #10886: the message is bounded, but the issue asks for a DOM node to print as markup.
  • #38910 (get_length for every caller; the formatter no longer depends on it), #39637, #38171.