console: collapse `%%` after the last format argument, print `undefined` for `%j` of undefined

RO
18d ago
+188-0

Problem

  • The native console stops the format pass when the arguments run out. console.log("%d%%", 50) prints 50%%. Node.js prints 50%.
  • console.log("[%j]", undefined) prints []. Node.js prints [undefined].
  • Cause: in Formatter::write_with_formatting (src/jsc/ConsoleObject.rs), two remaining_values.is_empty() breaks leave the loop and write the rest unchanged. The %j arm prints an empty json_stringify_fast result.

Fix

  • The two breaks set a flag. After the loop, a search collapses each %% in the rest. %j prints undefined for an empty result.
  • Correct because after the last value only %% still changes the text.
  • Verified: test/js/web/console/console-log.test.ts (5 new tests fail on main), test/regression/issue/24234.test.ts.
  • Self-reviewed: 24 concerns raised, 22 addressed. Not done: a class tracking issue and a real-world count, both unverified.

Background

  • A format string is a string first argument followed by other arguments. %s takes one value. %% takes none and prints %.
  • Node.js tests the argument count only around specifiers that take a value (formatWithOptionsInternal).
  • Considered: the byte loop for the rest (10 instructions per byte). #45626's i = 0 after %% (six printing calls then throw).

Downsides

  • Instructions per call (about 2,000): the search of the rest after the last value costs +18 to +88 for 1 to 15 bytes, then +39 to +63 (AVX-512) or up to +338 (AVX2). A lone % in the rest: +120 to +430. Each %j: +17.
  • Output changes: 50%% becomes 50% and [] becomes [undefined], also in the later arguments that Bun scans (#45571).
  • Still wrong: %% directly before a specifier or another %% with a value left (#45626), test.each titles (#44833).
Notes

Origin. No issue reports either case. Both came from a comparison of the native console with Node.js v26.3.0. In Bun, the %% arm and the first break came in together in #10910, and %j in #25195. util.format and new console.Console(stream) in the same process already print Node's text, so globalThis.console = new console.Console(process.stdout, process.stderr) or util.format at the call site is a workaround on a build without this change.

The rule in Node.js v26.3.0 (lib/internal/util/inspect.js): the argument test wraps only the specifier switch, %% with a value left, %% after the last value, %j and tryStringify.

How the search works. When a break stops the loop, slice is the text after the last value. strings::index_of_char_pos finds the next %. If the next byte is also %, the text up to the first % is written and the second is dropped. If the % is alone, one strings::index_of(.., b"%%") pass finds the next pair, so a rest with many % that are alone costs two searches and not one for each. The existing write of slice prints what is left. The first break is reached only after a %d or %i that prints NaN, or a %f of an int32. These two arms leave with continue 'outer and skip the second break. #45935 removes both exits. An empty json_stringify_fast result can only mean that JSON.stringify returned undefined, because a defined result has at least one character.

Forms of this change that did not hold. Each number is from my own run.

  1. July: the %% test above the first break, the second break deleted. Every byte after the last value goes through the byte loop. On main that loop costs 10.4 to 11.4 instructions per byte ("%s" + 0 / 64 / 256 bytes with a value left: 2,537 / 3,264 / 5,206).
  2. Argument test at the line that takes a value, one search after the last value, then back into the byte loop, with i = 0 after %% as in #45626. A % in the rest sent every byte after it through the loop: "%s%s" + 64 / 256 bytes with one value cost +702 / +2,622 instructions for the same output. With i = 0, six calls that print on main throw (table below).
  3. The search inside the hit_percent block at the top of the loop. The loop got one instruction per byte slower for every format string: +63 / +255 for a first argument of 64 / 256 bytes.
  4. One index_of_char_pos search for each % after the loop. A rest with many % that are alone paid one kernel call for each: +724 for a request line with 13 percent-escapes and +3,886 for 255 bytes of %2F, for the same output.
  5. A % test and then only the pair search. The plain console.log("%d%%", 50) cost +119 where this form costs +32.

Not built: one search-driven loop for the whole format string, with no byte loop. It would also make a long first argument without % cheaper. It changes the loop that every multi-argument call runs, so it is a separate change.

Instructions per call. Release builds of main 02f36b477e and of this PR on one machine (AMD EPYC, AVX-512). A perf_event_open counter of user-space instructions around the process, because valgrind and perf are not installed here. 1,000,000 calls to /dev/null minus a run with 0 calls, BUN_JSC_useConcurrentJIT=0 BUN_JSC_useConcurrentGC=0, minimum of 3 runs. The spread between runs is at most 0.15, and 0.35 in the last row (100,000 calls).

callmainPRdelta
console.log("hello")1,428.81,428.80
console.log("label:", 1)2,460.22,461.2+1
first argument of 8 / 64 / 256 bytes without %, then 12,488.3 / 3,045.3 / 4,987.32,489.3 / 3,046.3 / 4,988.3+1 / +1 / +1
"%s and more text here", "x", "y"2,893.82,894.8+1
"%s" + 64 bytes, "x", "y" (a value is left)3,283.83,284.8+1
"%f" + 64 bytes, 22,622.12,626.1+4
"%d" + 64 bytes, "x"2,606.12,611.1+5
"%j", 5 / "%j", { a: 1, b: "two" }2,363.4 / 2,922.12,380.5 / 2,939.1+17 / +17
"%s" + N bytes without %, "x": N = 01,952.21,953.2+1
N = 1 / 2 / 8 / 152,014.3 / 2,021.3 / 2,046.3 / 2,081.32,032.3 / 2,044.3 / 2,099.3 / 2,169.2+18 / +23 / +53 / +88
N = 16, 24, 31, 32, 40, 632,084.3 / 2,124.2 / 2,022.2 / 2,020.3 / 2,020.3 / 2,039.32,126.3 / 2,166.3 / 2,064.3 / 2,062.3 / 2,062.3 / 2,081.3+42 each
N = 64 / 127 / 1282,039.3 / 2,043.3 / 2,043.22,078.3 / 2,094.3 / 2,088.3+39 / +51 / +45
N = 255 / 2562,061.2 / 2,061.32,124.3 / 2,118.3+63 / +57
output changes: "%d%%", 50 / "%s %%", "x"1,984.2 / 2,026.22,016.2 / 2,064.3+32 / +38
output changes: "%s" + N bytes + "%%", N = 0 / 64 / 2562,021.3 / 2,039.3 / 2,069.32,052.3 / 2,115.3 / 2,163.3+31 / +76 / +94
output changes: "%s%%" + 64 / 256 bytes2,039.3 / 2,069.32,186.3 / 2,226.3+147 / +157
same output: "%s: 50% done", "x"2,056.32,187.3+131
same output: "%d% of statements covered", 872,082.22,220.3+138
same output: "%s%s" + 64 / 256 bytes, "x"2,039.3 / 2,069.32,161.3 / 2,224.3+122 / +155
same output: "[%s] GET /search?q=hello%20world&page=2&sort=desc&filter=active HTTP/1.1 200 12ms", "ts"2,059.22,207.2+148
same output: a banner with three %202,039.22,201.2+162
same output: a request line with 13 percent-escapes2,059.32,210.2+151
same output: "%s" + 85 times %2F (255 bytes)2,061.32,248.3+187
same output: "%s 50% " + 4 KiB / 64 KiB2,290.0 / 3,729.93,105.1 / 15,105.0+815 / +11,375

A format string with characters outside Latin-1 is converted to UTF-8 before the scan, so the search sees bytes in both cases: "%s" + 8 / 21 / 85 arrows (24 / 63 / 255 bytes) costs +42 / +42 / +63.

The search on other kernels. Below 16 bytes index_of_char is a scalar loop (SCALAR_CUTOFF in src/highway/lib.rs). From 16 bytes it is the Highway kernel IndexOfCharImpl, which scans the bytes after the last full vector one at a time on AVX2, SSE4 and NEON (hn::Find). That tail is most of the AVX2 and SSE4 columns. The kernel is not changed here. The AVX2 and SSE4 columns are copies of both binaries whose dispatch tables for IndexOfCharImpl and MemMemImpl point at that kernel, run on the same AVX-512 machine. NEON is not measured.

callAVX-512AVX2SSE4
"%s" + 1 / 15 bytes+18 / +88the samethe same
+ 16 bytes+42+164+40
+ 24 bytes+42+228+115
+ 31 bytes+42+284+178
+ 32 bytes+42+40+48
+ 40 bytes+42+112+123
+ 63 bytes+42+296+194
+ 64 bytes+39+47+64
+ 127 bytes+51+310+226
+ 128 bytes+45+61+96
+ 255 bytes+63+338+290
+ 256 bytes+57+89+160
"%s: 50% done"+131+131+126
"%d% of statements covered"+138+121+139
the request line with one %20+148+134+172
the banner with three %20+162+162+196
the request line with 13 percent-escapes+151+172+201
"%s" + 85 times %2F+187+257+427

Binary size. write_with_formatting::<false> and ::<true>: 3,156 B each on main, 3,695 B each on the PR (llvm-nm --print-size). Release text: +1,024 B (llvm-size).

Wall clock. Minimum and median of 31 rounds of 200,000 calls to /dev/null, interleaved, one pinned core, in ns per call.

callkernelmainPR
"%s" + 64 bytesAVX-512321.1 / 342.4324.2 / 340.1
"%s" + 31 bytesAVX-512326.8 / 363.4325.5 / 345.2
"%s: 50% done"AVX-512325.9 / 343.6327.5 / 337.1
the request line with 13 percent-escapesAVX-512331.6 / 349.6340.4 / 361.0
"%s" + 31 bytesAVX2321.9 / 355.7332.9 / 345.9
"%s" + 63 bytesAVX2321.9 / 396.3327.7 / 386.4
"%s" + 255 bytesAVX2318.9 / 339.7328.1 / 348.6
"%s" + 64 bytesAVX2327.3 / 336.8329.2 / 342.2

On the AVX2 kernel the minimum is 6 to 11 ns higher (2% to 3%) where the one-byte tail of the kernel runs. For "%s" + 64 bytes, Node.js v26.3.0 takes 1,960 ns per call and bun 1.4.3-canary.1 takes 331 ns (minimum of 5 rounds).

Differential test against Node.js v26.3.0. Generated format strings as the first argument, one console.log per case, lines compared one by one. The arguments are short strings, small integers, undefined and null.

corpuscasesmain differsPR differsfixedequal on main, not on the PR
every string of length 1 to 6 over % s d f c x, 5 argument lists279,9304,1912,6231,5680
every string of length 1 to 7 over % s f c x, 1 to 3 integers292,9659,0085,7203,2880
every string of length 1 to 5 over % j o O i x, 5 argument lists46,6502,8531,0911,7620
  • The lines that still differ are %% directly before a specifier or another %% while a value is left (#45626) and %i of null (#45935).
  • In a tree with this PR, #45626, #45935 and #45951 merged, 0 of these 619,545 lines differ. These corpora do not cover every defect of the scanner, for example %s of a Symbol (#45337).
  • 60,000 random rests of up to 200 bytes after %s, after a %i that prints NaN and after a %f of an int32: 0 lines differ from Node.js on the AVX-512, AVX2 and SSE4 kernels. main differs on 40,719.

Arguments that Bun scans and Node.js does not. Bun also scans a later string argument, a String object and a RegExp (the subject of #45571). These texts change and stay different from Node.js:

callNode.jsmainPR
console.log("done:", "%d%%", 50)done: %d%% 50done: 50%%done: 50%
console.log(5, "%s %%", "x")5 %s %% x5 x %%5 x %
console.log(new String("S %d%%"), 50)[String: 'S %d%%'] 50S 50%%S 50%
console.log(/a%d%%b/, 50)/a%d%%b/ 50/a50%%b//a50%b/

console.table with a first argument that is not an object prints every argument through the same path, where Node.js logs only the first. console.table("%d%%", [50]) prints %d%% on Node.js, 50%% on main and 50% on the PR. No open PR changes that.

With i = 0 after %% in this PR (not done). A specifier directly after %% then takes its value, and these calls throw because the specifier arms throw for these values on main:

callNode.jsmain and this PRwith i = 0
console.log("%%%d", 12n)%12n%%d 12nTypeError
console.log("%%%i", 5n)%5n%%i 5nTypeError
console.log("%%%f", 5n)%5%%f 5nTypeError
console.log("%%%s", Symbol("x"))%Symbol(x)%%s Symbol(x)TypeError
console.log("%%%s", Object.create(null))%[Object: null prototype] {}%%s [Object: null prototype] {}TypeError
console.log("%%%j", cyclic)%[Circular]%%j and the inspected objectTypeError

#45935, #45337 and #45325 are the open PRs for these three arms. The search after the loop does not use the %% arm, so this PR does not need i = 0: console.log("%s %%%%", "a") prints a %%.

Entry points. The scanner has one caller. log, info, debug, error, warn, trace, group, groupCollapsed, dirxml, assert, the node:console default export, and console.table with a first argument that is not an object all go through it. The tests cover all of them but assert and table. A failing console.assert aborts under the exception validator that the ASAN lanes set (#44950).

Other open PRs on this function or its tests. Conflict regions of this diff against each branch (git merge-file, three-way with the merge base):

PRConsoleObject.rsconsole-log.test.ts
#45626 (i = 0 after %%)00
#45571 (only the first argument is a format string)20
#45325 (%j of a cyclic value)00
#45337 (%s of a Symbol)00
#45935 (%i and %f, BigInt)00
#45951 (%d)00
#44268 (one value formatter)00
#44833 (Vitest compatibility, draft)00
#32638 (console.trace on stderr with a prefix)00
#37128 (console output order)00
#41565 (test.each titles)00
  • #45571 changes the condition of the two breaks to args.is_empty(). This diff adds a line to each. Keep both.
  • #45626 changes only the %% arm, which this diff does not touch. The two PRs merge in either order.
  • #45935 and #45951 delete the 'outer label. This diff does not use it.
  • A tree with this PR, #45626, #45935 and #45951 merged compiles and passes the merged console-log.test.ts with BUN_JSC_validateExceptionChecks=1 (16 pass, 1 todo).

Not changed here.

  • %% directly before a specifier or another %% while a value is left: console.log("%%%s", "x") prints %%s x, and console.log("%%%% %c", "") prints %%% . That is #45626.
  • format_label in src/runtime/test_runner/jest.rs formats test.each titles. It has the same two defects. Draft #44833 and #41565 rewrite it.
  • src/runtime/test_runner/pretty_format.rs has a copy of the scanner. It is only called with one value, so it never sees a format string. #44268 deletes it.
  • %j of a cyclic value throws a TypeError where Node.js prints [Circular]. That is #45325. It changes the json_stringify_fast call line of the same arm, which this diff does not touch.
  • The other callers of json_stringify_fast keep their own reaction to an empty result. Response.json({ toJSON() {} }) answers 200 with an empty body where Node.js throws.

Suites run with the debug build and BUN_JSC_validateExceptionChecks=1. test/js/web/console/console-log.test.ts: 11 pass. test/js/web/console/, test/js/bun/console/, test/js/node/console/, test/regression/issue/24234.test.ts, test/js/bun/util/inspect.test.js and inspect-error.test.js: 267 pass, 2 fail. The 2 are timeouts in this container that do not reach the scanner: console.table reads each cell once > cell values survive a full GC takes 3.2 to 7.8 s against the 5 s limit, and deep AggregateError with depth: Infinity takes 1.8 to 5.0 s. All 16 test-console-*.js files of test/js/node/test/parallel/ exit 0. test/js/web/console/console-log.expected.txt is unchanged.


[review] gate passed · iteration 1 · 2 files touched

fails on main (without fix)
ASAN without fix: 1 FAILED
$ BUN_DEBUG_QUIET_LOGS=1 bun scripts/build.ts --profile=debug --quiet test "--reporter=junit" "--reporter-outfile=/tmp/mechgate.xml" test/js/web/console/console-log.test.ts
info: syncing channel updates for nightly-2026-05-06-x86_64-unknown-linux-gnu
info: latest update on 2026-05-06 for version 1.97.0-nightly (e95e73209 2026-05-05)
info: component rust-src is up to date
info: checking for self-update (current version: 1.29.0)
bun test v1.4.0 (3f9d96a27)

test/js/web/console/console-log.test.ts:
(pass) should log to console correctly [932.69ms]
(pass) long arrays get cutoff [3.13ms]
(pass) console.group [455.33ms]
161 |     env: bunEnv,
162 |     stdout: "pipe",
163 |     stderr: "pipe",
164 |   });
165 |   const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]);
166 |   expect({ stdout: stdout.replaceAll("\r\n", "\n"), stderr, exitCode }).toEqual({
                                                                              ^
error: expect(received).toEqual(expected)

  {
    "exitCode": 0,
    "stderr": "",
    "stdout": 
- "x %
- 1 2 3 %
- x % % %
- a %s % end
+ "x %%
+ 1 2 3 %%
+ x %% %% %%
+ a %s %% end
  100
... (truncated)

release without fix: all passed
bun test v1.4.0-canary.1 (a21606870)

test/js/web/console/console-log.test.ts:
(pass) should log to console correctly [33.67ms]
(pass) long arrays get cutoff [0.10ms]
(pass) console.group [15.84ms]
(pass) console.log: %% collapses after format args are exhausted, %j of undefined prints 'undefined' [11.82ms]
(pass) console.log with SharedArrayBuffer [0.09ms]

 5 pass
 0 fail
 2 snapshots, 10 expect() calls
Ran 5 tests across 1 file. [212.00ms]
__F:0:S:0
passes on PR (with fix)
ASAN with fix: all passed
$ BUN_DEBUG_QUIET_LOGS=1 bun scripts/build.ts --profile=debug --quiet test "--reporter=junit" "--reporter-outfile=/tmp/mechgate.xml" test/js/web/console/console-log.test.ts
info: syncing channel updates for nightly-2026-05-06-x86_64-unknown-linux-gnu
info: latest update on 2026-05-06 for version 1.97.0-nightly (e95e73209 2026-05-05)
info: component rust-src is up to date
info: checking for self-update (current version: 1.29.0)
bun test v1.4.0 (3f9d96a27)

test/js/web/console/console-log.test.ts:
(pass) should log to console correctly [940.41ms]
(pass) long arrays get cutoff [3.36ms]
(pass) console.group [465.37ms]
(pass) console.log: %% collapses after format args are exhausted, %j of undefined prints 'undefined' [433.25ms]
(pass) console.log with SharedArrayBuffer [4.51ms]

 5 pass
 0 fail
 2 snapshots, 10 expect() calls
Ran 5 tests across 1 file. [3.83s]
__F:0:S:0

release with fix: all passed
$ bun scripts/build.ts --profile=release
info: syncing channel updates for nightly-2026-05-06-x86_64-unknown-linux-gnu
info: latest update on 2026-05-06 for version 1.97.0-nightly (e95e73209 2026-05-05)
info: component rust-src is up to date
info: checking for self-update (current version: 1.29.0)
[configured] bun-profile → bun (stripped) in 723ms (unchanged)
ninja: Entering directory `/workspace/bun/build/release'
[1/6] gen generated_host_exports.rs
generated_host_exports.rs: 91 exports (host=3, lazy=10, generic=78, rust=0); 243 extern-C blocks audited
[1/6] cargo bun_bin → libbun_rust.a (--target x86_64-unknown-linux-gnu)
info: syncing channel updates for nightly-2026-05-06-x86_64-unknown-linux-gnu
info: latest update on 2026-05-06 for version 1.97.0-nightly (e95e73209 2026-05-05)
info: component rust-src is up to date
info: component rust-std is up to date

  nightly-2026-05-06-x86_64-unknown-linux-gnu unchanged - rustc 1.97.0-nightly (e95e73209 2026-05-05)

info: checking for self-update (current version: 1.29.0)
^[[1m^[[92m   Compiling^[[0m bun_core v0.0.0 (/workspace/bun/src/bun_core)
^[[1m^[[92m   Compiling^[[0m bun_errno v0.0.0 (/workspace/bun/src/errno)
^[[1m^[
... (truncated)
diff hotspot
src/jsc/ConsoleObject.rs                | 53 ++++++++++++++++++++-------------
 test/js/web/console/console-log.test.ts | 37 +++++++++++++++++++++++
 2 files changed, 70 insertions(+), 20 deletions(-)

gate history · 2 passed · 0 rejected · iteration 1

evidence per changed file
file                                     reads  edits  tests
src/jsc/ConsoleObject.rs                     4      3      0
test/js/web/console/console-log.test.ts      1      1      0