From 8debca746ba45eb3687aaf3698300fc28e602acf Mon Sep 17 00:00:00 2001 From: Benjamin Borbe Date: Thu, 13 Aug 2026 21:56:57 +0200 Subject: [PATCH 1/2] fix: stamp dedup entries with the injectable libtime clock The four notifiers recorded dedup timestamps with time.Now(), so TTL expiry could only be exercised by sleeping -- every notify test currently does time.Sleep(60ms) for exactly that reason. libtime.Now is a package-level var, so this needs no signature change on any of the four public constructors; a test can swap the clock and drive expiry deterministically. --- CHANGELOG.md | 4 ++++ pkg/notify/log.go | 4 +++- pkg/notify/notify.go | 3 ++- pkg/notify/openclaw.go | 3 ++- pkg/notify/telegram.go | 3 ++- 5 files changed, 13 insertions(+), 4 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 7c28415..6e5dcd2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,10 @@ All notable changes to this project will be documented in this file. +## Unreleased + +- fix: stamp notification dedup entries with the injectable libtime clock instead of time.Now + ## v0.19.3 - chore: Delete tools.go — tool CLIs no longer declared as module dependencies; pinned via tools.env and `go run pkg@$(VERSION)` in Makefile diff --git a/pkg/notify/log.go b/pkg/notify/log.go index 3ca5961..0ffac7f 100644 --- a/pkg/notify/log.go +++ b/pkg/notify/log.go @@ -9,6 +9,8 @@ import ( "log/slog" "sync" "time" + + libtime "github.com/bborbe/time" ) // NewLogNotifier returns a Notifier that logs notifications to stdout instead of sending HTTP requests. @@ -41,7 +43,7 @@ func (l *logNotifier) Notify(_ context.Context, notification Notification) error ) return nil } - l.seen[key] = time.Now() + l.seen[key] = libtime.Now() l.mu.Unlock() slog.Info("log notifier: task event", diff --git a/pkg/notify/notify.go b/pkg/notify/notify.go index 3e76f53..e8ca3b1 100644 --- a/pkg/notify/notify.go +++ b/pkg/notify/notify.go @@ -16,6 +16,7 @@ import ( "time" "github.com/bborbe/errors" + libtime "github.com/bborbe/time" ) // Notification holds the data sent to the webhook. @@ -65,7 +66,7 @@ func (n *notifier) Notify(ctx context.Context, notification Notification) error ) return nil } - n.seen[key] = time.Now() + n.seen[key] = libtime.Now() n.mu.Unlock() body, err := json.Marshal(notification) diff --git a/pkg/notify/openclaw.go b/pkg/notify/openclaw.go index 7e87752..9bb1667 100644 --- a/pkg/notify/openclaw.go +++ b/pkg/notify/openclaw.go @@ -16,6 +16,7 @@ import ( "time" "github.com/bborbe/errors" + libtime "github.com/bborbe/time" ) // openClawPayload is the JSON payload sent to the OpenClaw /hooks/wake endpoint. @@ -64,7 +65,7 @@ func (n *openClawNotifier) Notify(ctx context.Context, notification Notification ) return nil } - n.seen[key] = time.Now() + n.seen[key] = libtime.Now() n.mu.Unlock() payload := openClawPayload{ diff --git a/pkg/notify/telegram.go b/pkg/notify/telegram.go index 9ef092e..e6468c9 100644 --- a/pkg/notify/telegram.go +++ b/pkg/notify/telegram.go @@ -16,6 +16,7 @@ import ( "time" "github.com/bborbe/errors" + libtime "github.com/bborbe/time" ) // telegramPayload is the JSON payload sent to the Telegram Bot API sendMessage endpoint. @@ -85,7 +86,7 @@ func (t *telegramNotifier) Notify(ctx context.Context, notification Notification ) return nil } - t.seen[key] = time.Now() + t.seen[key] = libtime.Now() t.mu.Unlock() payload := telegramPayload{ From dbc916320b179a39a6518a108a3a533187336342 Mon Sep 17 00:00:00 2001 From: Benjamin Borbe Date: Thu, 13 Aug 2026 22:28:06 +0200 Subject: [PATCH 2/2] fix: read the dedup TTL from the same clock it is written with The first revision of this PR converted only the write -- seen[key] = libtime.Now() -- and left the read as time.Since(lastSent). That is a mixed clock: under a fake clock the entry carries fake time while expiry is measured against the real one, so advancing the clock past the TTL never expires the entry. This is exactly the regression a reviewer caught in bborbe/log#13, and the bot caught it here. Convert the read as well, and add a spec that advances a fake clock past the TTL and asserts the notification is emitted again -- it fails against the half-converted code. --- CHANGELOG.md | 3 ++- pkg/notify/log.go | 2 +- pkg/notify/log_test.go | 38 ++++++++++++++++++++++++++++++++++++++ pkg/notify/notify.go | 2 +- pkg/notify/openclaw.go | 2 +- pkg/notify/telegram.go | 2 +- 6 files changed, 44 insertions(+), 5 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 6e5dcd2..d4c4b54 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,7 +4,8 @@ All notable changes to this project will be documented in this file. ## Unreleased -- fix: stamp notification dedup entries with the injectable libtime clock instead of time.Now +- fix: stamp AND expire notification dedup entries with the injectable libtime clock (both sides, not just the write) +- test: add a fake-clock regression spec proving TTL expiry without sleeping ## v0.19.3 diff --git a/pkg/notify/log.go b/pkg/notify/log.go index 0ffac7f..0387f2b 100644 --- a/pkg/notify/log.go +++ b/pkg/notify/log.go @@ -33,7 +33,7 @@ func (l *logNotifier) Notify(_ context.Context, notification Notification) error l.mu.Lock() lastSent, exists := l.seen[key] - if exists && time.Since(lastSent) < l.dedupTTL { + if exists && libtime.Now().Sub(lastSent) < l.dedupTTL { l.mu.Unlock() slog.Debug("log notifier skipped (duplicate within TTL)", "task", notification.TaskName, diff --git a/pkg/notify/log_test.go b/pkg/notify/log_test.go index f176f1a..e6134f8 100644 --- a/pkg/notify/log_test.go +++ b/pkg/notify/log_test.go @@ -11,6 +11,7 @@ import ( "strings" "time" + libtime "github.com/bborbe/time" . "github.com/onsi/ginkgo/v2" . "github.com/onsi/gomega" @@ -130,3 +131,40 @@ var _ = Describe("LogNotifier", func() { Expect(strings.Count(buf.String(), "log notifier: task event")).To(Equal(2)) }) }) + +var _ = Describe("LogNotifier dedup clock", func() { + var originalNow func() time.Time + var ctx context.Context + + BeforeEach(func() { originalNow = libtime.Now; ctx = context.Background() }) + AfterEach(func() { libtime.Now = originalNow }) + + // Regression: the dedup write and the TTL read must use the SAME clock. + // Before this fix the entry was stamped with libtime.Now() but expiry was + // measured with time.Since(), so advancing a fake clock past the TTL did + // not expire the entry and the second notify was still suppressed. + It("expires a dedup entry when the injected clock passes the TTL", func() { + current := time.Date(2026, 8, 13, 12, 0, 0, 0, time.UTC) + libtime.Now = func() time.Time { return current } + + var buf bytes.Buffer + slog.SetDefault(slog.New(slog.NewTextHandler(&buf, nil))) + + notifier := notify.NewLogNotifier(50 * time.Millisecond) + n := notify.Notification{TaskName: "t", Phase: "p"} + + Expect(notifier.Notify(ctx, n)).To(Succeed()) + first := strings.Count(buf.String(), "log notifier: task event") + + // Same instant: still inside the TTL, so this one is deduped. + Expect(notifier.Notify(ctx, n)).To(Succeed()) + Expect(strings.Count(buf.String(), "log notifier: task event")).To(Equal(first)) + + // Advance the injected clock past the TTL -- no real sleeping. + current = current.Add(time.Second) + Expect(notifier.Notify(ctx, n)).To(Succeed()) + Expect( + strings.Count(buf.String(), "log notifier: task event"), + ).To(BeNumerically(">", first)) + }) +}) diff --git a/pkg/notify/notify.go b/pkg/notify/notify.go index e8ca3b1..f7d1a46 100644 --- a/pkg/notify/notify.go +++ b/pkg/notify/notify.go @@ -56,7 +56,7 @@ func (n *notifier) Notify(ctx context.Context, notification Notification) error n.mu.Lock() lastSent, exists := n.seen[key] - if exists && time.Since(lastSent) < n.dedupTTL { + if exists && libtime.Now().Sub(lastSent) < n.dedupTTL { n.mu.Unlock() slog.Debug("webhook skipped (duplicate within TTL)", "task", notification.TaskName, diff --git a/pkg/notify/openclaw.go b/pkg/notify/openclaw.go index 9bb1667..9612211 100644 --- a/pkg/notify/openclaw.go +++ b/pkg/notify/openclaw.go @@ -55,7 +55,7 @@ func (n *openClawNotifier) Notify(ctx context.Context, notification Notification n.mu.Lock() lastSent, exists := n.seen[key] - if exists && time.Since(lastSent) < n.dedupTTL { + if exists && libtime.Now().Sub(lastSent) < n.dedupTTL { n.mu.Unlock() slog.Debug("webhook skipped (duplicate within TTL)", "task", notification.TaskName, diff --git a/pkg/notify/telegram.go b/pkg/notify/telegram.go index e6468c9..12d4693 100644 --- a/pkg/notify/telegram.go +++ b/pkg/notify/telegram.go @@ -76,7 +76,7 @@ func (t *telegramNotifier) Notify(ctx context.Context, notification Notification t.mu.Lock() lastSent, exists := t.seen[key] - if exists && time.Since(lastSent) < t.dedupTTL { + if exists && libtime.Now().Sub(lastSent) < t.dedupTTL { t.mu.Unlock() slog.Debug("telegram skipped (duplicate within TTL)", "task", notification.TaskName,