PM2 revived my apps so well that I couldn't see the outages
The health check kept returning 200 while the restart count sat at 96. Why crash loops should be judged by the increase within a window, not the cumulative total.
#PM2 #Monitoring #Node.js #Operations #Incident response
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. 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. 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.