Learning Hub

How to Fix Random 502 Errors Behind nginx: Reproduce the Keep-Alive Timeout Race With uvicorn, Match the Timeouts, and Check Them in CI

A step-by-step lab on nginx 1.30.6 and uvicorn 0.54.0 that reproduces the rare 502 Bad Gateway caused by nginx reusing an idle connection the moment the app closes it, measures it to the millisecond,...

November 13, 2026 38 Min Read
1

Every so often a perfectly healthy web service answers one request with 502 Bad Gateway. Your application log shows nothing. The same request works when you retry it. The error never appears when you try to reproduce it by hand, and the dashboards say the service is fine. If your app runs behind nginx, one very common cause is a timing accident between two timers: nginx reuses an idle connection to your app at the very moment your app closes it.

Table Of Content

In this tutorial you will build a small FastAPI service behind nginx on your own machine, make that accident happen on purpose, measure exactly when and how often it happens, and try three ways out. You will also see why retrying a POST is not one of them, and you will finish with a check you can run in CI so the mistake cannot come back unnoticed. Everything is measured rather than assumed: I ran every command on nginx 1.30.6 and uvicorn 0.54.0, and the numbers below come from those runs.

The topic is timely because nginx changed a default. The nginx change log for 1.29.7 (24 March 2026) says: “now the keepalive directive in the upstream block is enabled by default”. That change shipped in the stable 1.30 branch, whose first release, 1.30.0, came out on 14 April 2026. Before it, you had to ask for connection reuse with a keepalive line, proxy_http_version 1.1 and a cleared Connection header. Now, for a named upstream block, it happens unless you switch it off. If you upgraded, and your app drops idle connections sooner than nginx does, you can start seeing rare 502s that nothing in your own change history explains.

What you will learn, in plain words

Four terms come up all the time, so here they are before the first command. An upstream is the app that nginx forwards requests to; here it is uvicorn running FastAPI. A keep-alive (persistent) connection is a TCP connection that stays open after a response so that the next request can reuse it and skip the connection handshake. An idle timeout is how long such a connection may sit unused before one side closes it. And a race condition is a bug that only appears when two things happen at almost the same moment.

Here is the whole story in one paragraph. When nginx forwards a request, it may take an idle connection from its pool instead of opening a new one. Your app closes idle connections after its own timeout; uvicorn’s default is 5 seconds. nginx keeps its idle connections for 60 seconds by default, so in normal operation it is the app that ends the connection’s life, not nginx. Neither side tells the other what its timeout is. Usually that does not matter, because the closing message from the app reaches nginx and nginx throws the connection away before it needs it. But if nginx sends a request in the few milliseconds when the app is closing, the request goes onto a connection that is already gone, and nginx gets a reset instead of an answer. That is your 502.

The HTTP standard describes exactly this situation. RFC 9112, section 9.5, says: “From the server’s point of view, the connection is being closed while it was idle, but from the client’s point of view, a request is in progress.” Here is the timeline for a 5 second idle timeout:

app (uvicorn, idle timeout 5 s)             nginx (keeps idle connections 60 s)
   |  reply is finished ------------------->  |  t = 0.000 s   the connection goes idle in nginx's pool
   |                                          |
   |  idle timer fires, app closes (FIN) ---> |  t = 5.000 s
   |                        a new request arrives at nginx just now
   |  <-------- request on the pooled connection  t = 5.001 s   nginx has not read the FIN yet
   |  the connection is gone: reset --------> |
   |                                          |  nginx logs "upstream prematurely closed connection"
   |                                          |  and the client receives 502 Bad Gateway

The window is tiny, which is why the error is rare, random, and invisible in the app’s own log: the app never even sees the request. The rest of the tutorial turns that picture into numbers.

Prerequisites

  • Operating system: I ran everything on Windows 11 with Python 3.13.14, using Git Bash for the commands. The helper code has a Linux and macOS branch, but I did not run it, so treat it as untested. The numbers in this article are for Windows loopback; timings on Linux will differ.
  • Packages: FastAPI 0.162.5 (Starlette 1.10.0), uvicorn 0.54.0 with its default h11 HTTP parser, requests 2.34.2 and pytest 9.2.0, all from PyPI.
  • nginx: 1.30.6, the current stable release, as a zip from nginx.org. I also use 1.28.3, the previous stable release, once, to show what changed. On Linux or macOS, install nginx 1.30 or newer from your package source and change two path helpers in kit.py.
  • Knowledge: you can run a Python script and read a 20 line config file. You do not need to know nginx; the whole configuration is on the page.

Everything listens on 127.0.0.1: nginx on port 9100 and the app on 9101. I use the numeric address on purpose, because on Windows localhost can resolve to IPv6 first and add a delay to every new connection.

Step 1: Create the lab folder and the app

1.1 Set up the environment

Make a folder, create a virtual environment, install the packages and unpack the two nginx versions. The zip files are about 3 MB each. I unpack them with Python because the tar that Git Bash provides cannot read zip files.

mkdir ka_lab && cd ka_lab
python -m venv .venv
.venv/Scripts/python -m pip install fastapi uvicorn requests pytest
curl -L -o nginx-1.30.6.zip https://nginx.org/download/nginx-1.30.6.zip
curl -L -o nginx-1.28.3.zip https://nginx.org/download/nginx-1.28.3.zip
.venv/Scripts/python -c "import zipfile; [zipfile.ZipFile(f'nginx-{v}.zip').extractall('.') for v in ('1.30.6', '1.28.3')]"
nginx-1.30.6/nginx.exe -v
.venv/Scripts/python -c "import fastapi, uvicorn, requests; print(fastapi.__version__, uvicorn.__version__, requests.__version__)"

On Linux or macOS, use .venv/bin/python instead of .venv/Scripts/python. You should see these two lines at the end:

nginx version: nginx/1.30.6
0.162.5 0.54.0 2.34.2

1.2 The app (app.py)

The app does almost nothing, and that is the point: every field it returns exists to make a connection visible. /ping is a read. POST /orders is a write that records its request id in a list when its handler starts, so later we can ask whether a request that failed was ever handled. /processed returns that list. Both routes accept ms (wait that many milliseconds) or until (wait until a wall-clock moment, so many replies can finish at the same instant; Step 5 explains why we want that). Both report peer_port, the source port of the TCP connection the request arrived on. Two requests with the same source port travelled over the same connection, which is how we will see reuse.

# app.py
"""app.py: a tiny FastAPI service that reports which TCP connection carried each request."""
import asyncio
import time

from fastapi import FastAPI, Header, Request

app = FastAPI()
PROCESSED: list[str] = []


@app.get("/ping")
async def ping(request: Request, ms: int = 200, until: float | None = None):
    """Wait (a fixed time, or until a wall-clock moment so that many replies finish together), then say
    which source port nginx used to reach us."""
    await asyncio.sleep(max(0.0, until - time.time()) if until is not None else ms / 1000)
    return {"peer_port": request.client.port, "http_version": request.scope["http_version"],
            "connection_header": request.headers.get("connection"), "finished_at": time.time()}


@app.post("/orders")
async def create_order(request: Request, x_req_id: str = Header(...), ms: int = 200, until: float | None = None):
    """A write: the id is recorded only when this handler actually runs."""
    PROCESSED.append(x_req_id)
    await asyncio.sleep(max(0.0, until - time.time()) if until is not None else ms / 1000)
    return {"peer_port": request.client.port, "id": x_req_id, "finished_at": time.time()}


@app.get("/processed")
async def processed():
    return {"ids": PROCESSED}

Step 2: Write the helper that runs the stack

Every experiment needs uvicorn and nginx started, configured and stopped the same way. This helper, kit.py, does that, and it also holds the nginx configuration as text so each experiment can change it. Here is what each part does.

render_conf builds a complete nginx.conf: a log format that records the status each upstream attempt returned ($upstream_status) and how long connecting took, an optional upstream block, and one location that forwards everything. DEFAULT is the configuration most people write: a named upstream block with one server and nothing else. DIRECT is the other common style, proxy_pass straight to an address with no upstream block. upstream_conf adds extra directives to the block.

start_uvicorn launches the app with a chosen idle timeout. On Windows the python.exe inside a virtual environment is a launcher that starts the real interpreter as a child, so the helper runs the base interpreter with the virtual environment’s packages on its path; that way the process it controls is the server itself. Nginx writes the configuration, checks it with -t, starts nginx, and can read its logs. stack wraps both in a context manager so every experiment cleans up after itself, even when it fails.

# kit.py
"""kit.py: run uvicorn behind nginx (any unpacked nginx version) for the keep-alive lab."""
import contextlib
import os
import re
import signal
import subprocess
import sys
import time

