R-344 fixed and proven on both boxes: ep0 is back to fd 17 from 415
gates / gates (push) Successful in 14s
gates / gates (push) Successful in 14s
P1, outcome (i) in one second: replacing the agent on demo-hp released exactly its 199 established connections (ep0 fd 415 -> 216). CLOSE-WAIT stayed 0, so outcome (ii) does not exist and gets no row -- ep0 reaps on peer FIN correctly, and the 543 CLOSE-WAIT at the 08-18 wedge has another explanation. P2, 1.03 h (operator closed the >=4 h window early, so no daily rate is extrapolated): control +4, fixed +0, with each box making exactly 4 /snapshots and 4 /version calls. Same cadence, same work: 4 cycles -> 4 leaks vs 4 cycles -> 0. The fixed box's cycles are in ep0's log, so the zero is the fix and not a stopped agent. P3: the second box took ep0 from 220 to 17 fd in under two seconds. 17 is precisely the t0 baseline of 2026-08-18 09:51:22Z. Corrects a claim this session made earlier the same day: the accumulated descriptors did NOT need an ep0 proxy restart. They were held on both sides. ep0 was read-only throughout; its PID never changed. R-344 updated and left OPEN (unpublished is not delivered). R-336 re-scoped -- its old next-step would have fixed nothing while looking like a failed fix, and it is now a scaling row (~25 req/s at fifty customers). R-347 filed for the delivery gap (Viktor decides). R-348 filed: an agent restart blanks the reported backup list for ~18 h and the Store comment calls it unaffected -- blinds no alarm, checked not assumed.
This commit is contained in:
@@ -0,0 +1,174 @@
|
||||
# REPORT — R-344: the agent's leaked PBS connections, fixed and proven on both boxes (2026-08-20)
|
||||
|
||||
**Outcome: the fix works, measured three independent ways, and ep0 is back to its baseline of 17 file
|
||||
descriptors from 415.** Both demo boxes now run agent **0.130.0**. **Nothing is published** — that is
|
||||
the one decision left, filed as R-347.
|
||||
|
||||
## 1. Confirmed baselines
|
||||
|
||||
| repo | in | out |
|
||||
|---|---|---|
|
||||
| `felhom-agent` | `f17ed11` — v0.129.0 | **`ede49b6`** — 0.130.0, UNRELEASED |
|
||||
| `felhom.eu` | `9299f85` | docs + register only |
|
||||
|
||||
Both clean and equal to `origin/main` before each build. Agent version in: 0.129.0 on both boxes.
|
||||
Out: **0.130.0 on both**, confirmed from the hub, not from the boxes' own `--version`.
|
||||
|
||||
## 2. The diff
|
||||
|
||||
| file | symbol | change |
|
||||
|---|---|---|
|
||||
| `internal/httpx/transport.go` | **new package** | `DefaultIdleConnTimeout = 90s`; `NewTransport(tlsCfg, idle)` — fresh transport per call, `<= 0` means **use the default, never "no timeout"** |
|
||||
| `internal/httpx/transport_test.go` | new | zero/negative → default; the constant is read off `http.DefaultTransport`; freshness; TLS config preserved |
|
||||
| `internal/pbs/client.go` | `Config`, `NewClient` | `IdleConnTimeout` field (tests only); transport via `httpx` |
|
||||
| `internal/pbs/client_leak_test.go` | new | Scenarios A/C + the production-default pin |
|
||||
| `internal/hub/client.go` | `NewClient` | via `httpx` — **consistency only, did not contribute to the leak** |
|
||||
| `internal/proxmox/client.go` | `NewClient` | same |
|
||||
| `cmd/felhom-agent/main.go` | `version` | 0.92.1 → 0.130.0 (ldflags default) |
|
||||
| `REUSE.md`, `CHANGELOG.md` | — | `httpx.NewTransport` entry; the release note |
|
||||
|
||||
Commit `ede49b6` on `main`. `grep '&http.Transport{'` now matches only `httpx` itself.
|
||||
|
||||
**A check made before trusting the fix:** `doBody` already reads the body to completion and closes it,
|
||||
so the connection genuinely reaches the idle pool. Had it not, the idle timeout would have been the
|
||||
wrong fix entirely.
|
||||
|
||||
## 3. Tests and the red-proofs
|
||||
|
||||
`go build ./... && go vet ./... && go test ./...` → **30 packages, 0 failures.**
|
||||
`python3 scripts/agent_gates.py` → **all 4 gates OK.**
|
||||
|
||||
The leak test counts connections **server-side** and models what `pbsTargetsFromPVE` does — build a
|
||||
client, use it once, drop it. It deliberately does **not** assert `err == nil` or that a field holds a
|
||||
value; both were true of the leaking code (the R-224 lesson).
|
||||
|
||||
| red-proof | mutation | seen failing with |
|
||||
|---|---|---|
|
||||
| 1 — the fix | remove `IdleConnTimeout` | *"abandoned pbs.Clients: after 5s the server still holds 5 open connection(s), want 0 (5 dialled in total)"* — the count is in the message, so it cannot be a timeout with another cause |
|
||||
| 2 — the worse fix | `DisableKeepAlives: true` | **the leak test PASSES.** Caught only by `TestPBSClient_KeepAliveStillReuses`: *"3 sequential requests over 3 connection(s), want 1"* |
|
||||
|
||||
**Red-proof 2 is the load-bearing one: Scenario A alone would have accepted a fix that made the problem
|
||||
worse** — no leak, at the price of a fresh dial for every one of ~40,000 daily requests. Both mutations
|
||||
reverted, tree re-verified clean.
|
||||
|
||||
## 4. §4 quoted, beside the results
|
||||
|
||||
> **P1** — *"(i) ep0's fd count falls by ≈194 within seconds … (ii) … ≈194 sockets convert ESTAB →
|
||||
> CLOSE-WAIT … (iii) neither — the count barely moves. Then the ownership attribution is wrong and the
|
||||
> finding must be withdrawn."*
|
||||
> **P2** — *"demo-hp (fixed): ≈ 0 … demo-felhom (control, untouched): ≈ 4 per hour → ≈ 16 over 4 h."*
|
||||
> **P3** — *"ep0's overall leak rate should fall from ≈ 200/day to ≈ 100/day while one box is fixed, and
|
||||
> to ≈ 0/day after Part 5."*
|
||||
|
||||
## 5. P1 — **outcome (i)**, in one second
|
||||
|
||||
| | ep0 fd | ESTAB | demo-felhom | demo-hp | CLOSE-WAIT |
|
||||
|---|---|---|---|---|---|
|
||||
| T-0 `09:15:46Z` | 415 | 398 | 199 | **199** | 0 |
|
||||
| T+1s `09:15:47Z` | **216** | **199** | 199 | **0** | **0** |
|
||||
| T+60s `09:16:42Z` | 218 | 201 | 199 | 2 | 0 |
|
||||
|
||||
**Outcome (ii) did not occur, so it gets no register row.** Not one socket converted to `CLOSE-WAIT`:
|
||||
ep0 reaps on peer FIN correctly. That also means the 543 `CLOSE-WAIT` at the 2026-08-18 wedge has some
|
||||
other explanation and is **not** evidence of a second defect on the protected machine — a finding in the
|
||||
negative, worth the sixty seconds it cost.
|
||||
|
||||
Ownership is now proven a **third** independent way: what dies with the process, agreeing with
|
||||
`ss -tnp` and with the access-log user agent. At 133 s uptime the fixed box held **0** connections.
|
||||
|
||||
## 6. P2 — divergence
|
||||
|
||||
**Window 09:15:47Z → 10:17:52Z = 1.03 h. You closed the ≥4 h window early**, so no daily rate is
|
||||
extrapolated and none is needed.
|
||||
|
||||
| box | agent | start | end | delta | per hour | predicted |
|
||||
|---|---|---|---|---|---|---|
|
||||
| `demo-felhom` CONTROL | 0.129.0 | 199 | 203 | **+4** | 3.87 | ≈4 |
|
||||
| `demo-hp` FIXED | 0.130.0 | 0 | 0 | **+0** | 0.00 | ≈0 |
|
||||
|
||||
**The assumption-free statement.** ep0's access log counts the opportunities: each box made **exactly 4
|
||||
`/snapshots` and 4 `/version` calls** in the window.
|
||||
|
||||
> **control: 4 cycles → 4 leaks. fixed: 4 cycles → 0 leaks.**
|
||||
|
||||
**Positive observable (standing rule 3):** a zero leak is equally consistent with "the agent stopped
|
||||
working" — it did not; its four cycles are in ep0's log. The boxes' other traffic is near-identical
|
||||
(`libwww-perl` 924 vs 926, `proxmox-backup-client` 898 vs 898), so **the only difference between them
|
||||
is the binary**. Poisson alone gives P(0 | λ=4) = **1.8%**, which is suggestive rather than conclusive
|
||||
and is not relied on alone.
|
||||
|
||||
## 7. P3 — the second box, and the backlog clearing itself
|
||||
|
||||
`demo-felhom` upgraded `10:18:56Z` on your word.
|
||||
|
||||
| | ep0 fd | ESTAB | CLOSE-WAIT |
|
||||
|---|---|---|---|
|
||||
| T-0 `10:18:55Z` | 220 | 203 | 0 |
|
||||
| **T+2s** | **17** | **0** | 0 |
|
||||
| settled 10:30–10:35Z | **17–19** | 0–2 | 0 |
|
||||
|
||||
**17 is precisely ep0's `t0` baseline** (fd 17, ESTAB 0, 2026-08-18 09:51:22Z), and it returns to 17
|
||||
between poll cycles — the "healthy proxy near 20 fds" the incident document named. Predicted ≈0/day
|
||||
residual; **observed the baseline itself.**
|
||||
|
||||
**A correction, made within the hour it was written.** My STOP 1 report and the first CHANGELOG draft
|
||||
said *"does not clear the 388 descriptors already stuck on ep0 — those persist until that proxy
|
||||
restarts."* **Wrong.** They were held on both sides; restarting the agents released every one. **ep0 was
|
||||
read-only throughout and its proxy PID never changed (551655).** Corrected in the CHANGELOG, the audit
|
||||
document and R-344 rather than quietly edited.
|
||||
|
||||
## 8. Fleet sanity
|
||||
|
||||
Hub reports **0.130.0 on both** boxes. **No `floor held`** line (0.130.0 > golden MinAgent 0.129.0).
|
||||
**No `pbsdr_box_unreachable` / `offsite_box_unreachable`** during any window. Positive observable
|
||||
rather than the absent one: the PBS-DR gauge kept refreshing (`3.7% full (3.7 GB of 97.9 GB)`) and host
|
||||
reports kept landing from both boxes throughout.
|
||||
|
||||
## 9. What is NOT done
|
||||
|
||||
- **Not published.** No package, no tag, no manifest or floor field touched, no self-update staged.
|
||||
**A box installed from the current image still ships the leaking agent** — **R-347**, your call.
|
||||
- The CHANGELOG heading is `## UNRELEASED — v0.130.0 candidate`. The `release-complete` gate convicted
|
||||
on `## v0.130.0` because there is no tag and no package, and **it was right to**. I did not use
|
||||
`--no-verify`; I made the heading stop claiming a release that has not happened. It flips to
|
||||
`## v0.130.0` in the same commit as the tag.
|
||||
- Poll rate unchanged (**R-336**, re-scoped). `pbsTargetsFromPVE` not refactored; no
|
||||
`CloseIdleConnections` added. ep0 not touched.
|
||||
- **The 388 descriptors ARE cleared** — see §7. This is the one item the prompt expected to remain
|
||||
outstanding, and it did not.
|
||||
|
||||
## 10. Register
|
||||
|
||||
- **R-344** — updated with the fix, P1's outcome named, and P2/P3's numbers. **Left OPEN**, because a fix
|
||||
on two boxes by hand is not delivered.
|
||||
- **R-336 — re-scoped.** Its new next-step cell, verbatim: *"**NEW ACCEPTANCE CRITERION, since the old
|
||||
one is void:** the fd count is NOT the observable for this row any more — that belongs to R-344 and is
|
||||
already satisfied. Measure the REQUEST RATE at ep0's access log, and state the projected rate at the
|
||||
target customer count."* The row now records explicitly that its old next-step **would have "fixed"
|
||||
nothing while looking like a failed fix**, and re-scopes it to what it is: ~85,000 requests/day to a
|
||||
weekly-write DR endpoint, ≈**25 requests/second at fifty customers** against a CX33.
|
||||
- **R-347 (new)** — the delivery gap. Owner: **Viktor decides**, CC executes.
|
||||
- **R-348 (new)** — an agent restart blanks the reported backup list for up to ~18 h, and the `Store`
|
||||
comment calls backups *"unaffected"*. **Blinds no alarm** — checked, not assumed: the hub's
|
||||
`backupEvidenceLookback` scans 7 days for exactly this case, and `pbs_snapshots` stayed populated.
|
||||
- **No P1(ii) row**, because outcome (ii) did not occur.
|
||||
- **R-346** — this run anchored on the measured `t0` (fd 17 at 2026-08-18 09:51:22Z), never on a systemd
|
||||
timestamp, so the 5 h 56 m discrepancy did not touch these numbers.
|
||||
|
||||
## 12. Observations
|
||||
|
||||
- **The closure refactor is not worth doing — recommend leaving it.** With the idle timeout restored an
|
||||
abandoned client's connection is gone in 90 s, so the standing population is bounded at about one
|
||||
connection per box instead of growing without limit. Caching clients would add cache-invalidation
|
||||
questions (a storage's fingerprint, token or namespace can change under it) for no observable gain.
|
||||
- **Three other `http.Transport` defaults are still missing and were left alone:** `MaxIdleConns`,
|
||||
`TLSHandshakeTimeout` (0 = no limit; `DefaultTransport` uses 10 s) and `ExpectContinueTimeout`. None
|
||||
accumulates, and every client bounds its request with `http.Client.Timeout`. `TLSHandshakeTimeout` is
|
||||
the only one with a plausible failure mode — a stalled handshake over the tunnel, bounded today only
|
||||
by the outer 30 s. Not changed, because widening the diff would have made this measurement
|
||||
unattributable. Worth a look on its own terms; not a defect.
|
||||
- **A measurement error of mine, recorded because it nearly cost four hours.** The first P2 sampler
|
||||
reported both per-box columns as 0 while the totals were right: `ss` prints `[::ffff:10.77.0.2]:port`
|
||||
and my pattern expected `10.77.0.2:`. Caught 15 minutes in, because a 0/0 split cannot sum to 199.
|
||||
Fixed, then **one sample proved by hand before committing the window** — which is what should have
|
||||
happened first.
|
||||
@@ -1,7 +1,7 @@
|
||||
# STATUS — what works, what's broken, what's next
|
||||
|
||||
**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).**
|
||||
**Updated 2026-08-20 (midday — the leak was ours, and it is fixed and proven on both demo machines;
|
||||
it is not yet published).**
|
||||
|
||||
> **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.**
|
||||
@@ -124,6 +124,19 @@ record with no machine** — created 13 August, no host, no backups, nothing to
|
||||
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)*
|
||||
- **FIXED the same day, and proven on the machines** (R-344). One line of our code: the agent had the
|
||||
idle-connection timer switched off, so nothing ever retired the connections it abandoned. Turning it
|
||||
back on to the standard 90 seconds fixed it. **The proof cost nothing clever:** we put the fix on one
|
||||
machine and left the other alone, and in the same hour the untouched one leaked 4 more connections
|
||||
while the fixed one leaked none — with both doing exactly the same four rounds of work. **The
|
||||
off-site box is back to 17 open connections, its normal resting number, down from 415.** All of the
|
||||
built-up connections released themselves when the agents restarted; the off-site box was only ever
|
||||
read from, never touched. *(register: R-344)*
|
||||
- **The fix is on the two demo machines by hand and NOT published yet** (R-347). A machine installed
|
||||
from today's image still gets the old, leaking agent. That was deliberate — publishing it mid-test
|
||||
would have contaminated the comparison — and the reason has now expired. **It is not urgent:** a new
|
||||
machine would take the better part of a year to matter, and any agent update clears the build-up.
|
||||
**Publishing is your call**, and it needs the operator-only artifact screen at the end.
|
||||
- **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
|
||||
@@ -163,9 +176,8 @@ record with no machine** — created 13 August, no host, no backups, nothing to
|
||||
|
||||
## Working on next
|
||||
|
||||
**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
|
||||
**One decision is waiting for you:** whether to publish agent 0.130.0 so machines other than the two
|
||||
demo boxes get the fix (R-347). It needs the artifact screen, which only you can drive. 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.
|
||||
|
||||
@@ -321,3 +321,182 @@ result.** That is the substantive change to R-336 this spike delivers.
|
||||
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.
|
||||
|
||||
---
|
||||
|
||||
# Fix and proof — 2026-08-20, later the same day (R-344)
|
||||
|
||||
Run under `Claude Code Prompt: fix the agent's leaked PBS connections, then prove it on one box`,
|
||||
which **cancelled Phase C**. Evidence: `evidence-agent-transport-leak-2026-08-20/`.
|
||||
|
||||
**Phase C was never run, and cancelling it was right.** It would have quietened `pvestatd` on `demo-hp`
|
||||
to test whether the leak tracks the request rate. The spike had already shown `pvestatd` leaks nothing,
|
||||
so the honest prediction was a null result. The experiment that replaced it — deploy the fix to one box
|
||||
and leave the other as a control — proves the fix and re-proves the mechanism in one window, and it
|
||||
opens with a free, immediate, decisive observation Phase C could not have produced.
|
||||
|
||||
## The fix
|
||||
|
||||
One field, restored to the standard library's own value. New leaf package `felhom-agent/internal/httpx`
|
||||
owns `DefaultIdleConnTimeout = 90 * time.Second` — 90s because that is `http.DefaultTransport`'s value,
|
||||
so there is nothing invented to justify — and `NewTransport(tlsCfg, idle)`, which returns a **fresh**
|
||||
transport every call (never shared: each caller pins a different endpoint) and treats a zero or negative
|
||||
timeout as **use the default, never "no timeout"**. Wired into all three hand-rolled transports;
|
||||
`grep '&http.Transport{'` now matches only `httpx` itself.
|
||||
|
||||
`internal/hub/client.go` and `internal/proxmox/client.go` carried the identical missing default and were
|
||||
corrected in the same pass. **Neither contributed to the ep0 leak** — both are built once per process,
|
||||
so they held one idle connection for the life of the daemon rather than accumulating, and neither talks
|
||||
to `ep0:8007`. This must not be read as three leaks having been found.
|
||||
|
||||
**A check made before trusting the fix:** `doBody` already reads the response body to completion and
|
||||
closes it, so the connection genuinely reaches the idle pool. Had it not, `IdleConnTimeout` would have
|
||||
been the wrong fix and the leak would have been an un-drained body instead.
|
||||
|
||||
### The tests, and the two red-proofs
|
||||
|
||||
`internal/pbs/client_leak_test.go` counts connections **server-side** and models what
|
||||
`pbsTargetsFromPVE` actually does — build a client, use it once, drop it on the floor. It deliberately
|
||||
does not assert `err == nil` and does not assert that a field holds a value; **both were true of the
|
||||
leaking code**. This is the R-224 lesson applied: assert the consequence, not the mechanism.
|
||||
|
||||
| red-proof | mutation | result |
|
||||
|---|---|---|
|
||||
| 1 — the fix | remove `IdleConnTimeout` from `NewTransport` | **FAILS**: *"abandoned pbs.Clients: after 5s the server still holds 5 open connection(s), want 0 (5 dialled in total)"* — the count is in the message, so the failure cannot be a timeout with another cause |
|
||||
| 2 — the worse fix | `DisableKeepAlives: true` | **the leak test PASSES.** Disabling keep-alive also stops the leak — by dialling fresh for every one of ~40,000 daily requests. `TestPBSClient_KeepAliveStillReuses` is what catches it: *"3 sequential requests over 3 connection(s), want 1"* |
|
||||
|
||||
Red-proof 2 is the load-bearing one: **Scenario A alone would have accepted a fix that made the problem
|
||||
worse.** Both mutations were reverted and the tree re-verified clean.
|
||||
|
||||
Green gate: `go build ./... && go vet ./... && go test ./...` → 30 packages, 0 failures.
|
||||
`python3 scripts/agent_gates.py` → all 4 gates OK.
|
||||
|
||||
## P1 — the restart observation
|
||||
|
||||
Predicted in advance as one of three outcomes. **Outcome (i), within one second.**
|
||||
|
||||
| | ep0 fd | ESTAB | from `demo-felhom` | from `demo-hp` | CLOSE-WAIT |
|
||||
|---|---|---|---|---|---|
|
||||
| T-0 `09:15:46Z` | 415 | 398 | 199 | **199** | 0 |
|
||||
| T+1s `09:15:47Z` | **216** | **199** | 199 | **0** | **0** |
|
||||
| T+60s `09:16:42Z` | 218 | 201 | 199 | 2 | 0 |
|
||||
|
||||
**Outcome (ii) did not occur and gets no register row.** Not one socket converted to `CLOSE-WAIT`: ep0
|
||||
reaps on the peer's FIN correctly, so the 543 `CLOSE-WAIT` seen at the 2026-08-18 wedge has some other
|
||||
explanation and is not evidence of a second defect on the protected machine. That is a finding in the
|
||||
negative and it was worth the sixty seconds it cost.
|
||||
|
||||
**Ownership is now established by a third independent route.** Killing our process released exactly
|
||||
`demo-hp`'s 199 descriptors — agreeing with `ss -tnp` on the box and with the access-log user agent.
|
||||
|
||||
**The new code retires connections, observed directly:** at 133 s uptime `demo-hp` held **0**
|
||||
connections; the 2 it opened after restart were closed at the 90 s idle mark.
|
||||
|
||||
## P2 — the divergence window
|
||||
|
||||
**Window 09:15:47Z → 10:17:52Z = 1.03 h. The task specified ≥ 4 h; the operator closed it early.**
|
||||
The conclusion below therefore does not rest on an extrapolated daily rate, and none is used.
|
||||
|
||||
| box | agent | start | end | delta | per hour |
|
||||
|---|---|---|---|---|---|
|
||||
| `demo-felhom` — CONTROL | 0.129.0 | 199 | 203 | **+4** | 3.87 |
|
||||
| `demo-hp` — FIXED | 0.130.0 | 0 | 0 | **+0** | 0.00 |
|
||||
|
||||
Predicted: control ≈4/hour, fixed ≈0. **Control observed 3.87/hour.**
|
||||
|
||||
**The assumption-free statement, and the reason the short window still settles it.** ep0's access log
|
||||
counts the poll cycles directly: in that window **each box made exactly 4 `GET .../snapshots` calls and
|
||||
4 `GET /version` calls**. Same cadence, same work, the same four chances to leak.
|
||||
|
||||
> **control: 4 cycles → 4 leaked connections. fixed: 4 cycles → 0 leaked connections.**
|
||||
|
||||
**The positive observable, per standing rule 3.** A zero leak is equally consistent with "fixed" and
|
||||
with "the agent stopped working". It is the former: the fixed box's four poll cycles are in ep0's log,
|
||||
alongside the control's four. The rest of the two boxes' traffic is near-identical in the window —
|
||||
`libwww-perl` 924 vs 926, `proxmox-backup-client` 898 vs 898 — so **the only difference between them is
|
||||
the agent binary**.
|
||||
|
||||
Poisson alone would give P(0 leaks | old rate, λ=4) = **1.8%**, which is suggestive rather than
|
||||
conclusive. It does not stand alone: P1 released 199 descriptors instantly, the mechanism is identified
|
||||
at `file:line` and pinned by a red-proofed test, and the fixed box was directly observed returning to 0.
|
||||
|
||||
## P3 — the second box, and the accumulated leak clearing itself
|
||||
|
||||
`demo-felhom` — the former control — was upgraded at `10:18:56Z` on the operator's word.
|
||||
|
||||
| | ep0 fd | ESTAB | CLOSE-WAIT |
|
||||
|---|---|---|---|
|
||||
| T-0 `10:18:55Z` | 220 | 203 | 0 |
|
||||
| **T+2s `10:18:56Z`** | **17** | **0** | **0** |
|
||||
| T+65s `10:19:58Z` | 20 | 3 | 0 |
|
||||
| settled, 10:30–10:35Z | **17–19** | 0–2 | 0 |
|
||||
|
||||
**fd 17 is precisely ep0's `t0` baseline** — fd 17, ESTAB 0, recorded at 2026-08-18 09:51:22Z. The proxy
|
||||
sits at 17–19 and returns to 17 between poll cycles, which is the "healthy proxy near 20 fds" the
|
||||
incident document named as the positive observable. **ep0 was read-only throughout and its proxy PID
|
||||
never changed (551655).**
|
||||
|
||||
**This corrects a sentence written earlier the same day**, in the v0.130.0 CHANGELOG draft and in the
|
||||
STOP 1 report: *"does not clear the 388 descriptors already stuck on ep0 — those persist until that
|
||||
proxy restarts."* **Wrong, and measured wrong within the hour.** The descriptors were held on *both*
|
||||
sides; closing either side ends them. Restarting the two agents released all of them. Nothing on the
|
||||
protected machine had to be touched, and nothing was.
|
||||
|
||||
## Fleet sanity
|
||||
|
||||
- Hub reports `demo-hp` **0.130.0** and `demo-felhom` **0.130.0**; 0.130.0 is above the golden's
|
||||
MinAgent of 0.129.0, and **no `floor held` line appeared** for either box.
|
||||
- **No `pbsdr_box_unreachable` / `offsite_box_unreachable` event** fired during any window.
|
||||
- Positive observable rather than the absent one: the hub's PBS-DR gauge kept refreshing on schedule
|
||||
(`3.7% full (3.7 GB of 97.9 GB)`) and host reports kept landing from both boxes throughout.
|
||||
|
||||
## An unrelated finding the deploy exposed — R-348
|
||||
|
||||
The **first two host reports after an agent restart carry `0 backups`**, while the box's own
|
||||
`pvesm list` shows backups present on both tiers. `internal/backup/store.go`'s `Store` is in-memory and
|
||||
its `byTarget` map is repopulated only when a backup **runs** — daily for the local tier, weekly for
|
||||
offsite — so the field reads 0 for up to ~18 h after any restart. `restore_tests` did **not** blank,
|
||||
because that half has a durable on-disk companion (`RestoreTestState`, R-189).
|
||||
|
||||
**It blinds no alarm, and that was checked rather than assumed.** `hub/internal/monitor/deadline.go`
|
||||
already scans back over stored reports with a 7-day `backupEvidenceLookback`, whose comment names this
|
||||
exact case — *"when the LATEST report carries none... and against an agent that stayed restarted for
|
||||
days"* — and `pbs_snapshots` stayed populated at 2 regardless. So this is an observability wart, not a
|
||||
safety hole.
|
||||
|
||||
**But the `Store` comment is misleading in a way this project has a rule about.** It reads *"Backups are
|
||||
unaffected — their freshness has a ground truth on the storage (R-84)"*. That is true of the
|
||||
**consequence** and false of the **field**, and a future reader may take it as a guarantee the field
|
||||
stays populated. Filed as R-348.
|
||||
|
||||
## What this run did NOT do
|
||||
|
||||
- **Did not publish.** No Gitea package, no tag, no `artifact_agent_version` / `artifact_min_agent` /
|
||||
`artifact_golden_version` / `min_controller_version` change, no staged self-update. **A box installed
|
||||
from the current image still carries the leaking agent** — filed as **R-347**, and the CHANGELOG
|
||||
heading stays `## UNRELEASED` until that decision is taken.
|
||||
- **Did not reduce the poll rate.** R-336 stays open, **re-scoped**: it was never the cause of this leak.
|
||||
- **Did not refactor `pbsTargetsFromPVE`** to cache or reuse clients, and added no
|
||||
`CloseIdleConnections` call. See Observations.
|
||||
- **Did not touch ep0** — no restart, no config, no package, no nftables. Reads only.
|
||||
- Did not trigger a backup, restore or verify to generate traffic; did not contact `peti-felhom`.
|
||||
|
||||
## Observations
|
||||
|
||||
- **The closure refactor is not worth doing, and the measurement is why.** With the idle timeout
|
||||
restored, an abandoned client's connection is gone in 90 s, so the standing population is bounded at
|
||||
roughly one connection per box rather than growing without limit. Caching clients would add
|
||||
cache-invalidation questions — a storage's fingerprint, token or namespace can change under it — for
|
||||
no observable gain. Recommend leaving it.
|
||||
- **Three other `http.Transport` defaults are still missing** and were deliberately left alone:
|
||||
`MaxIdleConns` (0 = unlimited; `DefaultTransport` uses 100), `TLSHandshakeTimeout` (0 = no limit;
|
||||
`DefaultTransport` uses 10 s) and `ExpectContinueTimeout`. None of them accumulates anything, and every
|
||||
client bounds its whole request with `http.Client.Timeout`, so none is a leak. `TLSHandshakeTimeout`
|
||||
is the only one with a plausible failure mode — a stalled handshake over the tunnel, bounded today
|
||||
only by the outer 30 s client timeout. **Not changed here, because widening the diff would have made
|
||||
this measurement unattributable.** Worth a look on its own terms; not filed as a defect.
|
||||
- **A measurement error of mine, recorded because it nearly cost four hours.** The first P2 sampler
|
||||
reported both per-box columns as 0 while the totals were right: `ss` prints
|
||||
`[::ffff:10.77.0.2]:port`, and the pattern expected `10.77.0.2:`. Caught 15 minutes in by noticing
|
||||
that a 0/0 split could not sum to 199. Fixed, then **one sample was proved by hand before committing
|
||||
the window to it** — the check that should have happened first.
|
||||
|
||||
+87
@@ -0,0 +1,87 @@
|
||||
=== the 0-backups blip: what does the hub SHOW, and did anything ALARM? ===
|
||||
captured 2026-08-20T09:31:38+00:00
|
||||
demo-hp agent restarted 2026-08-20 09:15:46Z; two reports since, both '0 backups'
|
||||
|
||||
--- hub host page, the DR/Backup region (tags stripped) ---
|
||||
|
||||
|
||||
|
||||
|
||||
|
||||
DR / Backup
|
||||
|
||||
|
||||
DR Recipe
|
||||
present
|
||||
|
||||
|
||||
Key Escrow
|
||||
present · 1 superseded escrow blob(s) retained
|
||||
|
||||
|
||||
|
||||
|
||||
|
||||
Console access
|
||||
|
||||
|
||||
|
||||
User
|
||||
root@pam
|
||||
|
||||
|
||||
Password set
|
||||
29d ago
|
||||
|
||||
|
||||
|
||||
••••••••••••••••
|
||||
Reveal
|
||||
Copy
|
||||
|
||||
|
||||
Break-glass credential for the PVE web console at https://<host-ip>:8006 (realm: Linux PAM standard authentication). Copy puts it straight on the clipboard without showing it; Reveal displays it for 60 s. Either one is recorded on the customer's event timeline. Last vaulted value — if root@pam was changed on the box without re-vaulting, this is stale.
|
||||
|
||||
|
||||
|
||||
|
||||
|
||||
|
||||
|
||||
|
||||
|
||||
var consolePwState = typeof consolePwState !== 'undefined' ? consolePwState : {};
|
||||
var consolePwMask = '••••••••••••••••';
|
||||
function consoleHint(hostID, msg) {
|
||||
var h = document.getElementById('console-hint-' + hostID);
|
||||
if (h) { h.textContent = msg; }
|
||||
}
|
||||
function maskConsolePassword(hostID) {
|
||||
var st = consolePwState[hostID];
|
||||
if (st && st.timer) { clearTimeout(st.timer); }
|
||||
consolePwState[hostID] = null;
|
||||
var code = document.getElementById('console-pw-' + hostID);
|
||||
if (code) { code.textContent = consolePwMask; }
|
||||
var reveal = document.getElementById('console-reveal-' + hostID);
|
||||
if (reveal) { reveal.textContent = 'Reveal'; }
|
||||
|
||||
--- CONTROL: same region for demo-felhom (still 0.129.0, never restarted) ---
|
||||
763: DR / Backup
|
||||
764-
|
||||
765-
|
||||
766- DR Recipe
|
||||
767- present
|
||||
768-
|
||||
769-
|
||||
770- Key Escrow
|
||||
771- present · 3 superseded escrow blob(s) retained
|
||||
772-
|
||||
773-
|
||||
774-
|
||||
775-
|
||||
776-
|
||||
777- Console access
|
||||
778-
|
||||
779-
|
||||
780-
|
||||
781- User
|
||||
+41
@@ -0,0 +1,41 @@
|
||||
=== P1 — the restart observation. demo-hp gets 0.130.0; demo-felhom is the untouched control. ===
|
||||
DooPlex UTC now: 2026-08-20T09:15:45+00:00
|
||||
|
||||
--- T-0 ep0 IMMEDIATELY BEFORE ---
|
||||
t=09:15:46Z pid=551655 fd=415 | 398 ESTAB 1 LISTEN | peers: 199 10.77.0.2 199 10.77.0.3
|
||||
|
||||
--- installing + restarting felhom-agent on demo-hp ---
|
||||
old MainPID: 3199936
|
||||
RESTART AT: 09:15:46.964123161Z
|
||||
new MainPID: 375451
|
||||
felhom-agent 0.130.0
|
||||
|
||||
--- T+~5s ---
|
||||
t=09:15:47Z pid=551655 fd=216 | 199 ESTAB 1 LISTEN | peers: 199 10.77.0.2
|
||||
--- T+~15s ---
|
||||
t=09:15:55Z pid=551655 fd=218 | 201 ESTAB 1 LISTEN | peers: 199 10.77.0.2 2 10.77.0.3
|
||||
--- T+~30s ---
|
||||
t=09:16:11Z pid=551655 fd=218 | 201 ESTAB 1 LISTEN | peers: 199 10.77.0.2 2 10.77.0.3
|
||||
--- T+~60s ---
|
||||
t=09:16:42Z pid=551655 fd=218 | 201 ESTAB 1 LISTEN | peers: 199 10.77.0.2 2 10.77.0.3
|
||||
|
||||
--- demo-hp client side after restart ---
|
||||
ESTAB to 8007: 2
|
||||
active
|
||||
felhom-agent : PWD=/ ; USER=root ; COMMAND=/usr/bin/lxc-info -n 9201 -p -H
|
||||
pam_unix(sudo:session): session opened for user root(uid=0) by (uid=999)
|
||||
pam_unix(sudo:session): session closed for user root
|
||||
felhom-agent : PWD=/ ; USER=root ; COMMAND=/usr/sbin/blkid -p -o export /dev/nvme0n1
|
||||
pam_unix(sudo:session): session opened for user root(uid=0) by (uid=999)
|
||||
pam_unix(sudo:session): session closed for user root
|
||||
felhom-agent : PWD=/ ; USER=root ; COMMAND=/usr/bin/lsblk -J -o NAME,FSTYPE,PTTYPE,MOUNTPOINT /dev/nvme0n1
|
||||
pam_unix(sudo:session): session opened for user root(uid=0) by (uid=999)
|
||||
pam_unix(sudo:session): session closed for user root
|
||||
felhom-agent : PWD=/ ; USER=root ; COMMAND=/usr/bin/lxc-info -n 9201 -p -H
|
||||
pam_unix(sudo:session): session opened for user root(uid=0) by (uid=999)
|
||||
pam_unix(sudo:session): session closed for user root
|
||||
|
||||
--- demo-felhom (CONTROL — untouched) client side ---
|
||||
version: felhom-agent 0.129.0
|
||||
MainPID: 2596329
|
||||
ESTAB to 8007: 199
|
||||
@@ -0,0 +1,34 @@
|
||||
P2 ARITHMETIC — the divergence window
|
||||
|
||||
window 2026-08-20T09:15:47Z -> 10:17:52Z = 3725 s = 1.0347 h
|
||||
NOTE: this is 1.03 h, NOT the >=4 h the task specified. The operator closed it early.
|
||||
The conclusion below therefore does NOT rest on an extrapolated daily rate.
|
||||
|
||||
box agent start end delta per hour
|
||||
demo-felhom (CONTROL) 0.129.0 199 203 +4 3.87
|
||||
demo-hp (FIXED) 0.130.0 0 0 +0 0.00
|
||||
|
||||
PREDICTED (pre-registered, P2 table): control ~4/hour; fixed ~0.
|
||||
OBSERVED: control 3.87/hour, fixed 0. Control matches the prediction.
|
||||
|
||||
THE ASSUMPTION-FREE STATEMENT — matched opportunities, counted from ep0's access log:
|
||||
Both agents made EXACTLY 4 GET .../snapshots calls and 4 GET /version calls in this window.
|
||||
Same cadence, same work, same number of chances to leak.
|
||||
control: 4 cycles -> 4 leaked connections
|
||||
fixed : 4 cycles -> 0 leaked connections
|
||||
No rate extrapolation is needed for that, and none is used.
|
||||
|
||||
Poisson: P(observing 0 leaks | the OLD rate, lambda=4) = e^-4 = 1.83%
|
||||
On its own that is suggestive, not proof. It is not on its own:
|
||||
- P1 released exactly 199 descriptors the instant the old process died;
|
||||
- the mechanism is identified at file:line and pinned by a red-proofed unit test;
|
||||
- the fixed box was directly observed returning to 0 connections 133 s after restart.
|
||||
|
||||
P3 — total rate with ONE box fixed
|
||||
observed 92.8 fd/day (predicted ~100/day, from ~200/day with both boxes leaking)
|
||||
Poisson on n=4 is +/-2, so the 2-sigma band is 0..186/day — the prediction sits inside it.
|
||||
A 4-descriptor window cannot pin a daily rate tighter than that, and this does not pretend to.
|
||||
|
||||
CONTROL INTEGRITY: the two boxes' OTHER traffic is unchanged and near-identical in this window --
|
||||
libwww-perl 924 (.2) vs 926 (.3); proxmox-backup-client 898 vs 898.
|
||||
So the only thing that differs between them is the agent binary.
|
||||
@@ -0,0 +1,9 @@
|
||||
=== P2 — the divergence window ===
|
||||
fixed : demo-hp 10.77.0.3 agent 0.130.0 (restarted 2026-08-20 09:15:46Z)
|
||||
control: demo-felhom 10.77.0.2 agent 0.129.0 (untouched)
|
||||
ep0 read-only; sample every 900 s
|
||||
|
||||
utc fd estab ctrl(.2) fix(.3) proxyPID CLOSEWAIT
|
||||
2026-08-20T09:33:36Z 217 200 200 0 551655 0
|
||||
2026-08-20T09:48:37Z 218 201 201 0 551655 0
|
||||
2026-08-20T10:03:37Z 219 202 202 0 551655 0
|
||||
+19
@@ -0,0 +1,19 @@
|
||||
=== P2 FINAL SAMPLE + the positive observable ===
|
||||
UTC: 2026-08-20T10:17:52+00:00
|
||||
proxyPID=551655 fd=220 estab=203 ctrl(.2)=203 fix(.3)=0 CLOSE-WAIT=0
|
||||
|
||||
--- POSITIVE OBSERVABLE: is the FIXED agent still polling at all? ---
|
||||
(a zero leak could equally mean 'fixed' or 'the agent stopped working' — standing rule 3)
|
||||
agent (Go-http-client) requests since 09:16Z, per box:
|
||||
4 10.77.0.2 /api2/json/admin/datastore/felhom-offsite/snapshots
|
||||
4 10.77.0.2 /api2/json/version"
|
||||
4 10.77.0.3 /api2/json/admin/datastore/felhom-offsite/snapshots
|
||||
4 10.77.0.3 /api2/json/version"
|
||||
|
||||
--- and the pvestatd/backup-client streams, to show BOTH boxes are otherwise identical ---
|
||||
8 10.77.0.2 Go-http-client/1.1
|
||||
924 10.77.0.2 libwww-perl/6.78
|
||||
898 10.77.0.2 proxmox-backup-client/1.0
|
||||
8 10.77.0.3 Go-http-client/1.1
|
||||
926 10.77.0.3 libwww-perl/6.78
|
||||
898 10.77.0.3 proxmox-backup-client/1.0
|
||||
@@ -0,0 +1,20 @@
|
||||
=== 4.3 fleet sanity ===
|
||||
captured 2026-08-20T09:17:31+00:00
|
||||
|
||||
--- hub: agent version reported per host ---
|
||||
2026/08/20 10:52:35 [INFO] host-report from demo-hp-bb76ea (1 guests, 5 storage targets, 2 backups, 2 restore-tests, 2 pbs-snapshots, 14945 bytes)
|
||||
2026/08/20 11:00:33 [INFO] host-report from demo-felhom-8363b5 (1 guests, 4 storage targets, 2 backups, 2 restore-tests, 2 pbs-snapshots, 14341 bytes)
|
||||
2026/08/20 11:07:35 [INFO] host-report from demo-hp-bb76ea (1 guests, 5 storage targets, 2 backups, 2 restore-tests, 2 pbs-snapshots, 14960 bytes)
|
||||
2026/08/20 11:15:33 [INFO] host-report from demo-felhom-8363b5 (1 guests, 4 storage targets, 2 backups, 2 restore-tests, 2 pbs-snapshots, 14323 bytes)
|
||||
2026/08/20 11:15:50 [INFO] host-report from demo-hp-bb76ea (1 guests, 5 storage targets, 0 backups, 2 restore-tests, 2 pbs-snapshots, 13784 bytes)
|
||||
|
||||
--- hub: any floor-held line for demo-hp? ---
|
||||
(empty = none)
|
||||
|
||||
--- hub: any unreachable/recovered event since the deploy? ---
|
||||
(empty = none)
|
||||
|
||||
--- hub: PBS-DR gauge still refreshing (positive observable) ---
|
||||
2026/08/20 10:38:31 [INFO] PBS-DR box refreshed: 3.7% full (3.7 GB of 97.9 GB)
|
||||
2026/08/20 10:54:30 [INFO] PBS-DR box refreshed: 3.7% full (3.7 GB of 97.9 GB)
|
||||
2026/08/20 11:10:31 [INFO] PBS-DR box refreshed: 3.7% full (3.7 GB of 97.9 GB)
|
||||
@@ -0,0 +1,11 @@
|
||||
=== 4.3 hub /hosts — agent version as the FLEET sees it ===
|
||||
captured 2026-08-20T09:17:45+00:00
|
||||
0.106.0
|
||||
demo-felhom-8363b5'" style="cursor: pointer;">
|
||||
demo-felhom-8363b5">demo-felhom-8363b5
|
||||
0.129.0
|
||||
demo-hp-bb76ea'" style="cursor: pointer;">
|
||||
demo-hp-bb76ea">demo-hp-bb76ea
|
||||
0.130.0
|
||||
0.129.0
|
||||
0.106.0
|
||||
@@ -0,0 +1,21 @@
|
||||
=== PART 5 — the second box. demo-felhom (the former control) gets 0.130.0. ===
|
||||
DooPlex UTC: 2026-08-20T10:18:54+00:00
|
||||
|
||||
--- T-0 ep0 immediately before ---
|
||||
t=10:18:55Z pid=551655 fd=220 estab=203 ctrl(.2)=203 fix(.3)=0 CLOSE-WAIT=0
|
||||
|
||||
old MainPID: 2596329
|
||||
RESTART AT : 10:18:56.139906374Z
|
||||
new MainPID: 2540886
|
||||
felhom-agent 0.130.0
|
||||
|
||||
--- T+~2s ---
|
||||
t=10:18:56Z pid=551655 fd=17 estab=0 ctrl(.2)=0 fix(.3)=0 CLOSE-WAIT=0
|
||||
--- T+~25s ---
|
||||
t=10:19:17Z pid=551655 fd=19 estab=2 ctrl(.2)=2 fix(.3)=0 CLOSE-WAIT=0
|
||||
--- T+~65s ---
|
||||
t=10:19:58Z pid=551655 fd=20 estab=3 ctrl(.2)=3 fix(.3)=0 CLOSE-WAIT=0
|
||||
|
||||
--- both boxes, client side ---
|
||||
demo-felhom: agent 0.130.0, ESTAB to 8007 = 2, service active
|
||||
felhom-host: agent 0.130.0, ESTAB to 8007 = 0, service active
|
||||
@@ -0,0 +1,11 @@
|
||||
=== ep0 settle check — both boxes on 0.130.0 since 10:18:56Z ===
|
||||
t=10:30:27Z pid=551655 fd=17 estab=0 ctrl(.2)=0 fix(.3)=0 CLOSE-WAIT=0
|
||||
t=10:32:08Z pid=551655 fd=19 estab=2 ctrl(.2)=1 fix(.3)=1 CLOSE-WAIT=0
|
||||
t=10:33:49Z pid=551655 fd=19 estab=1 ctrl(.2)=0 fix(.3)=1 CLOSE-WAIT=0
|
||||
t=10:35:29Z pid=551655 fd=19 estab=2 ctrl(.2)=2 fix(.3)=0 CLOSE-WAIT=0
|
||||
|
||||
--- agent poll activity in the settle period (proves both are still working) ---
|
||||
1 10.77.0.2 /api2/json/admin/datastore/felhom-offsite/snapshots
|
||||
1 10.77.0.2 /api2/json/version"
|
||||
1 10.77.0.3 /api2/json/admin/datastore/felhom-offsite/snapshots
|
||||
1 10.77.0.3 /api2/json/version"
|
||||
@@ -0,0 +1,14 @@
|
||||
=== ep0 state at STOP 1 — read-only, immediately before the deploy decision ===
|
||||
UTC: 2026-08-20T09:10:00+00:00 epoch=1787217000
|
||||
PID=551655 (must still be 551655)
|
||||
Tue Aug 18 09:51:04 2026
|
||||
fd count: 414
|
||||
--- ESTAB / CLOSE-WAIT split (all states, sport 8007) ---
|
||||
397 ESTAB
|
||||
1 LISTEN
|
||||
--- per-peer established ---
|
||||
198 10.77.0.2
|
||||
199 10.77.0.3
|
||||
--- listener ---
|
||||
State Recv-Q Send-Q Local Address:Port Peer Address:Port
|
||||
LISTEN 0 1024 *:8007 *:*
|
||||
File diff suppressed because one or more lines are too long
Reference in New Issue
Block a user