504 인데 걸린 타임아웃이 다르다

한 줄 요약

502 와 504 는 증상의 이름이고, 범인의 이름은 이미 error.log 한 줄에 적혀 있다. 그 줄을 읽지 않고 추측을 시작하는 순간부터 시간이 새기 시작한다.

왜 이게 필요했나

장애 대응에서 제일 비싼 실수는 원인을 못 찾는 것이 아니라 틀린 원인을 확신하는 것이다.

전형적인 하루는 이렇게 흘러간다. 모니터링에 502 가 뜬다. "백엔드가 죽었나 보다" 하고 WAS 를 재기동한다. 안 낫는다. "그럼 느린 건가" 하고 proxy_read_timeout 을 30초로 올린다. 안 낫는다. "서버가 모자란가" 하고 인스턴스를 늘린다. 안 낫는다. 세 시간이 지났고, 그동안 error.log 는 첫 1 분부터 답을 들고 있었다.

이 코스는 그래서 로그를 읽는 것부터 시작하지 않는다. 장애를 직접 만들어 본다. 죽은 포트, 연결을 받지 않는 포트, 느린 응답, 버퍼보다 큰 헤더를 손으로 만들고 nginx 가 그때 무엇이라고 적는지 눈으로 본다. 한 번 본 문구는 다음에 실전에서 볼 때 0.5 초 만에 알아본다.

네 개의 서명

아래 네 줄은 실습 이미지(nginx 1.24.0)에서 실제로 재현해 받아 적은 것이다. 줄 안의 어느 부분이 범인을 지목하는지 표시해 두었다.

① 업스트림이 아예 안 떠 있다 → 502

[error] connect() failed (111: Connection refused) while connecting to upstream,  request: "GET /dead/ HTTP/1.1", upstream: "http://127.0.0.1:9999/"

connect() failed 는 TCP 연결 자체가 거부됐다는 뜻이다. 여기에 어떤 타임아웃을 올려도 아무 일도 일어나지 않는다. 502 에 타임아웃을 올리는 것이 헛수고인 이유가 이 한 줄에 있다 — 기다릴 시간조차 없었다. 커널이 즉시 RST 를 돌려보냈다.

② 업스트림이 떠 있는데 늦다 → 504

[error] upstream timed out (110: Connection timed out) while reading response  header from upstream, request: "GET /app/slow?d=10 HTTP/1.1"

③ 업스트림이 연결조차 받아 주지 않는다 → 504

[error] upstream timed out (110: Connection timed out) while connecting to  upstream, request: "GET /hang/ HTTP/1.1"

②와 ③을 나란히 놓고 보라. 상태 코드도 같은 504 이고, 괄호 안의 오류 번호도 같은 110 이다. 다른 것은 뒤쪽 구절 하나뿐이다.

| 구절 | 실제로 걸린 설정 |
| --- | --- |
| while connecting to upstream | proxy_connect_timeout |
| while reading response header from upstream | proxy_read_timeout |
| while sending request to upstream | proxy_send_timeout |

이 구절을 안 읽으면 어떻게 되는지가 이 코스의 핵심 장면이다. 실습 5 단계에서 여러분은 그 자리에 proxy_read_timeout 30s 를 넣는다. 30 초를 기다려 주겠다고 선언한 것이다. 그런데 요청은 여전히 2 초 만에 504 로 떨어진다. 걸린 것은 proxy_connect_timeout 2s 였기 때문이다. 올린 타임아웃은 발동한 타임아웃이 아니었다.

이것이 "타임아웃을 올렸는데 안 낫는데요" 의 정체다. 올릴 값을 고르기 전에 로그의 구절부터 읽어야 하는 이유다.

④ 응답 헤더가 프록시 버퍼보다 크다 → 502

[error] upstream sent too big header while reading response header from upstream,  request: "GET /app/bighdr?n=8000 HTTP/1.1"

이것이 넷 중 가장 고약하다. 서버는 멀쩡히 살아 있고, 헬스체크는 계속 초록색이고, 여러분이 curl 로 때려 보면 200 이 나온다. 특정 사용자만 502 를 받는다. 그 특정 사용자는 대개 SSO 로 로그인해서 세션 쿠키가 크거나, 권한 목록이 길어 응답 헤더가 부푼 사람이다.

