Vitest swallows all pino output

[vekexasia]

Apparently all pino output is being swallowed by vitest.

I'd like to have pino use standard console.log (which is captured by vitest) when in test mode which is captured by vitest but i am unable to do so. Probably missing some pieces of how pino works.

[jsumners]

If you need to verify the final NDJSON of individual logs, you should supply a stream that collects the logs and then inspect that collection. See https://github.com/pinojs/pino/issues/1274#issuecomment-997971329.

[vekexasia]

If you need to verify the final NDJSON of individual logs, you should supply a stream that collects the logs and then inspect that collection. See #1274 (comment).

Thanks for your link @jsumners , I dont want to verify the final ndjson. i'd like to have stuff printed in console as they come

[jsumners]

I don't understand the issue. What is the problem with Pino?

[kibertoad]

@jsumners pino is asynchronous by default, so it doesn't log anything in pino context unless explicitly sync output is used. We should improve our documentation around that use-case

@vekexasia You need to enable sync mode, like this:

pino(
      pretty({
        sync: true,
        minimumLevel: level,
        colorize: true,
        translateTime: 'SYS:standard',
        ignore: 'hostname,pid',
      }),
    )

(I don't have an example without pino-pretty, but it should be pretty similar)

[elnygren]

Sync mode didn't work for me with vitest. However, this sure does:

import pino from 'pino'

let hooks: pino.LoggerOptions['hooks'] | undefined

if (process.env.NODE_ENV === 'test') {
  const { prettyFactory } = require('pino-pretty')
  const prettify = prettyFactory({ sync: true, colorize: true })
  hooks = {
    streamWrite: (s) => {
      console.log(prettify(s)) // Mirror to console.log during tests
      return s
    },
  }
}

export const logger = pino({
  level: process.env.LOG_LEVEL || 'info',
  hooks,
})

[ethrob]

Just came across this.

I'm also using Vitest and am doing capturing stdout and have my transport set to undefined. I guess you have yours set to console?:

describe('PinoLogger -- all logging methods (via getLogger)', () => {
    let writeSpy: ReturnType<typeof vi.spyOn>;
    beforeEach(() => {
        writeSpy = vi.spyOn(process.stdout, 'write').mockImplementation(() => true);
    });

    afterEach(() => {
        writeSpy.mockRestore();
    });

// more code below

And then capture that output like this:

logger.info(data, 'hi');

const actual = JSON.parse(writeSpy.mock.calls[0][0] as string);

[vladshcherbin]

@kibertoad is it different for pino/browser? any idea how to capture logs with it in Vitest? 🙏

I've had a couple attempts with no luck and out of ideas:

import pino from 'pino/browser.js'

export default pino({
  browser: { asObject: true, serialize: true }
})

attempts:

// does not catch anything
vi.spyOn(console, 'warn')

// does not catch anything
vi.spyOn(globalThis.console, 'warn')

// `write` update in logger doesn't catch anything
browser: { asObject: true, serialize: true, write: console.warn }

[nathanbowang]

I don't think Pino can work with Vitest without hacks. I’ve searched online, looked through the source code for configuration examples, but couldn’t get it to work as expected.

So for now, I’ve decided to use console.log instead. In Node I still use Pino, but in vitest I mock the logger and rely on console.log for synchronous output. I also remember that setting up Pino last time was a bit tricky for me — only the main-page configuration seemed to work reliably.

import type { Logger, LevelWithSilent } from 'pino'
import { prettyFactory } from 'pino-pretty'

const pretty = prettyFactory({
  colorize: true,
})

const levelMap: Record<LevelWithSilent, number> = {
  trace: 10,
  debug: 20,
  info: 30,
  warn: 40,
  error: 50,
  fatal: 60,
  silent: 100,
}

type Log = {
  msg: string
  [key: string]: unknown
}

function createLogger(level: LevelWithSilent, minLevel: LevelWithSilent) {
  return (log: Log) => {
    if (levelMap[level] < levelMap[minLevel]) return

    const line = {
      time: Date.now(),
      level: levelMap[level],
      ...log,
    }

    console.log(pretty(line))
  }
}

export function mockLogger(minLevel: LevelWithSilent = 'debug'): Logger {
  return {
    trace: createLogger('trace', minLevel),
    debug: createLogger('debug', minLevel),
    info: createLogger('info', minLevel),
    warn: createLogger('warn', minLevel),
    error: createLogger('error', minLevel),
    fatal: createLogger('fatal', minLevel),
    silent: createLogger('silent', minLevel),
  } as Logger
}