1 Commits
Author SHA1 Message Date
sneak 68c3c66061 log: write durations as text, not nanoseconds (closes #228)
check / check (push) Successful in 1m21s
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
2026-10-02 06:35:40 +00:00
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 # 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 - 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). 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 - 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, "endpoint", endpoint,
"attempt", attempt+1, "attempt", attempt+1,
"maxAttempts", cfg.MaxRetries+1, "maxAttempts", cfg.MaxRetries+1,
"retryIn", delay, // As text: the JSON log writes a time.Duration as
// bare nanoseconds.
"retryIn", delay.String(),
"error", lastErr, "error", lastErr,
) )
+45
View File
@@ -2,6 +2,7 @@ package notify_test
import ( import (
"context" "context"
"encoding/json"
"errors" "errors"
"net/http" "net/http"
"net/http/httptest" "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( func TestDeliverWithRetryRespectsContextCancellation(
t *testing.T, t *testing.T,
) { ) {
+3 -1
View File
@@ -193,7 +193,9 @@ func (c *Checker) checkConnection(
c.log.Debug( c.log.Debug(
"port check succeeded", "port check succeeded",
"target", target, "target", target,
"latency", latency, // As text: the JSON log writes a time.Duration as bare
// nanoseconds.
"latency", latency.String(),
) )
return &PortResult{ return &PortResult{
+4 -2
View File
@@ -123,8 +123,10 @@ func (w *Watcher) Run(ctx context.Context) {
"watcher starting", "watcher starting",
"domains", len(w.config.Domains), "domains", len(w.config.Domains),
"hostnames", len(w.config.Hostnames), "hostnames", len(w.config.Hostnames),
"dnsInterval", w.config.DNSInterval, // As text: the JSON log writes a time.Duration as bare
"tlsInterval", w.config.TLSInterval, // nanoseconds.
"dnsInterval", w.config.DNSInterval.String(),
"tlsInterval", w.config.TLSInterval.String(),
) )
w.RunOnce(ctx) w.RunOnce(ctx)