안 되는데 어디부터 볼지 몰랐다

게임 서버가 캐시에 못 붙는다는 오류가 났고 원인을 찾는 데 40분이 걸렸다. 일주일 뒤에 비슷한 문제가 또 났고 또 처음부터 뒤졌다.

Open Table of contents

매번 다른 순서로 봤다
순서를 정했다
각 단계의 명령을 적었다
스크립트와 대기 상한
검증 — 실패해야 할 때 실패하는가
정리

매번 다른 순서로 봤다

첫 번째 때는 이렇게 봤다.

애플리케이션 로그 → 캐시 설정 → 캐시 프로세스 → 방화벽 → 망

두 번째 때는 이랬다.

캐시 프로세스 → 애플리케이션 로그 → 설정 → 망

같은 것을 다른 순서로 본다. 어디까지 봤는지도 헷갈리고 nc 한 번이면 걸렀을 것을 계속 봤다.

순서를 정했다

바깥에서 안으로 좁히는 순서로 잡았다.

1. 망     대상에 닿는가        ping, telnet, nc
2. 프로세스  대상이 살아 있는가   ps, netstat
3. 응답   대상이 응답하는가     실제 명령 하나
4. 인증   접근 권한이 있는가    인증 정보 확인
5. 설정   우리가 맞게 부르는가  설정 값 출력
6. 코드   부르는 코드가 맞는가  로그

앞이 안 되면 뒤를 볼 필요가 없다. ping 이 안 되는데 코드를 읽는 것은 시간 낭비다.

바깥일수록 확인이 빠르고 원인일 확률도 높았다. 앞에서 걸리면 거기서 끝나므로 대부분의 경우 몇 분이면 원인이 나온다.

각 단계의 명령을 적었다

순서만 있으면 netstat 을 칠지 ps 를 칠지 매번 다시 생각하므로 같이 적었다.

1. 망
   $ ping -c 3 cache-01
   $ nc -zv cache-01 6379

2. 프로세스
   $ ssh cache-01 "ps -ef | grep redis"
   $ ssh cache-01 "netstat -tlnp | grep 6379"

3. 응답
   $ redis-cli -h cache-01 ping        → PONG

4. 인증
   $ redis-cli -h cache-01 -a *** ping → PONG

5. 설정
   $ php -r 'include "config.php"; echo CACHE_HOST . ":" . CACHE_PORT;'

6. 코드
   $ tail -100 /var/log/app/error.log | grep -i redis

각 단계에 무엇이 나오면 통과인지를 적었다. PONG 이 오면 통과인 식이고 기준이 없으면 결과를 보고도 정상인지를 판단하지 못한다.

인증 단계는 PING 이 거부로 돌아오는 경우에 걸린다. requirepass 가 걸려 있으면 붙기는 붙고 그 뒤 명령이 전부 거부되는데 문서도 인증 전에는 어떤 명령도 받지 않는다고 적고 있다. 붙었는데 안 된다는 증상이 여기서 나온다.

스크립트와 대기 상한

손으로 여섯 단계를 치는 것도 번거로워서 스크립트로 만들었다.

#!/bin/sh
H=${1:-cache-01}
P=${2:-6379}

echo "== 1. 망 =="
nc -zv "$H" "$P" 2>&1 || { echo "FAIL: 포트에 닿지 않음"; exit 1; }

echo "== 2. 응답 =="
r=$(redis-cli -h "$H" -p "$P" ping 2>&1)
[ "$r" = "PONG" ] || { echo "FAIL: 응답 없음 ($r)"; exit 1; }

echo "== 3. 설정 =="
php -r 'include "/var/www/app/config/config.php"; echo CACHE_HOST.":".CACHE_PORT."\n";'

echo "== 4. 최근 오류 =="
tail -50 /var/log/app/error.log | grep -i "redis" | tail -5

echo "모든 확인 통과"

앞 단계가 실패하면 exit 1 로 멈추고 무엇이 실패했는지 알려 준다. 두 번째 문제가 났을 때 이것을 돌리니 2분 만에 원인이 나왔고 redis 프로세스가 메모리 부족으로 죽어 있었다.

각 단계에는 대기 상한도 같이 뒀다. 상한이 없으면 망이 막힌 단계에서 한참 매달려 다음으로 못 넘어간다. 도구가 받는 -w 같은 옵션이 연결을 기다리는 동안에도 걸리는지는 판마다 정의가 달라서 timeout 명령으로 바깥에서 씌우는 쪽이 어디서나 같게 동작한다.

매달리는 것과 즉시 끊기는 것이 갈리는 지점도 정보다. 포트가 닫혀 있으면 RST 가 바로 돌아와 몇 밀리초에 끝나고 방화벽이 버리면 SYN 만 나가고 아무것도 안 돌아와 커널이 재전송하는 동안 매달린다. 앞은 그 자리에 프로세스가 없는 것이고 뒤는 방화벽이 막은 것이라 볼 자리가 다르다.

검증 — 실패해야 할 때 실패하는가

스크립트가 실제로 거르는지 확인했다. 없는 주소로 돌리면 nc 단계에서 멈추고 캐시를 내리고 돌리면 redis-cli 단계에서 멈추며 정상 상태로 돌리면 전부 통과한다.

세 가지를 다 해 봤다. 통과만 나오는 스크립트는 아무것도 안 보는 것과 같다.

캐시가 되니 다른 것도 만들었다.

tools/check-cache.sh
tools/check-db.sh
tools/check-api.sh
tools/check-all.sh

check-all.sh 는 셋을 다 돌린다. 문제가 났을 때 이것부터 돌리면 어디가 문제인지 나온다.

./tools/check-all.sh 2>&1 | tee "log/check-$(date +%Y%m%d-%H%M%S).log"

돌린 결과는 tee 로 파일에 남겼다. 문제를 보고할 때 이 파일을 같이 주면 말로 설명하는 것보다 정확하고 어제는 통과했는데 오늘 실패하면 그 사이에 바뀐 것을 본다.

정리

확인 순서가 없으면 매번 다른 순서로 보고 시간이 든다
바깥에서 안으로 좁히고 망·프로세스·응답·인증·설정·코드 순이다
앞이 안 되면 뒤를 볼 필요가 없다
순서만 적지 말고 명령과 통과 기준을 같이 적는다
기준이 없으면 결과가 정상인지 판단 못 한다
requirepass 가 걸리면 붙기는 붙고 뒤 명령이 거부된다
대기 상한은 timeout 으로 바깥에서 씌운다
즉시 거절이면 프로세스가 없는 것이고 매달리면 방화벽이 막은 것이다
스크립트로 묶으면 실패 지점에서 멈추고 알려 준다
실패해야 하는 상태에서 돌려 거르는지 확인한다
결과를 파일로 남기면 보고에 쓰고 지난 결과와 비교할 수 있다