fix: batch console logs by microtask (#7183)

Author: hi-ogawa

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('__TEST__ [beforeAll 1]')
+})
+beforeAll(() => {
+  console.log('__TEST__ [beforeAll 2]')
+})
+
+afterAll(() => {
+  console.log('__TEST__ [afterAll 1]')
+})
+afterAll(() => {
+  console.log('__TEST__ [afterAll 2]')
+})
+
+beforeEach(() => {
+  console.log('__TEST__ [beforeEach 1]')
+})
+beforeEach(() => {
+  console.log('__TEST__ [beforeEach 2]')
+})
+
+afterEach(() => {
+  console.log('__TEST__ [afterEach 1]')
+})
+afterEach(() => {
+  console.log('__TEST__ [afterEach 2]')
+})
+
+test('test', async () => {
+  console.log('__TEST__ [test 1]')
+  console.log('__TEST__ [test 2]')
+  await Promise.resolve()
+  console.log('__TEST__ [test 3]')
+  console.log('__TEST__ [test 4]')
+})

test/config/test/console.test.ts

@@ -21,3 +21,47 @@ 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 { stdout } = await runVitest({
+    root: './fixtures/console-batch',
+  })
+  const logs = stdout
+    .split('\n')
+    .filter(row => row.length === 0 || row.startsWith('stdout | ') || row.startsWith('__TEST__'))
+    .join('\n')
+    .trim()
+  expect(logs).toMatchInlineSnapshot(`
+    "stdout | basic.test.ts
+    __TEST__ [beforeAll 1]
+
+    stdout | basic.test.ts
+    __TEST__ [beforeAll 2]
+
+    stdout | basic.test.ts > test
+    __TEST__ [beforeEach 1]
+
+    stdout | basic.test.ts > test
+    __TEST__ [beforeEach 2]
+
+    stdout | basic.test.ts > test
+    __TEST__ [test 1]
+    __TEST__ [test 2]
+
+    stdout | basic.test.ts > test
+    __TEST__ [test 3]
+    __TEST__ [test 4]
+
+    stdout | basic.test.ts > test
+    __TEST__ [afterEach 2]
+
+    stdout | basic.test.ts > test
+    __TEST__ [afterEach 1]
+
+    stdout | basic.test.ts
+    __TEST__ [afterAll 2]
+
+    stdout | basic.test.ts
+    __TEST__ [afterAll 1]"
+  `)
+})