Skip to content

Commit

Permalink
feat: add an option to print console stack trace (#5720)
Browse files Browse the repository at this point in the history
  • Loading branch information
sheremet-va authored May 31, 2024
1 parent fc53f56 commit e4fe6f5
Show file tree
Hide file tree
Showing 17 changed files with 267 additions and 38 deletions.
7 changes: 7 additions & 0 deletions docs/config/index.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.
11 changes: 8 additions & 3 deletions packages/browser/src/client/logger.ts
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
import { rpc } from './rpc'
import { importId } from './utils'
import { getConfig, importId } from './utils'

const { Date, console } = globalThis

Expand All @@ -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,
Expand Down Expand Up @@ -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)
}

Expand Down
3 changes: 3 additions & 0 deletions packages/vitest/src/node/cli/cli-config.ts
Original file line number Diff line number Diff line change
Expand Up @@ -618,6 +618,9 @@ export const cliOptionsConfig: VitestCLIOptions = {
return value
},
},
printConsoleTrace: {
description: 'Always print console stack traces',
},

// CLI only options
run: {
Expand Down
1 change: 1 addition & 0 deletions packages/vitest/src/node/core.ts
Original file line number Diff line number Diff line change
Expand Up @@ -315,6 +315,7 @@ export class Vitest {
'passWithNoTests',
'bail',
'isolate',
'printConsoleTrace',
] as const

const cliOverrides = overridesOptions.reduce((acc, name) => {
Expand Down
2 changes: 1 addition & 1 deletion packages/vitest/src/node/error.ts
Original file line number Diff line number Diff line change
Expand Up @@ -260,7 +260,7 @@ function printErrorMessage(error: ErrorWithDiff, logger: Logger) {
}
}

function printStack(
export function printStack(
logger: Logger,
project: WorkspaceProject,
stack: ParsedStack[],
Expand Down
30 changes: 27 additions & 3 deletions packages/vitest/src/node/reporters/base.ts
Original file line number Diff line number Diff line change
@@ -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'

Expand Down Expand Up @@ -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) {
Expand Down
1 change: 1 addition & 0 deletions packages/vitest/src/node/workspace.ts
Original file line number Diff line number Diff line change
Expand Up @@ -397,6 +397,7 @@ export class WorkspaceProject {
testerScripts: [],
commands: {},
},
printConsoleTrace: this.config.printConsoleTrace ?? this.ctx.config.printConsoleTrace,
}, this.ctx.configOverride || {} as any) as ResolvedConfig
}

Expand Down
89 changes: 66 additions & 23 deletions packages/vitest/src/runtime/console.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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({
Expand All @@ -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()
},
Expand All @@ -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()
},
Expand Down
8 changes: 8 additions & 0 deletions packages/vitest/src/types/config.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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
*
Expand Down Expand Up @@ -1000,6 +1007,7 @@ export type RuntimeConfig = Pick<
| 'fakeTimers'
| 'maxConcurrency'
| 'expect'
| 'printConsoleTrace'
> & {
sequence?: {
concurrent?: boolean
Expand Down
2 changes: 2 additions & 0 deletions packages/vitest/src/types/general.ts
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,8 @@ export interface Environment {

export interface UserConsoleLog {
content: string
origin?: string
browser?: boolean
type: 'stdout' | 'stderr'
taskId?: string
time: number
Expand Down
37 changes: 32 additions & 5 deletions test/browser/specs/runner.test.ts
Original file line number Diff line number Diff line change
@@ -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
Expand Down Expand Up @@ -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')
Expand All @@ -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)/)
})

Expand Down
4 changes: 2 additions & 2 deletions test/browser/specs/utils.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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({
Expand All @@ -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 }
}
9 changes: 8 additions & 1 deletion test/browser/test/logs.test.ts
Original file line number Diff line number Diff line change
@@ -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')
Expand Down Expand Up @@ -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')
})
3 changes: 3 additions & 0 deletions test/browser/vitest.config.mts
Original file line number Diff line number Diff line change
Expand Up @@ -86,5 +86,8 @@ export default defineConfig({
onServerRestart: noop,
onUserConsoleLog: noop,
}, 'default'],
env: {
BROWSER: browser,
},
},
})
12 changes: 12 additions & 0 deletions test/cli/fixtures/console/trace.test.ts
Original file line number Diff line number Diff line change
@@ -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')
})
Loading

0 comments on commit e4fe6f5

Please sign in to comment.