From b6d70a50feaa99e62ba3700d862373870200e04b Mon Sep 17 00:00:00 2001 From: developer Date: Sun, 27 Sep 2026 19:28:17 +0000 Subject: [PATCH] Finish the server shutdown tests; fix the two bugs they found MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit internal/server was the last package whose shutdown was tested by assumption: four transports, three shutdown shapes, and every one of them can strand a goroutine that a client is holding open. Both bugs below were live in the tree as handed over and neither had a test. An idle client could hold the whole shutdown open. The stream accept loop waits for its connections before Stop returns, and a connection parked in ReadMsg with no deadline in front of it only ends when the client goes away — ctx.Err() is checked between reads, so cancelling the context cannot reach a read that is already blocked. One connection that connected and said nothing was enough to make Stop sit there for the caller's entire grace period (15s in main) and then return context.DeadlineExceeded, which the app reports as "shutdown completed with errors"; and the cache snapshot the app takes right after Stop never happened, because the orchestrator had given up first. It is a shutdown DoS that costs the attacker one connection. The fix is a read deadline in the past on every accepted connection when the context is cancelled, and deliberately not a close: a query already inside the pipeline is past its read, so its answer still goes out, which is the invariant TestInFlightQueryIsAnsweredAcrossStop pins. The accept loop keeps a small registry of live connections for this — the accept path, not the query path, and no query ever takes that mutex. A UDP query in flight at Stop was lost and nothing waited for it. The stream paths register their connections with s.wait; servePacket did not register at all, so a UDP query already inside the pipeline was gone twice over: nothing waited for it, and the answer had nowhere to go once it was ready, because a datagram is written to the very socket the query arrived on. The visible damage was not the lost answer (the client retries) but the app, which snapshots the cache and closes the store the moment Stop returns — a query still in the pipeline could be writing to a store on its way out. Packets are now counted in s.wait, and the UDP listener's close wakes the read loop with an expired deadline and then waits, bounded by udpDrainGrace (250ms), for the loop and the packets it spawned before closing the socket. The bound is deliberate: a shutdown may not spend its grace period on one slow upstream, and past the bound the answer is dropped, which is what the client would see anyway. Stop returning did not mean the process was done, so nothing could tell a leaking shutdown from a clean one. TestStopLeavesNoGoroutineRunningServerCode counts goroutines whose stack still has a frame in the package — not runtime.NumGoroutine(), which in a test binary is net/http, crypto/tls and the race detector talking over each other — and it found the idle-connection bug above. TestStopIsNotBlockedByAnIdleStreamConnection sets a 60s DoT idle timeout on purpose so a config value cannot hide the regression behind a lucky tick, and TestInFlightQueryIsAnsweredAcrossStop now covers all four transports. harness.idleStream exists because a test that only dials a stream transport races the accept loop: Stop can close the listener while the connection is still in the backlog, the server never accepts it, and a shutdown assertion that needs a live server-side goroutine passes for the wrong reason. AGENTS.md gains the two durable invariants (no step in the shutdown may wait for a client; every query goroutine is registered with s.wait, UDP included) and the two test-hygiene traps. STATUS.md drops the UDP query lost at Stop from its pinned list, since it is now a test rather than an accident, and the plan starts at the pinned decisions that are actually left. --- AGENTS.md | 25 +++ STATUS.md | 137 +++++++++++----- internal/server/harness_test.go | 44 ++++++ internal/server/server.go | 99 +++++++++++- internal/server/shutdown_test.go | 262 +++++++++++++++++++++++++++++++ 5 files changed, 526 insertions(+), 41 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 7a69ed9..faf0c6a 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -83,6 +83,21 @@ Break these and you break the design, not just the test. truncated forever. - **The UDP read deadline is reset every iteration.** A deadline set once expires for good and turns the loop into a spin that never reads another packet. +- **No step in the shutdown may wait for a client.** `Stop` is: cancel, close + every listener (not interruptible — releasing the ports is the work the next + process start needs), then wait for the goroutines (interruptible by the + caller's context). The wait is the step that breaks when something depends on + a client: a connection parked in a read with no deadline in front of it never + notices the cancellation, and one idle connection is enough to spend the whole + grace period and then report a context error. Reach those connections with a + read deadline in the past, **not** a close — a query already inside the + pipeline is past its read, and its answer still has to go out. +- **Every query goroutine is registered with `s.wait`, UDP included**, so `Stop` + returning means nothing is still inside the engine: the app snapshots the + cache and closes the store immediately afterwards, and a query still in flight + would be writing to a store on its way out. A UDP answer has nowhere else to + go, so that transport also gets a short bounded drain before its socket + closes — see `udpDrainGrace` in `internal/server/server.go`. - **Only the Valkey lease holder fetches blocklists**, so N instances do not hit a mirror N times. Followers serve their compiled copy. - **Blocklist changes flush the cache** rather than guessing which subtrees are @@ -149,6 +164,16 @@ partial result described as done is not. - Assert on invariants, not on what a concurrent goroutine happened to observe. "A reader must have seen address X" is a flake; "every list a reader sees is one of the published ones" is a real property and cannot flake. +- **A test that only dials a stream transport races the accept loop.** A + shutdown can close the listener while the connection is still in the backlog, + so the server never accepts it and the test passes for the wrong reason. + Exchange one query first, then leave the connection idle + (`harness.idleStream`). +- **Count leaked goroutines by stack, not by `runtime.NumGoroutine()`.** The + test binary shares its process with net/http, crypto/tls and the race + detector, so a baseline count is noise. "Is any goroutine still running code + in this package?" is a property of the product — and it needs the caller's own + goroutine filtered out by id, or every run finds exactly one. - Spin up `dns.Server` fakes on `127.0.0.1:0`: `net.Listen`/`net.ListenPacket` to find the port, `ActivateAndServe` in a goroutine, stop in `t.Cleanup`. - A `dns.Msg` carrying a `TXT` string over 255 bytes **does not pack** in diff --git a/STATUS.md b/STATUS.md index 2cfe181..90ddcd8 100644 --- a/STATUS.md +++ b/STATUS.md @@ -1,11 +1,12 @@ # fancy-dns — development status and continuation plan -Last updated after the round that made the **API response contract a test** -(`internal/app/contract_test.go` pins the exact JSON key set of every admin -endpoint, and fixed the four drift items it exposed), decided the two pinned -open questions, and finished the cluster package's peer-reaping gap. `AGENTS.md` -holds the decisions, invariants and working rules; this file holds state and the -plan. +Last updated after the round that finished the **server shutdown paths**: +every transport's ordering with a query in flight is now a test, and it found +two real bugs — an idle client could hold a shutdown for the whole grace +period, and a UDP query in flight was neither waited for nor answered. The +round before that brought the console onto the Go side of the API contract, so +both halves of that are done. `AGENTS.md` holds the decisions, invariants and +working rules; this file holds state and the plan. ## Goal @@ -81,17 +82,17 @@ Cache is a single shard-local lookup; only a miss touches the network. |---|---|---| | `internal/acl` | 26 | group compilation, matching, first-group-wins | | `internal/api` | 55 (156 cases) | the whole route table, three auth modes, CORS, rate limiting, SSE, settings, error branches, pinned limitations | -| `internal/app` | 25 + the contract suite | wiring, hooks, **the API response contract**, integration | +| `internal/app` | 30 (incl. the contract suite) | wiring, hooks, **the API response contract**, integration | | `internal/blocklist` | 28 | four parsers, the set, the manager, the shipped example zone | | `internal/cache` | 27 | LRU, TTL policy, serve-stale, bbolt round-trip | -| `internal/cluster` | 30 | Valkey lease, pub/sub, divergence, dead-peer reaping | +| `internal/cluster` | 20 | Valkey lease, pub/sub, divergence, dead-peer reaping | | `internal/config` | 22 | Duration/Size, `${VAR}`, unknown keys, the JSON wire form, the shipped example configs | | `internal/engine` | 26 | the pipeline end to end, plus the pins | | `internal/localzone` | 18 | wildcards, delegation, CNAME following | | `internal/metrics` | 10 | the metric names, which are the contract with the dashboards | | `internal/qlog` | 18 | ring, bbolt, top domains, sampling | | `internal/resolver` | 10 | pool, breakers, health, policies | -| `internal/server` | 36 | four listeners, UDP deadline reset, truncation, DoH limits, identity, shutdown, stats | +| `internal/server` | 57 | four listeners, UDP deadline reset, truncation, DoH limits, identity, counters, **shutdown and leak** | | `internal/zonefile` | 29 | the master-file parser and the shipped example zone | | `web` | 0 | typecheck and `oxlint` clean (0 errors), no test runner | | `cmd/fancy-dns` | 0 | exercised by `make smoke` and the CI smoke job instead | @@ -109,14 +110,26 @@ Cache is a single shard-local lookup; only a miss touches the network. - `make web-check` — console typecheck and production build. - `make bench` — cache and blocklist benchmarks. -### Test coverage is no longer the interesting gap +### The contract gap is closed on both sides -The API **response contract** is. The console's types are hand-written and -`apiFetch` ends in `JSON.parse(text) as T`, so nothing in the toolchain compared -them with the Go structs; a field that lost its `json` tag, or a response a -struct never had, showed up as an empty table in a browser and nowhere else. -`internal/app` now has contract tests that assert the exact JSON key set of -every admin endpoint — see the fix list. +The API **response contract** used to be the interesting gap. The console's +types are hand-written and `apiFetch` ends in `JSON.parse(text) as T`, so +nothing in the toolchain compared them with the Go structs; a field that lost +its `json` tag, or a response a struct never had, showed up as an empty table in +a browser and nowhere else. `internal/app` now has contract tests that assert +the exact JSON key set of every admin endpoint (see the fix list), and the +console has been brought onto them — so the two sides agree *today*, but only +because someone compared them once. The durable fix is still open: see plan +item 2. + +### The server's shutdown is now pinned behaviour, not folklore + +It was the last part of `internal/server` tested by assumption. Four +transports, three shutdown shapes (a datagram socket, a stream accept loop with +configurable idle timeouts, and an `http.Server` that drains politely), and +every one of them can strand a goroutine a client is holding open. The +invariants that came out of it are in AGENTS.md; the two bugs it found are in +the fix list below. ### Decided this round (behaviour changed on purpose, each with a test) @@ -144,6 +157,47 @@ every admin endpoint — see the fix list. ## Fixed this round +- **A client that connected and said nothing held the whole shutdown open.** + The stream accept loop waits for its connections before `Stop` returns, and a + connection parked in `ReadMsg` with no deadline in front of it only ends when + the client goes away — `ctx.Err()` is checked *between* reads, so cancelling + the context cannot reach a read that is already blocked. One idle TCP + connection (or one DoT connection, with `timeouts.tls` set high) was enough to + make `Stop` sit there for the caller's entire grace period — 15s in `main` — + and then return `context.DeadlineExceeded`, which the app reports as + "shutdown completed with errors". Worse, the cache snapshot the app takes + right after `Stop` never happened: the orchestrator had already given up. It + is a shutdown DoS that costs the attacker one connection, and nothing tested + it. The fix is a read deadline in the past on every accepted connection when + the context is cancelled, and deliberately *not* a close: a query already + inside the pipeline is past its read, so its answer still goes out, which is + the invariant `TestInFlightQueryIsAnsweredAcrossStop` pins. + `TestStopIsNotBlockedByAnIdleStreamConnection` sets a 60s DoT idle timeout on + purpose, so a config value cannot hide the regression behind a lucky tick. +- **A UDP query in flight at `Stop` was lost, and nothing waited for it.** The + stream paths register their connections with `s.wait`, so `Stop` waits for + them; `servePacket` did not register at all, so a UDP query already inside + the pipeline when the socket closed was gone twice over — nothing waited for + it, and the answer had nowhere to go even once it was ready, because a + datagram is written to the very socket the query arrived on. The visible + damage was not the lost answer (the client retries) but the app: it snapshots + the cache and closes the store the moment `Stop` returns, so a query still in + the pipeline could be writing to a store that was about to close. Packets are + now counted in `s.wait`, and the UDP listener's close waits (bounded by + `udpDrainGrace`, 250ms) for the read loop and the packets it spawned before it + closes the socket. A shutdown must not spend its grace period on one slow + upstream, hence the bound: past it the answer is dropped, which is what the + client would see anyway. Pinned on all four transports by + `TestInFlightQueryIsAnsweredAcrossStop/{tcp,dot,udp,doh}`. +- **`Stop` returning did not mean the process was done.** Nothing asserted that + the server's goroutines were gone, so a shutdown that leaked one was + indistinguishable from one that did not. `TestStopLeavesNoGoroutineRunningServerCode` + counts goroutines whose stack still has a frame in this package — not + `runtime.NumGoroutine()`, which in a test binary is net/http, crypto/tls and + the race detector talking over each other — and it found the idle-connection + bug above, since the check is the only way to see a goroutine that has no + client left to answer. + - **A dead peer stayed in the cluster peer list forever.** `Cluster.seen` was only ever added to and deleted from on an explicit `bye`, so a node that crashed — or whose Valkey connection died — was reported as a live peer for @@ -336,12 +390,6 @@ a test that fails when it changes, and says what to do when it does. TCP/DoT.** `TestUDPQuestionlessMessageReachesTheEngine` pins the UDP half (the engine turns it into a FORMERR); the stream path returns instead. Probably right for both, but it is an asymmetry worth knowing about. -- **A UDP query in flight at `Stop` can be lost.** The stream paths register - with `s.wait`, so `Stop` waits for them; `servePacket` does not, so a UDP - query already inside the pipeline when the listener closes may never be - answered. That is arguable — UDP has no connection to hang up on and the - client will retry — but the asymmetry with TCP/DoT is not pinned anywhere, and - it should be a decision rather than an accident. - **`doh.sent` is never bumped.** The DoH handler writes its answer through `net/http`, so the `sent` counter is only meaningful on UDP/TCP/DoT, and the console's transport table shows `sent: 0` for DoH. Pinned as current @@ -355,29 +403,25 @@ a test that fails when it changes, and says what to do when it does. ## Continuation plan, in order -1. **The console side of the contract** — the Go side is authoritative now - (`internal/app/contract_test.go`); `web/src/lib/types.ts` and the pages have - to be brought onto it. The known items: the Cache page's "Lookups"/"Last - seen" columns read `count`/`last_seen` where the server sends `hits` (there - is no last-seen data at all), the Dashboard reads `qps`/`total_queries` where - the server sends `queries_per_sec`/`queries_total` and never sends a - `latency` block, `whoami.can_write`/`read_only` are fetched and never used so - a read-only key still shows every Save control, `blocked_pct` arrives as - 0..100 from the dashboard and 0..1 over SSE, and the upstreams page has to - cope with durations being strings on the wire. -2. **Finish the remaining server tests** — the counter-key layer is now covered - by `internal/server/counters_test.go`; what is left is a look at each - transport's shutdown ordering with a slow query in flight, and a `Stop` - goroutine-leak assertion. -3. **Decide the rest of the pinned list**, one at a time, each with a changelog +1. **Decide the rest of the pinned list**, one at a time, each with a changelog note: the frozen auth config, the DoH client identity, CORS wildcards, the - UDP query lost at `Stop`, `doh.sent` never bumped. -4. **Stop hand-writing the console's types.** The contract tests make the Go + question-less message asymmetry, `doh.sent` never bumped. (The UDP query lost + at `Stop` left this list when it was fixed.) +2. **Stop hand-writing the console's types.** The contract tests make the Go side authoritative; the cheapest durable answer is generating `web/src/lib/types.ts` from the Go structs (or an OpenAPI document emitted by the server) so `apiFetch` is typed against something real instead of `JSON.parse(text) as T`. `internal/app/dump_shapes_test.go` (`DUMP_SHAPES=1`) is the stopgap that already exists. +3. **Decide whether the shutdown grace belongs in config.** `main` hard-codes + 15s for the whole `Stop`, and the drain inside it is 250ms of that. A + Kubernetes `terminationGracePeriodSeconds` and a resolver's own notion of + "long enough to answer what is in flight" are the same number, and right now + only one of them is visible. The four-transport invariant is pinned, so + changing the bound is cheap — but the knobs do not exist yet. +4. **Read the pinned "not fixed" list in this file for anything that has since + become untrue.** Each entry claims a behaviour a reader may act on; a claim + that no longer matches the code is worse than a missing one. ## Design notes worth preserving @@ -399,6 +443,11 @@ a test that fails when it changes, and says what to do when it does. - **The UDP listener resets its read deadline every iteration.** A deadline set once expires for good and turns the loop into a spin that never reads another packet (caught by `TestBlocklistToggle`). +- **Shutdown order is: cancel, close every listener, then wait.** The close is + not interruptible by the caller's context, because releasing the ports is the + work the next process start needs. Everything after it is interruptible, and + a cancelled context is expected to be able to cut the *wait* short — which is + why no step in the shutdown may depend on a client doing anything. - **Only the Valkey lease holder fetches lists**, so N instances do not hit a mirror N times. - **Serve-stale** answers get TTL 1; an expired upstream answer is never cached; @@ -422,6 +471,16 @@ a test that fails when it changes, and says what to do when it does. - Assert on invariants, not on what a concurrent goroutine happened to observe. "A reader must have seen address X" is a flake; "every list a reader sees is one of the published ones" is a real property and cannot flake. +- **A test that only dials a stream transport races the accept loop.** Stop can + close the listener while the connection is still in the backlog, the server + never accepts it, and any shutdown assertion that needs a live server-side + goroutine passes for the wrong reason. Exchange one query first, then leave + the connection alone — that is what `harness.idleStream` is for. +- **Count leaked goroutines by stack, not by `runtime.NumGoroutine()`.** A test + binary shares its process with net/http, crypto/tls and the race detector; a + baseline count is noise. "Does any goroutine still have a frame in this + package?" is a property of the product, and it needs the caller's own + goroutine filtered out by id or every run finds exactly one. - `tsc -b` replays **cached diagnostics** from `node_modules/.tmp/*.tsbuildinfo`. After a large edit, `rm node_modules/.tmp/*.tsbuildinfo`. - `vite build` empties `outDir` and **deletes `internal/web/dist/.gitkeep`**. diff --git a/internal/server/harness_test.go b/internal/server/harness_test.go index dbc889b..002926d 100644 --- a/internal/server/harness_test.go +++ b/internal/server/harness_test.go @@ -545,6 +545,50 @@ func (h *harness) doHPostWith(m *dns.Msg, contentType string) (*http.Response, [ return res, body } +// idleStream hands back a stream connection the server has definitely +// accepted, and that the caller then leaves alone: one query has been +// exchanged on it, so the server is inside ReadMsg waiting for the next one. +// +// Waiting for a real exchange is the point. A test that only dials races the +// accept loop — Stop can close the listener while the connection is still in +// the backlog, the server never accepts it, and a shutdown that hangs on idle +// connections passes by accident. +func (h *harness) idleStream(t *testing.T, transport string) net.Conn { + t.Helper() + var ( + conn net.Conn + err error + ) + if transport == "dot" { + tc := h.clientTLS() + tc.NextProtos = []string{"dot"} + conn, err = tls.Dial("tcp", h.addr("dot"), tc) + } else { + conn, err = net.DialTimeout("tcp", h.addr("tcp"), 2*time.Second) + } + if err != nil { + t.Fatalf("dial %s: %v", transport, err) + } + t.Cleanup(func() { _ = conn.Close() }) + _ = conn.SetDeadline(time.Now().Add(5 * time.Second)) + co := &dns.Conn{Conn: conn} + name := "accepted-" + transport + ".test." + if err := co.WriteMsg(question(name, dns.TypeA)); err != nil { + t.Fatalf("write on the %s connection: %v", transport, err) + } + res, err := co.ReadMsg() + if err != nil { + t.Fatalf("the %s connection was never served: %v", transport, err) + } + if a := answerAddr(res); a != "203.0.113.9" { + t.Fatalf("the %s connection answered %q, want 203.0.113.9", transport, a) + } + // The deadline is dropped again so a later read blocks for real: this + // connection must not end the test on its own. + _ = conn.SetDeadline(time.Time{}) + return conn +} + func unpackDoH(t *testing.T, body []byte) *dns.Msg { t.Helper() m := new(dns.Msg) diff --git a/internal/server/server.go b/internal/server/server.go index 185d49d..4e7d815 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -254,7 +254,34 @@ func (s *Server) serveUDP(ctx context.Context, addr string) error { // on every iteration: a deadline set once expires for good and turns the // loop into a spin that never reads another packet. const readTick = 500 * time.Millisecond - s.add(listener{close: pc.Close, info: ListenerInfo{ + // Two counters, two jobs. s.wait is the lifecycle one: Stop must not + // return while a query is still inside the engine, because the app + // snapshots the cache and closes the store the moment Stop returns. + // packets is the drain one, and only the reader goroutine ever waits on + // it — after it has stopped adding to it, which is what makes waiting on + // it legal at all. + var packets sync.WaitGroup + readerDone := make(chan struct{}) + s.add(listener{close: func() error { + // A read deadline that has already expired wakes the read loop at + // once instead of leaving it to the read tick, so a Stop with an + // idle listener costs nothing. The loop returns on its next + // iteration either way: the context is already cancelled by the time + // Stop reaches this close. + _ = pc.SetReadDeadline(aLongPast) + // And then the queries already in the pipeline get their chance to + // be answered on this socket. Unlike the stream transports, a UDP + // answer has nowhere else to go: the write goes to the very socket + // the query arrived on, so a packet that is written after Close is + // simply lost and the client has nothing but its own retry. The wait + // is bounded — a shutdown may not spend its whole grace period on one + // slow upstream. + select { + case <-readerDone: + case <-time.After(udpDrainGrace): + } + return pc.Close() + }, info: ListenerInfo{ Transport: "udp", Addr: pc.LocalAddr().String(), Enabled: true, Running: true, }}) s.log.Info("dns listener up", "transport", "udp", "addr", pc.LocalAddr().String()) @@ -262,6 +289,11 @@ func (s *Server) serveUDP(ctx context.Context, addr string) error { s.wait.Add(1) go func() { defer s.wait.Done() + // The deferred order is the whole contract: drain the packets, then + // report the reader done — which is what releases the close func + // above — and only then leave s.wait. + defer close(readerDone) + defer packets.Wait() buf := make([]byte, dns.MaxMsgSize) for { if ctx.Err() != nil { @@ -290,7 +322,13 @@ func (s *Server) serveUDP(ctx context.Context, addr string) error { // on the hottest path in the process. servePacket only needs the // address to write back to, so pass what we already have. addr, _ := from.(*net.UDPAddr) - go s.servePacket(ctx, pc, pkt, from, addr) + packets.Add(1) + s.wait.Add(1) + go func() { + defer packets.Done() + defer s.wait.Done() + s.servePacket(ctx, pc, pkt, from, addr) + }() } }() return nil @@ -301,6 +339,18 @@ func isTimeout(err error) bool { return errors.As(err, &ne) && ne.Timeout() } +// udpDrainGrace is how long Stop waits for the queries already inside the +// pipeline before it closes the UDP socket. See serveUDP: the point is not to +// make a shutdown slow, it is to give an answer that is milliseconds from +// being written somewhere it can still reach the client. +const udpDrainGrace = 250 * time.Millisecond + +// aLongPast is a read deadline that has already expired. Setting it is how a +// blocked read is woken without closing anything under it: the read fails +// with a timeout, which is what a shutdown wants, and a connection that still +// owes the client an answer can still write it. +var aLongPast = time.Unix(1, 0) + // servePacket answers one UDP query. The listener is passed in so the reply // goes out on the very same socket the query arrived on: a fresh socket per // answer would burn an ephemeral port and a connect handshake per query. @@ -425,11 +475,48 @@ func (s *Server) serveStream(ctx context.Context, ln net.Listener, transport str Transport: transport, Addr: ln.Addr().String(), Enabled: true, Running: true, }}) s.log.Info("dns listener up", "transport", transport, "addr", ln.Addr().String()) + // The accepted connections, so that a cancellation can reach the ones + // parked in a read. This is the accept path, not the query path: a + // connection is added once and removed once, and no query ever takes this + // mutex. + var ( + connMu sync.Mutex + conns = map[net.Conn]struct{}{} + ) s.wait.Add(1) go func() { defer s.wait.Done() var wg sync.WaitGroup defer wg.Wait() + // A connection that is open but idle is the one thing a cancelled + // context cannot reach by itself: the loop below checks ctx.Err() + // between reads, so a client that connects and then says nothing + // parks in ReadMsg until the client goes away. Stop waits for these + // goroutines, so the shutdown would sit there until the caller's + // grace period ran out and then report a context error — a shutdown + // DoS that costs a client one connection. + // + // The nudge is a read deadline in the past, not a close: a query + // already inside the pipeline is past its read, so its answer is + // still written. That is the invariant + // TestInFlightQueryIsAnsweredAcrossStop pins, and closing the + // connection here would break it. + stop := make(chan struct{}) + defer close(stop) + wg.Add(1) + go func() { + defer wg.Done() + select { + case <-stop: + return + case <-ctx.Done(): + } + connMu.Lock() + for c := range conns { + _ = c.SetReadDeadline(aLongPast) + } + connMu.Unlock() + }() for { conn, err := ln.Accept() if err != nil { @@ -441,9 +528,17 @@ func (s *Server) serveStream(ctx context.Context, ln net.Listener, transport str } return } + connMu.Lock() + conns[conn] = struct{}{} + connMu.Unlock() wg.Add(1) go func() { defer wg.Done() + defer func() { + connMu.Lock() + delete(conns, conn) + connMu.Unlock() + }() s.serveConn(ctx, conn, transport, idleTimeout) }() } diff --git a/internal/server/shutdown_test.go b/internal/server/shutdown_test.go index 7d72c8b..e985826 100644 --- a/internal/server/shutdown_test.go +++ b/internal/server/shutdown_test.go @@ -3,13 +3,19 @@ package server import ( "bytes" "context" + "crypto/tls" "io" "net" + "runtime" + "strconv" + "strings" "sync" "testing" "time" "github.com/miekg/dns" + + "git.k8s-git-k6n.net/mats/fancy-dns/internal/config" ) // Shutdown is the only part of this package that can lose a client's query, @@ -334,6 +340,106 @@ func TestInFlightQueryIsAnsweredAcrossStop(t *testing.T) { t.Errorf("Stats().Inflight = %d after Stop returned, want 0", got) } }) + + // DoT is the same shape as TCP with a TLS handshake in front of it, and + // it is here because it is a *different* shutdown path in the product: + // the stream loop takes an idle timeout from the config, so a DoT query + // can be answered after its connection's deadline has been set, while a + // plain TCP one cannot. + t.Run("dot", func(t *testing.T) { + h := newHarness(t, nil) + release := holdOnce(t, h.fake) + tc := h.clientTLS() + tc.NextProtos = []string{"dot"} + conn, err := tls.Dial("tcp", h.addr("dot"), tc) + if err != nil { + t.Fatalf("dial dot: %v", err) + } + t.Cleanup(func() { _ = conn.Close() }) + _ = conn.SetDeadline(time.Now().Add(5 * time.Second)) + co := &dns.Conn{Conn: conn} + if err := co.WriteMsg(question("inflight-shutdown.test.", dns.TypeA)); err != nil { + t.Fatalf("write: %v", err) + } + h.fake.waitArrived(t) + + stopped := startStop(h.srv, 5*time.Second) + waitPortRefused(t, "tcp", h.addr("dot"), "Stop closing the DoT listener") + + release() + res, err := co.ReadMsg() + if err != nil { + t.Fatalf("the in-flight DoT query was lost across Stop: %v", err) + } + if a := answerAddr(res); a != "203.0.113.9" { + t.Errorf("A = %q, want 203.0.113.9 (reply: %v)", a, res) + } + if err := awaitStop(t, stopped, 3*time.Second); err != nil { + t.Errorf("Stop: %v", err) + } + if got := h.srv.Stats().Inflight; got != 0 { + t.Errorf("Stats().Inflight = %d after Stop returned, want 0", got) + } + }) + + // UDP is the transport that cannot make the promise the other three keep. + // There is no connection: the answer goes out on the very socket the + // query arrived on, so a socket closed before the query has been answered + // loses the datagram outright and the client has nothing but its own + // retry. Stop therefore has to let the queries already in the pipeline + // finish before it closes that socket, and the test pins that it does. + t.Run("udp", func(t *testing.T) { + h := newHarness(t, nil) + release := holdOnce(t, h.fake) + pc, err := net.ListenPacket("udp", "127.0.0.1:0") + if err != nil { + t.Fatalf("listen: %v", err) + } + t.Cleanup(func() { _ = pc.Close() }) + wire, err := question("inflight-shutdown.test.", dns.TypeA).Pack() + if err != nil { + t.Fatalf("pack: %v", err) + } + addr, err := net.ResolveUDPAddr("udp", h.addr("udp")) + if err != nil { + t.Fatalf("resolve: %v", err) + } + if _, err := pc.WriteTo(wire, addr); err != nil { + t.Fatalf("write: %v", err) + } + h.fake.waitArrived(t) + + // The probe is the opposite of the stream cases: a UDP port cannot be + // "refused", but Stop closing the socket is observable as the port + // becoming bindable. That also proves the drain finished — the close + // is the last thing the listener's close func does, after the + // in-flight packets have been answered. + stopped := startStop(h.srv, 5*time.Second) + waitPortFree(t, "udp", h.addr("udp"), "Stop draining and closing the UDP listener") + + release() + _ = pc.SetReadDeadline(time.Now().Add(3 * time.Second)) + buf := make([]byte, 4096) + n, _, err := pc.ReadFrom(buf) + if err != nil { + t.Fatalf("the in-flight UDP query was lost across Stop: %v", err) + } + res := new(dns.Msg) + if err := res.Unpack(buf[:n]); err != nil { + t.Fatalf("unpack: %v", err) + } + if a := answerAddr(res); a != "203.0.113.9" { + t.Errorf("A = %q, want 203.0.113.9 (reply: %v)", a, res) + } + if err := awaitStop(t, stopped, 3*time.Second); err != nil { + t.Errorf("Stop: %v", err) + } + // Stop waited for the pipeline, so the app's cache snapshot that + // follows it cannot race a query that is still writing to it. + if got := h.srv.Stats().Inflight; got != 0 { + t.Errorf("Stats().Inflight = %d after Stop returned, want 0", got) + } + }) } // TestStopWithNoQueryInFlightReturnsAndStartsAgain: an idle Stop has nothing @@ -377,3 +483,159 @@ func TestStopWithNoQueryInFlightReturnsAndStartsAgain(t *testing.T) { t.Errorf("Stats().Inflight = %d, want 0", got) } } + +// TestStopIsNotBlockedByAnIdleStreamConnection is the other half of shutdown: +// a client that connects and says nothing must not be able to hold the +// process open. +// +// The stream loop waits for its connections before Stop returns, and a +// connection parked in ReadMsg with no deadline in front of it only ends when +// the client goes away — the context is checked between reads, not during one. +// So the grace period the caller gave Stop (15s in main) used to be spent +// waiting for idle sockets, and Stop then returned context.DeadlineExceeded, +// which the app logs as "shutdown completed with errors". A client that +// opens a TCP connection and never sends a query is also trivially cheap to +// make, so this is a shutdown DoS rather than an edge case. +// +// The DoT subtest sets a 60s idle timeout on purpose: a config value must not +// be able to hold a shutdown hostage, and the harness default (2s) would hide +// a regression behind a lucky tick. +func TestStopIsNotBlockedByAnIdleStreamConnection(t *testing.T) { + for _, transport := range []string{"tcp", "dot"} { + t.Run(transport, func(t *testing.T) { + h := newHarness(t, func(c *config.Config) { + c.Server.Timeouts.TLS = config.Duration(60 * time.Second) + }) + conn := h.idleStream(t, transport) + // One query has been exchanged, so the server has accepted the + // connection and is inside ReadMsg waiting for a second one that + // never comes. Nothing is written and nothing is read from here. + + // The bound is the caller's, not Stop's: a correct Stop returns + // long before this fires, and a wrong one comes back with + // context.DeadlineExceeded and an error message that names the + // cause. + ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second) + defer cancel() + stopErr := h.srv.Stop(ctx) + if stopErr != nil { + t.Fatalf("Stop with an idle %s connection open = %v: a client that never sends a query must not be able to spend the whole shutdown grace period", transport, stopErr) + } + // Stop did not just give up on the connection, it ended it: the + // client must see the socket go away rather than sit there until + // its own deadline. A timeout error here is the tell — the server + // is still holding the connection and nothing closed it. + _ = conn.SetReadDeadline(time.Now().Add(2 * time.Second)) + buf := make([]byte, 1) + if _, err := conn.Read(buf); err == nil { + t.Fatalf("the server sent %d bytes on a connection with no query on it", len(buf)) + } else if ne, ok := err.(net.Error); ok && ne.Timeout() { + t.Errorf("the idle %s connection was still open 2s after Stop returned", transport) + } + }) + } +} + +// TestStopLeavesNoGoroutineRunningServerCode: Stop returning means the +// listeners are done, and if a goroutine of ours is still inside the package +// after that, the process is not. That matters twice over — the app snapshots +// the cache and closes the store the moment Stop returns, so anything still +// running can write to a closed store; and a goroutine blocked in a read on a +// listener that is never closed again is a leak that a long-lived process +// accumulates one connection at a time. +// +// The check counts goroutines whose stack still has a frame in this package +// rather than comparing runtime.NumGoroutine() against a baseline: the test +// binary shares its process with net/http, crypto/tls and the race detector's +// own goroutines, so a raw count is noise. A frame in this package cannot +// appear in any of those. +func TestStopLeavesNoGoroutineRunningServerCode(t *testing.T) { + h := newHarness(t, nil) + // Every transport, plus the two shapes that keep goroutines alive after a + // query is answered: a connection nobody has closed and an HTTP client + // with a keep-alive connection in it. + for _, transport := range []string{"udp", "tcp", "dot", "doh", "doh-post"} { + if a := answerAddr(h.ask(transport, "leak."+transport+".test.", dns.TypeA)); a != "203.0.113.9" { + t.Fatalf("%s query before the leak check returned %q", transport, a) + } + } + // An accepted connection that then goes quiet is the goroutine a leak + // check has to be able to see: it is the one a shutdown can strand. + _ = h.idleStream(t, "tcp") + + if err := stopWithin(t, h.srv, 3*time.Second); err != nil { + t.Fatalf("Stop: %v", err) + } + // Polled, not sampled once: a goroutine that is on its way out is not a + // leak, and the drain and Shutdown paths hand work to other goroutines + // (net/http's, the h2 server's) that finish just after Stop returns. Only + // a goroutine that is *still* there after a second is a leak. + deadline := time.Now().Add(3 * time.Second) + var leaked []string + for { + leaked = serverGoroutines() + if len(leaked) == 0 { + break + } + if time.Now().After(deadline) { + for _, g := range leaked { + t.Errorf("still running 3s after Stop returned:\n%s", g) + } + t.FailNow() + } + time.Sleep(25 * time.Millisecond) + } +} + +// serverGoroutines returns the stack of every goroutine that has a frame in +// this package, except the caller's own: the test function is itself in this +// package, so without the exclusion every run would find exactly one. +func serverGoroutines() []string { + self := goroutineID() + buf := make([]byte, 64<<10) + for { + n := runtime.Stack(buf, true) + if n < len(buf) { + buf = buf[:n] + break + } + buf = make([]byte, 2*len(buf)) + } + var out []string + for _, g := range strings.Split(string(buf), "\n\n") { + if !strings.Contains(g, "fancy-dns/internal/server.") { + continue + } + // "goroutine 775 [running]:" — the id is the second field, and the + // caller's own block is the one this scan must not report. + if fields := strings.Fields(g); len(fields) >= 2 { + if n, err := strconv.ParseUint(fields[1], 10, 64); err == nil && n == self { + continue + } + } + if id, _, ok := strings.Cut(g, " "); ok { + if n, err := strconv.ParseUint(strings.TrimPrefix(id, "goroutine"), 10, 64); err == nil && n == self { + continue + } + } + out = append(out, g) + } + return out +} + +// goroutineID returns the id of the calling goroutine. runtime has no API for +// it, but every stack dump starts with "goroutine N [state]:", and the +// current goroutine's dump with all=false is the one place that is printed. +func goroutineID() uint64 { + var buf [64]byte + n := runtime.Stack(buf[:], false) + fields := strings.Fields(string(buf[:n])) + if len(fields) < 2 { + return 0 + } + id, err := strconv.ParseUint(fields[1], 10, 64) + if err != nil { + return 0 + } + return id +}