Pino: Best way to stream logs when using PM2

[robcalcroft]

We're wanting to deploy using PM2 and want to stream pino logs to a file in the most performant way possible. Is there a way of redirecting stdout to a file when using PM2 with Pino? Also what is the best way of streaming to a single file with Pino? Thanks 😄

[robcalcroft]

Found it: pino(fs.createWriteStream('./my-log')) can I suggest you document this feature in the getting started please 😄

[jsumners]

Yes, that is a way to write directly to a log file. But if you do it that way then you will not be able to rotate that log easily. That's Pino is written to use downstream transports, i.e. be piped into something to deal with the log lines.

I use PM2 in my environment. PM2 will by default write an application foo's logs to ~/.pm2/logs/foo-out.log. Making use of that fact, you can implement the logagent strategy described at the end of https://www.nearform.com/blog/sematext-guest-post-pino-fastest-node-js-logger-production/

[robcalcroft]

@jsumners Ok cool thanks for that. For pino is streaming to a file like in my example any different than streaming to stdout in terms of performance/event loop blocking?

[jsumners]

I want to say yes. But depending on the situation, it could be negligible. @mcollina or @davidmarkclements may have a better answer.

[robcalcroft]

@jsumners right ok, thanks 😄

[robcalcroft]

@mcollina @davidmarkclements hi guys @jsumners said you may have an idea of a definitive answer to my query about stream logging 😄

[jsumners]

Closing because I believe this has been answered as sufficiently as it will be.

[ad34]

https://www.nearform.com/blog/sematext-guest-post-pino-fastest-node-js-logger-production/ link is dead (404) I am trying to use pino.extreme() together with pm2 and I get no logs at all (it s working fine with pm2 + normal mode and fine without pm2 and extreme mode)

[davidmarkclements]

Can you provide a reproducible case?

On Mon, 26 Nov 2018 at 15:52, Ad34 [e-mail] wrote:

>

https://www.nearform.com/blog/sematext-guest-post-pino-fastest-node-js-logger-production/
link is dead (404) I am trying to use pino.extreme() together with pm2 and
I get no logs at all (it s working fine with pm2 + normal mode and fine
without pm2 and extreme mode)

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

[ad34]

const pinoLib = require("pino")

if (config.usePinoExtreme)
{
const dest = pinoLib.extreme()
pino = pinoLib(dest)
pino.info("Pino configured in extreme mode")
}

without extreme mode :

without pm2 : logs are sent to stdout
with pm2 : logs are sent to the pm2 pm_out_log_path

with extreme mode :

without pm2 : logs are sent to stdout
with pm2 : i get no logs at all . I have no idea where they are sent

[mcollina]

extreme mode is not supported with pm2 due how pm2 handle logs.
Would you mind sending a PR to our docs to add this caveat?

[ad34]

I tried to use the code suggested by @robcalcroft (fs.createWriteStream ) , but for some reason I only get the first logs. will try to understand why and I can found the issue, I will submit a PR. thanks

[iSkore]

+1 here and some more detail.

index.js

'use strict';

const
    http        = require( 'http' ),
    express     = require( 'express' ),
    pino        = require( 'pino' ),
    dest        = pino.extreme(),
    logger      = pino( dest ),
    expressPino = require( 'express-pino-logger' );


// asynchronously flush every 10 seconds to keep the buffer empty in periods of low activity
setInterval( () => logger.flush(), 10000 ).unref();

// use pino.final to create a special logger that guarantees final tick writes
const finalLog = pino.final( logger, ( err, finalLogger, evt ) => {
    if( err ) {
        finalLogger.error( err, 'error caused exit' );
    } else {
        finalLogger.info( `${ evt } caught` );
    }

    process.exit( err ? 1 : 0 );
} );

// catch all the ways node might exit
process
    .on( 'SIGINT', () => finalLog( null, 'SIGINT' ) )
    .on( 'SIGQUIT', () => finalLog( null, 'SIGQUIT' ) )
    .on( 'SIGTERM', () => finalLog( null, 'SIGTERM' ) )
    .on( 'uncaughtException', err => finalLog( err, 'uncaughtException' ) )
    .on( 'beforeExit', () => finalLog( null, 'beforeExit' ) )
    .on( 'exit', () => finalLog( null, 'exit' ) );

