From ceb24c5004e81f1647888948d566723178aea3ca Mon Sep 17 00:00:00 2001
From: clawbot <35+clawbot@noreply.example.org>
Date: Fri, 2 Oct 2026 08:37:47 +0200
Subject: [PATCH] log: write durations as text, not nanoseconds (closes #228)

The JSON log wrote a Go duration as a bare count of nanoseconds, so
the watcher starting line showed dnsInterval 120000000000 for 2m and a
delivery retry showed retryIn 1015437050. Each duration logged is now
passed through its String() form: dnsInterval and tlsInterval when the
watcher starts, retryIn on a delivery retry, and latency on a
succeeded port check. A test checks that retryIn is logged as the
text of the wait the retry actually took.

The request log's latency_ms is left as it is: its key names its
unit.

Model: opus-5-5
---
 TODO.md                         |  2 ++
 internal/notify/retry.go        |  4 ++-
 internal/notify/retry_test.go   | 45 +++++++++++++++++++++++++++++++++
 internal/portcheck/portcheck.go |  4 ++-
 internal/watcher/watcher.go     |  6 +++--
 5 files changed, 57 insertions(+), 4 deletions(-)

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)