console: only a primitive-string first argument is a format string

RO
20d ago
+294-103

Fixes #4826

Problem

  • console.log("route", new URL(req.url).pathname, req.params) throws TypeError: No default value for 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) prints request failed: /wiki/NaN0%a0 and drops the Error.
  • Cause: format2 (src/jsc/ConsoleObject.rs:1430) tagged each string argument with arguments after it StringPossiblyFormatted.

Fix

  • format2 selects the format string once: only a primitive-string first argument. The specifier pass gets its arguments as a parameter. The tag and Formatter.remaining_values are removed.
  • Two wrappers put a prefix first and depended on the bug. $debug now joins its prefix to the format string. bun-lambda's log() uses util.format (from #35441).
  • Verified: test/js/web/console/console-log.test.ts and test/integration/bun-lambda/bun-lambda.test.ts (new tests fail on main). Also test/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.format differential test.

Background

  • The WHATWG console standard and node read specifiers from a string args[0] only. util.format, node:console and worker consoles in bun already do.
  • format2 is the native printer's entry for a console call. Its specifier pass replaces %s, %d and 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 in format2. console.log("x:", 1, 2) runs 189 fewer of 2,224.
Notes

Output against node v26.3.0

callnodemainthis PR
console.log("a", "100%foo", 42)a 100%foo 42a 10042ooa 100%foo 42
console.log("l", "%d %s", 1, "t")l %d %s 1 tl 1 tl %d %s 1 t
console.log("x", "%%", 1)x %% 1x % 1x %% 1
console.log("x", "%c", "color:red", "y")x %c color:red yx yx %c color:red y
console.log("%s %s", "a", "b", "%s", "c")a b %s ca b ca b %s c
console.log("", "%d", 5) %d 5 5 %d 5
console.log(1, "%d", 2)1 %d 21 21 %d 2
console.log(/%d/, 1)/%d/ 1/1//%d/ 1
console.log(new String("t"), 1)[String: 't'] 1t 1[String: "t"] 1
console.log("x", "%s", Symbol("q"), 1)x %s Symbol(q) 1throws TypeErrorx %s Symbol(q) 1
console.log("GET", "/wiki/%d0%a0", 12n, "ms")GET /wiki/%d0%a0 12n msthrows TypeErrorGET /wiki/%d0%a0 12n ms
console.log("%d/%s", 7, "k")7/k7/k7/k
console.log("%s %s", "a")a %sa %sa %s
  • A node:http listener that runs console.log(req.method, req.url, 5n, "ns") exits with an uncaught TypeError: Conversion from 'BigInt' to 'number' is not allowed. on GET /%d. With this PR it prints GET /%d 5n ns and answers 200, as node does.
  • console.log("p", "%d", obj) no longer calls obj[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, groupCollapsed and dirxml call 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_threads workers. Their console is new Console(...), which already has the first-argument rule. On main, one script prints a 10042oo on the main thread and a 100%foo 42 in a worker.

Output changes that contain no specifier

  • A String object, String subclass 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) called console.warn(prefix, ...args). With the old wrapper and the new format2, 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. With BUN_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() called logger(level, ...inspectedArguments). On main a handler's console.log("hi %s, you are %d", "bob", 42) prints INFO RequestId: req-log "hi "bob", you are 42". With only the format2 change it prints INFO RequestId: req-log "hi %s, you are %d" "bob" 42. With the log() change from #35441 it prints INFO RequestId: req-log hi bob, you are 42. #35441 also changes formatError(). 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 format2 call (gdb stepi tally 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 format2 call: 0 / 3 / 0 / 0 / 0 -> 0 / 3 / 0 / 0 / 0 (same tally)
  • syscalls inside one format2 call: 1 -> 1 on all five shapes
  • console.log('a', S, 1), S = 1 KiB: 12,354 -> 1,885 instructions inside format2. 16-byte S: 2,183 -> 1,792
  • size of Formatter: 144 -> 128 bytes (gdb sizeof, debug build)
  • release .text: 79,755,685 -> 79,748,773 bytes (-6,912 B, size). format2 2,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)
  • StringPossiblyFormatted under src/jsc: 9 -> 0 lines. remaining_values under src/jsc: 16 -> 0 lines. pretty_format.rs keeps 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 sets BUN_JSC_validateExceptionChecks=1, and console.assert(false) aborts there on main too (an unchecked throw scope in consoleProtoFuncAssert). #44950 fixes that and can remove the gate.
  • $debug passes the caller's format string to console as its first argument: evaluates the source that createLogClientJS returns, 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 node test-console-*.js files (16 of 16).

Not changed here

  • Conversions in args[0] still throw where node prints, for example console.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]) prints NaN.
  • #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.rs has 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 one From<FormatTag> arm that the deleted variant forces.
  • console.table with a first argument that is not an object sends all its arguments to format2. Node prints only the first.
  • console.log("%s %s %%", "a") prints a %s %%. Node prints a %s %.
  • %c is consumed and dropped. %o prints 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. Its formatError() change is not.
  • #34239, #45337 and #45325 edit the specifier pass. Their reads of the queue become reads of the args parameter.
  • #36404 changes the predicate that this PR removes. #40534 touches the From<FormatTag> impl. #31716 puts a marker before the console.assert message.