const app = express();

app.use( expressPino( { logger } ) );

app.get( '/', ( req, res ) => res.status( 200 ).send( 'hello world' ) );

const server = http.createServer( app );

server.listen( 3000, () => console.log( `Started on: ${ Date.now() }` ) );

1. Start index.js normally. No problems:

$ node index.js 
Started on: 1545424541468
{"level":30,"time":1545424543048,"msg":"request completed","pid":12470,"hostname":"MacBook-Pro.local","req":{"id":1,"method":"GET","url":"/","headers":{"host":"localhost:3000","user-agent":"curl/7.54.0","accept":"*/*"},"remoteAddress":"::1","remotePort":64597},"res":{"statusCode":200,"headers":{"x-powered-by":"Express","content-type":"text/html; charset=utf-8","content-length":"11","etag":"W/\"b-Kq5sNclPz7QV2+lfQIuc6R7oRu0\""}},"responseTime":5,"v":1}

1. Start index.js with PM2. No problems:

$ pm2 start index.js
[PM2] Starting pino-test/index.js in fork_mode (1 instance)
[PM2] Done.
┌──────────┬────┬─────────┬──────┬───────┬────────┬─────────┬────────┬─────┬──────────┬
│ App name │ id │ version │ mode │ pid   │ status │ restart │ uptime │ cpu │ mem      │
├──────────┼────┼─────────┼──────┼───────┼────────┼─────────┼────────┼─────┼──────────┼
│ index    │ 0  │ 0.0.0   │ fork │ 12475 │ online │ 0       │ 0s     │ 0%  │ 7.0 MB   │
└──────────┴────┴─────────┴──────┴───────┴────────┴─────────┴────────┴─────┴──────────┴


$ pm2 logs
~/.pm2/logs/index-out.log last 15 lines:
0|index    | Started on: 1545424645033
0|index    | {"level":30,"time":1545424649652,"msg":"request completed","pid":12475,"hostname":"MacBook-Pro.local","req":{"id":1,"method":"GET","url":"/","headers":{"host":"localhost:3000","user-agent":"curl/7.54.0","accept":"*/*"},"remoteAddress":"::1","remotePort":65030},"res":{"statusCode":200,"headers":{"x-powered-by":"Express","content-type":"text/html; charset=utf-8","content-length":"11","etag":"W/\"b-Kq5sNclPz7QV2+lfQIuc6R7oRu0\""}},"responseTime":5,"v":1}

1. Start index.js with PM2 in cluster mode:

$ pm2 start index.js -i 2
[PM2] Starting pino-test/index.js in cluster_mode (2 instances)
[PM2] Done.
┌──────────┬────┬─────────┬─────────┬───────┬────────┬─────────┬────────┬─────┬───────────┬
│ App name │ id │ version │ mode    │ pid   │ status │ restart │ uptime │ cpu │ mem       │
├──────────┼────┼─────────┼─────────┼───────┼────────┼─────────┼────────┼─────┼───────────┼
│ index    │ 0  │ 0.0.0   │ cluster │ 12540 │ online │ 0       │ 0s     │ 15% │ 27.4 MB   │
│ index    │ 1  │ 0.0.0   │ cluster │ 12541 │ online │ 0       │ 0s     │ 7%  │ 20.0 MB   │
└──────────┴────┴─────────┴─────────┴───────┴────────┴─────────┴────────┴─────┴───────────┴

$ pm2 logs
~/.pm2/logs/index-out-0.log last 15 lines:
0|index    | Started on: 1545424963175

~/.pm2/logs/index-out-1.log last 15 lines:
1|index    | Started on: 1545424963240

As you can see above in #3 - there are no logs after Started on.
It looks like it's not playing nicely with PM2 cluster mode

My guess is PM2's God overriding the process.stdout.write here and PM2's stream writer is causing problems for Pino's stream writer here

Thoughts?

[mcollina]

We should be protecting against this hijacks. What version of pino are you on?

[iSkore]

• pino v5.10.4 (I do not have it installed globally)
• @pm2/io v2.4.7 (locally)
• PM2 v3.2.2 (globally)

[mcollina]

Extreme mode does not work with pm2, mainly because pm2 tamper with process.stdout. Possibly we should throw badly in that case.