diff --git a/REPORT.md b/REPORT.md index aab3c2e..1f3bdfe 100644 --- a/REPORT.md +++ b/REPORT.md @@ -1,353 +1,119 @@ -# REPORT — the third near-homograph, a machine told to be quiet, and a picture you can query (2026-08-13, late) +# REPORT — a listening socket that served nobody (2026-08-18, early) -**Shipped: hub v0.105.0, deployed and verified.** All three parts complete; **nothing dropped**. -**`demo-hp` was not touched** — see §8. No controller change, no agent change, no wire change, so no -bake and no approval. +**Trigger:** two `whole_guest_backup_failed` alert mails, 04:30 and 04:32 CEST. +**Outcome:** root cause found on **ep0**, fixed, both missed backups re-driven and landed. +**No repo code changed** — this was an operational run. Documentation, register and evidence only. --- -## 1. Part 1 — the enumeration, the name, and the reasoning +## 1. What was wrong -**Enumerated before editing. Five customer-facing sites, all in the hub:** +Both alerts were the same incident and neither was on a customer box. `demo-felhom` and `demo-hp` +each failed their `felhom-pbs` tier with `Can't connect to 10.77.0.1:8007 (Connection timed out)` — +the one thing they share, the Hetzner offsite PBS endpoint. -| `file:line` | what it is | -|---|---| -| `hub/internal/web/selfbind.go:255` | the binding page's lead sentence | -| `hub/internal/web/selfbind.go:256` | the failure banner (said „a jelszót" — generic, but naming the secret) | -| `hub/internal/web/selfbind.go:261` | the field label — „Visszaállító jelszó" | -| `hub/internal/web/selfbind.go:263` | the hint under the field | -| `hub/internal/notify/templates.go:331` | the self-bind e-mail, item 2 | - -**No halt. The name appears nowhere in `felhom-controller` or `felhom-agent`** — the only hits there -are comments and a test asserting the *already-retired* „Visszaállító **kód**" is absent, which is a -different secret. Operator surfaces call it *"Retrieval Password"* in English and the installer uses -`FELHOM_RETRIEVAL_PASSPHRASE` as a shell identifier; neither is customer copy and neither was touched. - -### The name: **„Tulajdonosi jelmondat"** - -Checked against the table rather than against a habit. The phrase **proves the account owns the box -being bound — it restores nothing, so the old name was simply false.** - -**Both of your suggestions are rejected, and the reasons are the argument:** - -- **„Fiókjelszó" is worse than the trap it fixes.** There *is* an account password — the dashboard - login. This name would collide with a **different real secret**, trading one homograph for a worse - one. -- **„Összekötési jelszó" recreates the trap structurally.** The other factor on this very page and in - the same mail is the **„Párosító kód"** (`selfbind.go:258`, `templates.go:330`). Naming this one - after the same act would leave the two factors a customer types **in one sitting** separated only by - *kód*-versus-*jelszó* — which is precisely the „Visszaállító kód"/„Visszaállító jelszó" shape being - removed. It matches the page's verb, and that is exactly the problem. - -**„Tulajdonosi jelmondat" is distinct on BOTH axes:** - -| | stem | noun | -|---|---|---| -| „**Beállító** kód" | Beállító | kód | -| „**Helyreállítási** kód" | Helyreállítási | kód | -| „**Párosító** kód" (the other factor) | Párosító | kód | -| „**Tulajdonosi** jelmondat" | **Tulajdonosi** | **jelmondat** | - -*If a plainer noun is ever wanted, „Tulajdonosi jelszó" is a one-word change — the **stem** is what -carries the separation.* - -### As shipped, bytes confirmed - -| string | hex | -|---|---| -| `Tulajdonosi jelmondat` | `54756c616a646f6e6f7369206a656c6d6f6e646174` | -| `tulajdonosi jelmondatodat` | `74756c616a646f6e6f7369206a656c6d6f6e6461746f646174` | -| `tulajdonosi jelmondatot` | `74756c616a646f6e6f7369206a656c6d6f6e6461746f74` | -| `Ez igazolja, hogy a fiók a tiéd` | `457a206967617a6f6c6a612c20686f67792061206669c3b36b2061207469c3a964` | - -Mojibake check clean in both files. **Naming only:** the form field is still `name="passphrase"`, and -`TestSelfBindPassphrase_StillAcceptedAfterTheRename` drives the real handler with the same messy human -spacing (`" Alpha Beta gamma-delta epsilon "`) and asserts the appliance still binds. The whole -pre-existing self-bind suite (A, B, C1, C4, D, E, F, mint × 2) stayed green. - ---- - -## 2. Does any customer-facing document name the old phrase? **No.** - -Checked: `documentation/pilot/PETI-tester-agreement.md` does not mention the phrase **at all**; -`RUNBOOK-onboarding-draft-v4.md` and `RUNBOOK-byo-deployment.md` name it by its **English operator** -name ("retrieval passphrase"). The ISO/installer references are shell identifiers. - -**So nothing printed is stranded.** The one honest caveat: the phrase reaches a customer -**out-of-band** — `RUNBOOK-byo-deployment.md:11`, *"delivered to the box owner over a secure channel"* -— so the only stale copy of the old name is whatever was said in a message or on the telephone. A -person holding such a message would see „Tulajdonosi jelmondat" on the page, be told *"az öt szóból -álló kifejezés, amelyet a beállításkor kaptál"*, and be holding exactly that: **the description -identifies the thing even where the name has moved.** That was the reason for keeping the hint -sentence and extending it with *"Ez igazolja, hogy a fiók a tiéd."* - ---- - -## 3. Part 1b — the hub guard, and the control that found a bug in itself - -`scripts/hub_copy_gate.py`, registered as gate 9 in `repo_gates.py`. **Two checks, deliberately -different:** - -1. **Retired names — banned outright**, across **all 95** hub `.go`/`.html` files, no allowlist. A - name a different secret now owns is never correct anywhere. Comments are stripped, because the - register rows and the code comments that record these decisions must quote the retired names. -2. **Retrieval stems — registered, not banned**, in four declared customer surfaces - (`notify/templates.go`, `web/selfbind.go`, `api/handler.go`, `notify/dispatcher.go`). A missing - declared surface is a **FAILURE, never a skip**. The allowlist is **empty, and that is a - measurement**: the hub makes no retrieval promise today. - -### plant → convict → remove → pass +On ep0, `proxmox-backup-proxy` was `active`, held its listening socket, and **served nobody**: ``` -hub-copy gate SELFTEST - 1. clean tree : 0 conviction(s) OK - 2. planted „visszaállító jelszavadat”: CONVICTED (isszaállító jelsz) OK - 3. same phrase inside a comment : not convicted OK - 4. planting removed : 0 conviction(s) OK -hub-copy gate selftest OK — the guard has been watched catching, ignoring and releasing +ss -lnt '( sport = :8007 )' → LISTEN Recv-Q 1025 Send-Q 1024 +ls /proc//fd | wc -l → 1024 # == its soft RLIMIT_NOFILE ``` -**The control found a defect in its own instrument on the first run.** Step 3 convicted a comment, -because the synthetic source was named `` and comment-stripping keys off the `.go` -extension. **The bug was in the guard, and the control is what found it** — which is the entire -argument for insisting a guard be watched working. +`Send-Q` on a listener is the accept backlog; `Recv-Q` is the queue depth. At 1025 against 1024 the +queue had overflowed, because `accept()` was returning `EMFILE` on every call. **1016 of the 1024 +descriptors were sockets and 547 connections sat in `CLOSE-WAIT`** — a connection leak, fed by +~85,000 requests/day, that reached the ceiling after 14 days of uptime. Last request served: +2026-08-17 18:15:32 UTC. Offsite DR was therefore down **≈ 9 h 37 m**. -### One list, not two — and the gap is instrumented rather than hidden +**The observation that settled it:** the daemon was wedged from its own loopback too — +`curl https://127.0.0.1:8007/` on ep0 timed out. A listener that cannot serve `127.0.0.1` has no +network left to blame, and that check is cheap enough to make early. -Both lists live in **`scripts/customer_copy_vocab.py`**, the same shared-gate home -(`reuse_refs_check.py`, `instructions_gate.py`) that both repos already consume without copying. +Full record, including everything that was ruled out first (tunnel, nftables, disk, dead daemon): +**`documentation/audits/INCIDENT-ep0-pbs-fd-exhaustion-2026-08-18.md`**. -**`retrieval_promise_gate.py` has NOT adopted it**, because the end state forbade touching -`felhom-controller` tonight. So rather than ship two copies that drift, **this gate reads the -controller gate's `STEMS` and fails if they disagree** — watched failing: +## 2. What was done -``` -DRIFT: the controller gate's STEMS have diverged from customer_copy_vocab.py - controller : ['visszaállíthat', 'visszaszerezhet', 'visszahozhat', 'visszanyit'] - shared : ['visszaállíthat', 'visszaszerezhet', 'visszahozhat'] -HUB-COPY GATE FAILED: the shared vocabulary is no longer shared. +1. `LimitNOFILE=65536` drop-ins for `proxmox-backup-proxy.service` and `proxmox-backup.service`, each + carrying its reason inline. **The API daemon was not implicated** (15 fds) and its drop-in says so + — a later reader must not mistake it for a second culprit. +2. Restarted both. After: soft limit 65536, fds back to 18, `Recv-Q 0`, loopback `200`. +3. **Verified from the customer side, not only from ep0** — both boxes got `200` in ~0.1 s and + `pvesm status` read `felhom-pbs pbs active`. +4. Re-drove the missed backups **through the product path** — `POST /backup?target=felhom-pbs` on + each agent's local API, issued from inside the guest's controller container with the controller's + own credentials, i.e. the same call the scheduler makes. Not a hand-run `vzdump`. + +**Result:** `demo-felhom` → `ct/9201/2026-08-18T03:57:43Z` (4.10 GB, 36.4 s); +`demo-hp` → `ct/9201/2026-08-18T03:58:43Z` (4.29 GB, 41.5 s). Both directories carry a full manifest +on ep0, and both hosts log the re-run vzdump as `OK`. **And the hub agrees** — both boxes' next host +reports carry `felhom-pbs success=true` (04:00:33Z and 04:07:35Z), so the operator view went green on +the evidence rather than on the fact that a restart was performed. +**No data was lost and no backup was skipped** — the daily local +tier was never affected (it completed on both boxes at 05:00 and 05:02), and the PBS tier is weekly, +so the outage window cost exactly one attempt, which was re-driven the same morning. + +Evidence copied off ep0 **before** the restart, per standing rule 5: +`documentation/audits/evidence-ep0-fd-2026-08-18/` — pre-restart state, post-fix state, access-log tail. + +## 3. What I got wrong, and corrected + +- **`proxmox-backup-manager version` prints *available* then *running*.** It read + `4.2.5-1 running version: 4.2.2`, which looks exactly like a daemon left behind by a package + upgrade. It is not: `dpkg -l` shows **4.2.2-1 installed**, 4.2.5-1 merely available in the repo, + and the on-disk binary is dated 2026-06-18. I restarted the API daemon on that mistaken reading; + harmless, and its drop-in is a genuine improvement, but it was not needed. +- **I addressed `demo-hp`'s agent at the island address** because `operations/nodes.md` says that box + is island-migrated. It is not (**R-338**), and the resulting timeout was briefly read as a fault. + +## 4. Findings filed — R-336, R-337, R-338 + +All three are in `documentation/backlog/OPEN-ITEMS.md` with numbers, per the registers-first rule. + +- **R-336 — the poll rate is the real defect.** ~1 request/second against a DR endpoint written to + weekly. `LimitNOFILE` raises the ceiling; **it does not fix the leak**, it converts a fortnightly + outage into a multi-year one. +- **R-337 — a status endpoint that trailed its own artifact, then caught up. WATCHING, not a defect.** + `demo-hp`'s `/backup/status` was still serving the superseded 03:27:00Z failure at ~04:03Z while the + snapshot sat on ep0 and the host logged `OK`; `demo-felhom` updated within ~40 s. **I filed this as + a defect and that was premature** — the next host report (04:07:35Z) carried the success and the + skew cleared with no intervention. Rewritten as WATCHING, with the explicit instruction not to open + a fix until someone establishes whether this is just collection cadence. Recorded at all because + during the recovery it read as a second failure, and it was not one. +- **R-338 — `demo-hp` is not on the R-50 island and `nodes.md` says it is.** No `island_bridge` keys, + guest has no `eth1`, `vmbr9` has zero members, and the agent's local API is bound to the customer + LAN — the exposure R-50 existed to remove. + +**Not done, deliberately:** PBS 4.2.5-1 was not applied. Upgrading a production offsite endpoint was +outside what this run was authorised to do, and its changelog should be read for the connection- +handling leak first. + +## 5. Gates — one pre-existing conviction, and a stated bypass + +`python3 scripts/repo_gates.py --fast` → **rc=1, CONVICTED: golden-currency.** Eight of nine gates +pass. The conviction is **R-334, inherited and not caused here**: newest released controller +**0.216.0**, newest golden bake **0.214.0**, so a new install misses two releases. The gate reads +`felhom-controller/CHANGELOG.md` and `documentation/tests/golden-*` — **this session touched +neither**, and its whole diff is documentation. Baking is possible; **vouching is +operator-password-gated, and a baked-but-unvouched golden is worse than none**, so it is not a +one-sided job CC can finish. + +**This push therefore used `git push --no-verify`, stated here per `.claude/rules/gates.md`.** +R-334 is updated in the register with the new numbers rather than left reading 0.215.0. + +*(Noted for accuracy: the first gate run was piped to `tail`, which returned `rc=0` — `tail`'s exit +code, not the gate's. It was re-run unpiped to read the real `rc=1`. That is standing rule 1's trap +in its smaller form, and the number reported above is the unpiped one.)* + +## 6. What to watch + +The positive observable is the descriptor count, not the absence of an alert — an empty alert queue +is equally consistent with "healthy" and "wedged again": + +```bash +ssh root@ 'PID=$(systemctl show proxmox-backup-proxy -p MainPID --value); \ + ls /proc/$PID/fd | wc -l; ss -lnt "( sport = :8007 )"' ``` -…and green again when restored. An **absent** sibling clone is **INCONCLUSIVE (exit 2), never a pass** -— the G-1 lesson. **This is a scaffold, not the destination: R-325** is the few-line felhom-controller -change that makes it import the shared list and delete both its literal and this drift check. - ---- - -## 4. Part 2 — the four scenarios, the clock, and the red-proofs - -**Re-established at `file:line`, not taken from the prompt.** The chain end to end: controller -`cmd/controller/main.go:1253` sets `Health.Status = "disabled"` in the final minimal report → hub -`store.go:953-955,968-975` parses `health.status` into `reports.health_status` → -`CustomerSummary.HealthStatus` (`store.go:40`) carries it into `GetCustomers()` → -`web/rollup.go:25` renders `disabled` → **`monitor/staleness.go` ignored it and measured age alone.** - -**The halt condition did not fire:** the discriminator is the box's **own last word**, present in the -data this checker already reads. That is not a guess. - -### It was TWO doors, not one - -Because the state is **recorded** (`StateDisabled`) rather than **deleted** (as the `blocked` -precedent does), `CheckBackupDeadlines` can skip it too. A deleted state returns `""` from `GetState`, -and `""` is not `"down"` — so that check would have gone on e-mailing `expected_backup_missed` every -morning about the same machine. **R-195's shape returning through a second door**, and it is closed -with the first. Recording the state also satisfies the visibility requirement: quiet-on-purpose and -quiet-by-accident no longer look identical. - -### The re-enablement judgement - -**The clock runs from the report the hub can actually see.** For a box that reports on re-enabling, -that report *is* the re-enablement, so the clock starts there — your recommendation, and the mechanism -already had this shape. Timing from the last report *before* the switch-off would fire an instant -stale/down for a quiet period we asked for: a false alarm produced by fixing false alarms. Leaving -`disabled` re-enters the **same branch as a new customer**, so no `node_recovered` fires for an outage -that never happened. `downtimeStart` is cleared **on entry**, so a later genuine outage cannot compute -its duration from a clock that started before the silence was requested. - -**LIMIT, stated rather than hidden:** a box re-enabled that then **fails to report at all** keeps being -suppressed — the hub sees only that final `disabled` report, and its view changes only when a report -arrives. It cannot distinguish that from *still switched off*. **This is exactly why the state is made -visible:** an operator who re-enabled a box and still sees `disabled` is being told it has not come back. - -### Scenarios - -| | outcome | verified | -|---|---|---| -| **A** deliberately silent for days | no stale, no down, no e-mail; state visibly `disabled` | `TestStaleness_A` — observed healthy **first**, then switched off, then three passes | -| **B** simply stopped reporting | unchanged: stale then down, exactly as today | `TestStaleness_B` — state `down`, events emitted | -| **C** re-enabled, reports promptly | clean transition, **no** recovery event | `TestStaleness_C` — zero events, state `ok` | -| **D** re-enabled then genuinely quiet | stale and down fire normally, timed from re-enablement | `TestStaleness_D` — state `down`, events emitted | - -Plus `TestStaleness_DisabledIsAlsoSkippedByTheDeadlineCheck` for the second door. - -### Red-proofs — every mutation asserted applied by grep, and reverted after - -| # | Mutation | Asserted applied | Outcome | -|---|---|---|---| -| **1** *(the one that matters)* | suppression made **unconditional** (`if true \|\| …`) | `staleness.go:132` grep | **RED — B**: *"a genuinely silent machine is `"disabled"`, want `"down"` — a real alarm was swallowed"*. **A genuinely dead machine was seen NOT alarming.** C and D also red | -| **2** | suppression **removed** (`if false && …`) | `staleness.go:132` grep | **RED — A**: *"a deliberately-disabled machine emitted `[node_down]` — three days quiet BY REQUEST"*. Today's false alarm, reproduced verbatim | -| **3** | state made **sticky** — remembered instead of re-read from the box, so the clock never leaves the pre-disable report | `staleness.go:132` grep | **RED — D**: *"a once-disabled machine was silenced for ever"*. C also red | - -**A weakness in my own tests was found by red-proof 2 and fixed.** Scenario A originally seeded the -customer *already* disabled — and the checker's new-customer branch sets the first state without an -event, so **the test passed on its state assertion alone even with the suppression deleted.** It now -observes the machine healthy first, and the same mutation then fails on the **event**. A test that -cannot see the alarm it exists to prevent is not a test. - ---- - -## 5. Part 3 — the real counts, and the number that was wrong - -**Yes, a number I have been repeating is wrong.** - -``` -where felhom stands — 55 claims, verified_on 2026-08-09 - walked 23 - partial 14 (6 cite evidence, 8 prose only) - built 14 (0 cite evidence, 14 prose only) - missing 4 (0 cite evidence, 4 prose only) - NOT WALKED: 32 of 55 -``` - -**"Nine" is real, and it answers a different question: it is the count of claims carrying -`verdict: downgraded`** — the ones the 2026-08-09 verification pass **lowered**. That is "re-judged", -not "unproven". **Yesterday's session was right to refuse to guess**, and this is what it could not -have found without counting. - -The sharper cut is the evidence one: **all 23 walked claims cite an evidence document** (`check_stands.py` -convicts a `walked` claim without one), while of the **32** that are not walked, **only 6 cite evidence -and 26 are prose only**. - ---- - -## 6. The command, and its output - -``` -$ python3 scripts/unproven.py --summary -where felhom stands — 55 claims, verified_on 2026-08-09 - walked 23 - partial 14 (6 cite evidence, 8 prose only) - built 14 (0 cite evidence, 14 prose only) - missing 4 (0 cite evidence, 4 prose only) - NOT WALKED: 32 of 55 -``` - -Without `--summary` it prints every not-walked claim with its id, band, verdict and whether it cites -evidence, grouped `partial → built → missing`. It reads the dataset **only** — opens no evidence, -judges nothing, contacts no machine. An unrecognised status prints with a `⚠ status not known to this -script` marker rather than being silently dropped. - -**Wired into the end-of-session checklist** in `felhom.eu/CLAUDE.md`, with the instruction to say in -the report if a number moved. - -**Its first run found a stale claim** — `claim.code-naming` is still `partial` and its title still -describes the defect R-295 and R-323 have now closed twice over. **I did not move it**, because the -dataset's own header forbids it: *"A status may not be RAISED here — the MAP changes first and this -file follows it."* Filed as **R-327**, with the honest difficulty noted: no customer has typed -„Tulajdonosi jelmondat" yet, so `walked` would be an over-claim. - -**The capability map is deliberately NOT restructured** — recorded in R-326 so it does not read as -forgotten. - ---- - -## 7. Versions, manifest, CI - -| | | -|---|---| -| **Shipped** | **hub v0.105.0** (`gitea.dooplex.hu/admin/felhom-hub:0.105.0`) | -| **Unchanged** | controller **0.214.0**, agent **0.129.0**, installer **1.28.0**, golden 0.214.0, floor 0.214.0, MinAgent 0.129.0 | -| **Commits** | `b03a105` the work · `bbd59f4` the manifest bump | -| **Manifest** | `manifests/hub.yaml:128` → `0.105.0`, GitOps only — **no `kubectl set image`** | -| **Deploy** | ArgoCD hard-refresh + sync → **Synced / Healthy**; pod `hub-5ff87b556b-bvtvt` **1/1 Running**; deployment image confirmed `0.105.0` | -| **CI, by run ID** | run **336** (`b03a105375`) **success** · run **337** (`bbd59f4a44`) **success** | -| **Gates** | `repo_gates.py --fast` — all **9** OK (the new `hub-copy` included), and again in the pre-push hook on both pushes. **No `--no-verify`** | -| **Green gate** | `hub/`: build rc=0, vet rc=0, **test rc=0 across 18 packages**, run separately from every commit | - -**Live verification of the running artifact**, ASCII-only patterns against -`/usr/local/bin/felhom-hub` in the running pod: - -``` -Tulajdonosi jelmondat 1 ← the field label -tulajdonosi jelmondatodat 2 ← the page lead + the mail -jelszavadat 0 ← the retired possessive is GONE -``` - -The negative control is the point: the old copy is **absent**, not merely accompanied. - -**Method, stated: this proves the deployed artifact carries the new copy — it is not a rendering.** -Rendering the binding page requires minting a self-bind token, which mints a capability URL and sends -an e-mail against a real customer record; with `demo-hp` being re-deployed tonight I would not do that -to any customer row. The *rendering* is covered by `TestSelfBind_ThirdSecretNaming` and -`TestSelfBind_FailureBannerUsesTheSameName`, which drive the real handler through `ServeHTTP`. - -**Part 2 has no live observable tonight, and I will not manufacture one.** No machine is in the -disabled state, and producing one would mean switching a real box's reporting off — precisely the kind -of thing that must not happen to a fleet of two on the evening one of them is being re-deployed. The -fix is proven by four scenarios and three red-proofs and is **latent until a box is actually disabled**. - ---- - -## 8. `demo-hp` was not touched - -**No `ssh`, no `pct`, no controller call, no agent call, no hub write of any kind** was issued against -`demo-hp` or its records this session. Everything done here was in the `felhom.eu` repo, the hub image -and the hub deployment. - -Confirmed read-only, via the hub's own hosts page (`GET /hosts`, HTTP 200): - -``` -demo-hp-bb76ea ONLINE -demo-felhom-8363b5 ONLINE -drill-r50-0a4f9a DOWN (reverted to `virgin`, powered off — expected) -``` - -`demo-hp` is **online and reporting normally**, exactly as it was found. **`felhom-agent` and -`felhom-controller` are byte-unchanged** — neither repo was written to. - ---- - -## 9. Register - -**Ceiling moved R-322 → R-327** (grepped before minting). - -| Row | State | -|---|---| -| **R-323** third near-homograph → „Tulajdonosi jelmondat" | **CLOSED — shipped** | -| **R-324** the hub's customer copy under a guard | **CLOSED — shipped, selftest green** | -| **R-325** controller gate should import the shared vocabulary | **READY (S)** — the drift check is the scaffold | -| **R-326** "what is unproven" made queryable | **CLOSED — shipped** | -| **R-327** the picture still describes a fixed defect | **READY (S)** — map moves first | -| **R-321** a disabled machine alarmed as dead | **CLOSED — both doors** | -| **R-322** the guard had never scanned the hub | **CLOSED by R-324** | - ---- - -## 10. What was dropped, and observations - -**Nothing was dropped.** Part 1, Part 1b, Part 2 and Part 3 are all complete. Part 3 was the -designated first drop and was not needed. - -### Observations — noticed, not acted on - -- **I nearly published a false negative about my own deploy.** The first grep of the running binary - used accented patterns through `kubectl exec → sh -c` and returned **0 for every string, including - ones that are certainly present** — which reads exactly like "the rename did not deploy". The - standing rule (*never let an accented pattern gate a conclusion*) is what caught it; the ASCII-only - re-run gave the real answer. **The rule earns its place again, in a chain it was not written for** — - it was written for `ssh → pct exec`, and `kubectl exec` mangles identically. -- **The `blocked` branch does not clear `downtimeStart`.** The new `disabled` branch does. So a - customer that is blocked, later unblocked and later still goes down will compute its downtime from a - clock that started before the block. Small, pre-existing, and not changed under a row about - something else. -- **`gofmt -l internal/` lists 22 pre-existing unformatted files** in the hub, none of them touched by - this session. Worth one cleanup commit by someone, sometime — it makes `gofmt -l` useless as a - check, which is how a real formatting problem would hide. -- **The empty allowlist in the new gate is load-bearing and fragile in one direction.** It is empty - because the hub genuinely makes no retrieval promise. The moment someone adds one legitimately, they - must register it — and the gate's failure message says so, but nobody reads a failure message until - they hit it. -- **`unproven.py` shows 26 of 32 not-walked claims are prose only.** That is not a defect per claim — - a `missing` claim has nothing to cite — but **14 of 14 `built` claims cite no evidence at all**, and - "built" is the status that most invites being read as "done". Worth a look when the capability-map - session happens. +Healthy is ~20 fds and `Recv-Q 0`. **A count climbing between restarts means R-336's leak is still +live.** diff --git a/STATUS.md b/STATUS.md index ccecd63..97a42e4 100644 --- a/STATUS.md +++ b/STATUS.md @@ -1,6 +1,7 @@ # STATUS — what works, what's broken, what's next -**Updated 2026-08-13 (late — the third name, a machine told to be quiet, and a picture you can query).** +**Updated 2026-08-18 (early — a listening socket that served nobody; off-site backups were down for +9½ hours overnight and are back).** > **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.** @@ -42,6 +43,16 @@ record with no machine** — created 13 August, no host, no backups, nothing to ## Shipped +- **Last night's two backup alarms were real, and are fixed** (R-336). Both machines failed their + off-site backup at 04:30; **neither machine was at fault**. The off-site box in Germany had run out + of one internal resource and, while looking perfectly healthy from outside, was accepting no + connections at all — for 9½ hours. Restarted, given a ceiling 64× higher, and **both missed backups + were re-run the same morning and are on the off-site box**. **Nothing was lost and nothing was + skipped:** the daily copies on the machines themselves were never affected, and the off-site copy is + weekly, so exactly one attempt fell in the window. The underlying cause — we ask that box a question + about once a second, all day — is filed and **not yet fixed**; the raised ceiling buys years, not a + cure. + - **The removal now genuinely reverses the installation** (R-316, `installer-v1.28.0` published). The second reinstall used to hit our own leftover; it was watched failing on the cycle that actually fails, then watched passing. @@ -71,6 +82,22 @@ record with no machine** — created 13 August, no host, no backups, nothing to ## Broken, or knowingly incomplete +- **We interrogate the off-site box about once a second** (R-336). Roughly 85,000 questions a day, + for a box we actually write to once a week. That volume is what turned a slow internal leak into + last night's outage in a fortnight. The higher ceiling makes it rare, not impossible — **the leak + itself is untouched.** The honest health check is the resource count climbing, not the absence of an + alarm. +- **One machine's status took several minutes to admit a backup had worked** (R-337). `demo-hp` was + still showing this morning's failure for four minutes after the copy was safely on the off-site box; + `demo-felhom` updated in under a minute. **It corrected itself** and both machines now read + correctly, so this is a note to watch, **not something broken** — but during the repair it looked + briefly like a second fault, which is the reason it is written down. +- **`demo-hp` is not set up the way our own notes say it is** (R-338). Our inventory records both + machines as moved onto the isolated internal link last July. `demo-felhom` was; **`demo-hp` was + not** — its control channel is still bound to the ordinary home network, which is exactly what that + change existed to stop. The machine works; the page is wrong, and it misled this session by an hour. + Your call which one to correct. + - **Peti's machine has no recovery route at all** — see the `PETI` row. **This is a real machine belonging to a real person**, not one of ours and not a record: it reported to the hub for four and a half months and has been silent since 15 July, when its host record was deleted. There is no key, no diff --git a/documentation/audits/INCIDENT-ep0-pbs-fd-exhaustion-2026-08-18.md b/documentation/audits/INCIDENT-ep0-pbs-fd-exhaustion-2026-08-18.md new file mode 100644 index 0000000..66a190d --- /dev/null +++ b/documentation/audits/INCIDENT-ep0-pbs-fd-exhaustion-2026-08-18.md @@ -0,0 +1,168 @@ +# INCIDENT — ep0's PBS proxy ran out of file descriptors, 2026-08-18 + +**Detected by:** the two `whole_guest_backup_failed` alert mails (04:30 and 04:32 CEST). +**Resolved:** 05:52 CEST (proxy restart) / 05:59 CEST (both re-run backups landed). +**Offsite DR unavailable:** 2026-08-17 20:15 CEST → 2026-08-18 05:52 CEST, ≈ 9 h 37 m. +**Data lost:** none. **Backups missed:** none — the weekly offsite run was re-driven the same morning. +**Evidence:** `evidence-ep0-fd-2026-08-18/` (pre-restart and post-fix state, access-log tail). + +## What the operator saw + +Two mails, both `severity: error`, one per box: + +| time (CEST) | customer | event | tier | +|---|---|---|---| +| 04:30 | `demo-felhom` | `whole_guest_backup_failed` | `felhom-pbs` | +| 04:32 | `demo-hp` | `whole_guest_backup_failed` | `felhom-pbs` | + +Both carried the same underlying error: + +``` +could not activate storage 'felhom-pbs': felhom-pbs: error fetching datastores + - 500 Can't connect to 10.77.0.1:8007 (Connection timed out) +``` + +Two customers, two hosts, one error — so the fault was never on the customer boxes. It was on the +single thing they share: **ep0**, the Hetzner offsite PBS endpoint at `10.77.0.1` over `wg-felhom`. + +## What it was NOT + +Ruled out before touching anything, because each of these is the obvious suspect for a timeout and +each was innocent: + +- **Not the tunnel.** WireGuard was up on both boxes with handshakes seconds old; ep0's `wg show` + listed both peers live. ICMP to `10.77.0.1` answered in ~33 ms from `felhom-pve`. +- **Not the firewall.** ep0's `inet filter input` chain carries `tcp dport 8007 iifname "wg0" accept` + and it was in force. +- **Not a dead daemon.** `proxmox-backup-proxy` was `active (running)`, and `ss -lntp` showed it + holding the listening socket on `*:8007`. +- **Not disk.** `/mnt/pbs-datastore` was 3.4 G used of 98 G; no D-state processes; no I/O errors. +- **Not a stale binary.** `proxmox-backup-manager version` prints *available* then *running*, and it + read `proxmox-backup-server 4.2.5-1 running version: 4.2.2`. That looks exactly like a daemon left + behind by a package upgrade — **it is not.** `dpkg -l` shows `4.2.2-1` **installed**; 4.2.5-1 is + merely available in the repo, and the proxy binary on disk is dated 2026-06-18, matching 4.2.2. + Restarting the daemons did not (and could not) change that string. + +## Root cause — `accept()` returning `EMFILE` + +The proxy was listening and never accepting. Three numbers say it: + +``` +ss -lnt '( sport = :8007 )' → LISTEN Recv-Q 1025 Send-Q 1024 *:8007 +ls /proc//fd | wc -l → 1024 +grep 'open files' /proc//limits → soft 1024 / hard 524288 +``` + +`Send-Q` on a listening socket is the accept **backlog**; `Recv-Q` is how many completed connections +are waiting in it. At 1025 the queue had overflowed a 1024-deep backlog. The process held exactly +1024 file descriptors — its soft `RLIMIT_NOFILE`. Every `accept()` was failing with `EMFILE`, so +connections completed their handshake, queued, and timed out. The daemon looked healthy from the +outside and served nobody. + +**It was wedged from its own loopback too** — `curl https://127.0.0.1:8007/` on ep0 timed out. That +is the observation that moves this from "a network problem" to "a process problem", and it is worth +reaching for early: a listener that cannot serve `127.0.0.1` has no network left to blame. + +### Why the descriptors ran out + +Of the 1024 fds, **1016 were sockets**, and **547 connections sat in `CLOSE-WAIT`** with unread data +(`Recv-Q 1543`). `CLOSE-WAIT` means the peer closed and the local application never called `close()` +— accumulated, unreleased connections. That is a leak, and it was fed by an unreasonable request +volume: + +- **~85,000 requests/day**, a flat **3,538/hour** — a request roughly every second, all day. +- `74,445 GET /api2/json/admin/datastore` (`libwww-perl` — PVE's `pvestatd`) +- `73,171 GET /api2/json/admin/datastore/felhom-offsite/status` (`proxmox-backup-client`) +- everything else — snapshots, version, verify — is under 2,000 combined. + +Fourteen days of that (ep0 last booted 2026-08-03) walked the fd count to the 1024 ceiling. The last +request the proxy ever served was **2026-08-17 18:15:32 UTC**. The scattered HTTP `400`s that begin +at 17:34 UTC are the exhaustion setting in, not its cause. + +**So it is a three-part failure, and all three parts have to be named:** a leak in the proxy's +connection handling, a poll rate high enough to make that leak reach a limit in a fortnight, and a +soft limit of 1024 that no drop-in had ever raised. + +## The fix + +1. **`LimitNOFILE=65536`** drop-ins for `proxmox-backup-proxy.service` **and** `proxmox-backup.service` + (`/etc/systemd/system/.d/20-nofile.conf`), each carrying the reason in a comment. + The API daemon held only 15 fds and was **not** implicated — its limit was raised for symmetry, and + the drop-in says so, so a later reader does not mistake it for a second culprit. +2. **Restarted both daemons.** Verified after: soft limit `65536`, fd count back to 18, + `Recv-Q 0`, `curl https://127.0.0.1:8007/ → 200`. +3. **Verified from the customer side, not just from ep0** — from both boxes, `https://10.77.0.1:8007/` + returned **200 in ~0.1 s** and `pvesm status` showed `felhom-pbs pbs active`. +4. **Re-drove the missed backups through the product path**, not `vzdump` by hand: + `POST /backup?target=felhom-pbs` on each agent's local API, called from inside the guest's + controller container with the controller's own credentials — the same call the scheduler makes. + +## Result + +| box | snapshot | size | duration | +|---|---|---|---| +| `demo-felhom` | `ct/9201/2026-08-18T03:57:43Z` | 4.10 GB | 36.4 s | +| `demo-hp` | `ct/9201/2026-08-18T03:58:43Z` | 4.29 GB | 41.5 s | + +**The hub agrees, which is the check that actually closes this.** A snapshot on ep0 proves the write +landed; it does not prove the fleet's own picture recovered. Both boxes' next host reports carry +`felhom-pbs success=true` — `demo-felhom` at 04:00:33Z, `demo-hp` at 04:07:35Z — so the operator view +is green on the same evidence, not on a restart having been performed. + +Both snapshot directories carry a full manifest on ep0 (`index.json.blob`, `root.pxar.didx`, +`catalog.pcat1.didx`, `client.log.blob`, `pct.conf.blob`) — not a partial upload. Both hosts' own +`/var/log/pve/tasks/index` records the re-run vzdump as `OK`. + +**The daily local tier was never affected.** `felhom-backup` (dir) completed on both boxes this +morning — 05:00:17 on `demo-felhom` (1.49 GB), 05:02:00 on `demo-hp` (1.48 GB). The offsite PBS tier +is **weekly** (`cadence_seconds: 604800` vs 86400 for local), and its previous snapshots were +2026-08-11. **Today was the first weekly run to fall inside the outage window** — which is why a +9½-hour outage cost exactly one attempt and no coverage. + +## Findings filed + +- **R-336 — the offsite endpoint is polled ~1 request/second.** 85k requests/day from two boxes to a + DR endpoint is what converts a slow fd leak into a fortnightly outage. Two pollers duplicate the + same question (`admin/datastore` and `felhom-offsite/status`) at roughly the same rate. +- **R-337 — `/backup/status` trailed the completed backup by minutes on `demo-hp`, then caught up.** + The re-run landed on ep0 at 03:58:43Z with the host's task index reading `OK`, yet the controller's + status endpoint was still serving the 03:27:00Z failure at ~04:03Z; `demo-felhom` reflected its new + result within ~40 s. **It cleared without intervention** — demo-hp's 04:07:35Z host report carries + `felhom-pbs success=true`. **Filed as WATCHING, not as a defect**, and the distinction is the point: + during the recovery this looked like a second failure, and it was not one. See the note below. +- **R-338 — `demo-hp` is not on the R-50 island at all, and `operations/nodes.md` says it is.** + `nodes.md` records both boxes as island-migrated on 2026-07-25 (`local_api` on + `169.254.253.1:8443`/`vmbr9`, guest `eth1 169.254.253.2/30`). That is true of `felhom-pve` and + **false of `demo-hp`**, side by side in their own `agent.json`: + + | | `felhom-pve` | `demo-hp` | + |---|---|---| + | `listen_addr` | `169.254.253.1:8443` | **`192.168.0.87:8443`** (the LAN address) | + | `island_bridge` / `island_guest_addr` | present | **absent — the keys do not exist** | + | guest 9201 NICs | `net0` vmbr0 + **`net1` vmbr9** | **`net0` only** | + | `vmbr9` | carries the guest veth | **exists, zero members** | + + The controller's `controller.yaml` points at `192.168.0.87:8443`, so the product works — this is + drift in the inventory, not a broken box. But it has two costs. **A session that trusts the page + addresses the wrong endpoint** *(this one did, read the resulting timeout as a fault, and spent a + step on it)*. And more substantially, **the agent's local API is bound to the customer LAN on this + box** rather than to a point-to-point island — which is the exposure R-50 existed to remove. + Either migrate `demo-hp` or correct the page; leaving both as they are keeps a documented + security property that one of the two fleet boxes does not have. +- **PBS 4.2.5-1 is available and 4.2.2-1 is installed.** Not applied — upgrading a production offsite + endpoint was outside the scope authorised here. Worth checking its changelog for the connection- + handling leak before deciding. + +## What to watch + +The drop-in raises the ceiling; **it does not fix the leak.** At the observed rate the old limit was +reached in 14 days, so 65536 buys roughly 2.5 years at the same slope — but the slope is the defect. +The positive observable is the fd count itself, not the absence of an alert: + +```bash +ssh root@ 'PID=$(systemctl show proxmox-backup-proxy -p MainPID --value); \ + ls /proc/$PID/fd | wc -l; ss -lnt "( sport = :8007 )"' +``` + +A healthy proxy sits near 20 fds with `Recv-Q 0`. **A rising fd count between restarts confirms the +leak is still live** — an unchanging one after a poll-rate reduction would confirm the fix. diff --git a/documentation/audits/evidence-ep0-fd-2026-08-18/access.log.last200 b/documentation/audits/evidence-ep0-fd-2026-08-18/access.log.last200 new file mode 100644 index 0000000..14ed881 --- /dev/null +++ b/documentation/audits/evidence-ep0-fd-2026-08-18/access.log.last200 @@ -0,0 +1,200 @@ +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:08:50 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:08:52 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:08:53 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:08:55 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:08:56 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:08:56 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:08:57 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:09:02 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:09:05 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:09:06 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:09:07 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:09:10 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:09:12 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:09:12 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:09:15 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:09:22 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:09:25 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:09:26 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:09:27 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:09:30 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:09:32 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:09:33 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:09:34 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:09:35 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:09:36 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:09:37 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:09:42 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:09:46 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:09:50 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:09:52 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:09:52 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:09:54 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:09:55 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:09:55 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:09:56 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:09:56 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:09:56 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:09:57 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:10:02 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:10:05 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:10:06 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:10:07 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:10:10 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:10:12 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:10:13 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:10:16 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:10:22 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:10:25 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:10:26 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:10:27 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:10:30 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:10:32 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:10:32 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:10:34 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:10:35 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:10:36 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:10:37 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:10:42 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:10:45 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:10:50 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:10:52 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:10:53 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:10:55 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:10:55 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:10:56 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:10:57 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:11:02 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:11:06 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:11:06 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:11:07 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:11:10 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:11:12 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:11:12 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:11:15 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:11:22 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:11:25 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:11:26 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:11:27 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:11:30 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:11:32 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:11:33 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:11:34 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:11:34 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:11:35 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:11:35 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:11:36 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:11:36 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:11:37 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:11:42 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:11:45 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:11:50 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:11:52 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:11:52 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:11:55 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:11:55 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:11:56 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:11:57 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:12:02 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:12:05 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:12:06 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:12:07 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:12:10 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:12:12 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:12:13 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:12:15 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:12:22 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:12:26 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:12:26 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:12:27 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:12:30 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:12:32 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:12:32 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:12:34 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:12:35 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:12:36 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:12:37 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:12:42 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:12:45 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:12:50 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:12:52 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:12:52 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:12:55 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:12:56 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:12:56 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:12:57 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:13:02 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:13:05 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:13:06 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:13:07 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:13:10 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:13:12 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:13:12 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:13:15 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:13:22 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:13:25 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:13:26 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:13:27 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:13:30 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:13:32 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:13:32 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:13:34 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:13:35 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:13:36 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:13:37 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:13:42 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:13:46 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:13:50 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:13:52 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:13:52 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:13:55 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:13:55 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:13:56 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:13:57 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:14:02 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:14:05 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:14:06 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:14:07 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:14:10 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:14:12 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:14:12 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:14:16 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:14:23 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:14:25 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:14:26 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:14:27 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:14:30 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:14:32 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:14:32 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:14:34 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:14:35 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:14:36 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:14:37 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:14:42 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:14:45 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:14:50 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:14:52 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:14:52 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:14:54 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:14:55 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:14:55 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:14:56 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:14:56 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:14:56 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:14:57 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:15:03 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:15:05 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:15:06 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:15:07 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:15:10 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:15:12 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:15:12 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:15:15 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:15:22 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.3 - felhom@pbs!demo-hp [17/08/2026:18:15:25 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:15:26 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:15:27 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:15:30 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:15:31 +0000] "GET /api2/json/admin/datastore" 400 88 libwww-perl/6.78 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:15:32 +0000] "GET /api2/json/version" 200 92 Go-http-client/1.1 +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:15:32 +0000] "GET /api2/json/admin/datastore/felhom-offsite/snapshots?ns=demo-felhom" 400 27 Go-http-client/1.1 diff --git a/documentation/audits/evidence-ep0-fd-2026-08-18/post-fix-state.txt b/documentation/audits/evidence-ep0-fd-2026-08-18/post-fix-state.txt new file mode 100644 index 0000000..7429ce2 --- /dev/null +++ b/documentation/audits/evidence-ep0-fd-2026-08-18/post-fix-state.txt @@ -0,0 +1,28 @@ +### post-fix Tue Aug 18 04:00:41 UTC 2026 +proxy_pid=542065 fds=18 +Max open files 65536 65536 files +State Recv-Q Send-Q Local Address:Port Peer Address:Port +LISTEN 0 1024 *:8007 *:* + 1 ESTAB + 1 LISTEN +### snapshots +-- demo-felhom +2026-08-04T04:49:44Z +2026-08-11T04:54:07Z +2026-08-18T03:57:43Z +-- demo-hp +2026-08-04T19:24:16Z +2026-08-11T19:29:13Z +2026-08-18T03:58:43Z +### dropins +# 2026-08-18: proxy wedged after 14d uptime — accept() returned EMFILE at the +# systemd default soft limit of 1024 fds (1016 sockets, 547 in CLOSE-WAIT), +# the 1024-deep accept backlog overflowed, and every PBS client timed out. +# ~85k requests/day against this endpoint; 1024 is not a sane ceiling for it. +[Service] +LimitNOFILE=65536 +# 2026-08-18: raised alongside the proxy (see its 20-nofile.conf). This daemon +# was NOT the one that exhausted fds (it held 15), but the systemd default 1024 +# is not a sane ceiling for a PBS backend either. +[Service] +LimitNOFILE=65536 diff --git a/documentation/audits/evidence-ep0-fd-2026-08-18/pre-restart-state.txt b/documentation/audits/evidence-ep0-fd-2026-08-18/pre-restart-state.txt new file mode 100644 index 0000000..609660f --- /dev/null +++ b/documentation/audits/evidence-ep0-fd-2026-08-18/pre-restart-state.txt @@ -0,0 +1,28 @@ +### date +Tue Aug 18 03:54:48 UTC 2026 +### ss -lnt 8007 +State Recv-Q Send-Q Local Address:Port Peer Address:Port +LISTEN 1025 1024 *:8007 *:* +### socket states + 543 CLOSE-WAIT + 1011 ESTAB + 1 LISTEN +### fd count +1024 +### fd types + 1016 socket:anon + 3 anon_inode:anon + 1 0 + 1 /var/log/proxmox-backup/api/auth.log + 1 /var/log/proxmox-backup/api/access.log + 1 /var/lib/proxmox-backup/rrdb/rrd.journal-6a834fcb + 1 /mnt/pbs-datastore/.lock + 1 /dev/null +### limits +Max open files 1024 524288 files +### versions +proxmox-backup-server 4.2.5-1 running version: 4.2.2 +### uptime + 03:54:48 up 14 days, 16:41, 1 user, load average: 1.76, 1.88, 1.87 +### last served request +::ffff:10.77.0.2 - felhom@pbs!demo-felhom [17/08/2026:18:15:32 +0000] "GET /api2/json/admin/datastore/felhom-offsite/snapshots?ns=demo-felhom" 400 27 Go-http-client/1.1 diff --git a/documentation/backlog/OPEN-ITEMS.md b/documentation/backlog/OPEN-ITEMS.md index cb859f1..98da1a3 100644 --- a/documentation/backlog/OPEN-ITEMS.md +++ b/documentation/backlog/OPEN-ITEMS.md @@ -634,5 +634,8 @@ class (an image `VOLUME` at an unmounted path) is still live — `immich-server` | **R-331** | **Disk health Phase 3 — growth-rate detection, and retiring the static 64.** The v0.215.0 count backstop (64 unreadable sectors → Hiba) is **a judgement from ONE drive**: the observed benign excursion peaked at 16 and cleared inside an hour, and the terminal run passed 64 at 13 Aug 11:28 and never came back. It is deliberately a backstop BEHIND the sustain rule, not the primary signal, but it is still a magic number tuned on a single sample and it will be wrong for some drive. With Phase 2's history the box can ask the question that actually matters — *is this count climbing, and how fast* — which distinguishes a drive with eight stable aging sectors from one adding forty a day, something no static threshold can do. Revisit 64 when that exists | **READY (M) — NEW 2026-08-14** | R-330 | Growth-rate rule over persisted samples; re-derive or delete the static 64 | CC | | **R-332** | **The new Hiba-from-counters path has never fired on real hardware.** v0.215.0's whole point is a verdict the product could not previously reach, and it is proven only against the committed fixture's values in unit tests (12 scenario groups, 11 of 12 red-proofs failing as required). The live validation on demo-hp proved the **negative** — three healthy disks still read Rendben across the deploy, no false alert — and the **severity wire** end to end, but no live disk has actually reached Hiba. **This is the honest gap and it must not be closed by pointing at the fixture tests**: the drive that produced the fixture is in DooPlex, which is Tier 2 and never a drill target, and the demo boxes are all-flash and healthy | **WATCHING — NEW 2026-08-14, NARROWED same day.** One item originally in this gap is now PROVEN LIVE: the **persisted state surviving a controller restart**. The v0.215.0→v0.216.0 redeploy destroyed and rebuilt the container, and the new one read back a `changed_at` written by the PREVIOUS version (`2026-08-14T07:23:14.640216851Z`, still intact at 09:31:35Z) instead of re-baselining — Scenario L on real hardware, not just the production-path unit test. **What remains unproven is the verdict itself, plus the stronger restart half: an already-ALERTED disk not re-alerting** | a real degrading disk, or an injection harness | **Closing condition:** a live disk reaching Hiba from counters, OR a deliberate injection through the REAL pipeline (agent `/disks` → controller check → hub event), not a hand-set verdict | CC | | **R-333** | **Two disk-health questions the deploy raised and did NOT act on.** **(a) The 55/60 °C bands are SPINNING-DISK bands applied to NVMe.** They were adopted unchanged from the operator's Prometheus config so the two systems cannot disagree — a deliberate, stated decision — but **measured on demo-hp 2026-08-14 the healthy Toshiba KXG50PNV1T02 NVMe idles at 53 °C, two degrees below Figyelmeztetés and seven below Hiba**, and NVMe routinely exceeds 60 °C under load with no fault whatever. As it stands a healthy customer NVMe under sustained write can be reported as **Hiba** — the single worst outcome this feature can produce. **(b) The agent runs bare `smartctl -a -j` with no `-n standby`** (`felhom-agent/internal/storage/hostops.go:368`), so every poll WAKES a spun-down drive; going 6h → hourly multiplies that by six. demo-hp is all-flash so the cadence measurement could not reveal it, and it was recorded rather than acted on per the task's own instruction. Mitigating datum from the fixture: the failing drive logged only **3375 load cycles in 60505 hours** (~one per 18h), i.e. that duty cycle barely spins down at all | **READY (S each) — NEW 2026-08-14** | — | (a) split the temperature bands by device class, or drop them for NVMe and rely on `critical_warning`; (b) add `-n standby` to the agent's smartctl invocation (an agent change, so fold it into R-330's session) | Viktor decides (a); CC does (b) | -| **R-334** | **WAIVER + open item: controller v0.215.0 is released and deployed, and NO golden carries it.** Convicted by `golden_currency_gate.py` on the 2026-08-14 push: newest released controller **0.215.0**, newest golden bake **0.214.0** (`documentation/tests/golden-0.214.0-2026-08-12`). **A machine installed right now receives 0.214.0** — i.e. a brand-new box would ship WITHOUT the R-328 severity fix and would keep emailing nobody about a failing disk. The running fleet is unaffected (demo-hp guest 9201 is on 0.215.0 and healthy); this is purely the day-0 install path. **Not baked in this session deliberately:** the task scoped deployment to demo-hp only, and the second half of the fix — vouching the bake in the hub's day-0 artifact manifest — is **operator-password-gated, so CC cannot complete it**; a baked-but-unvouched golden is worse than none. **The push was made with `git push --no-verify` and it is stated here and in the session report**, per `.claude/rules/gates.md` — the gate has no waiver parser, so recording a waiver does not clear it | **READY (S) — NEW 2026-08-14** | operator availability for the vouch step | Bake a golden on 0.215.0 per `runbooks/RUNBOOK-manual-build.md` §4.1, then vouch it — a THREE-field change (`golden_version` + `agent_version` + `min_agent`). Until then every NEW install lacks the severity fix | CC bakes; **Viktor vouches** | +| **R-334** | **WAIVER + open item: controller v0.215.0 is released and deployed, and NO golden carries it.** Convicted by `golden_currency_gate.py` on the 2026-08-14 push: newest released controller **0.215.0**, newest golden bake **0.214.0** (`documentation/tests/golden-0.214.0-2026-08-12`). **A machine installed right now receives 0.214.0** — i.e. a brand-new box would ship WITHOUT the R-328 severity fix and would keep emailing nobody about a failing disk. The running fleet is unaffected (demo-hp guest 9201 is on 0.215.0 and healthy); this is purely the day-0 install path. **Not baked in this session deliberately:** the task scoped deployment to demo-hp only, and the second half of the fix — vouching the bake in the hub's day-0 artifact manifest — is **operator-password-gated, so CC cannot complete it**; a baked-but-unvouched golden is worse than none. **The push was made with `git push --no-verify` and it is stated here and in the session report**, per `.claude/rules/gates.md` — the gate has no waiver parser, so recording a waiver does not clear it. **STILL OPEN and now one version WIDER, 2026-08-18:** the newest released controller is **0.216.0** (v0.215.0's own follow-up fix, R-335) and the newest bake is still **0.214.0**, so a new install now misses *two* releases. Re-convicted on this date's documentation-only push, which was likewise made with `--no-verify`; the gate reads `felhom-controller/CHANGELOG.md` and `documentation/tests/golden-*`, **neither of which that session touched** — the conviction is inherited, not caused | **READY (S) — NEW 2026-08-14, re-confirmed 2026-08-18** | operator availability for the vouch step | Bake a golden on **0.216.0** per `runbooks/RUNBOOK-manual-build.md` §4.1, then vouch it — a THREE-field change (`golden_version` + `agent_version` + `min_agent`). Until then every NEW install lacks the severity fix | CC bakes; **Viktor vouches** | | **R-335** | **One physical disk was walked TWICE per run, and the second walk sustained it against itself.** Found on live hardware ~2h after the v0.215.0 deploy, **by noticing the release's own positive observable disagreed with its own persisted artefact**: the hourly check logged *"3 disk(s) evaluated"* while `disk-health-state.json` held **two** records. Cause: demo-hp's `c11-scratch` and `felhom-backup` are the same physical NVMe (`/dev/nvme0n1`) and resolve to the same `diskKey`. **Not cosmetic** — `RunDiskHealthCheck` writes a disk's new record before the next entry reads it, so the SECOND copy consumed the FIRST copy's write as its prior: the disk **sustained against itself and reached Hiba on a FIRST sighting**, defeating truth-table row 6 — the exact rule separating a one-hour benign excursion from a false critical — and would have emitted **two identical events** for one drive. **Latent, not active, on demo-hp** (all three entries healthy, zero counters), but any aliased disk developing a single pending sector would have gone straight to Hiba. **This is the shape standing rule 3 warns about: an absent alarm was not evidence — the two artefacts had to be read AGAINST each other** | **CLOSED — controller v0.216.0, 2026-08-14.** Each `diskKey` is evaluated once per run; both entries stay marked `seen` so neither looks like a disappeared disk, and the card still renders both storage rows (the dedup is about state and alerts, not display). Pinned by `TestDiskCheck_SameDiskTwiceIsEvaluatedOnce`; companion red-proof run and reverted — deleting the guard makes the first sighting emit `Kind:2` (Hiba-from-sectors) at 8 sectors | — | — | CC | +| **R-336** | **The offsite DR endpoint is polled about once per second, and that is what turned a slow leak into an outage.** ep0's PBS proxy served **~85,000 requests/day** — a flat **3,538/hour**, every hour, from two boxes: `74,445 GET /api2/json/admin/datastore` (`libwww-perl`, i.e. PVE's `pvestatd`) and `73,171 GET /admin/datastore/felhom-offsite/status` (`proxmox-backup-client`). Two pollers asking substantially the same question at the same rate. On 2026-08-18 this walked a connection leak in the proxy to its 1024-fd soft limit in **14 days**, wedging the offsite tier for 9½ hours (`audits/INCIDENT-ep0-pbs-fd-exhaustion-2026-08-18.md`). The `LimitNOFILE=65536` drop-in applied that morning raises the ceiling **but does not fix the leak** — it converts a fortnightly outage into a multi-year one, which is mitigation, not a fix. A DR endpoint that is written to weekly does not need to be asked about every second | **READY (M) — NEW 2026-08-18** | — | Find what polls `felhom-pbs` this hard (PVE storage status is the prime suspect, and its interval is tunable) and cut it; then confirm the fd count between restarts stops climbing — the positive observable, per standing rule 3 | CC | +| **R-337** | **`/backup/status` lagged a completed backup by minutes on one box and not the other — and it RESOLVED ITSELF, which is why this is WATCHING and not a defect.** During the R-336 recovery on 2026-08-18, `demo-hp`'s snapshot landed on ep0 at **03:58:43Z** (complete manifest; the host's own task index says `OK`) — yet `GET /backup/status` was **still serving the superseded 03:27:00Z failure at ~04:03Z**, four-plus minutes later. `demo-felhom` showed its new result within ~40 s of completion. **The lag cleared on its own:** demo-hp's 04:07:35Z host report carries `felhom-pbs success=true, 4.29 GB`, and the hub is green for both boxes. **The first draft of this row claimed the success was "still reported as failed" — that was written before the next report arrived and it was wrong; the corrected claim is a several-minute skew between the two boxes, not a stuck value.** It is recorded because a status field that can trail its own artifact by minutes will, during an incident, be read as a second failure — this session nearly did — and because the asymmetry between the two boxes is unexplained | **WATCHING — NEW 2026-08-18** | another observation, ideally during an incident rather than constructed | **Do not open a fix on this as written.** First establish the intended refresh path for `/backup/status` after an out-of-schedule run; only if the skew is not simply collection cadence is there anything to pin. If it is cadence, close this row and say so | CC | +| **R-338** | **`demo-hp` is not on the R-50 island at all, and `operations/nodes.md` states that it is.** The page records both fleet boxes as island-migrated 2026-07-25. True of `felhom-pve`; **false of `demo-hp`**, whose `agent.json` has `listen_addr: 192.168.0.87:8443` — the customer LAN address — and **no `island_bridge`/`island_guest_addr` keys at all**, whose guest 9201 has `net0` only (no `eth1`), and whose `vmbr9` exists with **zero members**. The controller's `controller.yaml` points at the LAN address, so the box works; this is inventory drift, not breakage. **Two costs.** A session trusting the page addresses the wrong endpoint — that happened on 2026-08-18 and the resulting timeout was briefly read as a fault. And the agent's local API is **bound to the customer LAN on this box** rather than to a point-to-point island, which is the exposure R-50 was built to remove — so a documented security property is claimed for a box that does not have it | **READY (S) — NEW 2026-08-18** | — | Decide which is true: migrate `demo-hp` to the island, or correct `nodes.md`. Leaving both is the one option that keeps the doc lying | Viktor decides; CC executes |