console: collapse `%%` after the last format argument, print `undefined` for `%j` of undefined
Problem
- The native console stops the format pass when the arguments run out.
console.log("%d%%", 50)prints50%%. Node.js prints50%. console.log("[%j]", undefined)prints[]. Node.js prints[undefined].- Cause: in
Formatter::write_with_formatting(src/jsc/ConsoleObject.rs), tworemaining_values.is_empty()breaks leave the loop and write the rest unchanged. The%jarm prints an emptyjson_stringify_fastresult.
Fix
- The two breaks set a flag. After the loop, a search collapses each
%%in the rest.%jprintsundefinedfor 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.
%stakes 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 = 0after%%(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%%becomes50%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.eachtitles (#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.
- 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). - Argument test at the line that takes a value, one search after the last value, then back into the byte loop, with
i = 0after%%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. Withi = 0, six calls that print on main throw (table below). - The search inside the
hit_percentblock 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. - One
index_of_char_possearch 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. - A
%test and then only the pair search. The plainconsole.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).
| call | main | PR | delta |
|---|---|---|---|
console.log("hello") | 1,428.8 | 1,428.8 | 0 |
console.log("label:", 1) | 2,460.2 | 2,461.2 | +1 |
first argument of 8 / 64 / 256 bytes without %, then 1 | 2,488.3 / 3,045.3 / 4,987.3 | 2,489.3 / 3,046.3 / 4,988.3 | +1 / +1 / +1 |
"%s and more text here", "x", "y" | 2,893.8 | 2,894.8 | +1 |
"%s" + 64 bytes, "x", "y" (a value is left) | 3,283.8 | 3,284.8 | +1 |
"%f" + 64 bytes, 2 | 2,622.1 | 2,626.1 | +4 |
"%d" + 64 bytes, "x" | 2,606.1 | 2,611.1 | +5 |
"%j", 5 / "%j", { a: 1, b: "two" } | 2,363.4 / 2,922.1 | 2,380.5 / 2,939.1 | +17 / +17 |
"%s" + N bytes without %, "x": N = 0 | 1,952.2 | 1,953.2 | +1 |
| N = 1 / 2 / 8 / 15 | 2,014.3 / 2,021.3 / 2,046.3 / 2,081.3 | 2,032.3 / 2,044.3 / 2,099.3 / 2,169.2 | +18 / +23 / +53 / +88 |
| N = 16, 24, 31, 32, 40, 63 | 2,084.3 / 2,124.2 / 2,022.2 / 2,020.3 / 2,020.3 / 2,039.3 | 2,126.3 / 2,166.3 / 2,064.3 / 2,062.3 / 2,062.3 / 2,081.3 | +42 each |
| N = 64 / 127 / 128 | 2,039.3 / 2,043.3 / 2,043.2 | 2,078.3 / 2,094.3 / 2,088.3 | +39 / +51 / +45 |
| N = 255 / 256 | 2,061.2 / 2,061.3 | 2,124.3 / 2,118.3 | +63 / +57 |
output changes: "%d%%", 50 / "%s %%", "x" | 1,984.2 / 2,026.2 | 2,016.2 / 2,064.3 | +32 / +38 |
output changes: "%s" + N bytes + "%%", N = 0 / 64 / 256 | 2,021.3 / 2,039.3 / 2,069.3 | 2,052.3 / 2,115.3 / 2,163.3 | +31 / +76 / +94 |
output changes: "%s%%" + 64 / 256 bytes | 2,039.3 / 2,069.3 | 2,186.3 / 2,226.3 | +147 / +157 |
same output: "%s: 50% done", "x" | 2,056.3 | 2,187.3 | +131 |
same output: "%d% of statements covered", 87 | 2,082.2 | 2,220.3 | +138 |
same output: "%s%s" + 64 / 256 bytes, "x" | 2,039.3 / 2,069.3 | 2,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.2 | 2,207.2 | +148 |
same output: a banner with three %20 | 2,039.2 | 2,201.2 | +162 |
| same output: a request line with 13 percent-escapes | 2,059.3 | 2,210.2 | +151 |
same output: "%s" + 85 times %2F (255 bytes) | 2,061.3 | 2,248.3 | +187 |
same output: "%s 50% " + 4 KiB / 64 KiB | 2,290.0 / 3,729.9 | 3,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.
| call | AVX-512 | AVX2 | SSE4 |
|---|---|---|---|
"%s" + 1 / 15 bytes | +18 / +88 | the same | the 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.
| call | kernel | main | PR |
|---|---|---|---|
"%s" + 64 bytes | AVX-512 | 321.1 / 342.4 | 324.2 / 340.1 |
"%s" + 31 bytes | AVX-512 | 326.8 / 363.4 | 325.5 / 345.2 |
"%s: 50% done" | AVX-512 | 325.9 / 343.6 | 327.5 / 337.1 |
| the request line with 13 percent-escapes | AVX-512 | 331.6 / 349.6 | 340.4 / 361.0 |
"%s" + 31 bytes | AVX2 | 321.9 / 355.7 | 332.9 / 345.9 |
"%s" + 63 bytes | AVX2 | 321.9 / 396.3 | 327.7 / 386.4 |
"%s" + 255 bytes | AVX2 | 318.9 / 339.7 | 328.1 / 348.6 |
"%s" + 64 bytes | AVX2 | 327.3 / 336.8 | 329.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.
| corpus | cases | main differs | PR differs | fixed | equal on main, not on the PR |
|---|---|---|---|---|---|
every string of length 1 to 6 over % s d f c x, 5 argument lists | 279,930 | 4,191 | 2,623 | 1,568 | 0 |
every string of length 1 to 7 over % s f c x, 1 to 3 integers | 292,965 | 9,008 | 5,720 | 3,288 | 0 |
every string of length 1 to 5 over % j o O i x, 5 argument lists | 46,650 | 2,853 | 1,091 | 1,762 | 0 |
- The lines that still differ are
%%directly before a specifier or another%%while a value is left (#45626) and%iofnull(#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
%sof a Symbol (#45337). - 60,000 random rests of up to 200 bytes after
%s, after a%ithat printsNaNand after a%fof 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:
| call | Node.js | main | PR |
|---|---|---|---|
console.log("done:", "%d%%", 50) | done: %d%% 50 | done: 50%% | done: 50% |
console.log(5, "%s %%", "x") | 5 %s %% x | 5 x %% | 5 x % |
console.log(new String("S %d%%"), 50) | [String: 'S %d%%'] 50 | S 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:
| call | Node.js | main and this PR | with i = 0 |
|---|---|---|---|
console.log("%%%d", 12n) | %12n | %%d 12n | TypeError |
console.log("%%%i", 5n) | %5n | %%i 5n | TypeError |
console.log("%%%f", 5n) | %5 | %%f 5n | TypeError |
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 object | TypeError |
#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):
| PR | ConsoleObject.rs | console-log.test.ts |
|---|---|---|
#45626 (i = 0 after %%) | 0 | 0 |
| #45571 (only the first argument is a format string) | 2 | 0 |
#45325 (%j of a cyclic value) | 0 | 0 |
#45337 (%s of a Symbol) | 0 | 0 |
#45935 (%i and %f, BigInt) | 0 | 0 |
#45951 (%d) | 0 | 0 |
| #44268 (one value formatter) | 0 | 0 |
| #44833 (Vitest compatibility, draft) | 0 | 0 |
#32638 (console.trace on stderr with a prefix) | 0 | 0 |
| #37128 (console output order) | 0 | 0 |
#41565 (test.each titles) | 0 | 0 |
- #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
'outerlabel. This diff does not use it. - A tree with this PR, #45626, #45935 and #45951 merged compiles and passes the merged
console-log.test.tswithBUN_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, andconsole.log("%%%% %c", "")prints%%%. That is #45626.format_labelinsrc/runtime/test_runner/jest.rsformatstest.eachtitles. It has the same two defects. Draft #44833 and #41565 rewrite it.src/runtime/test_runner/pretty_format.rshas a copy of the scanner. It is only called with one value, so it never sees a format string. #44268 deletes it.%jof a cyclic value throws a TypeError where Node.js prints[Circular]. That is #45325. It changes thejson_stringify_fastcall line of the same arm, which this diff does not touch.- The other callers of
json_stringify_fastkeep 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