From 02d009f86c221209f26605bad986d404a972e4ce Mon Sep 17 00:00:00 2001 From: paulieb89 Date: Fri, 4 Sep 2026 10:53:24 +0100 Subject: [PATCH] ops(stage1): record the 2026-09-04 attempt, aborted at S1 on a slow upstream 503 Not Stage 1 evidence. The frozen corpus is thirteen cases with two arms each; one case with one arm is not a smaller Stage 1 result. Stage 1 remains not started and snapshot serving remains off. What the attempt did produce is the first hard data on why the live arm keeps failing -- the thing v1.18.2's diagnostics exist for, and the thing the 2026-09-02 report could not supply because it preserved only an error string. The finding is that this was a SLOW 503, not a fast 429: started_at 2026-09-04T09:45:37.817Z finished_at 2026-09-04T09:50:09.599Z elapsed_ms 271785.89 status 503 reason "Service Temporarily Unavailable" headers {} Rate limiting is normally refused immediately, and 2026-09-02 was a 429. A 503 arriving after 4m32s of waiting is an upstream that could not complete the work rather than one declining to accept it, so the "throttle" framing -- which came from a single 429 and was never established -- is now in question. headers {} is the allow-list RESULT, not an omission: v1.18.2 captures Retry-After, RateLimit-* and X-RateLimit-*, and HMLR sent none. An honest negative. There is still no observed quota to pace against, and no Retry-After to say when a retry becomes reasonable. Live latency across the three observations now on record: ~58s per call on 2026-09-02 with a 429 on the third; 200 in 172.95s at 09:12 today; 503 after 271.79s at 09:46 today. Three points is a trend line, not a diagnosis, and this evidence does not separate upstream overload, a throttle expressed as latency, scheduled load, or something keyed to us we cannot see. The snapshot arm completed before the live arm failed: 50 rows in 314.61 ms, containment holding within B5 across sectors B5 4-7. Both figures are single observations and neither is a p95, so this is not the latency gate and must not be quoted as one. Also recorded, unexplained: PricePaidDataClient declares timeout 120 (ppd_client.py:155) yet this call ran 271.8s. Either the timeout is per socket operation or something retried beneath it. It does not reopen the 2026-08-30 closure, which rests on the loop staying free during a 172.95s call, but it does mean the blocking window can exceed the declared bound. The stop condition set in advance -- abort at S1 means stop and do not retry -- was honoured. No second attempt was made. --- docs/ops/2026-09-04-ppd-stage1-shadow.md | 143 ++++++++++ .../evidence/2026-09-04-stage1-report.json | 247 ++++++++++++++++++ 2 files changed, 390 insertions(+) create mode 100644 docs/ops/2026-09-04-ppd-stage1-shadow.md create mode 100644 docs/ops/evidence/2026-09-04-stage1-report.json diff --git a/docs/ops/2026-09-04-ppd-stage1-shadow.md b/docs/ops/2026-09-04-ppd-stage1-shadow.md new file mode 100644 index 0000000..c222eaf --- /dev/null +++ b/docs/ops/2026-09-04-ppd-stage1-shadow.md @@ -0,0 +1,143 @@ +# Stage 1 shadow comparison, attempt 2026-09-04 — aborted at S1 on an upstream 503 + +**This is not Stage 1 evidence.** The frozen corpus is thirteen cases with two +arms each; a report covering one case with one arm is not a smaller Stage 1 +result. Stage 1 remains **not started**, and snapshot serving remains off. + +What this run *did* produce is the first hard data on why the live arm keeps +failing — which is what v1.18.2's live-arm diagnostics were built for, and what +the 2026-09-02 attempt could not supply. + +## Conditions + +| Field | Value | +|---|---| +| Machine | `7849207a412608`, `lhr`, version 141 | +| Release | v1.18.2 | +| Artifact | `v20260828T194003Z`, `bundle_sha256 50f802b2…` | +| Instance | `docs/ops/evidence/2026-09-02-stage1-instance-v1.18.1.json`, `qualified_at 2026-09-02`, 2 days old against a 45-day bound, sha256 verified byte-identical after upload | +| Command | `compare --latency-repeats 30 --max-live-per-case 1 --live-delay-seconds 2.0 --deadline-seconds 3600` | +| Flag | `PPD_SHADOW_COMPARE_ENABLED=1`, inline for the one invocation, never a Fly secret | +| Window | 09:45:33Z – 09:51:02Z | + +`--live-delay-seconds` was deliberately left at the 2026-09-02 value. Changing +it without data would have confounded the one measurement worth having. + +Isolation, as recorded by the run itself: + +```json +{"installed_into_server_state": false, "snapshot_routing_enabled": false, + "artifacts_downloaded": 0, "snapshot_written_to": false} +``` + +## Outcome + +``` +aborted: "S1: the live arm failed (HTTPError: HTTP Error 503: Service + Temporarily Unavailable); completeness is already lost, so no + later case runs" +cases_recorded: 1 cases_compared: 0 live_calls_made: 1 +cases_never_reached: S2-S9, S11-S14 +``` + +## The finding: a slow 503, not a fast 429 + +```json +"live_timing": { + "started_at": "2026-09-04T09:45:37.817+00:00", + "finished_at": "2026-09-04T09:50:09.599+00:00", + "elapsed_ms": 271785.89, + "outcome": "error" +}, +"status": 503, "reason": "Service Temporarily Unavailable", "headers": {} +``` + +Three things follow, and they matter more than the abort itself. + +**1. The failure took 4 minutes 32 seconds.** Rate limiting is normally refused +immediately; the 2026-09-02 failure was a 429. A 503 arriving after 271.8 s of +waiting is the signature of an upstream that could not complete the work, not of +one declining to accept it. **This reopens the question of what has been +happening**: the "throttle" framing came from a single 429 and was never +established. + +**2. No rate-limit headers were sent at all.** `headers: {}` is the *allow-list +result*, not an omission by the comparator — v1.18.2 captures `Retry-After`, +`RateLimit-*` and `X-RateLimit-*`, and HMLR sent none of them. So the diagnostic +worked and returned an honest negative: **there is still no published or +observed quota to pace against.** No `Retry-After` also means nothing tells us +when a retry becomes reasonable. + +**3. Live latency is degrading across observations.** + +| When | Request | Result | +|---|---|---| +| 2026-09-02 | Stage 1 live arm | ~58 s per call; 429 on the third | +| 2026-09-04 09:12 | `/v1/ppd/comps` `B5 4BX` | **200 in 172.95 s** | +| 2026-09-04 09:46 | Stage 1 live arm S1 | **503 after 271.79 s** | + +Three points is a trend line, not a diagnosis. Candidate readings that this +evidence does **not** separate: upstream overload or degradation; a throttle +expressed as latency then 503; scheduled load on HMLR's side; or something +keyed to us that we still cannot see. The throttle key remains unknown, and it +is now unclear whether "throttle" is even the right word. + +## The one comparison that did happen + +The snapshot arm completed before the live arm failed: + +```json +{"count": 50, "latency_ms": 314.61, "source": "snapshot", + "outcodes_returned": ["B5"], "sectors_returned": ["B5 4","B5 5","B5 6","B5 7"], + "saturated_at_limit": true, "sample_complete": false, + "warning_classes": ["coverage_clamp", "freshness"]} +``` + +**314.61 ms against a live arm that spent 271,785 ms and then failed.** Both +figures are one observation each and neither is a p95, so this is not the +latency gate and must not be quoted as one. It is, however, the first +side-by-side on identical input, and the direction is not subtle. + +Geography containment held on the arm that ran: every returned row sat inside +`B5`, across sectors `B5 4`–`B5 7`. The coverage clamp and freshness warnings +are expected for a window reaching past `coverage_to 2026-06-30`. + +## Client timeout discrepancy — open, not explained + +`PricePaidDataClient` declares `timeout: float = 120` (`property_core/ppd_client.py:155`), +yet this call ran 271.8 s before erroring. Two readings, neither confirmed here: +the timeout applies per socket operation rather than to the whole request, or +something retried beneath it. Worth settling on its own, because a 120 s +declared bound that permits a 272 s call misstates the worst case for anyone +sizing timeouts or health-check budgets against it. + +This does **not** reopen the 2026-08-30 stall incident. That closure rests on +the event loop staying free during a 172.95 s call — 345 health beats at a +2.3 ms mean — and a longer blocking call does not weaken it. It does mean the +blocking window can be longer than the declared timeout implies. + +## Stop condition honoured + +The plan for this attempt set the stop condition in advance: an abort at S1 +means stop, record, and do not retry until a deliberate cool-off. That is what +happened, and no second attempt was made. A re-run would spend more upstream +capacity while adding nothing until the above is understood. + +## What is still true, unchanged by this run + +- `PPD_SNAPSHOT_ENABLED` is absent from both apps. Snapshot serving is off, and + nothing here is authority to enable it. +- G1a, G2 and G3 remain complete; **Stage 1 remains not started**. +- The frozen corpus is unchanged and the Instance is unchanged and still within + its staleness bound until roughly 2026-10-17. + +## Next, in order + +1. **Establish what the upstream is actually doing** before any further attempt. + A 503 after 272 s and a 429 after two calls are different failures and may + have different causes. Nothing retained so far distinguishes them. +2. **Settle the timeout discrepancy** — cheap, local, and it changes how any + future attempt should be bounded. +3. Only then choose a pacing strategy. `--live-delay-seconds` cannot be tuned + against evidence that does not exist, and on this run the gap between calls + never came into play: the run died on the first one. diff --git a/docs/ops/evidence/2026-09-04-stage1-report.json b/docs/ops/evidence/2026-09-04-stage1-report.json new file mode 100644 index 0000000..bac5db0 --- /dev/null +++ b/docs/ops/evidence/2026-09-04-stage1-report.json @@ -0,0 +1,247 @@ +{ + "kind": "stage1_shadow_comparison", + "stage_1_evidence": true, + "latency_sample_kind": "deployed_machine_frozen_corpus", + "not_organic_traffic": "The request mix is the frozen thirteen-case corpus, chosen in advance, executed on the deployed production Machine against the selected artifact. It is not a sample of organic traffic and must never be described as one (governing spec rev 10).", + "definition": "docs/design/ppd-shadow-corpus.md", + "artifact": { + "snapshot_version": "v20260828T194003Z", + "bundle_sha256": "50f802b29d9802ee42319122214aeb0adc6761e96c4f6c9ddd0498500bb9072c", + "coverage_from": "2016-01-01", + "coverage_to": "2026-06-30", + "provisional_from": "2026-03-01", + "comparator_version": "1" + }, + "instance": { + "instance_kind": "stage1", + "qualified_at": "2026-09-02", + "governs_run": "stage1-v20260828T194003Z-2026-09-02", + "staleness_bound_days": 45, + "aggregate_baselines": { + "S1_full": 139, + "S3_full": 70, + "S9_full": 136 + }, + "baselines_are": "declared during qualification, not measured here" + }, + "isolation": { + "installed_into_server_state": false, + "snapshot_routing_enabled": false, + "artifacts_downloaded": 0, + "snapshot_written_to": false + }, + "limits": { + "live_delay_seconds": 2.0, + "latency_repeats": 30, + "max_live_per_case": 1, + "deadline_seconds": 3600.0, + "min_available_memory_bytes": 268435456, + "live_calls_made": 1 + }, + "excluded": { + "health": 0, + "memory": 0 + }, + "midnight": { + "retries": 0, + "unrecoverable": false, + "pair_date_mismatches": 0 + }, + "aborted": "S1: the live arm failed (HTTPError: HTTP Error 503: Service Temporarily Unavailable); completeness is already lost, so no later case runs", + "cases_total": 1, + "cases_compared": 0, + "live_errors": [ + { + "shape": "S1", + "error": "HTTPError: HTTP Error 503: Service Temporarily Unavailable", + "type": "HTTPError", + "message": "HTTP Error 503: Service Temporarily Unavailable", + "status": 503, + "reason": "Service Temporarily Unavailable", + "headers": {} + } + ], + "latency": { + "snapshot_arm": { + "n": 0, + "p50_ms": null, + "p95_ms": null, + "p99_ms": null, + "max_ms": null, + "method": "nearest rank: sorted ascending, 1-based rank ceil(p/100*N)" + }, + "per_case_ms": {} + }, + "exit_criteria": { + "all_thirteen_cases_compared": { + "passed": false, + "cases_recorded": 1, + "cases_compared": 0, + "required": 13, + "cases_missing_snapshot_arm": [], + "cases_missing_live_arm": [ + "S1" + ], + "cases_never_reached": [ + "S11", + "S12", + "S13", + "S14", + "S2", + "S3", + "S4", + "S5", + "S6", + "S7", + "S8", + "S9" + ], + "live_errors": 1, + "snapshot_errors": 0, + "note": "the frozen corpus is thirteen cases with two arms each; a report covering fewer is not a smaller Stage 1 result, it is not a Stage 1 result" + }, + "corpus_invariants_hold": { + "passed": false, + "assertions_checked": 6, + "failures": [], + "note": "Definition section 3's universal invariants and each shape's intent, asserted on the snapshot arm; a case reporting sample_complete true is a defect, not a divergence" + }, + "zero_unexplained_false_empties": { + "passed": false, + "false_empty_shapes": [], + "note": "a false empty is only a failure when it is unexplained; these are checked against the classification below" + }, + "zero_geography_contamination": { + "passed": false, + "findings": [] + }, + "field_equality_on_shared_ids": { + "passed": false, + "mismatch_rows": 0, + "vacuous_comparison_shapes": [], + "note": "a shape listed under vacuous_comparison_shapes shared no transaction id while both arms returned rows; equality over an empty intersection proves nothing and is reported as a failure, not a pass" + }, + "every_divergence_classified": { + "passed": false, + "unclassified": 0, + "note": "an unclassified divergence blocks exit" + }, + "no_unconfirmed_classifications": { + "passed": true, + "operator_confirmation_required": 0, + "note": "later A/C/D revision cannot be evidenced from these two sources; while any remain proposed, Stage 1 cannot exit on this report alone -- external confirmation is a separately authorised step" + }, + "zero_snapshot_errors": { + "passed": true, + "errors": [] + }, + "p95_under_one_second": { + "passed": false, + "verdict": "insufficient_evidence", + "p95_ms": null, + "n": 0, + "required_observations": 390, + "required_repeats_per_case": 30, + "cases_short_of_the_required_repeats": [ + "S1", + "S11", + "S12", + "S13", + "S14", + "S2", + "S3", + "S4", + "S5", + "S6", + "S7", + "S8", + "S9" + ], + "criterion": "p95 < 1 second on the deployed production Machine and selected artifact, measured across the frozen corpus request mix (governing spec rev 10)", + "note": "a partial sample is insufficient_evidence, never a pass: a percentile over fewer observations than the gate is defined over is a different measurement" + } + }, + "passed": false, + "cases": [ + { + "shape": "S1", + "intent": "contamination boundary", + "request": { + "wire": { + "postcode": "B5", + "search_level": "district", + "months": 24, + "limit": 50, + "transaction_category": "A", + "filter_outliers": false, + "auto_escalate": true, + "enrich_epc": false, + "property_type": "", + "address": "" + }, + "effective": { + "property_type": "residential_default (F/D/S/T)", + "address": null, + "transaction_category": "A" + } + }, + "artifact": { + "snapshot_version": "v20260828T194003Z", + "bundle_sha256": "50f802b29d9802ee42319122214aeb0adc6761e96c4f6c9ddd0498500bb9072c", + "coverage_from": "2016-01-01", + "coverage_to": "2026-06-30", + "provisional_from": "2026-03-01", + "comparator_version": "1" + }, + "snapshot": { + "count": 50, + "latency_ms": 314.61, + "thin_market": false, + "outcodes_returned": [ + "B5" + ], + "sectors_returned": [ + "B5 4", + "B5 5", + "B5 6", + "B5 7" + ], + "warning_classes": [ + "coverage_clamp", + "freshness" + ], + "saturated_at_limit": true, + "returned_date_from": "2025-06-20", + "returned_date_to": "2026-06-26", + "source": "snapshot", + "observed_at": "2026-09-04", + "derived_from_date": "2024-09-14", + "resolved_to_date": "2026-06-30", + "recent_period_provisional": true, + "sample_complete": false + }, + "snapshot_invariants": { + "coverage_clamp_warning_present": true, + "sample_complete_is_false": true, + "completeness_basis_is_null": true, + "answered_by_snapshot": true, + "provisional_flagged": true, + "geography_isolation": true + }, + "live_timing": { + "started_at": "2026-09-04T09:45:37.817+00:00", + "finished_at": "2026-09-04T09:50:09.599+00:00", + "elapsed_ms": 271785.89, + "outcome": "error" + }, + "live_error": "HTTPError: HTTP Error 503: Service Temporarily Unavailable", + "live_error_detail": { + "type": "HTTPError", + "message": "HTTP Error 503: Service Temporarily Unavailable", + "status": 503, + "reason": "Service Temporarily Unavailable", + "headers": {} + } + } + ] +} \ No newline at end of file