admin
435e044cf1
gates / gates (push) Failing after 15s
Post-restart baseline on ep0: 19 fds at 16m43s (from 18), 1 CLOSE-WAIT, Recv-Q 0. One descriptor per ~17 min is ~85/day, which agrees with the ~73/day implied independently by the failure itself (1016 sockets over 14 days of uptime). Two estimates of the same slope agreeing turns "the ceiling raise is mitigation, not a cure" from a plausible claim into a measured one, and puts the next ceiling at ~2 years instead of a fortnight. Recorded because standing rule 3 asks for a positive observable: this is it, and it fired. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_016p1PTCzb8rF5G9Aa1qhpBN
176 lines
10 KiB
Markdown
176 lines
10 KiB
Markdown
# 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.
|
|
|
|
**It is still live, and it was measured rather than assumed.** At **16 m 43 s** after the restart the
|
|
proxy held **19 fds** (from 18) with **1** connection in `CLOSE-WAIT`. One descriptor per ~17 minutes
|
|
is **≈ 85/day** — which lands on the historical rate implied by the failure itself, 1016 sockets over
|
|
14 days ≈ **73/day**. Two independent estimates of the same slope agreeing is what makes this a
|
|
measurement instead of a story, and it puts the next ceiling at roughly **2 years** rather than the
|
|
fortnight the old limit gave. **The leak is unfixed; only its period changed.**
|