From 268a19e19aadd7e83567ad7226abe6ea38878c3b Mon Sep 17 00:00:00 2001 From: Hiroshi Ogawa Date: Tue, 11 Mar 2025 22:35:53 +0900 Subject: [PATCH] fix(runner): show stacktrace on hook timeout error (#7502) --- packages/runner/src/context.ts | 22 ++- packages/runner/src/hooks.ts | 62 +++++++-- .../fixtures/hook-timeout/basic.test.ts | 50 +++++++ .../__snapshots__/hook-timeout.test.ts.snap | 127 ++++++++++++++++++ test/config/test/hook-timeout.test.ts | 9 ++ 5 files changed, 256 insertions(+), 14 deletions(-) create mode 100644 test/config/fixtures/hook-timeout/basic.test.ts create mode 100644 test/config/test/__snapshots__/hook-timeout.test.ts.snap create mode 100644 test/config/test/hook-timeout.test.ts diff --git a/packages/runner/src/context.ts b/packages/runner/src/context.ts index 7dadb6033..8c08d3f15 100644 --- a/packages/runner/src/context.ts +++ b/packages/runner/src/context.ts @@ -34,6 +34,7 @@ export function withTimeout 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 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 } diff --git a/packages/runner/src/hooks.ts b/packages/runner/src/hooks.ts index 1e11fdb33..974024090 100644 --- a/packages/runner/src/hooks.ts +++ b/packages/runner/src/hooks.ts @@ -19,6 +19,7 @@ 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') { @@ -26,7 +27,11 @@ export function getBeforeHookCleanupCallback(hook: Function, result: any): Funct = 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( timeout: number = getDefaultHookTimeout(), ): void { assertTypes(fn, '"beforeEach" callback', ['function']) + const stackTraceError = new Error('STACK_TRACE_ERROR') return getCurrentSuite().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( assertTypes(fn, '"afterEach" callback', ['function']) return getCurrentSuite().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 = 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 = createTestHook( (test, handler, timeout) => { test.onFinished ||= [] test.onFinished.push( - withTimeout(handler, timeout ?? getDefaultHookTimeout(), true), + withTimeout( + handler, + timeout ?? getDefaultHookTimeout(), + true, + new Error('STACK_TRACE_ERROR'), + ), ) }, ) diff --git a/test/config/fixtures/hook-timeout/basic.test.ts b/test/config/fixtures/hook-timeout/basic.test.ts new file mode 100644 index 000000000..0278a6f57 --- /dev/null +++ b/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) + }) +}) diff --git a/test/config/test/__snapshots__/hook-timeout.test.ts.snap b/test/config/test/__snapshots__/hook-timeout.test.ts.snap new file mode 100644 index 000000000..29b6fffe2 --- /dev/null +++ b/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]⎯ + +" +`; diff --git a/test/config/test/hook-timeout.test.ts b/test/config/test/hook-timeout.test.ts new file mode 100644 index 000000000..7b6798bd7 --- /dev/null +++ b/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() +}) -- 2.51.2