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 now do it through logFailedLookup, which logs
nothing when the watcher's context was 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

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