Pino: Pino 5.8.1 fails to flush log on process exit

[yonjah]

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

[brandondoran]

I am running into this as well. I added console.logs, which i see output for, but not for the pino logs. This is code I ported directly over from bunyan, where it was working. I've tried calling flush but that did not help. I'm not using extreme mode. I've tried not specifying destination but also using pino.destination(1) but neither flush stdout.

If I put a 100 ms delay before the process.exit, then and I do see the logs.

[yonjah]

@brandondoran I found that using pino.final logger with some random log message will force the logs to be flushed.
It's a bit awkward to use but it's probably more reliable as a temporary fix than delaying the exit call

[mcollina]

What you can do is:

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

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

[mcollina]

I think this should be emphazised in the docs. Would you like to send a PR?

Logs are properly flushed when the process normally exists, but in case of an synchronous, abrupt end, you'll need to use pino.final or dest.flushSync(). pino.final is just a convenience wrapper around flushSync.

[yonjah]

@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

[brandondoran]

@mcollina thanks for pointing out that code.

I ended up getting the logs to show up using pino.final but it was a bit of journey to get there. I was creating my logger with some options like:

const logger = pino(options, pino.destination(1));

But then when I tried to use pino.final it was throwing an error because the destination wasn't an SonicBoom instance. After some debugging I figured out the destination was getting ignored in the createArgsNormalizer function. I then realized I was on an older version (5.6.2). Once I upgraded to the latest that problem was solved and final did not throw. However, I still was seeing my logs from final logger.

I added a delay in the code before the exit and then I got some error messages from pino around calling flush with prettyPrint option enabled. Once I disabled that, I can see my logs flushed to stdout.

[pies]

My solution was to use:

setTimeout(() => {
   process.exit(0);
}, 100);

[zyf0330]

@pies I use this code now, but I don't think it is a good idea.

[mcollina]

I'm working to add sync mode to sonic-boom: https://github.com/mcollina/sonic-boom/pull/21.

[zyf0330]

I cannot find these commits in pino v5.10.0 npm package, have you release correct code?

[ajkaushik]

I can confirm that issue is still present in v5.10.0.

[zyf0330]

@ajkaushik Yes, npm package v5.10.0 doesn't contain this fix. If you install from this git repo branch master, you can verify it has been fixed.
It is strange.

[ajkaushik]

@zyf0330 Thanks for the information, but I am about to make pino as one of my production dependency. And would like to use correct version from npm itself.

@mcollina Hey would you have any update on this or pointers to any optional flag we need to turn on?

[zyf0330]

I believe this is just a mistake. And we can wait fix.

On Wed, Dec 12, 2018, 13:10 Ajay Kaushik <[email protected] wrote:

@zyf0330 https://github.com/zyf0330 Thanks for the information, but I
am about to make pino as one of my production dependency. And would like to
use correct version from npm itself.

@mcollina https://github.com/mcollina Hey would you have any update on
this or pointers to any optional flag we need to turn on?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/pinojs/pino/issues/542#issuecomment-446464113, or mute
the thread
https://github.com/notifications/unsubscribe-auth/ALZ5gQW0QrAVGULOvy6YiHUyp9WcAAeCks5u4I-4gaJpZM4YRxLt
.

[mcollina]

Yes it was a mistake (cc @davidmarkclements :P).

Released as v5.10.1. I unpublished v5.10.0.

[zyf0330]

@mcollina Can you share this mistake, because I cannot image how it happened? Thanks!

[mcollina]

@davidmarkclements did not do any pull before releasing.

[ajkaushik]

Thanks for the update, I can confirm that behavior is as expected in v5.10.1 and logs are getting flushed correctly.