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 +}