mirror-500-timeout-rootcause-20260802.txt ========================================= Root-cause of the dc0 mirror's repeating `500 read timeout` on dists/jammy-backports/main/dep11/Components-amd64.yml.gz. Commissioned by operator ruling 2026-08-02, exact utterance: "Root-cause the curl/debmirror anomaly first" -- taken in preference to accepting the red gate, to recording error shape/count, or to --ignore-small-errors. Read-only throughout; nothing on the rack or in the mirror tree was modified by this investigation. The anomaly as stated: curl fetched the object in 0.44s (HTTP 200) from the same host, at the same time, while debmirror timed out on it after 300s, twice. -------------------------------------------------------------------------------- 0. VERDICT -------------------------------------------------------------------------------- ROOT CAUSE IS UPSTREAM AND BACKEND-SPECIFIC, NOT A DEFECT IN THIS DEPLOYMENT. `archive.ubuntu.com` is round-robin across NINE A records. ONE of them -- 91.189.92.23 -- HANGS on this specific object while serving its directory siblings normally. The rack's resolver ROTATES the record order per lookup, so each fetch has roughly a 1-in-9 chance of landing on the bad backend and stalling until the client's timeout expires. This CORRECTS the "NOT TRANSIENT" conclusion recorded earlier the same day from two consecutive debmirror failures. The failure is PROBABILISTIC, not deterministic. Measurement wins over the earlier reading (GA-R1 C2). -------------------------------------------------------------------------------- 1. FIRST CORRECTION: THE "500" IS NOT A SERVER 500 -------------------------------------------------------------------------------- LWP::UserAgent synthesises status 500 for CLIENT-side failures. `500 read timeout` is LWP reporting its own timeout, not the archive returning an error. Reading it as a server-side 500 sends the investigation upstream-to-Canonical for the wrong reason. debmirror's timeout default is 300s (/usr/bin/debmirror :629, `our $timeout=300;`), which is exactly the interval observed. -------------------------------------------------------------------------------- 2. HOW debmirror FETCHES (read from the vendor script, not assumed) -------------------------------------------------------------------------------- :938 $ua = LWP::UserAgent->new(keep_alive => 1); :939 $ua->timeout($timeout); :1832 my $response=$ua->get($url, %headers); # with ':content_cb' :1201 dep11_from_release($dist,"$section/dep11"); # unconditional :1384 get_dep11_files(); # unconditional :1620 exit 1 if (!$ignore_small_errors); # AFTER "All done." Two structural facts follow. There is NO dep11 exclusion option -- both dep11 calls are unconditional, so the mirror's scope cannot be narrowed to drop AppStream metadata without patching debmirror. And `--ignore-small-errors` is NOT a bounded tolerance: at :2891 `$num_errors = $t if ($ignore_small_errors);` DISCARDS the error count, so it would read clean on a wholly failed mirror. -------------------------------------------------------------------------------- 3. HYPOTHESIS TESTED AND REFUTED: CONNECTION REUSE -------------------------------------------------------------------------------- Because debmirror sets keep_alive => 1 and curl does not reuse connections, the obvious hypothesis was a stale persistent connection. It is WRONG, and the test inverted it. Same library, same callback style, same host, seconds apart: keep_alive=1 (debmirror's setting) 200 OK bytes=6361 1s keep_alive=0 (control) 500 read timeout bytes=0 30s Connection reuse is not the fault. A sequence test reusing ONE keep-alive agent across five dep11 objects, ending with the failing one, returned 200 on all five. Recorded because it is the hypothesis a reader would form first. -------------------------------------------------------------------------------- 4. THE DECISIVE TEST: FETCH THE OBJECT FROM EACH BACKEND BY IP -------------------------------------------------------------------------------- Nine A records. Each fetched with an explicit Host header, 25s cap. THE FAILING OBJECT (.yml.gz): 185.125.190.81 200 6361 0.305s 185.125.190.82 200 6361 0.302s 185.125.190.83 200 6361 0.284s 91.189.91.81 200 6361 0.139s 91.189.91.82 200 6361 0.136s 91.189.91.83 200 6361 0.140s 91.189.92.22 200 6361 0.344s 91.189.92.23 - - >25s TIMEOUT (curl rc=28) 91.189.92.24 200 6361 0.511s CONTROL, a sibling in the SAME directory (.yml.xz) -- this is what makes it a finding rather than "a backend is down": 91.189.92.23 200 5776 0.543s <-- the same backend, healthy (all other eight also 200 / 5776) So 91.189.92.23 is NOT down and NOT unreachable. It serves the directory's other objects in half a second and hangs specifically on Components-amd64.yml.gz. -------------------------------------------------------------------------------- 5. THE RESOLVER ROTATES, SO BACKEND CHOICE IS PER-REQUEST LUCK -------------------------------------------------------------------------------- Six consecutive `getent ahostsv4 archive.ubuntu.com` calls returned six DIFFERENT orderings. The bad record appeared first once, last twice, and mid-list otherwise. There is no pinning: every fetch re-rolls the dice. MEASURED FAILURE RATE, 12 sequential fetches through normal resolution: 11 x 200 / 6361 bytes / 0.14-0.51s 1 x timeout at >20s = 1 failure in 12 (~8%), consistent with exactly one bad record out of nine. -------------------------------------------------------------------------------- 6. RESIDUAL, DECLARED RATHER THAN EXPLAINED AWAY -------------------------------------------------------------------------------- debmirror failed 2 runs out of 2. A naive 1-in-9 model predicts that at ~1.2%. The discrepancy is NOT resolved here. Candidate explanations NOT tested: LWP's keep-alive pool may pin a run to one resolved address so a single bad draw poisons the whole run rather than one request; or more than one backend may be intermittently bad and the single-shot per-IP sweep in section 4 caught only the one that was failing at that instant. This is stated as an open question because the per-IP sweep tested each backend ONCE -- it establishes that 91.189.92.23 was bad, NOT that it is the only bad one. -------------------------------------------------------------------------------- 7. A SECOND, INDEPENDENT FINDING FOUND WHILE MEASURING -------------------------------------------------------------------------------- THE ARCHIVE HAS MOVED ON FROM THE LOCAL Release, AND THIS IS A DIFFERENT FAILURE MODE FROM THE TIMEOUT. local /var/lib/dc-mirror/ubuntu/dists/jammy-backports/Release expects: 31d77c7c6612732f36f85a01a5dc037f 6349 main/dep11/Components-amd64.yml.gz 0acaa4b278543447ef2a24d6882c08ff34aef6fb 6349 main/dep11/Components-amd64.yml.gz every backend currently serves: 6361 bytes Note also that an earlier curl in this same session measured 6349 and every measurement afterwards measured 6361, so the object was republished DURING the investigation. A successful download would therefore now mismatch the stale local Release on both size and hash -- a hash-verification failure, which is a DIFFERENT error from the read timeout and would not be fixed by fixing the timeout. Whether debmirror re-fetches Release early enough each run to avoid this was NOT measured. -------------------------------------------------------------------------------- 8. WHAT THIS MEANS FOR THE GATE (evidence only -- the ruling is the operator's) -------------------------------------------------------------------------------- - The mirror content is unaffected: the delta is one AppStream metadata file whose .xz twin is present and size-correct, and `apt-get update` against the mirror returns rc=0 fetching the .xz. Measured separately, same date. - A retry has roughly an 8-in-9 chance of clearing the object per request, so "wait for the daily timer" is a reasonable expectation -- but it is a PROBABILITY, not a guarantee, and section 6's residual means the per-RUN odds are not known to be the same as the per-REQUEST odds. - Nothing here justifies relaxing the gate. --ignore-small-errors remains refuted on its own terms (section 2). - If a deterministic fix is ever wanted, the shape is to pin the upstream away from the broken backend -- which is also what the 2026-07-25 operator preference for `--host=mirror.uoregon.edu` (recorded in dc-mirror.sh's header, NOT applied) would achieve as a side effect. That is a D-135 scope question, not a gate question, and is NOT proposed here.