Unitech / Unitech/pm2

pm2 reloadLogs fails for fork mode if only log_file is set but out_file and error_file are both NULL

Open
#5,509 1 comment 0 reactions 0 assignees View on GitHub

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?

For pm2 configuration running in fork mode and log_file is set, but both out_file and error_file are NULL, pm2 rotateLogs command fails for the second time of rotation with the following error.
Please note that the first time of pm2 rotateLogs command runs successfully.
Also note that this does not happen for cluster mode.

2022-12-27T13:56:09: PM2 log: Reloading logs for process id 0
2022-12-27T13:56:09: PM2 error: Trace: TypeError: Cannot read properties of undefined (reading '_file')
    at ChildProcess.cspr._reloadLogs (node_modules/pm2/lib/God/ForkMode.js:283:22)
    at node_modules/pm2/lib/God/ActionMethods.js:635:19
    at Array.forEach (<anonymous>)
    at God.reloadLogs (node_modules/pm2/lib/God/ActionMethods.js:617:16)
    at Server.onmessage (node_modules/pm2-axon-rpc/lib/server.js:104:6)
    at RepSocket.emit (node:events:513:28)
    at RepSocket.emit (node:domain:489:12)
    at Parser.<anonymous> (node_modules/pm2-axon/lib/sockets/rep.js:51:15)
    at Parser.emit (node:events:513:28)
    at Parser.emit (node:domain:552:15)
    at Object.God.logAndGenerateError (node_modules/pm2/lib/God/Methods.js:34:15)
    at ChildProcess.cspr._reloadLogs (node_modules/pm2/lib/God/ForkMode.js:286:26)
    at node_modules/pm2/lib/God/ActionMethods.js:635:19
    at Array.forEach (<anonymous>)
    at God.reloadLogs (node_modules/pm2/lib/God/ActionMethods.js:617:16)
    at Server.onmessage (node_modules/pm2-axon-rpc/lib/server.js:104:6)
    at RepSocket.emit (node:events:513:28)
    at RepSocket.emit (node:domain:489:12)
    at Parser.<anonymous> (node_modules/pm2-axon/lib/sockets/rep.js:51:15)
    at Parser.emit (node:events:513:28)

How could we reproduce this issue?

Followings are the sample app. You can actually use any app you want that generates some output to log.

dummy-app.js
'use strict';

const EventEmitter = require('events');

const emitter = new EventEmitter();
emitter.on('event', () => {
        console.log(new Date().toString());
});

async function emitEvent() {
        await new Promise(resolve => {
                setTimeout(() => {
                        emitter.emit('event');
                        resolve();
                }, 3000);
        });
        await emitEvent();
}

emitter.emit('event');
Promise.resolve().then(emitEvent);
pm2.config.js
'use strict';

module.exports = {
        apps: [{
                name: 'dummy-app',
                script: './dummy-app.js',
                watch: false,
                log_file: '/home/project/logs/dummy-app.log',
                out_file: 'NULL',
                error_file: 'NULL'
        }]
}
  1. run pm2 start pm2.config.js
  2. make sure that something goes out to /home/project/logs/dummy-app.log
  3. rename /home/project/logs/dummy-app.log to /home/project/logs/dummy-app.log.1 as if it has been rotated by logrotate.
  4. run pm2 rotateLogs
  5. make sure that something goes out to /home/project/logs/dummy-app.log, but not to /home/project/logs/dummy-app.log.1 anymore
  6. rename /home/project/logs/dummy-app.log to /home/project/logs/dummy-app.log.2 as if it has been rotated by logrotate.
  7. run pm2 rotateLogs
  8. error is shown in ~/.pm2/pm2.log as above, and log continues to /home/project/logs/dummy-app.log.2

Supporting information

Root cause is in lib/God/ForkMode.js https://github.com/Unitech/pm2/blob/master/lib/God/ForkMode.js#L277

        try {
          for (var k in stds){
            if (stds[k] && stds[k].destroy) stds[k].destroy();
            else if (stds[k] && stds[k].end) stds[k].end();
            else if (stds[k] && stds[k].close) stds[k].close();
            stds[k] = stds[k]._file;
          }
        } catch(e) { God.logAndGenerateError(e);}

When out_file or error_file is set to NULL, stds[k] becomes undefined. However, there is no error check here so it continues to L280 and fails to catch.

You need the same error check as you do for cluster mode.

https://github.com/Unitech/pm2/blob/master/lib/ProcessContainer.js#L140

      for (var k in stds){
        if (typeof stds[k] == 'object' && !isNaN(stds[k].fd)){    // THIS TYPE CHECK HERE
          if (stds[k].destroy) stds[k].destroy();
          else if (stds[k].end) stds[k].end();
          else if (stds[k].close) stds[k].close();
          stds[k] = stds[k]._file;
        }
      }
