diff --git a/TODO.md b/TODO.md index 927a598..7b66ab5 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: a resolver test that reads one record type from a nameserver's answer asks again when that type is missing from it (closes #218). - 2026-10-02: a plain `docker build .` of a clone stamps its tag or short diff --git a/internal/watcher/cancelled_test.go b/internal/watcher/cancelled_test.go index 7d600d2..45ceb88 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,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) + } +} diff --git a/internal/watcher/export_test.go b/internal/watcher/export_test.go index 59f0319..0e2f7aa 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 bcee203..0008cb2 100644 --- a/internal/watcher/watcher.go +++ b/internal/watcher/watcher.go @@ -2,6 +2,7 @@ package watcher import ( "context" + "errors" "fmt" "log/slog" "slices" @@ -217,11 +218,14 @@ func (w *Watcher) checkDomain( ) { nameservers, err := w.resolver.LookupNS(ctx, domain) if err != nil { - w.log.Error( - "failed to lookup NS", - "domain", domain, - "error", err, - ) + // Shutdown cancels ctx; a lookup it cut short did not fail. + if !errors.Is(ctx.Err(), context.Canceled) { + w.log.Error( + "failed to lookup NS", + "domain", domain, + "error", err, + ) + } return } @@ -257,11 +261,14 @@ func (w *Watcher) checkDomain( // the domain's IP addresses. results, err := w.resolver.LookupAllRecords(ctx, domain) if err != nil { - w.log.Error( - "failed to lookup records for domain", - "domain", domain, - "error", err, - ) + // Shutdown cancels ctx; a lookup it cut short did not fail. + if !errors.Is(ctx.Err(), context.Canceled) { + w.log.Error( + "failed to lookup records for domain", + "domain", domain, + "error", err, + ) + } return } @@ -337,11 +344,14 @@ func (w *Watcher) resolveNameserverAddresses( continue } - w.log.Error( - "no addresses found for nameserver", - "nameserver", ns, - "error", err, - ) + // Shutdown cancels ctx; a lookup it cut short did not fail. + if !errors.Is(ctx.Err(), context.Canceled) { + w.log.Error( + "no addresses found for nameserver", + "nameserver", ns, + "error", err, + ) + } if prevIPs, ok := prev[ns]; ok { addresses[ns] = prevIPs @@ -389,11 +399,14 @@ func (w *Watcher) checkHostname( ) { results, err := w.resolver.LookupAllRecords(ctx, hostname) if err != nil { - w.log.Error( - "failed to lookup records", - "hostname", hostname, - "error", err, - ) + // Shutdown cancels ctx; a lookup it cut short did not fail. + if !errors.Is(ctx.Err(), context.Canceled) { + w.log.Error( + "failed to lookup records", + "hostname", hostname, + "error", err, + ) + } return }