import requests

HERE = os.path.dirname(os.path.abspath(__file__))
WINDOWS = sys.platform == "win32"
UVICORN_PORT = 9101
NGINX_PORT = 9100

HEAD = """worker_processes 1;
error_log logs/error.log error;
pid logs/nginx.pid;
events {
    worker_connections 1024;
}
http {
    log_format ka '$request_method $uri $status ups=$upstream_status conn=$upstream_connect_time';
    access_log logs/access.log ka;
"""
SERVER = """    server {
        listen 127.0.0.1:%d;
        location / {
%s
        }
    }
}
"""


def render_conf(location: list[str], upstream: list[str] | None = None) -> str:
    """The whole nginx.conf: a log format, an optional upstream block, and one proxying location."""
    text = HEAD
    if upstream:
        text += "\n".join("    " + line for line in upstream) + "\n"
    return text + SERVER % (NGINX_PORT, "\n".join(" " * 12 + line for line in location))


def upstream_conf(*extra: str, location_extra: tuple[str, ...] = ()) -> str:
    """A named upstream with extra directives, as most production configs have."""
    block = ["upstream app {", "    server 127.0.0.1:%d;" % UVICORN_PORT, *["    " + e for e in extra], "}"]
    return render_conf(["proxy_pass http://app;", *location_extra], upstream=block)


DEFAULT = upstream_conf()  # a named upstream block and nothing else: no keepalive line, no proxy_http_version
DIRECT = render_conf(["proxy_pass http://127.0.0.1:%d;" % UVICORN_PORT])  # proxy_pass straight to an address, no upstream block


def nginx_dir(version: str) -> str:
    return os.path.join(HERE, f"nginx-{version}")


def nginx_exe(version: str) -> str:
    return os.path.join(nginx_dir(version), "nginx.exe" if WINDOWS else "nginx")


def python_for_servers() -> str:
    """Run the base interpreter on the venv's packages so proc.pid is the server itself (the venv python.exe is a launcher)."""
    return os.path.join(sys.base_prefix, "python.exe") if WINDOWS else sys.executable


def start_uvicorn(timeout_keep_alive: int, app: str = "app:app", port: int = UVICORN_PORT) -> subprocess.Popen:
    env = {**os.environ, "PYTHONUNBUFFERED": "1", "PYTHONDONTWRITEBYTECODE": "1"}
    if WINDOWS:
        env["PYTHONPATH"] = os.path.join(sys.prefix, "Lib", "site-packages")
    log = open(os.path.join(HERE, "uvicorn.log"), "wb")
    proc = subprocess.Popen([python_for_servers(), "-m", "uvicorn", app, "--host", "127.0.0.1", "--port", str(port),
                             "--timeout-keep-alive", str(int(timeout_keep_alive)), "--no-access-log"],
                            cwd=HERE, env=env, stdout=log, stderr=subprocess.STDOUT,
                            creationflags=subprocess.CREATE_NEW_PROCESS_GROUP if WINDOWS else 0)
    wait_for(port, "/processed")
    return proc


def stop_process(proc: subprocess.Popen) -> None:
    proc.send_signal(signal.CTRL_BREAK_EVENT if WINDOWS else signal.SIGTERM)
    try:
        proc.wait(timeout=10)
    except subprocess.TimeoutExpired:
        proc.kill()


def wait_for(port: int, path: str, seconds: float = 20.0) -> None:
    deadline = time.time() + seconds
    while time.time() < deadline:
        try:
            if requests.get(f"http://127.0.0.1:{port}{path}", timeout=0.5).status_code in (200, 502):
                return
        except requests.RequestException:
            time.sleep(0.05)
    raise RuntimeError(f"nothing answered on port {port}")


class Nginx:
    def __init__(self, version: str, conf: str):
        self.version, self.dir = version, nginx_dir(version)
        for name in ("access.log", "error.log"):
            path = os.path.join(self.dir, "logs", name)
            if os.path.exists(path):
                os.remove(path)
        with open(os.path.join(self.dir, "conf", "ka.conf"), "w", newline="\n") as f:
            f.write(conf)
        test = subprocess.run([nginx_exe(version), "-p", self.dir, "-c", "conf/ka.conf", "-t"], capture_output=True, text=True)
        if test.returncode != 0:
            raise RuntimeError(test.stderr)
        subprocess.Popen([nginx_exe(version), "-p", self.dir, "-c", "conf/ka.conf"], cwd=self.dir,
                         stdout=subprocess.DEVNULL, stderr=subprocess.DEVNULL)
        wait_for(NGINX_PORT, "/processed")

    def stop(self) -> None:
        subprocess.run([nginx_exe(self.version), "-p", self.dir, "-c", "conf/ka.conf", "-s", "stop"], capture_output=True)
        time.sleep(0.5)

    def log(self, name: str) -> list[str]:
        path = os.path.join(self.dir, "logs", name)
        if not os.path.exists(path):
            return []
        with open(path, encoding="utf-8", errors="replace") as f:
            return [line.rstrip("\n") for line in f]

    def errors(self, since: int = 0) -> dict[str, int]:
        """nginx error-log lines (after the first `since`), counted by their reason text."""
        counts: dict[str, int] = {}
        for line in self.log("error.log")[since:]:
            m = re.search(r"\[error\] \d+#\d+: \*\d+ (.*?)(?:, client:|$)", line)
            reason = m.group(1) if m else line[:80]
            counts[reason] = counts.get(reason, 0) + 1
        return counts


@contextlib.contextmanager
def stack(conf: str, keep_alive: int = 5, version: str = "1.30.6"):
    """uvicorn (idle timeout `keep_alive` seconds) behind nginx `version` running `conf`."""
    app = start_uvicorn(keep_alive)
    try:
        ngx = Nginx(version, conf)
        try:
            yield ngx
        finally:
            ngx.stop()
    finally:
        stop_process(app)


def processed_ids() -> set[str]:
    return set(requests.get(f"http://127.0.0.1:{UVICORN_PORT}/processed", timeout=5).json()["ids"])

Save kit.py next to app.py. Every step from here on uses it.

Step 3: Watch the app close an idle connection

Before involving nginx, watch the app on its own. The script below starts uvicorn with its default idle timeout of 5 seconds, sends one request over a persistent connection, and then simply waits on the socket. recv() returns an empty result when the other side closes the connection, so the time it takes to return is the time the app waited. Finally the script tries to send a second request on that same connection, which is exactly what nginx does with a pooled connection.

# step03_idle_close.py
"""step03_idle_close.py: watch uvicorn close an idle keep-alive connection, and what a late request on it sees."""
import http.client
import time

import kit

app = kit.start_uvicorn(timeout_keep_alive=5)
try:
    conn = http.client.HTTPConnection("127.0.0.1", kit.UVICORN_PORT, timeout=15)
    conn.request("GET", "/ping?ms=0")
    resp = conn.getresponse()
    resp.read()
    print(f"first request: HTTP {resp.status}, Connection header from the app: {resp.getheader('connection')!r}, "
          f"Keep-Alive header: {resp.getheader('keep-alive')!r}")
    answered = time.perf_counter()
    conn.sock.settimeout(15)
    closed = conn.sock.recv(1)  # blocks until the app says something; an empty read means it closed the connection
    print(f"idle connection: recv() returned {closed!r} {time.perf_counter() - answered:.2f} s after the response")
    try:
        conn.request("GET", "/ping?ms=0")
        conn.getresponse()
        print("second request on the same connection: answered")
    except Exception as exc:
        print(f"second request on the same connection: {type(exc).__name__}")
finally:
    kit.stop_process(app)

The script uses kit.start_uvicorn from the helper you just wrote. Run it with .venv/Scripts/python step03_idle_close.py. This is what I got:

first request: HTTP 200, Connection header from the app: None, Keep-Alive header: None
idle connection: recv() returned b'' 5.01 s after the response
second request on the same connection: ConnectionAbortedError

Three things to notice. First, the app closed the idle connection 5.01 seconds after the reply, which matches --timeout-keep-alive. The uvicorn documentation says: “Close Keep-Alive connections if no new data is received within this timeout (in seconds).” Its default is 5, and the option takes whole seconds only: when I passed 5.0 uvicorn refused it with is not a valid integer. In uvicorn’s source the timer is a single line, self.loop.call_later(self.timeout_keep_alive, self.timeout_keep_alive_handler), and the handler ends in self.transport.close().

