살아 있다고 말하는 것들 — active·exit 255·CPU 99.9%가 전부 거짓말이었습니다

LISTEN 상태의 accept 큐에, 응답을 못 받은 소켓 406개가 쌓여 있었습니다. systemd에는 active로 뜨고 포트도 열려 있었으니, 겉보기엔 정상이었거든요.

 

그런데 curl에는 답이 하나도 나오지 않았습니다. 상태는 정상이었는데, 일만 하지 않은 겁니다.

active였는데, 아무도 대답하지 않았습니다

문제였던 건 늘 쓰던 웹 대시보드 서비스였습니다. systemd에는 active로 뜨고, 연결을 기다리는 포트는 LISTEN 상태, 표로는 완벽했거든요. 그런데 curl로 요청을 보내면, 아무 대답 없이 시간만 흘러 타임아웃이 났습니다.

 

ss로 소켓 상태를 들여다보니, 사건의 크기가 나왔습니다. LISTEN 포트의 수신 대기열인 Recv-Q에 406개가 쌓여 있었고, 이미 끊긴 연결이 CLOSE-WAIT로 12개 남아 있었습니다.

 

문제는 이 신호들이 전부 '존재'만 말하고 있다는 데 있었습니다. active는 서비스가 살아있다는 확인일 뿐이고, LISTEN은 연결을 기다리는 자리가 열려 있다는 이야기일 뿐이죠. 그 프로세스가 지금 요청을 하나씩 받아서 처리하고 있는지는, 두 신호 어디에도 없습니다.

 

프로세스는 6일째 그 자리에 있었고, 스레드 128개는 전부 잠들어 있었죠. CPU 사용률은 0%인데, 메모리만 41.2G를 들고 있었습니다. 문패는 '영업 중'인데 전화를 아무도 받지 않는 식당 같은 상태였습니다.

 

원인은 스택 덤프에서 나왔습니다. 동작 중인 프로세스를 그대로 떠서, 스레드 128개가 각각 어디에 묶여 있는지 확인하는 방법이죠. 이벤트 루프가 데드락에 빠져서, 자기가 풀려야 움직이는데 자기가 기다리고 있었습니다.

 

루프가 멈춰 있으니 새 요청은 입장부터 못 하고 문 앞에 쌓이기만 합니다. 스스로 빠져나올 수 없는 상태라, 답은 재시작 한 번뿐이었습니다.

 

재시작 이후의 숫자는 바로 돌아왔습니다. 첫 응답은 로그인 화면으로 넘어가는 302 리다이렉트, 0.7ms였고 헬스체크도 ok로 나왔습니다. 쌓여 있던 소켓은 0개가 됐고, 메모리는 41.2G에서 246M로 내려왔습니다.

 

 

한 번의 재시작으로 돌아온 네 숫자 뒤에는, 하나의 사실이 있습니다. 서비스는 그동안 계속 살아 있었지만, 단 한순간도 일하지는 않았다는 사실입니다.

 

 

CPU 99.9%로, 7일째 헛돌고 있었습니다

두 번째 이야기는 다른 경로로 들어왔습니다. 9월 30일에 서빙 크래시를 조사하다가, 워크스테이션의 런처 프로세스 하나를 발견했는데 CPU 99.9%로 계속 돌고 있던 겁니다. 크래시의 원인을 찾으려 프로세스들을 훑다 보니, 자원을 씹는 양이 유난히 눈에 띄었습니다.

 

누적 CPU 시간을 재보니 약 10,140분, 7일치를 꽉 채운 양이었습니다. 누적 CPU 시간이란, 프로세스가 그동안 계산 자원을 얼마나 받아 썼는지의 총합입니다. 시작이 9월 23일 15시 14분, 크래시보다 일주일 앞서 있었죠.

 

결국 크래시와 무관한 별개의 문제였습니다. 서빙이 크래시나기 일주일 전부터, 이 프로세스는 혼자 7일째 돌고 있었습니다.

 

