Add review #010: EMFILE accept-loop flood (6M ERROR lines in 2h) + mitigation
This commit is contained in:
glm-5.3-flash committed
1 parent
203fcadffd
commit
00b05ee4b6
1 file changed
+249
@@ -0,0 +1,249 @@
|
||||
---
|
||||
status: open
|
||||
last_updated: 2026-09-12
|
||||
reviewed_code:
|
||||
- src/server.rs
|
||||
- src/config/static_config.rs
|
||||
- /opt/reverse-proxy/docker-compose.yml (dev1 deploy)
|
||||
- /etc/reverse-proxy/config.toml (dev1 deploy)
|
||||
reviewer: code-reviewer
|
||||
based_on: docs/reviews/009-fix-never-deployed-and-streaming-body-bug.md
|
||||
trigger: Production incident on dev1 (2026-09-11 ~21:00-23:00 UTC) — EMFILE
|
||||
busy-loop wrote ~6M ERROR lines (~1.9 GB log) in 2 hours
|
||||
fixes:
|
||||
- M1: MITIGATED in production 2026-09-12 — container RLIMIT_NOFILE raised
|
||||
to 8192 (compose ulimits) and max_connections lowered 1024 → 800.
|
||||
Code fixes (C1 backoff, C2 validation) remain open.
|
||||
- C1: OPEN — accept loop busy-spins on accept errors, no backoff.
|
||||
- C2: OPEN — no startup cross-check that max_connections fits under
|
||||
RLIMIT_NOFILE with headroom.
|
||||
---
|
||||
|
||||
# Review #010 — EMFILE Accept-Loop Flood (6M ERROR lines, 1.9 GB log in 2 hours)
|
||||
|
||||
## Summary
|
||||
|
||||
On 2026-09-11, between approximately 21:00 and 23:00 UTC, the production
|
||||
reverse proxy on dev1 hit `EMFILE` ("No file descriptors available", os
|
||||
error 24) and its accept loop **busy-spun, emitting ~6M ERROR log lines
|
||||
(~1.9 GB) in roughly 2 hours** — approximately 460K ERROR lines in the
|
||||
22:00 hour alone, sustained at ~127 lines/second.
|
||||
|
||||
The accept loop has no error backoff: `tcp_listener.accept()` fails
|
||||
instantly and repeatedly when the process is out of file descriptors, and
|
||||
the `continue` on error turns that into a hot spin. Every iteration writes
|
||||
an `error!` line both to stdout (Docker json-file, unbounded by rotation)
|
||||
and to the access log file. The access log grew to 1.9 GB in a day
|
||||
(vs. ~60 MB on normal days); 99% of it was the EMFILE flood. This is the
|
||||
same failure shape as a task leak: an unbounded resource (log bytes) with
|
||||
no circuit breaker.
|
||||
|
||||
Two contributing design gaps made the EMFILE reachable at all:
|
||||
|
||||
1. **C1**: the accept loop treats accept errors as transient
|
||||
("log and continue"), which is correct for `EINTR`/`EAGAIN` but
|
||||
catastrophic for persistent errors like `EMFILE`/`ENFILE` —
|
||||
retry-without-delay on those is a busy loop.
|
||||
2. **C2**: `max_connections = 1024` (the semaphore cap on concurrent TLS
|
||||
connections) equals the container's Docker-default `RLIMIT_NOFILE = 1024`
|
||||
— zero headroom for the listener sockets, health/admin listener, log
|
||||
file FD, ACME renewal sockets, stdin/out/err, and epoll instances.
|
||||
The semaphore therefore admits connections right up to (and past,
|
||||
counting non-connection FDs) the FD ceiling.
|
||||
|
||||
### Production mitigation applied (2026-09-12)
|
||||
|
||||
- `/opt/reverse-proxy/docker-compose.yml`: added
|
||||
`ulimits: nofile: {soft: 8192, hard: 8192}`.
|
||||
- `/etc/reverse-proxy/config.toml`: `max_connections` 1024 → 800.
|
||||
- Container restarted; verified: process limit shows 8192, health green,
|
||||
h2 traffic normal, zero EMFILE lines since.
|
||||
|
||||
With `nofile = 8192` and `max_connections = 800`, the semaphore now caps
|
||||
connection FDs at ~10% of the limit, leaving ample headroom. This removes
|
||||
the trigger, **not** the failure mode — see C1/C2 for the code fixes that
|
||||
remain open.
|
||||
|
||||
## Evidence
|
||||
|
||||
### Timeline (from /var/log/reverse-proxy/access.log.1, since rotated)
|
||||
|
||||
- 20:00 hour: 54 ERROR lines (baseline noise all day was 8–18/2h block)
|
||||
- 21:00 hour: 5,558,249 ERROR lines (grep count) — flood begins
|
||||
- 22:00 hour: 457,419 ERROR lines (flood tail)
|
||||
- First ERROR overall: `2026-09-11T00:15:37Z`; last:
|
||||
`2026-09-12T07:30:27Z` (the 07:30 last line is the deploy restart
|
||||
cutting off the tail)
|
||||
|
||||
Error line shape:
|
||||
|
||||
```
|
||||
2026-09-11T22:00:00.000011Z ERROR reverse_proxy::server: failed to accept TCP connection error=No file descriptors available (os error 24)
|
||||
2026-09-11T22:00:00.000024Z ERROR ... (repeat, ~80 µs apart)
|
||||
```
|
||||
|
||||
Note the ~13 µs spacing between consecutive EMFILE lines at 22:00:00.000 —
|
||||
a pure busy loop, no backoff, no yield.
|
||||
|
||||
### Rotated-log size comparison
|
||||
|
||||
| File | Size | Notes |
|
||||
|------|------|-------|
|
||||
| access.log.2.gz (Sep 11→12) | 55 MB gz / 1.9 GB raw | flood day |
|
||||
| access.log.3–7.gz (Sep 6→11) | 4.9–8.1 MB gz each | normal days |
|
||||
|
||||
### Trigger conditions
|
||||
|
||||
The EMFILE state was reachable because concurrent TLS connections
|
||||
(throttled only by the 1024 semaphore) plus the proxy's own FDs exceeded
|
||||
the container's Docker-default `RLIMIT_NOFILE = 1024`. Verified live on
|
||||
dev1 before mitigation:
|
||||
|
||||
```
|
||||
Max open files 1024 519288 files (containerized process)
|
||||
```
|
||||
|
||||
Traffic context: the flood hour followed sustained crawler load (~77K
|
||||
requests from a 63-IP crawler fleet that day, plus a 30K-request poller
|
||||
from 74.7.242.34). A burst of slow/held TLS connections (e.g. crawlers
|
||||
opening connections and stalling handshakes) suffices to exhaust 1024 FDs;
|
||||
TLS handshakes in progress each hold an FD, and `connection_idle_timeout`
|
||||
only frees them after 60 s.
|
||||
|
||||
After mitigation (`nofile 8192`, `max_connections 800`): 0 EMFILE lines,
|
||||
21 FDs in use at idle, health checks green.
|
||||
|
||||
## Finding C1: Accept loop busy-spins on persistent accept errors [server]
|
||||
|
||||
**Severity**: High — turns any FD/socket exhaustion into a log flood that
|
||||
burns disk and I/O (1.9 GB in 2 hours observed) and starves the accept
|
||||
loop entirely.
|
||||
|
||||
**Location**: `src/server.rs`, `serve_https_listener()` (lines ~255–264):
|
||||
|
||||
```rust
|
||||
loop {
|
||||
tokio::select! {
|
||||
accept_result = tcp_listener.accept() => {
|
||||
let (tcp_stream, remote_addr) = match accept_result {
|
||||
Ok(conn) => conn,
|
||||
Err(e) => {
|
||||
error!(error = %e, "failed to accept TCP connection");
|
||||
continue; // <- busy spin on EMFILE/ENFILE
|
||||
}
|
||||
};
|
||||
...
|
||||
```
|
||||
|
||||
**Why it matters**: `accept()` fails *immediately* with `EMFILE` — there
|
||||
is no blocking wait between retries, so `continue` yields a ~13 µs
|
||||
error-log cycle. The log write itself (to file + stdout) makes the spin
|
||||
slower and more destructive.
|
||||
|
||||
**Recommended fix** (matching tokio's standard pattern):
|
||||
|
||||
```rust
|
||||
Err(e) => {
|
||||
// Transient errors: retry immediately (EINTR, EAGAIN under load).
|
||||
// Persistent resource errors: back off so we don't busy-spin.
|
||||
let kind = e.kind();
|
||||
if matches!(kind, std::io::ErrorKind::WouldBlock | std::io::ErrorKind::Interrupted) {
|
||||
continue;
|
||||
}
|
||||
if matches!(kind, std::io::ErrorKind::ConnectionAborted)
|
||||
|| e.raw_os_error() == Some(libc::EMFILE)
|
||||
|| e.raw_os_error() == Some(libc::ENFILE)
|
||||
{
|
||||
error!(error = %e, "failed to accept TCP connection; backing off 1s");
|
||||
tokio::time::sleep(Duration::from_secs(1)).await;
|
||||
continue;
|
||||
}
|
||||
error!(error = %e, "failed to accept TCP connection");
|
||||
tokio::time::sleep(Duration::from_millis(100)).await;
|
||||
continue;
|
||||
}
|
||||
```
|
||||
|
||||
Options worth considering while fixing:
|
||||
- Log the first N occurrences of a repeated accept error at `error!`, then
|
||||
demote to a periodic (e.g. once/10s) summary until the error clears —
|
||||
bounds log damage from *any* repeating accept failure.
|
||||
- On EMFILE specifically, a small sleep (500 ms–1 s) is both correct and
|
||||
cheap: the process cannot make progress on accepts until FDs are
|
||||
released anyway.
|
||||
|
||||
**Note**: the redirect (HTTP:80) listener and health listener should get
|
||||
the same treatment if they share this loop shape.
|
||||
|
||||
## Finding C2: max_connections is not cross-checked against RLIMIT_NOFILE [config]
|
||||
|
||||
**Severity**: Medium — the semaphore is the intended protection against FD
|
||||
exhaustion, but it can be configured at/above the process's real ceiling,
|
||||
making it a false safety net.
|
||||
|
||||
**Location**: `src/config/static_config.rs` (`default_max_connections()`
|
||||
= 1024) and validation in `src/config/validation.rs`.
|
||||
|
||||
**Why it matters**: `max_connections` counts only TLS connections; the
|
||||
process also needs FDs for: HTTPS + HTTP + health-check listener sockets,
|
||||
the log file, stdin/stdout/stderr, epoll/timer FDs, and ACME renewal
|
||||
outbound sockets (rustls-acme opens TCP + TLS per ACME interaction).
|
||||
With `max_connections == RLIMIT_NOFILE` (the dev1 situation, both 1024),
|
||||
the semaphore guarantees the ceiling can be hit under load.
|
||||
|
||||
**Recommended fix**: at startup (and reload), read the process soft
|
||||
`RLIMIT_NOFILE` (via `rlimit` crate or `getrlimit`) and reject config (or
|
||||
warn + clamp) if:
|
||||
|
||||
```
|
||||
max_connections + reserved_fds > soft_limit
|
||||
```
|
||||
|
||||
with `reserved_fds` ~64 (listeners + log + ACME + epoll headroom). Warn
|
||||
prominently when the soft limit is the Docker default 1024; better, the
|
||||
project's Docker/systemd docs should recommend `nofile 8192` alongside
|
||||
`max_connections = 1024` (or vice versa: derive a sane default from the
|
||||
observed limit).
|
||||
|
||||
## Finding M1 (mitigation): raise nofile + lower max_connections [deploy]
|
||||
|
||||
**Status**: Applied 2026-09-12 (see Summary). Backups:
|
||||
`docker-compose.yml.bak.20260912-080241`, `config.toml.bak.20260912-080241`.
|
||||
|
||||
Residual risk after mitigation: none identified for FD exhaustion at
|
||||
current traffic (peak concurrent connections observed ≪ 800); the code
|
||||
findings C1/C2 remain the durable fix.
|
||||
|
||||
## Traffic-analysis side note (from the same investigation)
|
||||
|
||||
The EMFILE hunt began as a traffic-volume estimate for Gitea, which
|
||||
surfaced the flood because yesterday's rotated log was 1.9 GB vs ~60 MB
|
||||
normal. Traffic profile (2026-09-11, 204K REQUEST lines):
|
||||
|
||||
- ~77K requests from a 63-IP crawler fleet (57.141.20.x — GitHub's
|
||||
published crawler range), ~1.3K req/IP, commit/blame/raw pages
|
||||
- ~30K requests from 74.7.242.34 (Microsoft) polling `/pulls` + `/issues`
|
||||
on 3 repos (`alkdev/alktunnels`, `alkdev/alktls`, `alkdev/alkgen`)
|
||||
plus 56 on `alkdev/typemap`; all GET, no POSTs — dashboard-style
|
||||
monitoring, first seen that day
|
||||
- ~20 HTTPS git fetches, ~22 API calls, zero HTTPS pushes
|
||||
- Zero POSTs to `/user/login`; zero 401/403 that day — no credential
|
||||
attacks over HTTPS
|
||||
|
||||
None of this traffic is hostile per se, but it does mean the "1024
|
||||
concurrent connections" ceiling is reachable from ordinary crawler
|
||||
behavior, which is exactly what made the EMFILE state reachable.
|
||||
|
||||
## Recommended next steps
|
||||
|
||||
1. Land C1 (accept-loop error backoff + log de-duplication) — small,
|
||||
high-value; directly prevents recurrence of the log flood even under
|
||||
unknown future failure modes.
|
||||
2. Land C2 (RLIMIT cross-check at startup) with a prominent warning or
|
||||
hard validation error.
|
||||
3. Consider a doc note in `docs/architecture/operations.md` describing the
|
||||
nofile/max_connections relationship (the mitigation values above are a
|
||||
working baseline: `nofile 8192`, `max_connections 800`).
|
||||
4. Docker image: the deployment Dockerfile on dev1 is a two-line stub
|
||||
(FROM + COPY); if the project's own `deploy/Dockerfile` is ever used,
|
||||
it should also set `ulimits` guidance or rely on compose as done here.
|
||||
Reference in new issue
Block a user