Failures That Are Not the App's Fault — Buffers, Body Size, Connection Reuse

한국어 원문으로 표시합니다.

목표

상태 코드가 200 인데 사용자는 느리다고 하는 장애를 nginx 의 버퍼·본문 크기· 커넥션 설정에서 찾아낼 수 있게 됩니다. 그리고 각 설정이 무엇을 대가로 치르는지 숫자로 말할 수 있게 됩니다.

왜 중요한가

5xx 는 대시보드가 알려 줍니다. 정말 오래 끄는 것은 아무도 잘못한 사람이 없어 보이는 장애입니다. 개발팀은 "우리는 0.05 초에 응답했다" 고 하고 인프라팀은 "서버는 한가하다" 고 하는데 사용자는 7 초를 기다립니다. 셋 다 사실이고, 빠진 조각은 nginx 안에 있습니다. 응답이 디스크로 샜거나, 요청 본문이 임시 파일로 떨어졌거나, 매 요청마다 새 TCP 커넥션이 열리고 있습니다. 이 셋은 전부 상태 코드에 나타나지 않고, [warn] 수준의 로그 한 줄에만 흔적을 남깁니다. 그래서 error_log 를 warn 으로 열어 두는 것이 이 장애를 볼 수 있는 유일한 방법입니다.

단계

/root/ngb/upstream.py 를 저장해 띄우고 /root/ngb/nginx.conf 를 작성해 nginx 를 기동합니다. 8088 포트로 listen 하고 /app/ 을 upstream app 그룹(9101 번)으로 프록시합니다. error_log 는 /root/ngb/logs/error.log 에 warn 수준, 액세스 로그는 /root/ngb/logs/access.log 에 남기고 포맷에 $upstream_response_time, $request_time, $upstream_status 를 모두 넣습니다. client_max_body_size 는 아직 넣지 않습니다. 확인: http://127.0.0.1:8088/app/ 가 200 이어야 합니다. (브라우저 미리보기로 열어 볼 수 있습니다.)
두 가지 느린 요청을 각각 한 번씩 보냅니다.
- 업스트림이 느린 경우: http://127.0.0.1:8088/app/slow?d=4
- 전송이 느린 경우: http://127.0.0.1:8088/app/big?n=8000000 을 curl --limit-rate 1000k 로 두 요청의 액세스 로그 줄을 /root/ngb/attribute.log 로 떠 두고, /root/ngb/attribute.csv 를 만듭니다. 첫 줄은 case,upstream_time,request_time,verdict 이고 두 줄이 이어집니다. case 는 slow-upstream 과 slow-transfer, verdict 는 upstream 또는 transfer 입니다.

2 단계의 큰 응답이 error.log 에 남긴 경고를 찾아 /root/ngb/case-spill.txt 를 만듭니다. 네 줄입니다.

level=<대괄호 안 수준>
path=<로그에 적힌 임시 파일 경로 그대로>
status=<같은 요청의 액세스 로그 상태 코드>
tradeoff=<disk-spill 또는 upstream-held>

/nobuf/ 경로를 추가합니다. 같은 upstream app 으로 프록시하되 그 블록 안에 proxy_buffering off; 를 넣습니다. reload 한 뒤 http://127.0.0.1:8088/nobuf/big?n=8000000 을 같은 --limit-rate 1000k 로 받고 /root/ngb/case-nobuf.txt 를 만듭니다. 네 줄입니다.
```
upstream_time=<us 칸이 아니라 ut 칸 값 그대로>
request_time=<rt 칸 값 그대로>
warn=<none 또는 spilled>
tradeoff=<disk-spill 또는 upstream-held>
```
3MB 본문을 http://127.0.0.1:8088/app/toobig 로 POST 합니다. 상태 코드, 액세스 로그의 us 칸, 그리고 /root/ngb/upstream.log 에 그 요청이 몇 건 남았는지를 확인하고 /root/ngb/case-413.txt 를 만듭니다. 네 줄입니다.
```
status=<상태 코드>
upstream_status=<액세스 로그 us 칸 값>
app_saw=<업스트림 로그에 남은 건수>
fix=<이 실패를 푸는 지시자 이름>
```
그런 다음 그 지시자를 10m 으로 설정하고 reload 해서 http://127.0.0.1:8088/app/upload 로 같은 3MB 를 POST 하면 200 이 나오게 만듭니다.
500KB 본문을 http://127.0.0.1:8088/app/spill 로 POST 하면 error.log 에 임시 파일 경고가 하나 더 나옵니다. /root/ngb/case-bodyspill.txt 를 만듭니다. 세 줄입니다.
```
level=<대괄호 안 수준>
path=<로그에 적힌 임시 파일 경로 그대로>
fix=<본문을 메모리에 담는 크기를 정하는 지시자 이름>
```
그런 다음 그 지시자를 1m 으로 설정하고 reload 한 뒤 http://127.0.0.1:8088/app/nospill 로 같은 500KB 를 POST 해서 이번에는 경고가 나오지 않는 것을 확인합니다.
커넥션 재사용을 실측합니다. 먼저 지금 상태에서 http://127.0.0.1:8088/app/ 를 10 회 호출하고 upstream.log 의 conn 번호가 몇 종류인지 셉니다. 그다음 upstream app 블록에 keepalive 16; 을, /app/ 블록에 proxy_http_version 1.1; 과 proxy_set_header Connection ""; 를 넣고 reload 한 뒤 다시 10 회를 호출해 같은 방식으로 셉니다. /root/ngb/keepalive.txt 를 만듭니다.
```
before=<설정 전 커넥션 수>
after=<설정 뒤 커넥션 수>
```
/root/ngb/runbook.md 를 작성합니다. ## 증상별 첫 확인, ## 버퍼링, ## 본문 크기, ## 커넥션 재사용 네 개의 h2 제목이 있어야 하고, proxy_buffering, client_max_body_size, client_body_buffer_size, keepalive, upstream_response_time 다섯 낱말이 모두 나와야 하며, 2 단계에서 잰 두 시간 값이 숫자로 인용돼야 합니다.

