From e3c02b4045276c5f9d9e56e523b8a97f6184d66e Mon Sep 17 00:00:00 2001 From: sneak Date: Fri, 2 Oct 2026 06:04:46 +0000 Subject: [PATCH] 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 | 2 + internal/watcher/cancelled_test.go | 72 ++++++++++++++++++++++++++++++ internal/watcher/export_test.go | 6 +++ internal/watcher/watcher.go | 28 ++++++++++-- 4 files changed, 104 insertions(+), 4 deletions(-) diff --git a/TODO.md b/TODO.md index 41521ae..0ed2e3a 100644 --- a/TODO.md +++ b/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 diff --git a/internal/watcher/cancelled_test.go b/internal/watcher/cancelled_test.go index 7d600d2..5d83bc1 100644 --- a/internal/watcher/cancelled_test.go +++ b/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) + } +} diff --git a/internal/watcher/export_test.go b/internal/watcher/export_test.go index 218a566..863bb2a 100644 --- a/internal/watcher/export_test.go +++ b/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, diff --git a/internal/watcher/watcher.go b/internal/watcher/watcher.go index 001ee95..6a76074 100644 --- a/internal/watcher/watcher.go +++ b/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,