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

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)
+	}
+}