Unitech / Unitech/pm2

[Linux and Windows] output (stdout and stderr) lost in clustermode

Open
#4,075 11 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

SYS: Windows
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?

  1. 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)
  2. 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)

  1. "argv.length 3"
  2. "stdout before"

expected contents of err.log (time prepended to lines; repeated according to how many times the processes attempt to start)

  1. "stderr before"
  2. 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)

  1. "argv.length 3"
  2. MISSING: "stdout before"

actual contents of err.log (time prepended to lines; repeated according to how many times the processes attempt to start)

  1. "stderr before"
  2. 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

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.