Errors when using gracefulReload (or reload) #1101

bigethan · 2015-03-16T18:53:03Z

Hello.

I'm upgrading PM2 from 0.9.0 to 0.12.7 and with the pm2 gracefulReload myApp I'm getting EADDRINUSE and TypeError: Cannot read property 'apply' of undefined errors:

$ tail -f /var/log/myApp/error-0.log /var/log/myApp/access-0.log

==> /var/log/myApp/access-0.log <==
info: server pid 14369 listening on port 3030 in staging mode

==> /var/log/myApp/error-0.log <==
Error: bind EADDRINUSE
    at exports._errnoException (util.js:746:11)
    at cb (net.js:1178:33)
    at rr (cluster.js:592:14)
    at Worker.<anonymous> (cluster.js:563:9)
    at process.<anonymous> (cluster.js:692:8)
    at process.emit (events.js:129:20)
    at handleMessage (child_process.js:324:10)
    at Pipe.channel.onread (child_process.js:352:11)
error: uncaughtException: bind EADDRINUSE date=Mon Mar 16 2015 11:42:57 GMT-0700 (PDT), pid=14369, uid=202, gid=1349, cwd=/data/beaker/release-20150316105823-4f8dad2, execPath=/usr/bin/nodejs, version=v0.12.0, argv=[/usr/bin/nodejs, /usr/lib/node_modules/pm2/lib/ProcessContainer.js], rss=50991104, heapTotal=57662720, heapUsed=22800344, loadavg=[0.0029296875, 0.03125, 0.13720703125], uptime=33121385, trace=[column=11, file=util.js, function=exports._errnoException, line=746, method=_errnoException, native=false, column=33, file=net.js, function=cb, line=1178, method=null, native=false, column=14, file=cluster.js, function=rr, line=592, method=null, native=false, column=9, file=cluster.js, function=, line=563, method=null, native=false, column=8, file=cluster.js, function=, line=692, method=null, native=false, column=20, file=events.js, function=process.emit, line=129, method=emit, native=false, column=10, file=child_process.js, function=handleMessage, line=324, method=null, native=false, column=11, file=child_process.js, function=Pipe.channel.onread, line=352, method=channel.onread, native=false], stack=[Error: bind EADDRINUSE,     at exports._errnoException (util.js:746:11),     at cb (net.js:1178:33),     at rr (cluster.js:592:14),     at Worker.<anonymous> (cluster.js:563:9),     at process.<anonymous> (cluster.js:692:8),     at process.emit (events.js:129:20),     at handleMessage (child_process.js:324:10),     at Pipe.channel.onread (child_process.js:352:11)]
TypeError: Cannot read property 'apply' of undefined
    at process.<anonymous> (cluster.js:692:7)
    at process.emit (events.js:129:20)
    at handleMessage (child_process.js:324:10)
    at Pipe.channel.onread (child_process.js:352:11)
error: uncaughtException: Cannot read property 'apply' of undefined date=Mon Mar 16 2015 11:43:01 GMT-0700 (PDT), pid=14219, uid=202, gid=1349, cwd=/data/beaker/release-20150316105823-4f8dad2, execPath=/usr/bin/nodejs, version=v0.12.0, argv=[/usr/bin/nodejs, /usr/lib/node_modules/pm2/lib/ProcessContainer.js], rss=50962432, heapTotal=58682624, heapUsed=23955592, loadavg=[0.0029296875, 0.03076171875, 0.13623046875], uptime=33121388, trace=[column=7, file=cluster.js, function=, line=692, method=null, native=false, column=20, file=events.js, function=process.emit, line=129, method=emit, native=false, column=10, file=child_process.js, function=handleMessage, line=324, method=null, native=false, column=11, file=child_process.js, function=Pipe.channel.onread, line=352, method=channel.onread, native=false], stack=[TypeError: Cannot read property 'apply' of undefined,     at process.<anonymous> (cluster.js:692:7),     at process.emit (events.js:129:20),     at handleMessage (child_process.js:324:10),     at Pipe.channel.onread (child_process.js:352:11)]
TypeError: Cannot read property 'apply' of undefined
    at process.<anonymous> (cluster.js:692:7)
    at process.emit (events.js:129:20)
    at handleMessage (child_process.js:324:10)
    at Pipe.channel.onread (child_process.js:352:11)
error: uncaughtException: Cannot read property 'apply' of undefined date=Mon Mar 16 2015 11:43:09 GMT-0700 (PDT), pid=14219, uid=202, gid=1349, cwd=/data/beaker/release-20150316105823-4f8dad2, execPath=/usr/bin/nodejs, version=v0.12.0, argv=[/usr/bin/nodejs, /usr/lib/node_modules/pm2/lib/ProcessContainer.js], rss=50962432, heapTotal=58682624, heapUsed=24177616, loadavg=[0.0029296875, 0.02978515625, 0.13525390625], uptime=33121396, trace=[column=7, file=cluster.js, function=, line=692, method=null, native=false, column=20, file=events.js, function=process.emit, line=129, method=emit, native=false, column=10, file=child_process.js, function=handleMessage, line=324, method=null, native=false, column=11, file=child_process.js, function=Pipe.channel.onread, line=352, method=channel.onread, native=false], stack=[TypeError: Cannot read property 'apply' of undefined,     at process.<anonymous> (cluster.js:692:7),     at process.emit (events.js:129:20),     at handleMessage (child_process.js:324:10),     at Pipe.channel.onread (child_process.js:352:11)]
TypeError: Cannot read property 'apply' of undefined
    at process.<anonymous> (cluster.js:692:7)
    at process.emit (events.js:129:20)
    at handleMessage (child_process.js:324:10)
    at Pipe.channel.onread (child_process.js:352:11)
