pm2
pm2 copied to clipboard
Unitech
Logs not working when app is ran in cluster mode
Hi, I have an app that generates logs of different types such as DEBUG, WARN, ERROR, etc.
For some reason, when the app is ran in exec_mode=cluster none of the logs show up in the log files.
This works as expected however when I run the app in fork mode.
I tried setting instances from max to 1 but did not work.
Also, I had installed pm2-syslog and although it should be related, I stopped it.
Any suggestions and/or workaround to solve this? Thanks in advance!
h3. pm2 report
===============================================================================
--- PM2 REPORT (Tue Oct 17 2017 21:23:34 GMT+0000 (UTC)) ----------------------
===============================================================================
--- Daemon -------------------------------------------------
pm2d version : 2.7.1
node version : 6.11.2
node path : /home/ubuntu/.nvm/versions/node/v6.11.2/bin/pm2
argv : /home/ubuntu/.nvm/versions/node/v6.11.2/bin/node,/home/ubuntu/.nvm/versions/node/v6.11.2/lib/node_modules/pm2/lib/Daemon.js
argv0 : node
user : ubuntu
uid : 1000
gid : 1000
uptime : 168min
===============================================================================
--- CLI ----------------------------------------------------
local pm2 : 2.7.1
node version : 6.11.2
node path : /home/ubuntu/.nvm/versions/node/v6.11.2/bin/pm2
argv : /home/ubuntu/.nvm/versions/node/v6.11.2/bin/node,/home/ubuntu/.nvm/versions/node/v6.11.2/bin/pm2,report
argv0 : node
user : ubuntu
uid : 1000
gid : 1000
===============================================================================
--- System info --------------------------------------------
arch : x64
platform : linux
type : Linux
cpus : Intel(R) Xeon(R) CPU E5-2676 v3 @ 2.40GHz
cpus nb : 2
freemem : 1531846656
totalmem : 4142292992
home : /home/ubuntu
===============================================================================
--- PM2 list -----------------------------------------------
┌───────────────────┬────┬─────────┬───────┬────────┬─────────┬────────┬─────┬────────────┬────────┬──────────┐
│ App name │ id │ mode │ pid │ status │ restart │ uptime │ cpu │ mem │ user │ watching │
├───────────────────┼────┼─────────┼───────┼────────┼─────────┼────────┼─────┼────────────┼────────┼──────────┤
│ Node Cron Workers │ 7 │ fork │ 22739 │ online │ 0 │ 9m │ 0% │ 119.3 MB │ ubuntu │ disabled │
│ Node Web Server │ 6 │ cluster │ 22733 │ online │ 0 │ 9m │ 0% │ 172.4 MB │ ubuntu │ disabled │
└───────────────────┴────┴─────────┴───────┴────────┴─────────┴────────┴─────┴────────────┴────────┴──────────┘
Module activated
┌────────────┬─────────┬────────────┬─────────┬─────────┬─────┬────────┬────────┐
│ Module │ version │ target PID │ status │ restart │ cpu │ memory │ user │
├────────────┼─────────┼────────────┼─────────┼─────────┼─────┼────────┼────────┤
│ pm2-syslog │ 2.7.1 │ N/A │ stopped │ 0 │ 0% │ 0 B │ ubuntu │
└────────────┴─────────┴────────────┴─────────┴─────────┴─────┴────────┴────────┘
===============================================================================
--- Daemon logs --------------------------------------------
┌───────────────────┬────┬─────────┬───────┬────────┬─────────┬────────┬─────┬────────────┬────────┬──────────┐
│ App name │ id │ mode │ pid │ status │ restart │ uptime │ cpu │ mem │ user │ watching │
├───────────────────┼────┼─────────┼───────┼────────┼─────────┼────────┼─────┼────────────┼────────┼──────────┤
│ Node Cron Workers │ 7 │ fork │ 22739 │ online │ 0 │ 9m │ 0% │ 119.3 MB │ ubuntu │ disabled │
│ Node Web Server │ 6 │ cluster │ 22733 │ online │ 0 │ 9m │ 0% │ 172.4 MB │ ubuntu │ disabled │
└───────────────────┴────┴─────────┴───────┴────────┴─────────┴────────┴─────┴────────────┴────────┴──────────┘
Module activated
┌────────────┬─────────┬────────────┬─────────┬─────────┬─────┬────────┬────────┐
│ Module │ version │ target PID │ status │ restart │ cpu │ memory │ user │
├────────────┼─────────┼────────────┼─────────┼─────────┼─────┼────────┼────────┤
│ pm2-syslog │ 2.7.1 │ N/A │ stopped │ 0 │ 0% │ 0 B │ ubuntu │
└────────────┴─────────┴────────────┴─────────┴─────────┴─────┴────────┴────────┘
Could you make a little example that replicate the problem ? Also which log framework are you using ?
Sure @vmarchaud! I'm using log4js
To simplify things I created a project with the following files:
package.json
{
"name": "pm2-logging-test",
"version": "1.0.0",
"description": "Test if logs work with pm2 in cluster mode",
"main": "index.js",
"scripts": {
"start": "node index.js",
"test": "echo \"Error: no test specified\" && exit 1"
},
"author": "Sebastian Ricaldoni",
"license": "ISC",
"dependencies": {
"express": "^4.16.2",
"log4js": "^2.3.7"
}
}
index.js
const express = require('express');
const log4js = require('log4js');
const app = express();
var logger = log4js.getLogger();
logger.level = 'debug';
app.get('/', (req, res) => {
logger.debug('Running default endpoint');
res.send('Hello World!');
});
app.listen(3000, ()=>{
logger.debug('App started on port 3000!');
})
pm2-cluster.yml
apps:
- script : index.js
instances : max
exec_mode : cluster
pm2-fork.yml
apps:
- script : index.js
instances : 1
exec_mode : fork
Output running pm2 with pm2 start pm2-cluster.yml
sebs@MacBook-Pro ~/temp/celled/pm2-logging-test $ pm2 logs
[TAILING] Tailing last 15 lines for [all] processes (change the value with --lines option)
/Users/sebs/.pm2/pm2.log last 15 lines:
PM2 | 2017-10-19 11:03:41: App name:index id:0 online
PM2 | 2017-10-19 11:03:41: Starting execution sequence in -cluster mode- for app name:index id:1
PM2 | 2017-10-19 11:03:41: App name:index id:1 online
PM2 | 2017-10-19 11:03:41: Starting execution sequence in -cluster mode- for app name:index id:2
PM2 | 2017-10-19 11:03:41: App name:index id:2 online
PM2 | 2017-10-19 11:03:41: Starting execution sequence in -cluster mode- for app name:index id:3
PM2 | 2017-10-19 11:03:41: App name:index id:3 online
PM2 | 2017-10-19 11:03:41: Starting execution sequence in -cluster mode- for app name:index id:4
PM2 | 2017-10-19 11:03:41: App name:index id:4 online
PM2 | 2017-10-19 11:03:41: Starting execution sequence in -cluster mode- for app name:index id:5
PM2 | 2017-10-19 11:03:41: App name:index id:5 online
PM2 | 2017-10-19 11:03:41: Starting execution sequence in -cluster mode- for app name:index id:6
PM2 | 2017-10-19 11:03:41: App name:index id:6 online
PM2 | 2017-10-19 11:03:41: Starting execution sequence in -cluster mode- for app name:index id:7
PM2 | 2017-10-19 11:03:41: App name:index id:7 online
/Users/sebs/.pm2/logs/index-out-4.log last 15 lines:
/Users/sebs/.pm2/logs/index-out-0.log last 15 lines:
/Users/sebs/.pm2/logs/index-out-1.log last 15 lines:
/Users/sebs/.pm2/logs/index-error-1.log last 15 lines:
/Users/sebs/.pm2/logs/index-out-2.log last 15 lines:
/Users/sebs/.pm2/logs/index-error-2.log last 15 lines:
/Users/sebs/.pm2/logs/index-out-3.log last 15 lines:
/Users/sebs/.pm2/logs/index-error-3.log last 15 lines:
/Users/sebs/.pm2/logs/index-error-0.log last 15 lines:
/Users/sebs/.pm2/logs/index-error-4.log last 15 lines:
/Users/sebs/.pm2/logs/index-out-5.log last 15 lines:
/Users/sebs/.pm2/logs/index-error-5.log last 15 lines:
/Users/sebs/.pm2/logs/index-out-6.log last 15 lines:
/Users/sebs/.pm2/logs/index-error-6.log last 15 lines:
/Users/sebs/.pm2/logs/index-out-7.log last 15 lines:
/Users/sebs/.pm2/logs/index-error-7.log last 15 lines:
^C
NOTE: I'm not seeing any of my logged messages
Output running pm2 with pm2 start pm2-fork.yml
sebs@MacBook-Pro ~/temp/celled/pm2-logging-test $ pm2 start pm2-fork.yml
[PM2][WARN] Applications index not running, starting...
[PM2] App [index] launched (1 instances)
┌──────────┬────┬──────┬───────┬────────┬─────────┬────────┬─────┬───────────┬──────┬──────────┐
│ App name │ id │ mode │ pid │ status │ restart │ uptime │ cpu │ mem │ user │ watching │
├──────────┼────┼──────┼───────┼────────┼─────────┼────────┼─────┼───────────┼──────┼──────────┤
│ index │ 0 │ fork │ 63834 │ online │ 0 │ 0s │ 0% │ 11.2 MB │ sebs │ disabled │
└──────────┴────┴──────┴───────┴────────┴─────────┴────────┴─────┴───────────┴──────┴──────────┘
Use `pm2 show <id|name>` to get more details about an app
sebs@MacBook-Pro ~/temp/celled/pm2-logging-test $ pm2 logs
[TAILING] Tailing last 15 lines for [all] processes (change the value with --lines option)
/Users/sebs/.pm2/pm2.log last 15 lines:
PM2 | 2017-10-19 11:06:02: Starting execution sequence in -fork mode- for app name:index id:0
PM2 | 2017-10-19 11:06:02: App name:index id:0 online
/Users/sebs/.pm2/logs/index-error-0.log last 15 lines:
/Users/sebs/.pm2/logs/index-out-0.log last 15 lines:
0|index | [2017-10-19 11:06:02.921] [DEBUG] default - App started on port 3000!
0|index | [2017-10-19 11:06:25.385] [DEBUG] default - Running default endpoint
NOTE: In this case I do see my logged messages...take a look at the last 2 lines
Any help would be much appreciated!! Thanks!! Seb
The difference between cluster and fork is that with the cluster we need to override the few methods to redirect the logs, see these lines. I suspect that log4js doesn't actually broadcast log to process.stderr.write one way or another
I am seeing the same problem. Log4js & pm2 & cluster.
The log4js stdout appender appears to be calling process.stdout.write ... here
From what I can tell:
- It is definitely an issue that only manifests itself in cluster mode...
- Doesnt matter if I use stdout or stderr appender.
Looks like it does not enter in this method: https://github.com/Unitech/pm2/blob/master/lib/ProcessContainer.js#L200
log4js.configure({
appenders: { out: { type: 'stdout'}},
categories: { default: { appenders: ['out'], level: 'info'}},
disableClustering: true
})
I was having the same problem in both scenarios (cluster and fork) and the root cause was a zombie pm2 process ("PM2 v3.2.1: God Daemon"). I just killed it and now everything is working fine.
ps -ef | grep PM2
All logs are being written to pm2.log Command used to start process: pm2 start -i 0 npm -- start
There is lot of unclear discussions regarding pm2 cluster with log4js.
As for my current investigation it seems that the pm2-intercom is not needed. When using new version of log4js (5.2.2) the only required settings are:
const log4js = require('log4js').configure
(
{
appenders: {
app: {
type: 'file',
filename: './log4js.log'
}
},
categories: {
default: { appenders: [ 'app'], level: 'DEBUG' }
},
pm2: true,
disableClustering: true
}
);
I have tested by running 6 pm2 cluster nodes and ran 30 parallel jmeter workers to check whether any of the logs get lost. By comparing with the pm2 log (this is assumed to be cluster safe), I can see the log entries are identical.
Here the complete test app:
"use strict";
const log4js = require('log4js').configure
(
{
appenders: {
app: {
type: 'file',
filename: './log4js.log'
}
},
categories: {
default: { appenders: [ 'app'], level: 'DEBUG' }
},
pm2: true,
disableClustering: true
}
);
const express = require('express')
const app = express()
const port = 8075;
const instanceID = process.env.NODE_APP_INSTANCE;
const logger = log4js.getLogger();
logger.info('Start worker ' + instanceID);
console.log('Start worker ' + instanceID);
let logit = function(req) {
let s = 'received requestID: ' + req.query.id + ' / worker: ' + instanceID;
logger.info(s);
console.log(s);
}
app.get('/a', (req, res) => {
res.send('Hello World! Here A with received requestID: ' + req.query.id + 'worker: ' + instanceID);
logit(req);
}
);
app.get('/b', (req, res) => {
res.send('Hello World! Here B with received requestID: ' + req.query.id + 'worker: ' + instanceID);
logit(req);
}
);
app.listen(port, () => {
let s = `Cluster app listening on port ${port}!`;
logger.info(s);
console.log(s);
});
We are experiencing the same issue. When running PM2 in cluster mode no logs what so ever :(
any plans to fix this issue? im using winston logger and not log4j, so no workaround for me
I'm experiencing the same problem.
PM2: 4.5.6 Winston: 3.3.3 OS: Centos 7
It seems like the environment variables/config settings are not being used. Instead of writing to the specified log locations the logs are being written to pm2.log and there are no dates being added even when specified in the config.
When running the command pm2 show <name> I get the correct locations for out log path and error log path. It just isn't writing to those locations.
The same thing for pm2 env 0 the log_date_format is set to YYYY-MM-DD HH:mm Z
@brayden-bcgsc do you have a workaround for this?
I'm using pm2 for an in-house app where scalability is not a huge concern at the moment, so I personally just swapped back to forked mode for the time being.
I HAVE NOT TESTED THIS If you are also using winston, I would assume you could just set the transports in winston to the location of the files you want to use for the output and error logs. This isn't a great solution and will probably only be useful to a select few, if it works correctly.
it looks like it still hasn't been solved as I'm having the same issue, is logs4j included by default with pm2 ?
I have the same issue, I'm running yarn start and the logs don't show if I set cluster mode. Works fine on fork mode.
Having the same issue when running in cluster mode. Any workaround for this?
Long story short
the nodejs utils debuglog doesn't work if process is runned with pm2 config with instances param set but no exec_mode set.
Details and tests Script envtest.js
const debug = require('util').debuglog('debug')
console.log('process.env.NODE_DEBUG', process.env.NODE_DEBUG)
console.log('debug.enabled', debug.enabled)
debug('test 123')
PM2 config - test.json
{
"apps": [
{
"name": "envtest",
"script": "envtest.js",
"kill_timeout": 15000,
"log_date_format": "YYYY-MM-DD HH:mm:ss Z",
"args": [],
"watch": false,
"autorestart": false,
"merge_logs": true,
"cwd": "./",
"instances": 1,
"exec_mode": "fork",
"error_file": "./log/envtest-err.log",
"out_file": "./log/envtest-out.log",
"env": {
"NODE_ENV": "development",
"NODE_DEBUG": "debug"
},
"pid_file": "./tmp/envtest.pid"
}
]
}
Output of pm2 kill && pm2 start test.json && pm2 logs
1|envtest | process.env.NODE_DEBUG debug
1|envtest | debug.enabled true
1|envtest | DEBUG 30443: test 123
So all good, now i just remove the "exec_mode": "fork", from pm2 config and do the same.
Output of pm2 kill && pm2 start test.json && pm2 logs
1|envtest | process.env.NODE_DEBUG debug
1|envtest | debug.enabled false
Which is wrong, the debug should be logged regardless.
Now i just remove the "instances": "1, from pm2 config and do the same.
Output of pm2 kill && pm2 start test.json && pm2 logs
1|envtest | process.env.NODE_DEBUG debug
1|envtest | debug.enabled true
1|envtest | DEBUG 30443: test 123
