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

src/jsc/ConsoleObject.rs

@@ -5922,6 +5922,48 @@ thread_local! {
     static PENDING_TIME_LOGS_LOADED: Cell<bool> = const { Cell::new(false) };
 }
 
+/// Write `label: <duration>` to `w` using Node.js's `console.timeEnd` /
+/// `console.timeLog` formatting rules (see Node's `internal/util/debuglog.js`
+/// `formatTime`): `<n>ms` below one second, `<n.nnn>s` below one minute, then
+/// `m:ss.mmm` / `h:mm:ss.mmm` above that.
+fn write_timer_label_and_duration(w: &mut bun_core::io::Writer, label: &[u8], ms: f64) {
+    const SECOND: f64 = 1_000.0;
+    const MINUTE: f64 = 60.0 * SECOND;
+    const HOUR: f64 = 60.0 * MINUTE;
+
+    let _ = w.write_all(label);
+    let _ = w.write_all(b": ");
+
+    if ms >= MINUTE {
+        let mut rem = ms;
+        let hours = if rem >= HOUR {
+            let h = (rem / HOUR).floor();
+            rem -= h * HOUR;
+            h as u64
+        } else {
+            0
+        };
+        let minutes = {
+            let m = (rem / MINUTE).floor();
+            rem -= m * MINUTE;
+            m as u64
+        };
+        let seconds = rem / SECOND;
+        if hours != 0 {
+            let _ = write!(w, "{hours}:{minutes:02}:{seconds:06.3} (h:mm:ss.mmm)");
+        } else {
+            let _ = write!(w, "{minutes}:{seconds:06.3} (m:ss.mmm)");
+        }
+    } else if ms >= SECOND {
+        let _ = write!(w, "{:.3}s", ms / SECOND);
+    } else {
+        // Node: `Number(ms.toFixed(3))` — round to three decimals, then print
+        // with JS number formatting (trailing zeros stripped).
+        let rounded = (ms * 1000.0).round() / 1000.0;
+        let _ = write!(w, "{}ms", bun_core::fmt::double(rounded));
+    }
+}
+
 #[unsafe(no_mangle)]
 #[crate::host_call]
 pub extern "C" fn Bun__ConsoleObject__time(
@@ -5949,7 +5991,7 @@ pub extern "C" fn Bun__ConsoleObject__time(
 #[crate::host_call]
 pub extern "C" fn Bun__ConsoleObject__timeEnd(
     _console: *mut ConsoleObject,
-    _global: &JSGlobalObject,
+    global: &JSGlobalObject,
     chars: *const u8,
     len: usize,
 ) {
@@ -5967,15 +6009,15 @@ pub extern "C" fn Bun__ConsoleObject__timeEnd(
     };
     let Some(value) = prev else { return };
     // get the duration in microseconds, then display it in milliseconds
-    Output::print_elapsed(
-        (value.read() / bun_core::time::NS_PER_US) as f64 / bun_core::time::US_PER_MS as f64,
-    );
-    match len {
-        0 => Output::print_errorln(format_args!("")),
-        _ => Output::print_errorln(format_args!(" {}", bstr::BStr::new(slice))),
-    }
+    let elapsed_ms =
+        (value.read() / bun_core::time::NS_PER_US) as f64 / bun_core::time::US_PER_MS as f64;
 
-    Output::flush();
+    // SAFETY: top-level JS-thread host call ⇒ exclusive access to the
+    // set-once `VirtualMachine.console` box.
+    let writer = unsafe { vm_console_mut(global) }.writer();
+    write_timer_label_and_duration(writer, slice, elapsed_ms);
+    let _ = writer.write_all(b"\n");
+    let _ = writer.flush();
 }
 
 #[unsafe(no_mangle)]
@@ -5999,14 +6041,16 @@ pub extern "C" fn Bun__ConsoleObject__timeLog(
         return;
     };
     // get the duration in microseconds, then display it in milliseconds
-    Output::print_elapsed(
-        (value.read() / bun_core::time::NS_PER_US) as f64 / bun_core::time::US_PER_MS as f64,
-    );
-    match len {
-        0 => {}
-        _ => Output::print_error(format_args!(" {}", bstr::BStr::new(slice))),
-    }
-    Output::flush();
+    let elapsed_ms =
+        (value.read() / bun_core::time::NS_PER_US) as f64 / bun_core::time::US_PER_MS as f64;
+
+    let console = vm_console(global);
+    // SAFETY: see [`vm_console`] — points at the live boxed `ConsoleObject` for
+    // this VM; JS-thread-only. Kept as a raw deref (not `vm_console_mut`) so the
+    // resulting `writer` borrow does not pin a long-lived `&mut ConsoleObject`
+    // across the `fmt.format(...)` calls below, which can re-enter JS.
+    let mut writer = unsafe { (*console).writer() };
+    write_timer_label_and_duration(writer, slice, elapsed_ms);
 
     // print the arguments
     // `Formatter` has a `Drop` impl, so struct-update from a
@@ -6017,19 +6061,14 @@ pub extern "C" fn Bun__ConsoleObject__timeLog(
         .unwrap_or(DEFAULT_CONSOLE_LOG_DEPTH);
     fmt.stack_check = StackCheck::init();
     fmt.can_throw_stack_overflow = true;
-    let console = vm_console(global);
-    // SAFETY: see [`vm_console`] — points at the live boxed `ConsoleObject` for
-    // this VM; JS-thread-only. Kept as a raw deref (not `vm_console_mut`) so the
-    // resulting `writer` borrow does not pin a long-lived `&mut ConsoleObject`
-    // across the `fmt.format(...)` calls below, which can re-enter JS.
-    let mut writer = unsafe { (*console).error_writer() };
+    let enable_colors = Output::enable_ansi_colors_stdout();
     // SAFETY: caller passes a valid (args, args_len) pair.
     for &arg in unsafe { bun_core::ffi::slice(args, args_len) } {
         let Ok(tag) = formatter::Tag::get(arg, global) else {
             return;
         };
         let _ = bun_io::Write::write_all(&mut writer, b" ");
-        if Output::enable_ansi_colors_stderr() {
+        if enable_colors {
             let _ = fmt.format::<true>(tag, &mut writer, arg, global);
         } else {
             let _ = fmt.format::<false>(tag, &mut writer, arg, global);

test/js/web/console/console-timeLog.expected.txt

@@ -1,18 +1,18 @@
-[0.00ms] label
-[0.06ms] label Hello World!
-[0.09ms] label a %s b c d
-[0.11ms] label 0 -0 123 -123 123.567 -123.567 Infinity -Infinity
-[0.14ms] label true false
-[0.15ms] label null undefined
-[0.17ms] label Symbol(Symbol Description)
-[0.22ms] label 2000-06-27T02:24:34.304Z
-[0.29ms] label [ 123, 456, 789 ]
-[0.34ms] label {
+label: 0.00ms
+label: 0.06ms Hello World!
+label: 0.09ms a %s b c d
+label: 0.11ms 0 -0 123 -123 123.567 -123.567 Infinity -Infinity
+label: 0.14ms true false
+label: 0.15ms null undefined
+label: 0.17ms Symbol(Symbol Description)
+label: 0.22ms 2000-06-27T02:24:34.304Z
+label: 0.29ms [ 123, 456, 789 ]
+label: 0.34ms {
   name: "foo",
 }
-[0.37ms] label {
+label: 0.37ms {
   a: 123,
   b: 456,
   c: 789,
 }
-[0.39ms] label
+label: 0.39ms

test/js/web/console/console-timeLog.test.ts

@@ -1,8 +1,28 @@
 import { file, spawn } from "bun";
-import { expect, it } from "bun:test";
+import { describe, expect, it } from "bun:test";
 import { bunEnv, bunExe } from "harness";
 import { join } from "node:path";
 
+// Matches Node.js: `label: 0.123ms`, `label: 1.234s`, `label: 1:02.345 (m:ss.mmm)`, ...
+const DURATION = /[\d.]+ms|[\d.]+s|[\d:.]+ \((?:h:mm|m):ss\.mmm\)/;
+
+it.concurrent("console.time/timeLog/timeEnd write to stdout, not stderr", async () => {
+  await using proc = Bun.spawn({
+    cmd: [bunExe(), "-e", `console.time("t"); console.timeLog("t", "x"); console.timeEnd("t");`],
+    env: bunEnv,
+    stdout: "pipe",
+    stderr: "pipe",
+  });
+  const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]);
+  expect(stderr).toBe("");
+  expect(stdout.split("\n")).toEqual([
+    expect.stringMatching(new RegExp(String.raw`^t: ${DURATION.source} x$`)),
+    expect.stringMatching(new RegExp(String.raw`^t: ${DURATION.source}$`)),
+    "",
+  ]);
+  expect(exitCode).toBe(0);
+});
+
 it.concurrent("console.timeEnd with empty label emits exactly one trailing newline", async () => {
   await using proc = Bun.spawn({
     cmd: [bunExe(), "-e", `console.time(""); console.timeEnd("");`],
@@ -11,8 +31,8 @@
     stderr: "pipe",
   });
   const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]);
-  expect(stdout).toBe("");
-  expect(stderr).toMatch(/^\[[\d.]+[mnµ]?s\]\n$/);
+  expect(stderr).toBe("");
+  expect(stdout).toMatch(new RegExp(String.raw`^: ${DURATION.source}\n$`));
   expect(exitCode).toBe(0);
 });
 
@@ -24,25 +44,103 @@
     stderr: "pipe",
   });
   const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]);