참고

기동: nginx -c /root/ngb/nginx.conf -p /root/ngb
재적용: nginx -s reload -c /root/ngb/nginx.conf -p /root/ngb
느린 클라이언트: curl -s -o /dev/null --limit-rate 1000k <URL>
큰 본문 보내기: head -c 3000000 /dev/zero | curl -s --data-binary @- <URL>
커넥션 수 세기: awk '$3=="start"{print $2}' /root/ngb/upstream.log | sort -u | wc -l (앞 요청이 섞이니 셀 구간을 tail 로 잘라 쓰세요)
흔한 실수 1: 1 단계에서 client_max_body_size 를 미리 넣는 것. 5 단계에서 볼 기본값 동작이 사라집니다.
흔한 실수 2: 커넥션 재사용 3 종 중 proxy_set_header Connection ""; 를 빠뜨리는 것. HTTP/1.1 로 올려도 매 요청마다 커넥션이 끊깁니다.
흔한 실수 3: 응답 쪽 임시 파일 경로와 요청 본문 쪽 임시 파일 경로를 섞어 적는 것. 서로 다른 디렉터리입니다.

측정할 수 있는 프록시 세우기

/root/ngb/upstream.py 를 저장해 띄우고 /root/ngb/nginx.conf 를 작성해 nginx 를 기동합니다. 8088 포트로 listen 하고 /app/ 을 upstream app 그룹(9101 번)으로 프록시합니다. error_log 는 /root/ngb/logs/error.log 에 warn 수준, 액세스 로그는 /root/ngb/logs/access.log 에 남기고 포맷에 $upstream_response_time, $request_time, $upstream_status 를 모두 넣습니다. client_max_body_size 는 아직 넣지 않습니다. 확인: http://127.0.0.1:8088/app/ 가 200 이어야 합니다. (브라우저 미리보기로 열어 볼 수 있습니다.)

1 편과 같은 장애 발생기를 /root/ngb 아래에 다시 띄웁니다. 이번 실습의 승부는 액세스 로그 포맷에서 갈립니다 — 업스트림이 쓴 시간과 전체 시간을 함께 남기지 않으면 2 단계부터 아무것도 못 봅니다. 업스트림은 upstream 블록으로 묶어 두세요. 7 단계에서 그 블록 안에 지시자를 하나 넣게 됩니다.

앱이 느린가 전송이 느린가

두 가지 느린 요청을 각각 한 번씩 보냅니다.

업스트림이 느린 경우: http://127.0.0.1:8088/app/slow?d=4
전송이 느린 경우: http://127.0.0.1:8088/app/big?n=8000000 을 curl --limit-rate 1000k 로 두 요청의 액세스 로그 줄을 /root/ngb/attribute.log 로 떠 두고, /root/ngb/attribute.csv 를 만듭니다. 첫 줄은 case,upstream_time,request_time,verdict 이고 두 줄이 이어집니다. case 는 slow-upstream 과 slow-transfer, verdict 는 upstream 또는 transfer 입니다.

두 가지 느림을 각각 한 번씩 만듭니다 — 업스트림이 4 초를 끄는 요청과, 응답은 순식간에 나오지만 클라이언트가 천천히 받는 요청. curl 의 --limit-rate 로 느린 클라이언트를 흉내 낼 수 있습니다. 두 요청의 액세스 로그 줄을 따로 떠 두고 ut 와 rt 를 비교하세요.

디스크로 새는 응답

2 단계의 큰 응답이 error.log 에 남긴 경고를 찾아 /root/ngb/case-spill.txt 를 만듭니다. 네 줄입니다.

level=<대괄호 안 수준>
path=<로그에 적힌 임시 파일 경로 그대로>
status=<같은 요청의 액세스 로그 상태 코드>
tradeoff=<disk-spill 또는 upstream-held>

2 단계의 큰 응답이 error.log 에 무엇을 남겼는지 보세요. 수준이 error 가 아니라는 점, 그리고 같은 요청의 액세스 로그 상태 코드가 무엇인지가 이 단계의 요점입니다. 이 장애는 상태 코드로는 절대 보이지 않습니다.

