diff --git a/docs/CURRENT-STATE.md b/docs/CURRENT-STATE.md index faa1399..083b70d 100644 --- a/docs/CURRENT-STATE.md +++ b/docs/CURRENT-STATE.md @@ -3039,6 +3039,41 @@ login shell). Not chased -- it does not gate the deploy, and guessing at an LWP-vs-curl difference would be the reasoning-instead-of-measuring failure this project keeps logging. `scripts/dc-mirror.sh` remains UNTOUCHED; no tolerance relaxed, no assertion weakened. + **>>> THE ANOMALY IS ROOT-CAUSED, AND IT CORRECTS THE "NOT TRANSIENT" CALL ABOVE (GA-R1 + C2 -- measurement wins). <<<** **OPERATOR RULING 2026-08-02, exact utterance: "Root-cause + the curl/debmirror anomaly first"** (taken over accepting the red, over recording error + shape/count, and over `--ignore-small-errors`). Capture: + `docs/audit/mirror-500-timeout-rootcause-20260802.txt`. **ROOT CAUSE IS UPSTREAM AND + BACKEND-SPECIFIC, NOT A DEFECT IN THIS DEPLOYMENT: `archive.ubuntu.com` is round-robin + across NINE A records, and ONE of them -- `91.189.92.23` -- HANGS on this specific object + while serving its directory siblings normally.** The control is what makes it a finding + rather than "a backend is down": that same backend returns the `.xz` sibling **200 / 5776 B + / 0.543s**, and the other eight return the `.gz` in 0.14-0.51s. **The resolver ROTATES** + (six consecutive lookups gave six different orderings), so every fetch re-rolls which + backend it gets. **MEASURED RATE: 12 sequential fetches -> 11 x 200, 1 timeout (~8%), + consistent with exactly one bad record of nine. SO THE FAILURE IS PROBABILISTIC, NOT + PERSISTENT** -- the earlier conclusion drawn from 2-of-2 debmirror runs is WITHDRAWN. + **A HYPOTHESIS WAS TESTED AND REFUTED, recorded because it is the one a reader forms + first:** debmirror sets `keep_alive => 1` and curl does not reuse connections, so stale + connection reuse looked like the answer. The test INVERTED it -- same library, seconds + apart, `keep_alive=1` (debmirror's own setting) returned **200 in 1s** while `keep_alive=0` + **timed out**. **ALSO CORRECTED: the `500` is NOT a server 500** -- LWP synthesises 500 for + CLIENT-side failures, so it is LWP reporting its own 300s timeout + (`/usr/bin/debmirror:629`). Reading it as a server error sends the investigation the wrong + way. **TWO STRUCTURAL FACTS READ FROM THE VENDOR SCRIPT:** there is NO dep11 exclusion + option (`dep11_from_release` `:1201` and `get_dep11_files` `:1384` are both unconditional), + so the mirror's scope cannot be narrowed without patching debmirror; and + **`--ignore-small-errors` is NOT a bounded tolerance -- `:2891` DISCARDS the error count**, + so it would read clean on a wholly failed mirror. It stays refuted. + **RESIDUAL, DECLARED NOT EXPLAINED:** debmirror failed 2 of 2, which a naive 1-in-9 model + predicts at ~1.2%. Not resolved. The per-IP sweep tested each backend ONCE, so it + establishes that `91.189.92.23` was bad, NOT that it is the only bad one. + **SECOND, INDEPENDENT FINDING -- A DIFFERENT FAILURE MODE IS NOW LATENT:** the local + `Release` expects **6349 B** for that object while every backend now serves **6361 B**, and + the object was republished DURING this investigation (an early curl measured 6349, every + later one 6361). **A successful download would now fail HASH verification against the stale + local Release** -- a different error from the timeout, not fixed by fixing the timeout. + Whether debmirror re-fetches `Release` early enough each run to avoid this was NOT measured. - Project: Omega Cloud, VR1 DC-DC rehearsal -- a two-DC + Office1-headend virtual rehearsal on KVM (vcloud host), rehearsing the future bare-metal Roosevelt deployment (D-100, `docs/design-decisions.md:1946`). diff --git a/docs/audit/mirror-500-timeout-rootcause-20260802.txt b/docs/audit/mirror-500-timeout-rootcause-20260802.txt new file mode 100644 index 0000000..d105860 --- /dev/null +++ b/docs/audit/mirror-500-timeout-rootcause-20260802.txt @@ -0,0 +1,153 @@ +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. diff --git a/docs/changelog-20260802-queued-items.md b/docs/changelog-20260802-queued-items.md index 4e7edb0..52db97b 100644 --- a/docs/changelog-20260802-queued-items.md +++ b/docs/changelog-20260802-queued-items.md @@ -391,3 +391,70 @@ - State changed on the rack: one sync run, which wrote `last-sync.status` and fetched ~1.3 MB of indices. The apt test wrote only to a scratch dir, removed on exit. - **Revert:** n/a. + +## Item 9 -- sweep F2 ROOT-CAUSED, and item 8's "not transient" is WITHDRAWN + +**OPERATOR RULING, exact utterance: "Root-cause the curl/debmirror anomaly first"** -- taken +over accepting the red gate, over recording error shape/count, and over +`--ignore-small-errors`. Capture: `docs/audit/mirror-500-timeout-rootcause-20260802.txt`. + +**ROOT CAUSE: UPSTREAM AND BACKEND-SPECIFIC. `archive.ubuntu.com` is round-robin across +NINE A records and ONE of them, `91.189.92.23`, HANGS on this specific object while serving +its directory siblings normally.** + +``` +THE FAILING OBJECT (.yml.gz) CONTROL, SAME DIR (.yml.xz) +185.125.190.81 200 6361 0.305s 91.189.92.23 200 5776 0.543s <-- healthy +...(seven more, all 200) (all nine 200) +91.189.92.23 - - >25s TIMEOUT +``` + +The control is what makes this a finding rather than "a backend is down": the same backend +serves the sibling in half a second. **The resolver ROTATES** -- six consecutive lookups +returned six different orderings -- so each fetch re-rolls which backend it gets. + +**MEASURED RATE: 12 sequential fetches -> 11 x 200, 1 timeout (~8%)**, consistent with +exactly one bad record of nine. + +**SO ITEM 8's "NOT TRANSIENT" IS WITHDRAWN (GA-R1 C2 -- measurement wins over a document, +including one written an hour earlier).** The failure is PROBABILISTIC, not deterministic; +two consecutive debmirror failures were not the proof of persistence they looked like. + +**A HYPOTHESIS TESTED AND REFUTED, kept because it is the one a reader forms first.** +debmirror sets `keep_alive => 1` and curl does not reuse connections, so a stale persistent +connection looked like the answer. The test INVERTED it -- same library, same callback +style, seconds apart: + +``` +keep_alive=1 (debmirror's setting) 200 OK bytes=6361 1s +keep_alive=0 (my "control") 500 read timeout bytes=0 30s +``` + +**ALSO CORRECTED: the `500` was never a server 500.** LWP synthesises status 500 for +CLIENT-side failures, so it is LWP reporting its own 300s timeout +(`/usr/bin/debmirror:629`, `our $timeout=300;`). I had read it as an archive-side error, +which points the investigation the wrong way. + +**TWO STRUCTURAL FACTS, read from the vendor script rather than assumed** -- both bear on +options that were on the table: there is **NO dep11 exclusion option** (`dep11_from_release` +`:1201` and `get_dep11_files` `:1384` 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 -- `:2891` `$num_errors = $t if ($ignore_small_errors);` DISCARDS +the count**, so it would read clean on a wholly failed mirror. + +**RESIDUAL, DECLARED NOT EXPLAINED:** debmirror failed 2 of 2, which a naive 1-in-9 model +predicts at ~1.2%. Untested candidates: LWP's keep-alive pool may pin a whole run to one +resolved address so one bad draw poisons the run; or more backends may be intermittently bad. +**The per-IP sweep tested each backend ONCE, so it establishes that `91.189.92.23` was bad, +NOT that it is the only bad one.** + +**SECOND, INDEPENDENT FINDING -- A DIFFERENT FAILURE MODE IS NOW LATENT.** The local +`Release` expects **6349 B**; every backend now serves **6361 B**. The object was +republished DURING this investigation (an early curl measured 6349, every later one 6361). +**A successful download would now fail HASH verification against the stale local Release** -- +a different error from the timeout, and not fixed by fixing the timeout. Whether debmirror +re-fetches `Release` early enough each run to avoid this was NOT measured. + +- Changed: `docs/audit/mirror-500-timeout-rootcause-20260802.txt` (new capture). + `scripts/dc-mirror.sh` STILL untouched. +- **Revert:** n/a -- read-only investigation.