feat(experimental): add trace timeline for node (#11753)

Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>

Author: hi-ogawa

docs/config/experimental.md

@@ -460,6 +460,37 @@ If [`isolate`](/config/isolate) is disabled, test files that run in the same wor
 If [`experimental.viteModuleRunner`](#experimental-vitemodulerunner) is disabled, Vitest records the imports with a resolve hook of [`module.registerHooks`](https://nodejs.org/api/module.html#moduleregisterhooksoptions). Node.js versions without it do not write records, so every test runs.
 :::
 
+## experimental.traceTimeline <Version type="experimental">5.1.0</Version> {#experimental-tracetimeline}
+
+- **Type:** `boolean`
+- **Default:** `false`
+
+Records the [`expect.poll`](/api/expect#poll), [`vi.waitFor`](/api/vi#vi-waitfor), and [`vi.waitUntil`](/api/vi#vi-waituntil) steps of each test, and prints them as a timeline under the error when the test fails. This shows what the test waited on before it failed and how long each wait took, which helps with flaky tests that wait on servers, queues, or file watchers.
+
+```ts [vitest.config.ts]
+import { defineConfig } from 'vitest/config'
+
+export default defineConfig({
+  test: {
+    experimental: {
+      traceTimeline: true,
+    },
+  },
+})
+```
+
+<<< ./snippets/trace-timeline-failure.ansi [Error report]
+
+Steps are reported only for failed attempts, so the option adds almost no overhead to passing tests.
+
+Step locations are resolved like error stacks, so a step in a helper file points at that file, and a step in a [`vi.defineHelper`](/api/vi#vi-definehelper) helper points at the line that called the helper.
+
+This option has no effect in browser mode, which prints the same timeline with [`browser.traceView`](/config/browser/traceview).
+
+::: warning
+`vi.waitFor`, `vi.waitUntil`, and polls from the global `expect` are attributed to the test that is currently running. When several tests run at the same time with [`test.concurrent`](/api/test#test-concurrent), `vi.waitFor` and `vi.waitUntil` are not recorded, and polls from the global `expect` can appear in another test's timeline. Use `expect` from the [test context](/guide/test-context) in concurrent tests to record polls for the right test.
+:::
+
 ## experimental.nodeLoader <Version type="experimental">4.1.0</Version> {#experimental-nodeloader}
 
 - **Type:** `boolean`

docs/config/snippets/trace-timeline-failure.ansi

@@ -0,0 +1,23 @@
+ FAIL src/search.test.ts > finds new user in search
+AssertionError: expected [] to have a length of 1 but got +0
+
+- Expected
++ Received
+
+- 1
++ 0
+
+ ❯ src/search.test.ts:8:50
+      6|   await api.post('/users', { name: 'alice' })
+      7|   await vi.waitUntil(() => db.users.findByName('alice'))
+      8|   await expect.poll(() => search.query('alice')).toHaveLength(1)
+       |                                                  ^
+      9| })
+
+Caused by: Error: Matcher did not succeed in time.
+
+Trace:
+  step                           start  duration  location
+  vi.waitFor()                    +2ms     120ms  src/search.test.ts:5:12
+  vi.waitUntil()                +171ms      42ms  src/search.test.ts:7:12
+  expect.poll().toHaveLength()  +214ms    1001ms  src/search.test.ts:8:50

docs/guide/browser/trace-view.md

@@ -85,6 +85,8 @@ Vitest records a step for:
 
 Each step records its timing, selector, and the source location that triggered it.
 
+Tests outside browser mode can print the same timeline for their `expect.poll`, `vi.waitFor`, and `vi.waitUntil` steps with [`experimental.traceTimeline`](/config/experimental#experimental-tracetimeline).
+
 ## Custom Trace Entries
 
 You can insert your own named entries with `page.mark()` and `locator.mark()`:

docs/guide/cli-generated.md

@@ -1020,6 +1020,13 @@ Control whether Vitest uses Vite's module runner to run the code or fallback to
 
 Controls whether Vitest will use Node.js Loader API to process in-source or mocked files. This has no effect if `viteModuleRunner` is enabled. Disabling this can increase performance. (default: `true`)
 
+### experimental.traceTimeline
+
+- **CLI:** `--experimental.traceTimeline`
+- **Config:** [experimental.traceTimeline](/config/experimental#experimental-tracetimeline)
+
+Record `expect.poll`, `vi.waitFor`, and `vi.waitUntil` steps of each test and print them as a timeline when the test fails. This has no effect in browser mode. (default: `false`)
+
 ### experimental.vcsProvider
 
 - **CLI:** `--experimental.vcsProvider <path>`

packages/vitest/src/integrations/chai/poll.ts

@@ -2,10 +2,17 @@ import type { Assertion, ExpectStatic } from '@vitest/expect'
 import type { Test } from '../../runtime/runner/types'
 import { chai } from '@vitest/expect'
 import { delay, getSafeTimers } from '@vitest/utils/timers'
+import { createTraceRangeId, getTraceAttempt, recordTraceEntry } from '../../runtime/trace-timeline'
 import { getWorkerState } from '../../runtime/utils'
 import { copyStackTrace } from '../../utils/errors'
 import { vi } from '../vi'
 
+type PollOnStart = (meta: { assertion: Assertion }) => void | Promise<void>
+type PollOnSettled = (meta: {
+  assertion: Assertion
+  status: 'pass' | 'fail'
+}) => void | Promise<void>
+
 // these matchers are not supported because they don't make sense with poll
 const unsupported = [
   // .poll is meant to retry matchers until they succeed, and
@@ -73,6 +80,7 @@ export function createExpectPoll(expect: ExpectStatic): ExpectStatic['poll'] {
     if (!test) {
       throw new Error('expect.poll() must be called inside a test')
     }
+    setTraceHandlers(assertion, test)
     const proxy: any = new Proxy(assertion, {
       get(target, key, receiver) {
         const assertionFunction = Reflect.get(target, key, receiver)
@@ -115,8 +123,10 @@ export function createExpectPoll(expect: ExpectStatic): ExpectStatic['poll'] {
             chai.util.flag(assertion, '_name', key)
             chai.util.flag(assertion, 'error', STACK_TRACE_ERROR)
 
-            const onStart = chai.util.flag(assertion, '_poll.onStart') as Function | undefined
-            const onSettled = chai.util.flag(assertion, '_poll.onSettled') as Function | undefined
+            const onStart = chai.util.flag(assertion, '_poll.onStart') as PollOnStart | undefined
+            const onSettled = chai.util.flag(assertion, '_poll.onSettled') as
+              | PollOnSettled
+              | undefined
             await onStart?.({ assertion })
 
             // We use `matcher.__vitest_poll_takeover__` flag
@@ -245,6 +255,36 @@ export function createExpectPoll(expect: ExpectStatic): ExpectStatic['poll'] {
   }
 }
 
+function setTraceHandlers(assertion: Assertion, test: Test) {
+  const attempt = getTraceAttempt(test)
+  if (!attempt) {
+    return
+  }
+  const rangeId = createTraceRangeId()
+  // TODO: compute the name once in `__VITEST_POLL_CHAIN__` and pass it to the hooks,
+  // so this and `getTraceName` in packages/browser/src/client/tester/expect-element.ts can share it
+  const getName = (assertion: Assertion) => {
+    const negated = chai.util.flag(assertion, 'negate') ? 'not.' : ''
+    return `expect.poll().${negated}${chai.util.flag(assertion, '_name')}()`
+  }
+  const onStart: PollOnStart = ({ assertion }) => {
+    recordTraceEntry(
+      attempt,
+      { name: getName(assertion), kind: 'expect', range: { id: rangeId, phase: 'start' } },
+      chai.util.flag(assertion, 'error'),
+    )
+  }
+  const onSettled: PollOnSettled = ({ assertion, status }) => {
+    recordTraceEntry(
+      attempt,
+      { name: getName(assertion), kind: 'expect', range: { id: rangeId, phase: 'end' }, status },
+      chai.util.flag(assertion, 'error'),
+    )
+  }
+  chai.util.flag(assertion, '_poll.onStart', onStart)
+  chai.util.flag(assertion, '_poll.onSettled', onSettled)
+}
+
 function raceWith<A, B>(
   promise: Promise<A>,
   other?: Promise<B>,

packages/vitest/src/integrations/wait.ts

@@ -1,4 +1,5 @@
 import { getSafeTimers } from '@vitest/utils/timers'
+import { startPromiseTraceRange } from '../runtime/trace-timeline'
 import { copyStackTrace } from '../utils/errors'
 import { vi } from './vi'
 
@@ -27,8 +28,9 @@ export function waitFor<T>(
   const { interval = 50, timeout = 1000 } =
     typeof options === 'number' ? { timeout: options } : options
   const STACK_TRACE_ERROR = new Error('STACK_TRACE_ERROR')
+  const trackPromise = startPromiseTraceRange('vi.waitFor()', STACK_TRACE_ERROR)
 
-  return new Promise<T>((resolve, reject) => {
+  const promise = new Promise<T>((resolve, reject) => {
     let lastError: unknown
     let promiseStatus: 'idle' | 'pending' | 'resolved' | 'rejected' = 'idle'
     let timeoutId: ReturnType<typeof setTimeout>
@@ -100,6 +102,7 @@ export function waitFor<T>(
     timeoutId = setTimeout(handleTimeout, timeout)
     intervalId = setInterval(checkCallback, interval)
   })
+  return trackPromise(promise)
 }
 
 export type WaitUntilCallback<T> = () => T | Promise<T>
@@ -116,8 +119,9 @@ export function waitUntil<T>(
   const { interval = 50, timeout = 1000 } =
     typeof options === 'number' ? { timeout: options } : options
   const STACK_TRACE_ERROR = new Error('STACK_TRACE_ERROR')
+  const trackPromise = startPromiseTraceRange('vi.waitUntil()', STACK_TRACE_ERROR)
 
-  return new Promise<Truthy<T>>((resolve, reject) => {
+  const promise = new Promise<Truthy<T>>((resolve, reject) => {
     let promiseStatus: 'idle' | 'pending' | 'resolved' | 'rejected' = 'idle'
     let timeoutId: ReturnType<typeof setTimeout>
     let intervalId: ReturnType<typeof setInterval>
@@ -190,4 +194,5 @@ export function waitUntil<T>(
     timeoutId = setTimeout(onReject, timeout)
     intervalId = setInterval(checkCallback, interval)
   })
+  return trackPromise(promise)
 }

packages/vitest/src/node/cli/cli-config.ts

@@ -957,6 +957,10 @@ export const cliOptionsConfig: VitestCLIOptions = {
         description:
           'Controls whether Vitest will use Node.js Loader API to process in-source or mocked files. This has no effect if `viteModuleRunner` is enabled. Disabling this can increase performance. (default: `true`)',
       },
+      traceTimeline: {
+        description:
+          'Record `expect.poll`, `vi.waitFor`, and `vi.waitUntil` steps of each test and print them as a timeline when the test fails. This has no effect in browser mode. (default: `false`)',
+      },
       vcsProvider: {
         argument: '<path>',
         description:

packages/vitest/src/node/config/serializeConfig.ts

@@ -148,6 +148,8 @@ export function serializeConfig(project: TestProject): SerializedConfig {
       viteModuleRunner: config.experimental.viteModuleRunner ?? true,
       nodeLoader: config.experimental.nodeLoader ?? true,
       recordDependencies: !!globalConfig.experimental.recordDependencies && !!globalConfig.cache,
+      // browser mode records its own trace through `browser.traceView`
+      traceTimeline: !!config.experimental.traceTimeline && !config.browser.enabled,
       openTelemetry: config.experimental.openTelemetry,
     },
     tags: config.tags || [],

packages/vitest/src/node/reporters/renderers/trace-timeline.ts

@@ -33,15 +33,18 @@ export function formatTraceTimeline(
   const rows = [headerRow, ...shown.map((step, i) => formatStep(step, prefixes[i], root))]
 
   const widths = headerRow.cells.map((_, i) => Math.max(...rows.map((row) => row.cells[i].length)))
+  const hasLocator = shown.some((step) => step.element?.locator)
   const lines = rows.map((row) => {
     // the last column is left unpadded so rows have no trailing spaces inside its color codes
     const [name, locator, start, duration, location] = row.cells.map((cell, i) =>
       i === 4 ? cell : i === 2 || i === 3 ? cell.padStart(widths[i]) : cell.padEnd(widths[i]),
     )
     if (row === headerRow) {
-      return c.dim(`  ${name}  ${locator}  ${start}  ${duration}  ${location}`)
+      const locatorColumn = hasLocator ? `${locator}  ` : ''
+      return c.dim(`  ${name}  ${locatorColumn}${start}  ${duration}  ${location}`)
     }
-    const text = `  ${name}  ${colorCell(locator, c.cyan)}  ${start}  ${colorCell(duration)}  ${colorCell(location, c.dim)}`
+    const locatorColumn = hasLocator ? `${colorCell(locator, c.cyan)}  ` : ''
+    const text = `  ${name}  ${locatorColumn}${start}  ${colorCell(duration)}  ${colorCell(location, c.dim)}`
     return row.status === 'fail' ? c.red(text) : text
   })
   const omitted = visible.length - shown.length
@@ -110,9 +113,10 @@ function formatStepName(name: string): string {
 // TODO: everything below is copied from `BrowserTraceData`/`BrowserTraceEntry` in
 // packages/browser/src/client/tester/trace.ts (only the fields used here) and
 // `getTraceAttemptMap` in packages/ui/client/composables/trace-view.ts.
-// share them instead (https://github.com/vitest-dev/vitest/pull/11604)
+// move the trace types to runtime/runner/types.ts, merge them with `TraceEntry` in
+// runtime/trace-timeline.ts, and share them with browser mode (https://github.com/vitest-dev/vitest/pull/11604)
 
-interface BrowserTraceData {
+export interface BrowserTraceData {
   retry: number
   repeats: number
   entries: BrowserTraceEntry[]
@@ -124,6 +128,7 @@ interface BrowserTraceEntry {
   status?: 'pass' | 'fail'
   startTime: number
   duration?: number
+  stack?: string
   location?: { file: string; line: number; column: number }
   element?: { locator: string }
 }

packages/vitest/src/node/test-run.ts

@@ -12,6 +12,7 @@ import type {
 import type { UserConsoleLog } from '../types/general'
 import type { Vitest } from './core'
 import type { TestProject } from './project'
+import type { BrowserTraceData } from './reporters/renderers/trace-timeline'
 import type {
   ReportedHookContext,
   TestCase,
@@ -26,7 +27,7 @@ import { existsSync, readFileSync } from 'node:fs'
 import { copyFile, mkdir, writeFile } from 'node:fs/promises'
 import { isPrimitive, sanitizeFilePath } from '@vitest/utils/helpers'
 import { serializeValue } from '@vitest/utils/serialize'
-import { parseErrorStacktrace } from '@vitest/utils/source-map'
+import { parseErrorStacktrace, parseStacktrace } from '@vitest/utils/source-map'
 import { extractSourcemapFromFile } from '@vitest/utils/source-map/node'
 import mime from 'mime/lite'
 import { basename, extname, resolve } from 'pathe'
@@ -95,6 +96,23 @@ export class TestRun {
       )
     }
 
+    // TODO: resolve browser trace locations here too, using `project.browser.parseStacktrace`
+    // like `syncUpdateStacks`, and drop the mapping in `__vitest_recordBrowserTrace`
+    if (artifact.type === 'internal:browserTrace' && testCase.task.file.pool !== 'browser') {
+      const { entries } = artifact.data as BrowserTraceData
+      for (const entry of entries) {
+        if (entry.stack && !entry.location) {
+          const [stack] = parseStacktrace(entry.stack, {
+            firstOnly: true,
+            getSourceMap: (file) => getExternalSourceMap(testCase.project, file),
+          })
+          if (stack) {
+            entry.location = { file: stack.file, line: stack.line, column: stack.column }
+          }
+        }
+      }
+    }
+
     testCase.task.artifacts.push(artifact)
 
     await this.vitest.report('onTestCaseArtifactRecord', testCase, artifact)
@@ -199,20 +217,7 @@ export class TestRun {
         } else {
           error.stacks = parseErrorStacktrace(error, {
             frameFilter: project.config.onStackTrace,
-            getSourceMap(file) {
-              // This only handles external modules since
-              // source map is already applied for inlined modules.
-              // Module node exists due to Vitest fetch module,
-              // but transformResult should be empty for external modules.
-              // TODO: this uses client module graph and thus miss detects
-              // inlined modules in ssr environment as if external.
-              const mod = project.vite.moduleGraph.getModuleById(file)
-              if (!mod?.transformResult && existsSync(file)) {
-                const code = readFileSync(file, 'utf-8')
-                const result = extractSourcemapFromFile(code, file)
-                return result?.map
-              }
-            },
+            getSourceMap: (file) => getExternalSourceMap(project, file),
           })
         }
       })
@@ -346,3 +351,18 @@ export class TestRun {
     }
   }
 }
+
+function getExternalSourceMap(project: TestProject, file: string) {
+  // This only handles external modules since
+  // source map is already applied for inlined modules.
+  // Module node exists due to Vitest fetch module,
+  // but transformResult should be empty for external modules.
+  // TODO: this uses client module graph and thus miss detects
+  // inlined modules in ssr environment as if external.
+  const mod = project.vite.moduleGraph.getModuleById(file)
+  if (!mod?.transformResult && existsSync(file)) {
+    const code = readFileSync(file, 'utf-8')
+    const result = extractSourcemapFromFile(code, file)
+    return result?.map
+  }
+}