Logging inside process exit event?

[06000208]

Before migrating to pino, I used this pattern with various loggers:

process.on("exit", (code) => code == 0 ? console.log("Exiting peacefully") : console.error(`Exiting abnormally with code ${code}`));

This works correctly with pino with the defaults:

import pino from "pino";
import process from "node:process";
const log = pino();
log.info("hello world!");
process.on("exit", (code) => code == 0 ? log.info("Exiting peacefully") : log.fatal(`Exiting abnormally with code ${code}`));

{"level":30,"time":1649412627196,"pid":20108,"hostname":"pc","msg":"hello world!"}
{"level":30,"time":1649412627198,"pid":20108,"hostname":"pc","msg":"Exiting peacefully"}

However, when using a transport (such as pino/file), an error is thrown and the line isn't logged:

import pino from "pino";
import process from "node:process";
const log = pino({
    transport: {
        target: "pino/file",
        options: { destination: `${Date.now()}.log` },
    },
});
log.info("hello world!");
process.on("exit", (code) => code == 0 ? log.info("Exiting peacefully") : log.fatal(`Exiting abnormally with code ${code}`));

{"level":30,"time":1649413220294,"pid":15488,"hostname":"pc","msg":"hello world!"}

G:\example>node index
G:\example\node_modules\thread-stream\index.js:214
      throw new Error('the worker has exited')
      ^

Error: the worker has exited
    at ThreadStream.write (G:\example\node_modules\thread-stream\index.js:214:13)
    at Pino.write (G:\example\node_modules\pino\lib\proto.js:208:10)
    at Pino.LOG [as info] (G:\example\node_modules\pino\lib\tools.js:60:21)
    at process.<anonymous> (file:///G:/example/index.js:9:46)
    at process.emit (node:events:390:28)

I noticed pino.final() in the docs, but it's deprecated, and doesn't seem intended for this anyway.

Is there a way of logging from an exit event, or is this a bug/not possible?

[mcollina]

This is a good bug, the good news is that we can totally support it. The problem is in order for transports to work we need to add an exit handler ourselves... in which we close the worker. We might need to change the logic a bit to make sure pino exit handler is always the last.

[mcollina]

The bad news is that I might not have time to work on it.

[jsumners]

Is this the return of? #1075 (comment)

[mcollina]

Same feature, different implementation. The fix is in https://github.com/mcollina/on-exit-leak-free and we must make sure that the specified handler is always the last.

[msainiuk-bb]

I solved it in such way

const flushLogs = ({ logger }) =>
  new Promise((resolve) => {
    const symbol = Object.getOwnPropertySymbols(logger).find(
      (key) => String(key) === 'Symbol(pino.stream)',
    );
    const threadStream = logger[symbol];
    if (threadStream) {
      threadStream.flushSync();
      threadStream.end(resolve);
    } else {
      resolve(void 0);
    }
  });

but in my Nest.js code (works well in Koa project) it leads to throw new Error('the worker has exited')

[mcollina]

I debugged this.

The fundamental issue is that on-exit-leak-free listen to both 'beforeExit' and 'exit' and pino is closing the thread stream inside 'beforeExit'. By the time it reaches the 'exit' event, the stream is already closed.

I'm preparing a significant refactor inside on-exit-leak-free to have some APIs to handle this case.

[mcollina]

Here is the fix: #1474

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.