The 504 That Took 35 Seconds: Reading Network Failures by the Clock

A 504 said only "timeout". The 35 seconds it took ruled out DNS and connection refused before reading a single log. Measured in Go: 7 ms, 408 ms, 5.00

Yesterday a colleague asked me what could be causing an error they were seeing. All it said was a 504 timeout, and they had no idea what the timeout was actually related to. So the first question I asked was: how long did it take?

Thirty-five seconds. That number turned out to be worth more than the error code.

Tested environment
Client OS: macOS
Go: 1.26.5
Probe: a small connect-only tool I wrote for this
Cluster side: Kubernetes, behind a gateway returning 504

Why the clock is the first question

I asked that because the time a failure takes tells you more about what kind of error it is than the error code itself.

When you get a fast reply, it means something is answering you: something exists on the other side and is responding. When the wait is long, it means nothing is there.

The rule
Fast means somebody answered. Slow means nobody answered at all.

A fast failure is usually one of two things. The first is NXDOMAIN: there is no IP address associated with that domain name, and the resolver is the one that answers, telling you that no record links that name to an address. The second is connection refused: the reply is fast as well, and it means the host is there and its kernel actively rejected the connection, because no process is listening on that port.

When it takes a long time, it usually means nothing is replying at all. There is nothing on the other side that can respond, so you wait until something gives up: a timeout in the application, in the proxy, or in your own kernel. That is why this failure always takes longer than the two above.

I stopped assuming and measured it

So I decided to demonstrate it by reproducing the same three situations anyone can run into. I wrote a small program in Go that tries to connect to three targets: a domain name that does not exist, an IP address and port where nothing is listening, and an address from a range that is reserved for documentation and is not routed anywhere, which behaves as a black hole.

All three runs use the same five-second timeout on purpose. Two of them fail long before that limit is reached. One of them consumes the whole thing.

go build -o netprobe .
$ time ./netprobe -timeout 5s -target nonexistent-abc123.invalid:443
Operation: nonexistent-abc123.invalid   Description: no such host
0.408 total     exit=3        # NXDOMAIN

$ time ./netprobe -timeout 5s -target 127.0.0.1:9
Envolved: dial tcp 127.0.0.1:9: connect: connection refused
0.007 total     exit=4        # connection refused

$ time ./netprobe -timeout 5s -target 192.0.2.1:80
timeout
5.009 total     exit=5        # black hole

The output made the point on its own.

Failure mode Measured time Who answered What the duration means
NXDOMAIN 408 ms The DNS resolver One round trip to ask, and a definitive answer
Connection refused 7 ms The remote kernel An RST came straight back: nobody is listening
Black hole 5.009 s Nobody Exactly the timeout I configured, not a property of the network

The black hole took five seconds because five seconds is the timeout I passed on the command line. If I had not passed one, the program would have used its own default of two seconds. And with no timeout at all, my kernel would have kept retrying for around seventy-five seconds before giving up, which is not a number I remembered, it is a number I read:

$ sysctl net.inet.tcp.keepinit
net.inet.tcp.keepinit: 75000
Worth noticing
The first two failures have a duration of their own. The black hole does not. Its duration is whatever you configured it to be.

Back to the 504

After that, we went back to the cluster. We took the request that was working and compared it against the ones that were timing out, character by character. The difference was at the very end of the path: the failing requests had a couple of extra characters that the working one did not have.

So those thirty-five seconds were not telling us anything about the network. They were the timeout configured in the client that was consuming the endpoint: it was willing to wait thirty-five seconds for a reply that was never going to arrive.

Root cause
The client was requesting a path with extra characters at the end. Nothing on the other side answered that path, so the request sat there until the configured timeout expired and the gateway returned a 504.

What the clock told me, and what it did not

So what the clock told me was that the first two cases I mentioned, NXDOMAIN and connection refused, were not what we were dealing with. Thirty-five seconds meant that nothing on the other side was replying to the client, so I ruled those two out immediately.

What the clock did not tell me was that the path to the endpoint was wrong because it carried an extra character. And more importantly, it did not tell me that this was not a network problem at all: DNS resolved correctly and the TCP connection was established. We only found the real issue when we compared the requests that were working against the ones that were not.

Key takeaway
The clock narrows down the shape of the failure. Comparing a working request against a failing one is what locates it.

References:
RFC 5737 · IPv4 Address Blocks Reserved for Documentation
RFC 2606 · Reserved Top Level DNS Names
Go Documentation · net package

Post a Comment