error: uncaughtException: Cannot read property 'apply' of undefined date=Mon Mar 16 2015 11:43:11 GMT-0700 (PDT), pid=14219, uid=202, gid=1349, cwd=/data/beaker/release-20150316105823-4f8dad2, execPath=/usr/bin/nodejs, version=v0.12.0, argv=[/usr/bin/nodejs, /usr/lib/node_modules/pm2/lib/ProcessContainer.js], rss=50962432, heapTotal=58682624, heapUsed=24368200, loadavg=[0.0029296875, 0.02978515625, 0.13525390625], uptime=33121398, trace=[column=7, file=cluster.js, function=, line=692, method=null, native=false, column=20, file=events.js, function=process.emit, line=129, method=emit, native=false, column=10, file=child_process.js, function=handleMessage, line=324, method=null, native=false, column=11, file=child_process.js, function=Pipe.channel.onread, line=352, method=channel.onread, native=false], stack=[TypeError: Cannot read property 'apply' of undefined,     at process.<anonymous> (cluster.js:692:7),     at process.emit (events.js:129:20),     at handleMessage (child_process.js:324:10),     at Pipe.channel.onread (child_process.js:352:11)]

It's also missing the logging that I'm doing within my shutdown function in my index.js:

process.on('message', function(msg) {
  if (msg == 'shutdown') {
    logger.error('Shutdown requested - closing open connections.');
    //close session connections (sync)
    sessionStore.client.end();
    //shut down the app
    process.exit(0);
  }
});

my json config is:

    "name"       : "myApp",
    "script"     : "/data/myApp/current-stage/site/index.js",
    "exec_mode"  : "cluster_mode",
    "instances"  : "max",
    "error_file" : "/var/log/myApp/error.log",
    "out_file"   : "/var/log/myApp/access.log",
    "pid_file"   : "/data/myApp/current-stage/app.pid",
    "port"       : 3030,
    "env": {
      "NODE_ENV": "staging",
      "PM2_GRACEFUL_TIMEOUT": 500
    }

Any ideas what I'm doing wrong? Any new buttons to push to get this to work properly?

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

jshkurti · 2015-03-16T18:57:58Z

Hello, thanks for this feedback.
I'll be working on it and will keep you informed :)

bigethan · 2015-03-16T20:20:41Z

please let me know if you need any other information. I'm gonna keep working on it and will update if I find anything.

bigethan · 2015-03-18T17:43:46Z

I'ved tweaked various aspects of my app, but the error persists. Any suggestions?

jshkurti · 2015-03-18T18:05:27Z

How many instances of the app are launched ?

bigethan · 2015-03-18T18:54:16Z

"instances" : "max", is in the json config.

jshkurti · 2015-03-18T20:27:22Z

I'm going to refactor reload/gracefulReload a bit, I'll keep you informed.

davisford · 2015-03-20T16:10:12Z

Hey, not to pile on, but I'm seeing something similar when executing pm2 restart all. I have three processes running under pm2 0.12.7:

ubuntu@ip-10-0-0-191:~/.pm2/logs$ pm2 list
┌───────────────┬────┬──────┬───────┬────────┬─────────┬────────┬──────────────┬──────────┐
│ App name      │ id │ mode │ pid   │ status │ restart │ uptime │ memory       │ watching │
├───────────────┼────┼──────┼───────┼────────┼─────────┼────────┼──────────────┼──────────┤
│ reports       │ 0  │ fork │ 18704 │ online │ 0       │ 3h     │ 203.391 MB   │ disabled │
│ alerts        │ 1  │ fork │ 18772 │ online │ 0       │ 3h     │ 85.254 MB    │ disabled │
│ subscriptions │ 2  │ fork │ 18827 │ online │ 0       │ 3h     │ 69.020 MB    │ disabled │
└───────────────┴────┴──────┴───────┴────────┴─────────┴────────┴──────────────┴──────────┘

But occasionally on our EC2 Ubuntu 14.04 host, when I execute pm2 restart all, the reports app fails to terminate, but pm2 will try to launch another one, resulting in:

 { [Error: listen EADDRINUSE] code: 'EADDRINUSE', errno: 'EADDRINUSE', syscall: 'listen' }

I have to manually kill the process then and then I use pm2 to restart. Any idea why this might be happening or how to resolve it?

jshkurti · 2015-03-20T16:27:50Z

@davisford When PM2 kills a process it basically sends a 'SIGTERM' signal and waits 800ms for the process to exit, if after 800ms it still doesn't, then PM2 spawns a new process indeed.
Any clue why your app 'reports' wouldn't exit properly even 800ms after receiving SIGTERM signal ?

jshkurti · 2015-03-20T16:39:32Z

Do you catch 'SIGTERM' signal on purpose anywhere in your code ?

jshkurti · 2015-03-20T17:40:54Z

If you indeed catch SIGTERM in order to perform a graceFul exit (closing all connections etc) and your app takes more than 800ms to do that. We could make this 800ms timeout configurable via an env variable such as PM2_KILL_TIMEOUT so you can set it to 2seconds or whatever it takes.

davisford · 2015-03-20T18:20:16Z

Yep, I do catch SIGTERM, so that must be it. I need to gracefully shutdown a few services, and perhaps it is taking longer than 800ms. If you make this configurable that would be awesome 👍

bigethan · 2015-03-20T18:47:33Z

Ah interesting, so should my shutdown code look for a SIGTERM rather than a shutdown message?

eg, instead of

process.on('message', function(msg) {
  if (msg == 'shutdown') {
    logger.error('Shutdown requested - closing open connections.');
     ...
    //shut down the app
    process.exit(0);
  }
});

should be:

process.on('SIGTERM', function(msg) {
    logger.error('Shutdown requested - closing open connections.');
     ...
    //shut down the app
    process.exit(0);
});

jshkurti · 2015-03-20T18:53:33Z

Nop, 'SIGTERM' concerns only fork_mode.
@bigethan I'n gonna investigate your issue very soon.
Sorry for my lateness. I had to fix a bunch of critical issues lately :)

jshkurti · 2015-03-20T19:04:56Z

@davisford Here we go : 33180a9
npm i -g git://github.com/Unitech/PM2#development

You have to set it the first time you launch PM2 daemon like this :
PM2_KILL_TIMEOUT=4000 pm2 start test.js : sets it to 4seconds.

Cheers.

bigethan · 2015-03-20T19:36:19Z

Sorry for my lateness. I had to fix a bunch of critical issues lately :)

No worries at all, I was just trying to see if I'd missed a change along the way. PM2 has been great for us for over a year now, so I'm trying to see what we might be doing "wrong" from a PM@ point of view.

jshkurti · 2015-03-23T15:34:16Z

