test(e2e): surface why a server failed to start, and stop leaking on that path (#54) - #55
Merged
Merged
Conversation
…that path (#54) Thirteen cluster tests fail on Linux CI with `error.ServerNotReady` — the harness's own 10s timeout — and nothing else. The server's stdout/stderr was already captured to a log file; it was simply never printed, so the CI log carried no bind error, no panic, no reason at all. `ServerProcess.start` now prints the tail of that log when readiness fails. Bounded to 4 KiB, and best-effort: it runs on a path that is already returning an error, so a diagnostic that can itself fail is worse than none. `startServerWithRetry` prints only on its final attempt, since the three attempts usually fail identically. Building it turned up a trap that would have silently disabled the whole feature: `initWithConfig` does `allocator.create(Self)` and assigns fields one at a time, so the struct-level `= true` default never applied and the flag held garbage. The dump did nothing until the field was assigned explicitly. `log_thread` had the same gap — only ever assigned inside `start()`, so a server created and torn down without starting would join a garbage handle. Both are now initialised where every other field is, with a comment naming the hazard. Also fixes the 75 leaks in the same runs. `ClusterContext.init` declared its `errdefer` inside the join loop, which only covers its own iteration, so when the third node failed the two already-started nodes leaked. Replaced with a function-scope `deinitServers()` that tears down whatever was built. Removes a stale comment in `waitForReady` claiming the metrics listener is not wired into the runtime — it has been since #43 — and says why readiness deliberately checks only the client and dashboard ports. Verified the diagnostic fires on the failure path and stays silent on success. macOS e2e: 575/579, the same 4 kv/cluster assertion failures as the baseline.
#54) The log dump added in this PR gave the first real evidence: all 15 failing servers stop at exactly the same line. Starting server... INF topology verified: shards=1 partitions=0 path=... [server] end of log No error, no panic, no io_uring message — the joining node simply stops producing output and never becomes ready. That rules out the RLIMIT_MEMLOCK theory I had been carrying: if ring allocation were failing, the reactor would have logged it. It does not yet say where it stops, because everything between topology verification and the acceptor going live logs at debug, and the harness never wrote a [logging] section at all — every test server ran at info. ServerConfig gains a log_level written into flo.toml, and ClusterContext defaults its nodes to debug. The log is only ever printed as a bounded tail on failure, so this costs nothing when tests pass. Verified the level actually reaches the server (DBG lines present in the captured log), not just that the config parses.
Debug logging narrowed the stall to a window, not a line. The captured log now
ends at:
DBG Raft: bootstrap complete, leader at term=1, commit_index=1
DBG Shard 0 initializing: shard_count=1 partition_count=0 handlers=97 ...
That log statement is the last thing `Shard.init` does before returning, and
`Runtime.start: N shards initialized` never appears — so the node gets past
shard construction and stalls somewhere in the cross-shard wiring between them.
Every one of those steps is pure pointer assignment with no I/O, which makes a
stall there surprising and worth pinning down exactly.
Each wiring step now logs before it runs, so the next run names the one that
does not return.
Also reports whether the child process is still alive when readiness times out.
A crash and a hang look identical in the log — output simply stops — and they
have completely different causes. `waitpid(WNOHANG)` before the kill separates
them.
macOS: unit green, cluster tests unchanged (same known assertion failure).
The last line a hung joining node writes is "wiring peer shards", and the next statement's log never appears — but that function is two single-iteration loops around an 8-byte allocation, which should not be able to block. Either it genuinely blocks in the allocator, or the previous line was simply the last one flushed and execution stopped further along. Logging each step inside the function, plus one immediately after it returns, separates those.
Zig analyses lazily, so a macOS build never compiles flo's Linux-only code — the io_uring reactor, the /proc host stats. That has hidden real breakage twice already (#50, #52), and #54's cluster failures do not reproduce on macOS at all, which left CI as the only way to see them at ~15 minutes per attempt. scripts/linux/run.sh builds and tests in a Debian container pinned to the same Zig as CI. Three constraints are baked in with the reasons, because each cost time to rediscover: * seccomp=unconfined — Docker's default profile blocks the io_uring syscalls and flo cannot start without them (the same trap documented for operators in #42 item 7) * the Zig cache lives in a named volume, so Linux artifacts never collide with the host's macOS .zig-cache * -Dcpu=baseline+crc on aarch64 — checksum_hw.zig emits a crc instruction the aarch64 baseline does not enable Used it to reproduce #54 locally in seconds instead of a CI round trip.
// F_GETFL=3, F_SETFL=4, O_NONBLOCK=0x0004 on macOS
const O_NONBLOCK: c_int = 0x0004;
O_NONBLOCK is 0x0004 on macOS/BSD but 0o4000 on Linux. Both unguarded
copies of this helper hardcoded the macOS value, so on Linux they set an
unrelated flag, fcntl still returned success, and the socket stayed BLOCKING
with nothing to indicate it.
The Raft network thread then blocked forever in read() on its first peer and
never returned to acceptPending, so no further peer could join. That is why
the e2e failures were always the *third* node: the seed accepts exactly one
peer before its network thread dies. Evidence: the seed's loop stopped at
iteration 456, eight seconds before node 3 even connected, having logged
acceptPending and readFromPeers but never flushPending.
The blast radius is not just Raft. acceptor.zig calls the same helper on every
accepted client connection, so on Linux every client socket has been blocking
inside an event loop that assumes otherwise.
`std.posix.O` is target-specific, so bit-casting it gets the right value
everywhere — the idiom already used in runtime.zig. The duplicate in
raft/network.zig now delegates to the stdx helper instead of repeating it.
Note the two sysSocket sites using the same literal are correct: they sit
behind `if (builtin.os.tag == .macos)` and pass SOCK_NONBLOCK directly on
Linux. Only the two unguarded helpers were wrong.
Verified in the Linux container added earlier in this PR:
3-node cluster 2/3 ready → 3/3 ready
seed accepts 1 → 2
seed loop stuck 456 → 3029 iterations
node 3 timeouts 5+ → 0
test-e2e (Linux) 564 pass / 13 fail → 575 pass / 4 fail
The 4 that remain are exactly the kv/cluster assertion failures that also fail
on macOS, so Linux and macOS now agree. macOS build, test-unit and
test-integration all still pass.
…erged tree The step-by-step logging through Runtime.start's wiring block and through wirePeerShards existed only to locate the stall; it says nothing useful now that the cause is fixed. Removed, along with the raft trace logs for accepting a peer and connecting to a seed. Three debug logs stay, all on error paths in the join handshake: a join that fails to read its request, fails to write its response, or times out reading one. A silently failing handshake is precisely what made this bug invisible, and those lines cost nothing until something goes wrong. Comments rewritten to explain why the code is the way it is rather than what used to be wrong with it. A reader of the merged tree does not need the history — they need to know that O_NONBLOCK differs per platform and fails silently when it is wrong, not that a previous version hardcoded the macOS value. Verified unchanged: macOS build, test-unit, test-integration; Linux build; and the 3-node cluster still forms with all nodes ready.
This was referenced Aug 30, 2026
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
First step on #54. This does not fix the cluster failures — it makes them diagnosable, because right now any fix would be a guess.
The problem
Thirteen cluster tests fail on Linux CI with
error.ServerNotReadyand nothing else. That error is the harness's own 10s timeout. The server's stdout/stderr was already being captured to a log file — we just never printed it, so the CI log carries no bind error, no panic, no reason.ServerProcess.startnow prints the tail of that log when readiness fails. Bounded to 4 KiB, and best-effort: it runs on a path that is already returning an error, so a diagnostic that can itself throw is worse than none.startServerWithRetryprints only on the final attempt, since three attempts usually fail identically and would triple the output.A trap that would have silently disabled this
I added
dump_log_on_failure: bool = trueand the dump did nothing.initWithConfigdoesallocator.create(Self)and then assigns fields one at a time — so struct-level defaults never apply. The flag held garbage.I only caught it because I checked the output rather than trusting that the code path ran:
log_threadhas the same gap: it's only ever assigned insidestart(), so a server created and torn down without starting joins a garbage thread handle. Both are now initialised alongside every other field, with a comment naming the hazard so the next= defaultdoesn't quietly do nothing.The 75 leaks
Same runs, one cause.
ClusterContext.initdeclares itserrdeferinside the join loop, which only covers its own iteration — so when the third node failed, the two already-started nodes leaked. Replaced with a function-scopedeinitServers()that tears down whatever was built so far.Metrics has been wired since #43. Replaced with the actual reason readiness checks only the client and dashboard ports: the other two listeners are conditional (#43, #47), so neither is a reliable readiness signal.
Verification
kv/clusterassertion failures as the baseline — no behaviour changeWhat this unblocks
Once merged, the next CI run should print what the third node actually does instead of only that it didn't answer. My hypothesis is
RLIMIT_MEMLOCKexhaustion on io_uring ring allocation at the third node — the reactor already logs a clear message for that (#47), we just couldn't see it. But that's a hypothesis, and this PR exists so the next step is reading an error rather than guessing again.