910fd91124
gates / gates (push) Successful in 14s
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.
247 lines
14 KiB
Markdown
247 lines
14 KiB
Markdown
# 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.
|