console: substitute format specifiers in the first argument only

Closed
RO
1mo ago
+90-8

What

console.log() (and every other console level) applied %s/%d/%f/%o/%c/%% substitution to every top-level string argument, not just args[0]. A later argument that merely contained a % silently consumed and reformatted the arguments after it, so they disappeared from the output entirely.

$ bun -e 'console.log("a", "100%foo", 42); console.log("q", "/p?x=%ff", 8); console.log("l", "%d %s", 1, "t")'
a 10042oo         # before
q /p?x=8f
l 1 t

a 100%foo 42      # after (matches node)
q /p?x=%ff 8
l %d %s 1 t

Logging a URL, a query string, or a percentage as a second argument is a common pattern, and the 42 / 8 above are gone from the line, not just reformatted.

Root cause

src/jsc/ConsoleObject.rs, the per-argument loop in format2 (both the color and no-color copies):

tag = formatter::Tag::get(this_value, global)?;
if matches!(tag.tag, TagPayload::String) && !fmt.remaining().is_empty() {
    tag.tag = TagPayload::StringPossiblyFormatted;
}

The loop walks every argument through the same body, so every string argument with something after it got promoted to StringPossiblyFormatted and ran through write_with_formatting, which pulls its substitutions out of remaining_values. The promotion is only correct for vals[0].

Two smaller divergences fall out of the same predicate:

  • TagPayload::String also covers StringObject / DerivedStringObject / RegExpObject, so console.log(/%d/, 1) printed /1/ and console.log(new String("%d"), 1) printed 1. The WHATWG Formatter only treats a primitive string as a format string (node checks typeof first === 'string').
  • Consequently console.log("%s %s", "a", "b", "%s", "c") printed a b c instead of a b %s c.

util.format is implemented separately in JS and was already correct; only the native console path diverged.

Fix

Gate the promotion on being the first argument and on that argument being a primitive string, via a shared is_format_string helper used by both copies of the loop.

Sibling site

src/runtime/test_runner/pretty_format.rs holds a byte-identical copy of this loop (the jest snapshot/diff formatter, with its own local Tag enum). Its multi-value path is unreachable today: all three callers (test_runner/mod.rs:208, test_runner/diff_format.rs:47 and :56) pass core::slice::from_ref(&x) with len = 1, so the len == 1 branch returns first. The same gate is applied there anyway to keep the two copies from silently diverging. No behavior change, so no test covers it.

Verification

test/js/web/console/console-log.test.ts gains a table of console.log calls whose expected output is node's, run through both the color and no-color branches of the loop (with an assertion that the colored branch really is taken), plus the String object case.

full before/after vs node
callnodebun beforebun after
"a", "100%foo", 42a 100%foo 42a 10042ooa 100%foo 42
"q", "/p?x=%ff", 8q /p?x=%ff 8q /p?x=8fq /p?x=%ff 8
"l", "%d %s", 1, "t"l %d %s 1 tl 1 tl %d %s 1 t
"x", "%%", 1x %% 1x % 1x %% 1
"x", "%c", "color:red", "y"x %c color:red yx yx %c color:red y
"%s %s", "a", "b", "%s", "c"a b %s ca b ca b %s c
1, "%d", 21 %d 21 21 %d 2
/%d/, 1/%d/ 1/1//%d/ 1
new String("%d"), 1[String: '%d'] 11[String: "%d"] 1
"%d/%s", 7, "k"7/k7/k7/k
"%%d", 1%d 1%d 1%d 1

Existing coverage is unchanged: console-log.expected.txt, test/js/bun/console/, test/js/bun/util/inspect.test.js, test/js/node/util/node-inspect-tests/, and the test-console-*.js node parallel tests all still pass.