diff --git a/CHANGELOG.md b/CHANGELOG.md index 7c28415..d4c4b54 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,11 @@ All notable changes to this project will be documented in this file. +## Unreleased + +- 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 - 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..0387f2b 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. @@ -31,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, @@ -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/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 3e76f53..f7d1a46 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. @@ -55,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, @@ -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..9612211 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. @@ -54,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, @@ -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..12d4693 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. @@ -75,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, @@ -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{