Skip to content

console: match Node.js output for timeEnd/timeLog (stdout, "label: duration", 1000 ms threshold) - #34240

Closed
robobun wants to merge 2 commits into
mainfrom
claude/farm/3fc048a8/console-time-node-compat
Closed

console: match Node.js output for timeEnd/timeLog (stdout, "label: duration", 1000 ms threshold)#34240
robobun wants to merge 2 commits into
mainfrom
claude/farm/3fc048a8/console-time-node-compat

Conversation

@robobun

@robobun robobun commented Jul 15, 2026

Copy link
Copy Markdown
Collaborator

console.timeEnd and console.timeLog wrote [<n>ms] label to stderr, scaling to seconds only above 1500 ms. Node.js documents and prints label: <n>ms on stdout, scaling at 1000 ms, so shell redirects and log parsers written against the documented shape received nothing from Bun.

Supersedes #32423, which switched the stream but kept the Bun-specific format and threshold.

Repro

console.time("fast");
console.timeLog("fast", "extra", 42);
console.timeEnd("fast");
$ node repro.mjs                    # stdout
fast: 0.05ms extra 42
fast: 0.1ms

$ bun repro.mjs 2>/dev/null         # nothing on stdout
$ bun repro.mjs 2>&1 >/dev/null     # all on stderr, different grammar
[0.01ms] fast extra 42
[0.03ms] fast

And with a >1 s timer, Node prints sc: 1.201s while Bun printed [1199.23ms] sc (no scaling until 1500 ms).

Cause

Bun__ConsoleObject__timeEnd / timeLog in src/jsc/ConsoleObject.rs called Output::print_elapsed, which is the CLI-style stderr helper in src/bun_core/output.rs: pretty_error! with a [{:.2}ms] template and a 0..=1500 match arm for the ms/s split. The label was appended afterwards via print_error{,ln}, and timeLog's extra arguments went through the console's error_writer().

Fix

Add write_timer_label_and_duration, a dedicated stdout formatter that mirrors Node's internal/util/debuglog.js formatTime:

  • < 1000 ms: Number(ms.toFixed(3)) + "ms" (round to three decimals, trailing zeros stripped)
  • < 60 s: seconds.toFixed(3) + "s"
  • < 1 h: m:ss.mmm (m:ss.mmm)
  • >= 1 h: h:mm:ss.mmm (h:mm:ss.mmm)

timeEnd and timeLog now write label: <duration> to the console's stdout writer; timeLog's extra arguments follow the duration on the same line and pick the stdout colour setting.

Unchanged behaviours, now covered by tests:

  • Duplicate console.time(label) keeps the original timer.
  • timeEnd / timeLog on an unknown label produce no stdout output.

Verification

test/js/web/console/console-timeLog.test.ts asserts the stream, the label: <duration> grammar, the 1000 ms threshold, the default label, and the duplicate/unknown-label cases.

  • USE_SYSTEM_BUN=1 bun test test/js/web/console/console-timeLog.test.ts fails 8/9
  • bun bd test test/js/web/console/console-timeLog.test.ts passes 9/9
  • bun bd test test/js/web/console/ passes 16/16

Fixes #12031


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

fails on main (without fix)
ASAN without fix: 8 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-timeLog.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 (c3b6b145c)

test/js/web/console/console-timeLog.test.ts:
12 |     env: bunEnv,
13 |     stdout: "pipe",
14 |     stderr: "pipe",
15 |   });
16 |   const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]);
17 |   expect(stderr).toBe("");
                      ^
error: expect(received).toBe(expected)

- ""
+ "[0.06ms] t x
+ [0.21ms] t
+ "

- Expected  - 1
+ Received  + 3

      at <anonymous> (/workspace/bun/test/js/web/console/console-timeLog.test.ts:17:18)
