PM2 API ignores maxRestarts and restartDelay configuration

[kharandziuk]

So, I have a worker which tries to grab some data from web. I want to restart it on every fail and log the error. To monitor the worker process I use pm2. The simplified sample looks like:

index.js

const pm2 = require('pm2');

pm2.connect(function(err) {
    if (err) {
          console.error(err);
          process.exit(2);
        }
    pm2.start({
          script    : 'populate.js',
          exec_mode : 'cluster',
          instances : 1,
          autorestart: true,
          max_memory_restart : '100M',
          max_restarts: 1000 // or maxRestarts: 1000 documentation is inconsistent here
    }, function(err) {
      if (err) return console.error('Error while launching applications', err.stack || err);
      console.log('PM2 and application has been succesfully started');
      pm2.launchBus(function(err, bus) {
        console.log('[PM2] Log streaming started');
        bus.on('log:out', function(packet) {
         console.log('[App:%s] %s', packet.process.name, packet.data);
        });
        bus.on('log:err', function(packet) {
          console.error('[App:%s][Err] %s', packet.process.name, packet.data);
        });
      });
    });
});

populate.js

const Promise = require('bluebird');

function populate() { // this function is just for illustration purpose
  return Promise.delay(500)
    .then(()=> Math.random() >= 0.5)
    .then(flag => {
      if(flag) {
        console.log('populates db')
        return populate()
      } else {
        throw new Error('something wrong')
      }
    })

}
populate()

But when I run script it doesn't restart scrapper more then 3 times(I expect 1000 times)

>    node index.js

PM2 and application has been succesfully started
[PM2] Log streaming started
[App:populate] populates db

[App:populate][Err]
You have triggered an unhandledRejection, you may
[App:populate][Err]
You have triggered an unhandledRejection, you may
[App:populate] populates db

[App:populate][Err]
You have triggered an unhandledRejection, you may
[App:populate][Err]
You have triggered an unhandledRejection, you may

Software versions used

OS         : os x 10.10.5
node.js    : v6.3.1
PM2        : pm2@2.4.0

[vmarchaud]

Are you sure that your application is actually restarted ? Cause the throwing an error inside a promise might only cause a warning (the one you can ready inside your logs : You have triggered an unhandledRejection).

[kharandziuk]

Yep, you are right. Thanks! Basically it's a reason why it doesn't work. If I simplify populate to something like:

const Promise = require('bluebird');

function populate() {
  const flag = Math.random() >= 0.5
  if(flag) {
    console.log('populate')
    setTimeout(populate, 500)
  } else {
    throw new Error('some error')
  }
}
populate()

it works

And the other thing: In the original promise example application stop with 0 code. Is it true that pm2 restarts process only in case when it stops with non-zero code?

[kharandziuk]

if I add

process.on("unhandledRejection", function(reason, promise) {
  process.exit(1)
});

to the first sample. it works as expected

[vmarchaud]

No it isn't, pm2 restart your application in any case (but respecting max_restart configuration of course). See this stackoverflow for unhandledRejection : http://stackoverflow.com/questions/40500490/what-is-unhandled-promise-rejection

[kharandziuk]

Thanks @vmarchaud . but it doesn't. BTW: do you mean: max_restarts? I change populate to this:

>cat populate.js
function populate() {
  console.log('populate')
}
populate()

now when I run I see one populate in log:

node index.js
PM2 and application has been succesfully started
[PM2] Log streaming started
[App:populate] populate

but I expect to see 1000 of them.

Configuration looks like this:

pm2.start({
          script: 'populate.js',
          exec_mode : 'cluster',
          instances : 1,
          autorestart: true,
          max_memory_restart: '100M',
          max_restarts: 1000, // I tried all of them max_restarts, max_restart and maxRestart
          restartDelay: 500
    }

Or what am I doing wrong?

[vmarchaud]

Are you sure that your application exit ? Run it without PM2 to verify that.

[kharandziuk]

node populate.js ; echo $?
populate
0

[vmarchaud]

From the doc here, you should use maxRestarts and minUptime

[kharandziuk]

does it work for you? I changed the populate to

>cat populate.js
function populate() {
  console.log('populate')
}

setTimeout(
  populate,
  4000 // much bigger then minUptime
)

and index.js to

const pm2 = require('pm2');

pm2.connect(function(err) {
    if (err) {
          console.error(err);
          process.exit(2);
        }
    pm2.start({
          script: '_populate.js',
          exec_mode : 'cluster',
          instances : 1,
          autorestart: true,
          max_memory_restart: '100M',
          maxRestarts: 500,
          minUptime: 100
    },

and I observe the same behaviour

If i change populate to:

function populate() {
  console.log('populate')
  process.exit(1)
}

it works as expected

[kharandziuk]

hey, the situation is a little bit different. It isn't because zero-code but somehow related to it. Look for the difference between zeroExplicit and zero files. Can you provide an idea what is the expected behavior for zero.js file?

>cat index.js
const pm2 = require('pm2')

function errorHandler(err) {
    if (err) return console.error('Error while launching applications', err.stack || err)
    console.log('PM2 and application has been succesfully started')
}

pm2.connect(function(err) {
  if (err) {
    console.error(err)
    process.exit(2)
  }
  ['zeroExplicit.js', 'zero.js', 'nonZero.js'].forEach(function(name) {
    pm2.start({
      script: name,
      exec_mode : 'cluster',
      instances : 1,
      autorestart: true,
      max_memory_restart: '100M',
      maxRestarts: 500,
      minUptime: 100
    }, errorHandler)
  })
  pm2.launchBus(function(err, bus) {
    console.log('[PM2] Log streaming started')
    bus.on('log:out', function(packet) {
      console.log('[App:%s] %s', packet.process.name, packet.data)
    })
    bus.on('log:err', function(packet) {
      console.error('[App:%s][Err] %s', packet.process.name, packet.data.substring(0, 50))
    })
  })
})

>cat zero.js nonZero.js zeroExplicit.js
function populate() {
  console.log('zero')
}

setTimeout(
  populate,
  2000
)
function populate() {
  console.log('nonZero')
  process.exit(1)
}

setTimeout(
  populate,
  2000
)
function populate() {
  console.log('zeroExplicit')
  process.exit(0)
}

setTimeout(
  populate,
  2000
)

and the result is:

>node index.js

[PM2] Log streaming started
PM2 and application has been succesfully started
PM2 and application has been succesfully started
PM2 and application has been succesfully started
[App:zero] zero <---------------------- APPEARS ONLY ONCE

[App:zeroExplicit] zeroExplicit

[App:nonZero] nonZero

[App:zeroExplicit] zeroExplicit

[App:nonZero] nonZero

[App:zeroExplicit] zeroExplicit

[App:nonZero] nonZero

[App:zeroExplicit] zeroExplicit

[App:nonZero] nonZero

> cat package.json
{
  "dependencies": {
    "bluebird": "^3.4.7",
    "express": "^4.14.1",
    "pm2": "^2.4.0"
  }
}