Finish the server shutdown tests; fix the two bugs they found
build / build-push (push) Successful in 22s

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.
This commit is contained in:
developer committed 2026-09-27 19:28:40 +00:00
1 parent 3a199bb310
commit b6d70a50fe
5 files changed
+526 -41

No files matched your search

+262
View File
@@ -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
}