177 lines
10 KiB
Markdown
177 lines
10 KiB
Markdown
# REPORT — SPIKE: who holds ep0's connections open (2026-08-20)
|
||
|
||
**Status: STOP 1 reached. Parts 0, 1 and 2 are complete. Phase C (Part 3) has NOT been run — it is your
|
||
decision, below.** Everything done in this session was **read-only**. No machine was changed.
|
||
|
||
---
|
||
|
||
## ⛔ The decision waiting on you
|
||
|
||
Phase C wants one overnight window on `demo-hp`. **The measurement found something that changes which
|
||
mutation is worth running**, so there are two versions of it. Both are one mutation on a Tier-0
|
||
disposable box, both arm a dead-man timer first, both are unattended.
|
||
|
||
| | **Option A — stop `pvestatd`** (what the spike prompt specifies) | **Option B — stop `felhom-agent`** (what the evidence now points at) |
|
||
|---|---|---|
|
||
| what it tests | the original Q3: does the leak track the request rate? | does the leak track **our agent's** cycle? |
|
||
| predicted result | **null** — leak unchanged at ~201.6/day, ~84 descriptors in 10 h, split evenly ~42/~42 | leak **halves** — ~101/day, ~42 descriptors in 10 h, split ~42 from `demo-felhom` and **~0** from `demo-hp` |
|
||
| what it buys | **falsification.** If the leak *did* halve, the whole Part-1/2 attribution is wrong and must be withdrawn | **confirmation by a second, independent route.** A near-zero contribution from the quietened box is decisive |
|
||
| cost if the attribution is right | a confirmed null — real evidence, but no new information beyond what Parts 1–2 already show | the sharpest possible confirmation |
|
||
| risk | none beyond the window: `pvestatd` is PVE's stats daemon; the box keeps running, backups are not due until ~08-25 | slightly higher: the agent is our own product on the box. It would stop reporting to the hub for the window, and the hub's staleness watch may notice |
|
||
|
||
**I would run Option A, tonight.** Two reasons. It is the mutation the prompt authorises, and standing
|
||
rule 2 says exactly one mutation exists in this run — substituting one is my call to propose, not to
|
||
make. More importantly, **A is the falsification test and B is the confirmation test**, and the
|
||
attribution is already confirmed twice over (socket ownership on the boxes, and the access-log user
|
||
agent, by completely independent routes). A test that can prove me wrong is worth more right now than a
|
||
third test that can only agree with me.
|
||
|
||
**What I need from you: "A tonight", "B tonight", "at the weekend", or "skip it".** If you pick B I will
|
||
need you to say so explicitly, because it is a second mutation the prompt does not authorise.
|
||
|
||
---
|
||
|
||
## What I did, and what it found
|
||
|
||
### Part 0 — the dated-check gate's first real conviction, captured before anything else
|
||
|
||
The 2026-08-19 row was one day overdue. Every conviction this gate had produced before came from a
|
||
fixture or a `FELHOM_GATE_TODAY` override; **this is its first firing on a real overdue date in the live
|
||
register**, and it behaved correctly:
|
||
|
||
- **exit code 1** — a verdict, not a crash (2) and not a pass (0);
|
||
- the message **names R-341 and the days overdue** (`R-341 due 2026-08-19 1 day(s) OVERDUE`), so the
|
||
exit code is not doing the work alone — which is the failure mode this gate's own red-proof fell into
|
||
on 18 August;
|
||
- inside `repo_gates.py` it is the **only** conviction: 9 gates OK, `CONVICTED: due-checks`.
|
||
|
||
Captured verbatim in `part0-due-checks-gate.txt` and `part0-repo-gates.txt`. The row was **not** cleared
|
||
to make the push work — it was cleared at Part 4, after the measurement existed and its result was
|
||
recorded in R-341, which is the sanctioned order.
|
||
|
||
### Q0 — R-341's first dated check: the slope is UNCHANGED
|
||
|
||
Precondition passed: PID still **551655**, `NRestarts=0`, so the elapsed window is valid.
|
||
|
||
**fd 17 → 405 over 166,251 s (46.18 h) = 201.6 fd/day**, Poisson 2σ 181.2–222.1.
|
||
The prediction was pre-registered before the reading: **370–450**. **Observed 388.**
|
||
Verdict: **unchanged**, the expected result, and not a failed upgrade.
|
||
|
||
This settles the check on a window **88× longer** and a descriptor count **97× larger** than the
|
||
30-minute windows the original answer rested on. Uncertainty drops from roughly ±50% to ±5%.
|
||
|
||
**Composition:** ESTAB 0 → 388, and **CLOSE-WAIT is 0 — absent from the histogram entirely.** The
|
||
incident document's original emphasis on `CLOSE-WAIT` is not merely the minority story; on this proxy
|
||
generation that state does not occur at all.
|
||
|
||
Runway to the 65536 ceiling: **~323 days (~2027-07-09)**.
|
||
|
||
### Q1 — who is at the far end: exactly the two demo boxes, 194 each
|
||
|
||
No third peer. Outcome (c) excluded. The identity is read from the API token name on every access-log
|
||
line, not inferred from the address. `lsof` confirms the leak is sockets and nothing else: 390 of 405
|
||
descriptors are TCP.
|
||
|
||
**Persistence (31-minute diff of full 4-tuples): 388 in both readings, 0 closed, 4 new.** Not one socket
|
||
closed. All carry keepalive timers with `retrans=0` — the far ends are answering, so these are not
|
||
half-open sockets.
|
||
|
||
### Q2 — outcome **(a)**, confirmed twice, exactly
|
||
|
||
| instant | ep0 | `demo-felhom` | `demo-hp` | sum |
|
||
|---|---|---|---|---|
|
||
| 08:02:39 / 08:04:37Z | **388** | 194 | 194 | **388** |
|
||
| 08:33:42 / 08:34:01Z | **392** | 196 | 196 | **392** |
|
||
|
||
And the four sockets that appeared between the readings carry **the same four source ports** on ep0 and
|
||
on the boxes. Both sides hold every connection.
|
||
|
||
### The finding nobody predicted: the leak is ours
|
||
|
||
`ss -tnp` on the boxes names the owner of **194 of 194** on each: **`felhom-agent`**, one PID per box.
|
||
Zero are held by `pvestatd`. Zero by `proxmox-backup-client`.
|
||
|
||
ep0's access log says the same thing by a completely independent route:
|
||
|
||
| who | requests in the window | descriptors leaked |
|
||
|---|---|---|
|
||
| `libwww-perl` (pvestatd) | 81,192 | **0** |
|
||
| `proxmox-backup-client` | 80,061 | **0** |
|
||
| `Go-http-client` (**our agent**) | 811 (of which **387** `/snapshots` calls) | **388** |
|
||
|
||
**One leaked socket per agent `/snapshots` call, within one.** 99.5% of the traffic produces 0% of the
|
||
leak.
|
||
|
||
**Mechanism, named from source** — `felhom-agent/internal/pbs/client.go:56-60` builds
|
||
`&http.Transport{TLSClientConfig: tlsCfg}` as a composite literal, so `IdleConnTimeout` is the zero value
|
||
(= no limit; `http.DefaultTransport` sets 90 s and a literal does not inherit it), and
|
||
`cmd/felhom-agent/main.go:1486` builds **a fresh client every cycle**, as its own doc comment states.
|
||
`CloseIdleConnections`, `IdleConnTimeout` and `MaxIdleConns` appear **nowhere in the agent repo**.
|
||
Cadences reconcile without fitting: 900 s hub poll (184.7 cycles) + 6 h verify cadence (7.7) = 192.4
|
||
predicted against **194 observed per box**.
|
||
|
||
**No fix is proposed** — the spike-first gate forbids it, and the spec is a separate task. Filed as
|
||
**R-344**, with the open design questions listed rather than pre-answered.
|
||
|
||
### Control window: clean
|
||
|
||
No reboots (ep0 up 17 d, boxes up 10 d), no daemon restarts (`NRestarts=0`), no agent restarts, **no
|
||
request-rate gap** (3,536–3,553 per hour, every hour), **no HTTP errors at all** (every response 200
|
||
except 8 expected 101s), no tunnel flap. **No backup ran inside the window** — the last offsite protocol
|
||
upgrades were 08-18 03:57/03:58Z, *before* `t0`, and the tier is weekly with the next run due ~08-25, so
|
||
**tonight's window is also clear of one.** Routine verify jobs and restore-test reads did occur; they are
|
||
1.2% of traffic and are already counted inside the 194/box reconciliation.
|
||
|
||
**Hub:** no `*_unreachable` or `*_recovered` event; the PBS-DR gauge refreshes on schedule and host
|
||
reports land from both boxes. **Honest limit:** the hub pod is 39 h old, so hub-side logs cover 36.6 of
|
||
the window's 46.2 hours; the first 9.6 h rests on ep0's own evidence.
|
||
|
||
---
|
||
|
||
## Register changes
|
||
|
||
- **R-341** — first check recorded (taken at **+46.2 h, not +24 h**; the delay was pure elapsed time and
|
||
the longer window is stated as a **better** measurement, not a degraded one). **2026-08-19 row removed**
|
||
from `DUE-CHECKS`; 2026-08-25 kept, with the Phase-C perturbation quantified against it (**~3%** shift
|
||
on the 7-day slope even under the hypothesis we expect to be false — the reading stays usable).
|
||
- **R-336** — mechanism named; **premise corrected and re-ranked**. Its recorded next step would have
|
||
produced a null result and read as a failed fix. The poll rate is now a scaling/cost item; the leak fix
|
||
is R-344. **Q3's proportionality verdict is explicitly NOT recorded** — Phase C has not run.
|
||
- **R-340** — noted which of its wanted observations this run already produced, so the health-op task
|
||
reuses them rather than measuring a protected machine a third time. Only the loopback probe is still
|
||
owed.
|
||
- **R-344 (new)** — the agent's per-cycle transport leak. READY (S).
|
||
- **R-345 (new)** — `hub/Makefile` lines 21–22 tag and push `:latest`, which two rule files forbid.
|
||
READY (XS).
|
||
- **R-346 (new)** — `ActiveEnterTimestamp` reads 5 h 56 m early for this proxy generation (the upgrade
|
||
re-exec'd rather than restarted, so `NRestarts` is still 0). Anchoring a slope on it gives ~12% low.
|
||
READY (XS).
|
||
|
||
## Deliverables
|
||
|
||
- `documentation/audits/SPIKE-ep0-established-connections-2026-08-20.md` — the findings.
|
||
- `documentation/audits/evidence-ep0-established-connections-2026-08-20/` — 11 raw evidence files,
|
||
including the **pre-registered Phase C prediction**, committed before the mutation exists.
|
||
- `documentation/backlog/OPEN-ITEMS.md`, `STATUS.md` — as above.
|
||
|
||
## CI, checked by run ID
|
||
|
||
**id `360` / run_number `237`, `head_sha 19672e685`, conclusion `success`**, started 2026-08-20 08:41:50Z
|
||
— this run's own push. The four runs before it (ids 356–359) are also `success`, so the "green since run
|
||
356" baseline in the spike prompt holds and nothing was inherited red.
|
||
|
||
*Numbering note:* the API exposes two numbers per run and they differ by 123 here. The prompt's "run 356"
|
||
matches the **`id`**, not the `run_number`; both are recorded in `evidence-…/ci-run-by-id.txt` so the
|
||
reference is unambiguous.
|
||
|
||
The pre-push hook ran `repo_gates.py --fast` and reported **all 10 gates OK** before the push proceeded —
|
||
including `due-checks`, which convicted at Part 0 and passes now that the row is properly cleared. **No
|
||
`--no-verify` was used**, and none was needed.
|
||
|
||
## What is inconclusive
|
||
|
||
**Q3 is unmeasured**, by design. Everything stated about proportionality is a labelled prediction. Also
|
||
unexplained: why the two boxes' leaked counts are *exactly* equal at two separate instants rather than
|
||
merely close. And whether restore-test reader connections leak too was not separated out (≤2% of the
|
||
total, inside the noise).
|