PM2 revived my apps so well that I couldn't see the outages

I run about ten sites on my personal server. All of them run under PM2, and I built my own monitoring dashboard with HTTP health checks on it. It sends a request to each service every 3 or 5 minutes and checks that a 200 comes back.

The dashboard was always green. So I assumed everything was running fine.

Then I happened to look at pm2 list.

┌────┬─────────────────┬─────────┬──────┬───────────┐
│ id │ name            │ uptime  │ ↺    │ status    │
├────┼─────────────────┼─────────┼──────┼───────────┤
│ 1  │ game-server     │ 9h      │ 96   │ online    │
│ 6  │ travel-server   │ 17h     │ 82   │ online    │
│ 9  │ ieum-server     │ 18h     │ 15   │ online    │
└────┴─────────────────┴─────────┴──────┴───────────┘

uptime has a column right next to it with a circular arrow on it, and that's the restart count. game-server was at 96 and travel-server at 82.

On September 15, as I'm revising this post, I ran the same command again and game-server is at 113 and travel-server at 99. That means each of them died 17 more times in the ten days or so since I wrote it. The health check screen stayed green the whole time.

Every one of them was online, and the health check had never once recorded a failure.

A health check can't catch this

Thinking about it, that was obvious.

When an app dies, PM2 brings it back within a second. The health check sends one request per service every 3 or 5 minutes. If the app dies and comes back in between, it's already returning a healthy 200 by the time the health check arrives.

App crash ──┐
            │ PM2 restarts it within 1 second
            └──> healthy

Health check        ^              ^
(every 3 to 5 min)  200 OK         200 OK

Even if an app dies and comes back dozens of times a day, the health check graph shows 100% uptime. The health check isn't sloppy, it just can't catch this by design.

It's not completely invisible to users. Whoever sends a request at the moment of the crash gets a 502. But that only lasts a few seconds, so no signal ever reaches me.

So I decided to build a separate monitor that looks at "is it quietly dying over and over" instead of "is it responding".

Reading PM2's state

PM2 dumps its whole state as JSON with jlist.

$ pm2 jlist | jq '.[0].pm2_env | {status, restart_time, pm_err_log_path}'
{
  "status": "online",
  "restart_time": 96,
  "pm_err_log_path": "/home/user/.pm2/logs/game-server-error.log"
}

Everything I need is there. The status, the restart count, and even the error log path.

The monitoring server runs as the same user as PM2, so it can just read this without any extra permissions. I didn't even need to add the pm2 npm package as a dependency, because exec was enough.

function pm2List() {
  return new Promise((resolve) => {
    exec('pm2 jlist', { timeout: 15000, maxBuffer: 20 * 1024 * 1024 }, (err, stdout) => {
      if (err) return resolve(null);
      try { resolve(JSON.parse(stdout)); } catch { resolve(null); }
    });
  });
}

The most important decision here

At first I was going to write it like this.

if (restart_time >= threshold) alert();   // <- don't do this

With this, game-server fires alerts forever from the moment I turn it on. It's already at 96. And even if it never dies once in the next two months, it's still 96. restart_time is a cumulative counter, so it says nothing at all about "is there a problem right now".

What I want to know isn't "how many times has it died in total" but "is it dying right now". So I decided to store a snapshot of the counter every 60 seconds and judge only by the increase within a window.

CREATE TABLE pm2_snapshots (
  id           INT AUTO_INCREMENT PRIMARY KEY,
  name         VARCHAR(100) NOT NULL,
  restart_time INT NOT NULL,
  status       VARCHAR(20),
  recorded_at  DATETIME DEFAULT CURRENT_TIMESTAMP,
  INDEX idx_name_time (name, recorded_at)
);

The check works like this.

async function restartsInWindow(name, current, windowMinutes) {
  const [rows] = await pool.execute(
    `SELECT restart_time FROM pm2_snapshots
      WHERE name = ? AND recorded_at <= DATE_SUB(NOW(), INTERVAL ? MINUTE)
      ORDER BY recorded_at DESC LIMIT 1`,
    [name, windowMinutes]
  );
  if (!rows.length) return null;              // no baseline, no verdict
  return Math.max(0, current - rows[0].restart_time);
}

"It was 96 ten minutes ago and it's 103 now. So it died 7 times in 10 minutes." That's the signal I wanted. Whether the total is 96 or 9600 stops mattering.

No baseline, no verdict

The return null part of the code above turned out to matter more than I expected.

Right after the monitor is turned on, or when a process has just been started, there is no snapshot from 10 minutes ago. If I treated that as 0 because there's nothing to compare against, or judged by the cumulative value instead, everything would be a false positive.

So it returns null and the caller skips the check entirely. On screen it shows as building baseline. That means checks only start 10 minutes after the monitor is turned on, and I think that's right. Saying nothing is better than sending an alert based on a guess when I don't know.