$ pm2 report
--- PM2 report ----------------------------------------------------------------
Date                 : Tue Dec 27 2022 14:12:19 GMT+0900 (日本標準時)
===============================================================================
--- Daemon -------------------------------------------------
pm2d version         : 5.2.2
node version         : 16.19.0
node path            : /usr/local/bin/pm2
argv                 : /usr/local/bin/node,/node_modules/pm2/lib/Daemon.js
argv0                : node
user                 : kusanagi
uid                  : 1001
gid                  : 1001
uptime               : 0min
===============================================================================
--- CLI ----------------------------------------------------
local pm2            : 5.2.2
node version         : 16.19.0
node path            : /usr/local/bin/pm2
argv                 : /usr/local/bin/node,/usr/local/bin/pm2,report
argv0                : /usr/local/bin/node
user                 : kusanagi
uid                  : 1001
gid                  : 1001
===============================================================================
--- System info --------------------------------------------
arch                 : x64
platform             : linux
type                 : Linux
cpus                 : Intel Core Processor (Haswell, no TSX, IBRS)
cpus nb              : 4
freemem              : 6284881920
totalmem             : 8200638464
home                 : /home/kusanagi
===============================================================================
--- PM2 list -----------------------------------------------
┌────┬────────────────────┬──────────┬──────┬───────────┬──────────┬──────────┐
│ id │ name               │ mode     │ ↺    │ status    │ cpu      │ memory   │
└────┴────────────────────┴──────────┴──────┴───────────┴──────────┴──────────┘
===============================================================================
--- Daemon logs --------------------------------------------
/home/kusanagi/.pm2/pm2.log last 20 lines:
PM2        |     at Process.callbackTrampoline (node:internal/async_hooks:130:17)
PM2        | 2022-12-27T13:56:29: PM2 log: App [dummy-app:0] exited with code [0] via signal [SIGINT]
PM2        | 2022-12-27T13:56:29: PM2 log: pid=30891 msg=process killed
PM2        | 2022-12-27T13:56:29: PM2 log: PM2 successfully stopped
PM2        | 2022-12-27T14:12:19: PM2 log: ===============================================================================
PM2        | 2022-12-27T14:12:19: PM2 log: --- New PM2 Daemon started ----------------------------------------------------
PM2        | 2022-12-27T14:12:19: PM2 log: Time                 : Tue Dec 27 2022 14:12:19 GMT+0900 (日本標準時)
PM2        | 2022-12-27T14:12:19: PM2 log: PM2 version          : 5.2.2
PM2        | 2022-12-27T14:12:19: PM2 log: Node.js version      : 16.19.0
PM2        | 2022-12-27T14:12:19: PM2 log: Current arch         : x64
PM2        | 2022-12-27T14:12:19: PM2 log: PM2 home             : /home/kusanagi/.pm2
PM2        | 2022-12-27T14:12:19: PM2 log: PM2 PID file         : /home/kusanagi/.pm2/pm2.pid
PM2        | 2022-12-27T14:12:19: PM2 log: RPC socket file      : /home/kusanagi/.pm2/rpc.sock
PM2        | 2022-12-27T14:12:19: PM2 log: BUS socket file      : /home/kusanagi/.pm2/pub.sock
PM2        | 2022-12-27T14:12:19: PM2 log: Application log path : /home/kusanagi/.pm2/logs
PM2        | 2022-12-27T14:12:19: PM2 log: Worker Interval      : 30000
PM2        | 2022-12-27T14:12:19: PM2 log: Process dump file    : /home/kusanagi/.pm2/dump.pm2
PM2        | 2022-12-27T14:12:19: PM2 log: Concurrent actions   : 2
PM2        | 2022-12-27T14:12:19: PM2 log: SIGTERM timeout      : 1600
PM2        | 2022-12-27T14:12:19: PM2 log: ===============================================================================

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 in lib/God/ForkMode.js around the _reloadLogs implementation and compare its stream handling with lib/ProcessContainer.js. Reproduce the two successive pm2 rotateLogs runs using the supplied fork-mode configuration, then verify that rotation completes without an exception when out_file and error_file are NULL.

Written by the indexing model from the issue text.

Assessment

Tech stack
javascript, node.js
Domain
cli, devops
Issue type
Bug
Difficulty
2/5
Estimated time
1-3 hours
Activity status
Stale
Clarity
Clearly specified
Newbie friendliness
52/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.