PR #35441 - oven-sh/bun

Fixes #4826

Problem

Under bun-lambda, console.log("url:", url) prints "url:" "https://…". console.log("GET", "/caf%c3%a9", 200) prints "GET" "/caf3%a9". The error endpoints get errorMessage: "\"Function timed out\"".
log() (packages/bun-lambda/runtime.ts:25) prints each argument with Bun.inspect, which quotes a string, and the native console formats the pieces again. formatError() (:114) does the same.

Fix

formatArgs() builds the message once: a string as it is, every other value with Bun.inspect. formatError() uses the same rule.
For a format string, formatSpecifier() converts %s, %d, %i, %f, %j as node's util.format does. Under %s an object with a built-in toString (an Error, a Date) is inspected, so an Error keeps its stack. %j prints a cycle as [Circular]. Bun.inspect prints %o, %O.
Verified: test/integration/bun-lambda/bun-lambda.test.ts (4 of 6 fail on main). Same text on 16 binaries, 0.7.3 to 1.4.3.
Self-reviewed: 17 concerns raised, 17 addressed. One needs an edit to #45571. Review round two: 3 concerns, 2 addressed (%s on an Error, the catch in formatArgs()), 1 left (console.log() with no arguments is a pre-existing drop outside this fix).

Background

A released bun runs runtime.ts. One stdout line is one CloudWatch record, so log() writes line breaks in a message as \r.
Considered node:util's format (the earlier version). It prints Headers {}, logs the event body with a Request, and loads 17 M instructions at cold start or in the first format-string log.
Land this PR before #45571, which copied the earlier log() and drops it with its bun-lambda test. These tests pass on its native change.

Downsides

