PM2가 너무 잘 되살려서 장애를 못 보고 있었다
개인 서버에 사이트를 열 개쯤 올려두고 쓴다. 전부 PM2로 돌리고, 모니터링 대시보드도 직접 만들어서 HTTP 헬스체크를 붙여놨다. 서비스마다 3분이나 5분 간격으로 요청을 보내서 200이 오는지 확인한다.
대시보드는 늘 초록불이었다. 그래서 잘 돌아가는 줄 알았다.
그러다 우연히 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 바로 옆, 돌아가는 화살표가 그려진 열이 재시작 횟수다. game-server가 96회, travel-server가 82회였다.
이 글을 다시 손보는 9월 15일에 같은 명령을 쳐보니 game-server는 113회, travel-server는 99회다. 글을 쓰고 열흘 남짓 지나는 동안 둘 다 17번씩 더 죽었다는 뜻이다. 그동안 헬스체크 화면은 계속 초록색이었다.
전부 online이고, 헬스체크는 그동안 한 번도 실패로 잡은 적이 없었다.
헬스체크는 이걸 못 잡는다
생각해보면 당연했다.
앱이 죽으면 PM2가 1초 안에 되살린다. 헬스체크는 서비스마다 3분이나 5분에 한 번 요청을 보낸다. 그 사이에 앱이 죽었다 살아나면, 헬스체크가 도착할 때쯤엔 이미 멀쩡히 200을 돌려준다.
앱 크래시 ──┐
│ PM2가 1초 만에 재시작
└──▶ 정상
헬스체크 ↑ ↑
(3~5분 간격) 200 OK 200 OK앱이 하루에 수십 번 죽었다 살아나도 헬스체크 그래프는 100% 가동률로 나온다. 구조적으로 못 잡는 거지 헬스체크가 부실한 게 아니다.
사용자 입장에서 아예 안 보이는 건 아니다. 죽는 그 순간에 요청을 보낸 사람은 502를 받는다. 다만 그게 몇 초짜리라 나한테는 아무 신호도 안 온다.
그래서 "응답하는가"가 아니라 "조용히 계속 죽고 있는가"를 보는 감시를 따로 만들기로 했다.
PM2 상태 읽어오기
PM2는 jlist로 전체 상태를 JSON으로 뱉는다.
$ pm2 jlist | jq '.[0].pm2_env | {status, restart_time, pm_err_log_path}'
{
"status": "online",
"restart_time": 96,
"pm_err_log_path": "/home/사용자/.pm2/logs/game-server-error.log"
}필요한 게 다 있다. 상태, 재시작 횟수, 그리고 에러 로그 경로까지.
모니터링 서버가 PM2와 같은 사용자로 돌기 때문에 별도 권한 없이 그냥 읽힌다. pm2 npm 패키지를 의존성에 추가할 필요도 없이 exec로 충분했다.
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); }
});
});
}여기서 제일 중요한 결정
처음엔 이렇게 짜려고 했다.
if (restart_time >= 임계치) 알림(); // ← 이러면 안 된다
이러면 game-server가 켜자마자 영구히 알림을 뿜는다. 이미 96회니까. 그리고 앞으로 두 달간 한 번도 안 죽어도 계속 96회다. restart_time은 누적 카운터라서 "지금 문제가 있는가"를 전혀 말해주지 않는다.
내가 알고 싶은 건 "총 몇 번 죽었나"가 아니라 "지금 죽고 있는 중인가"다. 그래서 60초마다 카운터를 스냅샷으로 쌓고, 구간 내 증가량으로만 판정하기로 했다.
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) );
판정은 이렇게 한다.
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; // 기준이 없으면 판정하지 않는다
return Math.max(0, current - rows[0].restart_time);
}"10분 전엔 96이었는데 지금은 103이다. 그러니까 10분 동안 7번 죽었다." 이게 내가 원하던 신호다. 누적이 96이든 9600이든 상관없어진다.
기준이 없으면 판정하지 않는다
위 코드에서 return null 부분이 생각보다 중요했다.
감시를 막 켰을 때나 프로세스를 새로 띄웠을 때는 10분 전 스냅샷이 존재하지 않는다. 이때 비교 대상이 없다고 0으로 처리하거나, 누적값으로 대신 판정하면 전부 오탐이 된다.
그래서 null을 돌려주고 호출부는 판정 자체를 건너뛴다. 화면에는 기준 축적중으로 표시한다. 감시를 켜고 10분이 지나야 판정이 시작된다는 뜻인데, 이게 맞다고 본다. 모르는 상태에서 추측으로 알림을 보내는 것보다 아무 말도 안 하는 게 낫다.
실제로 이 덕분에 감시를 처음 켰을 때 누적 96회짜리를 포함해 열 개 전부 오탐 없이 조용히 등록됐다.
알림은 상태가 바뀔 때만
판정 조건이 맞을 때마다 메일을 보내면 60초마다 한 통씩 온다. 그래서 프로세스별로 ok / crashloop / down 상태를 들고 있다가 전이되는 순간에만 한 번 보낸다.
if (state === prevState) return; // 안 바뀌었으면 아무것도 안 한다
크래시 루프에 빠지면 1통, 안정화되면 1통. 그 사이에 계속 죽고 있어도 추가 발송은 없다.
중단 판정도 같이 넣었다. status가 online이 아니면(stopped, errored) 그것도 알린다.
메일에 에러 로그를 같이 넣기
이게 만들고 나서 제일 만족스러운 부분이다.
"game-server가 크래시 루프입니다"라는 알림만 오면, 결국 서버에 접속해서 pm2 logs를 쳐봐야 한다. 새벽에 이러면 꽤 귀찮다.
그런데 jlist에 이미 pm_err_log_path가 들어있다. 그래서 그 파일의 끝부분을 읽어서 메일 본문에 같이 넣었다.
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); // 끝에서 16KB 만
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(() => {});
}
}로그 파일이 수십 MB까지 커지므로 통째로 읽으면 안 된다. 끝에서 16KB만 읽고 마지막 18줄을 자른다.
결과적으로 알림이 이렇게 온다.
메일만 보고 db/game.js:298에서 undefined를 읽고 있다는 것, 그리고 그 아래 PROTOCOL_PACKETS_OUT_OF_ORDER까지 바로 알 수 있다. 참고로 이건 오래된 mysql 드라이버가 끊긴 커넥션을 못 살려서 나는 증상이라 mysql2 풀로 바꾸면 대개 사라진다.
화면
대시보드에도 페이지를 하나 붙였다.
표에서 제일 중요한 열은 최근 재시작이다. 7/3 옆에 10분이 같이 적혀 있는데, "10분 안에 7번 죽었고 임계치는 3번"이라는 뜻이다. 옆의 누적 열과 대비해서 보면 왜 누적으로 판정하면 안 되는지가 바로 보인다. game-server는 누적 112회지만, 문제는 그중 7번이 최근 10분에 몰려 있다는 거다.
임계치는 표에서 바로 클릭해서 고칠 수 있게 했다. 프로세스마다 성격이 다르기 때문이다. 어떤 앱은 배포할 때마다 몇 번씩 재시작하는 게 정상이라 임계치를 높여야 하고, 어떤 앱은 한 번만 죽어도 이상한 거라 낮춰야 한다.
테스트
이런 건 실제로 터뜨려보지 않으면 믿을 수 없다. 5초 살다가 죽는 프로세스를 만들어서 PM2에 올렸다.
// crashtest.js
console.log('시작');
setTimeout(() => {
console.error('의도적 크래시');
process.exit(1);
}, 5000);$ pm2 start crashtest.js --name crash-test --restart-delay=1000
판정 구간을 1분으로 줄여놓고 기다렸더니 로그에 이렇게 찍혔다.
[PM2] crash-test 크래시 루프 — 최근 1분 동안 10회 재시작 (누적 14회)
메일도 왔다. 그다음 죽지 않는 코드로 바꿔서 재시작했더니,
[PM2] crash-test 안정화 — 재시작 멈춤 (지속 2분)
복구 알림까지 확인했다. 그리고 이 시간 동안 실제 프로세스 열 개는 오탐이 하나도 없었다. 누적 96회, 82회짜리가 섞여 있었는데도. 구간 증가량으로 판정한 게 제대로 동작한 거다.
실전에서도 며칠 안 돼 한 번 잡았다. 9월 13일 밤에 travel-server가 10분 사이 세 번씩 죽는 일이 두 번 있었고, 알림 기록에는 이렇게 남았다.
23:08:07 travel-server 크래시 루프 - 최근 10분 동안 3회 재시작 (누적 94회) 23:12:08 travel-server 안정화 - 재시작 멈춤 (지속 4분) 23:39:07 travel-server 크래시 루프 - 최근 10분 동안 3회 재시작 (누적 99회) 23:43:07 travel-server 안정화 - 재시작 멈춤 (지속 4분)
같은 시각 헬스체크는 첫 번째 루프 때 딱 한 번 503을 봤고, 두 번째 루프 때는 한 번도 실패하지 않았다. PM2가 바로 되살려서 체크가 도착했을 땐 이미 멀쩡했기 때문이다. 이 글 맨 앞에서 말한 사각지대가 그대로 재현된 셈이다.
알아둘 점 하나
pm2 kill 후 재기동하면 restart_time이 0으로 리셋된다. 그러면 "이전 스냅샷은 96인데 현재는 0"이 되어 증가량이 음수가 된다.
음수는 임계치를 넘지 않으니 알림이 잘못 가지는 않지만, 이후 카운터가 다시 오를 때 기준이 꼬인다. Math.max(0, ...) 한 줄로 막아뒀다.
남는 생각
모니터링을 붙일 때 "서비스가 살아있나"만 확인하기 쉽다. 나도 그렇게 만들었고, 그게 틀린 건 아니다. 다만 자동 복구 장치가 있으면 그 장치가 문제를 가려버린다. PM2가 일을 너무 잘해서 내가 몇 달 동안 아무것도 몰랐다.
재시작 카운터는 계속 거기 있었다. pm2 list 한 번이면 보이는 자리에. 그런데 아무도 안 보는 숫자는 없는 숫자와 같다.
PM2를 쓰고 있다면 지금 한 번 쳐보길 권한다.
pm2 list
uptime 옆 재시작 횟수 열에 두 자리 숫자가 있으면, 그동안 조용히 죽고 있었던 거다.