Logs not working when app is ran in cluster mode #3215

sebastianricaldoni · 2017-10-17T21:27:55Z

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 │
└────────────┴─────────┴────────────┴─────────┴─────────┴─────┴────────┴────────┘

The text was updated successfully, but these errors were encountered:

vmarchaud · 2017-10-18T09:07:40Z

Could you make a little example that replicate the problem ? Also which log framework are you using ?

sebastianricaldoni · 2017-10-19T14:16:49Z

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

vmarchaud · 2017-10-22T11:24:01Z

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

nickminutello · 2018-01-18T17:00:08Z

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.

singla96 · 2018-10-03T15:29:39Z

Same problem. Morgan and pm2 cluster. works fine in fork
pm2@3.1.3

Unitech · 2018-10-03T16:13:25Z

Looks like it does not enter in this method: https://github.com/Unitech/pm2/blob/master/lib/ProcessContainer.js#L200

Unitech · 2018-10-03T16:29:23Z

log4js.configure({
  appenders: { out: { type: 'stdout'}},
  categories: { default: { appenders: ['out'], level: 'info'}},
  disableClustering: true                                                                                                                                                                                                                                       
})

rogerweb · 2018-10-04T22:07:31Z

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

singla96 · 2018-10-13T12:30:15Z

All logs are being written to pm2.log
Command used to start process: pm2 start -i 0 npm -- start

praveenax · 2019-05-24T05:53:57Z

Can I know, when this is going to be fixed?

ziimakc · 2019-05-24T08:39:10Z

@praveenax when someone will do PR, go ahead :)

ghost · 2019-10-18T15:12:27Z

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);
});

DNRN · 2020-10-28T13:40:11Z

We are experiencing the same issue.
When running PM2 in cluster mode no logs what so ever :(

barakseri1 · 2021-01-11T10:28:27Z

any plans to fix this issue?
im using winston logger and not log4j, so no workaround for me

brayden-bcgsc · 2021-09-07T16:40:45Z

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

eder-chamale · 2021-09-24T23:37:06Z

@brayden-bcgsc do you have a workaround for this?

brayden-bcgsc · 2021-10-04T16:22:42Z

@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.

BaptisteGarcin · 2023-01-06T00:04:56Z

it looks like it still hasn't been solved as I'm having the same issue, is logs4j included by default with pm2 ?

afonsomatos · 2023-06-30T07:28:09Z

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.

joaofrsilva · 2023-08-02T21:07:38Z

Having the same issue when running in cluster mode. Any workaround for this?

crazyfree · 2023-08-24T02:12:43Z

+1 just got experience with this

utkarshdeep · 2023-11-21T11:33:04Z

Has this issue been resolved?

AndreaFranchini · 2024-04-09T12:25:20Z

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

vmarchaud added the S: Need More Data label Oct 18, 2017

vmarchaud added S: Open for PR SYS : Log T: Bug and removed S: Need More Data labels Oct 22, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logs not working when app is ran in cluster mode #3215

Logs not working when app is ran in cluster mode #3215

sebastianricaldoni commented Oct 17, 2017

vmarchaud commented Oct 18, 2017

sebastianricaldoni commented Oct 19, 2017

vmarchaud commented Oct 22, 2017

nickminutello commented Jan 18, 2018

singla96 commented Oct 3, 2018

Unitech commented Oct 3, 2018

Unitech commented Oct 3, 2018 •

edited

Loading

rogerweb commented Oct 4, 2018

singla96 commented Oct 13, 2018

praveenax commented May 24, 2019

ziimakc commented May 24, 2019

ghost commented Oct 18, 2019 •

edited by ghost

Loading

DNRN commented Oct 28, 2020

barakseri1 commented Jan 11, 2021

brayden-bcgsc commented Sep 7, 2021

eder-chamale commented Sep 24, 2021 •

edited

Loading

brayden-bcgsc commented Oct 4, 2021

BaptisteGarcin commented Jan 6, 2023

afonsomatos commented Jun 30, 2023

joaofrsilva commented Aug 2, 2023

crazyfree commented Aug 24, 2023

utkarshdeep commented Nov 21, 2023

AndreaFranchini commented Apr 9, 2024

Logs not working when app is ran in cluster mode #3215

Logs not working when app is ran in cluster mode #3215

Comments

sebastianricaldoni commented Oct 17, 2017

vmarchaud commented Oct 18, 2017

sebastianricaldoni commented Oct 19, 2017

package.json

index.js

pm2-cluster.yml

pm2-fork.yml

Output running pm2 with pm2 start pm2-cluster.yml

Output running pm2 with pm2 start pm2-fork.yml

vmarchaud commented Oct 22, 2017

nickminutello commented Jan 18, 2018

singla96 commented Oct 3, 2018

Unitech commented Oct 3, 2018

Unitech commented Oct 3, 2018 • edited Loading

rogerweb commented Oct 4, 2018

singla96 commented Oct 13, 2018

praveenax commented May 24, 2019

ziimakc commented May 24, 2019

ghost commented Oct 18, 2019 • edited by ghost Loading

DNRN commented Oct 28, 2020

barakseri1 commented Jan 11, 2021

brayden-bcgsc commented Sep 7, 2021

eder-chamale commented Sep 24, 2021 • edited Loading

brayden-bcgsc commented Oct 4, 2021

BaptisteGarcin commented Jan 6, 2023

afonsomatos commented Jun 30, 2023

joaofrsilva commented Aug 2, 2023

crazyfree commented Aug 24, 2023

utkarshdeep commented Nov 21, 2023

AndreaFranchini commented Apr 9, 2024

Output running pm2 with `pm2 start pm2-cluster.yml`

Output running pm2 with `pm2 start pm2-fork.yml`

Unitech commented Oct 3, 2018 •

edited

Loading

ghost commented Oct 18, 2019 •

edited by ghost

Loading

eder-chamale commented Sep 24, 2021 •

edited

Loading