pinojs / pino-tee

🌲 tee pino logs into a file, with multiple levels
MIT License
89 stars 17 forks source link

Not working with Gracefull Shutdown #21

Closed lamualfa closed 3 years ago

lamualfa commented 3 years ago

Problem

I use node-graceful-shutdown to handle shutdown process. But, the log that are called from Shutdown Handler are not recorded in the log file. What's the solution?

Example code

import pino from 'pino'
import { onShutdown } from 'node-graceful-shutdown'

// Initialize the pino stream here as in README.md

const logger = pino({
  name: 'application'
}, streamConnectedToPinoTee)

onShutdown(async () => {
  // Works correctly
  console.log('Shutdown handler has been called')

  // Does not work
  logger.info('Application has been stopped')

  // Works correctly
  console.log('After logger.info called')
})

// Works correctly. The messages are recorded in the `info.log` file
logger.info('Starting application')

Output when the application is shut down

Shutdown handler has been called
After logger.info called

at first i thought the problem was with pino, but the following code works fine with pino-colada:

Code

import pino from 'pino'
import pinoColada from 'pino-colada'
import { onShutdown } from 'node-graceful-shutdown'

const logger = pino({
  name: 'application',
  prettifier: pinoColada,
  prettyPrint: true
})

onShutdown(async () => {
  // Works correctly
  console.log('Shutdown handler has been called')

  // Works correctly
  logger.info('Application has been stopped')

  // Works correctly
  console.log('After logger.info called')
})

// Works correctly
logger.info('Starting application')

Output

12:10:11 ✨ application Starting application

Output when the application is shut down

Shutdown handler has been called
12:10:12 ✨ application Application has been stopped
After logger.info called

Environment

jsumners commented 3 years ago

I believe you left out the most important part of your question: how streamConnectedToPinoTee is defined.

mcollina commented 3 years ago

Depending on how node-graceful-shutdown is implemented, it might not be possible to log anything inside that block as the process can only synchronously log. This is a current limit of using streams.. essentially you can't use pino-tee. We are planning to solve this in pino v7 with a new transport mechanism.

alexey-sh commented 4 months ago

pino is a big pain for graceful shutdown even with stdout dest