Pino: Doesn't work with pm2?

[ronag]

I can't see anything from pino when running through pm2 & pm2 logs?

[ronag]

Maybe related? https://github.com/pinojs/pino/pull/489

[mcollina]

Can you add an example program, and instructions to replicate the bug? I _think_ it is related, but I would prefer to check.

[mcollina]

I cannot replicate.

[ronag]

Archive.zip

Run

pm2 start ecosystem.json
pm2 logs test

You should see:

PINO
CONSOLE

But you will only see:

CONSOLE

[mcollina]

Logs are going into .pm2/pm2.log on my system, because that's where the file descriptor 1 is point to.

The problem is in pm2 that __overwrites process.stdout.write__ with its own function:

1|test   | function (string, encoding, cb) {
1|test   |         var log_data = null;
1|test   |         // Disable logs if specified
1|test   |         if (pm2_env.disable_logs === true) {
1|test   |           return cb ? cb() : false;
1|test   |         }
1|test   |         if (pm2_env.log_type && pm2_env.log_type === 'json') {
1|test   |           log_data = JSON.stringify({
1|test   |             message : string.toString(),
1|test   |             timestamp : pm2_env.log_date_format && moment ?
1|test   |               moment().format(pm2_env.log_date_format) : new Date().toISOString(),
1|test   |             type : 'out',
1|test   |             process_id : pm2_env.pm_id,
1|test   |             app_name : pm2_env.name
1|test   |           }) + '\n';
1|test   |         }
1|test   |         else if (pm2_env.log_date_format && moment)
1|test   |           log_data = moment().format(pm2_env.log_date_format) + ': ' + string.toString();
1|test   |         else
1|test   |           log_data = string.toString();
1|test   |         process.send({
1|test   |           type : 'log:out',
1|test   |           data : log_data
1|test   |         });
1|test   |         if (Utility.checkPathIsNull(pm2_env.pm_out_log_path) &&
1|test   |           (!pm2_env.pm_log_path || Utility.checkPathIsNull(pm2_env.pm_log_path)))
1|test   |           return cb ? cb() : null;
1|test   |         stds.std && stds.std.write && stds.std.write(log_data, encoding);
1|test   |         stds.out && stds.out.write && stds.out.write(log_data, encoding, cb);
1|test   |       }

@Unitech maybe pm2 should be doing its log routing differently instead of hijacking process.stdout.write?

[ronag]

@mcollina could we have an option to pino on whether to use sonic boom or not? i.e. same thing as we "auto detect" for aws lambda.

[kamesh95]

@mcollina @jsumners Is there any workaround for this? I am using pm2 in cluster mode and when I run pm2 logs, log streaming does not work, It's all blank. Although I am writing logs to a file using a different pino instance, but I would still like to stream via pm2 as well if possible.

[mcollina]

This should work fine in pm2, it was fixed in #493.

[kamesh95]

Well it does not seem to work then, See example below:

PM2 ecosystem.config.js

module.exports = {
  apps : [{
    name: 'Pino Application',
    script: './pino.js',
    instances: 2,
    autorestart: true,
    exec_mode:'cluster',
  }]
};

Pino script

const pino = require('pino');
const logger = pino({
  level: 'info'
}, pino.destination({
  minLength: 0,
  sync: false
}));

function main() {
  console.log('CONSOLE');
  logger.info('PINO');
  setInterval(main, 2000);
}

main();

[kamesh95]

Okay. so if I remove the second argumentpino.destination it works, but how to keep it asynchronous then?

[mcollina]

Okay. so if I remove the second argumentpino.destination it works, but how to keep it asynchronous then?

You can't. That is not compatible with pm2 as it modifies process.stdout.

[kamesh95]

Okay. makes sense. What are the tradeoffs then? As I see pino runs in a separate process, if I keep it synchronous then is there any noticeable impact on performance?

[mcollina]

As I see pino runs in a separate process, if I keep it synchronous then is there any noticeable impact on performance?

Yes there are unfortunately, and not just with pino. pm2 monkeypatches process.stdout adding some code to intercept the lines and send them to the parent process. As a result, logging will be measurably slower.

[kamesh95]

Hmm, anyways it's far far better than winston. I really like it. We were having memory issues in production with winston when logging under high load, I compared the performance with pino and the results were really amazing, the script I used to test consumed 1gb of memory in less then a matter of seconds for winston while pino was hovering around 20-30 mb with great speed. Thanks for this great module, should be a saviour for us with extreme logging in prod.

[jsumners]

My opinion: Pino's default configuration works with the standard Node core streams. As soon as the code is being run under an environment where those streams are mutated, it's all bets are off and outside of our support scope.

Really happy the Pino is helping you solve real problems, though.