Best way to stream logs when using PM2
Closed this issue · 18 comments
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 😄
Found it: pino(fs.createWriteStream('./my-log')) can I suggest you document this feature in the getting started please 😄
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/
@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?
I want to say yes. But depending on the situation, it could be negligible. @mcollina or @davidmarkclements may have a better answer.
@jsumners right ok, thanks 😄
@mcollina @davidmarkclements hi guys @jsumners said you may have an idea of a definitive answer to my query about stream logging 😄
Closing because I believe this has been answered as sufficiently as it will be.
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)
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
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?
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
+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() }` ) );
- Start
index.jsnormally. 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}
- Start
index.jswith 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}
- Start
index.jswith 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?
We should be protecting against this hijacks. What version of pino are you on?
pinov5.10.4 (I do not have it installed globally)@pm2/iov2.4.7 (locally)- PM2 v3.2.2 (globally)
Extreme mode does not work with pm2, mainly because pm2 tamper with process.stdout. Possibly we should throw badly in that case.
Has this been solved
Has this been solved