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

@@ -19,6 +19,10 @@ trial run of the finished image: https://git.eeqj.de/sneak/dnswatcher/issues/149
 
 # Completed Steps
 
+- 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/resolver/export_test.go

@@ -11,6 +11,13 @@ func ExtractRecordValue(rr dns.RR) string {
 	return extractRecordValue(rr)
 }
 
+// CollectAnswerRecords exports collectAnswerRecords for testing.
+func CollectAnswerRecords(msg *dns.Msg, resp *NameserverResponse) {
+	var state queryState
+
+	collectAnswerRecords(msg, resp, &state)
+}
+
 // UsableReply exports usableReply for testing.
 func UsableReply(resp *dns.Msg, zone string, name string) bool {
 	return usableReply(resp, zone, name)

internal/resolver/iterative.go

@@ -714,6 +714,10 @@ func (r *Resolver) querySingleType(
 	collectAnswerRecords(msg, resp, state)
 }
 
+// collectAnswerRecords adds the records in msg's answer to resp, each
+// value once per record type. For a name with a CNAME, a nameserver
+// answers a query of any type with that CNAME, so the same value comes
+// in the answer to every type asked for.
 func collectAnswerRecords(
 	msg *dns.Msg,
 	resp *NameserverResponse,
@@ -726,9 +730,12 @@ func collectAnswerRecords(
 		}
 
 		typeName := dns.TypeToString[rr.Header().Rrtype]
+		if !slices.Contains(resp.Records[typeName], val) {
 			resp.Records[typeName] = append(
 				resp.Records[typeName], val,
 			)
+		}
+
 		state.hasRecords = true
 	}
 }

internal/resolver/iterative_test.go

@@ -238,6 +238,38 @@ func TestExtractRecordValue_LetterCase(t *testing.T) {
 	}
 }
 
+// TestCollectAnswerRecords_CNAMEOnce collects the answers a nameserver
+// gives for a name with a CNAME, one for each record type a check asks
+// for. Each answer holds the CNAME, which must be stored once.
+func TestCollectAnswerRecords_CNAMEOnce(t *testing.T) {
+	t.Parallel()
+
+	cname := &dns.CNAME{
+		Hdr: dns.RR_Header{
+			Name: "git.eeqj.de.", Rrtype: dns.TypeCNAME, Class: dns.ClassINET,
+		},
+		Target: "fsn1app1.datavi.be.",
+	}
+
+	resp := &resolver.NameserverResponse{Records: map[string][]string{}}
+
+	for _, qtype := range []uint16{
+		dns.TypeA, dns.TypeAAAA, dns.TypeCNAME, dns.TypeMX,
+		dns.TypeTXT, dns.TypeSRV, dns.TypeCAA, dns.TypeNS,
+	} {
+		msg := new(dns.Msg)
+		msg.SetQuestion("git.eeqj.de.", qtype)
+		msg.Answer = []dns.RR{cname}
+
+		resolver.CollectAnswerRecords(msg, resp)
+	}
+
+	assert.Equal(t,
+		map[string][]string{"CNAME": {"fsn1app1.datavi.be."}},
+		resp.Records,
+	)
+}
+
 // TestShuffled shuffles the root servers with many seeds. Every order
 // must hold each root server once, so each is tried before a
 // resolution fails; each root server must come first for some seed, so

internal/state/state.go

@@ -8,6 +8,7 @@ import (
 	"log/slog"
 	"os"
 	"path/filepath"
+	"slices"
 	"sync"
 	"time"
 
@@ -201,6 +202,19 @@ func (s *State) Load() error {
 		return fmt.Errorf("parsing state file: %w", err)
 	}
 
+	// A state file saved before each record value was stored once can
+	// hold a hostname's CNAME once for every record type asked for.
+	// Each value is kept once, so the first check does not see a
+	// record change.
+	for _, hs := range snapshot.Hostnames {
+		for _, ns := range hs.RecordsByNameserver {
+			for recordType, values := range ns.Records {
+				slices.Sort(values)
+				ns.Records[recordType] = slices.Compact(values)
+			}
+		}
+	}
+
 	s.snapshot = &snapshot
 	s.log.Info("loaded state from disk", "path", path)
 

internal/state/state_test.go

@@ -277,6 +277,59 @@ func TestLoadStateFromBeforeCNAMEAddresses(t *testing.T) {
 	}
 }
 
