diff --git a/TODO.md b/TODO.md index e456bf2..6de64a5 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: durations in the log are written as text such as `2m0s`, not as a + bare count of nanoseconds (closes #228). - 2026-10-02: a watched name whose nameservers answer with a CNAME and no address gets port and TLS checks at the end of its CNAME chain (closes #203). - 2026-10-02: a resolver test that reads one record type from a nameserver's diff --git a/internal/notify/retry.go b/internal/notify/retry.go index 6745085..ccf6666 100644 --- a/internal/notify/retry.go +++ b/internal/notify/retry.go @@ -115,7 +115,9 @@ func (svc *Service) deliverWithRetry( "endpoint", endpoint, "attempt", attempt+1, "maxAttempts", cfg.MaxRetries+1, - "retryIn", delay, + // As text: the JSON log writes a time.Duration as + // bare nanoseconds. + "retryIn", delay.String(), "error", lastErr, ) diff --git a/internal/notify/retry_test.go b/internal/notify/retry_test.go index 878e1bf..4d47897 100644 --- a/internal/notify/retry_test.go +++ b/internal/notify/retry_test.go @@ -2,6 +2,7 @@ package notify_test import ( "context" + "encoding/json" "errors" "net/http" "net/http/httptest" @@ -189,6 +190,50 @@ func TestDeliverWithRetryExhaustsAttempts(t *testing.T) { } } +// TestDeliverWithRetryLogsRetryInAsText checks that the wait +// before a retry is logged as text such as "1.02s", not as a +// count of nanoseconds. +func TestDeliverWithRetryLogsRetryInAsText(t *testing.T) { + t.Parallel() + + svc, logs := newLoggingService(http.DefaultTransport) + svc.SetRetryConfig(notify.RetryConfig{ + MaxRetries: 1, + BaseDelay: time.Second, + MaxDelay: time.Second, + }) + + var waited time.Duration + + svc.SetSleepFunc(func(d time.Duration) <-chan time.Time { + waited = d + + return instantSleep(d) + }) + + _ = svc.DeliverWithRetry( + context.Background(), "test", + func(_ context.Context) error { + return errFail + }, + ) + + // With one retry, only the first failure is logged. + var record map[string]any + + err := json.Unmarshal([]byte(logs.String()), &record) + if err != nil { + t.Fatalf("log is not one JSON record: %v\n%s", err, logs) + } + + if record["retryIn"] != waited.String() { + t.Errorf( + "retryIn logged as %v, want %q", + record["retryIn"], waited.String(), + ) + } +} + func TestDeliverWithRetryRespectsContextCancellation( t *testing.T, ) { diff --git a/internal/portcheck/portcheck.go b/internal/portcheck/portcheck.go index a57b230..3d795b2 100644 --- a/internal/portcheck/portcheck.go +++ b/internal/portcheck/portcheck.go @@ -193,7 +193,9 @@ func (c *Checker) checkConnection( c.log.Debug( "port check succeeded", "target", target, - "latency", latency, + // As text: the JSON log writes a time.Duration as bare + // nanoseconds. + "latency", latency.String(), ) return &PortResult{ diff --git a/internal/watcher/watcher.go b/internal/watcher/watcher.go index ac0cd58..4e006cc 100644 --- a/internal/watcher/watcher.go +++ b/internal/watcher/watcher.go @@ -123,8 +123,10 @@ func (w *Watcher) Run(ctx context.Context) { "watcher starting", "domains", len(w.config.Domains), "hostnames", len(w.config.Hostnames), - "dnsInterval", w.config.DNSInterval, - "tlsInterval", w.config.TLSInterval, + // As text: the JSON log writes a time.Duration as bare + // nanoseconds. + "dnsInterval", w.config.DNSInterval.String(), + "tlsInterval", w.config.TLSInterval.String(), ) w.RunOnce(ctx)