watcher: notify NS query failure and recovery (closes #104)

LookupAllRecords now returns each nameserver's response, so the
watcher saves its status: ok when it answered, NXDOMAIN and no records
included, and error with the reason when it timed out, answered
SERVFAIL or REFUSED, or could not be reached. A nameserver that starts
failing sends NS Failure and one that answers again sends NS Recovery.
A failing nameserver is left out of the record change and
inconsistency comparisons. The resolver used to report REFUSED and
network errors as an answer with no records; they are now errors. A
lookup cut short by its context now returns an error instead of a
failure of the nameserver it was querying.

Model: opus-5-5

TODO.md

@@ -21,8 +21,6 @@ Rationale, Design, TODO, License, Author) if any are still missing.
 
 - 2026-10-01: a nameserver that does not answer is saved as `error` with the
   reason, and NS failure and NS recovery are notified (closes #104).
-- 2026-10-01: notify shutdown tests use one timing constant per meaning, name
-  the bound they check, and require the drain's debug line (closes #116).
 - 2026-09-29: the live-DNS test package is renamed `internal/livednstest` and
   added to the `test-support` `deny` list in `.golangci.yml`, so `make lint`
   fails when program code imports it (closes #164).

internal/notify/shutdown_test.go

@@ -33,29 +33,10 @@ const (
 	// out.
 	drainDeadline = 50 * time.Millisecond
 
-	// timeoutDrainBound is how long a drain given drainDeadline
+	// drainSlack is the upper bound on how long a bounded
-	// may take to return before the test gives up on it.  At
+	// drain may take; generous enough for a loaded CI box,
-	// forty times drainDeadline it leaves ample room for
+	// still far below the 20s test ceiling.
-	// scheduling delay on a loaded box under -race, yet it is far
+	drainSlack = 2 * time.Second
-	// below the test binary's -timeout, so a drain that its
-	// deadline does not bound fails that one test instead of
-	// hanging the package.
-	timeoutDrainBound = 2 * time.Second
-
-	// longDrainDeadline is the deadline given to a drain that is
-	// expected to finish well before it: when the in-flight
-	// delivery completes after inFlightHold, or at once when
-	// nothing is in flight.  It is far above inFlightHold, so
-	// those drains never reach it, and four times
-	// idleDrainBound, so an idle drain that waited for its
-	// deadline instead of returning fails that bound.
-	longDrainDeadline = 2 * time.Second
-
-	// reachEndpointTimeout is how long a submitted delivery may
-	// take to reach the test server.  That normally takes a few
-	// milliseconds; the margin is for a loaded box under -race,
-	// and only a failing run ever waits this long.
-	reachEndpointTimeout = 2 * time.Second
 
 	// settleDelay is how long to wait before asserting that
 	// something did *not* happen.
@@ -65,11 +46,10 @@ const (
 	// nothing in flight.  It is deliberately far above the cost
 	// of the goroutine hop through inFlight.Wait() — which
 	// reached 57ms on a loaded box under -race with the package's
-	// parallel tests — and far below longDrainDeadline, the
+	// parallel tests — and far below drainSlack, the deadline
-	// deadline such a drain is given.  A drain that blocked until
+	// such a drain is given.  A drain that blocked until its
-	// its deadline instead of returning on the WaitGroup
+	// deadline instead of returning on the WaitGroup therefore
-	// therefore still fails this bound, but scheduling delay
+	// still fails this bound, but scheduling delay alone cannot.
-	// alone cannot.
 	idleDrainBound = 500 * time.Millisecond
 )
 
@@ -95,14 +75,12 @@ func (sb *syncBuffer) String() string {
 }
 
 // newLoggingService returns a Service writing JSON logs into
-// the returned buffer, debug level included.
+// the returned buffer.
 func newLoggingService(
 	transport http.RoundTripper,
 ) (*notify.Service, *syncBuffer) {
 	logs := &syncBuffer{}
-	handler := slog.NewJSONHandler(
+	handler := slog.NewJSONHandler(logs, nil)
-		logs, &slog.HandlerOptions{Level: slog.LevelDebug},
-	)
 
 	return notify.NewTestServiceWithLogger(transport, handler),
 		logs
@@ -156,7 +134,7 @@ func TestDrainWaitsForInFlightDelivery(t *testing.T) {
 	// drain begins.
 	select {
 	case <-entered:
-	case <-time.After(reachEndpointTimeout):
+	case <-time.After(drainSlack):
 		t.Fatal("delivery never reached the endpoint")
 	}
 
@@ -173,7 +151,7 @@ func TestDrainWaitsForInFlightDelivery(t *testing.T) {
 	defer timer.Stop()
 
 	ctx, cancel := context.WithTimeout(
-		context.Background(), longDrainDeadline,
+		context.Background(), drainSlack,
 	)
 	defer cancel()
 
@@ -279,11 +257,11 @@ func TestDrainBoundedByContextDeadline(t *testing.T) {
 
 	select {
 	case <-returned:
-	case <-time.After(timeoutDrainBound):
+	case <-time.After(drainSlack):
 		t.Fatalf(
 			"drain did not return within %v; its %v deadline "+
 				"did not bound it",
-			timeoutDrainBound, drainDeadline,
+			drainSlack, drainDeadline,
 		)
 	}
 
@@ -355,7 +333,7 @@ func TestDrainRefusesNewDeliveries(t *testing.T) {
 	svc.SetMattermostWebhookURL(target)
 
 	ctx, cancel := context.WithTimeout(
-		context.Background(), longDrainDeadline,
+		context.Background(), drainSlack,
 	)
 	defer cancel()
 
@@ -468,7 +446,7 @@ func TestNewRegistersDrainingStopHook(t *testing.T) {
 
 	select {
 	case <-entered:
-	case <-time.After(reachEndpointTimeout):
+	case <-time.After(drainSlack):
 		t.Fatal("delivery never reached the endpoint")
 	}
 
@@ -478,7 +456,7 @@ func TestNewRegistersDrainingStopHook(t *testing.T) {
 	defer timer.Stop()
 
 	ctx, cancel := context.WithTimeout(
-		context.Background(), longDrainDeadline,
+		context.Background(), drainSlack,
 	)
 	defer cancel()
 
@@ -509,7 +487,7 @@ func TestDrainWithoutDeliveriesReturnsImmediately(t *testing.T) {
 	start := time.Now()
 
 	ctx, cancel := context.WithTimeout(
-		context.Background(), longDrainDeadline,
+		context.Background(), drainSlack,
 	)
 	defer cancel()
 
@@ -517,9 +495,9 @@ func TestDrainWithoutDeliveriesReturnsImmediately(t *testing.T) {
 
 	if elapsed := time.Since(start); elapsed > idleDrainBound {
 		t.Errorf(
-			"drain of an idle service took %v, want at most "+
+			"drain of an idle service took %v, want well "+
-				"%v; its deadline was %v",
+				"under its %v deadline",
-			elapsed, idleDrainBound, longDrainDeadline,
+			elapsed, drainSlack,
 		)
 	}
 }
@@ -527,11 +505,10 @@ func TestDrainWithoutDeliveriesReturnsImmediately(t *testing.T) {
 // TestDrainWithCancelledContextDoesNotWarn verifies that an
 // OnStop context that is already dead on entry does not produce
 // an "abandoning them" warning when there was nothing in flight
-// to abandon, and that the drain returns and says at debug level
+// to abandon.  The expired context wins the select immediately,
-// that nothing was in flight.  The expired context wins the
+// so only the outstanding count can tell the difference between
-// select immediately, so only the outstanding count can tell the
+// a genuine timeout and a shutdown that had simply already run
-// difference between a genuine timeout and a shutdown that had
+// out of time with no work left.
-// simply already run out of time with no work left.
 func TestDrainWithCancelledContextDoesNotWarn(t *testing.T) {
 	t.Parallel()
 
@@ -540,43 +517,11 @@ func TestDrainWithCancelledContextDoesNotWarn(t *testing.T) {
 	ctx, cancel := context.WithCancel(context.Background())
 	cancel()
 
-	// A watchdog, as in TestDrainBoundedByContextDeadline, so
+	svc.Drain(ctx)
-	// that a drain which never returns fails here instead of
-	// hanging the package.
-	returned := make(chan struct{})
 
-	go func() {
+	if output := logs.String(); strings.Contains(
-		defer close(returned)
+		output, `"level":"WARN"`,
-
-		svc.Drain(ctx)
-	}()
-
-	select {
-	case <-returned:
-	case <-time.After(idleDrainBound):
-		t.Fatalf(
-			"drain with nothing in flight and a cancelled "+
-				"context did not return within %v",
-			idleDrainBound,
-		)
-	}
-
-	output := logs.String()
-
-	// The absence of a warning alone would also pass if the drain
-	// logged nothing at all, so require the debug line it writes
-	// when it finds nothing outstanding.
-	if !strings.Contains(
-		output, "all in-flight notifications completed",
 	) {
-		t.Errorf(
-			"drain did not log that nothing was in flight; "+
-				"log output: %s",
-			output,
-		)
-	}
-
-	if strings.Contains(output, `"level":"WARN"`) {
 		t.Errorf(
 			"drain with nothing in flight warned about "+
 				"abandoned deliveries; log output: %s",

internal/watcher/nsfailure_test.go

@@ -2,13 +2,11 @@ package watcher_test
 
 import (
 	"context"
-	"fmt"
 	"log/slog"
 	"strings"
 	"testing"
 	"time"
 
-	"sneak.berlin/go/dnswatcher/internal/livednstest"
 	"sneak.berlin/go/dnswatcher/internal/resolver"
 	"sneak.berlin/go/dnswatcher/internal/state"
 	"sneak.berlin/go/dnswatcher/internal/watcher"
@@ -154,7 +152,7 @@ func TestNSFailureAndRecoveryAlerts(t *testing.T) {
 	}
 }
 
-func TestNSFailureAlertNamesHostnameNameserverAndReason(t *testing.T) {
+func TestNSFailureAlertNamesNameserverAndReason(t *testing.T) {
 	t.Parallel()
 
 	records := map[string][]string{"A": {ip1}}
@@ -174,12 +172,9 @@ func TestNSFailureAlertNamesHostnameNameserverAndReason(t *testing.T) {
 	}
 
 	msg := notifications[0].Message
-	if !strings.Contains(msg, host) || !strings.Contains(msg, nsA) ||
+	if !strings.Contains(msg, nsA) ||
 		!strings.Contains(msg, failed().Error) {
-		t.Errorf(
+		t.Errorf("message %q does not name %s and the reason", msg, nsA)
-			"message %q does not name %s, %s and the reason",
-			msg, host, nsA,
-		)
 	}
 }
 
@@ -212,58 +207,3 @@ func TestNameserverThatNeverAnswers(t *testing.T) {
 		)
 	}
 }
-
-// TestNameserverThatAnswersNXDOMAIN asks a real nameserver about a name
-// that does not exist and checks what the watcher saves for it: NXDOMAIN
-// is an answer, so the nameserver is saved as ok with no error.
-func TestNameserverThatAnswersNXDOMAIN(t *testing.T) {
-	t.Parallel()
-
-	res := resolver.NewFromLogger(slog.Default())
-	name := "this-surely-does-not-exist-xyz." + testDomain
-
-	var (
-		ns   string
-		resp *resolver.NameserverResponse
-	)
-
-	livednstest.Retry(t, "QueryNameserver("+name+")", func(ctx context.Context) error {
-		nameservers, err := res.LookupNS(ctx, testDomain)
-		if err != nil {
-			return err
-		}
-
-		ns = nameservers[0]
-
-		resp, err = res.QueryNameserver(ctx, ns, name)
-		if err != nil {
-			return err
-		}
-
-		// A timeout or a failure is no answer to check.
-		if resp.Status == resolver.StatusTimeout ||
-			resp.Status == resolver.StatusError {
-			return fmt.Errorf(
-				"%w: %s: %s", livednstest.ErrNoAnswer, ns, resp.Error,
-			)
-		}
-
-		return nil
-	})
-
-	if resp.Status != resolver.StatusNXDomain {
-		t.Fatalf("%s answered %q for %s, want NXDOMAIN", ns, resp.Status, name)
-	}
-
-	hs := watcher.BuildHostnameState(
-		map[string]*resolver.NameserverResponse{ns: resp}, time.Now(),
-	)
-
-	got := hs.RecordsByNameserver[ns]
-	if got.Status != "ok" || got.Error != "" {
-		t.Errorf(
-			"saved status %q, error %q; want status ok with no error",
-			got.Status, got.Error,
-		)
-	}
-}