@bigethan does this bug happen everytime you gracefulReload your app or does it happen randomly ?

Can you npm i -g git://github.com/Unitech/PM2#development ; pm2 kill ; and give it a try ? :)
Also, which version of Node.js are you using ?
I would highly suggest you to use Node.js v0.12.0 and PM2 v0.12.8.
Thanks.

bigethan · 2015-03-23T16:36:16Z

it seemed to happen every time I did a gracefulReload with new PM2 under node 0.12. Errors persist with the new version, and address already in use, and a few apply errors for each restart:

TypeError: Cannot read property 'apply' of undefined
    at process.<anonymous> (cluster.js:692:7)
    at process.emit (events.js:129:20)
    at handleMessage (child_process.js:324:10)
    at Pipe.channel.onread (child_process.js:352:11)
error: uncaughtException: Cannot read property 'apply' of undefined date=Mon Mar 23 2015 09:27:39 GMT-0700 (PDT), pid=19890, uid=202, gid=1349, cwd=/data/beaker/release-20150316105823-4f8dad2, execPath=/usr/bin/nodejs, version=v0.12.0, argv=[/usr/bin/nodejs, /usr/lib/node_modules/pm2/lib/ProcessContainer.js], rss=69193728, heapTotal=60746496, heapUsed=36718200, loadavg=[0.0029296875, 0.0146484375, 0.04541015625], uptime=33718067, trace=[column=7, file=cluster.js, function=, line=692, method=null, native=false, column=20, file=events.js, function=process.emit, line=129, method=emit, native=false, column=10, file=child_process.js, function=handleMessage, line=324, method=null, native=false, column=11, file=child_process.js, function=Pipe.channel.onread, line=352, method=channel.onread, native=false], stack=[TypeError: Cannot read property 'apply' of undefined,     at process.<anonymous> (cluster.js:692:7),     at process.emit (events.js:129:20),     at handleMessage (child_process.js:324:10),     at Pipe.channel.onread (child_process.js:352:11)]
Error: bind EADDRINUSE
    at exports._errnoException (util.js:746:11)
    at cb (net.js:1178:33)
    at rr (cluster.js:592:14)
    at Worker.<anonymous> (cluster.js:563:9)
    at process.<anonymous> (cluster.js:692:8)
    at process.emit (events.js:129:20)
    at handleMessage (child_process.js:324:10)
    at Pipe.channel.onread (child_process.js:352:11)
error: uncaughtException: bind EADDRINUSE date=Mon Mar 23 2015 09:27:48 GMT-0700 (PDT), pid=3935, uid=202, gid=1349, cwd=/data/beaker/release-20150316105823-4f8dad2, execPath=/usr/bin/nodejs, version=v0.12.0, argv=[/usr/bin/nodejs, /usr/lib/node_modules/pm2/lib/ProcessContainer.js], rss=50786304, heapTotal=58682624, heapUsed=22883944, loadavg=[0.0029296875, 0.0146484375, 0.04541015625], uptime=33718076, trace=[column=11, file=util.js, function=exports._errnoException, line=746, method=_errnoException, native=false, column=33, file=net.js, function=cb, line=1178, method=null, native=false, column=14, file=cluster.js, function=rr, line=592, method=null, native=false, column=9, file=cluster.js, function=, line=563, method=null, native=false, column=8, file=cluster.js, function=, line=692, method=null, native=false, column=20, file=events.js, function=process.emit, line=129, method=emit, native=false, column=10, file=child_process.js, function=handleMessage, line=324, method=null, native=false, column=11, file=child_process.js, function=Pipe.channel.onread, line=352, method=channel.onread, native=false], stack=[Error: bind EADDRINUSE,     at exports._errnoException (util.js:746:11),     at cb (net.js:1178:33),     at rr (cluster.js:592:14),     at Worker.<anonymous> (cluster.js:563:9),     at process.<anonymous> (cluster.js:692:8),     at process.emit (events.js:129:20),     at handleMessage (child_process.js:324:10),     at Pipe.channel.onread (child_process.js:352:11)]
Error: bind EADDRINUSE
    at exports._errnoException (util.js:746:11)
    at cb (net.js:1178:33)
    at rr (cluster.js:592:14)
    at Worker.<anonymous> (cluster.js:563:9)
    at process.<anonymous> (cluster.js:692:8)
    at process.emit (events.js:129:20)
    at handleMessage (child_process.js:324:10)
    at Pipe.channel.onread (child_process.js:352:11)
error: uncaughtException: bind EADDRINUSE date=Mon Mar 23 2015 09:28:41 GMT-0700 (PDT), pid=4164, uid=202, gid=1349, cwd=/data/beaker/release-20150316105823-4f8dad2, execPath=/usr/bin/nodejs, version=v0.12.0, argv=[/usr/bin/nodejs, /usr/lib/node_modules/pm2/lib/ProcessContainer.js], rss=51175424, heapTotal=58682624, heapUsed=22613696, loadavg=[0.22021484375, 0.0849609375, 0.0673828125], uptime=33718129, trace=[column=11, file=util.js, function=exports._errnoException, line=746, method=_errnoException, native=false, column=33, file=net.js, function=cb, line=1178, method=null, native=false, column=14, file=cluster.js, function=rr, line=592, method=null, native=false, column=9, file=cluster.js, function=, line=563, method=null, native=false, column=8, file=cluster.js, function=, line=692, method=null, native=false, column=20, file=events.js, function=process.emit, line=129, method=emit, native=false, column=10, file=child_process.js, function=handleMessage, line=324, method=null, native=false, column=11, file=child_process.js, function=Pipe.channel.onread, line=352, method=channel.onread, native=false], stack=[Error: bind EADDRINUSE,     at exports._errnoException (util.js:746:11),     at cb (net.js:1178:33),     at rr (cluster.js:592:14),     at Worker.<anonymous> (cluster.js:563:9),     at process.<anonymous> (cluster.js:692:8),     at process.emit (events.js:129:20),     at handleMessage (child_process.js:324:10),     at Pipe.channel.onread (child_process.js:352:11)]
TypeError: Cannot read property 'apply' of undefined
    at process.<anonymous> (cluster.js:692:7)
    at process.emit (events.js:129:20)
    at handleMessage (child_process.js:324:10)
    at Pipe.channel.onread (child_process.js:352:11)
