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.
