From e4fe6f51a049a3da277d58c9aa285c9962b533a6 Mon Sep 17 00:00:00 2001 From: Vladimir Date: Fri, 31 May 2024 15:29:54 +0200 Subject: [PATCH] feat: add an option to print console stack trace (#5720) --- docs/config/index.md | 7 ++ packages/browser/src/client/logger.ts | 11 ++- packages/vitest/src/node/cli/cli-config.ts | 3 + packages/vitest/src/node/core.ts | 1 + packages/vitest/src/node/error.ts | 2 +- packages/vitest/src/node/reporters/base.ts | 30 +++++++- packages/vitest/src/node/workspace.ts | 1 + packages/vitest/src/runtime/console.ts | 89 ++++++++++++++++------ packages/vitest/src/types/config.ts | 8 ++ packages/vitest/src/types/general.ts | 2 + test/browser/specs/runner.test.ts | 37 +++++++-- test/browser/specs/utils.ts | 4 +- test/browser/test/logs.test.ts | 9 ++- test/browser/vitest.config.mts | 3 + test/cli/fixtures/console/trace.test.ts | 12 +++ test/cli/fixtures/console/vitest.config.ts | 7 ++ test/cli/test/console.test.ts | 79 +++++++++++++++++++ 17 files changed, 267 insertions(+), 38 deletions(-) create mode 100644 test/cli/fixtures/console/trace.test.ts create mode 100644 test/cli/fixtures/console/vitest.config.ts create mode 100644 test/cli/test/console.test.ts diff --git a/docs/config/index.md b/docs/config/index.md index 38c311ebf21a..41c09cefac76 100644 --- a/docs/config/index.md +++ b/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. diff --git a/packages/browser/src/client/logger.ts b/packages/browser/src/client/logger.ts index 5f761aef1e0a..9de7ea758c63 100644 --- a/packages/browser/src/client/logger.ts +++ b/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) } diff --git a/packages/vitest/src/node/cli/cli-config.ts b/packages/vitest/src/node/cli/cli-config.ts index e92924629e31..22e54dcea7d9 100644 --- a/packages/vitest/src/node/cli/cli-config.ts +++ b/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: { diff --git a/packages/vitest/src/node/core.ts b/packages/vitest/src/node/core.ts index 83a4d05948e8..1945102a9168 100644 --- a/packages/vitest/src/node/core.ts +++ b/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) => { diff --git a/packages/vitest/src/node/error.ts b/packages/vitest/src/node/error.ts index 64118194fb45..830068ab7c7a 100644 --- a/packages/vitest/src/node/error.ts +++ b/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[], diff --git a/packages/vitest/src/node/reporters/base.ts b/packages/vitest/src/node/reporters/base.ts index 3014c8ce6a83..64833476fff8 100644 --- a/packages/vitest/src/node/reporters/base.ts +++ b/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) + + 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`)) + } + } - // @ts-expect-error -- write() method has different signature on the union type - output.write(`${header}\n${log.content}\n`) + write('\n') } shouldLog(log: UserConsoleLog) { diff --git a/packages/vitest/src/node/workspace.ts b/packages/vitest/src/node/workspace.ts index 4b4500d37f41..bc7fe45e1e62 100644 --- a/packages/vitest/src/node/workspace.ts +++ b/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 } diff --git a/packages/vitest/src/runtime/console.ts b/packages/vitest/src/runtime/console.ts index 6158bf169e60..c7c71000704f 100644 --- a/packages/vitest/src/runtime/console.ts +++ b/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 || '', - 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 || '', 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() }, diff --git a/packages/vitest/src/types/config.ts b/packages/vitest/src/types/config.ts index 7a2cee668927..7d6ff75e8cf2 100644 --- a/packages/vitest/src/types/config.ts +++ b/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 diff --git a/packages/vitest/src/types/general.ts b/packages/vitest/src/types/general.ts index 3a8bf373657b..84aec6cada5d 100644 --- a/packages/vitest/src/types/general.ts +++ b/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 diff --git a/test/browser/specs/runner.test.ts b/test/browser/specs/runner.test.ts index 4db0b1111454..ce098cf900b8 100644 --- a/test/browser/specs/runner.test.ts +++ b/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
') 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.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()' + 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)/) }) diff --git a/test/browser/specs/utils.ts b/test/browser/specs/utils.ts index 4a58183d5c6f..4547f8986067 100644 --- a/test/browser/specs/utils.ts +++ b/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 & { browser?: Partial }, include?: string[]) { const result = await runVitest({ @@ -24,5 +24,5 @@ export async function runBrowserTests(config?: Omit & { b const passedTests = getPassed(browserResultJson.testResults) const failedTests = getFailed(browserResultJson.testResults) - return { ...result, browserResultJson, passedTests, failedTests } + return { ...result, browserResultJson, passedTests, failedTests, browser } } diff --git a/test/browser/test/logs.test.ts b/test/browser/test/logs.test.ts index c1377092b872..6bd985ade711 100644 --- a/test/browser/test/logs.test.ts +++ b/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') +}) diff --git a/test/browser/vitest.config.mts b/test/browser/vitest.config.mts index 950f229e07d6..c3bd055bbe0b 100644 --- a/test/browser/vitest.config.mts +++ b/test/browser/vitest.config.mts @@ -86,5 +86,8 @@ export default defineConfig({ onServerRestart: noop, onUserConsoleLog: noop, }, 'default'], + env: { + BROWSER: browser, + }, }, }) diff --git a/test/cli/fixtures/console/trace.test.ts b/test/cli/fixtures/console/trace.test.ts new file mode 100644 index 000000000000..ceebeb669e6b --- /dev/null +++ b/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') +}) diff --git a/test/cli/fixtures/console/vitest.config.ts b/test/cli/fixtures/console/vitest.config.ts new file mode 100644 index 000000000000..50db083eb436 --- /dev/null +++ b/test/cli/fixtures/console/vitest.config.ts @@ -0,0 +1,7 @@ +import { defineConfig } from 'vitest/config' + +export default defineConfig({ + test: { + printConsoleTrace: true, + } +}) \ No newline at end of file diff --git a/test/cli/test/console.test.ts b/test/cli/test/console.test.ts new file mode 100644 index 000000000000..ad0c4080d225 --- /dev/null +++ b/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'), '').replace(/\d+:\d+/g, 'ln:cl')).toMatchInlineSnapshot(` + "stderr | trace.test.ts > logging to stdout + Trace: trace with trace + at /test/cli/fixtures/console/trace.test.ts:ln:cl + at file:///packages/runner/dist/index.js:ln:cl + at file:///packages/runner/dist/index.js:ln:cl + at runTest (file:///packages/runner/dist/index.js:ln:cl) + at processTicksAndRejections (node:internal/process/task_queues:ln:cl) + + " + `) + } +})