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

Goal

You learn to find, in nginx's buffer, body size and connection settings, the kind of incident where the status code is 200 but the user says it is slow. And you learn to state in numbers what each setting costs you in exchange.

Why it matters

The dashboard tells you about 5xx. What really drags on is an incident where nobody seems to be at fault. The development team says "we responded in 0.05 seconds", and the infrastructure team says "the servers are idle", yet the user waits 7 seconds. All three are true, and the missing piece is inside nginx. The response spilled to disk, or the request body fell into a temporary file, or a new TCP connection is opened for every request. None of these three appears in the status code, and they leave a trace only in one log line at [warn] level. That is why keeping error_log open at warn is the only way to see this kind of incident.

Steps

Save and start /root/ngb/upstream.py, write /root/ngb/nginx.conf, and start nginx. Listen on port 8088 and proxy /app/ to the upstream app group (port 9101). Put error_log at /root/ngb/logs/error.log at warn level, put the access log at /root/ngb/logs/access.log, and include all of $upstream_response_time, $request_time and $upstream_status in its format. Do not add client_max_body_size yet. Check: http://127.0.0.1:8088/app/ must return 200. (You can open it with the browser preview.)
Send two kinds of slow request, once each.
- Slow upstream: http://127.0.0.1:8088/app/slow?d=4
- Slow transfer: http://127.0.0.1:8088/app/big?n=8000000 using curl --limit-rate 1000k Save the access log lines of the two requests to /root/ngb/attribute.log, and create /root/ngb/attribute.csv. The first line is case,upstream_time,request_time,verdict, followed by two lines. case is slow-upstream and slow-transfer, and verdict is upstream or transfer.

Find the warning that the large response from step 2 left in error.log and create /root/ngb/case-spill.txt. It has four lines.

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

Add a /nobuf/ path. Proxy it to the same upstream app and put proxy_buffering off; inside that block. After reload, receive http://127.0.0.1:8088/nobuf/big?n=8000000 with the same --limit-rate 1000k and create /root/ngb/case-nobuf.txt. It has four lines.
```
upstream_time=<us 칸이 아니라 ut 칸 값 그대로>
request_time=<rt 칸 값 그대로>
warn=<none 또는 spilled>
tradeoff=<disk-spill 또는 upstream-held>
```
POST a 3MB body to http://127.0.0.1:8088/app/toobig. Check the status code, the us column of the access log, and how many entries of that request are left in /root/ngb/upstream.log, and create /root/ngb/case-413.txt. It has four lines.
```
status=<상태 코드>
upstream_status=<액세스 로그 us 칸 값>
app_saw=<업스트림 로그에 남은 건수>
fix=<이 실패를 푸는 지시자 이름>
```
Then set that directive to 10m and reload, so that POSTing the same 3MB to http://127.0.0.1:8088/app/upload returns 200.
POSTing a 500KB body to http://127.0.0.1:8088/app/spill produces one more temporary-file warning in error.log. Create /root/ngb/case-bodyspill.txt. It has three lines.
```
level=<대괄호 안 수준>
path=<로그에 적힌 임시 파일 경로 그대로>
fix=<본문을 메모리에 담는 크기를 정하는 지시자 이름>
```
Then set that directive to 1m, reload, and POST the same 500KB to http://127.0.0.1:8088/app/nospill to confirm that no warning appears this time.
Measure connection reuse. First, in the current state, call http://127.0.0.1:8088/app/ 10 times and, in upstream.log, count how many kinds of conn numbers there are. Then, in the upstream app block, put keepalive 16;, and in the /app/ block put proxy_http_version 1.1; and proxy_set_header Connection "";, reload, call 10 times again and count in the same way. Create /root/ngb/keepalive.txt.
```
before=<설정 전 커넥션 수>
after=<설정 뒤 커넥션 수>
```
Write /root/ngb/runbook.md. It must have four h2 headings, ## 증상별 첫 확인, ## 버퍼링, ## 본문 크기 and ## 커넥션 재사용, and all five words proxy_buffering, client_max_body_size, client_body_buffer_size, keepalive and upstream_response_time must appear, and the two time values measured in step 2 must be quoted as numbers.

Notes

Start: nginx -c /root/ngb/nginx.conf -p /root/ngb
Re-apply: nginx -s reload -c /root/ngb/nginx.conf -p /root/ngb
Slow client: curl -s -o /dev/null --limit-rate 1000k <URL>
Sending a large body: head -c 3000000 /dev/zero | curl -s --data-binary @- <URL>
Counting connections: awk '$3=="start"{print $2}' /root/ngb/upstream.log | sort -u | wc -l (earlier requests get mixed in, so cut out the span to count with tail)
Common mistake 1: adding client_max_body_size in step 1 in advance. The default behavior you are supposed to see in step 5 disappears.
Common mistake 2: leaving out proxy_set_header Connection ""; from the three connection reuse settings. Even with HTTP/1.1 the connection is closed on every request.
Common mistake 3: mixing up the temporary file path on the response side and the one on the request body side. They are different directories.

