이번 시간에는 NGINX 뒤에 일부러 응답을 망치는 작은 앱을 두고, 502와 504가 나뉘는 기준을 상태 코드와 error.log 줄로 하나씩 맞춰 보며 배워가는 시간입니다.
예를 들어서 우리가 NGINX를 앞에 둔 서비스를 운영하고 있다고 해볼게요. 어떤 날은 502 Bad Gateway 알림이 오고, 어떤 날은 504 Gateway Timeout 알림이 옵니다.
둘 다 뒤쪽 서버에 문제가 있다는 뜻이라 같은 장애처럼 보이죠. 그런데 NGINX가 둘을 나누는 기준은 분명합니다.
먼저 용어 하나만 잡고 갈게요. NGINX가 요청을 넘겨주는 뒤쪽 서버를 upstream이라고 부릅니다.
클라이언트 요청을 받은 NGINX는 upstream과 연결을 맺고, 요청을 보내고, 응답 헤더를 기다리고, 응답 바디를 받아요.
이 구간마다 시간을 재는 설정이 따로 있습니다. 세 설정 모두 기본값은 60초예요.
proxy_connect_timeout: upstream과 TCP 연결을 맺는 데 쓸 수 있는 시간입니다. 문서에 따르면 보통 75초보다 길게 잡을 수 없어요.proxy_send_timeout: 요청을 보낼 때, 연속된 두 번의 쓰기 사이에 허용하는 간격입니다.proxy_read_timeout: 응답을 읽을 때, 연속된 두 번의 읽기 사이에 허용하는 간격입니다. send와 read 모두 요청이나 응답 전체에 걸리는 시간을 재지 않는다는 점을 기억해 주세요.
실습 준비
이 글의 명령은 모두 실습 코드의 nginx-502-504/ 디렉터리에서 실행합니다.
compose.yaml: NGINX와 앱 컨테이너 a, b 정의app.py: 경로마다 다르게 응답하는 Python 앱nginx.conf: 실습별 location과 access log 형식
compose.yaml에는 NGINX 1.30.5 컨테이너 하나와, 같은 Python 앱을 띄운 컨테이너 두 개(a, b)가 들어 있어요. b는 이 글에서는 쓰지 않아요.
앱 app.py는 표준 라이브러리 http.server만 씁니다.
이 앱은 경로마다 다르게 행동합니다. 요청마다 X-Req-Id 헤더 값과, 앱에서 본 NGINX 쪽 포트 번호를 로그에 남겨요.
/ok는 바로 200으로 답합니다./slow?s=N은 N초 처리한 뒤 답합니다./drip?n=N&gap=G는 헤더와 첫 줄을 바로 보내고, 나머지 줄을 G초 간격으로 보냅니다./close는 요청을 읽고 아무것도 보내지 않은 채 연결을 닫습니다./reset은 요청을 읽고 RST로 연결을 끊습니다. RST는 정상 종료 절차 없이 연결을 바로 끊는 TCP 신호예요./badheader는 상태 줄은 맞지만 헤더 형식이 틀린 응답을 보냅니다.
nginx.conf에는 실습마다 location을 하나씩 뒀어요. access log에는 upstream 주소와 upstream이 돌려준 상태 코드를 함께 남깁니다.
이제 컨테이너를 띄우고 NGINX 버전을 확인해 볼게요.
docker compose up -d
docker compose exec nginx nginx -v
nginx version: nginx/1.30.5
명령을 짧게 쓰려고 셸 함수 두 개를 만들어 놓을게요.
req는 요청 경로, 상태 코드, 걸린 시간을 한 줄로 찍어 줍니다. errlog는 지정한 시간 이후의 error.log 줄에서 날짜, 프로세스 번호, client·server·host 항목을 지워 짧게 보여 줘요.
공식 이미지는 error.log와 access log를 컨테이너 로그로 보내기 때문에 docker compose logs로 읽으면 됩니다.
아래 블록은 파일로 만들지 말고 실습 디렉터리에서 연 터미널에 그대로 붙여 넣어 주세요. 이후 명령은 모두 이 터미널에서 실행하고, 터미널을 새로 열면 다시 붙여 넣으시면 됩니다.
req() { curl -s -o /dev/null -H "X-Req-Id: ${2:--}" -w "$1 %{http_code} %{time_total}s\n" "localhost:7150$1"; }
errlog() {
docker compose logs --no-log-prefix --since "$1" nginx | grep -E '\[(error|warn)\]' |
sed -E 's/^[0-9\/]+ //; s/ [0-9]+#[0-9]+: \*[0-9]+//; s/, client: [^,]*, server: [^,]*,/,/; s/, host: .*//'
}
실습 1: 502를 만드는 방법들
/a/ location은 앱 a 하나만 둔 upstream으로 요청을 넘깁니다. 여기서 응답을 망치는 경로를 차례로 부르고, 마지막에는 a 컨테이너를 내린 뒤 /ok를 불러 볼게요.
/refused/는 a 컨테이너에서 아무도 듣지 않는 8001번 포트로 넘깁니다. 앱 프로세스만 죽고 서버는 살아 있는 상황이라고 보시면 됩니다.
t=$(date +%s)
req /a/close
req /a/reset
req /a/badheader
req /refused/ok
docker compose stop a
req /a/ok
docker compose start a
errlog $t
/a/close 502 0.011634s
/a/reset 502 0.010639s
/a/badheader 502 0.011812s
/refused/ok 502 0.053914s
/a/ok 502 39.088468s
05:33:11 [error] upstream prematurely closed connection while reading response header from upstream, request: "GET /a/close HTTP/1.1", upstream: "http://172.28.0.3:8000/close"
05:33:11 [error] recv() failed (104: Connection reset by peer) while reading response header from upstream, request: "GET /a/reset HTTP/1.1", upstream: "http://172.28.0.3:8000/reset"
05:33:11 [error] upstream sent invalid header: "this\x20..." while reading response header from upstream, request: "GET /a/badheader HTTP/1.1", upstream: "http://172.28.0.3:8000/badheader"
05:33:11 [error] connect() failed (111: Connection refused) while connecting to upstream, request: "GET /refused/ok HTTP/1.1", upstream: "http://172.28.0.3:8001/ok"
05:34:04 [error] connect() failed (113: Host is unreachable) while connecting to upstream, request: "GET /a/ok HTTP/1.1", upstream: "http://172.28.0.3:8000/ok"
502가 된 다섯 경우를 error.log 메시지로 나눠 보면 이렇습니다.
upstream prematurely closed connection while reading response header: 앱이 응답 헤더를 보내기 전에 연결을 정상 종료했습니다. 앱이 처리 중에 죽거나 스스로 연결을 닫은 경우예요.recv() failed (104: Connection reset by peer) while reading response header: 앱 쪽에서 RST로 연결을 끊었습니다.upstream sent invalid header: 응답이 왔지만 헤더 형식이 틀렸습니다.connect() failed (111: Connection refused) while connecting to upstream: 서버에는 닿았지만 그 포트에서 듣는 프로세스가 없습니다. 배포나 재시작 중에 흔히 보게 돼요.connect() failed (113: Host is unreachable) while connecting to upstream: 그 주소를 가진 서버를 찾지 못했습니다.
마지막 경우는 걸린 시간도 같이 봐 주세요. 컨테이너를 내리면 그 IP를 쓰는 상대가 사라집니다.
이 환경에서는 연결 시도가 실패로 끝날 때까지 약 39초가 걸렸고, 그동안 클라이언트는 기다렸어요.
같은 502라도 포트에 듣는 프로세스가 없을 때는 0.1초도 걸리지 않았습니다. 그러니 서버가 사라진 경우와는 응답 시간이 크게 다르죠.
실습 2: 504와 세 가지 타임아웃
/t3/ location은 proxy_read_timeout을 3초로 줄였어요. 여기에 5초 걸리는 요청과 2초 걸리는 요청을 세 번씩 보내 볼게요.
/unroutable/은 proxy_connect_timeout을 2초로 두고, 응답하는 장비가 없는 주소 10.255.255.1로 넘깁니다.
t=$(date +%s)
for i in 1 2 3; do req "/t3/slow?s=5" slow5-$i; done
for i in 1 2 3; do req "/t3/slow?s=2" slow2-$i; done
for i in 1 2 3; do req /unroutable/ok; done
errlog $t
/t3/slow?s=5 504 3.009071s
/t3/slow?s=5 504 3.027755s
/t3/slow?s=5 504 3.014265s
/t3/slow?s=2 200 2.007250s
/t3/slow?s=2 200 2.047419s
/t3/slow?s=2 200 2.048188s
/unroutable/ok 504 2.001850s
/unroutable/ok 504 2.057065s
/unroutable/ok 504 2.005884s
05:34:23 [error] upstream timed out (110: Operation timed out) while reading response header from upstream, request: "GET /t3/slow?s=5 HTTP/1.1", upstream: "http://172.28.0.3:8000/slow?s=5"
05:34:26 [error] upstream timed out (110: Operation timed out) while reading response header from upstream, request: "GET /t3/slow?s=5 HTTP/1.1", upstream: "http://172.28.0.3:8000/slow?s=5"
05:34:29 [error] upstream timed out (110: Operation timed out) while reading response header from upstream, request: "GET /t3/slow?s=5 HTTP/1.1", upstream: "http://172.28.0.3:8000/slow?s=5"
05:34:37 [error] upstream timed out (110: Operation timed out) while connecting to upstream, request: "GET /unroutable/ok HTTP/1.1", upstream: "http://10.255.255.1:8000/ok"
05:34:39 [error] upstream timed out (110: Operation timed out) while connecting to upstream, request: "GET /unroutable/ok HTTP/1.1", upstream: "http://10.255.255.1:8000/ok"
05:34:41 [error] upstream timed out (110: Operation timed out) while connecting to upstream, request: "GET /unroutable/ok HTTP/1.1", upstream: "http://10.255.255.1:8000/ok"
- 5초 걸리는 요청은 3.009~3.028초에 504를 받았습니다. 메시지는
upstream timed out ... while reading response header from upstream이에요. - 2초 걸리는 요청은 3초 안에 헤더가 왔으므로 200입니다.
- 응답 없는 주소로의 연결은 2.002~2.057초에 504를 받았습니다. 메시지 끝이
while connecting to upstream이라 연결 구간에서 시간이 다 됐다는 것을 알 수 있어요.
앞에서 본 113: Host is unreachable과 비교해 보면 차이가 보입니다. 연결 구간의 실패는 "실패했다는 답을 받았는지"(502)와 "아무 답도 못 받았는지"(504)로 갈려요.
그럼 504가 난 요청은 앱에서 어떻게 끝났을까요? 같은 시간 동안 앱 a가 남긴 로그를 확인해 볼게요.
docker compose logs --no-log-prefix --since $t a
05:34:20 a start GET /slow id=slow5-1 port=59832 conn=None
05:34:23 a start GET /slow id=slow5-2 port=59842 conn=None
05:34:25 a done /slow id=slow5-1
05:34:25 a write failed /slow id=slow5-1 Broken pipe
05:34:26 a start GET /slow id=slow5-3 port=59846 conn=None
05:34:28 a done /slow id=slow5-2
05:34:28 a write failed /slow id=slow5-2 Broken pipe
05:34:29 a start GET /slow id=slow2-1 port=59854 conn=None
05:34:31 a done /slow id=slow5-3
05:34:31 a write failed /slow id=slow5-3 Broken pipe
05:34:31 a done /slow id=slow2-1
05:34:31 a start GET /slow id=slow2-2 port=59854 conn=None
05:34:33 a done /slow id=slow2-2
05:34:33 a start GET /slow id=slow2-3 port=59854 conn=None
05:34:35 a done /slow id=slow2-3
여기서 눈여겨볼 건 slow5-1이에요. NGINX가 3초에서 포기한 뒤에도 앱에서는 끝까지 처리됐고(done), 응답을 쓰려는 순간에야 연결이 끊긴 것을 알았습니다(Broken pipe).
504는 NGINX가 기다리기를 그만뒀다는 뜻이고, 앱이 처리하지 못했다는 뜻은 아닙니다.
그래서 주문이나 결제처럼 상태를 바꾸는 요청이라면 조심해야 해요. 클라이언트는 504를 받았어도 앱에서는 처리가 끝났을 수 있습니다.
proxy_send_timeout은 이 글에서 재현하지 않았어요. 큰 요청 바디를 보내는 동안 앱이 읽기를 멈추는 경우에 해당하고, 문서상 메시지 끝은 while sending request to upstream입니다.
실습 3: proxy_read_timeout은 전체 시간이 아닙니다
같은 3초 설정에서 세 가지 응답을 비교해 볼게요.
/t3/drip?n=8: 헤더와 첫 줄을 바로 보내고, 1초 간격으로 7줄을 더 보냅니다. 전체는 약 7초입니다./t3/slow?s=8: 8초 동안 아무것도 보내지 않다가 한 번에 보냅니다./t3/drip?n=3&gap=4: 헤더와 첫 줄을 바로 보내고, 4초 쉰 뒤 다음 줄을 보냅니다.
받은 바이트 수(size_download)와 curl 종료 코드도 함께 봅니다.
body() {
curl -sS -o /dev/null -w "$1 %{http_code} %{time_total}s %{size_download}B" "localhost:7150$1" 2> curl-err.txt
echo " exit=$?"
cat curl-err.txt
}
t=$(date +%s)
for i in 1 2 3; do body "/t3/drip?n=8"; done
for i in 1 2 3; do body "/t3/slow?s=8"; done
for i in 1 2 3; do body "/t3/drip?n=3&gap=4"; done
errlog $t
docker compose logs --no-log-prefix --since $t nginx | grep -E '^GET'
/t3/drip?n=8 200 7.022186s 56B exit=0
/t3/drip?n=8 200 7.023879s 56B exit=0
/t3/drip?n=8 200 7.023516s 56B exit=0
/t3/slow?s=8 504 3.022943s 167B exit=0
/t3/slow?s=8 504 3.027359s 167B exit=0
/t3/slow?s=8 504 3.015226s 167B exit=0
/t3/drip?n=3&gap=4 200 3.006471s 0B exit=18
curl: (18) end of response with 21 bytes missing
/t3/drip?n=3&gap=4 200 3.019728s 0B exit=18
curl: (18) end of response with 21 bytes missing
/t3/drip?n=3&gap=4 200 3.025364s 0B exit=18
curl: (18) end of response with 21 bytes missing
05:35:15 [error] upstream timed out (110: Operation timed out) while reading response header from upstream, request: "GET /t3/slow?s=8 HTTP/1.1", upstream: "http://172.28.0.3:8000/slow?s=8"
05:35:18 [error] upstream timed out (110: Operation timed out) while reading response header from upstream, request: "GET /t3/slow?s=8 HTTP/1.1", upstream: "http://172.28.0.3:8000/slow?s=8"
05:35:21 [error] upstream timed out (110: Operation timed out) while reading response header from upstream, request: "GET /t3/slow?s=8 HTTP/1.1", upstream: "http://172.28.0.3:8000/slow?s=8"
05:35:24 [error] upstream timed out (110: Operation timed out) while reading upstream, request: "GET /t3/drip?n=3&gap=4 HTTP/1.1", upstream: "http://172.28.0.3:8000/drip?n=3&gap=4"
05:35:27 [error] upstream timed out (110: Operation timed out) while reading upstream, request: "GET /t3/drip?n=3&gap=4 HTTP/1.1", upstream: "http://172.28.0.3:8000/drip?n=3&gap=4"
05:35:30 [error] upstream timed out (110: Operation timed out) while reading upstream, request: "GET /t3/drip?n=3&gap=4 HTTP/1.1", upstream: "http://172.28.0.3:8000/drip?n=3&gap=4"
GET /t3/drip?n=8 200 upstream=172.28.0.3:8000 upstream_status=200 time=7.009
GET /t3/drip?n=8 200 upstream=172.28.0.3:8000 upstream_status=200 time=7.019
GET /t3/drip?n=8 200 upstream=172.28.0.3:8000 upstream_status=200 time=7.005
GET /t3/slow?s=8 504 upstream=172.28.0.3:8000 upstream_status=504 time=3.000
GET /t3/slow?s=8 504 upstream=172.28.0.3:8000 upstream_status=504 time=3.001
GET /t3/slow?s=8 504 upstream=172.28.0.3:8000 upstream_status=504 time=3.001
GET /t3/drip?n=3&gap=4 200 upstream=172.28.0.3:8000 upstream_status=200 time=3.001
GET /t3/drip?n=3&gap=4 200 upstream=172.28.0.3:8000 upstream_status=200 time=3.000
GET /t3/drip?n=3&gap=4 200 upstream=172.28.0.3:8000 upstream_status=200 time=3.001
- 1초 간격 drip은 약 7초가 걸렸지만 3초 제한에 걸리지 않고 56바이트를 모두 받았어요. 읽기 사이 간격이 1초라 시간이 계속 새로 시작됐기 때문입니다.
- slow는 3초에 504입니다. 헤더가 오기 전이라 NGINX가 상태 코드를 504로 정할 수 있었어요.
- 4초 간격 drip은 상태 코드가 200인데, 3초에 연결이 끊겨 curl이
(18) end of response with 21 bytes missing으로 끝났습니다. error.log 메시지는while reading upstream으로, 헤더가 아니라 바디를 읽다가 시간이 다 됐다는 뜻이에요.
마지막 경우는 조금 더 들여다볼게요. 앱이 바로 보낸 첫 줄조차 클라이언트에 도착하지 않았습니다(0B).
기본값인 proxy_buffering on에서 NGINX는 받은 응답을 버퍼에 모았다가 보냅니다. 그래서 7바이트짜리 첫 줄이 버퍼에 머문 채 연결이 끊긴 것으로 보여요.
이 요청도 access log에는 200으로 남았습니다. 상태 코드만 세는 모니터링으로는 응답이 중간에 잘린 요청을 찾을 수 없다는 뜻이죠.
이런 실패는 error.log의 while reading upstream이나, 클라이언트 쪽 오류로 찾아 주셔야 합니다.
정리하면 proxy_read_timeout은 응답이 멈춰 있어도 되는 시간의 상한이에요. 오래 걸리는 작업이라면 이 값을 계속 늘리기보다, 작업을 접수만 하고 바로 답한 뒤 결과를 따로 조회하게 만드는 편이 낫습니다.
정리
범위: NGINX 1.30.5 공식 이미지(Alpine), Python http.server 앱 두 대, 타임아웃은 location마다 2~3초로 줄여 재현.
- 앱이 헤더 전에 연결을 닫거나, RST로 끊거나, 헤더 형식이 틀리거나, 포트에 듣는 프로세스가 없거나, 서버가 사라지면 502였고, 서버가 사라진 경우(
113: Host is unreachable)만 약 39초 뒤에 났습니다. 502의 원인은 상태 코드가 아니라 error.log 메시지와while뒤 문구로 가려 주세요. proxy_read_timeout3초에서 5초 걸리는 요청은 3.009~3.028초에 504였지만 앱은 처리를 끝까지 했습니다(done,Broken pipe). 504를 받은 상태 변경 요청은 앱에서 처리됐을 수 있다고 보고 다뤄 주세요.- 1초 간격으로 보내는 7초짜리 응답은 3초 제한에 걸리지 않았고, 4초 쉰 응답은 200으로 시작해 바디가 잘렸는데 access log에는 200으로 남았습니다. 잘린 응답은 error.log의
while reading upstream으로 찾아 주세요. - 이 글에 싣지 않은 추가 측정에서는 설정에
keepalive(끝난 연결을 닫지 않고 다음 요청에 다시 쓰는 것)가 없어도 1.30.5가 upstream 블록을 거친 요청에서 같은 TCP 연결을 재사용했고, 앱이 1초 동안 쓰지 않은 연결을 닫게 하자/a/에서 POST 600건 중 1건이 502였으며 NGINX가 먼저 닫거나 앱이 더 오래 유지한 설정은 0건이었습니다. upstream 블록의keepalive_timeout을 앱의 유휴 연결 종료 시간보다 짧게 두세요.