[Linux and Windows] output (stdout and stderr) lost in clustermode
Nobody has claimed this yet.
- Dominant language
- JavaScript
- Stars
- 43.3k
- Forks
- 2.7k
- PR merge metrics
- No merged PRs in 30d
Description
What's going wrong?
output (stdout and stderr via console.log, console.error, and output of uncaught exceptions to stderr) is lost when node app running in cluster mode terminates.
How could we reproduce this issue?
- npm install pm2@latest -g (this was originally seen on Linux on pm2 2.10.4; it was reproduced on Windows on 2.10.4, then reproduced and the example script simplified on Windows on pm2 3.2.3)
- node 'C:\Program Files\nodejs\node_modules\pm2\bin\pm2' start .\log-and-throw.js -i 2 --merge-logs --log-date-format='YYYY-MM-DD HH:mm:ss' --output out.log --error err.log --name log-and-throw '--' arg-to-app
expected results
expected contents of out.log (time prepended to lines; repeated according to how many times the processes attempt to start)
- "argv.length 3"
- "stdout before"
expected contents of err.log (time prepended to lines; repeated according to how many times the processes attempt to start)
- "stderr before"
- stack trace showing no such file or directory
actual results
actual contents of out.log (time prepended to lines; repeated according to how many times the processes attempt to start)
- "argv.length 3"
- MISSING: "stdout before"
actual contents of err.log (time prepended to lines; repeated according to how many times the processes attempt to start)
- "stderr before"
- MISSING: stack trace showing no such file or directory
Note that running under fork mode (by removing the -i entirely under 2.10.4; by passing -i 1 under 3.2.3) results in the expected output in the log files.
Supporting information
$ pm2 report
username replaced with first.last, preserving whatever case it appeared in:
pm2 report
===============================================================================
--- PM2 REPORT (Fri Dec 14 2018 17:07:01 GMT-0700 (Mountain Standard Time)) ---
===============================================================================
--- Daemon -------------------------------------------------
pm2d version : 3.2.3
node version : 8.11.4
node path : not found
argv : C:\Program Files\nodejs\node.exe,C:\Users\first.last\AppData\Roaming\nvm\v8.11.4\node_modules\pm2\lib\Daemon.js
argv0 : node
user : undefined
uid : N/A
gid : N/A
uptime : 6min
===============================================================================
--- CLI ----------------------------------------------------
local pm2 : 3.2.3
node version : 8.11.4
node path : not found
argv : C:\Program Files\nodejs\node.exe,C:\Program Files\nodejs\node_modules\pm2\bin\pm2,report
argv0 : C:\Program Files\nodejs\\node.exe
user : First.Last
===============================================================================
--- System info --------------------------------------------
arch : x64
platform : win32
type : Windows_NT
cpus : Intel(R) Core(TM) i7-6920HQ CPU @ 2.90GHz
cpus nb : 8
freemem : 16592232448
totalmem : 33936121856
home : C:\Users\first.last
===============================================================================
--- PM2 list -----------------------------------------------
┌───────────────┬────┬─────────┬─────────┬─────┬─────────┬─────────┬────────┬─────┬────────┬─────────────┬──────────┐
│ App name │ id │ version │ mode │ pid │ status │ restart │ uptime │ cpu │ mem │ user │ watching │
├───────────────┼────┼─────────┼─────────┼─────┼─────────┼─────────┼────────┼─────┼────────┼─────────────┼──────────┤
│ log-and-throw │ 0 │ 0.0.1 │ cluster │ 0 │ errored │ 15 │ 0 │ 0% │ 0 B │ First.Last │ disabled │
│ log-and-throw │ 1 │ 0.0.1 │ cluster │ 0 │ errored │ 15 │ 0 │ 0% │ 0 B │ First.Last │ disabled │
└───────────────┴────┴─────────┴─────────┴─────┴─────────┴─────────┴────────┴─────┴────────┴─────────────┴──────────┘
===============================================================================
--- Daemon logs --------------------------------------------
┌───────────────┬────┬─────────┬─────────┬─────┬─────────┬─────────┬────────┬─────┬────────┬─────────────┬──────────┐
│ App name │ id │ version │ mode │ pid │ status │ restart │ uptime │ cpu │ mem │ user │ watching │
├───────────────┼────┼─────────┼─────────┼─────┼─────────┼─────────┼────────┼─────┼────────┼─────────────┼──────────┤
│ log-and-throw │ 0 │ 0.0.1 │ cluster │ 0 │ errored │ 15 │ 0 │ 0% │ 0 B │ First.Last │ disabled │
│ log-and-throw │ 1 │ 0.0.1 │ cluster │ 0 │ errored │ 15 │ 0 │ 0% │ 0 B │ First.Last │ disabled │
└───────────────┴────┴─────────┴─────────┴─────┴─────────┴─────────┴────────┴─────┴────────┴─────────────┴──────────┘
Use `pm2 show <id|name>` to get more details about an app
first ~50 of pm2.log, replacing username again
2018-12-14T17:00:56: PM2 log: ===============================================================================
2018-12-14T17:00:56: PM2 log: --- New PM2 Daemon started ----------------------------------------------------
2018-12-14T17:00:56: PM2 log: Time : Fri Dec 14 2018 17:00:56 GMT-0700 (Mountain Standard Time)
2018-12-14T17:00:56: PM2 log: PM2 version : 3.2.3
2018-12-14T17:00:56: PM2 log: Node.js version : 8.11.4
2018-12-14T17:00:56: PM2 log: Current arch : x64
2018-12-14T17:00:56: PM2 log: PM2 home : C:\Users\first.last\.pm2
2018-12-14T17:00:56: PM2 log: PM2 PID file : C:\Users\first.last\.pm2\pm2.pid
2018-12-14T17:00:56: PM2 log: RPC socket file : \\.\pipe\rpc.sock
2018-12-14T17:00:56: PM2 log: BUS socket file : \\.\pipe\pub.sock
2018-12-14T17:00:56: PM2 log: Application log path : C:\Users\first.last\.pm2\logs
2018-12-14T17:00:56: PM2 log: Process dump file : C:\Users\first.last\.pm2\dump.pm2
2018-12-14T17:00:56: PM2 log: Concurrent actions : 2
2018-12-14T17:00:56: PM2 log: SIGTERM timeout : 1600
2018-12-14T17:00:56: PM2 log: ===============================================================================
2018-12-14T17:00:56: PM2 log: App [log-and-throw:0] starting in -cluster mode-
2018-12-14T17:00:57: PM2 log: App [log-and-throw:0] online
2018-12-14T17:00:57: PM2 log: App [log-and-throw:1] starting in -cluster mode-
2018-12-14T17:00:57: PM2 error: (node:8608) [DEP0007] DeprecationWarning: worker.suicide is deprecated. Please use worker.exitedAfterDisconnect.
2018-12-14T17:00:57: PM2 log: App name:log-and-throw id:0 disconnected
2018-12-14T17:00:57: PM2 log: App [log-and-throw:0] exited with code [0] via signal [SIGINT]
2018-12-14T17:00:57: PM2 log: App [log-and-throw:0] starting in -cluster mode-
2018-12-14T17:00:57: PM2 log: App [log-and-throw:1] online
2018-12-14T17:00:57: PM2 error: (node:8608) [DEP0007] DeprecationWarning: worker.suicide is deprecated. Please use worker.exitedAfterDisconnect.
2018-12-14T17:00:58: PM2 log: App name:log-and-throw id:1 disconnected
2018-12-14T17:00:58: PM2 log: App [log-and-throw:0] online
2018-12-14T17:00:58: PM2 log: App [log-and-throw:1] exited with code [0] via signal [SIGINT]
2018-12-14T17:00:58: PM2 log: App [log-and-throw:1] starting in -cluster mode-
2018-12-14T17:00:58: PM2 error: Error caught while calling pidusage
2018-12-14T17:00:58: PM2 error: Error: No maching pid found
2018-12-14T17:00:58: PM2 log: App name:log-and-throw id:0 disconnected
2018-12-14T17:00:58: PM2 log: App [log-and-throw:0] exited with code [0] via signal [SIGINT]
2018-12-14T17:00:58: PM2 log: App [log-and-throw:0] starting in -cluster mode-
2018-12-14T17:00:58: PM2 log: App [log-and-throw:1] online
2018-12-14T17:00:58: PM2 log: App [log-and-throw:0] online
2018-12-14T17:00:58: PM2 log: App name:log-and-throw id:1 disconnected
2018-12-14T17:00:58: PM2 log: App [log-and-throw:1] exited with code [0] via signal [SIGINT]
2018-12-14T17:00:58: PM2 log: App [log-and-throw:1] starting in -cluster mode-
2018-12-14T17:00:59: PM2 log: App name:log-and-throw id:0 disconnected
2018-12-14T17:00:59: PM2 log: App [log-and-throw:0] exited with code [0] via signal [SIGINT]
2018-12-14T17:00:59: PM2 log: App [log-and-throw:0] starting in -cluster mode-
2018-12-14T17:00:59: PM2 log: App [log-and-throw:1] online
2018-12-14T17:00:59: PM2 log: App [log-and-throw:0] online
2018-12-14T17:00:59: PM2 log: App name:log-and-throw id:1 disconnected
2018-12-14T17:00:59: PM2 log: App [log-and-throw:1] exited with code [0] via signal [SIGINT]
2018-12-14T17:00:59: PM2 log: App [log-and-throw:1] starting in -cluster mode-
2018-12-14T17:00:59: PM2 log: App name:log-and-throw id:0 disconnected
2018-12-14T17:00:59: PM2 log: App [log-and-throw:0] exited with code [0] via signal [SIGINT]
2018-12-14T17:00:59: PM2 log: App [log-and-throw:0] starting in -cluster mode-
2018-12-14T17:00:59: PM2 log: App [log-and-throw:1] online
lines from pm2.log when running in fork mode (problem is only seen in cluster mode)
2018-12-14T17:32:37: PM2 log: App [log-and-throw:0] starting in -fork mode-
2018-12-14T17:32:37: PM2 log: App [log-and-throw:0] online
2018-12-14T17:32:37: PM2 log: App [log-and-throw:0] exited with code [1] via signal [SIGINT]
2018-12-14T17:32:37: PM2 log: App [log-and-throw:0] starting in -fork mode-
2018-12-14T17:32:37: PM2 log: App [log-and-throw:0] online
2018-12-14T17:32:37: PM2 error: Error caught while calling pidusage
2018-12-14T17:32:37: PM2 error: Error: No maching pid found
2018-12-14T17:32:37: PM2 log: App [log-and-throw:0] exited with code [1] via signal [SIGINT]
2018-12-14T17:32:37: PM2 log: App [log-and-throw:0] starting in -fork mode-
2018-12-14T17:32:37: PM2 log: App [log-and-throw:0] online
2018-12-14T17:32:38: PM2 log: App [log-and-throw:0] exited with code [1] via signal [SIGINT]
2018-12-14T17:32:38: PM2 log: App [log-and-throw:0] starting in -fork mode-
2018-12-14T17:32:38: PM2 log: App [log-and-throw:0] online
2018-12-14T17:32:38: PM2 log: App [log-and-throw:0] exited with code [1] via signal [SIGINT]
2018-12-14T17:32:38: PM2 log: App [log-and-throw:0] starting in -fork mode-
2018-12-14T17:32:38: PM2 log: App [log-and-throw:0] online
2018-12-14T17:32:38: PM2 error: Error caught while calling pidusage
2018-12-14T17:32:38: PM2 error: Error: No maching pid found
2018-12-14T17:32:38: PM2 log: App [log-and-throw:0] exited with code [1] via signal [SIGINT]
2018-12-14T17:32:38: PM2 log: App [log-and-throw:0] starting in -fork mode-
contents of log-and-throw.js
'use stict';
const fs = require('fs');
console.log('argv.length', process.argv.length);
console.log('stdout before');
console.error('stderr before');
const junk = fs.readFileSync('no/such/file', 'utf8');
console.log('stdout not reached');
console.error('stderr not reached');
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Start by running the provided PM2 cluster-mode command with log-and-throw.js on Linux and Windows, then compare it with fork mode. Trace the cluster-mode logging path for stdout, stderr, and uncaught exceptions; the issue is done when out.log and err.log retain all expected lines in both environments.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- javascript, node.js
- Domain
- devops
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 35/100