Thanks to this, when I first turned the monitor on, all ten processes, including the one with 96 cumulative restarts, registered quietly without a single false positive.

Alert only when the state changes

If I sent an email every time the condition matched, I'd get one every 60 seconds. So each process holds a state, ok / crashloop / down, and an email goes out once, only at the moment of a transition.

if (state === prevState) return;   // do nothing if it hasn't changed

One email when it falls into a crash loop, one when it stabilizes. Even if it keeps dying in between, nothing more is sent.

I added a check for stopped processes as well. If status is anything other than online (stopped, errored), that gets reported too.

Putting the error log in the email

This is the part I'm happiest with now that it's built.

If all I get is an alert saying "game-server is in a crash loop", I still have to log in to the server and run pm2 logs. That's pretty annoying in the middle of the night.

But jlist already includes pm_err_log_path. So I read the tail of that file and put it in the email body.

async function errorLogTail(path, lines = 18, maxBytes = 16 * 1024) {
  let fh;
  try {
    fh = await fs.open(path, 'r');
    const { size } = await fh.stat();
    const start = Math.max(0, size - maxBytes);   // last 16KB only
    const buf = Buffer.alloc(Math.min(maxBytes, size));
    await fh.read(buf, 0, buf.length, start);
    return buf.toString('utf8').split('\n').filter(Boolean).slice(-lines).join('\n');
  } catch {
    return null;
  } finally {
    await fh?.close().catch(() => {});
  }
}

The log files grow to tens of MB, so reading them whole is out. It reads only the last 16KB and cuts out the final 18 lines.

As a result, the alert arrives looking like this.

PM2 revived my apps so well that I couldn't see the outages image 1

From the email alone I can tell right away that db/game.js:298 is reading undefined, and that there's a PROTOCOL_PACKETS_OUT_OF_ORDER below it too. For reference, this is a symptom of the old mysql driver failing to revive a dropped connection, and it usually goes away after switching to a mysql2 pool.

The screen

I added a page to the dashboard as well.

PM2 revived my apps so well that I couldn't see the outages image 2

The most important column in the table is Recent restarts. Next to 7/3 it says 10 min, which means "it died 7 times within 10 minutes and the threshold is 3". Compare it with the Total column beside it and it's immediately clear why judging by the total is wrong. game-server has 112 restarts in total, but the problem is that 7 of them are packed into the last 10 minutes.

I made the threshold editable by clicking it right in the table. That's because every process behaves differently. For some apps a few restarts on every deploy is normal, so the threshold has to go up, and for others dying even once is odd, so it has to go down.

Testing

I can't trust something like this until I've actually made it blow up. I wrote a process that lives for 5 seconds and then dies, and put it on PM2.

// crashtest.js
console.log('start');
setTimeout(() => {
  console.error('intentional crash');
  process.exit(1);
}, 5000);
$ pm2 start crashtest.js --name crash-test --restart-delay=1000

I shortened the window to 1 minute and waited, and this showed up in the log.

[PM2] crash-test crash loop - 10 restarts in the last 1 min (14 total)

The email came too. Then I swapped in code that doesn't die and restarted it,

[PM2] crash-test stabilized - restarts stopped (lasted 2 min)

and confirmed the recovery alert as well. And during that time the ten real processes didn't produce a single false positive. That's with the ones at 96 and 82 cumulative restarts in the mix. Judging by the increase within a window worked the way it should.

It also caught something for real within a few days. On the night of September 13, travel-server twice went through a stretch of dying three times within 10 minutes, and the alert history recorded it like this.

23:08:07  travel-server crash loop - 3 restarts in the last 10 min (94 total)
23:12:08  travel-server stabilized - restarts stopped (lasted 4 min)
23:39:07  travel-server crash loop - 3 restarts in the last 10 min (99 total)
23:43:07  travel-server stabilized - restarts stopped (lasted 4 min)

Over the same period the health check saw a 503 exactly once during the first loop and didn't fail a single time during the second. PM2 revived the app right away, so it was already fine by the time the check arrived. The blind spot I described at the top of this post was reproduced exactly.

One thing to know

pm2 kill followed by a fresh start resets restart_time to 0. Then it becomes "the previous snapshot is 96 but the current value is 0", and the increase comes out negative.

A negative number doesn't cross the threshold, so no wrong alert goes out, but the baseline gets tangled once the counter starts climbing again. I guarded against that with one line, Math.max(0, ...).

What I'm left with

When adding monitoring, it's easy to check only "is the service alive". That's how I built mine too, and it isn't wrong. But when there's an automatic recovery mechanism, that mechanism hides the problem. PM2 did its job so well that I knew nothing for months.

The restart counter was there the whole time. Right where a single pm2 list would show it. But a number nobody looks at is the same as a number that doesn't exist.

If you're using PM2, I'd suggest running it once right now.

pm2 list

uptime has the restart count column next to it, and if there's a two-digit number in it, something has been quietly dying all this time.