proxy_buffer_size 기본값은 4k 이고, 응답 헤더 전체가 이 버퍼 하나에 들어가야 한다. 넘으면 nginx 는 응답을 받았는데도 처리하지 못하고 502 를 낸다. 규범이 말하는 502 는 "상류가 죽었다" 가 아니라 "게이트웨이가 상류로부터 유효하지 않은 응답을 받았다" 이고, 이 경우가 바로 그 정의에 해당한다.

여기에 함정이 하나 더 있다. proxy_buffer_size 만 16k 로 올리면 nginx 는 아예 뜨지 않는다.

[emerg] "proxy_busy_buffers_size" must be less than the size of all  "proxy_buffers" minus one buffer

proxy_buffers 도 함께 키워야 한다. 새벽에 이 메시지를 처음 보면 손이 굳는다. 한 번 보고 나면 아무것도 아니다.

access.log 두 칸으로 갈래를 나눈다

error.log 가 범인을 지목한다면, access.log 는 어느 방향을 볼지를 정해 준다. 로그 포맷에 이 세 변수를 넣어 두는 것이 이 코스에서 가장 값싼 투자다.

log_format ev '$time_local $status ut=$upstream_response_time '              'rt=$request_time us=$upstream_status "$request"';

실측한 세 줄을 보자.

504 ut=3.004 rt=3.004 us=504 "GET /app/slow?d=10 HTTP/1.1"200 ut=0.049 rt=4.173 us=200 "GET /app/big?n=8000000 HTTP/1.1"413 ut=-     rt=0.002 us=-   "POST /app/upload HTTP/1.1"

• 첫 줄: ut 와 rt 가 같다. 업스트림이 느린 것이다. 앱이나 DB 를 봐야 한다.
• 둘째 줄: ut 는 0.049 초인데 rt 는 4.173 초다. 앱은 이미 끝냈고 전송이 느린 것이다. 앱 로그를 아무리 뒤져도 "0.05 초에 응답했다" 밖에 안 나온다.
• 셋째 줄: us=- 다. 대시는 "업스트림에 간 적이 없다" 는 뜻이고, 그 순간 애플리케이션 로그에는 아무 흔적도 없다. nginx 가 혼자 답한 것이다.

us=- 를 읽을 줄 알면 "우리 앱 로그에는 그런 요청이 없는데요" 라는 대답이 근거가 된다. 모르면 그 대답은 그냥 책임 떠넘기기로 들린다.

현장에서 만나는 모습

진단 사다리의 마지막 칸을 먼저 밟는다. 프록시를 건너뛰고 업스트림에 직접, 원래 Host 헤더를 유지한 채 한 번 때려 본다.

curl -sSI -H 'Host: api.example.com' http://127.0.0.1:8080/health

여기서 정상이면 문제는 프록시와 업스트림 사이(설정·헤더·버퍼·타임아웃)에 있고, 여기서도 실패하면 프록시는 무죄다. 이 한 번으로 탐색 공간이 절반이 된다. -H 'Host: ...' 를 빼면 가상 호스트 라우팅이 걸린 경우 아예 다른 앱으로 가므로 비교가 무의미해진다.

증상만 적힌 티켓을 받으면 먼저 코드와 구절을 물어본다. "502 가 나요" 는 정보가 거의 없다. "502 이고 로그에 connect() failed (111: Connection refused) 가 찍힙니다" 는 사실상 원인 보고다. 이 습관 하나가 팀의 평균 복구 시간을 바꾼다.

다음 실습에서 할 것

파이썬으로 장애 발생기를 만들어 죽은 포트·응답하지 않는 포트·느린 응답·큰 헤더를 직접 만든다. 그리고 네 가지 경우 각각에서 상태 코드와 error.log 의 구절, 실제로 걸린 타임아웃을 증거 파일로 남긴다. 마지막에는 네 줄짜리 판정표와 장애 보고서를 쓴다.