Files
felhom.eu/REPORT-spike-ep0-connections.md
T
2026-08-20 10:42:50 +02:00

10 KiB
Raw Blame History

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).