console: only a primitive-string first argument is a format string
RO
20d ago+294+294+012345678901234567890123456789-103-103-012345678901234567890123456789
Fixes #4826
Problem
console.log("route", new URL(req.url).pathname, req.params)throwsTypeError: No default valuefor a request to/users/%s. A%specifier in a later string argument consumes the arguments after it.console.error("request failed:", "/wiki/%d0%a0", err)printsrequest failed: /wiki/NaN0%a0and drops the Error.- Cause:
format2(src/jsc/ConsoleObject.rs:1430) tagged each string argument with arguments after itStringPossiblyFormatted.
Fix
format2selects the format string once: only a primitive-string first argument. The specifier pass gets its arguments as a parameter. The tag andFormatter.remaining_valuesare removed.- Two wrappers put a prefix first and depended on the bug.
$debugnow joins its prefix to the format string. bun-lambda'slog()usesutil.format(from #35441). - Verified:
test/js/web/console/console-log.test.tsandtest/integration/bun-lambda/bun-lambda.test.ts(new tests fail on main). Alsotest/js/bun/console/,inspect.test.js,expect.test.js. - Self-reviewed: 13 concerns raised, 11 addressed. Open: the landing order with #44268. Not done: an optional
util.formatdifferential test.
Background
- The WHATWG console standard and node read specifiers from a string
args[0]only.util.format,node:consoleand worker consoles in bun already do. format2is the native printer's entry for a console call. Its specifier pass replaces%s,%dand the others with the next arguments.- Differential fuzzing against node found this, with no user report. #33445 tried a position check in the loop, which keeps the tag and the queue. The stale-PR action closed it without human review.
Downsides
- Code that depends on the bug prints differently, for example
console.log(prefix, "%d items", n). - bun-lambda log lines print strings without quotes. A CloudWatch filter on the quoted text stops matching.
console.log(1, 2, 3)runs 3 more instructions of 2,451 informat2.console.log("x:", 1, 2)runs 189 fewer of 2,224.
Notes
Output against node v26.3.0
| call | node | main | this PR |
|---|---|---|---|
console.log("a", "100%foo", 42) | a 100%foo 42 | a 10042oo | a 100%foo 42 |
console.log("l", "%d %s", 1, "t") | l %d %s 1 t | l 1 t | l %d %s 1 t |
console.log("x", "%%", 1) | x %% 1 | x % 1 | x %% 1 |
console.log("x", "%c", "color:red", "y") | x %c color:red y | x y | x %c color:red y |
console.log("%s %s", "a", "b", "%s", "c") | a b %s c | a b c | a b %s c |
console.log("", "%d", 5) | %d 5 | 5 | %d 5 |
console.log(1, "%d", 2) | 1 %d 2 | 1 2 | 1 %d 2 |
console.log(/%d/, 1) | /%d/ 1 | /1/ | /%d/ 1 |
console.log(new String("t"), 1) | [String: 't'] 1 | t 1 | [String: "t"] 1 |
console.log("x", "%s", Symbol("q"), 1) | x %s Symbol(q) 1 | throws TypeError | x %s Symbol(q) 1 |
console.log("GET", "/wiki/%d0%a0", 12n, "ms") | GET /wiki/%d0%a0 12n ms | throws TypeError | GET /wiki/%d0%a0 12n ms |
console.log("%d/%s", 7, "k") | 7/k | 7/k | 7/k |
console.log("%s %s", "a") | a %s | a %s | a %s |
- A
node:httplistener that runsconsole.log(req.method, req.url, 5n, "ns")exits with an uncaughtTypeError: Conversion from 'BigInt' to 'number' is not allowed.onGET /%d. With this PR it printsGET /%d 5n nsand answers 200, as node does. console.log("p", "%d", obj)no longer callsobj[Symbol.toPrimitive].- Related to #17663: the one-argument form was fixed there. The
new String("t")row above is the form with more arguments.
Who reaches this path
- Each
console.log,info,debug,error,warn,trace,assert,group,groupCollapsedanddirxmlcall with two or more arguments on the main thread. Bun.WebView({ console: globalThis.console }), which sends the page's console calls to the same code.- Not
node:worker_threadsworkers. Their console isnew Console(...), which already has the first-argument rule. On main, one script printsa 10042ooon the main thread anda 100%foo 42in a worker.
Output changes that contain no specifier
- A
Stringobject,Stringsubclass or RegExp before the last argument prints as a value, for example[String: "b"]. It already did in last position. - A later string adds its character count to the line width, not its UTF-8 byte count.
console.log("a", "é".repeat(40), [1, 2, 3, 4, 5, 6])keeps the array on one line, as node does.
The two wrappers
$debug(debug builds only) calledconsole.warn(prefix, ...args). With the old wrapper and the newformat2, the line is[net] connect: attempting to connect to %s:%d (addressType: %d) 127.0.0.1 41987 4. With the new wrapper it is[net] connect: attempting to connect to 127.0.0.1:41987 (addressType: 4), the same as main. WithBUN_DEBUG_JS=1, 0 of 62 lines of a net connect and 0 of 60 lines of a stream pipe differ from main.- bun-lambda's
log()calledlogger(level, ...inspectedArguments). On main a handler'sconsole.log("hi %s, you are %d", "bob", 42)printsINFO RequestId: req-log "hi "bob", you are 42". With only theformat2change it printsINFO RequestId: req-log "hi %s, you are %d" "bob" 42. With thelog()change from #35441 it printsINFO RequestId: req-log hi bob, you are 42. #35441 also changesformatError(). That part is not included.
Measurements (release builds of 7583003d8, which was main at the time, and of this change on it. src/jsc/ConsoleObject.rs is the same on today's main.)
- instructions inside one
format2call (gdbstepitally on the 30th of 40 calls, NO_COLOR=1):'hello'644 -> 642,{hello:'object'}5,199 -> 5,196,('x:', 1, 2)2,224 -> 2,035,(1, 2, 3)2,451 -> 2,454,('%d/%s', 7, 'k')1,413 -> 1,226 - the same with FORCE_COLOR=1: 658 -> 656, 5,422 -> 5,419, 2,230 -> 2,044, 2,459 -> 2,465, 1,428 -> 1,240
- allocator entries inside one
format2call: 0 / 3 / 0 / 0 / 0 -> 0 / 3 / 0 / 0 / 0 (same tally) - syscalls inside one
format2call: 1 -> 1 on all five shapes console.log('a', S, 1), S = 1 KiB: 12,354 -> 1,885 instructions insideformat2. 16-byte S: 2,183 -> 1,792- size of
Formatter: 144 -> 128 bytes (gdbsizeof, debug build) - release
.text: 79,755,685 -> 79,748,773 bytes (-6,912 B,size).format22,242 -> 2,376,print_as::<C>1,204 -> 979, the pass with its entry 3,605 -> 3,456 per colour mode - mordant
generic_body_not_generic,src/jsc/ConsoleObject.rs: 6 -> 6 (job exit 0) StringPossiblyFormattedundersrc/jsc: 9 -> 0 lines.remaining_valuesundersrc/jsc: 16 -> 0 lines.pretty_format.rskeeps 7 of 8 (git grep)- console fixtures, 4 files x 2 colour modes x 2 streams: 0 of 16 differ from main
Tests
console reads format specifiers from its first argument only: the table, with colours off and on.console.error wraps a multi-argument line in red once: the exact bytes of the red wrapper.console.assert reads format specifiers from its first message argument only: runs on release builds. On debug and ASAN builds the test runner setsBUN_JSC_validateExceptionChecks=1, andconsole.assert(false)aborts there on main too (an unchecked throw scope inconsoleProtoFuncAssert). #44950 fixes that and can remove the gate.$debug passes the caller's format string to console as its first argument: evaluates the source thatcreateLogClientJSreturns, because no CI build compiles the wrapper.console.log in a handler formats its arguments like util.format: the bun-lambda test from #35441, with one later-%row added.- With
BUN_JSC_validateExceptionChecks=1,test/js/web/console/passes. Other suites on the debug build:test/js/bun/console/,test/js/bun/util/inspect.test.js,test/js/bun/test/expect.test.js, and the nodetest-console-*.jsfiles (16 of 16).
Not changed here
- Conversions in
args[0]still throw where node prints, for exampleconsole.log("%d", 12n). So a format string that a client controls can still throw when it is the first argument. - #31777:
console.log("%i", [1, 2, 3])printsNaN. - #20061: the dev-server echo of browser logs substitutes no specifier at all. It does not use this code.
src/runtime/test_runner/pretty_format.rshas a copy of the old loop and its own specifier pass. Its three callers pass one value, so the loop cannot run. This PR removes only the oneFrom<FormatTag>arm that the deleted variant forces.console.tablewith a first argument that is not an object sends all its arguments toformat2. Node prints only the first.console.log("%s %s %%", "a")printsa %s %%. Node printsa %s %.%cis consumed and dropped.%oprints a string without quotes.
Overlap with open PRs
- #44268 rewrites the same loop. It keeps the tag and the queue that this PR removes, so the two need a landing order. The new tests fail on main and protect the rule in that rebase.
- #39592 sends worker consoles through the native console again. Workers keep the first-argument rule only if this lands first.
- #35441: its
log()change and test are here. ItsformatError()change is not. - #34239, #45337 and #45325 edit the specifier pass. Their reads of the queue become reads of the
argsparameter. - #36404 changes the predicate that this PR removes. #40534 touches the
From<FormatTag>impl. #31716 puts a marker before theconsole.assertmessage.