It Is a 504, but a Different Timeout Fired

In one line

502 and 504 are the names of symptoms, and the name of the culprit is already written on one line of error.log. The moment you start guessing without reading that line, time starts to leak away.

Why this was needed

The most expensive mistake in incident response is not failing to find the cause but being confident about the wrong cause.

A typical day goes like this. A 502 shows up in monitoring. You think "the backend must be dead" and restart the WAS. It doesn't help. You think "then it must be slow" and raise proxy_read_timeout to 30 seconds. It doesn't help. You think "we must be short on servers" and add instances. It doesn't help. Three hours pass, and all that time error.log has held the answer since the first minute.

So this course does not start with reading logs. You create the failures yourself. You build by hand a dead port, a port that doesn't accept connections, a slow response and a header larger than the buffer, and watch with your own eyes what nginx writes at each one. A phrase you have seen once, you recognize in 0.5 seconds the next time you see it in a real incident.

The four signatures

The four entries below were actually reproduced and copied from the lab image (nginx 1.24.0). We have marked which part of each line points to the culprit.

① The upstream is not running at all → 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 means the TCP connection itself was refused. Raising any timeout here does nothing. The reason raising a timeout for a 502 is wasted effort is in this one line — there was no time to wait at all. The kernel sent back an RST immediately.

② The upstream is running but slow → 504

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

③ The upstream doesn't even accept the connection → 504

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

Put ② and ③ side by side. The status code is the same 504, and the error number in parentheses is the same 110. The only difference is one phrase at the end.

Phrase	The setting that actually fired
`while connecting to upstream`	`proxy_connect_timeout`
`while reading response header from upstream`	`proxy_read_timeout`
`while sending request to upstream`	`proxy_send_timeout`

What happens if you don't read this phrase is the central scene of this course. In step 5 of the lab, you put proxy_read_timeout 30s in that spot. You have declared that you will wait 30 seconds. Yet the request still drops with a 504 after 2 seconds. What fired was proxy_connect_timeout 2s. The timeout you raised was not the timeout that fired.

This is what lies behind "I raised the timeout and it still isn't fixed." It is the reason you must read the phrase in the log before choosing which value to raise.

④ The response header is larger than the proxy buffer → 502

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

This is the nastiest of the four. The server is perfectly alive, the health check stays green, and if you hit it with curl you get a 200. Only certain users get a 502. Those users are usually people who log in through SSO and have a large session cookie, or a long permission list that bloats the response header.

The default of proxy_buffer_size is 4k, and the whole response header has to fit in this one buffer. If it doesn't, nginx cannot process the response even though it received it, and returns a 502. The 502 as the specification defines it means not "the upstream is dead" but "the gateway received an invalid response from the upstream", and this case is exactly that definition.

There is one more trap here. If you raise only proxy_buffer_size to 16k, nginx won't start at all.

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

You must raise proxy_buffers as well. The first time you see this message at dawn, your hands freeze. Once you have seen it, it is nothing.

Two columns of access.log sort out the branches

If error.log points to the culprit, access.log decides which direction to look. Putting these three variables in the log format is the cheapest investment in this course.

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

Let's look at three measured lines.

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"

First line: ut and rt are the same. The upstream is slow. You should look at the app or the DB.
Second line: ut is 0.049 seconds but rt is 4.173 seconds. The app has already finished and the transfer is slow. However much you dig through the app log, all you find is "responded in 0.05 seconds".
Third line: us=-. The dash means "it never went to the upstream", and at that moment there is no trace at all in the application log. nginx answered by itself.

If you can read us=-, the answer "there is no such request in our app log" becomes evidence. If you can't, that answer just sounds like passing the blame.

What you see in the field

Step on the last rung of the diagnostic ladder first. Skip the proxy and hit the upstream directly once, keeping the original Host header.

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

If it is healthy here, the problem is between the proxy and the upstream (configuration, headers, buffers, timeouts), and if it fails here too, the proxy is innocent. This one call halves the search space. If you leave out -H 'Host: ...', then where virtual-host routing applies you reach an entirely different app, and the comparison is meaningless.

When you receive a ticket that has only the symptom, first ask for the code and the phrase. "I get a 502" has almost no information. "It's a 502 and the log shows connect() failed (111: Connection refused)" is in effect a root cause report. This one habit changes a team's mean time to recovery.

What you will do in the next lab

You build a failure generator in Python and create by hand a dead port, a port that doesn't respond, a slow response and a large header. Then for each of the four cases, you leave the status code, the phrase in error.log and the timeout that actually fired as evidence files. At the end you write a four-line verdict table and an incident report.