log: write durations as text, not nanoseconds (closes #228) #239

Merged
clawbot merged 1 commits from issue-228-log-durations-readable into next 2026-10-02 08:37:48 +02:00
5 changed files with 57 additions and 4 deletions
Showing only changes of commit 68c3c66061 - Show all commits
+2
View File
@@ -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
+3 -1
View File
@@ -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,
)
+45
View File
@@ -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,
) {
+3 -1
View File
@@ -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{
+4 -2
View File
@@ -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)