INCIDENT + registers: ep0's PBS proxy served nobody for 9.5h (R-336..R-338)
gates / gates (push) Failing after 12s
gates / gates (push) Failing after 12s
Two whole_guest_backup_failed alerts at 04:30 and 04:32 CEST were one incident, and not on either customer box: ep0's proxmox-backup-proxy was active, holding its listening socket, and accepting nothing. Root cause: accept() returning EMFILE. The process held exactly 1024 fds -- its systemd-default soft RLIMIT_NOFILE -- of which 1016 were sockets and 547 connections sat in CLOSE-WAIT. The 1024-deep accept backlog had overflowed (Recv-Q 1025), so every client timed out. It was wedged from its own loopback too, which is what moved this from a network problem to a process problem. Fed by ~85k requests/day (a flat 3,538/hour) against an endpoint written to weekly, that leak reached the ceiling in 14 days of uptime. Fix: LimitNOFILE=65536 drop-ins for both PBS units, restart, verified from both boxes (200 in ~0.1s, felhom-pbs active), then re-drove the missed backups through the product path -- POST /backup?target=felhom-pbs on each agent's local API, not a hand-run vzdump. demo-felhom ct/9201/2026-08-18T03:57:43Z 4.10 GB 36.4s demo-hp ct/9201/2026-08-18T03:58:43Z 4.29 GB 41.5s Both host reports now carry felhom-pbs success=true, so the hub is green on the evidence rather than on a restart having been performed. No data lost, no backup skipped: the daily local tier was never affected and the PBS tier is weekly, so the window cost exactly one attempt. Evidence copied off ep0 BEFORE the restart, per standing rule 5. Filed: R-336 (the ~1 req/s poll rate is the real defect; the raised ceiling is mitigation, not a cure), R-337 (a status endpoint that trailed its own artifact by minutes then caught up -- WATCHING, downgraded from the defect I first wrote, because it self-corrected), R-338 (demo-hp is not on the R-50 island at all and nodes.md says it is; its local API is bound to the customer LAN). R-334 updated: still open, now one version wider (controller 0.216.0 vs golden 0.214.0). golden-currency is the only failing gate and is inherited -- it reads files this session did not touch -- so this push used --no-verify, stated per .claude/rules/gates.md. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_016p1PTCzb8rF5G9Aa1qhpBN
This commit is contained in:
@@ -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/<proxy>/fd | wc -l → 1024
|
||||
grep 'open files' /proc/<proxy>/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/<unit>.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@<ep0> '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.
|
||||
Reference in New Issue
Block a user