버퍼링을 끄면 무엇이 바뀌는가

/nobuf/ 경로를 추가합니다. 같은 upstream app 으로 프록시하되 그 블록 안에 proxy_buffering off; 를 넣습니다. reload 한 뒤 http://127.0.0.1:8088/nobuf/big?n=8000000 을 같은 --limit-rate 1000k 로 받고 /root/ngb/case-nobuf.txt 를 만듭니다. 네 줄입니다.

upstream_time=<us 칸이 아니라 ut 칸 값 그대로>
request_time=<rt 칸 값 그대로>
warn=<none 또는 spilled>
tradeoff=<disk-spill 또는 upstream-held>

같은 8MB 응답을 버퍼링을 끈 경로로 한 번 더 받아 보세요. 임시 파일 경고가 사라지는 대신 액세스 로그의 두 숫자 관계가 뒤집힙니다. 그 뒤집힘이 무엇을 뜻하는지가 이 단계의 답입니다.

애플리케이션이 영영 못 보는 413

3MB 본문을 http://127.0.0.1:8088/app/toobig 로 POST 합니다. 상태 코드, 액세스 로그의 us 칸, 그리고 /root/ngb/upstream.log 에 그 요청이 몇 건 남았는지를 확인하고 /root/ngb/case-413.txt 를 만듭니다. 네 줄입니다.

status=<상태 코드>
upstream_status=<액세스 로그 us 칸 값>
app_saw=<업스트림 로그에 남은 건수>
fix=<이 실패를 푸는 지시자 이름>

그런 다음 그 지시자를 10m 으로 설정하고 reload 해서 http://127.0.0.1:8088/app/upload 로 같은 3MB 를 POST 하면 200 이 나오게 만듭니다.

3MB 짜리 본문을 올려 보세요. 상태 코드보다 중요한 것은 그 요청이 업스트림에 갔는지입니다 — 액세스 로그의 업스트림 상태 코드 칸과 업스트림 서버 자신의 로그, 두 곳에서 확인할 수 있습니다. 확인이 끝난 뒤에 설정을 고쳐 통과시키세요.

요청 본문도 디스크로 샌다

500KB 본문을 http://127.0.0.1:8088/app/spill 로 POST 하면 error.log 에 임시 파일 경고가 하나 더 나옵니다. /root/ngb/case-bodyspill.txt 를 만듭니다. 세 줄입니다.

level=<대괄호 안 수준>
path=<로그에 적힌 임시 파일 경로 그대로>
fix=<본문을 메모리에 담는 크기를 정하는 지시자 이름>

그런 다음 그 지시자를 1m 으로 설정하고 reload 한 뒤 http://127.0.0.1:8088/app/nospill 로 같은 500KB 를 POST 해서 이번에는 경고가 나오지 않는 것을 확인합니다.

413 문턱보다는 작지만 메모리 버퍼보다는 큰 본문을 올리면 경고가 하나 더 나옵니다. 응답 쪽 임시 파일과는 다른 디렉터리에 떨어지니 경로를 잘 보세요. 고친 뒤에는 다른 경로로 한 번 더 올려 경고가 안 나오는 것을 확인합니다.

세 줄이 다 있어야 커넥션이 재사용된다

커넥션 재사용을 실측합니다. 먼저 지금 상태에서 http://127.0.0.1:8088/app/ 를 10 회 호출하고 upstream.log 의 conn 번호가 몇 종류인지 셉니다. 그다음 upstream app 블록에 keepalive 16; 을, /app/ 블록에 proxy_http_version 1.1; 과 proxy_set_header Connection ""; 를 넣고 reload 한 뒤 다시 10 회를 호출해 같은 방식으로 셉니다. /root/ngb/keepalive.txt 를 만듭니다.

before=<설정 전 커넥션 수>
after=<설정 뒤 커넥션 수>

먼저 지금 상태에서 10 회를 보내고 업스트림이 본 커넥션이 몇 개인지 세세요. 그다음 세 가지를 모두 넣고 다시 세면 숫자가 크게 달라집니다. 하나만 빠져도 아무 효과가 없으니, 안 바뀌면 셋 중 무엇이 빠졌는지 보세요.

운영 판단 기준서

/root/ngb/runbook.md 를 작성합니다. ## 증상별 첫 확인, ## 버퍼링, ## 본문 크기, ## 커넥션 재사용 네 개의 h2 제목이 있어야 하고, proxy_buffering, client_max_body_size, client_body_buffer_size, keepalive, upstream_response_time 다섯 낱말이 모두 나와야 하며, 2 단계에서 잰 두 시간 값이 숫자로 인용돼야 합니다.

각 설정의 장점만 적으면 문서가 아닙니다. 무엇을 얻고 무엇을 내주는지를 앞 단계에서 잰 숫자로 적어야 6 개월 뒤에 누군가 그 값을 건드릴 수 있습니다.