Set up a proxy you can measure

Save and start /root/ngb/upstream.py, write /root/ngb/nginx.conf, and start nginx. Listen on port 8088 and proxy /app/ to the upstream app group (port 9101). Put error_log at /root/ngb/logs/error.log at warn level, put the access log at /root/ngb/logs/access.log, and include all of $upstream_response_time, $request_time and $upstream_status in its format. Do not add client_max_body_size yet. Check: http://127.0.0.1:8088/app/ must return 200. (You can open it with the browser preview.)

Start the same failure generator as in part 1 again under /root/ngb. The game in this lab is decided by the access log format — if you don't record both the time the upstream took and the total time, you can see nothing from step 2 onward. Group the upstream in an upstream block. In step 7 you will put a directive inside that block.

Is the app slow or is the transfer slow

Send two kinds of slow request, once each.

Slow upstream: http://127.0.0.1:8088/app/slow?d=4
Slow transfer: http://127.0.0.1:8088/app/big?n=8000000 using curl --limit-rate 1000k Save the access log lines of the two requests to /root/ngb/attribute.log, and create /root/ngb/attribute.csv. The first line is case,upstream_time,request_time,verdict, followed by two lines. case is slow-upstream and slow-transfer, and verdict is upstream or transfer.

Create each kind of slowness once — a request where the upstream drags on for 4 seconds, and a request where the response comes out instantly but the client receives it slowly. You can imitate a slow client with curl's --limit-rate. Save the access log lines of the two requests separately and compare ut and rt.

A response leaking to disk

Find the warning that the large response from step 2 left in error.log and create /root/ngb/case-spill.txt. It has four lines.

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

See what the large response from step 2 left in error.log. The point of this step is that the level is not error, and what the status code in the access log for the same request is. This kind of incident is never visible through the status code.

What changes when you turn buffering off

Add a /nobuf/ path. Proxy it to the same upstream app and put proxy_buffering off; inside that block. After reload, receive http://127.0.0.1:8088/nobuf/big?n=8000000 with the same --limit-rate 1000k and create /root/ngb/case-nobuf.txt. It has four lines.

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

Receive the same 8MB response once more through the path with buffering off. The temporary-file warning disappears, but the relationship between the two numbers in the access log flips. What that flip means is the answer to this step.

The 413 the application never sees

POST a 3MB body to http://127.0.0.1:8088/app/toobig. Check the status code, the us column of the access log, and how many entries of that request are left in /root/ngb/upstream.log, and create /root/ngb/case-413.txt. It has four lines.

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

Then set that directive to 10m and reload, so that POSTing the same 3MB to http://127.0.0.1:8088/app/upload returns 200.

Upload a 3MB body. More important than the status code is whether that request went to the upstream — you can check in two places: the upstream status code column of the access log, and the log of the upstream server itself. After you have confirmed it, fix the configuration to let it through.

The request body leaks to disk too

POSTing a 500KB body to http://127.0.0.1:8088/app/spill produces one more temporary-file warning in error.log. Create /root/ngb/case-bodyspill.txt. It has three lines.

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

Then set that directive to 1m, reload, and POST the same 500KB to http://127.0.0.1:8088/app/nospill to confirm that no warning appears this time.

If you upload a body that is smaller than the 413 threshold but larger than the memory buffer, one more warning appears. It lands in a different directory from the response-side temporary file, so look at the path carefully. After the fix, upload once more to a different path and confirm that no warning appears.

Connections are reused only when all three lines are present

Measure connection reuse. First, in the current state, call http://127.0.0.1:8088/app/ 10 times and, in upstream.log, count how many kinds of conn numbers there are. Then, in the upstream app block, put keepalive 16;, and in the /app/ block put proxy_http_version 1.1; and proxy_set_header Connection "";, reload, call 10 times again and count in the same way. Create /root/ngb/keepalive.txt.

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

First send 10 requests in the current state and count how many connections the upstream saw. Then put in all three and count again, and the number changes a lot. If even one is missing there is no effect at all, so if it doesn't change, check which of the three is missing.

Operations decision guide

Write /root/ngb/runbook.md. It must have four h2 headings, ## 증상별 첫 확인, ## 버퍼링, ## 본문 크기 and ## 커넥션 재사용, and all five words proxy_buffering, client_max_body_size, client_body_buffer_size, keepalive and upstream_response_time must appear, and the two time values measured in step 2 must be quoted as numbers.

A document that lists only the advantages of each setting is not a document. You have to write what you gain and what you give up, using the numbers you measured in the earlier steps, so that six months from now someone can touch those values.