First stderr entry shares timestamp with preceding stdout entry in custom reporters

[aslushnikov]

Describe the bug

When a test writes to stdout and then later to stderr, the time on the stderr UserConsoleLog matches the timestamp of the preceding stdout entry rather than the actual time stderr was written.

Reproduction

it('test-1', async () => {
  await new Promise(x => setTimeout(x, 50));
  console.log('foo');
  await new Promise(x => setTimeout(x, 100));
  console.error('bar');
});

In onUserConsoleLog, the bar entry's time equals the foo entry's time, despite being ~100ms apart in real time.

System Info

N/A

Used Package Manager

npm

Validations

• Follow our Code of Conduct
• Read the Contributing Guidelines.
• Read the docs.
• Check that there isn't already an issue that reports the same bug to avoid creating a duplicate.
• Check that this is a concrete bug. For Q&A open a GitHub Discussion or join our Discord Chat Server.
• The provided reproduction is a minimal reproducible example of the bug.

[hi-ogawa]

We only buffer by microtask and they do get split as log entry, so looks like a bug. Stackblits repro https://stackblitz.com/edit/vitest-dev-vitest-vbwyk18o?file=repro.test.ts

[onUserConsoleLog] {
  type: 'stdout',
  content: 'foo\n',
  taskId: '-880132345_0',
  time: 1778290295188,
  size: 1,
  origin: undefined
}
[onUserConsoleLog] {
  type: 'stderr',
  content: 'bar\n',
  taskId: '-880132345_0',
  time: 1778290295188,
  size: 1,
  origin: undefined
}

[truffle-dev]

The fault is in the create-new-timer branches of runtime/console.ts.

// packages/vitest/src/runtime/console.ts:135-144 (stdout write)
let timer = timers.get(id)
if (timer) {
  timer.stdoutTime = timer.stdoutTime || RealDate.now()
}
else {
  timer = {
    stdoutTime: RealDate.now(),
    stderrTime: RealDate.now(),   // stderr seeded before stderr has written
  }
  timers.set(id, timer)
}

When stderr writes ~100ms later, the existing-timer branch at line 176 is timer.stderrTime = timer.stderrTime || RealDate.now(), which short-circuits because stderrTime is already non-zero (the stale stdout time from creation). Symmetric on the stderr-first path at lines 180-181.

Minimal fix is to seed the other side to 0 at create-time so the || correctly fires on first write:

   timer = {
     stdoutTime: RealDate.now(),
-    stderrTime: RealDate.now(),
+    stderrTime: 0,
   }

   timer = {
     stderrTime: RealDate.now(),
-    stdoutTime: RealDate.now(),
+    stdoutTime: 0,
   }

The post-flush reset already uses 0 (lines 101, 104), sendLog already has the time: time || RealDate.now() fallback (line 121), and schedule()'s ordering check (line 65) is safe with one side at 0 because sendStdout/sendStderr early-return on empty buffers when the corresponding stream hasn't written yet.

Happy to PR with a regression test in test/e2e/test/reporters/console.test.ts if useful.