log: write durations as text, not nanoseconds (closes #228)
check / check (push) Canceled after 0s

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
This commit was merged in pull request #239.
This commit is contained in:
2026-10-02 08:37:47 +02:00
parent ee4cadbd05
commit ceb24c5004
5 changed files with 57 additions and 4 deletions
+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)