(fail) console.time/timeLog/timeEnd write to stdout, not stderr [445.49ms]
29 |     env: bunEnv,
30 |     stdout: "pipe",
31 |     stderr: "pipe",
32 |   });
33 |   const [stdout, stderr, exitCode] = await Promise.all([p
... (truncated)

release without fix: all passed
bun test v1.4.0-canary.1 (ead1fa5ab)

test/js/web/console/console-timeLog.test.ts:
(pass) console.time/timeLog/timeEnd write to stdout, not stderr [13.05ms]
(pass) console.timeEnd with empty label emits exactly one trailing newline [11.21ms]
(pass) console.timeEnd prints ms below one second [10.56ms]
(pass) console.timeEnd with non-empty label emits exactly one trailing newline [11.43ms]
(pass) console.timeEnd uses the default label when none is given [10.61ms]
(pass) duplicate / unknown labels > console.timeEnd / timeLog on an unknown label produce no stdout [10.50ms]
(pass) duplicate / unknown labels > console.time on an existing label keeps the original timer [1110.80ms]
(pass) console.timeEnd scales to seconds at >=1000ms [1111.53ms]
(pass) should log to console correctly [13.94ms]

 9 pass
 0 fail
 25 expect() calls
Ran 9 tests across 1 file. [1275.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-timeLog.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 (c3b6b145c)

test/js/web/console/console-timeLog.test.ts:
(pass) console.time/timeLog/timeEnd write to stdout, not stderr [445.76ms]
(pass) console.timeEnd with empty label emits exactly one trailing newline [447.19ms]
(pass) console.timeEnd with non-empty label emits exactly one trailing newline [453.55ms]
(pass) console.timeEnd prints ms below one second [455.25ms]
(pass) console.timeEnd uses the default label when none is given [439.10ms]
(pass) duplicate / unknown labels > console.timeEnd / timeLog on an unknown label produce no stdout [423.37ms]
(pass) console.timeEnd scales to seconds at >=1000ms [1532.11ms]
(pass) duplicate / unknown labels > console.time on an existing label keeps the original timer [1530.16ms]
(pas
... (truncated)

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 711ms (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                         |  87 ++++++++++++-----
 test/js/web/console/console-timeLog.expected.txt |  24 ++---
 test/js/web/console/console-timeLog.test.ts      | 116 +++++++++++++++++++++--
 3 files changed, 182 insertions(+), 45 deletions(-)

gate history · 2 passed · 0 rejected · iteration 0

evidence per changed file
file                                              reads  edits  tests
src/jsc/ConsoleObject.rs                              7      7      0
test/js/web/console/console-timeLog.expected.txt      1      1      0
test/js/web/console/console-timeLog.test.ts           1      4      0

console.timeEnd and console.timeLog wrote "[<n>ms] label" to stderr,
scaling to seconds only above 1500 ms. Node.js documents and prints
"label: <n>ms" on stdout, with seconds kicking in at 1000 ms (and
m:ss.mmm / h:mm:ss.mmm beyond that), so shell redirects and log parsers
written against the documented shape saw nothing.

Route both paths through the console's stdout writer and format with a
Node-compatible "label: <duration>" helper that mirrors Node's
internal/util/debuglog.js formatTime (ms / s / m:ss.mmm / h:mm:ss.mmm).
timeLog's extra arguments now follow the duration and pick stdout's
colour setting.
@coderabbitai

coderabbitai Bot commented Jul 15, 2026

Copy link
Copy Markdown
Contributor

Warning

Review limit reached

@robobun, you've reached your PR review limit, so we couldn't start this review.

Next review available in: 6 minutes

Enable usage-based reviews in Billing to review now. Otherwise, wait until the next included review is available.
You're only billed for reviews past your plan's rate limits ($0.25/file).

How can I continue?

After more reviews become available, a review can be triggered using the @coderabbitai review command as a PR comment. Alternatively, push new commits to this PR.

To avoid repeated limits, reduce automatic review volume by pausing incremental auto-reviews earlier, using label-based review opt-in, excluding WIP or generated PR titles, or requesting reviews manually when the PR is ready. If your team needs uninterrupted high-volume reviews, an organization admin can enable usage-based reviews.

How do review limits work?

CodeRabbit enforces per-developer PR review limits for each organization. Most developers receive the normal plan review availability.

For paid Pro and Pro+ PR reviews, CodeRabbit uses adaptive limits for sustained high-volume activity. When a developer's recent PR review activity reaches the 95th percentile or higher among CodeRabbit users, additional reviews become available more gradually as earlier reviews age out of the rolling window.

Please refer docs for additional details.

Review details
⚙️ Run configuration

Configuration used: Path: .coderabbit.yaml

Review profile: ASSERTIVE

Plan: Pro

Run ID: cabffbd0-a3f0-40bc-8026-5e6ef452679d

📥 Commits

Reviewing files that changed from the base of the PR and between be77b65 and ead1fa5.

📒 Files selected for processing (3)
  • src/jsc/ConsoleObject.rs
  • test/js/web/console/console-timeLog.expected.txt
  • test/js/web/console/console-timeLog.test.ts

Comment @coderabbitai help to get the list of available commands.

@robobun

robobun commented Jul 15, 2026

Copy link
Copy Markdown
Collaborator Author
Updated 11:38 AM PT - Jul 15th, 2026

@robobun, your commit c3b6b14 has 2 failures in Build #73285 (All Failures):


🧪   To try this PR locally:

bunx bun-pr 34240

That installs a local version of the PR into your bun-34240 executable, so you can run:

bun-34240 --bun

@github-actions

Copy link
Copy Markdown
Contributor

Found 1 issue this PR may fix:

  1. console.timeEnd behaviour different in bun from node #12031 - Reports that console.timeEnd output goes to stderr instead of stdout (unlike Node.js); this PR routes timer output to stdout and matches Node's format

If this is helpful, copy the block below into the PR description to auto-close this issue on merge.

Fixes #12031

🤖 Generated with Claude Code

@github-actions

Copy link
Copy Markdown
Contributor

This PR may be a duplicate of:

  1. console: write timeEnd/timeLog to stdout instead of stderr #32423 - Also fixes console.timeEnd/timeLog to write to stdout instead of stderr; this PR supersedes it by additionally matching Node.js output format and threshold

🤖 Generated with Claude Code

Comment thread test/js/web/console/console-timeLog.test.ts Outdated
Comment thread test/js/web/console/console-timeLog.test.ts Outdated
The top-level | in DURATION was ungrouped, so when interpolated into a
larger pattern the surrounding anchors only attached to the first/last
alternative. Wrap in (?:...).

Also relax the seconds assertions from 1\. to \d+\. so a descheduled
busy-wait on a loaded runner cannot spuriously fail; the property under
test is the seconds unit, not the leading digit.

@claude claude Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for addressing both nits in c3b6b14 — the DURATION alternation is now grouped and the seconds-regex flake window is gone. I didn't find anything else in this pass, but leaving the merge to a maintainer since this changes user-visible output (stream + format) and supersedes #32423, which took a narrower approach.

What was reviewed:

  • write_timer_label_and_duration formatting against Node's formatTime (ms/s/m:ss/h:mm:ss branches, trailing-zero stripping via fmt::double)
  • timeEnd/timeLog writer switch: vm_console_mut vs raw-pointer deref pattern is preserved from the pre-PR error_writer() path; no new aliasing across fmt.format(...)
  • Grepped for other tests/snapshots asserting the old [Nms] label shape — none found (test-console-with-frozen-intrinsics.js calls but doesn't assert output)
Extended reasoning...

Overview

The PR rewires Bun__ConsoleObject__timeEnd and Bun__ConsoleObject__timeLog in src/jsc/ConsoleObject.rs to write label: <duration> to the console's stdout writer instead of [<duration>] label to stderr via Output::print_elapsed. A new write_timer_label_and_duration helper implements Node's formatTime rules (ms → s at 1000 ms; m:ss.mmm / h:mm:ss.mmm above one minute). Tests in console-timeLog.test.ts are updated for the new stream/format and expanded to cover the threshold, default label, and duplicate/unknown-label cases; the .expected.txt snapshot is regenerated.

What changed since my last review

Both prior nits were fixed in c3b6b14: the DURATION regex now wraps its alternation in (?:...) so interpolated anchors bind to every branch, and the two seconds-format assertions use \\d+\\.\\d{3}s instead of pinning the leading 1. Both inline threads are resolved. No new bugs surfaced from the bug-hunting pass on the current head.

Security risks

None. This is output formatting to stdout; no untrusted-input parsing, auth, or filesystem paths are involved. The unsafe blocks (vm_console_mut / raw (*console).writer() deref) are the same pre-existing pattern that was already used for error_writer(), with the same SAFETY comments; the change only swaps which writer is returned and moves acquisition a few lines earlier. timeEnd uses vm_console_mut (exclusive borrow, no re-entry after acquisition) while timeLog keeps the raw-pointer approach so the writer borrow doesn't span fmt.format(...) — structurally identical to before.

Level of scrutiny

Medium. The implementation is small, well-tested (9 cases, verified failing on main and passing under ASAN per the PR gate), and the unsafe pattern is unchanged. However, this is a user-visible behavior change: anyone parsing Bun's old [Nms] label on stderr will break. Issue #12031 requests exactly this and #32423 already attempted the stream switch, so organizational intent is clear — but #32423 deliberately kept Bun's format, and this PR goes further (full Node grammar including the untested m:ss.mmm / h:mm:ss.mmm branches). A maintainer should confirm which approach they want before merge.

Other factors

I checked for collateral test breakage from the format change: test/js/node/test/parallel/test-console-with-frozen-intrinsics.js calls console.time* but asserts nothing about the output, and no other test or snapshot in the repo matches the old [Nms] console-timer shape. The tests follow test/CLAUDE.md conventions (bunExe/bunEnv, -e for single-file, it.concurrent, drain pipes with Promise.all, exit-code asserted last). Given all feedback is addressed and the code looks correct, this is a product-decision sign-off rather than a code-quality block.

@robobun

robobun commented Jul 15, 2026

Copy link
Copy Markdown
Collaborator Author

CI on build 73285 is green for test/js/web/console/console-timeLog.test.ts on every lane. The remaining reds are unrelated to this diff:

  • test/js/node/test/parallel/test-worker-message-port-transfer-terminate.js (pre-existing JSC assertion on debian-13 x64-asan)
  • test/bake/deinitialization.test.ts (flaky timeout, windows-aarch64)
  • test/cli/install/bun-install-registry.test.ts (flaky hoisting assertion, windows-aarch64)
  • test/js/node/net/net-mongodb-pattern-leak.test.ts (flaky RSS bound, windows x64-baseline)
  • test/js/bun/spawn/spawn.test.ts (flaky timeout, windows)

Diff is ready for review.

@robobun

robobun commented Aug 13, 2026

Copy link
Copy Markdown
Collaborator Author

Closing as a duplicate of #37128, which reworks console output as a whole and includes everything here: timeEnd/timeLog on stdout, the label: <duration> grammar and Node's formatTime thresholds (checked on its current head: t: 0.077ms extra 42, slow: 1.007s, nothing on stderr). It also adds Node's missing-label warning.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

console.timeEnd behaviour different in bun from node

1 participant