Log lines with a string change: CloudWatch filters on the quoted text stop matching.
A BigInt under %j, or a toString that throws under %s, now throws from the console call, as util.format does on node's runtime. On main the value printed as Bun.inspect text. In a handler the throw becomes a 500 response and an ERROR record.
Cold start: +503 K instructions:u on 13.16 M (+3.8%, A/A +12 K) for 2.3 KB more source, measured with aws4fetch on disk. A real layer installs aws4fetch first (#19756).

Notes

Output (the real runtime.ts against a mock Lambda Runtime API, bun 1.4.3. ⏎ is \r.)

handler call	main	this PR
`console.log("url:", request.url)`	`"url:" "http://api.example.com/hello"`	`url: http://api.example.com/hello`
`console.error("payload:", JSON.stringify({ a: 1 }, null, 2))`	`"payload:" "{\n \"a\": 1\n}"`	`payload: {⏎ "a": 1⏎}`
`console.log("hi %s, you are %d", "bob", 42)`	`"hi "bob", you are 42"`	`hi bob, you are 42`
`console.log("GET", "/caf%c3%a9", 200)`	`"GET" "/caf3%a9"`	`GET /caf%c3%a9 200`
`console.log({ url: "/caf%c3%a9" }, 200)`	`{⏎ url: "/caf3%a9",⏎}`	`{⏎ url: "/caf%c3%a9",⏎} 200`
`console.log("headers:", new Headers({ a: "1" }))`	`"headers:" Headers {⏎ "a": "1",⏎}`	`headers: Headers {⏎ "a": "1",⏎}`
`console.log("req %s took %dms", "GET /", 12, headers)`	`"req "GET /" took 12ms" Headers {…}`	`req GET / took 12ms Headers {⏎ "a": "1",⏎}`
`console.log("Event: %j", { c: [1] })`	`"Event: "{\r c: [ 1 ],\r}""`	`Event: {"c":[1]}`
runtime diagnostic at exit	`ERROR "Runtime failed to send request to Lambda [status: 500]"`	`ERROR Runtime failed to send request to Lambda [status: 500]`
`errorMessage` after a timeout	`"\"Function timed out\""`	`"Function timed out"`

A value that is not a string prints as on main: a Response, a Blob, a 5-level object, Headers, a Request, an Error, the IAM policy in the runtime's own WebSocket warning.
A cause that is not an Error and not a string keeps its Bun.inspect text in errorMessage. errorType stays "Error".

The format string

Only a string first argument is a format string, and only when more arguments follow. That is the rule of node and of the console standard.
For a string, a number, a BigInt, a boolean, a Symbol, null and undefined, every argument list prints what util.format prints (node v26.3.0 and Bun's port), and %j with a BigInt throws a TypeError as it does there.
For an object: %d, %i, %f and %j convert as util.format does. %s follows node's hasBuiltInToString rule: the owner of toString or Symbol.toPrimitive in the prototype chain is found, and when its constructor is a global built-in the value prints with Bun.inspect (an Error with its stack, a Date as ISO text, { a: 1 }). An object with its own toString or Symbol.toPrimitive prints String(value). Node uses depth: 0 for the inspect under %s. This PR uses the default depth, the same as %o. %o, %O and the arguments after the last specifier print with Bun.inspect.
%j on a cycle prints [Circular]. The cyclic TypeError is told apart by its message, computed once from a known cycle, as util.format does. Every other throw (a BigInt under %j, a user toString that throws) reaches the caller. A throw in a handler's fetch is a 500 response and an ERROR record with the stack.

Why not node:util

The earlier version of this PR sent every call to util.format, and #45571 has a copy of that log(). It is what node's Lambda runtime does (aws-lambda-nodejs-runtime-interface-client, src/LogPatch.js: util.format(message, ...params), then \n to \r). In Bun it changes the printer of every value, and a Lambda handler logs web objects:

console.log("headers:", request.headers) prints headers: Headers {}. A Response, a Blob and a FormData print empty too.
console.log(request) prints Request { aws: { ..., body: '...' } }. The runtime stores the event in request.aws, and util.inspect lists own properties. So the request body lands in CloudWatch. main and this PR print Request (N bytes) { method, url, headers }.
The IAM policy in the runtime's own WebSocket warning prints Action: [Array], Resource: [Array], because util.inspect stops at depth 2.
A static node:util import loads it in every execution environment: 13.16 M to 30.33 M instructions to the first GET /invocation/next, 13.9 to 22.4 ms, 2,301 to 5,042 heap objects, for a handler that never logs.
#45355 makes util.inspect print the web classes. It is open. It does not change the depth or the load.

A second version kept Bun.inspect for values and loaded node:util only at the first format string, with each object in a wrapper that sent node:util back to Bun.inspect. Then the load ran inside the first invocation that logs a format string: 17.96 M instructions and 2,698 heap objects (417 KB), where main runs none. The switch in formatSpecifier() runs 0.2 M there and loads nothing.

The hand-off to the console

log() keeps main's call shape: the level, the request id, then one finished message where main spread the pieces. The message is the last argument, so every release prints it as it is.
One joined string is two write(2) calls per line on bun 1.1.22 and older (the text, then the newline). This shape is one call on all 10 binaries measured, 0.7.3 to 1.4.3, as on main. It also does not copy a long message: a joined string cost 300 more instructions than main for a logged Error.
A CRLF in a string folds to one \r. node's runtime writes \r\r. On main a raw CRLF does not reach the fold, because Bun.inspect escapes it.

Releases

The layer runs on the release that the user picks (build-layer --release). 54 handler calls ran on 16 binaries: 0.7.3, 0.8.0, 0.8.1, 1.0.0, 1.0.4, 1.1.0, 1.1.22, 1.1.23, 1.1.45, 1.2.0, 1.2.23, 1.3.0, 1.3.14, 1.4.0, 1.4.3 and a 1.4.3 canary. 50 calls print the same text on all 16. The other 4 differ only by Bun.inspect's own text in that release: the field order of a Response, the text of an Error, the label of a null-prototype object, and a string under %o on 0.7.3.

Measurements (bun 1.4.3 release, linux x64 baseline build, transpiler cache off, the test layout with aws4fetch on disk. Instructions are instructions:u from perf_event_open over the process tree.)

Cold start to the first GET /invocation/next, handler never logs, median of 40 interleaved runs: main 13,158,521, this PR +502,958 (+3.8%), a second copy of main +12,094. Wall time 12.65 and 12.89 ms (second copy of main 13.50). Peak RSS 19,824 and 19,880 KB.
Heap objects at init: main 2,301, this PR 2,305. After the first format-string log: main 3,062, this PR 3,109 (+15 KB).
The first format-string log of a process: +0.2 M instructions (main +0.1 M, the spread of 11 runs is 0.5 M).
Per call, instructions, main to this PR: log("request received") 8,721 to 5,560. log("url:", url) 12,071 to 5,685. log(obj) 12,715 to 12,497. log("obj:", obj) 15,198 to 12,806. log(headers) 55,660 to 55,367. log(request) 81,787 to 81,375. error(new Error) 45,244 to 44,977. ("hi %s, you are %d", "bob", 42) 13,668 to 7,537. ("req %s took %dms", "GET /", 12, headers) 64,938 to 59,391. ("Event: %j", event) 45,757 to 8,905. Two copies of main differ by up to 295.
GC cells per call (1.4.3 canary, heapStats() deltas, 3 runs): fewer than main on 15 of 15 shapes. For example log(obj) 9 to 6, log(headers) 14 to 11, ("hi %s, you are %d", "bob", 42) 12 to 8.
Bun.inspect calls per console.log("url:", url): 0 (main 2). Regex passes per call: 1 (main 1 per argument). Console arguments per call: 3 (main 2 plus 1 per argument).
write(2) calls per log line: 1 (main 1).
No native change: 0 host functions, 0 binary bytes. runtime.ts is 24,584 to 26,850 bytes.

Cold start in a real layer

The numbers above have aws4fetch in node_modules, as the test has. The layer zip holds only bun, bootstrap and runtime.ts (scripts/build-layer.ts), and runtime.ts:1 imports aws4fetch. So a real cold start asks the npm registry for aws4fetch before the first Runtime API call. With a registry that does not answer, the process exits with error: Cannot find package 'aws4fetch' (#19756). That cost is larger than anything in this PR.
A lazy import of aws4fetch inside fetchAws() is a separate change. It is not in this PR. Related to #19756 and #6825.

Tests

console prints a string as it is and every other value as Bun.inspect does: 29 console calls in one handler, at init and in an invocation, through the six methods. The expected text of each value is Bun.inspect of the same value in the test process. The Request row compares with Bun.inspect(request) from the handler. The last assertion reads a heap marker: the runtime has not loaded node:util after all the calls.
errorMessage of ... is the cause as console prints it: a string at init, an object at init, and Function timed out in an invocation. The test checks the error body, stdout and the exit code.
a BigInt under %j throws in the handler, as any other throw in fetch: the ERROR record holds the TypeError with its stack and the invocation posts a 500 response.
With main's runtime.ts, 4 of 6 fail. With the earlier util.format version, 2 of 5 fail. With #45571's copy of log(), 4 of 5 fail.
39 of 41 mutants of the new code fail a test. The other two print the same bytes: one removes the includes("%") check that skips the specifier pass, one gives the console a single joined string.
The change is TypeScript in packages/, so a released bun runs it too. The tests ran on the debug build and on 1.4.3.

Landing order with #45571

#45571 changes the native console so that only the first argument is a format string. main's log() passes the level first and depended on the old rule, so #45571 copied this PR's earlier log() and its console test.
The order has one direction. With #45571's native change and main's log(), a handler's console.log("hi %s, you are %d", "bob", 42) prints "hi %s, you are %d" "bob" 42. So #45571 can drop its copy only after this log() is on main.
This log() does not depend on either native rule. With #45571's native change cherry-picked on top, the 5 tests pass on the debug build.
After this PR merges, #45571 drops its packages/bun-lambda/runtime.ts hunk, its bun-lambda test and its Fixes #4826 line. The two PRs conflict in those two files.

Not changed

The line layout: LEVEL message before the first invocation, LEVEL RequestId: ID message in one.
console.dir, table, assert, group, count and time are not wrapped.
errorType is "Error" for a cause that is not an Error. node's runtime sends typeof.
A string reaches the log as it is, as in node's runtime. A \n in it becomes \r inside the same record.

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

fails on main (without fix)

ASAN without fix: 2 FAILED
$ BUN_DEBUG_QUIET_LOGS=1 bun scripts/build.ts --profile=debug --quiet test "--reporter=junit" "--reporter-outfile=/tmp/mechgate.xml" test/integration/bun-lambda/bun-lambda.test.ts
bun test v1.4.0 (1e36aad1d)

test/integration/bun-lambda/bun-lambda.test.ts:
287 |   const exitedPromise = proc.exited;
288 |   const { pathname, body } = await initError;
289 |   const [stdout, stderr, exitCode] = await Promise.all([stdoutPromise, stderrPromise, exitedPromise]);
290 | 
291 |   expect(stderr).toBe("");
292 |   expect(stdout).toBe("ERROR handler does not have a default export with a function named 'fetch'\n");
                       ^
error: expect(received).toBe(expected)

- "ERROR handler does not have a default export with a function named 'fetch'
+ "ERROR "handler does not have a default export with a function named 'fetch'"
  "

- Expected  - 1
+ Received  + 1

      at <anonymous> (/workspace/bun/test/integration/bun-lambda/bun-lambda.test.ts:292:18)
(fail) init error errorMessage is not wrapped in extra quotes [783.88ms]
230 |   expect(stderr).toBe("");
231 |   expect(result.unexpected).toBeUndefined();
232 |   // Lines from inside the invocation carry the RequestId 
... (truncated)

release without fix: 2 FAILED
bun test v1.4.0-canary.1 (1498d7b77)

test/integration/bun-lambda/bun-lambda.test.ts:
230 |   expect(stderr).toBe("");
231 |   expect(result.unexpected).toBeUndefined();
232 |   // Lines from inside the invocation carry the RequestId prefix; the trailing
233 |   // ERROR line is the runtime shutting down after the mock server returns 500.
234 |   const lines = stdout.split("\n").filter(line => line.includes("RequestId: req-log"));
235 |   expect(lines).toEqual([
                      ^
error: expect(received).toEqual(expected)

  [
-   "INFO RequestId: req-log url: http://api.example.com/hello",
-   "INFO RequestId: req-log hi bob, you are 42",
+   "INFO RequestId: req-log "url:" "http://api.example.com/hello"",
+   "INFO RequestId: req-log "hi "bob", you are 42"",
+   "ERROR RequestId: req-log "payload:" "{\n  \"a\": 1\n}"",
    
- "ERROR RequestId: req-log payload: {
-   "a": 1
+ "INFO RequestId: req-log "obj:" {
+   a: 1,
  }"
  ,
-   "INFO RequestId: req-log obj: { a: 1 }",
-   "WARN RequestId: req-log keep %s literal",
-   
- "INFO RequestId: req-log crlf: a
- b"
- ,
+   "WARN RequestId: req-log "keep %s literal"",
+   "INFO RequestId: req-log "crlf:" "a\r\nb""
... (truncated)

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/integration/bun-lambda/bun-lambda.test.ts
bun test v1.4.0 (1e36aad1d)

test/integration/bun-lambda/bun-lambda.test.ts:
(pass) init error errorMessage is not wrapped in extra quotes [1187.27ms]
(pass) console.log formats arguments like Node, not Bun.inspect per-arg [1401.61ms]
(pass) lambda HTTP events cannot override the request authority [1567.24ms]

 3 pass
 0 fail
 14 expect() calls
Ran 3 tests across 1 file. [4.36s]
__F:0:S:0

release with fix: all passed
$ bun scripts/build.ts --profile=release
[configured] bun-profile → bun (stripped)
  target       linux-x64-gnu
  build type   Release
  build dir    ./build/release
  revision     1e36aad1da
  features     baseline

22 deps, 108 codegen, 1170 objects in 1163ms

ninja: Entering directory `/workspace/bun/build/release'
[1/1233] install /workspace/bun
bun install v1.4.0-canary.1 (1498d7b77)

Checked 124 installs across 170 packages (no changes) [34.00ms]
[2/1233] install /workspace/bun/packages/bun-error
bun install v1.4.0-canary.1 (1498d7b77)

Checked 1 install across 2 packages (no changes) [2.00ms]
[3/1233] gen bindgenv2
[4/1233] install /workspace/bun/src/node-fallbacks
bun install v1.4.0-canary.1 (1498d7b77)

Checked 129 installs across 147 packages (no changes) [9.00ms]
[5/1233] gen ErrorCode+*.h
[6/1233] fetch zlib
[zlib] up to date
[7/1233] fetch picohttpparser
[picohttpparser] up to date
[8/1233] fetch tinycc
[tinycc] up to date
[9/1233] gen .bind.ts → GeneratedBindings.cpp
[10/1233] fetch libjpeg-turbo
[libjpeg-turbo] up to date
[11/1233] subst deps/zlib/zlib.h
[12/1233] gen ProcessBindingConstants.lut.h
Generating /workspace/bun/build/release/codegen/Pr
... (truncated)

diff hotspot

packages/bun-lambda/runtime.ts                 |   9 +-
 test/integration/bun-lambda/bun-lambda.test.ts | 169 ++++++++++++++++++++++++-
 2 files changed, 173 insertions(+), 5 deletions(-)

gate history · 1 passed · 0 rejected · iteration 0

evidence per changed file

file                                            reads  edits  tests
packages/bun-lambda/runtime.ts                      9      8      0
test/integration/bun-lambda/bun-lambda.test.ts      2      6      0

#35441 bun-lambda: print a console string as it is and every other value with Bun.inspect

Problem

Fix

Background

Downsides

bun-lambda: print a console string as it is and every other value with Bun.inspect