error: uncaughtException: Cannot read property 'apply' of undefined date=Mon Mar 23 2015 09:28:44 GMT-0700 (PDT), pid=3935, uid=202, gid=1349, cwd=/data/beaker/release-20150316105823-4f8dad2, execPath=/usr/bin/nodejs, version=v0.12.0, argv=[/usr/bin/nodejs, /usr/lib/node_modules/pm2/lib/ProcessContainer.js], rss=51113984, heapTotal=58682624, heapUsed=23636440, loadavg=[0.22021484375, 0.0849609375, 0.0673828125], uptime=33718132, trace=[column=7, file=cluster.js, function=, line=692, method=null, native=false, column=20, file=events.js, function=process.emit, line=129, method=emit, native=false, column=10, file=child_process.js, function=handleMessage, line=324, method=null, native=false, column=11, file=child_process.js, function=Pipe.channel.onread, line=352, method=channel.onread, native=false], stack=[TypeError: Cannot read property 'apply' of undefined,     at process.<anonymous> (cluster.js:692:7),     at process.emit (events.js:129:20),     at handleMessage (child_process.js:324:10),     at Pipe.channel.onread (child_process.js:352:11)]
TypeError: Cannot read property 'apply' of undefined
    at process.<anonymous> (cluster.js:692:7)
    at process.emit (events.js:129:20)
    at handleMessage (child_process.js:324:10)
    at Pipe.channel.onread (child_process.js:352:11)