CPU 99.9%는 보통 열심히 일하는 신호로 읽힙니다. 그런데 이건 일이 아니라 헛돌이였습니다.

 

비유하자면 기어를 중립에 놓고 액셀을 끝까지 밟고 있는 차 같습니다. 회전계는 계속 올라가는데 차는 한 발짝도 안 가고, 차 자체는 무사한 거죠. 실제로 노드는 사설망 ping 2ms로 완전 정상이었고, 좀비가 있다고 노드 장애는 아니었습니다.

 

노드도 정상이었고 네트워크도 정상이었습니다. 비정상인 프로세스는 그 하나뿐이었죠.

 

할 일이 없다는 걸 확인한 뒤에 런처를 종료시키고, GPU를 해제했습니다. 7일치 자원을 먹고 있던 헛돌이가, 종료 한 번에 끝났습니다. 며칠을 돌아도 일감이 없던 프로세스를 끝냈을 뿐인데, 묶여 있던 GPU까지 풀렸습니다.

 

 

exit 255와, 아무것도 없는 로그

세 번째는 컨테이너가 exit 255로 죽은 사건이었습니다. 로그를 열어보니 크래시라면 있어야 할 에러도 traceback도 하나 없었습니다. 아무 일도 없었던 사람처럼, 깔끔하기만 했죠.

 

종료 코드는 프로세스가 삶을 마치면서 남기는 마지막 숫자입니다. 알고 보니 앱의 버그가 아니라, 바깥에서 stop이 걸린 상황이었습니다.

 

저절로 죽은 게 아니라 밖에서 종료된 건데, 로그만 쫓는 조사로는 이 사건의 답을 영원히 찾을 수 없습니다. 크래시한 적이 없으니까요.

 

앱 버그로 죽은 서비스의 로그는 보통 시끄럽습니다. 여기는 이상할 만큼 조용했죠. 에러가 빽빽한 벽보다 아무것도 없는 벽이 훨씬 더 수상했습니다.

 

stop을 누가 걸었든 무죄는 아닙니다. 다만 답을 앱 안에서 찾는 한, 영원히 못 만난다는 이야기죠. stop의 출처는 앱 바깥을 봐야만 보입니다.

살아있음과 일하고 있음은, 다른 질문입니다

세 이야기를 포개보면 같은 구멍이 보입니다. active나 포트, 로그처럼 '살아있음'을 알려주는 지표와, 응답시간과 큐 길이, 소켓 상태처럼 '일하고 있음'을 알려주는 지표는 별개라는 점입니다.

 

감시를 '프로세스 존재'로 잡으면 장애의 절반을 놓칩니다. 사례 1처럼, 존재와 일은 별개일 수 있거든요.

 

'로그 조용함'을 기준으로 잡으면 나머지 절반이 빠집니다. 사례 3처럼 밖에서 종료되면 로그는 끝까지 깨끗합니다.

 

현관 앞에 걸린 문패는, 부엌에서 밥이 나오고 있는지를 말해주지 않습니다. 존재 확인은 쉽지만 많이 말해주지 않습니다. 응답시간과 큐 적체는 손이 더 가지만, 실제로는 이쪽이 장애를 훨씬 정확히 잡습니다.

 

정직하게 적어두면, 이 세 건 모두 자동 감시로 먼저 잡아낸 게 아닙니다. 누군가 이상하다고 느낀 뒤에 손으로 들여다보고서야 나온, 사후 발견이었죠. 감시 규칙으로 옮기는 작업은 지금도 진행 중입니다.

 

curl로 주기적으로 응답을 확인하고, 소켓이 쌓이기 시작하면 알림이 오게 만드는 형태를 생각하고 있어요. 아직은 규칙으로 정리되지 않았습니다.

 

감시 규칙이 자리를 잡기 전까지는, 서비스가 자기 상태를 알려주는 말을 믿었다가 당하는 이야기가 또 반복될 겁니다. 그 작업을 빨리 끝내야겠습니다.