자동 복구가 매분 돌고 있었다

노드가 자주 죽는다는 것을 두 달 만에 알았는데 자동 복구가 그때마다 계속 살려 내고 있었다.

Open Table of contents

증상 — 문제가 없어 보이는 상태
검증 — 재시작 횟수
원인 — 2GB에서 죽고 있었다
조치 — 복구를 남기고 횟수 세기
사전 준비 — 재시작 직전 상태 남기기
재발 방지 — 다른 자동 복구도 찾았다
정리

증상 — 문제가 없어 보이는 상태

노드 상태는 항상 정상이었는데 watchdog.log 에서 이상한 것을 봤다.

2018-10-28 03:12:01  node restart (reason: not responding)
2018-10-28 05:44:01  node restart (reason: not responding)
2018-10-28 09:21:01  node restart (reason: not responding)

not responding 을 이유로 하루에 몇 번씩 재시작하고 있었다.

$ crontab -l
* * * * * /usr/local/bin/node-watchdog.sh

node-watchdog.sh 가 매분 확인해서 응답이 없으면 그 자리에서 재시작한다.

재시작한 노드가 30초 안에 살아나므로 쓰는 쪽에서는 아무도 몰랐다. 밖에서 보이는 상태만으로는 문제가 없다는 것과 문제가 가려져 있다는 것을 가를 수 없었다.

검증 — 재시작 횟수

watchdog.log 에서 재시작 횟수를 셌다.

$ grep -c "node restart" /var/log/watchdog.log.*
watchdog.log.1:12
watchdog.log.2:8
watchdog.log.3:14

하루 8회에서 14회였고 두 달이면 node 를 600번 넘게 재시작한 것이다.

세어 보기 전에는 가끔 그러려니 하고 있었는데 짐작과 실제가 자릿수만큼 벌어져 있었다. 자동으로 고쳐 주는 것이 있으니 그 차이가 드러날 자리가 없었다.

원인 — 2GB에서 죽고 있었다

재시작 직전의 node.log 를 봤다.

2018-10-28 03:11:44  ERROR out of memory

out of memory 로 죽고 있었다.

$ ps -o rss= -p $(pidof node)

rss 가 시간이 갈수록 늘어서 몇 시간만 돌면 설정된 한계에 닿았다.

node-watchdog.sh 의 재시작이 그 메모리를 그때마다 비워 주고 있어서 문제가 커지지 않았고 동시에 드러나지도 않았다.

조치 — 복구를 남기고 횟수 세기

node-watchdog.sh 를 없애지는 않았는데 없애면 서비스가 멈춘다.

count=$(redis-cli INCR "watchdog:restart:$(date +%Y%m%d)")
redis-cli EXPIRE "watchdog:restart:$(date +%Y%m%d)" 172800

if [ "$count" -gt 3 ]; then
    notify "노드 재시작이 오늘 ${count}회입니다"
fi

watchdog:restart 를 날짜별로 세고 하루 셋을 넘으면 notify 로 알린다.

복구는 그대로 계속하되 오늘 몇 번 했는지가 알림으로 함께 보인다. 가려진 것을 드러내는 것과 가리는 장치를 없애는 것은 다른 일이었다.

사전 준비 — 재시작 직전 상태 남기기

재시작하고 나면 원인을 볼 수 있는 자료가 함께 사라진다.

before_restart() {
    date -Is >> /var/log/node-crash.log
    ps -o pid,rss,vsz,etime -p "$(pidof node)" >> /var/log/node-crash.log
    tail -50 /var/log/node.log >> /var/log/node-crash.log
    cat /proc/$(pidof node)/status | grep -E "VmRSS|Threads" >> /var/log/node-crash.log
    echo "---" >> /var/log/node-crash.log
}

before_restart 로 죽기 직전의 VmRSS 와 Threads 를 남기고 재시작한다.

node-crash.log 에 여러 번 쌓이니 공통점이 보였다.

VmRSS: 2,096,404 kB  (항상 2GB 근처에서 죽는다)
Threads: 41

VmRSS 가 언제나 2GB 근처였고 실행 옵션에 상한이 그렇게 걸려 있었다.

상한을 올리는 것과 새는 것을 찾는 것 중 뒤를 골랐는데 올려도 죽는 주기가 길어질 뿐이고 끊긴 연결 객체가 정리되지 않고 쌓이는 것이 실제 원인이었다.

재발 방지 — 다른 자동 복구도 찾았다

같은 성격의 자동 복구가 더 있는지 찾아봤다.

$ crontab -l | grep -i "restart\|watchdog\|check"
$ ls /etc/cron.d/ | grep -i "restart\|watchdog"
$ systemctl show '*' -p Restart | grep -c always

비슷한 장치가 셋 더 나왔다.

API 서버      죽으면 자동 재시작 (systemd)
배치          실패하면 재시도 3회
큐 워커       응답 없으면 재시작

각각 얼마나 자주 도는지 세게 했더니 큐 워커 가 하루 40번 재시작하고 있었다.

자동 복구가 있는 곳은 전부 횟수를 세야 했는데 복구가 도는 것 자체는 설계대로지만 얼마나 자주 도는지는 아무도 안 보고 있었다.

정리

자동으로 고쳐 주는 것이 있으면 문제가 안 드러난다
밖에서 보이는 상태만으로 판단할 수 없다
복구가 얼마나 자주 도는지 센다
짐작과 실제가 자릿수만큼 다를 수 있다
복구를 없애지 않고 횟수를 보이게 한다
가려진 것을 드러내는 것과 장치를 없애는 것은 다르다
임계를 넘으면 알린다
재시작 전에 상태를 남기면 쌓였을 때 공통점이 보인다
한계를 올리는 것은 문제를 미루는 것이다
자동 복구가 있는 곳을 전부 찾아 각각 횟수를 센다