Cron broken since 3.2.3 ? "PM ID unknown" #4307

yched · 2019-06-05T12:55:14Z

Not sure if we're doing something wrong, but PR #3944 broke cron_restart for us :

the 1st cron run following the initial pm2 start successfully restarts the app,
but all the subsequent runs fail with error PM ID unknown

In more details on a sample setup :

ecosystem.json :

{
  "apps" : [{
    "name"       : "my_app",
    "script"     : "main.js",
    "exec_mode"  : "cluster",
    "autorestart": true,
    "cron_restart" : "* * * * *",
    "log_date_format": "YYYY-MM-DD HH:mm:ss"
  }]
}

main.js :

// Logs on startup
console.log('my_app started');
// Pings every 10s
setInterval(() => console.log('my_app is running'), 10 * 1000);
// Dies after 1m20s (shouldn't happen since pm2 is supposed to restart us every minute)
setTimeout(() => { console.log('my_app will die'); process.exit(0); }, 80 * 1000);

Output of pm2 log :
(can't seem to have PM2 daemon logs include timestamps for some reason ?)

PM2      | App [my_app:0] starting in -cluster mode-      <-- "pm2 start ecosystem.json"
PM2      | App [my_app:0] online
0|my_app | 2019-06-05 13:34:04: my_app started
0|my_app | 2019-06-05 13:34:14: my_app is running
PM2      | [PM2][WORKER] Registering a cron job on: 0
0|my_app | 2019-06-05 13:34:24: my_app is running
0|my_app | 2019-06-05 13:34:34: my_app is running
0|my_app | 2019-06-05 13:34:44: my_app is running
0|my_app | 2019-06-05 13:34:54: my_app is running
PM2      | App [my_app:0] starting in -cluster mode-      <-- 1st cron restart at 13:35:00, works
PM2      | App [my_app:0] online
0|my_app | 2019-06-05 13:35:00: my_app started
_old_0|my_app  | 2019-06-05 13:35:04: my_app is running   <-- apparently the initial process (synced at second 4) keeps running for some time ?
0|my_app       | 2019-06-05 13:35:10: my_app is running   
PM2            | Stopping app:my_app id:_old_0            <-- the initial process is being stopped
PM2            | App name:my_app id:_old_0 disconnected
PM2            | App [my_app:_old_0] exited with code [0] via signal [SIGINT]
PM2            | pid=8462 msg=process killed
0|my_app       | 2019-06-05 13:35:20: my_app is running   
0|my_app       | 2019-06-05 13:35:30: my_app is running
0|my_app       | 2019-06-05 13:35:40: my_app is running
0|my_app       | 2019-06-05 13:35:50: my_app is running
PM2            | Error: PM ID unknown                     <-- 2nd cron restart at 13:36:00, fails
PM2            |     at Object.God.softReloadProcessId ([...]/pm2/lib/God/Reload.js:185:17)
PM2            |     at CronJob.onTick ([...]//pm2/lib/Worker.js:40:13)
PM2            |     at CronJob.fireOnTick ([...]//pm2/node_modules/cron/lib/cron.js:562:23)
PM2            |     at Timeout.callbackWrapper [as _onTimeout] ([...]//pm2/node_modules/cron/lib/cron.js:629:10)
PM2            |     at ontimeout (timers.js:436:11)
PM2            |     at tryOnTimeout (timers.js:300:5)
PM2            |     at listOnTimeout (timers.js:263:5)
PM2            |     at Timer.processTimers (timers.js:223:10)
0|my_app       | 2019-06-05 13:36:00: my_app is running   <-- still running
0|my_app       | 2019-06-05 13:36:10: my_app is running
0|my_app       | 2019-06-05 13:36:20: my_app will die     <-- dies after 80s (= 1min20s after the cron that worked)
PM2            | App name:my_app id:0 disconnected
PM2            | App [my_app:0] exited with code [0] via signal [SIGINT]
PM2            | App [my_app:0] starting in -cluster mode-
PM2            | App [my_app:0] online
0|my_app       | 2019-06-05 13:36:20: my_app started      <-- restarted by autorestart
0|my_app       | 2019-06-05 13:36:30: my_app is running
etc...
- at every round clock minute, cron fails with Error: PM ID unknown
- process naturally dies every 100s, and gets restarted

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

yched · 2019-06-05T12:58:01Z

Same setup (main.js / ecosystem.js) with pm2 3.2.2 :
works as expected : app restarts every minute, and never reaches "die after 1m20"

PM2      | App [my_app:0] starting in -cluster mode-
PM2      | App [my_app:0] online
0|my_app | 2019-06-05 14:47:42: my_app started
0|my_app | 2019-06-05 14:47:52: my_app is running
PM2      | Stopping app:my_app id:0                      <-- 1st cron restart
PM2      | App name:my_app id:0 disconnected
PM2      | App [my_app:0] exited with code [0] via signal [SIGINT]
PM2      | pid=16476 msg=process killed
PM2      | App [my_app:0] starting in -cluster mode-
PM2      | App [my_app:0] online
PM2      | Application my_app has been restarted via CRON
0|my_app | 2019-06-05 14:48:00: my_app started
0|my_app | 2019-06-05 14:48:10: my_app is running
0|my_app | 2019-06-05 14:48:20: my_app is running
0|my_app | 2019-06-05 14:48:30: my_app is running
0|my_app | 2019-06-05 14:48:40: my_app is running
0|my_app | 2019-06-05 14:48:50: my_app is running
PM2      | Stopping app:my_app id:0                      <-- 2nd cron restart
PM2      | App name:my_app id:0 disconnected
PM2      | App [my_app:0] exited with code [0] via signal [SIGINT]
PM2      | pid=16496 msg=process killed
PM2      | App [my_app:0] starting in -cluster mode-
PM2      | App [my_app:0] online
PM2      | Application my_app has been restarted via CRON
0|my_app | 2019-06-05 14:49:00: my_app started
0|my_app | 2019-06-05 14:49:10: my_app is running
etc...

18601673727 · 2019-06-26T17:31:38Z

Similar problem here

krunalshah68 · 2019-07-10T08:24:00Z

+1

wong2 · 2019-07-12T08:47:38Z

same here

ejames17 · 2019-07-22T19:29:25Z

same here.
Im rolling back to 3.2.2

gnehs · 2019-11-02T05:05:32Z

same here

yahao87 · 2019-12-11T01:25:36Z

same here
The same problem occurs with version 3.5.1.

mirajehossain · 2020-01-14T08:43:11Z

Same problem here,
Does anyone fix it?

rcupic · 2020-02-04T09:22:36Z

Same problem. I deleted cron job with "pm2 delete {name}", after that it looks like pm2 is still trying to start that process.

kelleghan1 · 2020-05-17T04:46:32Z

Any solution to this? I am having this issue in a production server

Allain55 · 2020-05-20T06:30:29Z

Same problem here

stale · 2020-06-19T07:24:16Z

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

yched · 2020-06-19T09:37:00Z

That is still an issue

stale · 2020-07-19T09:59:46Z

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

yched · 2020-07-19T16:23:34Z

seriously ?

goodwillsandy · 2020-08-15T20:29:40Z

Facing same issue,

--- PM2 report ----------------------------------------------------------------
Date                 : Sat Aug 15 2020 20:24:46 GMT+0000 (Coordinated Universal Time)
===============================================================================
--- Daemon -------------------------------------------------
pm2d version         : 4.4.0
node version         : 12.18.3
node path            : /usr/bin/pm2
argv                 : /usr/bin/node,/usr/lib/node_modules/pm2/lib/Daemon.js
argv0                : node
user                 : ubuntu
uid                  : 1000
gid                  : 1000
uptime               : 40min
===============================================================================
--- CLI ----------------------------------------------------
local pm2            : 4.4.0
node version         : 12.18.3
node path            : /usr/bin/pm2
argv                 : /usr/bin/node,/usr/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              : 1
freemem              : 114925568
totalmem             : 1026158592
home                 : /home/ubuntu
===============================================================================
--- PM2 list -----------------------------------------------
┌─────┬─────────────────────────┬─────────────┬─────────┬─────────┬──────────┬────────┬──────┬───────────┬──────────┬──────────┬──────────┬──────────┐
│ id  │ name                    │ namespace   │ version │ mode    │ pid      │ uptime │ ↺    │ status    │ cpu      │ mem      │ user     │ watching │
├─────┼─────────────────────────┼─────────────┼─────────┼─────────┼──────────┼────────┼──────┼───────────┼──────────┼──────────┼──────────┼──────────┤
│ 0   │ Project2-SchedulerMS    │ default     │ 1.0.0   │ cluster │ 5068     │ 9m     │ 1    │ online    │ 0%       │ 76.8mb   │ ubuntu   │ disabled │
└─────┴─────────────────────────┴─────────────┴─────────┴─────────┴──────────┴────────┴──────┴───────────┴──────────┴──────────┴──────────┴──────────┘
===============================================================================
--- Daemon logs --------------------------------------------
/home/ubuntu/.pm2/pm2.log last 20 lines:
PM2        | 2020-08-15T20:12:41: PM2 log: Stopping app:Project2-SchedulerMS id:0
PM2        | 2020-08-15T20:12:41: PM2 log: App name:Project2-SchedulerMS id:0 disconnected
PM2        | 2020-08-15T20:12:41: PM2 log: App [Project2-SchedulerMS:0] exited with code [0] via signal [SIGINT]
PM2        | 2020-08-15T20:12:41: PM2 log: pid=4934 msg=process killed
PM2        | 2020-08-15T20:13:09: PM2 log: [PM2][WORKER] Registering a cron job on: 0
PM2        | 2020-08-15T20:13:09: PM2 log: App [Project2-SchedulerMS:0] starting in -cluster mode-
PM2        | 2020-08-15T20:13:09: PM2 log: App [Project2-SchedulerMS:0] online
PM2        | 2020-08-15T20:15:00: PM2 log: App [Project2-SchedulerMS:0] starting in -cluster mode-
PM2        | 2020-08-15T20:15:00: PM2 log: App [Project2-SchedulerMS:0] online
PM2        | 2020-08-15T20:15:11: PM2 log: Stopping app:Project2-SchedulerMS id:_old_0
PM2        | 2020-08-15T20:15:11: PM2 log: App name:Project2-SchedulerMS id:_old_0 disconnected
PM2        | 2020-08-15T20:15:11: PM2 log: App [Project2-SchedulerMS:_old_0] exited with code [0] via signal [SIGINT]
PM2        | 2020-08-15T20:15:11: PM2 log: pid=5033 msg=process killed
PM2        | 2020-08-15T20:20:00: PM2 error: Error: pm_id _old_0 not available in _old_0
PM2        |     at Object.God.softReloadProcessId (/usr/lib/node_modules/pm2/lib/God/Reload.js:194:17)
PM2        |     at CronJob.onTick (/usr/lib/node_modules/pm2/lib/Worker.js:38:13)
PM2        |     at CronJob.fireOnTick (/usr/lib/node_modules/pm2/node_modules/cron/lib/cron.js:600:23)
PM2        |     at Timeout.callbackWrapper [as _onTimeout] (/usr/lib/node_modules/pm2/node_modules/cron/lib/cron.js:667:10)
PM2        |     at listOnTimeout (internal/timers.js:549:17)
PM2        |     at processTimers (internal/timers.js:492:7)

goodwillsandy · 2020-08-15T20:42:18Z

This issue exists here when exec_mode: cluster. If you change to exec_mode: fork it will work.
Keep me posted.

…#4834 #4733 #4307 #4834

Unitech · 2020-12-16T14:38:01Z

fixed in pm2@4.5.1:

npm install pm2@latest -g
pm2 update

…Unitech#4834 Unitech#4733 Unitech#4307 Unitech#4834

stale bot added the stale label Jun 19, 2020

stale bot removed the stale label Jun 19, 2020

stale bot added the stale label Jul 19, 2020

stale bot removed the stale label Jul 19, 2020

goodwillsandy mentioned this issue Aug 16, 2020

Error when delete a cron job then restart it. #4532

Closed

Unitech added a commit that referenced this issue Dec 9, 2020

fix: cron-restart in cluster mode + alias --cron to --cron-restart fix …

2f61ddb

…#4834 #4733 #4307 #4834

Unitech closed this as completed Dec 16, 2020

mendrix pushed a commit to mendrix/pm2 that referenced this issue Dec 29, 2020

fix: cron-restart in cluster mode + alias --cron to --cron-restart fix …

d4fd08c

…Unitech#4834 Unitech#4733 Unitech#4307 Unitech#4834

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Cron broken since 3.2.3 ? "PM ID unknown" #4307

Cron broken since 3.2.3 ? "PM ID unknown" #4307

yched commented Jun 5, 2019

yched commented Jun 5, 2019 •

edited

Loading

18601673727 commented Jun 26, 2019

krunalshah68 commented Jul 10, 2019

wong2 commented Jul 12, 2019

ejames17 commented Jul 22, 2019 •

edited

Loading

gnehs commented Nov 2, 2019

yahao87 commented Dec 11, 2019 •

edited

Loading

mirajehossain commented Jan 14, 2020

rcupic commented Feb 4, 2020

kelleghan1 commented May 17, 2020

Allain55 commented May 20, 2020

stale bot commented Jun 19, 2020

yched commented Jun 19, 2020

stale bot commented Jul 19, 2020

yched commented Jul 19, 2020

goodwillsandy commented Aug 15, 2020

goodwillsandy commented Aug 15, 2020

Unitech commented Dec 16, 2020

Cron broken since 3.2.3 ? "PM ID unknown" #4307

Cron broken since 3.2.3 ? "PM ID unknown" #4307

Comments

yched commented Jun 5, 2019

yched commented Jun 5, 2019 • edited Loading

18601673727 commented Jun 26, 2019

krunalshah68 commented Jul 10, 2019

wong2 commented Jul 12, 2019

ejames17 commented Jul 22, 2019 • edited Loading

gnehs commented Nov 2, 2019

yahao87 commented Dec 11, 2019 • edited Loading

mirajehossain commented Jan 14, 2020

rcupic commented Feb 4, 2020

kelleghan1 commented May 17, 2020

Allain55 commented May 20, 2020

stale bot commented Jun 19, 2020

yched commented Jun 19, 2020

stale bot commented Jul 19, 2020

yched commented Jul 19, 2020

goodwillsandy commented Aug 15, 2020

goodwillsandy commented Aug 15, 2020

Unitech commented Dec 16, 2020

yched commented Jun 5, 2019 •

edited

Loading

ejames17 commented Jul 22, 2019 •

edited

Loading

yahao87 commented Dec 11, 2019 •

edited

Loading