NetFault Lab

Replay a real run

Each scenario below is a genuine capture: the proxy's own JSON Lines event log, plus a time series of its metrics documents sampled while the workload ran. Nothing here is simulated or hand-authored — the capture tool is in the repository. No proxy is running on this page; a TCP relay reachable from the internet would be an open relay, and the project is loopback-only by design.

Five problems worth the write-up

The tests earned their keep. These are real defects, each with a root cause that only shows up once you look at what the kernel actually promises — including two that this very page uncovered.

1. A lost timer expiration

   Found by CI on an Azure 6.17 kernel · Milestone 5

   The event loop re-armed its timerfd at the end of every iteration, even when the earliest deadline had not changed. But timerfd_settime clears a pending expiration as part of arming. If the timer fired in the window between an unrelated socket wakeup and that rearm, the expiration was silently swallowed and the deadline never fired — connections waiting on a connect timeout hung forever. The fix is to skip arming entirely when the earliest deadline is unchanged. It reproduced on CI and never locally, because it needs a wakeup to land in a window a few microseconds wide.

2. Partial writes that would not happen

   Found while proving a code path · Milestone 2

   The proxy retries short send() results, but no test could force one. Loopback TCP copies up to its ~64 KiB size goal before it consults send-buffer memory, so any smaller write either completes fully or returns EAGAIN — a positive short write simply never occurs. Provoking one needs a queue larger than that goal and a constrained upstream socket buffer. Until then the retry loop was correct by inspection and unproven by test; now it is covered both by a scripted fake at the socket boundary and against the real kernel.

3. A test harness corrupting its own evidence

   Found chasing a 1-in-10 flake · Milestone 3

   Integration tests polled the proxy's log through the same Python file object whose descriptor the proxy had inherited as stdout. Both handles shared one open file description — and therefore one offset — so the harness's seek(0) rewound the writer, and the proxy's next line overwrote the beginning of its own log. The symptom was events appearing out of order. The fix reads through an independent file description instead.

4. A busy loop the tests could not see

   Found by building this page · fixed, with a regression guard

   Capturing the backpressure run above surfaced something no test asserted on: a single one-mebibyte transfer through a slow upstream logged 721,806 EAGAIN results, and the proxy burned most of a CPU core waiting on a peer that was, by construction, slow.

   The cause was EPOLLRDHUP, requested unconditionally. It is level-triggered and stays asserted from the moment a peer half-closes — and the client half-closes as soon as it has sent its payload. With backpressure holding reads paused, the loop woke on that flag, correctly declined to read, performed a futile flush, and woke again immediately: a hot loop on a condition it had deliberately decided not to act on yet. The fix is to request EPOLLRDHUP only alongside read interest, which costs nothing, because level-triggered delivery re-reports the half-close the moment reads resume.

   My first reading of the evidence was wrong. I blamed spurious writability — the kernel calling a socket writable while send() still refuses — which fitted the EAGAIN counter but could not explain why an unconstrained upstream, producing just 131 EAGAIN results, still burned 196 CPU ticks. A spin with empty queues never reaches a send(), so it never moves that counter at all. The regression guard now asserts both signals, and was checked against the pre-fix build to confirm it actually fails there.

5. A rate limiter that dribbled

   Found re-measuring after the previous fix · fixed

   Moving 200 kB through a 100 kB/s token bucket took 144,936 read and write operations — about 1.4 bytes per system call. Nothing was incorrect: the rate was enforced exactly and every byte arrived in order. It was simply the least efficient possible way to honour the limit, because the bucket released the instant a single byte's worth of tokens had accrued.

   A direction now waits until it can release a worthwhile quantum, bounded by the bytes actually queued and by the configured burst so a small tail still drains rather than stalling. The same 200 kB now takes 149 operations at about 1,342 bytes each, with CPU falling from 39% of wall time to 0.5% — and the wall time itself unchanged at 1.92 s, which is the point. The limit is enforced to the same accuracy using three orders of magnitude fewer syscalls.