pino: Pino 5.8.1 fails to flush log on process exit

If I use process exit after a log the log entry is missing -

const pino = require('pino');
const logger = pino(pino.destination(1));

try {
	logger.info('start', pino.version);
	throw new Error('oops');
} catch (e) {
	logger.error(e);
	process.exit(1);
}
logger.info('end');

Expected Output -

{"level":30,"time":1541564755224,"msg":"start 5.8.1","pid":9237,"hostname":"dev","v":1}
{"level":50,"time":1541564755225,"msg":"oops","pid":9237,"hostname":"dev","type":"Error","stack":"Error: oops\n    at Object.<anonymous> (/test.js:7:8)\n    at Module._compile (internal/modules/cjs/loader.js:689:30)\n    at Object.Module._extensions..js (internal/modules/cjs/loader.js:700:10)\n    at Module.load (internal/modules/cjs/loader.js:599:32)\n    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)\n    at Function.Module._load (internal/modules/cjs/loader.js:530:3)\n    at Function.Module.runMain (internal/modules/cjs/loader.js:742:12)\n    at startup (internal/bootstrap/node.js:279:19)\n    at bootstrapNodeJSCore (internal/bootstrap/node.js:696:3)","v":1}

Actual output -

{"level":30,"time":1541564543106,"msg":"start 5.8.1","pid":9214,"hostname":"dev","v":1}

I also tried without setting the destination but result is the same. I think this might be a regression of https://github.com/pinojs/pino/issues/458 though I’m not sure if it worked on previous v5 versions

About this issue

Original URL
State: closed
Created 6 years ago
Comments: 20 (8 by maintainers)

Most upvoted comments

@mcollina docs are really not clear about this issue so I’m sure they can be improved.

But I feel this are all temporary hacks that are not good enough. First you need to have access to the destination in the code that triggers the exit. This is not only cumbersome and prone to errors, but in most complex apps the log will happen in a different area of the app than the code that actually calls the exit. So it is not really intuitive

I don’t know why log lose is acceptable in normal mode (documentation make it look like it is only an extreme mode and performance compromise). If it stays as is I think the only way to nicely solve this issue is to add a configuration for a minimum log level where every log above it also triggers flushSync automatically. The error level is probably a good default for this settings since we can assume that error and fatal messages will be followed by a process exit and a log you don’t want to lose. They are probably also a lot less common than other logs so the impact on performance will be less noticeable.

A user who need high performance can set the level to be higher than fatal (or even Infinity) and a user who cares about accurate logs can set it to 0 and flush on every log

yonjah on Nov 9, 2018