fix: batch console logs by microtask

packages/utils/src/timers.ts

@@ -8,6 +8,7 @@ export interface SafeTimers {
   clearTimeout: typeof clearTimeout
   setImmediate: typeof setImmediate
   clearImmediate: typeof clearImmediate
+  queueMicrotask: typeof queueMicrotask
 }
 
 export function getSafeTimers(): SafeTimers {
@@ -18,6 +19,7 @@ export function getSafeTimers(): SafeTimers {
     clearTimeout: safeClearTimeout,
     setImmediate: safeSetImmediate,
     clearImmediate: safeClearImmediate,
+    queueMicrotask: safeQueueMicrotask,
   } = (globalThis as any)[SAFE_TIMERS_SYMBOL] || globalThis
 
   const { nextTick: safeNextTick } = (globalThis as any)[SAFE_TIMERS_SYMBOL]
@@ -31,6 +33,7 @@ export function getSafeTimers(): SafeTimers {
     clearTimeout: safeClearTimeout,
     setImmediate: safeSetImmediate,
     clearImmediate: safeClearImmediate,
+    queueMicrotask: safeQueueMicrotask,
   }
 }
 
@@ -42,6 +45,7 @@ export function setSafeTimers(): void {
     clearTimeout: safeClearTimeout,
     setImmediate: safeSetImmediate,
     clearImmediate: safeClearImmediate,
+    queueMicrotask: safeQueueMicrotask,
   } = globalThis
 
   const { nextTick: safeNextTick } = globalThis.process || {
@@ -56,6 +60,7 @@ export function setSafeTimers(): void {
     clearTimeout: safeClearTimeout,
     setImmediate: safeSetImmediate,
     clearImmediate: safeClearImmediate,
+    queueMicrotask: safeQueueMicrotask,
   };
 
   (globalThis as any)[SAFE_TIMERS_SYMBOL] = timers

packages/vitest/src/runtime/console.ts

@@ -37,19 +37,31 @@ export function createCustomConsole(defaultState?: WorkerGlobalState) {
   const stderrBuffer = new Map<string, any[]>()
   const timers = new Map<
     string,
-    { stdoutTime: number; stderrTime: number; timer: any }
+    { stdoutTime: number; stderrTime: number; cancel?: () => void }
   >()
 
-  const { setTimeout, clearTimeout } = getSafeTimers()
+  const { queueMicrotask } = getSafeTimers()
+
+  function queueCancelableMicrotask(callback: () => void) {
+    let canceled = false
+    queueMicrotask(() => {
+      if (!canceled) {
+        callback()
+      }
+    })
+    return () => {
+      canceled = true
+    }
+  }
 
   const state = () => defaultState || getWorkerState()
 
-  // group sync console.log calls with macro task
+  // group sync console.log calls with micro task
   function schedule(taskId: string) {
     const timer = timers.get(taskId)!
     const { stdoutTime, stderrTime } = timer
-    clearTimeout(timer.timer)
-    timer.timer = setTimeout(() => {
+    timer.cancel?.()
+    timer.cancel = queueCancelableMicrotask(() => {
       if (stderrTime < stdoutTime) {
         sendStderr(taskId)
         sendStdout(taskId)
@@ -128,7 +140,6 @@ export function createCustomConsole(defaultState?: WorkerGlobalState) {
         timer = {
           stdoutTime: RealDate.now(),
           stderrTime: RealDate.now(),
-          timer: 0,
         }
         timers.set(id, timer)
       }
@@ -168,7 +179,6 @@ export function createCustomConsole(defaultState?: WorkerGlobalState) {
         timer = {
           stderrTime: RealDate.now(),
           stdoutTime: RealDate.now(),
-          timer: 0,
         }
         timers.set(id, timer)
       }

test/config/fixtures/console-batch/basic.test.ts

@@ -0,0 +1,37 @@
+import { afterAll, afterEach, beforeAll, beforeEach, describe, test } from 'vitest'
+
+beforeAll(() => {
+  console.log('[beforeAll 1]')
+})
+beforeAll(() => {
+  console.log('[beforeAll 2]')
+})
+
+afterAll(() => {
+  console.log('[afterAll 1]')
+})
+afterAll(() => {
+  console.log('[afterAll 2]')
+})
+
+beforeEach(() => {
+  console.log('[beforeEach 1]')
+})
+beforeEach(() => {
+  console.log('[beforeEach 2]')
+})
+
+afterEach(() => {
+  console.log('[afterEach 1]')
+})
+afterEach(() => {
+  console.log('[afterEach 2]')
+})
+
+test('test', async () => {
+  console.log('[test 1]')
+  console.log('[test 2]')
+  await Promise.resolve()
+  console.log('[test 3]')
+  console.log('[test 4]')
+})

test/config/test/console.test.ts

@@ -1,3 +1,4 @@
+import type { UserConsoleLog } from 'vitest'
 import { expect, test, vi } from 'vitest'
 import { runVitest } from '../../test-utils'
 
@@ -21,3 +22,44 @@ test.each(['threads', 'vmThreads'] as const)(`disable intercept pool=%s`, async
   const call = spy.mock.lastCall![0]
   expect(call.toString()).toBe('__test_console__\n')
 })
+
+test('group synchronous console logs', async () => {
+  const logs: UserConsoleLog[] = []
+  await runVitest({
+    root: './fixtures/console-batch',
+    reporters: [
+      'default',
+      {
+        onUserConsoleLog(log) {
+          logs.push(log)
+        },
+      },
+    ],
+  })
+  expect(logs.map(log => log.content)).toMatchInlineSnapshot(`
+    [
+      "[beforeAll 1]
+    ",
+      "[beforeAll 2]
+    ",
+      "[beforeEach 1]
+    ",
+      "[beforeEach 2]
+    ",
+      "[test 1]
+    [test 2]
+    ",
+      "[test 3]
+    [test 4]
+    ",
+      "[afterEach 2]
+    ",
+      "[afterEach 1]
+    ",
+      "[afterAll 2]
+    ",
+      "[afterAll 1]
+    ",
+    ]
+  `)
+})