watcher: a lookup cut short by shutdown is not logged as an error (closes #229)

Stopping dnswatcher during a DNS check logged every lookup the stop cut
short as an error, "context canceled". The four places in the watcher
that log a failed lookup, checkDomain, checkHostname,
resolveNameserverAddresses and resolveCNAMEAddresses, now do it through
logFailedLookup, which logs nothing when the watcher's context was
cancelled. It asks the context, not the lookup's error: the resolver
reports a cancelled lookup with its own error, which does not wrap
context.Canceled. A context whose deadline passed is not cancelled, so a
lookup that ran out of time is still logged. The tests run each of these
lookups on a cancelled context and on one whose deadline passed; neither
sends a query.

Model: opus-5-5

TODO.md

@@ -19,6 +19,8 @@ trial run of the finished image: https://git.eeqj.de/sneak/dnswatcher/issues/149
 
 # Completed Steps
 
+- 2026-10-02: a DNS lookup that shutdown cuts short logs no error; one that
+  fails otherwise, or runs out of time, still does (closes #229).
 - 2026-10-02: Record Change and Inconsistency notifications list only the record
   types that differ, each with its values as plain text (closes #219).
 - 2026-10-02: the startup notification no longer says every notification

internal/watcher/cancelled_test.go

@@ -1,10 +1,13 @@
 package watcher_test
 
 import (
+	"bytes"
 	"context"
 	"log/slog"
 	"reflect"
+	"strings"
 	"testing"
+	"time"
 
 	"sneak.berlin/go/dnswatcher/internal/portcheck"
 	"sneak.berlin/go/dnswatcher/internal/resolver"
@@ -79,3 +82,72 @@ func TestCancelledCheckSavesNothing(t *testing.T) {
 		t.Errorf("sent %v, want no notifications", notifications)
 	}
 }
+
+// newLoggingWatcher returns a watcher for a domain and a hostname, with
+// the real resolver, that writes what it logs at warning level or above
+// into the returned buffer.
+func newLoggingWatcher(t *testing.T) (*watcher.Watcher, *bytes.Buffer) {
+	t.Helper()
+
+	cfg := defaultTestConfig(t)
+	cfg.Domains = []string{testSmallDomain}
+	cfg.Hostnames = []string{host}
+
+	w, _ := newTestWatcher(t, cfg)
+
+	logs := &bytes.Buffer{}
+	w.SetLogger(slog.New(slog.NewJSONHandler(
+		logs, &slog.HandlerOptions{Level: slog.LevelWarn},
+	)))
+
+	return w, logs
+}
+
+// TestLookupCutShortIsNotLogged checks a domain and a hostname, looks
+// up a nameserver's addresses and follows a CNAME, with the context
+// cancelled, as shutdown leaves it. The real resolver fails each lookup
+// without sending a query. Shutdown cutting a lookup short is not a
+// failure, so nothing may be logged at warning level or above.
+func TestLookupCutShortIsNotLogged(t *testing.T) {
+	t.Parallel()
+
+	w, logs := newLoggingWatcher(t)
+
+	ctx, cancel := context.WithCancel(t.Context())
+	cancel()
+
+	w.RunOnce(ctx)
+	w.ResolveNameserverAddresses(ctx, []string{nsA}, nil)
+	w.ResolveCNAMEAddresses(ctx, host, cnameState(), nil)
+
+	if logs.Len() > 0 {
+		t.Errorf("logged at warning level or above:\n%s", logs)
+	}
+}
+
+// TestLookupOutOfTimeIsLoggedAsError does what
+// TestLookupCutShortIsNotLogged does, with the context's deadline passed
+// instead. A lookup that ran out of time did fail, so the domain's NS
+// lookup, the hostname's lookup, the nameserver's address lookup and the
+// CNAME's are each logged as an error.
+func TestLookupOutOfTimeIsLoggedAsError(t *testing.T) {
+	t.Parallel()
+
+	w, logs := newLoggingWatcher(t)
+
+	ctx, cancel := context.WithDeadline(t.Context(), time.Now())
+	t.Cleanup(cancel)
+
+	w.RunOnce(ctx)
+	w.ResolveNameserverAddresses(ctx, []string{nsA}, nil)
+	w.ResolveCNAMEAddresses(ctx, host, cnameState(), nil)
+
+	const want = 4
+
+	lines := strings.Count(logs.String(), "\n")
+	errorLines := strings.Count(logs.String(), `"level":"ERROR"`)
+
+	if lines != want || errorLines != want {
+		t.Errorf("logged:\n%s\nwant %d lines, each at error level", logs, want)
+	}
+}

internal/watcher/export_test.go

@@ -31,6 +31,12 @@ func NewForTest(
 	}
 }
 
+// SetLogger replaces the watcher's logger, so a test can read what it
+// logs.
+func (w *Watcher) SetLogger(log *slog.Logger) {
+	w.log = log
+}
+
 // NewlyDisagreeingPairs exports newlyDisagreeingPairs for testing.
 func NewlyDisagreeingPairs(
 	prev, current *state.HostnameState,

internal/watcher/watcher.go

@@ -2,6 +2,7 @@ package watcher
 
 import (
 	"context"
+	"errors"
 	"fmt"
 	"log/slog"
 	"slices"
@@ -213,13 +214,29 @@ func (w *Watcher) runDNSChecks(ctx context.Context) {
 	}
 }
 
+// logFailedLookup logs a failed DNS lookup at error level, unless ctx
+// was cancelled: shutdown cancels it, and a lookup it cut short did not
+// fail. A lookup that ran out of time did fail, so it is logged.
+func (w *Watcher) logFailedLookup(
+	ctx context.Context,
+	msg string,
+	args ...any,
+) {
+	if errors.Is(ctx.Err(), context.Canceled) {
+		return
+	}
+
+	w.log.Error(msg, args...)
+}
+
 func (w *Watcher) checkDomain(
 	ctx context.Context,
 	domain string,
 ) {
 	nameservers, err := w.resolver.LookupNS(ctx, domain)
 	if err != nil {
-		w.log.Error(
+		w.logFailedLookup(
+			ctx,
 			"failed to lookup NS",
 			"domain", domain,
 			"error", err,
@@ -320,7 +337,8 @@ func (w *Watcher) resolveNameserverAddresses(
 			continue
 		}
 
-		w.log.Error(
+		w.logFailedLookup(
+			ctx,
 			"no addresses found for nameserver",
 			"nameserver", ns,
 			"error", err,
@@ -372,7 +390,8 @@ func (w *Watcher) checkHostname(
 ) {
 	results, err := w.resolver.LookupAllRecords(ctx, hostname)
 	if err != nil {
-		w.log.Error(
+		w.logFailedLookup(
+			ctx,
 			"failed to lookup records",
 			"hostname", hostname,
 			"error", err,
@@ -455,7 +474,8 @@ func (w *Watcher) resolveCNAMEAddresses(
 	for target := range targets {
 		ips, err := w.resolver.ResolveIPAddresses(ctx, target)
 		if err != nil {
-			w.log.Error(
+			w.logFailedLookup(
+				ctx,
 				"failed to follow CNAME",
 				"hostname", hostname,
 				"target", target,