fix(runner): show stacktrace on hook timeout error

packages/runner/src/context.ts

@@ -34,6 +34,7 @@ export function withTimeout<T extends (...args: any[]) => any>(
   fn: T,
   timeout: number,
   isHook = false,
+  stackTraceError?: Error,
 ): T {
   if (timeout <= 0 || timeout === Number.POSITIVE_INFINITY) {
     return fn
@@ -47,18 +48,22 @@ export function withTimeout<T extends (...args: any[]) => any>(
     return new Promise((resolve_, reject_) => {
       const timer = setTimeout(() => {
         clearTimeout(timer)
-        reject(new Error(makeTimeoutMsg(isHook, timeout)))
+        rejectTimeoutError()
       }, timeout)
       // `unref` might not exist in browser
       timer.unref?.()
 
+      function rejectTimeoutError() {
+        reject_(makeTimeoutError(isHook, timeout, stackTraceError))
+      }
+
       function resolve(result: unknown) {
         clearTimeout(timer)
         // if test/hook took too long in microtask, setTimeout won't be triggered,
         // but we still need to fail the test, see
         // https://github.com/vitest-dev/vitest/issues/2920
         if (now() - startTime >= timeout) {
-          reject_(new Error(makeTimeoutMsg(isHook, timeout)))
+          rejectTimeoutError()
           return
         }
         resolve_(result)
@@ -108,26 +113,31 @@ export function createTestContext(
   context.onTestFailed = (handler, timeout) => {
     test.onFailed ||= []
     test.onFailed.push(
-      withTimeout(handler, timeout ?? runner.config.hookTimeout, true),
+      withTimeout(handler, timeout ?? runner.config.hookTimeout, true, new Error('STACK_TRACE_ERROR')),
     )
   }
 
   context.onTestFinished = (handler, timeout) => {
     test.onFinished ||= []
     test.onFinished.push(
-      withTimeout(handler, timeout ?? runner.config.hookTimeout, true),
+      withTimeout(handler, timeout ?? runner.config.hookTimeout, true, new Error('STACK_TRACE_ERROR')),
     )
   }
 
   return runner.extendTaskContext?.(context) || context
 }
 
-function makeTimeoutMsg(isHook: boolean, timeout: number) {
-  return `${
+function makeTimeoutError(isHook: boolean, timeout: number, stackTraceError?: Error) {
+  const message = `${
     isHook ? 'Hook' : 'Test'
   } timed out in ${timeout}ms.\nIf this is a long-running ${
     isHook ? 'hook' : 'test'
   }, pass a timeout value as the last argument or configure it globally with "${
     isHook ? 'hookTimeout' : 'testTimeout'
   }".`
+  const error = new Error(message)
+  if (stackTraceError?.stack) {
+    error.stack = stackTraceError.stack.replace(error.message, stackTraceError.message)
+  }
+  return error
 }

packages/runner/src/hooks.ts

@@ -19,14 +19,19 @@ function getDefaultHookTimeout() {
 }
 
 const CLEANUP_TIMEOUT_KEY = Symbol.for('VITEST_CLEANUP_TIMEOUT')
+const CLEANUP_STACK_TRACE_KEY = Symbol.for('VITEST_CLEANUP_STACK_TRACE')
 
 export function getBeforeHookCleanupCallback(hook: Function, result: any): Function | undefined {
   if (typeof result === 'function') {
     const timeout
       = CLEANUP_TIMEOUT_KEY in hook && typeof hook[CLEANUP_TIMEOUT_KEY] === 'number'
         ? hook[CLEANUP_TIMEOUT_KEY]
         : getDefaultHookTimeout()
-    return withTimeout(result, timeout, true)
+    const stackTraceError
+      = CLEANUP_STACK_TRACE_KEY in hook && hook[CLEANUP_STACK_TRACE_KEY] instanceof Error
+        ? hook[CLEANUP_STACK_TRACE_KEY]
+        : undefined
+    return withTimeout(result, timeout, true, stackTraceError)
   }
 }
 
@@ -52,9 +57,21 @@ export function beforeAll(
   timeout: number = getDefaultHookTimeout(),
 ): void {
   assertTypes(fn, '"beforeAll" callback', ['function'])
+  const stackTraceError = new Error('STACK_TRACE_ERROR')
   return getCurrentSuite().on(
     'beforeAll',
-    Object.assign(withTimeout(fn, timeout, true), { [CLEANUP_TIMEOUT_KEY]: timeout }),
+    Object.assign(
+      withTimeout(
+        fn,
+        timeout,
+        true,
+        stackTraceError,
+      ),
+      {
+        [CLEANUP_TIMEOUT_KEY]: timeout,
+        [CLEANUP_STACK_TRACE_KEY]: stackTraceError,
+      },
+    ),
   )
 }
 
@@ -79,7 +96,12 @@ export function afterAll(fn: AfterAllListener, timeout?: number): void {
   assertTypes(fn, '"afterAll" callback', ['function'])
   return getCurrentSuite().on(
     'afterAll',
-    withTimeout(fn, timeout ?? getDefaultHookTimeout(), true),
+    withTimeout(
+      fn,
+      timeout ?? getDefaultHookTimeout(),
+      true,
+      new Error('STACK_TRACE_ERROR'),
+    ),
   )
 }
 
@@ -105,11 +127,20 @@ export function beforeEach<ExtraContext = object>(
   timeout: number = getDefaultHookTimeout(),
 ): void {
   assertTypes(fn, '"beforeEach" callback', ['function'])
+  const stackTraceError = new Error('STACK_TRACE_ERROR')
   return getCurrentSuite<ExtraContext>().on(
     'beforeEach',
     Object.assign(
-      withTimeout(withFixtures(fn), timeout ?? getDefaultHookTimeout(), true),
-      { [CLEANUP_TIMEOUT_KEY]: timeout },
+      withTimeout(
+        withFixtures(fn),
+        timeout ?? getDefaultHookTimeout(),
+        true,
+        stackTraceError,
+      ),
+      {
+        [CLEANUP_TIMEOUT_KEY]: timeout,
+        [CLEANUP_STACK_TRACE_KEY]: stackTraceError,
+      },
     ),
   )
 }
@@ -138,7 +169,12 @@ export function afterEach<ExtraContext = object>(
   assertTypes(fn, '"afterEach" callback', ['function'])
   return getCurrentSuite<ExtraContext>().on(
     'afterEach',
-    withTimeout(withFixtures(fn), timeout ?? getDefaultHookTimeout(), true),
+    withTimeout(
+      withFixtures(fn),
+      timeout ?? getDefaultHookTimeout(),
+      true,
+      new Error('STACK_TRACE_ERROR'),
+    ),
   )
 }
 
@@ -165,7 +201,12 @@ export const onTestFailed: TaskHook<OnTestFailedHandler> = createTestHook(
   (test, handler, timeout) => {
     test.onFailed ||= []
     test.onFailed.push(
-      withTimeout(handler, timeout ?? getDefaultHookTimeout(), true),
+      withTimeout(
+        handler,
+        timeout ?? getDefaultHookTimeout(),
+        true,
+        new Error('STACK_TRACE_ERROR'),
+      ),
     )
   },
 )
@@ -198,7 +239,12 @@ export const onTestFinished: TaskHook<OnTestFinishedHandler> = createTestHook(
   (test, handler, timeout) => {
     test.onFinished ||= []
     test.onFinished.push(
-      withTimeout(handler, timeout ?? getDefaultHookTimeout(), true),
+      withTimeout(
+        handler,
+        timeout ?? getDefaultHookTimeout(),
+        true,
+        new Error('STACK_TRACE_ERROR'),
+      ),
     )
   },
 )

test/config/fixtures/hook-timeout/basic.test.ts

@@ -0,0 +1,50 @@
+import { describe, it, beforeAll, beforeEach, afterAll, afterEach } from "vitest"
+
+describe('beforeAll', () => {
+  beforeAll(() => new Promise(() => {}), 10)
+
+  it('ok', () => {})
+})
+
+describe('beforeEach', () => {
+  beforeEach(() => new Promise(() => {}), 20)
+
+  it('ok', () => {})
+})
+
+describe('afterAll', () => {
+  afterAll(() => new Promise(() => {}), 30)
+
+  it('ok', () => {})
+})
+
+describe('afterEach', () => {
+  afterEach(() => new Promise(() => {}), 40)
+
+  it('ok', () => {})
+})
+
+describe('cleanup-beforeAll', () => {
+  beforeAll(() => () => new Promise(() => {}), 50)
+
+  it('ok', () => {})
+})
+
+describe('cleanup-beforeEach', () => {
+  beforeEach(() => () => new Promise(() => {}), 60)
+
+  it('ok', () => {})
+})
+
+describe('onFailed', () => {
+  it('fail', (ctx) => {
+    ctx.onTestFailed(() => new Promise(() => {}), 70)
+    throw new Error('fail')
+  })
+})
+
+describe('onFinished', () => {
+  it('ok', (ctx) => {
+    ctx.onTestFinished(() => new Promise(() => {}), 80)
+  })
+})

test/config/test/__snapshots__/hook-timeout.test.ts.snap

@@ -0,0 +1,127 @@
+// Vitest Snapshot v1, https://vitest.dev/guide/snapshot.html
+
+exports[`timeout error with stack trace 1`] = `
+"
+⎯⎯⎯⎯⎯⎯ Failed Suites 3 ⎯⎯⎯⎯⎯⎯⎯
+
+ FAIL  basic.test.ts > beforeAll
+Error: Hook timed out in 10ms.
+If this is a long-running hook, pass a timeout value as the last argument or configure it globally with "hookTimeout".
+ ❯ basic.test.ts:4:3
+      2| 
+      3| describe('beforeAll', () => {
+      4|   beforeAll(() => new Promise(() => {}), 10)
+       |   ^
+      5| 
+      6|   it('ok', () => {})
+
+⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯[1/9]⎯
+
+ FAIL  basic.test.ts > afterAll
+Error: Hook timed out in 30ms.
+If this is a long-running hook, pass a timeout value as the last argument or configure it globally with "hookTimeout".
+ ❯ basic.test.ts:16:3
+     14| 
+     15| describe('afterAll', () => {
+     16|   afterAll(() => new Promise(() => {}), 30)
+       |   ^
+     17| 
+     18|   it('ok', () => {})
+
+⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯[2/9]⎯
+
+ FAIL  basic.test.ts > cleanup-beforeAll
+Error: Hook timed out in 50ms.
+If this is a long-running hook, pass a timeout value as the last argument or configure it globally with "hookTimeout".
+ ❯ basic.test.ts:28:3
+     26| 
+     27| describe('cleanup-beforeAll', () => {
+     28|   beforeAll(() => () => new Promise(() => {}), 50)
+       |   ^
+     29| 
+     30|   it('ok', () => {})
+
+⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯[3/9]⎯
+
+
+⎯⎯⎯⎯⎯⎯⎯ Failed Tests 5 ⎯⎯⎯⎯⎯⎯⎯
+
+ FAIL  basic.test.ts > beforeEach > ok
+Error: Hook timed out in 20ms.
+If this is a long-running hook, pass a timeout value as the last argument or configure it globally with "hookTimeout".
+ ❯ basic.test.ts:10:3
+      8| 
+      9| describe('beforeEach', () => {
+     10|   beforeEach(() => new Promise(() => {}), 20)
+       |   ^
+     11| 
+     12|   it('ok', () => {})
+
+⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯[4/9]⎯
+
+ FAIL  basic.test.ts > afterEach > ok
+Error: Hook timed out in 40ms.
+If this is a long-running hook, pass a timeout value as the last argument or configure it globally with "hookTimeout".
+ ❯ basic.test.ts:22:3
+     20| 
+     21| describe('afterEach', () => {
+     22|   afterEach(() => new Promise(() => {}), 40)
+       |   ^
+     23| 
+     24|   it('ok', () => {})
+
+⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯[5/9]⎯
+
+ FAIL  basic.test.ts > cleanup-beforeEach > ok
+Error: Hook timed out in 60ms.
+If this is a long-running hook, pass a timeout value as the last argument or configure it globally with "hookTimeout".
+ ❯ basic.test.ts:34:3
+     32| 
+     33| describe('cleanup-beforeEach', () => {
+     34|   beforeEach(() => () => new Promise(() => {}), 60)
+       |   ^
+     35| 
+     36|   it('ok', () => {})
+
+⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯[6/9]⎯
+
+ FAIL  basic.test.ts > onFailed > fail
+Error: fail
+ ❯ basic.test.ts:42:11
+     40|   it('fail', (ctx) => {
+     41|     ctx.onTestFailed(() => new Promise(() => {}), 70)
+     42|     throw new Error('fail')
+       |           ^
+     43|   })
+     44| })
+
+⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯[7/9]⎯
+
+ FAIL  basic.test.ts > onFailed > fail
+Error: Hook timed out in 70ms.
+If this is a long-running hook, pass a timeout value as the last argument or configure it globally with "hookTimeout".
+ ❯ basic.test.ts:41:9
+     39| describe('onFailed', () => {
+     40|   it('fail', (ctx) => {
+     41|     ctx.onTestFailed(() => new Promise(() => {}), 70)
+       |         ^
+     42|     throw new Error('fail')
+     43|   })
+
+⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯[8/9]⎯
+
+ FAIL  basic.test.ts > onFinished > ok
+Error: Hook timed out in 80ms.
+If this is a long-running hook, pass a timeout value as the last argument or configure it globally with "hookTimeout".
+ ❯ basic.test.ts:48:9
+     46| describe('onFinished', () => {
+     47|   it('ok', (ctx) => {
+     48|     ctx.onTestFinished(() => new Promise(() => {}), 80)
+       |         ^
+     49|   })
+     50| })
+
+⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯[9/9]⎯
+
+"
+`;

test/config/test/hook-timeout.test.ts

@@ -0,0 +1,9 @@
+import { expect, test } from 'vitest'
+import { runVitest } from '../../test-utils'
+
+test('timeout error with stack trace', async () => {
+  const { stderr } = await runVitest({
+    root: './fixtures/hook-timeout',
+  })
+  expect(stderr).toMatchSnapshot()
+})