Files
felhom.eu/REPORT-agent-transport-leak.md
T
admin 910fd91124
gates / gates (push) Successful in 14s
agent 0.130.0 published and vouched; R-347 closed, R-349 + R-350 filed
Released via scripts/release-agent.sh: tag v0.130.0 at 7569f34, sha256
a56a92a7bd68f5b46736eaec4806c3d26c16ccb35118c4ac0e3d8094eaefabc3,
verified by independent download and reproducible byte for byte with
-trimpath -buildvcs=false.

Vouched agent 0.129.0 -> 0.130.0 in the Day-0 manifest. Only the agent
fields changed: min_agent stays 0.129.0 because it states what the GOLDEN
CONTROLLER requires, and raising it would have HELD the floor for every
box below 0.130.0. Global floor untouched at 0.216.0 -- and on hub
v0.106.0 it is a separate form with its own action, so publish-train
rule 2's hazard no longer exists in the shape its incident describes.

No --no-verify: the CHANGELOG heading was flipped only after the tag and
package existed, so release-complete passes on the real artifact.

R-349: the fleet was running a DIFFERENT binary under the same version
name -- the proof deploy was a hand build, the release is -trimpath.
Self-update could never have corrected it, because every version check
compares the string. Both boxes reinstalled from the downloaded package.
The proper fix exists in miniature as wrapper_sha256 and was never
extended to the agent's own binary.

R-350: I printed the hub password into the session transcript via
curl -w '%{redirect_url}' -- the hub answers 303 and curl re-attaches the
credential. Not in git, not in any committed file, not in the evidence
directory. Rotation is the operator's call.

ep0 closes at fd 17, ESTAB 0, CLOSE-WAIT 0 -- its t0 baseline -- and was
read-only for this entire arc.
2026-08-20 12:54:54 +02:00

247 lines
14 KiB
Markdown
Raw Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
# 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; ep0 is back to its baseline of 17 file
descriptors from 415; and 0.130.0 is now published and vouched.** Both demo boxes run the **byte-exact
published artifact**. R-347 is CLOSED. Two new findings came out of the release itself — **R-349**
(the fleet was briefly running a different binary under the same version name) and **R-350** (I printed
the hub password into the transcript; rotation is your call).
## 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.
## 11. CI, by run ID — and the claim ledger
| repo | run | sha | conclusion |
|---|---|---|---|
| `felhom-agent` | id **362** / run_number 50 | `ede49b610` — the fix | **success** |
| `felhom-agent` | id **363** / run_number 51 | `7569f34ae` — the correction | **success** |
| `felhom.eu` | id **364** / run_number 239 | `57dd62b09` — the write-up | **success** |
No `--no-verify` anywhere. Both repos' pre-push hooks ran their gate entry point and passed;
`release-complete` passes on v0.129.0, which is the honest state while 0.130.0 is unpublished.
`python3 scripts/unproven.py --summary` — **unchanged: 23 walked, 32 not walked of 55.** No number
moved, and correctly so: this run proved an engineering fact about our own connection handling, not a
customer-facing product claim.
**Closing state of ep0**, read one last time after everything:
```
t=10:40:23Z pid=551655 fd=17 estab=0 ctrl(.2)=0 fix(.3)=0 CLOSE-WAIT=0
```
`CLOSE-WAIT 0`, `ESTAB` in the low single digits, `fd` at the baseline, proxy PID **551655** — the same
process that has been running since 2026-08-18 09:51:04, never restarted by this work.
## 11b. The release (R-347, CLOSED)
`bash scripts/release-agent.sh 0.130.0` — the one documented way (R-115): build, tag, publish, and
**verify by independent download**.
| | |
|---|---|
| tag | `v0.130.0` at `7569f34` |
| sha256 | **`a56a92a7bd68f5b46736eaec4806c3d26c16ccb35118c4ac0e3d8094eaefabc3`** |
| size | 14,141,158 bytes |
| reproducible | **yes, checked** — `-trimpath -buildvcs=false` rebuild matches byte for byte |
**Vouched** in the Day-0 artifact manifest: agent 0.129.0 → **0.130.0** + its sha. **Only the agent
fields changed.**
- **`min_agent` left at 0.129.0** — it states what the **golden controller** needs. Raising it to
0.130.0 would have made the hub **HOLD the floor** for every box below 0.130.0, which is the
opposite of shipping a fix.
- **Global floor never touched** (0.216.0). On hub v0.106.0 it is a *separate form with its own
action*, so publish-train rule 2's "save the floor last" hazard no longer exists in the shape its
incident describes — the rule's reasoning holds, its mechanism has moved.
- After: no `floor held`, no `*_unreachable`, both boxes reporting 0.130.0, artifact downloading
anonymously at the vouched sha.
**No `--no-verify` in the train.** The heading was flipped to `## v0.130.0` only after tag and package
existed. Flipping first and bypassing would have produced a red CI run and an alarm mail for a release
that worked — R-168's failure mode.
## 11c. Two findings from the release
**R-349 — the fleet was running a different binary under the same version name.** The proof deploy was
a hand build; the release builds `-trimpath -buildvcs=false`. Same source, same version string,
different bytes (`256e0829…` vs `a56a92a7…`). **Self-update could never have corrected it** — the boxes
already reported 0.130.0, so the vouched version looked installed. Every version check in the system
compares the *string*. Fixed by installing the **downloaded** artifact on both. The proper fix already
exists in miniature: `wrapper_sha256` does exactly this drift detection for the PBS wrapper and was
never extended to the agent's own binary.
**R-350 — I printed the hub password into the transcript.** Confirming the vouch used
`curl -w '%{redirect_url}'`; the hub answers 303 and curl re-attaches the basic-auth credential to the
redirect target it prints. **Not in git, not in any committed file** (checked by content), not in the
evidence directory — it is in the session transcript on DooPlex. Every other call printed only the
length; this came through curl's own formatting. **Rotation is your call** — I did not do it
unilaterally, and I can do it file-to-file without printing the new value if you want. The reusable
half: `%{redirect_url}`, `-v` and `--libcurl` all re-render a basic-auth credential.
## 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.