NGINX timeouts: fix a nasty 502 Bad Gateway race condition

This was a hard one. Many hours tuning sysctl settings, running tcpdump, re-architecting flows, and trying to recreate a rare and intrusive error before figuring out what was happening.

Summary: the default nginx keepalive_timeout is incompatible with the Google Cloud Platform HTTP(S) Load Balancer!

You must increase nginx's keepalive_timeout, or risk intermittent and sporadic 502 Bad Gateway responses to POST requests.

# Tune nginx keepalives to work with the GCP HTTP(S) Load Balancer:
keepalive_timeout 650;
keepalive_requests 10000;

The "650 seconds" here is not arbitrary, see below for justification of why we picked this specific timeout. Notably, this is opposite of the advice that most articles will give you, but most of them are configuring nginx for direct connections and not for sitting behind a global load balancer.

In-depth root cause

Several times a day, POST requests to our API would return a 502 Bad Gateway response, with no backend log of the error. Long ago we added client-side retries to our API libraries to handle these cases, but I decided to finally root-cause this bug once and for all so we didn't have to keep patching it across libraries.

In Google Cloud Logging, you can see if you are experiencing these particular 502 responses using an advanced filter:

metadata.serviceName="network.googleapis.com"
httpRequest.status=502
structPayload.statusDetails="backend_connection_closed_before_data_sent_to_client"

Now it gets tricky. There were no other logs that correlated with this rare error—no logs from nginx itself, nothing from the API app, nothing related to any syslog or kernel message—nothing, except rare 502s in load balancer logs.

That looks very much like a problem with the GCP HTTP(S) Load Balancer itself. But, as an ex-Googler who has configured services behind Google load balancers in the past, I knew it was very unlikely that my site was a special snowflake that was hitting some new bug uncaught by the billions of requests that flow through those LBs every day. It was much more likely I had a bad config somewhere.

Digging further, we see more info:

Ah ha. So, this was not a problem finding a backend machine (which would have been "failed_to_pick_backend"). The docs have a tiny description of this error:

backend_connection_closed_before_data_sent_to_client: The backend unexpectedly closed its connection to the load balancer before the response was proxied to the client.

— Google Cloud Platform: Setting Up HTTP(S) Load Balancing

Meaning, a TCP connection is being established from the load balancer to the GCE instance, but the instance is terminating the connection prematurely.

Some things were common to the error:

• It only happened on POST requests, never on GET requests.
• It only happened on our nginx + API services, not on our nginx + static.
• It only happened under moderate traffic load (but the server was not overloaded, still 2–5% CPU usage and plenty of memory). This made it feel like a race condition or timeout problem of some sort.

I finally found the right knob to turn. It turns out that there is a race condition between the Google Cloud HTTP(S) Load Balancer and NGINX's default keep-alive timeout of 65 seconds. The NGINX timeout might be reached at the same time the load balancer tries to re-use the connection for another HTTP request, which breaks the connection and results in a 502 Bad Gateway response from the load balancer.

Let's dig deeper.

I was actually able to reliably reproduce this error using a simple curl POST load test script, combined with an aggressive nginx timeout:

keepalive_timeout 1;  # Don't do this.

And here's a tcpdump of what happened:

1. Load balancer establishes a TCP connection.
2. Load balancer makes first HTTP POST request and receives response.
3. Nginx's keepalive_timeout is reached, nginx sends [FIN,ACK] to close the TCP connection.
4. Load balancer tries to send the second HTTP POST request at the same time as #3 (race condition).
5. nginx says NOOOOO we're done with that! [RST][RST] causing a 502 to be returned to your user from the load balancer, with no log from nginx.

So, why doesn't the load balancer just retry the request?

Well, that's where the POST part of this whole thing becomes important—the Google Cloud HTTP(S) Load Balancer will retry failed GET requests, but will never retry failed POST requests. These retry behaviors are completely undocumented as far as I can tell, but relatively standard practice—GET requests are assumed to be idempotent, and POST requests are not.

So what timeout should we use to fix this? Unfortunately, the load balancer timeout is also undocumented on the actual Load Balancer docs. After some tcpdump research, I found that it matches the same ten minute TCP timeout noted elsewhere in GCE.

If you're familiar with GCE, you might be thinking that we missed the tcp_keepalive_time tuning mentioned in General tips for using Compute Engine. We didn't. :) This error happens regardless of the fact that we had tuned sysctl net.ipv4.tcp_keepalive_time long ago based on the docs. I haven't completely figured out why, but I assume this is because the connection is inbound not outbound, and NGINX probably sets custom socket options that override the system defaults and then enforces its own keepalive_timeout regardless.

To fix this race condition, set "keepalive_timeout 650;" in nginx so that your timeout is longer than the 600 second timeout in the GCP HTTP(S) Load Balancer. This causes the load balancer to be the side that closes idle connections, rather than nginx, which fixes the race condition! (This is not a 100% accurate description for how closing TCP connections works, but it's fair enough for here).

# Tune nginx keepalives to work with the GCP HTTP(S) Load Balancer:
keepalive_timeout 650;
keepalive_requests 10000;

After setting this, we have not seen a single 502 Bad Gateway response from our APIs in weeks.