diff --git a/REPORT-spike-ep0-connections.md b/REPORT-spike-ep0-connections.md new file mode 100644 index 00000000..1f64a1e0 --- /dev/null +++ b/REPORT-spike-ep0-connections.md @@ -0,0 +1,162 @@ +# 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. + +## 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). diff --git a/STATUS.md b/STATUS.md index c5f5ad63..93390d12 100644 --- a/STATUS.md +++ b/STATUS.md @@ -1,7 +1,7 @@ # STATUS — what works, what's broken, what's next -**Updated 2026-08-18 (afternoon — a listening socket that served nobody, a rehearsal upgrade that changed -nothing, and a new install that is finally current).** +**Updated 2026-08-20 (morning — we looked at who was actually holding the off-site box's connections +open, and it turned out to be us).** > **A view, not a source.** `documentation/backlog/OPEN-ITEMS.md` is the authority; this page restates > part of it in plain words, and **nothing may exist only here**. **Items, not paragraphs. One screen.** @@ -116,6 +116,14 @@ record with no machine** — created 13 August, no host, no backups, nothing to alarm. **Corrected later the same morning: my first estimate of how fast it leaks was too optimistic by about 2.5×** — measured properly it is under a year to the new ceiling, not two years. A deadline, not a comfort. +- **The leak is OURS, not Proxmox's, and asking fewer questions would not have fixed it** (R-344, found + 2026-08-20). We finally looked at who was on the other end of the stuck connections. Every single one + belongs to **our own agent** on the two demo machines — it opens a connection to the off-site box on + each 15-minute cycle and never closes it, and neither does the box. The two Proxmox pollers that make + 99.5% of the traffic leak **nothing at all**. So the plan recorded under R-336 — turn the question + rate down, then watch the count stop climbing — **would have changed nothing and looked like a failed + fix.** The count still says about a year to the ceiling. **Nothing is broken today**; this is a + deadline we now know where to aim at. *(register: R-344, and R-336 re-ranked)* - **The off-site box was updated, and it did not help — as expected** (R-341). On your ruling we installed the newer backup software for the practice, having first read its release notes and found **nothing** about the fault we have. The update went cleanly and everything works, but the leak @@ -155,7 +163,9 @@ record with no machine** — created 13 August, no host, no backups, nothing to ## Working on next -`demo-hp` is yours this evening — **this session did not touch it**. After that: the three remaining +**One decision is waiting for you, at the top of `REPORT-spike-ep0-connections.md`:** whether to run the +overnight measurement window on `demo-hp` tonight, and which of two versions of it. Nothing was changed on +any machine in this session — every reading was read-only. After that: the three remaining R-264 readers, now that one has been built and we know what one costs; R-317 (one line in the agent); R-327 (decide what the naming claim's status should be); then the 2026-08-09 batch (R-279 … R-292), still untriaged against everything since. diff --git a/documentation/audits/SPIKE-ep0-established-connections-2026-08-20.md b/documentation/audits/SPIKE-ep0-established-connections-2026-08-20.md new file mode 100644 index 00000000..ef1bc4b3 --- /dev/null +++ b/documentation/audits/SPIKE-ep0-established-connections-2026-08-20.md @@ -0,0 +1,323 @@ +# SPIKE — who holds ep0's connections open, and does the leak track the poll rate? + +**Run:** 2026-08-20 08:01–08:35 UTC, read-only throughout. **Phase C (the one mutation) has NOT been run** — it is +held at STOP 1 for the operator's window decision. +**Evidence:** `evidence-ep0-established-connections-2026-08-20/`, one file per step. +**Supersedes the plan in** `SPIKE-ep0-established-connections.md` (issued 2026-08-18, never run). + +> **Headline, and it is not the headline the spike expected.** +> The leak is **ours**. Every one of the 388 leaked descriptors on ep0 is an established connection held +> open by **`felhom-agent`** on the customer boxes — one per PBS poll cycle, never closed on either side. +> `pvestatd` and `proxmox-backup-client` made **162,404 requests** in the same window and leaked **zero**. +> R-336's premise — that cutting the ~85,000/day poll rate is the leak fix — **does not survive this +> measurement.** The poll rate is a separate (real) problem; it is not what is consuming descriptors. + +--- + +## Q0 — R-341's first dated check: has the fd slope changed since the PBS 4.2.5-1 upgrade? + +### Answer: NO. Unchanged, and now measured over a window 88× longer than the one it replaces. + +**Precondition passed.** `MainPID = 551655`, `ps -o lstart` = `Tue Aug 18 09:51:04 2026`, `NRestarts = 0` on +both `proxmox-backup-proxy` and `proxmox-backup`. The proxy generation that carries `t0` is the one that was +read. The elapsed-window measurement is valid. + +| | value | +|---|---| +| `t0` | fd **17**, ESTAB 0, 2026-08-18 **09:51:22Z**, PID 551655 | +| reading A | fd **405**, ESTAB **388**, CLOSE-WAIT **0**, 2026-08-20 **08:02:13Z**, PID 551655 | +| elapsed | **166,251 s** = 46.181 h = 1.9242 d | +| delta | **+388 fd** | +| rate | **201.6 fd/day** (8.40/h) | +| Poisson on n=388 | ±19.7 counts → **±10.2/day (1σ)**, ±20.5/day (2σ) → **181.2 … 222.1 /day** | +| limits | soft/hard **65536 / 65536** — the drop-in survived the upgrade | +| listener | `LISTEN Recv-Q 0 Send-Q 1024` — accept queue empty, nothing wedged | + +**Verdict against the pre-registration**, quoted from the spike prompt §2 so it is visible beside the result: + +> *"Predicted range: roughly **370–450** … A reading anywhere in **330–490** confirms an unchanged rate … +> **In range** → unchanged rate. This is the EXPECTED result, consistent with the changelog containing no +> mechanism to change it. It is not a failed upgrade."* + +**Observed: 388.** In range, and close to the centre. The rate is **unchanged** since the upgrade. This is the +expected result and it is recorded as such — not as a success and not as a failure of the upgrade, which was +run for rehearsal value and never claimed to fix anything. + +For comparison, on the identical method: **183/day** (31 min, pre-upgrade), **200/day** (5.64 h, pre-upgrade), +**225/day** (32 min, post-upgrade). This window carries **97× the descriptor count** of the 31-minute window, +so its uncertainty is ±5% rather than ±50%. + +### Composition — the split, which is what says *which* leak it is + +``` +t0 fd 17 ESTAB 0 CLOSE-WAIT 0 +reading A fd 405 ESTAB 388 CLOSE-WAIT 0 17 + 388 = 405, exactly +``` + +**`CLOSE-WAIT` is absent from the `ss` histogram entirely — 0, not merely flat.** 100% of the growth is +**established** connections on `:8007`. This closes the question the incident's own correction block opened: +the mechanism is *connections the proxy never reaps*, and `CLOSE-WAIT` is not merely the minority half, it is +**not present at all** on this proxy generation. + +### Runway + +From fd 405 at 201.6/day to the 65536 soft limit: **≈ 323 days**, i.e. around **2027-07-09**. Under a year. +A deadline, not a comfort — unchanged in character from what R-341 recorded. + +--- + +## Q1 — who is at the far end? + +### Answer: exactly the two demo boxes, in a dead-even split. No third peer. Outcome (c) is excluded. + +At 08:02:39Z, `ss -tn state established '( sport = :8007 )'`, peer histogram: + +| peer | connections | identity | +|---|---|---| +| `10.77.0.2` | **194** | `demo-felhom` (host `felhom-pve`) — token `felhom@pbs!demo-felhom` | +| `10.77.0.3` | **194** | `demo-hp` (host `felhom-host`) — token `felhom@pbs!demo-hp` | + +The identity is not inferred from the address: ep0's own access log carries the API token name on every line +(`::ffff:10.77.0.3 - felhom@pbs!demo-hp …`), and the mapping is one-to-one across the whole file. + +**194 / 194 is not approximately even — it is exactly even**, which is itself a finding: whatever opens these +is a per-box periodic task running the same schedule on both, not traffic proportional to anything the boxes +differ in. + +### Descriptor-type breakdown (1.3) + +`lsof -np 551655`, which distinguishes sockets from files, pipes and eventfds so a "leak" that is not sockets +gets caught here: + +| type | count | +|---|---| +| **IPv6 (TCP)** | **390** | +| REG (log files, rrd journal, datastore lock) | 32 | +| unix | 7 | +| a_inode (epoll ×2, eventfd ×1) | 3 | +| DIR | 2 | +| CHR (`/dev/null`) | 1 | + +`lsof … | grep -c TCP` = **390** = 388 established + 1 listener + 1 other. The independent `/proc//fd` +link-target histogram agrees: **397 sockets** (390 TCP + 7 unix), 9 regular/anon fds. **The leak is sockets, +and the sockets are TCP on :8007.** Nothing else is growing. + +### 1.4 — persistence: are they long-lived, or churn? + +Full 4-tuples diffed between reading A (08:02:39Z) and reading B (08:33:42Z), **1,843 s apart**: + +| | count | +|---|---| +| sockets in reading A | 388 | +| sockets in reading B | 392 | +| **in BOTH — long-lived** | **388** | +| **only in A — closed during the interval** | **0** | +| only in B — new arrivals | **4** (2 per box) | + +**Not one socket closed in 31 minutes.** There is no churn to separate from the leak: every established +connection on this proxy is the leak. The 4 arrivals over 1,843 s = 187.5 fd/day, consistent with the +elapsed-window 201.6/day within Poisson on n=4. + +**Idle age and liveness.** All 392 sockets carry a TCP keepalive timer and **all 392 report `retrans=0`** — +the far end is answering keepalive probes. These are not half-open sockets whose peer went away; they are +mutually held, live, idle connections. That, on its own, points at outcome **(a)** and Part 2 confirms it. + +--- + +## Q2 — do the boxes hold them too? + +### Answer: **outcome (a)** — both sides hold every connection, and the two counts match exactly. Twice. + +| instant (UTC) | ep0 ESTAB on `:8007` | `demo-felhom` ESTAB to `10.77.0.1:8007` | `demo-hp` | sum | +|---|---|---|---|---| +| reading A — ep0 08:02:39, boxes 08:04:37/38 | **388** | **194** | **194** | **388** | +| reading B — ep0 08:33:42, boxes 08:34:01/02 | **392** | **196** | **196** | **392** | + +Two independent paired readings, both exact. And the confirmation is tighter than the totals: the **four new +sockets** that appeared on ep0 during the persistence window carry **the same four source ports** the boxes +report as new — + +``` +ep0 new: 10.77.0.2:45620 10.77.0.2:53226 10.77.0.3:37554 10.77.0.3:46214 +demo-felhom new: 10.77.0.2:45620 10.77.0.2:53226 +demo-hp new: 10.77.0.3:37554 10.77.0.3:46214 +``` + +Both boxes also closed **zero** sockets in the same interval (A=194, B=196, closed=0, new=2, on each). + +**This is not a hedge between two outcomes.** Outcome (b) — half-open sockets ep0 never noticed — is +excluded by both the matching counts and the `retrans=0` keepalives. Outcome (c) is excluded by Q1. + +### And the owner has a name + +`ss -tnp` on the boxes attributes **194 of 194** on each, to a single PID: + +| box | PID | process | +|---|---|---| +| `demo-felhom` | 2596329 | `/usr/local/bin/felhom-agent --config /etc/felhom-agent/agent.json` | +| `demo-hp` | 3199936 | `/usr/local/bin/felhom-agent --config /etc/felhom-agent/agent.json` | + +**Zero are held by `pvestatd`. Zero by `proxmox-backup-client`.** Both agents have been running continuously +since 2026-08-12 (they did not restart); the count restarted at the proxy's 08-18 restart because that +restart closed the old sockets on both sides. + +Each agent's own descriptor table is **208 fds, of which 196 are these connections** — so the leak is +bilateral. The agents' `RLIMIT_NOFILE` is 524287, so they are in no danger; that is a reason it stayed +invisible, not a reason it is harmless. + +--- + +## The user-agent attribution (1.5) — the access log settles it independently + +Over the same 46.18 h window, from ep0's own `access.log.1` + `access.log`: + +| user agent | endpoint | requests | req/day | **descriptors leaked** | +|---|---|---|---|---| +| `libwww-perl/6.78` | `GET /admin/datastore` (pvestatd) | 81,192 | 42,195 | **0** | +| `proxmox-backup-client/1.0` | `GET …/felhom-offsite/status` | 80,061 | 41,607 | **0** | +| `libwww-perl/6.78` | `GET …/felhom-offsite/snapshots` | 1,131 | 588 | **0** | +| **`Go-http-client/1.1`** | **`GET …/felhom-offsite/snapshots`** | **387** | **201** | **388** | +| `Go-http-client/1.1` | `GET /version` | 371 | 193 | (same connections) | +| `Go-http-client/1.1` | `POST …/verify` + task status | 53 | 28 | (same connections) | +| | **total, both boxes** | **163,215** | **84,822** | **388** | + +`Go-http-client/1.1` is `felhom-agent` — the same process `ss` names on the box side, reached by a completely +independent route. **387 agent `/snapshots` calls against 388 leaked sockets: one per call, within one.** + +**162,404 requests from the two Proxmox pollers leaked nothing.** They are 99.5% of the traffic and 0% of the +leak. + +### Cadence reconciliation — the numbers close + +| source | cadence | cycles in 166,251 s | +|---|---|---| +| agent hub-report poll (`poll_seconds: 900`, read from each box's `agent.json`) | 15 min | 184.7 | +| `pbs.VerifyLoop` (`DefaultVerifyCadence = 6h`) | 6 h | 7.7 | +| | **sum** | **192.4** | + +Observed leaked per box: **194**. Observed `POST …/verify` per box in the window: **8** (predicted 7.7). +Observed `GET /version` per box: ~185.5 (predicted 184.7). Mean interval between leaked descriptors per box: +**857 s**. Every count reconciles against a cadence read from configuration, not fitted to the data. + +### Mechanism — named from source, and it is a two-line Go footgun + +`felhom-agent/internal/pbs/client.go:56-60`: + +```go +http: &http.Client{ + Timeout: timeout, + Transport: &http.Transport{TLSClientConfig: tlsCfg}, +}, +``` + +A hand-rolled `http.Transport` takes the **zero value** for `IdleConnTimeout`, which in Go means *no limit* — +idle keep-alive connections are never closed. (`http.DefaultTransport` sets 90 s; a composite literal does +not inherit it.) That alone would be harmless if one client were reused. It is not: +`felhom-agent/cmd/felhom-agent/main.go:1486-1509` — `pbsTargetsFromPVE` — says so in its own doc comment: + +> *"returns a `pbs.Targets` closure that, **each cycle**, discovers the pbs storages from the PVE config and +> **builds a fingerprint-pinned, token-authed client for each**"* + +So each cycle constructs a **new** `Transport`, performs one request, and leaves the connection idle in that +transport's pool forever. The transport then becomes unreachable, but Go's `persistConn` read-loop goroutine +keeps the socket alive — an unreachable `http.Transport` does not close its connections. `grep` across the +whole `felhom-agent` repo for `CloseIdleConnections`, `IdleConnTimeout`, `MaxIdleConns`: **no matches at all.** + +**The same composite-literal pattern appears in two more clients** — `internal/hub/client.go:53` and +`internal/proxmox/client.go:69`. Those are built once at start-up rather than per cycle, so they do not leak +by this route; they are recorded because the pattern is one refactor away from doing so. Filed as **R-344**. + +--- + +## Control-window cleanliness (1.6) + +The elapsed window is doing double duty as Phase C's control, so it has to be shown undisturbed. It was. + +| check | finding | +|---|---| +| **ep0 host reboot** | none — booted 2026-08-03 11:12:57, up 17 d | +| **proxy / API daemon restart** | none — `NRestarts = 0` on both units, PID 551655 throughout | +| **box reboots** | none — both booted 2026-08-10 09:2xZ, up 10 d | +| **agent restarts** | none — both `ActiveEnterTimestamp` 2026-08-12 | +| **request-rate gaps** | **none.** Hourly totals across the window: 3,536–3,553 every hour, no hour missing | +| **HTTP errors** | **none.** Every response in the window is `200`, except 8 × `101` (expected protocol upgrades) | +| **tunnel flaps** | no evidence — WireGuard handshakes for `10.77.0.2`, `.3`, `.250` all seconds old; and a flap would have shown as a request gap or errors, and neither exists | +| **a backup inside the window?** | **NO.** The last offsite protocol upgrades were 2026-08-18 **03:57 and 03:58Z** — the incident re-runs, **before `t0` at 09:51:22Z**. Both boxes' `pvesm list felhom-pbs` confirms the newest snapshots are `2026-08-18T03:57:43Z` / `03:58:43Z`. The tier's `cadence_seconds` is **604800** (weekly), read from each box's `agent.json`, so the next offsite run is due ~2026-08-25 | +| **other non-poll activity** | **yes, and it is routine, quantified, and does not contaminate.** Server-side verify jobs ran on ep0 on a ~6 h cadence (8 per box in the window), and restore-test reads ran on 2026-08-19 at 04:45–04:50 and 06:52–06:54Z (8 reader upgrades total). Together with snapshot/version/task-status calls this is **~1,963 of 163,215 requests = 1.2%** of the window's traffic, and at most 8 of the 388 descriptors could be attributed to reader connections (≤2%). The verify cycle is already counted **inside** the 194/box reconciliation above — it is part of the measured leak, not a contaminant of it | + +**Verdict: the control window is clean.** No correction is applied and none is needed. + +**Two nuances recorded rather than smoothed over.** + +1. `systemctl show proxmox-backup-proxy -p ActiveEnterTimestamp` reads **2026-08-18 03:54:54Z**, not 09:51:04Z, + while `NRestarts = 0` and `MainPID` did change. The upgrade therefore **re-exec'd** the proxy rather than + restarting the unit — systemd never saw a stop. Anyone using `ActiveEnterTimestamp` as the "when did this + proxy generation start" anchor would get a figure **5 h 56 m too early** and compute a rate ~12% low (388 fd over 52.1 h instead of 46.2 h = 178.7/day instead of 201.6/day). + Use `ps -o lstart= -p $MainPID`, as R-341's own command does. +2. ep0 carries a fourth WireGuard peer, `10.77.0.4`, whose last handshake was 2026-08-13 (7 d ago). It is + `drill-r50-0a4f9a`, a drill host, and its dormant peer entry is already recorded in + `architecture/_recovery-inventory-2026-07-28.md`. Outside the window; not a contaminant; not a new finding. + +**Hub view.** No `pbsdr_box_unreachable` / `offsite_box_unreachable` and no `*_recovered` event was logged. +The positive observable rather than the absent one: the PBS-DR gauge refreshes on schedule +(`PBS-DR box refreshed: 3.7% full (3.7 GB of 97.9 GB)`, every ~16 min through the run) and host reports land +from both boxes. **Honest limit:** the hub pod is 39 h old (redeployed for v0.106.0 at 2026-08-18 19:29), so +hub-side log evidence covers **36.6 of the window's 46.2 hours**. For the first 9.6 h the evidence is ep0's +own access log — which shows no gap and no error — and `NRestarts = 0`. Hub log timestamps render **CEST**. + +--- + +## Q3 — is the leak rate proportional to the request rate? + +### NOT ANSWERED BY MEASUREMENT. Phase C has not been run; it is held at STOP 1. + +What exists instead is a **pre-registered prediction**, written and committed before any Phase C number can +exist: `evidence-ep0-established-connections-2026-08-20/phaseC-prediction.txt`. Its substance: + +- Stopping `pvestatd` on `demo-hp` removes **both** pvestatd-driven streams from that box (the PVE PBS storage + plugin issues the `libwww-perl` datastore list *and* shells out to `proxmox-backup-client` for the status + call, both on pvestatd's cycle) — **−98.8% of demo-hp's requests, −49.4% of the fleet total**. If ep0's + request count does not fall by close to half, the independent variable did not move and no ratio may be + computed. +- **H1 (what Parts 1–2 predict): NOT proportional.** demo-hp's `felhom-agent` keeps running, so both boxes + keep leaking. Expect **~201.6 fd/day, unchanged — ~84 descriptors in a 10 h window (2σ 66–102) — split + symmetrically ~42/~42 between the two peers.** +- **H2 (the hypothesis Q3 was written to test): proportional.** Expect **~101 fd/day — ~42 descriptors in + 10 h (2σ 29–55) — split strongly asymmetrically ~42/~0.** + +H1 and H2 do not overlap at 2σ for a window of 10 h or more. The **peer split is the sharpest discriminator** +and it is free: it needs no second box and no arithmetic. + +**A result matching H2 falsifies the Parts 1–2 attribution**, and the prediction file says so in those words, +so the outcome cannot be rationalised in either direction afterwards. + +--- + +## Which fix the evidence points at + +**No design here, per the spike-first gate — only the target.** The evidence points at +`felhom-agent/internal/pbs/client.go`'s HTTP transport lifetime, not at the poll rate. One `pbs.Client` is +constructed per cycle by `pbsTargetsFromPVE`, each carrying a fresh `http.Transport` whose `IdleConnTimeout` +is the zero value, and nothing ever closes it; the observed leak is exactly one socket per agent +`/snapshots` call, on both sides, on both boxes, and it reconciles with cadences read from configuration. A +fix that touches only the ~85,000/day Proxmox poll rate would reduce ep0's request load by ~99.5% and its +descriptor leak by **zero**. R-336's poll rate remains a genuine problem — 85,000 requests/day to a +weekly-write DR endpoint is still wrong — but **it is a different problem from this one, and the row's +"cut the poll rate, then confirm the fd count stops climbing" plan would have produced a confusing null +result.** That is the substantive change to R-336 this spike delivers. + +--- + +## What was inconclusive + +- **Q3 is unmeasured**, by design — Phase C is held at STOP 1 for the operator. Everything above about + proportionality is a prediction, labelled as one. +- **The ~9.6 h of hub-side evidence before the v0.106.0 pod redeploy is gone** with the previous pod's logs. + The window is covered by ep0-side evidence for that period, which is adequate for the questions asked, but + it is not the same evidence and is not presented as such. +- **Why `demo-hp`'s and `demo-felhom`'s leaked counts are *identical* rather than merely similar** is not + established. Both run the same cadences, so equality is expected — but exact equality at two separate + instants (194/194 and 196/196) is stronger than the cadences alone require, and no attempt was made to + explain it beyond noting it. +- **Whether a reader (restore-test) connection also leaks** was not separated out. At most 8 of 388 sockets + could be involved (≤2%), which is inside the noise, so it was not pursued. diff --git a/documentation/audits/evidence-ep0-established-connections-2026-08-20/part0-due-checks-gate.txt b/documentation/audits/evidence-ep0-established-connections-2026-08-20/part0-due-checks-gate.txt new file mode 100644 index 00000000..e26fb932 --- /dev/null +++ b/documentation/audits/evidence-ep0-established-connections-2026-08-20/part0-due-checks-gate.txt @@ -0,0 +1,16 @@ +=== part0-due-checks-gate.txt === +captured: 2026-08-20T10:01:45+02:00 (DooPlex, CEST) +utc: 2026-08-20T08:01:45+00:00 +repo HEAD: 848368ec38a7f9a49c6beb3a68b5620c822edc86 +cmd: python3 scripts/due_checks_gate.py +--- stdout+stderr --- +DUE-CHECKS GATE FAILED: 1 dated check(s) are due or overdue as of 2026-08-20 (UTC). + + R-341 due 2026-08-19 1 day(s) OVERDUE + measure: ep0 proxy fd count + ESTAB/CLOSE-WAIT split; PID must still be 551655 + the command and its preconditions are in the R-341 row of documentation/backlog/OPEN-ITEMS.md + +Take the measurement, record the result in that R-row, then remove the row from the +DUE-CHECKS block. Moving the date instead is allowed — state the reason in the R-row. +NOTE: this gate fires on a PUSH, not on the date; it may be later than the date. +rc=1 diff --git a/documentation/audits/evidence-ep0-established-connections-2026-08-20/part0-repo-gates.txt b/documentation/audits/evidence-ep0-established-connections-2026-08-20/part0-repo-gates.txt new file mode 100644 index 00000000..a0d1a333 --- /dev/null +++ b/documentation/audits/evidence-ep0-established-connections-2026-08-20/part0-repo-gates.txt @@ -0,0 +1,141 @@ +=== part0-repo-gates.txt === +captured: 2026-08-20T08:01:52+00:00 UTC +cmd: python3 scripts/repo_gates.py +--- stdout+stderr --- +repo_gates (felhom.eu) — 10 gate(s) + +============================================================================== +== gate: site (site_gates.py) +============================================================================== +site gates OK — BOM, emoji=0, nav/footer consistent, analytics present, no CDN, no legacy tokens, no