+// TestLoadStateWithRepeatedValues loads a state file saved when a
+// hostname's CNAME was stored once for every record type asked for.
+// Each value must load once, and every different value must load.
+func TestLoadStateWithRepeatedValues(t *testing.T) {
+	t.Parallel()
+
+	dir := t.TempDir()
+
+	data := []byte(`{
+		"version": 1,
+		"hostnames": {
+			"www.example.com": {
+				"recordsByNameserver": {
+					"ns1.example.com.": {
+						"records": {
+							"A": ["192.0.2.2", "192.0.2.1", "192.0.2.2", "192.0.2.1"],
+							"CNAME": ["a.example.net.", "a.example.net.", "a.example.net."]
+						},
+						"status": "ok"
+					}
+				}
+			}
+		}
+	}`)
+
+	err := os.WriteFile(filepath.Join(dir, "state.json"), data, 0o600)
+	if err != nil {
+		t.Fatalf("writing state file: %v", err)
+	}
+
+	s := state.NewForTestWithDataDir(dir)
+
+	err = s.Load()
+	if err != nil {
+		t.Fatalf("Load() error: %v", err)
+	}
+
+	hs, ok := s.GetHostnameState(testHostname)
+	if !ok {
+		t.Fatal("missing hostname " + testHostname)
+	}
+
+	want := map[string][]string{
+		"A":     {"192.0.2.1", "192.0.2.2"},
+		"CNAME": {"a.example.net."},
+	}
+
+	got := hs.RecordsByNameserver[testNS1].Records
+	if !reflect.DeepEqual(got, want) {
+		t.Errorf("records: got %v, want %v", got, want)
+	}
+}
+
 // TestSaveLoadRoundTrip_Hostnames verifies hostname data survives a save/load cycle.
 func TestSaveLoadRoundTrip_Hostnames(t *testing.T) {
 	t.Parallel()

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/inconsistency_test.go

@@ -183,3 +183,58 @@ func TestInconsistencyAlert(t *testing.T) {
 		})
 	}
 }
+
+// TestFirstCheckAfterRepeatedValuesLoaded saves a state file holding a
+// hostname's CNAME once for every record type asked for, as checks did
+// before each value was stored once, and two addresses each repeated,
+// and loads it. A check that then finds each value once at each
+// nameserver must notify nothing.
+func TestFirstCheckAfterRepeatedValuesLoaded(t *testing.T) {
+	t.Parallel()
+
+	const (
+		cnameType = "CNAME"
+		cname     = "c.example.net."
+	)
+
+	cfg := defaultTestConfig(t)
+	repeated := map[string][]string{
+		"A":       {ip2, ip1, ip2, ip1},
+		cnameType: {cname, cname, cname, cname, cname, cname, cname, cname},
+	}
+	once := map[string][]string{"A": {ip1, ip2}, cnameType: {cname}}
+
+	saved := newTestDeps(t, cfg).state
+	saved.SetHostnameState(host, hostnameState(map[string]map[string][]string{
+		nsA: repeated, nsB: repeated,
+	}))
+
+	err := saved.Save()
+	if err != nil {
+		t.Fatalf("saving the state file: %v", err)
+	}
+
+	deps := newTestDeps(t, cfg)
+
+	err = deps.state.Load()
+	if err != nil {
+		t.Fatalf("loading the state file: %v", err)
+	}
+
+	prev, ok := deps.state.GetHostnameState(host)
+	if !ok {
+		t.Fatal("the state file has no state for " + host)
+	}
+
+	current := hostnameState(map[string]map[string][]string{
+		nsA: once, nsB: once,
+	})
+
+	// The hostname change detection uses only the notifier.
+	w := watcher.NewForTest(nil, nil, nil, nil, nil, deps.notifier)
+	w.DetectHostnameChanges(t.Context(), host, prev, current)
+
+	if got := deps.notifier.getNotifications(); len(got) != 0 {
+		t.Errorf("sent %v, want no notification", got)
+	}
+}

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,