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 watcher now logs a failed
lookup only when its context was not cancelled; the port and TLS checks
already return quietly. It asks the context, not the lookup's error,
because 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 as an
error. The tests run a check 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: a resolver test that reads one record type from a nameserver's
   answer asks again when that type is missing from it (closes #218).
 - 2026-10-02: a plain `docker build .` of a clone stamps its tag or short

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,70 @@ 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, and
+// looks up a nameserver's addresses, 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)
+
+	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 and the nameserver's address lookup 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)
+
+	const want = 3
+
+	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"
@@ -217,11 +218,14 @@ func (w *Watcher) checkDomain(
 ) {
 	nameservers, err := w.resolver.LookupNS(ctx, domain)
 	if err != nil {
-		w.log.Error(
-			"failed to lookup NS",
-			"domain", domain,
-			"error", err,
-		)
+		// Shutdown cancels ctx; a lookup it cut short did not fail.
+		if !errors.Is(ctx.Err(), context.Canceled) {
+			w.log.Error(
+				"failed to lookup NS",
+				"domain", domain,
+				"error", err,
+			)
+		}
 
 		return
 	}
@@ -257,11 +261,14 @@ func (w *Watcher) checkDomain(
 	// the domain's IP addresses.
 	results, err := w.resolver.LookupAllRecords(ctx, domain)
 	if err != nil {
-		w.log.Error(
-			"failed to lookup records for domain",
-			"domain", domain,
-			"error", err,
-		)
+		// Shutdown cancels ctx; a lookup it cut short did not fail.
+		if !errors.Is(ctx.Err(), context.Canceled) {
+			w.log.Error(
+				"failed to lookup records for domain",
+				"domain", domain,
+				"error", err,
+			)
+		}
 
 		return
 	}
@@ -337,11 +344,14 @@ func (w *Watcher) resolveNameserverAddresses(
 			continue
 		}
 
-		w.log.Error(
-			"no addresses found for nameserver",
-			"nameserver", ns,
-			"error", err,
-		)
+		// Shutdown cancels ctx; a lookup it cut short did not fail.
+		if !errors.Is(ctx.Err(), context.Canceled) {
+			w.log.Error(
+				"no addresses found for nameserver",
+				"nameserver", ns,
+				"error", err,
+			)
+		}
 
 		if prevIPs, ok := prev[ns]; ok {
 			addresses[ns] = prevIPs
@@ -389,11 +399,14 @@ func (w *Watcher) checkHostname(
 ) {
 	results, err := w.resolver.LookupAllRecords(ctx, hostname)
 	if err != nil {
-		w.log.Error(
-			"failed to lookup records",
-			"hostname", hostname,
-			"error", err,
-		)
+		// Shutdown cancels ctx; a lookup it cut short did not fail.
+		if !errors.Is(ctx.Err(), context.Canceled) {
+			w.log.Error(
+				"failed to lookup records",
+				"hostname", hostname,
+				"error", err,
+			)
+		}
 
 		return
 	}