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

14 KiB
Raw Blame History

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.