error: uncaughtException: Cannot read property 'apply' of undefined date=Mon Mar 23 2015 09:28:54 GMT-0700 (PDT), pid=3935, uid=202, gid=1349, cwd=/data/beaker/release-20150316105823-4f8dad2, execPath=/usr/bin/nodejs, version=v0.12.0, argv=[/usr/bin/nodejs, /usr/lib/node_modules/pm2/lib/ProcessContainer.js], rss=51113984, heapTotal=58682624, heapUsed=23872960, loadavg=[0.1865234375, 0.08203125, 0.06640625], uptime=33718142, trace=[column=7, file=cluster.js, function=, line=692, method=null, native=false, column=20, file=events.js, function=process.emit, line=129, method=emit, native=false, column=10, file=child_process.js, function=handleMessage, line=324, method=null, native=false, column=11, file=child_process.js, function=Pipe.channel.onread, line=352, method=channel.onread, native=false], stack=[TypeError: Cannot read property 'apply' of undefined,     at process.<anonymous> (cluster.js:692:7),     at process.emit (events.js:129:20),     at handleMessage (child_process.js:324:10),     at Pipe.channel.onread (child_process.js:352:11)]`

Also noticed that it's now starting up 8 instances, when I only have 4 cpus?

cat /proc/cpuinfo | grep processor | wc -l
4

$ pm2 ls
┌──────────┬────┬─────────┬──────┬────────┬─────────┬────────┬─────────────┬──────────┐
│ App name │ id │ mode    │ pid  │ status │ restart │ uptime │ memory      │ watching │
├──────────┼────┼─────────┼──────┼────────┼─────────┼────────┼─────────────┼──────────┤
│ myApp   │ 0  │ cluster │ 4164 │ online │ 1       │ 6m     │ 49.367 MB   │ disabled │
│ myApp   │ 1  │ cluster │ 4200 │ online │ 1       │ 6m     │ 49.141 MB   │ disabled │
│ myApp   │ 2  │ cluster │ 4229 │ online │ 1       │ 5m     │ 49.055 MB   │ disabled │
│ myApp   │ 3  │ cluster │ 4254 │ online │ 1       │ 5m     │ 49.008 MB   │ disabled │
│ myApp   │ 4  │ cluster │ 4278 │ online │ 1       │ 5m     │ 48.734 MB   │ disabled │
│ myApp   │ 5  │ cluster │ 4301 │ online │ 1       │ 5m     │ 49.059 MB   │ disabled │
│ myApp   │ 6  │ cluster │ 4332 │ online │ 1       │ 5m     │ 48.918 MB   │ disabled │
│ myApp   │ 7  │ cluster │ 4355 │ online │ 1       │ 4m     │ 49.086 MB   │ disabled │
└──────────┴────┴─────────┴──────┴────────┴─────────┴────────┴─────────────┴──────────┘

as opposed to 0.9.0

● ES6 mode
{ online: true, success: true, pid: 5616, pm2_version: '0.9.0' }
Process launched
┌──────────┬────┬─────────┬──────┬────────┬───────────┬────────┬─────────────┬─────────────┐
│ App name │ id │ mode    │ PID  │ status │ restarted │ uptime │      memory │    watching │
├──────────┼────┼─────────┼──────┼────────┼───────────┼────────┼─────────────┼─────────────┤
│ myApp   │ 0  │ cluster │ 5625 │ online │         0 │ 0s     │ 42.387 MB   │ unactivated │
│ myApp   │ 1  │ cluster │ 5630 │ online │         0 │ 0s     │ 39.734 MB   │ unactivated │
│ myApp   │ 2  │ cluster │ 5639 │ online │         0 │ 0s     │ 30.133 MB   │ unactivated │
│ myApp   │ 3  │ cluster │ 5648 │ online │         0 │ 0s     │ 24.066 MB   │ unactivated │
└──────────┴────┴─────────┴──────┴────────┴───────────┴────────┴─────────────┴─────────────┘

davisford · 2015-03-24T04:44:08Z

Thanks @jshkurti !

jshkurti · 2015-03-24T17:33:49Z

@bigethan What's the result of this on your machine with different Node versions ?

require('os').cpus().length

It might be a Node.js issue.

bigethan · 2015-03-24T20:20:44Z

$ cat cpu_count.js 
var os = require('os');
console.log('Node CPU Count: ' + os.cpus().length);
$ node cpu_count.js 
Node CPU Count: 4
$ node --version
v0.12.0

dcaillibaud · 2015-04-24T01:23:32Z

with node v0.12.2 and pm2 0.12.12, on a cluster of 2 (and a quadcore), on debian wheezy amd64, I have a similar problem :

  console.log('starting app, pid ' +process.pid)
  process.on('message', function (message) {
    console.log('message #' +message +'# of pid ' +process.pid)
    if (message === 'shutdown') {
      // this is never reached
      console.log('launching shutdown')
    }
  });

In the log I found (comment added for this post)

# first start with startOrGracefulReload
2015-04-23 20:16:39 : starting app, pid 25423
  message: '',
2015-04-23 20:16:39 : starting app, pid 25432
  message: '',

# then startOrGracefulReload
2015-04-23 20:16:48 : starting app, pid 25479
  message: '',
2015-04-23 20:16:48 : message #shutdown# of pid 25423
2015-04-23 20:16:49 : starting app, pid 25501
2015-04-23 20:16:49 : message #shutdown# of pid 25432
  message: '',

# then another startOrGracefulReload
2015-04-23 20:16:58 : starting app, pid 25529
2015-04-23 20:16:58 : message #shutdown# of pid 25479
  message: '',
2015-04-23 20:16:59 : starting app, pid 25552
2015-04-23 20:16:59 : message #shutdown# of pid 25501
  message: '',

So the lauch of the app.shutdown() can never be done, it seems the process die before

dcaillibaud · 2015-04-24T16:12:37Z

It seems that pm2 is closing output of process too early, because my app.shutdown() put just after the console.log('launching shutdown') write in another app.log showing that shutdown is processing as expected, but the string "launching shutdown" isn't in the out.log

XadillaX · 2015-06-12T06:30:41Z

I have the same error.

jshkurti · 2015-06-12T10:42:48Z

Hi @XadillaX, give us more details please.

Which version of PM2 and Node.js were you using ?
So, you have an app launched in cluster mode ? How many instances ?
What kind of app ? Is it a http server or something else ?
Provide us some logs and/or screenshots if possible.

Thanks

XadillaX · 2015-06-15T06:50:41Z

PM2:0.12.14
Node.JS:v0.12.2
mode: cluster
┌────────────────────┬────┬─────────┬─────────┬────────┬─────────┬────────┬──────────────┬──────────┐
│ App name           │ id │ mode    │ pid     │ status │ restart │ uptime │ memory       │ watching │
├────────────────────┼────┼─────────┼─────────┼────────┼─────────┼────────┼──────────────┼──────────┤
│ gateway-final      │ 0  │ cluster │ 2214204 │ online │ 0       │ 2D     │ 372.227 MB   │ disabled │
│ gateway-final      │ 1  │ cluster │ 2214217 │ online │ 0       │ 2D     │ 338.832 MB   │ disabled │
│ gateway-final      │ 2  │ cluster │ 2214231 │ online │ 0       │ 2D     │ 408.813 MB   │ disabled │
│ hangout-final      │ 3  │ cluster │ 2214274 │ online │ 0       │ 2D     │ 102.293 MB   │ disabled │
│ hangout-final      │ 4  │ cluster │ 2214279 │ online │ 0       │ 2D     │ 94.652 MB    │ disabled │
│ hangout-final      │ 5  │ cluster │ 2214288 │ online │ 0       │ 2D     │ 98.328 MB    │ disabled │
│ lean-final         │ 6  │ cluster │ 2218455 │ online │ 1       │ 2D     │ 130.352 MB   │ disabled │
│ lean-final         │ 7  │ cluster │ 2218474 │ online │ 1       │ 2D     │ 125.254 MB   │ disabled │
│ lean-final         │ 8  │ cluster │ 2218503 │ online │ 1       │ 2D     │ 130.848 MB   │ disabled │
│ notification-final │ 9  │ cluster │ 2218911 │ online │ 1       │ 2D     │ 143.332 MB   │ disabled │
│ notification-final │ 10 │ cluster │ 2641979 │ online │ 4       │ 8m     │ 88.133 MB    │ disabled │
│ notification-final │ 11 │ cluster │ 2528991 │ online │ 3       │ 21h    │ 322.156 MB   │ disabled │
└────────────────────┴────┴─────────┴─────────┴────────┴─────────┴────────┴──────────────┴──────────┘

They are all HTTP or RPC servers.

And this occurred while restarting of max memory.

2015-06-12 16:22:33: -reload- New worker listening
2015-06-12 16:22:33: Stopping app:gateway-final id:_old_1
2015-06-12 16:22:33: Process with pid 2177211 killed
2015-06-12 17:29:09: [PM2][WORKER] Process 0 restarted because it exceeds --max-memory-restart value
2015-06-12 17:29:09: Starting execution sequence in -cluster mode- for app name:gateway-final id:0
2015-06-12 17:29:09: App name:gateway-final id:0 online
2015-06-12 17:29:12: -reload- New worker listening
2015-06-12 17:29:12: Stopping app:gateway-final id:_old_0
2015-06-12 17:29:12: Process with pid 2185075 killed
2015-06-12 17:35:40: [PM2][WORKER] Process 2 restarted because it exceeds --max-memory-restart value
2015-06-12 17:35:40: Starting execution sequence in -cluster mode- for app name:gateway-final id:2
2015-06-12 17:35:40: App name:gateway-final id:2 online
2015-06-12 17:35:43: -reload- New worker listening
2015-06-12 17:35:43: Stopping app:gateway-final id:_old_2
2015-06-12 17:35:43: Process with pid 2185668 killed
2015-06-12 17:59:43: [PM2][WORKER] Process 1 restarted because it exceeds --max-memory-restart value
2015-06-12 17:59:43: Starting execution sequence in -cluster mode- for app name:gateway-final id:1
2015-06-12 17:59:43: App name:gateway-final id:1 online
2015-06-12 17:59:46: -reload- New worker listening
2015-06-12 17:59:46: Stopping app:gateway-final id:_old_1
2015-06-12 17:59:46: Process with pid 2186559 killed
2015-06-12 19:18:54: [PM2][WORKER] Process 0 restarted because it exceeds --max-memory-restart value
2015-06-12 19:18:54: Starting execution sequence in -cluster mode- for app name:gateway-final id:0
2015-06-12 19:18:54: App name:gateway-final id:0 online
2015-06-12 19:18:57: -reload- New worker listening
2015-06-12 19:18:57: Stopping app:gateway-final id:_old_0
2015-06-12 19:18:57: Process with pid 2194311 killed
2015-06-12 19:19:54: [PM2][WORKER] Process 2 restarted because it exceeds --max-memory-restart value
2015-06-12 19:19:54: Starting execution sequence in -cluster mode- for app name:gateway-final id:2
2015-06-12 19:19:54: App name:gateway-final id:2 online
2015-06-12 19:19:57: -reload- New worker listening
2015-06-12 19:19:57: Stopping app:gateway-final id:_old_2
2015-06-12 19:19:57: Process with pid 2195074 killed
2015-06-12 19:34:56: [PM2][WORKER] Process 1 restarted because it exceeds --max-memory-restart value
2015-06-12 19:34:56: Starting execution sequence in -cluster mode- for app name:gateway-final id:1
2015-06-12 19:34:56: App name:gateway-final id:1 online
2015-06-12 19:34:59: -reload- New worker listening
2015-06-12 19:34:59: Stopping app:gateway-final id:_old_1
2015-06-12 19:34:59: Process with pid 2197872 killed
2015-06-12 19:42:57: [PM2][WORKER] Process 8 restarted because it exceeds --max-memory-restart value
2015-06-12 19:42:57: Starting execution sequence in -cluster mode- for app name:notification-final id:8
2015-06-12 19:42:58: App name:notification-final id:8 online
2015-06-12 19:42:59: -reload- New worker listening
2015-06-12 19:42:59: Stopping app:notification-final id:_old_8
events.js:85
      throw er; // Unhandled 'error' event
            ^
Error: channel closed
    at process.target.send (child_process.js:414:26)
    at SyncWriteStream.write (/opt/nvm/versions/node/v0.12.2/lib/node_modules/pm2/lib/ProcessContainer.js:157:17)
    at Console.log (console.js:55:16)
    at Logger.<anonymous> (/disk/ssd1/yupoo/app/her/notification/node_modules/log4js/lib/appenders/console.js:8:5)
    at Logger.emit (events.js:129:20)
    at Logger.log (/disk/ssd1/yupoo/app/her/notification/node_modules/log4js/lib/logger.js:58:10)
    at Logger.(anonymous function) [as error] (/disk/ssd1/yupoo/app/her/notification/node_modules/log4js/lib/logger.js:77:30)
    at process.<anonymous> (/disk/ssd1/yupoo/app/her/notification/bin/her-notification:5:13)
    at process.emit (events.js:129:20)
    at process._fatalException (node.js:236:26)
    at process.emit (events.js:107:17)
    at process.target.send (child_process.js:414:12)
    at SyncWriteStream.write (/opt/nvm/versions/node/v0.12.2/lib/node_modules/pm2/lib/ProcessContainer.js:157:17)
    at Console.log (console.js:55:16)
    at Logger.<anonymous> (/disk/ssd1/yupoo/app/her/notification/node_modules/log4js/lib/appenders/console.js:8:5)
    at Logger.emit (events.js:129:20)
2015-06-12 19:42:59: Process with pid 2170190 still not killed, retrying...
2015-06-12 19:42:59: Process with pid 2170190 killed
2015-06-12 20:16:32: [PM2][WORKER] Process 6 restarted because it exceeds --max-memory-restart value
2015-06-12 20:16:32: Starting execution sequence in -cluster mode- for app name:notification-final id:6
2015-06-12 20:16:32: App name:notification-final id:6 online
2015-06-12 20:16:33: -reload- New worker listening
2015-06-12 20:16:33: Stopping app:notification-final id:_old_6
2015-06-12 20:16:34: Process with pid 2186197 still not killed, retrying...
2015-06-12 20:16:34: Process with pid 2186197 killed
cluster.js:692
    fn.apply(worker, arguments);
      ^
TypeError: Cannot read property 'apply' of undefined
    at ChildProcess.<anonymous> (cluster.js:692:7)
    at ChildProcess.emit (events.js:129:20)
    at handleMessage (child_process.js:324:10)
    at Pipe.channel.onread (child_process.js:352:11)
events.js:85
      throw er; // Unhandled 'error' event
            ^
Error: channel closed
    at process.target.send (child_process.js:414:26)
    at SyncWriteStream.write (/opt/nvm/versions/node/v0.12.2/lib/node_modules/pm2/lib/ProcessContainer.js:157:17)
    at Console.log (console.js:55:16)
    at Logger.<anonymous> (/disk/ssd1/yupoo/app/her/notification/node_modules/log4js/lib/appenders/console.js:8:5)
    at Logger.emit (events.js:129:20)
    at Logger.log (/disk/ssd1/yupoo/app/her/notification/node_modules/log4js/lib/logger.js:58:10)
    at Logger.(anonymous function) [as error] (/disk/ssd1/yupoo/app/her/notification/node_modules/log4js/lib/logger.js:77:30)
    at process.<anonymous> (/disk/ssd1/yupoo/app/her/notification/bin/her-notification:5:13)
    at process.emit (events.js:129:20)
    at process._fatalException (node.js:236:26)
    at process.emit (events.js:107:17)
    at process.target.send (child_process.js:414:12)
    at sendHelper (cluster.js:676:8)
    at send (cluster.js:663:5)
    at Object.close (cluster.js:609:7)
    at Server.close (net.js:1374:18)
events.js:85
      throw er; // Unhandled 'error' event
            ^
Error: channel closed
    at process.target.send (child_process.js:414:26)
    at SyncWriteStream.write (/opt/nvm/versions/node/v0.12.2/lib/node_modules/pm2/lib/ProcessContainer.js:157:17)
    at Console.log (console.js:55:16)
    at Logger.<anonymous> (/disk/ssd1/yupoo/app/her/notification/node_modules/log4js/lib/appenders/console.js:8:5)
    at Logger.emit (events.js:129:20)
    at Logger.log (/disk/ssd1/yupoo/app/her/notification/node_modules/log4js/lib/logger.js:58:10)
    at Logger.(anonymous function) [as error] (/disk/ssd1/yupoo/app/her/notification/node_modules/log4js/lib/logger.js:77:30)
    at process.<anonymous> (/disk/ssd1/yupoo/app/her/notification/bin/her-notification:5:13)
    at process.emit (events.js:129:20)
    at process._fatalException (node.js:236:26)
    at process.emit (events.js:107:17)
    at process.target.send (child_process.js:414:12)
    at sendHelper (cluster.js:676:8)
    at send (cluster.js:663:5)
    at Object.close (cluster.js:609:7)
    at Server.close (net.js:1374:18)
events.js:85
      throw er; // Unhandled 'error' event
            ^
Error: channel closed
    at process.target.send (child_process.js:414:26)
    at SyncWriteStream.write (/opt/nvm/versions/node/v0.12.2/lib/node_modules/pm2/lib/ProcessContainer.js:142:17)
    at Console.warn (console.js:63:16)
    at Console.log (/disk/ssd1/yupoo/app/her/gateway/node_modules/bucker/lib/console.js:37:5)
    at /disk/ssd1/yupoo/app/her/gateway/node_modules/bucker/index.js:205:30
    at Array.forEach (native)
    at Bucker._runHandlers (/disk/ssd1/yupoo/app/her/gateway/node_modules/bucker/index.js:203:11)
    at Bucker.error (/disk/ssd1/yupoo/app/her/gateway/node_modules/bucker/index.js:268:10)
    at process.<anonymous> (/disk/ssd1/yupoo/app/her/gateway/app.js:51:12)
    at process.emit (events.js:129:20)
    at process._fatalException (node.js:236:26)
    at process.emit (events.js:107:17)
    at process.target.send (child_process.js:414:12)
    at SyncWriteStream.write (/opt/nvm/versions/node/v0.12.2/lib/node_modules/pm2/lib/ProcessContainer.js:157:17)
    at Console.log (console.js:55:16)
    at Console.log (/disk/ssd1/yupoo/app/her/gateway/node_modules/bucker/lib/console.js:37:5)
events.js:85
      throw er; // Unhandled 'error' event
            ^
Error: channel closed
    at process.target.send (child_process.js:414:26)
    at SyncWriteStream.write (/opt/nvm/versions/node/v0.12.2/lib/node_modules/pm2/lib/ProcessContainer.js:142:17)
    at Console.warn (console.js:63:16)
    at Console.log (/disk/ssd1/yupoo/app/her/gateway/node_modules/bucker/lib/console.js:37:5)
    at /disk/ssd1/yupoo/app/her/gateway/node_modules/bucker/index.js:205:30
    at Array.forEach (native)
    at Bucker._runHandlers (/disk/ssd1/yupoo/app/her/gateway/node_modules/bucker/index.js:203:11)
    at Bucker.error (/disk/ssd1/yupoo/app/her/gateway/node_modules/bucker/index.js:268:10)
    at process.<anonymous> (/disk/ssd1/yupoo/app/her/gateway/app.js:51:12)
    at process.emit (events.js:129:20)
    at process._fatalException (node.js:236:26)
    at process.emit (events.js:107:17)
    at process.target.send (child_process.js:414:12)
    at SyncWriteStream.write (/opt/nvm/versions/node/v0.12.2/lib/node_modules/pm2/lib/ProcessContainer.js:157:17)
    at Console.log (console.js:55:16)
    at Console.log (/disk/ssd1/yupoo/app/her/gateway/node_modules/bucker/lib/console.js:37:5)
events.js:85
      throw er; // Unhandled 'error' event
            ^
Error: channel closed
    at process.target.send (child_process.js:414:26)
    at SyncWriteStream.write (/opt/nvm/versions/node/v0.12.2/lib/node_modules/pm2/lib/ProcessContainer.js:142:17)
    at Console.warn (console.js:63:16)
    at Console.log (/disk/ssd1/yupoo/app/her/gateway/node_modules/bucker/lib/console.js:37:5)
    at /disk/ssd1/yupoo/app/her/gateway/node_modules/bucker/index.js:205:30
    at Array.forEach (native)
    at Bucker._runHandlers (/disk/ssd1/yupoo/app/her/gateway/node_modules/bucker/index.js:203:11)
    at Bucker.error (/disk/ssd1/yupoo/app/her/gateway/node_modules/bucker/index.js:268:10)
    at process.<anonymous> (/disk/ssd1/yupoo/app/her/gateway/app.js:51:12)
    at process.emit (events.js:129:20)
    at process._fatalException (node.js:236:26)
    at process.emit (events.js:107:17)
    at process.target.send (child_process.js:414:12)
    at SyncWriteStream.write (/opt/nvm/versions/node/v0.12.2/lib/node_modules/pm2/lib/ProcessContainer.js:157:17)
    at Console.log (console.js:55:16)
    at Console.log (/disk/ssd1/yupoo/app/her/gateway/node_modules/bucker/lib/console.js:37:5)
events.js:85
      throw er; // Unhandled 'error' event
            ^
Error: channel closed
    at process.target.send (child_process.js:414:26)
    at SyncWriteStream.write (/opt/nvm/versions/node/v0.12.2/lib/node_modules/pm2/lib/ProcessContainer.js:157:17)
    at Console.log (console.js:55:16)
    at Logger.<anonymous> (/disk/ssd1/yupoo/app/her/notification/node_modules/log4js/lib/appenders/console.js:8:5)
    at Logger.emit (events.js:129:20)
    at Logger.log (/disk/ssd1/yupoo/app/her/notification/node_modules/log4js/lib/logger.js:58:10)
    at Logger.(anonymous function) [as error] (/disk/ssd1/yupoo/app/her/notification/node_modules/log4js/lib/logger.js:77:30)
    at process.<anonymous> (/disk/ssd1/yupoo/app/her/notification/bin/her-notification:5:13)
    at process.emit (events.js:129:20)
    at process._fatalException (node.js:236:26)
    at process.emit (events.js:107:17)
    at process.target.send (child_process.js:414:12)
    at sendHelper (cluster.js:676:8)
    at send (cluster.js:663:5)
    at Object.close (cluster.js:609:7)
    at Server.close (net.js:1374:18)
2015-06-12 20:19:32: [PM2][WORKER] Started with refreshing interval: 30000
2015-06-12 20:19:32: [[[[ PM2/God daemon launched ]]]]
2015-06-12 20:19:32: BUS system [READY] on port /root/.pm2/pub.sock
2015-06-12 20:19:32: RPC interface [READY] on port /root/.pm2/rpc.sock
2015-06-12 20:19:32: Starting execution sequence in -cluster mode- for app name:gateway-final id:0
2015-06-12 20:19:32: App name:gateway-final id:0 online
2015-06-12 20:19:32: Starting execution sequence in -cluster mode- for app name:gateway-final id:1
2015-06-12 20:19:32: App name:gateway-final id:1 online
2015-06-12 20:19:32: Starting execution sequence in -cluster mode- for app name:gateway-final id:2
2015-06-12 20:19:32: App name:gateway-final id:2 online
2015-06-12 20:19:39: Starting execution sequence in -cluster mode- for app name:hangout-final id:3
2015-06-12 20:19:39: App name:hangout-final id:3 online
2015-06-12 20:19:39: Starting execution sequence in -cluster mode- for app name:hangout-final id:4
2015-06-12 20:19:39: App name:hangout-final id:4 online
2015-06-12 20:19:39: Starting execution sequence in -cluster mode- for app name:hangout-final id:5
2015-06-12 20:19:39: App name:hangout-final id:5 online
2015-06-12 20:19:46: Starting execution sequence in -cluster mode- for app name:lean-final id:6
2015-06-12 20:19:46: App name:lean-final id:6 online
2015-06-12 20:19:46: Starting execution sequence in -cluster mode- for app name:lean-final id:7
2015-06-12 20:19:46: App name:lean-final id:7 online
2015-06-12 20:19:46: Starting execution sequence in -cluster mode- for app name:lean-final id:8

The PM2 God daemon crashed with no notification. We found the daemon is mission and then we restart the daemon manully. Just as the log said.

@jshkurti

jshkurti · 2015-06-19T12:49:21Z

0ab7248

Should fix it.
npm i -g Unitech/PM2#development

jshkurti · 2015-06-19T12:49:28Z

@XadillaX

XadillaX · 2015-06-19T15:13:19Z

@jshkurti Thx, and i will check it later.

jworm7 · 2016-02-18T18:00:26Z

I think I'm facing a similar issue where when pm2 tries to reload based on a watch but I sporadically get several EADDRINUSE errors until the port opens up from the previous PM2 process. Is there a way to gracefully close the server of the original process before restarting?

Unitech · 2016-10-31T09:39:01Z

Every problem listed on that issue will be fixed by upgrading to the latest pm2 version
New Graceful Stop system: http://pm2.keymetrics.io/docs/usage/signals-clean-restart/

$ npm install pm2 -g
$ pm2 update

pm2.gracefulReload() is now pm2.reload() Unitech/pm2#1101

jshkurti self-assigned this Mar 16, 2015

jshkurti added the S: In progress label Apr 24, 2015

XadillaX mentioned this issue Jun 16, 2015

An error about cluster.js nodejs/node-v0.x-archive#25529

Closed

Unitech unassigned jshkurti Oct 1, 2015

Unitech mentioned this issue Oct 29, 2016

Stop/Reload methods simplification + harden SIGINT handling #2481

Closed

Unitech closed this as completed Oct 31, 2016

jphilung added a commit to jphilung/pm2-githook that referenced this issue Nov 24, 2022

Fix deprecated function

a8bb04a

pm2.gracefulReload() is now pm2.reload() Unitech/pm2#1101

This was referenced Nov 24, 2022

Fix deprecated function jphilung/pm2-githook#1

Merged

Fix deprecated function vmarchaud/pm2-githook#25

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Errors when using gracefulReload (or reload) #1101

Errors when using gracefulReload (or reload) #1101

bigethan commented Mar 16, 2015

jshkurti commented Mar 16, 2015

bigethan commented Mar 16, 2015

bigethan commented Mar 18, 2015

jshkurti commented Mar 18, 2015

bigethan commented Mar 18, 2015

jshkurti commented Mar 18, 2015

davisford commented Mar 20, 2015

jshkurti commented Mar 20, 2015

jshkurti commented Mar 20, 2015

jshkurti commented Mar 20, 2015

davisford commented Mar 20, 2015

bigethan commented Mar 20, 2015

jshkurti commented Mar 20, 2015

jshkurti commented Mar 20, 2015

bigethan commented Mar 20, 2015

jshkurti commented Mar 23, 2015

bigethan commented Mar 23, 2015

davisford commented Mar 24, 2015

jshkurti commented Mar 24, 2015

bigethan commented Mar 24, 2015

dcaillibaud commented Apr 24, 2015

dcaillibaud commented Apr 24, 2015

XadillaX commented Jun 12, 2015

jshkurti commented Jun 12, 2015

XadillaX commented Jun 15, 2015

jshkurti commented Jun 19, 2015

jshkurti commented Jun 19, 2015

XadillaX commented Jun 19, 2015

jworm7 commented Feb 18, 2016

Unitech commented Oct 31, 2016 •

edited

Errors when using gracefulReload (or reload) #1101

Errors when using gracefulReload (or reload) #1101

Comments

bigethan commented Mar 16, 2015

jshkurti commented Mar 16, 2015

bigethan commented Mar 16, 2015

bigethan commented Mar 18, 2015

jshkurti commented Mar 18, 2015

bigethan commented Mar 18, 2015

jshkurti commented Mar 18, 2015

davisford commented Mar 20, 2015

jshkurti commented Mar 20, 2015

jshkurti commented Mar 20, 2015

jshkurti commented Mar 20, 2015

davisford commented Mar 20, 2015

bigethan commented Mar 20, 2015

jshkurti commented Mar 20, 2015

jshkurti commented Mar 20, 2015

bigethan commented Mar 20, 2015

jshkurti commented Mar 23, 2015

bigethan commented Mar 23, 2015

davisford commented Mar 24, 2015

jshkurti commented Mar 24, 2015

bigethan commented Mar 24, 2015

dcaillibaud commented Apr 24, 2015

dcaillibaud commented Apr 24, 2015

XadillaX commented Jun 12, 2015

jshkurti commented Jun 12, 2015

XadillaX commented Jun 15, 2015

jshkurti commented Jun 19, 2015

jshkurti commented Jun 19, 2015

XadillaX commented Jun 19, 2015

jworm7 commented Feb 18, 2016

Unitech commented Oct 31, 2016 • edited

Unitech commented Oct 31, 2016 •

edited