Second, the app announced nothing. Its reply had no Keep-Alive header, so nothing told the client how long the connection would live. Even if it had, nginx would not listen: in the nginx 1.30.6 source the table that handles upstream response headers contains a row for Keep-Alive whose handler is ngx_http_upstream_ignore_header_line. Third, the second request failed. The exception name (ConnectionAbortedError here) depends on the operating system, but the meaning is the same: you cannot reuse a connection the other side has closed.

Step 4: Check whether nginx reuses connections by default

Here is the configuration that kit.DEFAULT renders. It is the entire file. There is no keepalive line, no proxy_http_version and no Connection header:

worker_processes 1;
error_log logs/error.log error;
pid logs/nginx.pid;
events {
    worker_connections 1024;
}
http {
    log_format ka '$request_method $uri $status ups=$upstream_status conn=$upstream_connect_time';
    access_log logs/access.log ka;
    upstream app {
        server 127.0.0.1:9101;
    }
    server {
        listen 127.0.0.1:9100;
        location / {
            proxy_pass http://app;
        }
    }
}

The next script sends six requests, each from a brand-new client connection, and prints the source port the app saw. If nginx opens a fresh connection to the app every time, the ports differ. If it reuses one, they repeat. I test three cases: the old stable release, the new stable release with the default style above, and the new release with proxy_pass straight to an address.

# step04_default_keepalive.py
"""step04_default_keepalive.py: does nginx reuse its connection to the app when the config says nothing about keep-alive?"""
import http.client
import json

import kit


def ask(count: int = 6) -> list[dict]:
    """Send `count` requests, each from a brand-new client connection, and keep what the app saw."""
    seen = []
    for _ in range(count):
        conn = http.client.HTTPConnection("127.0.0.1", kit.NGINX_PORT, timeout=10)
        conn.request("GET", "/ping?ms=0", headers={"Connection": "close"})
        seen.append(json.loads(conn.getresponse().read()))
        conn.close()
    return seen


CASES = [
    ("1.28.3", "named upstream block, no keepalive line", kit.DEFAULT),
    ("1.30.6", "proxy_pass straight to an address", kit.DIRECT),
    ("1.30.6", "named upstream block, no keepalive line", kit.DEFAULT),
]
for version, label, conf in CASES:
    with kit.stack(conf, keep_alive=5, version=version):
        seen = ask()
        ports = [s["peer_port"] for s in seen]
        print(f"nginx {version}, {label}")
        print(f"  the app saw HTTP/{seen[0]['http_version']} and a Connection header of {seen[0]['connection_header']!r}")
        print(f"  source ports of the 6 requests: {ports}")
        print(f"  -> {len(set(ports))} connection(s) to the app for {len(ports)} requests")
.venv/Scripts/python step04_default_keepalive.py
nginx 1.28.3, named upstream block, no keepalive line
  the app saw HTTP/1.0 and a Connection header of 'close'
  source ports of the 6 requests: [65499, 65501, 65503, 65505, 65507, 65509]
  -> 6 connection(s) to the app for 6 requests
nginx 1.30.6, proxy_pass straight to an address
  the app saw HTTP/1.1 and a Connection header of None
  source ports of the 6 requests: [65519, 65521, 65523, 65525, 65527, 65529]
  -> 6 connection(s) to the app for 6 requests
nginx 1.30.6, named upstream block, no keepalive line
  the app saw HTTP/1.1 and a Connection header of None
  source ports of the 6 requests: [49153, 49153, 49153, 49153, 49153, 49153]
  -> 1 connection(s) to the app for 6 requests

The result matches the nginx change log, with one detail the log does not spell out. On 1.28.3 the app saw an HTTP/1.0 request with Connection: close, so every request used its own connection. On 1.30.6 with a named upstream block, the app saw HTTP/1.1 with no Connection header, and all six requests travelled over one connection (source port 49153 in my run). That matches the change log: “now ngx_http_proxy_module supports keepalive by default; the default value for proxy_http_version is 1.1; the Connection proxy header is not sent by default anymore.” In the third case, proxy_pass straight to 127.0.0.1:9101 with no upstream block, nginx 1.30.6 still opened six connections in my run. So in my runs the new default applied to the named upstream block, and a config that proxies straight to an address had no pooled connections and nothing to race on.

The nginx documentation gives the numbers behind the default: keepalive 32 local, where “the connections parameter sets the maximum number of idle keepalive connections to upstream servers that are preserved in the cache of each worker process”, and when that number is exceeded, “the least recently used connections are closed”. Another directive in the same block decides how long an idle pooled connection survives: keepalive_timeout, “Default: keepalive_timeout 60s”, with the description “Sets a timeout during which an idle keepalive connection to an upstream server will stay open.” It appeared in nginx 1.15.3. Do not confuse it with the keepalive_timeout you may know from the http level, which defaults to 75 seconds and governs the connection to the browser, not the connection to your app.

So with nginx 1.30 defaults and uvicorn defaults you have a 60 second nginx timeout against a 5 second app timeout. Now let us see what that does.

Step 5: Reproduce the race on purpose

5.1 Why a simple test does not work

If you send a request every few seconds with curl, you will never see the error. The race only exists in a window a few milliseconds wide around the app’s timeout. To hit it on purpose you need to control the idle time of each connection to the millisecond, and you need many connections so that you collect enough samples. To make the experiment faster I also start uvicorn with --timeout-keep-alive 1, so each wave takes about one second instead of five. The mechanism is identical; Step 7 repeats the measurement at the real 5 second default.

The experiment works in waves of 30 concurrent requests. I use 30 because nginx keeps 32 idle upstream connections by default, so 30 connections all survive in the pool. Wave 0 opens the connections. In every later wave, each request is released at a different, known idle time after the previous wave’s replies, spread evenly between 0.95 and 1.05 seconds. This is why the app takes an until parameter: every reply in a wave finishes at the same wall-clock moment, so every connection’s idle clock starts together, and the script can compute each request’s exact idle time. The script records what happened to each request, and at the end we have outcome against idle time.

5.2 The scanning script (scan.py)

fire sends one request: it connects to nginx early, waits until its release time, sends, and records the status, the source port and when the app finished. scan runs the waves and fills in each request’s idle time and whether it reused a connection (its port appeared in the previous wave). totals, print_histogram and print_summary turn the records into the numbers you will read below.

# scan.py
"""scan.py: waves of requests, each released a known idle time after the previous wave's replies."""
import http.client
import json
import random
import statistics
import threading
import time
import uuid

import kit


def fire(method: str, release_at: float, until: float, out: list, wave: int) -> None:
    """Connect to nginx now, send one request at `release_at`; the app answers at wall-clock time `until`."""
    rid = uuid.uuid4().hex[:12]
    record = {"wave": wave, "id": rid, "status": 0, "port": None, "finished_at": None, "sent_at": release_at}
    conn = http.client.HTTPConnection("127.0.0.1", kit.NGINX_PORT, timeout=15)
    try:
        conn.connect()
        while (left := release_at - time.time()) > 0:
            time.sleep(left - 0.002 if left > 0.004 else 0)
        record["sent_at"] = time.time()
        path = ("/ping" if method == "GET" else "/orders") + f"?until={until:.6f}"
        conn.request(method, path, body=b"{}" if method == "POST" else None, headers={"Connection": "close", "X-Req-Id": rid})
        resp = conn.getresponse()
        data = resp.read()
        record["status"] = resp.status
        if resp.status == 200:
            body = json.loads(data)
            record["port"], record["finished_at"] = body["peer_port"], body["finished_at"]
    except Exception:  # a reset or a timeout seen by the client
        record["status"] = 0
    finally:
        conn.close()
    out.append(record)


def scan(ngx: "kit.Nginx", lo: float, hi: float, waves: int, n: int, method: str = "POST") -> dict:
    """Wave 0 opens n connections. In every later wave, request i is released `idle` seconds after the previous
    wave's replies, with idle spread evenly (plus a random offset) over lo..hi."""
    span = hi - lo
    err0, acc0 = len(ngx.log("error.log")), len(ngx.log("access.log"))
    records, previous_ports, finished_prev = [], set(), 0.0
    base = time.time() + 0.5
    for wave in range(waves):
        until = base + span + 0.15
        offsets = [0.0] * n if wave == 0 else [(i + random.random()) / n * span for i in range(n)]
        out: list[dict] = []
        threads = [threading.Thread(target=fire, args=(method, base + off, until, out, wave)) for off in offsets]
        for t in threads:
            t.start()
        for t in threads:
            t.join()
        if wave > 0:
            for r in out:
                r["idle"] = r["sent_at"] - finished_prev
                r["reused"] = r["port"] in previous_ports if r["port"] else None
            records.extend(out)
        previous_ports = {r["port"] for r in out if r["port"]}
        done = [r["finished_at"] for r in out if r["finished_at"]]
        finished_prev = statistics.median(done) if done else until
        base = finished_prev + lo
    acc = [line for line in ngx.log("access.log")[acc0:] if " /ping " in line or " /orders " in line]
    return {"records": records, "lo": lo, "hi": hi, "error_lines": sum(ngx.errors(err0).values()),
            "retries": sum(1 for line in acc if "ups=" in line and ", " in line.split("ups=")[1].split(" conn=")[0])}


