PM2가 너무 잘 되살려서 장애를 못 보고 있었다
헬스체크는 계속 200이었는데 재시작이 96회였다. 누적이 아니라 구간 증가량으로 판정해야 하는 이유
#PM2 #모니터링 #Node.js #운영 #장애대응
PM2가 너무 잘 되살려서 장애를 못 보고 있었다 개인 서버에 사이트를 열 개쯤 올려두고 쓴다. 전부 PM2로 돌리고, 모니터링 대시보드도 직접 만들어서 HTTP 헬스체크를 붙여놨다. 1분마다 각 사이트에 요청을 보내서 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 │ └────┴─────────────────┴─────────┴──────┴───────────┘ ↺ 열이 재시작 횟수다. game-server가 96회, travel-server가 82회. 전부 online 이고, 헬스체크는 그동안 한 번도 실패로 잡은 적이 없었다. 헬스체크는 이걸 못 잡는다 생각해보면 당연했다. 앱이 죽으면 PM2가 1초 안에 되살린다. 헬스체크는 1분에 한 번 요청을 보낸다. 그 1분 사이에 앱이 죽었다 살아나면, 헬스체크가 도착할 때쯤엔 이미 멀쩡히 200을 돌려준다. 앱 크래시 ──┐ │ PM2가 1초 만에 재시작 └──▶ 정상 헬스체크 ↑ ↑ (1분 간격) 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회짜리가 섞여 있었는데도. 구간 증가량으로 판정한 게 제대로 동작한 거다. 알아둘 점 하나 pm2 kill 후 재기동하면 restart_time 이 0으로 리셋된다. 그러면 "이전 스냅샷 96 → 현재 0"이 되어 증가량이 음수 가 된다. 음수는 임계치를 넘지 않으니 알림이 잘못 가지는 않지만, 이후 카운터가 다시 오를 때 기준이 꼬인다. Math.max(0, ...) 한 줄로 막아뒀다. 남는 생각 모니터링을 붙일 때 "서비스가 살아있나"만 확인하기 쉽다. 나도 그렇게 만들었고, 그게 틀린 건 아니다. 다만 자동 복구 장치가 있으면 그 장치가 문제를 가려버린다. PM2가 일을 너무 잘해서 내가 몇 달 동안 아무것도 몰랐다. 재시작 카운터는 계속 거기 있었다. pm2 list 한 번이면 보이는 자리에. 그런데 아무도 안 보는 숫자는 없는 숫자와 같다. PM2를 쓰고 있다면 지금 한 번 쳐보길 권한다. pm2 list ↺ 열에 두 자리 숫자가 있으면, 그동안 조용히 죽고 있었던 거다.