-  expect(stdout).toBe("");
-  expect(stderr).toMatch(/^\[[\d.]+[mnµ]?s\] abc\n$/);
+  expect(stderr).toBe("");
+  expect(stdout).toMatch(new RegExp(String.raw`^abc: ${DURATION.source}\n$`));
+  expect(exitCode).toBe(0);
+});
+
+it.concurrent("console.timeEnd prints ms below one second", async () => {
+  await using proc = Bun.spawn({
+    cmd: [bunExe(), "-e", `console.time("fast"); console.timeEnd("fast");`],
+    env: bunEnv,
+    stdout: "pipe",
+    stderr: "pipe",
+  });
+  const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]);
+  expect(stderr).toBe("");
+  expect(stdout).toMatch(/^fast: \d+(?:\.\d{1,3})?ms\n$/);
   expect(exitCode).toBe(0);
 });
 
+it.concurrent("console.timeEnd scales to seconds at >=1000ms", async () => {
+  await using proc = Bun.spawn({
+    cmd: [
+      bunExe(),
+      "-e",
+      // Busy-wait just past one second so the elapsed time lands in [1000, 2000)ms.
+      `console.time("sc"); const t0=Date.now(); while (Date.now()-t0 < 1100) {} console.timeEnd("sc");`,
+    ],
+    env: bunEnv,
+    stdout: "pipe",
+    stderr: "pipe",
+  });
+  const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]);
+  expect(stderr).toBe("");
+  expect(stdout).toMatch(/^sc: 1\.\d{3}s\n$/);
+  expect(exitCode).toBe(0);
+});
+
+it.concurrent("console.timeEnd uses the default label when none is given", async () => {
+  await using proc = Bun.spawn({
+    cmd: [bunExe(), "-e", `console.time(); console.timeEnd();`],
+    env: bunEnv,
+    stdout: "pipe",
+    stderr: "pipe",
+  });
+  const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]);
+  expect(stderr).toBe("");
+  expect(stdout).toMatch(new RegExp(String.raw`^default: ${DURATION.source}\n$`));
+  expect(exitCode).toBe(0);
+});
+
+describe("duplicate / unknown labels", () => {
+  it.concurrent("console.time on an existing label keeps the original timer", async () => {
+    await using proc = Bun.spawn({
+      cmd: [
+        bunExe(),
+        "-e",
+        `console.time("d"); const t0=Date.now(); while (Date.now()-t0 < 1100) {} console.time("d"); console.timeEnd("d");`,
+      ],
+      env: bunEnv,
+      stdout: "pipe",
+      stderr: "pipe",
+    });
+    const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]);
+    // Node emits a warning on duplicate console.time; Bun currently does not.
+    // Either way the original timer must be kept, so the duration is >= 1s.
+    expect(stdout).toMatch(/^d: 1\.\d{3}s\n$/);
+    expect(exitCode).toBe(0);
+  });
+
+  it.concurrent("console.timeEnd / timeLog on an unknown label produce no stdout", async () => {
+    await using proc = Bun.spawn({
+      cmd: [bunExe(), "-e", `console.timeLog("nope"); console.timeEnd("nope");`],
+      env: bunEnv,
+      stdout: "pipe",
+      stderr: "pipe",
+    });
+    const [stdout, , exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]);
+    expect(stdout).toBe("");
+    expect(exitCode).toBe(0);
+  });
+});
+
 it("should log to console correctly", async () => {
-  const { stderr, exited } = spawn({
+  const { stdout, stderr, exited } = spawn({
     cmd: [bunExe(), join(import.meta.dir, "console-timeLog.js")],
     stdin: null,
     stdout: "pipe",
     stderr: "pipe",
     env: bunEnv,
   });
-  expect(await exited).toBe(0);
-  const outText = await stderr.text();
+  const [outText, errText, exitCode] = await Promise.all([stdout.text(), stderr.text(), exited]);
+  expect(errText).toBe("");
   const expectedText = (await file(join(import.meta.dir, "console-timeLog.expected.txt")).text()).replaceAll(
     "\r\n",
     "\n",
   );
 
-  expect(outText.replace(/^\[.+?s\] /gm, "")).toBe(expectedText.replace(/^\[.+?s\] /gm, ""));
+  const normalize = (s: string) => s.replace(new RegExp(String.raw`^(.*?): ${DURATION.source}`, "gm"), "$1: <time>");
+  expect(normalize(outText)).toBe(normalize(expectedText));
+  expect(exitCode).toBe(0);
 });