def totals(res: dict) -> dict:
    recs = res["records"]
    bad = sorted(r["idle"] for r in recs if r["status"] != 200)
    return {"requests": len(recs), "reused": sum(1 for r in recs if r["reused"]), "client_502": sum(1 for r in recs if r["status"] == 502),
            "other": sum(1 for r in recs if r["status"] not in (200, 502)), "first": bad[0] if bad else None,
            "last": bad[-1] if bad else None, "failed_ids": [r["id"] for r in recs if r["status"] != 200],
            "error_lines": res["error_lines"], "retries": res["retries"]}


def print_histogram(res: dict, width: float = 0.004) -> None:
    """Outcome counts per `width`-second bin of idle time; only bins that contain a failure are listed."""
    bins: dict[int, list[int]] = {}
    for r in res["records"]:
        k = int((r["idle"] - res["lo"]) // width)
        row = bins.setdefault(k, [0, 0])
        row[0] += 1
        row[1] += r["status"] != 200
    print(f"{'idle time after the previous reply':>36} {'requests':>9} {'failed':>7}")
    for k in sorted(bins):
        if bins[k][1]:
            start = res["lo"] + k * width
            print(f"{start * 1000:>20.0f} to {(start + width) * 1000:>5.0f} ms {bins[k][0]:>9} {bins[k][1]:>7}")


def print_summary(label: str, res: dict) -> dict:
    t = totals(res)
    print(f"{label}: {t['requests']} requests, {t['reused']} reused a connection, {t['client_502']} got a 502"
          + (f", {t['other']} other failures" if t["other"] else "")
          + (f"; failures between {t['first'] * 1000:.1f} and {t['last'] * 1000:.1f} ms idle" if t["first"] else ""))
    return t

Two small helpers complete the lab. params.py holds the two shared numbers, and step05_race.py runs the scan against the default configuration with POST requests and reports what happened to the failures.

# params.py
"""params.py: the knobs every step shares."""
SHORT = 1    # uvicorn --timeout-keep-alive for the accelerated experiments (seconds)
N = 30       # requests per wave (nginx keeps 32 idle upstream connections by default)
# step05_race.py
"""step05_race.py: find the idle time at which nginx reuses a connection that the app is closing at that moment."""
import kit
import scan
from params import N, SHORT

with kit.stack(kit.DEFAULT, keep_alive=SHORT) as ngx:
    res = scan.scan(ngx, 0.95, 1.05, 100, N, "POST")
    t = scan.print_summary("POST scan, uvicorn timeout 1 s, nginx defaults", res)
    print()
    scan.print_histogram(res)
    recs = res["records"]
    if t["first"]:
        before = sum(1 for r in recs if r["idle"] < t["first"])
        after = sum(1 for r in recs if r["idle"] > t["last"])
        inside = sum(1 for r in recs if t["first"] <= r["idle"] <= t["last"])
        print(f"\nreleased before the first failure: {before} requests, after the last failure: {after}, in between: {inside}")
    handled = kit.processed_ids()
    print(f"requests that got a 502: {len(t['failed_ids'])}; of those, handled by the app anyway: {sum(1 for i in t['failed_ids'] if i in handled)}")
    print("\nnginx error log, by reason:")
    for reason, count in sorted(ngx.errors().items(), key=lambda kv: -kv[1]):
        print(f"  {count:3d}  {reason}")
.venv/Scripts/python step05_race.py

The scan takes about two minutes. This is the output of my run:

POST scan, uvicorn timeout 1 s, nginx defaults: 2970 requests, 1529 reused a connection, 16 got a 502; failures between 1000.0 and 1004.0 ms idle

  idle time after the previous reply  requests  failed
                 998 to  1002 ms       112      12
                1002 to  1006 ms       124       4

released before the first failure: 1485 requests, after the last failure: 1370, in between: 115
requests that got a 502: 16; of those, handled by the app anyway: 0

nginx error log, by reason:
   10  WSARecv() failed (10053: An established connection was aborted by the software in your host machine) while reading response header from upstream
    3  WSARecv() failed (10054: An existing connection was forcibly closed by the remote host) while reading response header from upstream
    3  upstream prematurely closed connection while reading response header from upstream

5.3 Read the numbers

Out of 2,970 requests, 16 got a 502, and every one of them was released between 1000.0 and 1004.0 milliseconds after the previous reply, right at the app’s one second timeout. Of the 1,485 requests released earlier, none failed, because the connection was still open. Of the 1,370 released later, none failed, because by then nginx had already learned that the app closed the connection and opened a new one. Only the 115 requests inside the narrow band were exposed, and 16 of them lost. The POST scan in Step 6 put its failures between 998.8 and 1002.8 milliseconds, so the band is about 4 to 5 milliseconds wide on this machine. I did not test Linux, so do not assume the same width there.

The line that matters most is the one about the app: of the 16 requests that got a 502, the app handled 0. Their ids never appeared in the app’s list. The app did not fail; it never saw them. That is why your application log is clean.

Finally, the error log. nginx wrote one line for every failure, in three different words for the same event: WSARecv() failed (10053: An established connection was aborted by the software in your host machine), WSARecv() failed (10054: An existing connection was forcibly closed by the remote host) and upstream prematurely closed connection, each followed by while reading response header from upstream. Which wording you get depends on the operating system and on whether the app’s closing message or a reset arrived first. If you search your own error log for while reading response header from upstream and the lines cluster around an idle time equal to your app’s timeout, this is your bug.

Step 6: See what nginx does for a GET and for a POST

The default for proxy_next_upstream is error timeout, which means that when an attempt fails, nginx may pass the request to the next server. The docs add a rule for risky methods: with non_idempotent off, “requests with a non-idempotent method (POST, LOCK, PATCH) are not passed to the next server if a request has been sent to an upstream server”. The standard says the same thing about proxies: RFC 9110, section 9.2.2, states “A proxy MUST NOT automatically retry non-idempotent requests.”

The nginx source also contains a rule for exactly our case. When the failed connection came from the pool, nginx gives the request one more try even if there is only one server in the upstream. Here are the lines from ngx_http_upstream_next in 1.30.6:

if (u->peer.cached && ft_type == NGX_HTTP_UPSTREAM_FT_ERROR) {
    /* TODO: inform balancer instead */
    u->peer.tries++;
}

So I expect GET requests to be retried quietly and POST requests to fail. This script runs the same scan twice, with GET and then with POST, over a narrower range of idle times (0.99 to 1.01 seconds, 40 waves):

# step06_get_vs_post.py
"""step06_get_vs_post.py: the same race for a GET and for a POST, around the idle time where it bites."""
import kit
import scan
from params import N, SHORT

for method in ("GET", "POST"):
    with kit.stack(kit.DEFAULT, keep_alive=SHORT) as ngx:
        res = scan.scan(ngx, 0.99, 1.01, 40, N, method)
        scan.print_summary(f"{method} scan, idle 0.99 to 1.01 s", res)
        print(f"  nginx error-log lines: {res['error_lines']}, requests nginx silently retried: {res['retries']}")
        access = [line for line in ngx.log("access.log") if " /ping " in line or " /orders " in line]
        odd = [line for line in access if "ups=" in line and (", " in line.split("ups=")[1].split(" conn=")[0] or " 502 " in line)]
        print("  access log lines where nginx saw a failure:")
        for line in odd[:4]:
            print("    " + line)
.venv/Scripts/python step06_get_vs_post.py
GET scan, idle 0.99 to 1.01 s: 1170 requests, 648 reused a connection, 0 got a 502
  nginx error-log lines: 8, requests nginx silently retried: 7
  access log lines where nginx saw a failure:
    GET /ping 200 ups=502, 200 conn=0.000, 0.002
    GET /ping 200 ups=502, 502, 200 conn=0.000, 0.000, 0.000
    GET /ping 200 ups=502, 200 conn=0.000, 0.000
    GET /ping 200 ups=502, 200 conn=0.000, 0.000
POST scan, idle 0.99 to 1.01 s: 1170 requests, 619 reused a connection, 20 got a 502; failures between 998.8 and 1002.8 ms idle
  nginx error-log lines: 20, requests nginx silently retried: 0
  access log lines where nginx saw a failure:
    POST /orders 502 ups=502 conn=0.000
    POST /orders 502 ups=502 conn=0.000
    POST /orders 502 ups=502 conn=0.000
    POST /orders 502 ups=502 conn=0.000

The GET scan shows no failure on the client side at all: 1,170 requests, 0 got a 502. But nginx’s error log has 8 lines, and its access log shows what happened. ups=502, 200 means the first attempt on a pooled connection failed and a second attempt succeeded; ups=502, 502, 200 means two pooled connections in a row were already dead before nginx reached a live one. Seven requests were retried this way, so the failures are real but invisible to users. The cost is a little latency and, more importantly, errors that only an operator reading logs will ever notice.

The POST scan shows what users see: 20 of 1,170 requests received the 502, again only in a band of about 4 milliseconds (998.8 to 1002.8 in this run), and the access log shows a single failed attempt (ups=502) with no retry. That is the 502 that reaches customers, and it hits exactly the requests where a retry is not obviously safe.

Step 7: Fix it by making nginx the one that closes

7.1 The rule

The race needs the app to close a connection that nginx still wants to use. The fix is to flip who closes first. If nginx gives up on an idle connection before the app would, then nginx is the one that closes it, at a moment when nginx knows it is not using that connection, so there is no request in flight to lose. In one line: the app’s idle timeout must be longer than nginx’s idle timeout for that upstream, with some margin. You can reach that in either of two places. Lower nginx’s timeout inside the upstream block:

upstream app {
    server 127.0.0.1:9101;
    keepalive_timeout 4s;
}

Or raise the app’s, which for uvicorn means uvicorn app:app --timeout-keep-alive 75, longer than nginx’s default of 60 seconds. I use a margin of one second in the examples. That is my own choice, not a standard. A margin is sensible because the two timers do not start at exactly the same moment; Node.js ships a similar cushion by default, its keepAliveTimeoutBuffer, “Default: 1000 (1 second)”, which “helps reduce connection reset (ECONNRESET) errors by increasing the socket timeout slightly beyond the advertised keep-alive timeout.”

7.2 Prove it with the same scan

A fix that merely stops connections from being reused would also remove the error, so the proof has two halves: no failures, and reuse still happening. This script tries four configurations. For the first fix I scan around nginx’s own timeout as well as the app’s. In the row for the rule the other way round, nginx closes at 1 second and the app at 2 seconds, which is the same rule at a different scale.

# step07_fixes.py
"""step07_fixes.py: the ways out, each probed around the idle time where the app closes (and where nginx closes)."""
import kit
import scan
from params import N, SHORT

# (label, nginx conf, app timeout in seconds, [(idle from, idle to, what that range probes)])
CONFIGS = [
    ("defaults (the problem)", kit.DEFAULT, SHORT, [(0.98, 1.02, "app closes at 1 s")]),
    ("fix 1: nginx closes first (keepalive_timeout 500ms, app 1 s)", kit.upstream_conf("keepalive_timeout 500ms;"), SHORT,
     [(0.46, 0.54, "nginx closes at 0.5 s"), (0.98, 1.02, "app would close at 1 s")]),
    ("fix 1, same rule the other way (keepalive_timeout 1s, app 2 s)", kit.upstream_conf("keepalive_timeout 1s;"), 2,
     [(0.98, 1.02, "nginx closes at 1 s"), (1.98, 2.02, "app would close at 2 s")]),
    ("fix 2: no upstream keep-alive (keepalive 0, app 1 s)", kit.upstream_conf("keepalive 0;"), SHORT, [(0.98, 1.02, "app closes at 1 s")]),
]
print(f"{'configuration':<66} {'idle range (s)':<15} {'requests':>8} {'reused':>7} {'502s':>5}")
for label, conf, app_timeout, ranges in CONFIGS:
    with kit.stack(conf, keep_alive=app_timeout) as ngx:
        for lo, hi, _what in ranges:
            t = scan.totals(scan.scan(ngx, lo, hi, 40, N, "POST"))
            print(f"{label:<66} {lo:.2f} to {hi:.2f}   {t['requests']:>8} {t['reused']:>7} {t['client_502']:>5}")
            label = ""
.venv/Scripts/python step07_fixes.py
configuration                                                      idle range (s)  requests  reused  502s
defaults (the problem)                                             0.98 to 1.02       1170     608    16
fix 1: nginx closes first (keepalive_timeout 500ms, app 1 s)       0.46 to 0.54       1170     590     0
                                                                   0.98 to 1.02       1170       0     0
fix 1, same rule the other way (keepalive_timeout 1s, app 2 s)     0.98 to 1.02       1170     591     0
                                                                   1.98 to 2.02       1170       0     0
fix 2: no upstream keep-alive (keepalive 0, app 1 s)               0.98 to 1.02       1170       0     0

Read the table row by row. The defaults lose 16 of 1,170 requests, as before. With keepalive_timeout 500ms and the app at 1 second, scanning around nginx’s own 0.5 second timer shows 590 requests that reused a connection and 0 that failed, so the keep-alive is still working and the moment nginx closes is harmless. Scanning around the app’s 1 second shows no reuse at all, because nginx already closed everything at 0.5 seconds, and again no failures. The same rule at the other scale, nginx at 1 second and the app at 2, gives 591 reused and 0 failed around nginx’s timer, and 0 and 0 around the app’s. The last row, keepalive 0, switches the pool off: nothing is reused, so nothing can race.

7.3 Confirm it at the real 5 second default

One second is a convenient stand-in, but you run uvicorn at 5. This script repeats the baseline and the fix with uvicorn’s real default timeout, scanning from 4.98 to 5.02 seconds. In the fixed configuration it also scans around nginx’s own 4 second timer, to show that reuse is alive.

# step07_real_defaults.py
"""step07_real_defaults.py: the same race at uvicorn's real 5 s default, and the fix at the same real scale."""
import kit
import scan
from params import N

CONFIGS = [
    ("nginx defaults (upstream keepalive_timeout 60s)", kit.DEFAULT, [(4.98, 5.02, 30)]),
    ("keepalive_timeout 4s in the upstream block", kit.upstream_conf("keepalive_timeout 4s;"), [(3.98, 4.02, 12), (4.98, 5.02, 30)]),
]
print(f"{'configuration (uvicorn --timeout-keep-alive 5)':<50} {'idle range (s)':<15} {'requests':>8} {'reused':>7} {'502s':>5}")
for label, conf, ranges in CONFIGS:
    with kit.stack(conf, keep_alive=5) as ngx:
        for lo, hi, waves in ranges:
            t = scan.totals(scan.scan(ngx, lo, hi, waves, N, "POST"))
            print(f"{label:<50} {lo:.2f} to {hi:.2f}   {t['requests']:>8} {t['reused']:>7} {t['client_502']:>5}")
            label = ""
.venv/Scripts/python step07_real_defaults.py
configuration (uvicorn --timeout-keep-alive 5)     idle range (s)  requests  reused  502s
nginx defaults (upstream keepalive_timeout 60s)    4.98 to 5.02        870     454    12
keepalive_timeout 4s in the upstream block         3.98 to 4.02        330     170     0
                                                   4.98 to 5.02        870       0     0

At the real default the picture is the same. With nginx’s defaults and uvicorn at 5 seconds, 12 of 870 requests released between 4.98 and 5.02 seconds after the previous reply got a 502, and 454 of them reused a pooled connection. With keepalive_timeout 4s in the upstream block, the scan around nginx’s own 4 second timer shows 170 of 330 requests reusing a connection and 0 failures, and the scan around the app’s 5 second timer shows 0 reused (nginx closed them a second earlier) and 0 failures out of 870. Matching the timeouts removes the race at the scale you actually run.

7.4 What the same rule looks like on other servers

The idea is not specific to uvicorn and nginx. Any component that closes idle connections on a timer can race with a client that reuses them. These are the defaults documented by the projects themselves; look up the setting in your own stack before you rely on this table.

Component Default idle timeout Where to set it
uvicorn 0.54.0 5 seconds --timeout-keep-alive (whole seconds)
Gunicorn 2 seconds; the sync worker “does not support persistent connections and will ignore this option” --keep-alive
Node.js http server 5000 milliseconds, plus a 1000 millisecond buffer in recent versions server.keepAliveTimeout
nginx upstream pool (your side of the problem) 60 seconds keepalive_timeout inside upstream
AWS Application Load Balancer 60 seconds the load balancer’s connection idle timeout attribute

The AWS documentation spells out the same rule and the same symptom: “We also recommend that you configure the idle timeout of your application to be larger than the idle timeout configured for the load balancer.” If the app closes first, “the load balancer might send a request to the application before it receives the packet indicating that the connection is closed. If this is the case, then the load balancer sends an HTTP 502 Bad Gateway error to the client.” That is the same race with a different proxy in the middle.

Step 8: What switching keep-alive off costs

keepalive 0 works, and it is the right emergency fix on a system you cannot change quickly. But it is not free: every request now pays for a new TCP connection. This script measures a steady client sending 400 requests through nginx to a do-nothing route, three times per configuration, and prints the middle round. The client keeps its own connection to nginx the whole time, so only the upstream side differs.

# step08_cost.py
"""step08_cost.py: what turning upstream keep-alive off costs, measured on loopback with one steady client."""
import http.client
import json
import statistics
import time

import kit


def run(count: int = 400) -> tuple[float, float, float, int]:
    conn = http.client.HTTPConnection("127.0.0.1", kit.NGINX_PORT, timeout=10)
    times, ports = [], set()
    for _ in range(count):
        start = time.perf_counter()
        conn.request("GET", "/ping?ms=0")
        ports.add(json.loads(conn.getresponse().read())["peer_port"])
        times.append((time.perf_counter() - start) * 1000)
    conn.close()
    total = sum(times) / 1000
    times.sort()
    return count / total, statistics.median(times), times[int(count * 0.95)], len(ports)


print(f"{'configuration':<34} {'requests/s':>11} {'median ms':>10} {'p95 ms':>8} {'connections to app':>19}")
for label, conf in (("upstream keep-alive on (default)", kit.DEFAULT), ("keepalive 0 (off)", kit.upstream_conf("keepalive 0;"))):
    with kit.stack(conf, keep_alive=5):
        run(50)  # warm-up
        rounds = sorted((run() for _ in range(3)), key=lambda r: r[0])
        rps, median, p95, conns = rounds[1]  # the middle round of three
        print(f"{label:<34} {rps:>11.0f} {median:>10.2f} {p95:>8.2f} {conns:>19}")
.venv/Scripts/python step08_cost.py
configuration                       requests/s  median ms   p95 ms  connections to app
upstream keep-alive on (default)          2223       0.44     0.51                   1
keepalive 0 (off)                          628       1.59     1.73                 400

With the pool on, one connection carried all 400 requests and the median request took 0.44 milliseconds. With it off, there were 400 connections and the median was 1.59 milliseconds, about 3.6 times slower, with throughput down from 2,223 to 628 requests per second. This is loopback on one Windows machine, so the absolute numbers are small; across a real network, and especially if the connection to your app uses TLS, every extra handshake costs more. Matching the timeouts removes the race and keeps the speed.

Step 9: Why retrying a POST is not a fix

One tempting shortcut is to add non_idempotent to proxy_next_upstream, which makes nginx retry POST requests as well. It removes the error message. The lab below shows what else it does. This time the upstream is a deliberately flaky server, flaky.py, that models a different failure: it does the work, then drops the connection before it answers, once per request id. (Our race never reaches the app; this models the failures where it does, such as a crash after the commit.)

# flaky.py
"""flaky.py: an upstream that does the work, then drops the connection before answering, once per request id."""
import asyncio
import json

SEEN: dict[str, int] = {}


async def handle(reader: asyncio.StreamReader, writer: asyncio.StreamWriter) -> None:
    try:
        while True:
            head = (await reader.readuntil(b"\r\n\r\n")).decode("latin-1").split("\r\n")
            headers = {line.split(":", 1)[0].lower(): line.split(":", 1)[1].strip() for line in head[1:] if ":" in line}
            if head[0].startswith("GET /processed"):
                body = json.dumps({"counts": SEEN}).encode()
            else:
                length = int(headers.get("content-length", 0))
                if length:
                    await reader.readexactly(length)
                rid = headers["x-req-id"]
                SEEN[rid] = SEEN.get(rid, 0) + 1  # the work is done and committed here
                if SEEN[rid] == 1:
                    return  # first attempt: drop the connection before the answer is written
                body = b'{"ok": true}'
            writer.write(b"HTTP/1.1 200 OK\r\nContent-Type: application/json\r\nContent-Length: %d\r\n\r\n" % len(body) + body)
            await writer.drain()
    except (asyncio.IncompleteReadError, ConnectionError):
        pass
    finally:
        writer.close()


async def main() -> None:
    server = await asyncio.start_server(handle, "127.0.0.1", 9101)
    async with server:
        await server.serve_forever()


asyncio.run(main())
# step09_retry_hazard.py
"""step09_retry_hazard.py: why retrying a POST is not a fix. The upstream commits the work, then drops the answer."""
import http.client
import json
import subprocess
import time
import uuid

import kit

CONFIGS = [
    ("nginx defaults (idempotent requests only)", kit.DEFAULT),
    ("proxy_next_upstream error timeout non_idempotent",
     kit.upstream_conf(location_extra=("proxy_next_upstream error timeout non_idempotent;",))),
]
for label, conf in CONFIGS:
    flaky = subprocess.Popen([kit.python_for_servers(), "flaky.py"], cwd=kit.HERE)
    kit.wait_for(kit.UVICORN_PORT, "/processed")
    try:
        ngx = kit.Nginx("1.30.6", conf)
        try:
            ids, statuses = [], []
            for _ in range(20):
                rid = uuid.uuid4().hex[:12]
                conn = http.client.HTTPConnection("127.0.0.1", kit.NGINX_PORT, timeout=10)
                conn.request("POST", "/orders", body=b"{}", headers={"X-Req-Id": rid, "Connection": "close"})
                statuses.append(conn.getresponse().status)
                conn.close()
                ids.append(rid)
            direct = http.client.HTTPConnection("127.0.0.1", kit.UVICORN_PORT)
            direct.request("GET", "/processed")
            counts = json.loads(direct.getresponse().read())["counts"]
            print(f"=== {label}")
            print(f"  client saw: {sum(s == 200 for s in statuses)} x 200, {sum(s == 502 for s in statuses)} x 502 (of {len(statuses)} POSTs)")
            print(f"  upstream ran the work {sum(counts.get(i, 0) for i in ids)} times for {len(ids)} orders; "
                  f"{sum(1 for i in ids if counts.get(i, 0) > 1)} orders ran twice")
        finally:
            ngx.stop()
    finally:
        flaky.terminate()
        flaky.wait(timeout=10)
        time.sleep(0.3)
.venv/Scripts/python step09_retry_hazard.py
=== nginx defaults (idempotent requests only)
  client saw: 0 x 200, 20 x 502 (of 20 POSTs)
  upstream ran the work 20 times for 20 orders; 0 orders ran twice
=== proxy_next_upstream error timeout non_idempotent
  client saw: 20 x 200, 0 x 502 (of 20 POSTs)
  upstream ran the work 40 times for 20 orders; 20 orders ran twice

With nginx’s defaults, all 20 POSTs came back as 502 although the app had done the work for each of them once. With non_idempotent enabled, all 20 came back as 200, and the app ran the work 40 times for 20 orders: every order was created twice. For a payment or an order, that is worse than a visible error. RFC 9110 explains the underlying problem: a client “SHOULD NOT automatically retry a request with a non-idempotent method unless it has some means to know that the request semantics are actually idempotent, regardless of the method”. The safe way to give POST that means is an idempotency key that the app checks before doing the work, which is the subject of how to prevent duplicate charges with idempotency keys. Fix the timeouts first, then add idempotency keys if you also want safe retries for writes.

Step 10: Guard the rule in CI

A timeout rule that lives in two different files, the nginx config and the app’s start command, is exactly the kind of rule that breaks silently when someone edits one of them. The audit below reads the output of nginx -T (which prints the effective configuration), takes the app’s idle timeout for each upstream from the command line, and fails when an upstream keeps idle connections for longer than the app allows. It knows the nginx 1.29.7 change: for versions from 1.29.7 an upstream block with no keepalive line counts as keepalive 32, and for older versions as off.

# ka_audit.py
"""ka_audit.py: check that nginx gives up an idle upstream connection before the app does.

    nginx -T 2>&1 | python ka_audit.py - --nginx 1.30.6 --app app=5

Exit code 0: every upstream is safe. 1: some upstream keeps idle connections longer than its app allows. 2: unknown input.
"""
import argparse
import re
import sys

UNITS = {"ms": 0.001, "s": 1, "m": 60, "h": 3600, "d": 86400, "w": 604800}
DEFAULT_TIMEOUT = 60.0  # keepalive_timeout inside an upstream block (nginx docs: Default 60s)
KEEPALIVE_ON_BY_DEFAULT = (1, 29, 7)  # nginx CHANGES: from 1.29.7 an upstream block keeps idle connections without a keepalive line
DEFAULT_KEEPALIVE = 32  # the documented default: keepalive 32 local


def seconds(text: str) -> float:
    """Read an nginx time value such as 500ms, 4s, 1m or 1h30m."""
    parts = re.findall(r"(\d+)(ms|s|m|h|d|w)", text)
    if not parts or "".join(n + u for n, u in parts) != text:
        raise ValueError(f"cannot read nginx time {text!r}")
    return sum(int(n) * UNITS[u] for n, u in parts)


def upstreams(conf: str, version: tuple[int, ...]) -> dict[str, dict]:
    """{name: {'keepalive': idle connections kept, 'timeout': seconds an idle one is kept}} for every upstream block."""
    conf = re.sub(r"#[^\n]*", "", conf)
    found = {}
    for name, body in re.findall(r"\bupstream\s+(\S+)\s*\{([^{}]*)\}", conf):
        ka = re.search(r"\bkeepalive\s+(\d+)", body)
        kt = re.search(r"\bkeepalive_timeout\s+([^;\s]+)\s*;", body)
        default = DEFAULT_KEEPALIVE if version >= KEEPALIVE_ON_BY_DEFAULT else 0
        found[name] = {"keepalive": int(ka.group(1)) if ka else default, "timeout": seconds(kt.group(1)) if kt else DEFAULT_TIMEOUT}
    return found


def check(found: dict[str, dict], app_seconds: dict[str, float], margin: float) -> list[tuple[str, str, str]]:
    """One (upstream, 'ok' | 'FAIL' | 'unknown', explanation) row per upstream."""
    rows = []
    for name, up in found.items():
        if up["keepalive"] == 0:
            rows.append((name, "ok", "nginx keeps no idle connections to it"))
        elif name not in app_seconds:
            rows.append((name, "unknown", f"nginx keeps idle connections for {up['timeout']:g} s; pass --app {name}=<the app's idle timeout>"))
        elif app_seconds[name] >= up["timeout"] + margin:
            rows.append((name, "ok", f"the app waits {app_seconds[name]:g} s, nginx gives up after {up['timeout']:g} s"))
        else:
            rows.append((name, "FAIL", f"the app closes idle connections after {app_seconds[name]:g} s but nginx keeps them for "
                                       f"{up['timeout']:g} s; set the app above {up['timeout'] + margin:g} s or keepalive_timeout below "
                                       f"{app_seconds[name] - margin:g} s"))
    return rows


def main(argv: list[str] | None = None) -> int:
    parser = argparse.ArgumentParser(description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter)
    parser.add_argument("conf", help="a file made with `nginx -T`, or - for standard input")
    parser.add_argument("--nginx", required=True, help="nginx version, for example 1.30.6")
    parser.add_argument("--app", action="append", default=[], metavar="UPSTREAM=SECONDS", help="the app's idle timeout for an upstream")
    parser.add_argument("--margin", type=float, default=1.0, help="seconds the app must outlast nginx by (default 1)")
    args = parser.parse_args(argv)
    try:
        version = tuple(int(part) for part in args.nginx.split("."))
        app_seconds = {name: float(value) for name, value in (item.split("=", 1) for item in args.app)}
        text = sys.stdin.read() if args.conf == "-" else open(args.conf, encoding="utf-8", errors="replace").read()
        rows = check(upstreams(text, version), app_seconds, args.margin)
    except (ValueError, OSError) as exc:
        print(f"ka_audit: {exc}", file=sys.stderr)
        return 2
    for name, verdict, why in rows:
        print(f"{verdict:<8}{name}: {why}")
    if not rows:
        print("ka_audit: no upstream block found", file=sys.stderr)
        return 2
    return 1 if any(v == "FAIL" for _, v, _ in rows) else 2 if any(v == "unknown" for _, v, _ in rows) else 0


if __name__ == "__main__":
    sys.exit(main())

Its exit code is the contract: 0 means every upstream is safe, 1 means at least one upstream keeps idle connections longer than its app allows, and 2 means the input was not understood or an app timeout was not provided for an upstream that keeps connections. The unknown case fails on purpose, so that nobody can make the check pass by omitting a value.

10.1 Tests that pin each rule

# test_ka_audit.py
"""test_ka_audit.py: the audit's rules, one behaviour per test."""
import pytest

import ka_audit

NEW, OLD = (1, 30, 6), (1, 28, 3)


def conf(*lines: str, name: str = "app") -> str:
    body = "\n".join(f"    {line}" for line in ("server 127.0.0.1:9101;", *lines))
    return f"http {{\n  upstream {name} {{\n{body}\n  }}\n}}\n"


def verdicts(text: str, app: dict, version=NEW, margin: float = 1.0) -> list[str]:
    return [v for _, v, _ in ka_audit.check(ka_audit.upstreams(text, version), app, margin)]


@pytest.mark.parametrize("text, expected", [("500ms", 0.5), ("4s", 4), ("1m", 60), ("1m30s", 90), ("2h", 7200)])
def test_reads_nginx_times(text, expected):
    assert ka_audit.seconds(text) == expected


@pytest.mark.parametrize("text", ["", "soon", "5", "4 s", "1x"])
def test_refuses_times_it_cannot_read(text):
    with pytest.raises(ValueError):
        ka_audit.seconds(text)


def test_new_nginx_keeps_connections_by_default_for_60_seconds():
    assert ka_audit.upstreams(conf(), NEW) == {"app": {"keepalive": 32, "timeout": 60.0}}


def test_old_nginx_keeps_nothing_by_default():
    assert ka_audit.upstreams(conf(), OLD) == {"app": {"keepalive": 0, "timeout": 60.0}}
    assert verdicts(conf(), {"app": 5}, OLD) == ["ok"]


def test_old_nginx_with_a_keepalive_line_is_checked():
    assert verdicts(conf("keepalive 16;"), {"app": 5}, OLD) == ["FAIL"]


def test_five_second_app_against_the_default_fails():
    assert verdicts(conf(), {"app": 5}) == ["FAIL"]


def test_app_longer_than_nginx_passes():
    assert verdicts(conf(), {"app": 75}) == ["ok"]


def test_margin_boundary():
    assert verdicts(conf(), {"app": 61}) == ["ok"]
    assert verdicts(conf(), {"app": 60.5}) == ["FAIL"]
    assert verdicts(conf(), {"app": 60.5}, margin=0.5) == ["ok"]


def test_shorter_nginx_timeout_passes():
    assert verdicts(conf("keepalive_timeout 4s;"), {"app": 5}) == ["ok"]
    assert verdicts(conf("keepalive_timeout 500ms;"), {"app": 1}) == ["FAIL"]  # 1 s is not 1 s above 0.5 s
    assert verdicts(conf("keepalive_timeout 500ms;"), {"app": 2}) == ["ok"]


def test_keepalive_zero_needs_no_app_value():
    assert verdicts(conf("keepalive 0;"), {}) == ["ok"]


def test_commented_out_directives_are_ignored():
    assert verdicts(conf("# keepalive_timeout 1s;", "# keepalive 0;"), {"app": 5}) == ["FAIL"]


def test_only_the_offending_upstream_fails():
    text = conf("keepalive_timeout 3s;", name="api") + conf(name="web")
    rows = dict((name, v) for name, v, _ in ka_audit.check(ka_audit.upstreams(text, NEW), {"api": 5, "web": 5}, 1.0))
    assert rows == {"api": "ok", "web": "FAIL"}


def test_main_exit_codes(tmp_path, capsys):
    path = tmp_path / "nginx-T.txt"
    path.write_text(conf(), encoding="utf-8")
    assert ka_audit.main([str(path), "--nginx", "1.30.6", "--app", "app=5"]) == 1
    assert "FAIL" in capsys.readouterr().out
    assert ka_audit.main([str(path), "--nginx", "1.30.6", "--app", "app=75"]) == 0
    assert ka_audit.main([str(path), "--nginx", "1.30.6"]) == 2  # nginx keeps connections and the app's timeout is unknown
    assert ka_audit.main([str(path), "--nginx", "one.thirty"]) == 2
    assert ka_audit.main([str(tmp_path / "missing.txt"), "--nginx", "1.30.6"]) == 2
.venv/Scripts/python -m pytest -q
.....................                                                    [100%]
21 passed in 0.05s

10.2 Break it on purpose

Tests are only useful if they fail when the code is wrong. This script plants seven bugs in the audit, one at a time, and runs the tests against each. All seven must be caught.

# mutants.py
"""mutants.py: plant one bug at a time in ka_audit.py and check that the tests notice."""
import os
import shutil
import subprocess
import sys
import tempfile

HERE = os.path.dirname(os.path.abspath(__file__))
MUTANTS = [
    ("wrong default timeout", "DEFAULT_TIMEOUT = 60.0", "DEFAULT_TIMEOUT = 6.0"),
    ("boundary: >= becomes >", "app_seconds[name] >= up[\"timeout\"] + margin", "app_seconds[name] > up[\"timeout\"] + margin"),
    ("new nginx treated like old", "default = DEFAULT_KEEPALIVE if version >= KEEPALIVE_ON_BY_DEFAULT else 0", "default = 0"),
    ("comments are not stripped", "conf = re.sub(r\"#[^\\n]*\", \"\", conf)", "pass"),
    ("ms read as seconds", "\"ms\": 0.001", "\"ms\": 1"),
    ("keepalive 0 is checked anyway", "if up[\"keepalive\"] == 0:", "if False:"),
    ("unknown app timeout passes", "return 1 if any(v == \"FAIL\" for _, v, _ in rows) else 2 if any(v == \"unknown\" for _, v, _ in rows) else 0",
     "return 1 if any(v == \"FAIL\" for _, v, _ in rows) else 0"),
]
source = open(os.path.join(HERE, "ka_audit.py"), encoding="utf-8").read()
caught = 0
for label, old, new in MUTANTS:
    assert source.count(old) == 1, f"mutant {label!r}: the original text occurs {source.count(old)} times"
    with tempfile.TemporaryDirectory() as tmp:
        shutil.copy(os.path.join(HERE, "test_ka_audit.py"), tmp)
        with open(os.path.join(tmp, "ka_audit.py"), "w", encoding="utf-8", newline="\n") as f:
            f.write(source.replace(old, new))
        run = subprocess.run([sys.executable, "-m", "pytest", "-q", "-p", "no:cacheprovider", "--no-header"], cwd=tmp, capture_output=True,
                             text=True, env={**os.environ, "PYTHONDONTWRITEBYTECODE": "1", "COLUMNS": "170"})
    failed = run.stdout.strip().splitlines()[-1]
    caught += run.returncode != 0
    print(f"{'caught' if run.returncode else 'MISSED'}  {label:<32} {failed}")
print(f"{caught} of {len(MUTANTS)} planted bugs caught")
.venv/Scripts/python mutants.py
caught  wrong default timeout            3 failed, 18 passed in 0.08s
caught  boundary: >= becomes >           2 failed, 19 passed in 0.08s
caught  new nginx treated like old       7 failed, 14 passed in 0.08s
caught  comments are not stripped        1 failed, 20 passed in 0.07s
caught  ms read as seconds               2 failed, 19 passed in 0.07s
caught  keepalive 0 is checked anyway    2 failed, 19 passed in 0.07s
caught  unknown app timeout passes       1 failed, 20 passed in 0.07s
7 of 7 planted bugs caught

10.3 Run it on real nginx -T output

The last script writes three configurations, runs the real nginx -T on each, and pipes the dump into the audit with the app’s 5 second timeout. In your own pipeline the equivalent is nginx -T 2>&1 | .venv/Scripts/python ka_audit.py - --nginx 1.30.6 --app app=5.

# step10_audit.py
"""step10_audit.py: feed the audit the real `nginx -T` output of three configurations."""
import os
import subprocess
import sys

import kit

CASES = [
    ("nginx defaults", kit.DEFAULT),
    ("keepalive_timeout 4s inside the upstream block", kit.upstream_conf("keepalive_timeout 4s;")),
    ("keepalive 0", kit.upstream_conf("keepalive 0;")),
]
directory = kit.nginx_dir("1.30.6")
for label, conf in CASES:
    with open(os.path.join(directory, "conf", "audit.conf"), "w", newline="\n") as f:
        f.write(conf)
    dump = subprocess.run([kit.nginx_exe("1.30.6"), "-p", directory, "-c", "conf/audit.conf", "-T"], capture_output=True, text=True)
    audit = subprocess.run([sys.executable, "ka_audit.py", "-", "--nginx", "1.30.6", "--app", "app=5"],
                           input=dump.stdout + dump.stderr, capture_output=True, text=True)
    print(f"--- {label}: exit code {audit.returncode}")
    print(audit.stdout.rstrip())
.venv/Scripts/python step10_audit.py
--- nginx defaults: exit code 1
FAIL    app: the app closes idle connections after 5 s but nginx keeps them for 60 s; set the app above 61 s or keepalive_timeout below 4 s
--- keepalive_timeout 4s inside the upstream block: exit code 0
ok      app: the app waits 5 s, nginx gives up after 4 s
--- keepalive 0: exit code 0
ok      app: nginx keeps no idle connections to it

The default configuration fails with exit code 1 and an explanation that names both numbers and both ways out; the two fixed configurations pass.

Check that everything works end to end

You now have a lab that reproduces the problem, three fixes and a guard. To check the whole thing, run these in order and compare with the outputs above: step03_idle_close.py (the app closes after about 5 seconds), step04_default_keepalive.py (one connection on nginx 1.30.6, six on 1.28.3), step05_race.py (failures confined to a band of a few milliseconds around 1 second, none handled by the app), step07_fixes.py (zero 502s in every fixed row, reuse still above zero where nginx closes), pytest and mutants.py. The exact counts will differ by a few from run to run, because the race is a matter of milliseconds; the pattern should not.

How to look for this in production

You do not need a lab to check a live system. Add the upstream status and connect time to your access log, then search for the signature.

log_format ka '$request_method $uri $status ups=$upstream_status conn=$upstream_connect_time';
access_log logs/access.log ka;

A request with ups=502, 200 is a silent retry; a request with status 502 and ups=502 is the customer-facing failure. Then compare the idle timeout of your app with nginx’s keepalive_timeout for that upstream, using the audit above. If the same 502 lines also appear in bursts right when you deploy, you may have a second problem: shutting down a service without dropping requests covers that one.

Common mistakes

Testing with a few curl calls

A handful of requests cannot hit a window a few milliseconds wide. The failure is statistical, so test with many connections and controlled idle times, as the scan does, or search your logs.

Changing the http level keepalive_timeout

The directive of the same name in the http or server block governs connections from browsers. The one that matters here lives inside the upstream block. Changing the wrong one does nothing for this bug.

Raising proxy_read_timeout

That timer is about waiting for a slow reply. In this failure the app never replies at all, so a longer read timeout changes nothing.

Setting the app’s timeout in the wrong unit

uvicorn takes whole seconds, Node.js takes milliseconds, and nginx accepts values like 500ms and 4s. A keepAliveTimeout of 75 in Node means 75 milliseconds.

Checking only one upstream

If several apps sit behind one nginx, each upstream needs the rule against its own app’s timeout. The audit takes one --app name=seconds value per upstream for that reason.

Assuming a load balancer in front changes nothing

The same rule applies in every hop. The AWS quote in Step 7 describes the identical failure between a load balancer and an app.

What this lab does not show

I ran everything on Windows 11 over loopback with one nginx worker and one uvicorn process using the h11 parser. I did not test Linux, where the width of the failure band will differ, uvicorn’s optional httptools parser, Gunicorn, Node.js, TLS between nginx and the app, HTTP/2 to the upstream, or a real load balancer. The Gunicorn, Node.js and AWS numbers in the table come from their documentation, not from my runs. The one second experiments stand in for the real 5 second default, and Step 7.3 confirms the same behaviour at 5 seconds. The width of the band and the percentage of failed requests depend on how your traffic spreads idle times, so use them as a way to understand the mechanism, not as a prediction for your system.

Where to go next

If you want to go further on the same stack, these tutorials on this site fit well with this one. Timeouts and deadlines for HTTP calls in Python covers the client side of the same timers. Retrying failed API calls with exponential backoff and jitter and the circuit breaker are the next layers once the 502s are gone. Cache-Control headers in FastAPI and nginx uses the same nginx setup for a different problem, and the power of two choices uses it to compare balancing policies. Try the scan against your own timeouts, for example by setting uvicorn to --timeout-keep-alive 75 and repeating Step 5, to watch the failures disappear.

Sources

Tags:

502 Bad GatewayFastAPIHTTP Keep-AliveNGINXReverse ProxyTimeoutsUvicorn

Share

No Comment! Be the first one.

Leave a Reply

Your email address will not be published. Required fields are marked *

Related Posts