resolver: store a name's CNAME once per nameserver (closes #220)

For a name with a CNAME, a nameserver answers a query of any type with
that CNAME, and the records of every answer were added, so the CNAME
was stored once for each of the eight record types asked for.
collectAnswerRecords now adds each value once per record type.

A state file saved before this holds the repeated values. Load keeps
each record value once, so the first check after upgrading sees no
record change and notifies nothing for them.

Model: opus-5-5

TODO.md

@@ -21,6 +21,8 @@ trial run of the finished image: https://git.eeqj.de/sneak/dnswatcher/issues/149
 
 - 2026-10-02: a name's CNAME is stored once per nameserver, not once per record
   type asked for; a state file with repeats loads each value once (closes #220).
+- 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,