feat: add an option to print console stack trace (#5720)

docs/config/index.md

@@ -2322,3 +2322,10 @@ Polling interval in milliseconds
 - **Default:** `1000`
 
 Polling timeout in milliseconds
+
+### printConsoleTrace
+
+- **Type:** `boolean`
+- **Default:** `false`
+
+Always print console traces when calling any `console` method. This is useful for debugging.

packages/browser/src/client/logger.ts

@@ -1,5 +1,5 @@
 import { rpc } from './rpc'
-import { importId } from './utils'
+import { getConfig, importId } from './utils'
 
 const { Date, console } = globalThis
 
@@ -12,14 +12,19 @@ export async function setupConsoleLogSpy() {
     return format(input)
   }
   const processLog = (args: unknown[]) => args.map(formatInput).join(' ')
-  const sendLog = (type: 'stdout' | 'stderr', content: string) => {
+  const sendLog = (type: 'stdout' | 'stderr', content: string, disableStack?: boolean) => {
     if (content.startsWith('[vite]'))
       return
     const unknownTestId = '__vitest__unknown_test__'
     // @ts-expect-error untyped global
     const taskId = globalThis.__vitest_worker__?.current?.id ?? unknownTestId
+    const origin = getConfig().printConsoleTrace && !disableStack
+      ? new Error('STACK_TRACE').stack?.split('\n').slice(1).join('\n')
+      : undefined
     rpc().sendLog({
+      origin,
       content,
+      browser: true,
       time: Date.now(),
       taskId,
       type,
@@ -58,7 +63,7 @@ export async function setupConsoleLogSpy() {
       .split('\n')
       .slice(error.stack?.includes('$$Trace') ? 2 : 1)
       .join('\n')
-    sendLog('stdout', `${content}\n${stack}`)
+    sendLog('stderr', `${content}\n${stack}`, true)
     return trace(...args)
   }
 

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

@@ -618,6 +618,9 @@ export const cliOptionsConfig: VitestCLIOptions = {
       return value
     },
   },
+  printConsoleTrace: {
+    description: 'Always print console stack traces',
+  },
 
   // CLI only options
   run: {

packages/vitest/src/node/core.ts

@@ -315,6 +315,7 @@ export class Vitest {
       'passWithNoTests',
       'bail',
       'isolate',
+      'printConsoleTrace',
     ] as const
 
     const cliOverrides = overridesOptions.reduce((acc, name) => {

packages/vitest/src/node/error.ts

@@ -260,7 +260,7 @@ function printErrorMessage(error: ErrorWithDiff, logger: Logger) {
   }
 }
 
-function printStack(
+export function printStack(
   logger: Logger,
   project: WorkspaceProject,
   stack: ParsedStack[],

packages/vitest/src/node/reporters/base.ts

@@ -1,9 +1,11 @@
 import { performance } from 'node:perf_hooks'
 import c from 'picocolors'
+import { parseStacktrace } from '@vitest/utils/source-map'
+import { relative } from 'pathe'
 import type { ErrorWithDiff, File, Reporter, Task, TaskResultPack, UserConsoleLog } from '../../types'
 import { getFullName, getSafeTimers, getSuites, getTests, hasFailed, hasFailedSnapshot, isCI, isNode, relativePath, toArray } from '../../utils'
 import type { Vitest } from '../../node'
-import { F_RIGHT } from '../../utils/figures'
+import { F_POINTER, F_RIGHT } from '../../utils/figures'
 import { UNKNOWN_TEST_ID } from '../../runtime/console'
 import { countTestErrors, divider, formatProjectName, formatTimeString, getStateString, getStateSymbol, pointer, renderSnapshotSummary } from './renderers/utils'
 
@@ -198,9 +200,31 @@ export abstract class BaseReporter implements Reporter {
     const header = c.gray(log.type + c.dim(` | ${task ? getFullName(task, c.dim(' > ')) : log.taskId !== UNKNOWN_TEST_ID ? log.taskId : 'unknown test'}`))
 
     const output = log.type === 'stdout' ? this.ctx.logger.outputStream : this.ctx.logger.errorStream
+    const write = (msg: string) => (output as any).write(msg)
 
-    // @ts-expect-error -- write() method has different signature on the union type
-    output.write(`${header}\n${log.content}\n`)
+    write(`${header}\n${log.content}`)
+
+    if (log.origin) {
+      // browser logs don't have an extra end of line at the end like Node.js does
+      if (log.browser)
+        write('\n')
+      const project = log.taskId
+        ? this.ctx.getProjectByTaskId(log.taskId)
+        : this.ctx.getCoreWorkspaceProject()
+      const stack = parseStacktrace(log.origin, {
+        getSourceMap: file => project.getBrowserSourceMapModuleById(file),
+        frameFilter: project.config.onStackTrace,
+      })
+      const highlight = task ? stack.find(i => i.file === task.file.filepath) : null
+      for (const frame of stack) {
+        const color = frame === highlight ? c.cyan : c.gray
+        const path = relative(project.config.root, frame.file)
+
+        write(color(` ${c.dim(F_POINTER)} ${[frame.method, `${path}:${c.dim(`${frame.line}:${frame.column}`)}`].filter(Boolean).join(' ')}\n`))
+      }
+    }
+
+    write('\n')
   }
 
   shouldLog(log: UserConsoleLog) {

packages/vitest/src/node/workspace.ts

@@ -397,6 +397,7 @@ export class WorkspaceProject {
         testerScripts: [],
         commands: {},
       },
+      printConsoleTrace: this.config.printConsoleTrace ?? this.ctx.config.printConsoleTrace,
     }, this.ctx.configOverride || {} as any) as ResolvedConfig
   }
 

packages/vitest/src/runtime/console.ts

@@ -54,36 +54,52 @@ export function createCustomConsole(defaultState?: WorkerGlobalState) {
     })
   }
   function sendStdout(taskId: string) {
-    const buffer = stdoutBuffer.get(taskId)
-    if (!buffer)
-      return
-    const content = buffer.map(i => String(i)).join('')
-    const timer = timers.get(taskId)!
-    state().rpc.onUserConsoleLog({
-      type: 'stdout',
-      content: content || '<empty line>',
-      taskId,
-      time: timer.stdoutTime || RealDate.now(),
-      size: buffer.length,
-    })
-    stdoutBuffer.set(taskId, [])
-    timer.stdoutTime = 0
+    sendBuffer('stdout', taskId)
   }
+
   function sendStderr(taskId: string) {
-    const buffer = stderrBuffer.get(taskId)
+    sendBuffer('stderr', taskId)
+  }
+
+  function sendBuffer(type: 'stdout' | 'stderr', taskId: string) {
+    const buffers = type === 'stdout' ? stdoutBuffer : stderrBuffer
+    const buffer = buffers.get(taskId)
     if (!buffer)
       return
-    const content = buffer.map(i => String(i)).join('')
+    if (state().config.printConsoleTrace) {
+      buffer.forEach(([buffer, origin]) => {
+        sendLog(type, taskId, String(buffer), buffer.length, origin)
+      })
+    }
+    else {
+      const content = buffer.map(i => String(i[0])).join('')
+      sendLog(type, taskId, content, buffer.length)
+    }
     const timer = timers.get(taskId)!
+    buffers.set(taskId, [])
+    if (type === 'stderr')
+      timer.stderrTime = 0
+    else
+      timer.stdoutTime = 0
+  }
+
+  function sendLog(
+    type: 'stderr' | 'stdout',
+    taskId: string,
+    content: string,
+    size: number,
+    origin?: string,
+  ) {
+    const timer = timers.get(taskId)!
+    const time = type === 'stderr' ? timer.stderrTime : timer.stdoutTime
     state().rpc.onUserConsoleLog({
-      type: 'stderr',
+      type,
       content: content || '<empty line>',
       taskId,
-      time: timer.stderrTime || RealDate.now(),
-      size: buffer.length,
+      time: time || RealDate.now(),
+      size,
+      origin,
     })
-    stderrBuffer.set(taskId, [])
-    timer.stderrTime = 0
   }
 
   const stdout = new Writable({
@@ -103,7 +119,17 @@ export function createCustomConsole(defaultState?: WorkerGlobalState) {
         buffer = []
         stdoutBuffer.set(id, buffer)
       }
-      buffer.push(data)
+      if (state().config.printConsoleTrace) {
+        const limit = Error.stackTraceLimit
+        Error.stackTraceLimit = limit + 6
+        const stack = new Error('STACK_TRACE').stack
+        const trace = stack?.split('\n').slice(7).join('\n')
+        Error.stackTraceLimit = limit
+        buffer.push([data, trace])
+      }
+      else {
+        buffer.push([data, undefined])
+      }
       schedule(id)
       callback()
     },
@@ -125,7 +151,24 @@ export function createCustomConsole(defaultState?: WorkerGlobalState) {
         buffer = []
         stderrBuffer.set(id, buffer)
       }
-      buffer.push(data)
+      if (state().config.printConsoleTrace) {
+        const limit = Error.stackTraceLimit
+        Error.stackTraceLimit = limit + 6
+        const stack = new Error('STACK_TRACE').stack?.split('\n')
+        Error.stackTraceLimit = limit
+        const isTrace = stack?.some(line => line.includes('at Console.trace'))
+        if (isTrace) {
+          buffer.push([data, undefined])
+        }
+        else {
+          const trace = stack?.slice(7).join('\n')
+          Error.stackTraceLimit = limit
+          buffer.push([data, trace])
+        }
+      }
+      else {
+        buffer.push([data, undefined])
+      }
       schedule(id)
       callback()
     },

packages/vitest/src/types/config.ts

@@ -765,6 +765,13 @@ export interface InlineConfig {
    */
   disableConsoleIntercept?: boolean
 
+  /**
+   * Always print console stack traces.
+   *
+   * @default false
+   */
+  printConsoleTrace?: boolean
+
   /**
    * Include "location" property inside the test definition
    *
@@ -1000,6 +1007,7 @@ export type RuntimeConfig = Pick<
   | 'fakeTimers'
   | 'maxConcurrency'
   | 'expect'
+  | 'printConsoleTrace'
 > & {
   sequence?: {
     concurrent?: boolean

packages/vitest/src/types/general.ts

@@ -35,6 +35,8 @@ export interface Environment {
 
 export interface UserConsoleLog {
   content: string
+  origin?: string
+  browser?: boolean
   type: 'stdout' | 'stderr'
   taskId?: string
   time: number

test/browser/specs/runner.test.ts

@@ -1,5 +1,5 @@
 import { beforeAll, describe, expect, onTestFailed, test } from 'vitest'
-import { runBrowserTests } from './utils'
+import { browser, runBrowserTests } from './utils'
 
 describe('running browser tests', async () => {
   let stderr: string
@@ -45,8 +45,6 @@ describe('running browser tests', async () => {
     expect(stdout).toContain('hello from console.debug')
     expect(stdout).toContain('{ hello: \'from dir\' }')
     expect(stdout).toContain('{ hello: \'from dirxml\' }')
-    // safari logs the stack files with @https://...
-    expect(stdout).toMatch(/hello from console.trace\s+(\w+|@)/)
     expect(stdout).toContain('dom <div />')
     expect(stdout).toContain('default: 1')
     expect(stdout).toContain('default: 2')
@@ -64,10 +62,39 @@ describe('running browser tests', async () => {
     expect(stderr).toContain('hello from console.warn')
     expect(stderr).toContain('Timer "invalid timeLog" does not exist')
     expect(stderr).toContain('Timer "invalid timeEnd" does not exist')
+    // safari logs the stack files with @https://...
+    expect(stderr).toMatch(/hello from console.trace\s+(\w+|@)/)
   })
 
-  test('stack trace points to correct file in every browser', () => {
-    // dependeing on the browser it references either '.toBe()' or 'expect()'
+  test.runIf(browser !== 'webkit')(`logs have stack traces in non-safari`, () => {
+    expect(stdout).toMatch(`
+log with a stack
+ ❯ test/logs.test.ts:58:10
+    `.trim())
+    expect(stderr).toMatch(`
+error with a stack
+ ❯ test/logs.test.ts:59:10
+    `.trim())
+    // console.trace doens't add additional stack trace
+    expect(stderr).not.toMatch('test/logs.test.ts:60:10')
+  })
+
+  test.runIf(browser === 'webkit')(`logs have stack traces in safari`, () => {
+    // safari print stack trace in a different place
+    expect(stdout).toMatch(`
+log with a stack
+ ❯ test/logs.test.ts:58:14
+    `.trim())
+    expect(stderr).toMatch(`
+error with a stack
+ ❯ test/logs.test.ts:59:16
+    `.trim())
+    // console.trace doens't add additional stack trace
+    expect(stderr).not.toMatch('test/logs.test.ts:60:16')
+  })
+
+  test(`stack trace points to correct file in every browser`, () => {
+    // dependeing on the browser it references either `.toBe()` or `expect()`
     expect(stderr).toMatch(/test\/failing.test.ts:4:(12|17)/)
   })
 

test/browser/specs/utils.ts

@@ -2,7 +2,7 @@ import { readFile } from 'node:fs/promises'
 import type { UserConfig } from 'vitest'
 import { runVitest } from '../../test-utils'
 
-const browser = process.env.BROWSER || (process.env.PROVIDER !== 'playwright' ? 'chromium' : 'chrome')
+export const browser = process.env.BROWSER || (process.env.PROVIDER !== 'playwright' ? 'chromium' : 'chrome')
 
 export async function runBrowserTests(config?: Omit<UserConfig, 'browser'> & { browser?: Partial<UserConfig['browser']> }, include?: string[]) {
   const result = await runVitest({
@@ -24,5 +24,5 @@ export async function runBrowserTests(config?: Omit<UserConfig, 'browser'> & { b
   const passedTests = getPassed(browserResultJson.testResults)
   const failedTests = getFailed(browserResultJson.testResults)
 
-  return { ...result, browserResultJson, passedTests, failedTests }
+  return { ...result, browserResultJson, passedTests, failedTests, browser }
 }

test/browser/test/logs.test.ts

@@ -1,5 +1,5 @@
 /* eslint-disable no-console */
-import { test } from 'vitest'
+import { test, vi } from 'vitest'
 
 test('logging to stdout', () => {
   console.log('hello from console.log')
@@ -52,3 +52,10 @@ test('logging invalid time', () => {
   console.timeLog('invalid timeLog')
   console.timeEnd('invalid timeEnd')
 })
+
+test('logging the stack', () => {
+  vi.setConfig({ printConsoleTrace: true })
+  console.log('log with a stack')
+  console.error('error with a stack')
+  console.trace('trace with a stack')
+})

test/browser/vitest.config.mts

@@ -86,5 +86,8 @@ export default defineConfig({
       onServerRestart: noop,
       onUserConsoleLog: noop,
     }, 'default'],
+    env: {
+      BROWSER: browser,
+    },
   },
 })

test/cli/fixtures/console/trace.test.ts

@@ -0,0 +1,12 @@
+import { test } from 'vitest';
+
+test('logging to stdout', () => {
+  console.log('log with trace')
+  console.info('info with trace')
+  console.debug('debug with trace')
+  console.dir({ hello: 'from dir with trace' })
+  console.warn('warn with trace')
+  console.assert(false, 'assert with trace')
+  console.error('error with trace')
+  console.trace('trace with trace')
+})

test/cli/fixtures/console/vitest.config.ts

@@ -0,0 +1,7 @@
+import { defineConfig } from 'vitest/config'
+
+export default defineConfig({
+  test: {
+    printConsoleTrace: true,
+  }
+})

test/cli/test/console.test.ts

@@ -0,0 +1,79 @@
+import { expect, test } from 'vitest'
+import { DefaultReporter } from 'vitest/reporters'
+import { resolve } from 'pathe'
+import { runVitest } from '../../test-utils'
+
+test('can run custom pools with Vitest', async () => {
+  const reporter = new DefaultReporter()
+  const vitest = await runVitest({
+    root: './fixtures/console',
+    reporters: [
+      {
+        onInit(ctx) {
+          reporter.onInit(ctx as any)
+        },
+        onUserConsoleLog(ctx) {
+          reporter.onUserConsoleLog(ctx)
+        },
+      },
+    ],
+  })
+  // removed the banner with version and timestamp
+  expect(vitest.stdout.split('\n').slice(2).join('\n')).toMatchInlineSnapshot(`
+    "
+    stdout | trace.test.ts > logging to stdout
+    log with trace
+     ❯ trace.test.ts:4:11
+
+    stdout | trace.test.ts > logging to stdout
+    info with trace
+     ❯ trace.test.ts:5:11
+
+    stdout | trace.test.ts > logging to stdout
+    debug with trace
+     ❯ trace.test.ts:6:11
+
+    stdout | trace.test.ts > logging to stdout
+    { hello: 'from dir with trace' }
+     ❯ trace.test.ts:7:11
+
+    "
+  `)
+  const stderrArray = vitest.stderr.split('\n')
+  // remove stack trace
+  const stderr = stderrArray.slice(0, -9).join('\n')
+  const stackStderr = stderrArray.slice(-9).join('\n')
+  expect(stderr).toMatchInlineSnapshot(`
+    "stderr | trace.test.ts > logging to stdout
+    warn with trace
+     ❯ trace.test.ts:8:11
+
+    stderr | trace.test.ts > logging to stdout
+    Assertion failed: assert with trace
+     ❯ trace.test.ts:9:11
+
+    stderr | trace.test.ts > logging to stdout
+    error with trace
+     ❯ trace.test.ts:10:11
+    "
+  `)
+  // shows built-in stack because we don't intercept it, but doesn't show the new one
+  expect(stackStderr).toMatch('Trace: trace with trace')
+  expect(stackStderr).toMatch('trace.test.ts:11:11')
+  expect(stackStderr).toMatch('   at ')
+  expect(stackStderr).not.toMatch('❯ ')
+  if (process.platform !== 'win32') {
+    const root = resolve(process.cwd(), '../..')
+    expect(stackStderr.replace(new RegExp(root, 'g'), '<root>').replace(/\d+:\d+/g, 'ln:cl')).toMatchInlineSnapshot(`
+      "stderr | trace.test.ts > logging to stdout
+      Trace: trace with trace
+          at <root>/test/cli/fixtures/console/trace.test.ts:ln:cl
+          at file://<root>/packages/runner/dist/index.js:ln:cl
+          at file://<root>/packages/runner/dist/index.js:ln:cl
+          at runTest (file://<root>/packages/runner/dist/index.js:ln:cl)
+          at processTicksAndRejections (node:internal/process/task_queues:ln:cl)
+
+      "
+    `)
+  }
+})