Skip to content

Commit a1d7304

Browse files
alexluongclaude
andauthored
fix: handle duplicate log messages idempotently (#953)
* fix(logstore): tolerate intra-batch duplicate entries in InsertMany Duplicate log messages (MQ redelivery, producer re-publish) can land in the same batch. pglogstore's attempts INSERT uses ON CONFLICT DO UPDATE, which Postgres rejects when the same (time, id) appears twice in one statement (SQLSTATE 21000) — failing the whole batch. chlogstore accepted duplicates but paid merge overhead and surfaced transient duplicate reads until ReplacingMergeTree compaction. Make InsertMany tolerate intra-batch duplicates as part of the driver contract: dedupe entries by Attempt.ID (shared driver helper) in pglogstore and chlogstore. memlogstore already conforms via keyed upsert. Add a drivertest conformance case: a batch containing duplicate entries inserts without error and persists a single attempt row. Part of #947 Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> * fix(logmq): dedup duplicate messages by attempt ID within a batch At-least-once redelivery and producer re-publish (deliverymq retrying after a post-publish error) can land multiple copies of the same log entry in one batch — possibly under different MQ message IDs, so dedup keys on Attempt.ID. Previously duplicates flowed into InsertMany (where they crashed pglogstore, see #946) and re-ran alert evaluation once per copy. Drop duplicates while parsing: ack the duplicate copy immediately and keep the first. Safe because copies are byte-identical and the kept copy stays un-acked until persisted — the at-least-once guarantee rides on it. Alert eval now runs once per unique attempt per batch. Part of #947 Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> * fix(alert): skip re-evaluating replayed attempts once fully processed Alert evaluation already dedups counting by attempt ID (SADD), but the "newly added" signal was discarded — every replayed copy of an attempt (MQ redelivery, producer re-publish) re-ran the full evaluation and re-emitted alerts. Track an evaluated marker per attempt: IncrementConsecutiveFailureCount now returns FailureCountResult{Count, NewlyCounted, AlreadyEvaluated}, and the monitor marks the attempt evaluated (cfeval set, 24h TTL) only after the full evaluation succeeds. Replays of fully evaluated attempts are skipped; attempts counted but never marked (eval failed mid-way, the message was nacked) fall through and re-run as recovery — a naive early-exit on already-counted would silently drop those alerts. Marking is non-fatal: on failure the attempt re-evaluates on replay, matching previous behavior. Reset clears both keys. Part of #947 Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> --------- Co-authored-by: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
1 parent 25ddeea commit a1d7304

10 files changed

Lines changed: 435 additions & 45 deletions

File tree

internal/alert/monitor.go

Lines changed: 27 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -146,11 +146,25 @@ func (m *alertMonitor) HandleAttempt(ctx context.Context, attempt DeliveryAttemp
146146
}
147147

148148
// Consecutive failure tracking
149-
count, err := m.store.IncrementConsecutiveFailureCount(ctx, attempt.Destination.TenantID, attempt.Destination.ID, attempt.Attempt.ID)
149+
res, err := m.store.IncrementConsecutiveFailureCount(ctx, attempt.Destination.TenantID, attempt.Destination.ID, attempt.Attempt.ID)
150150
if err != nil {
151151
return fmt.Errorf("failed to get alert state: %w", err)
152152
}
153153

154+
// Replayed attempt (MQ redelivery, producer re-publish) that already
155+
// completed a full evaluation — skip re-emitting alerts. Attempts that
156+
// were counted but never marked evaluated (eval failed mid-way and the
157+
// message was nacked) fall through and re-run as recovery.
158+
if !res.NewlyCounted && res.AlreadyEvaluated {
159+
m.logger.Ctx(ctx).Debug("skipping replayed attempt: already evaluated",
160+
zap.String("attempt_id", attempt.Attempt.ID),
161+
zap.String("tenant_id", attempt.Destination.TenantID),
162+
zap.String("destination_id", attempt.Destination.ID),
163+
)
164+
return nil
165+
}
166+
167+
count := res.Count
154168
level, shouldAlert := m.evaluator.ShouldAlert(count)
155169
if shouldAlert {
156170
// At 100% threshold, disable the destination and emit disabled alert.
@@ -249,5 +263,17 @@ func (m *alertMonitor) HandleAttempt(ctx context.Context, attempt DeliveryAttemp
249263
}
250264
}
251265

266+
// Mark the attempt fully evaluated so replays skip re-emitting alerts.
267+
// Non-fatal: on failure the attempt simply re-evaluates on replay, which
268+
// matches the previous behavior (emit/disable are idempotent-by-design).
269+
if err := m.store.MarkAttemptEvaluated(ctx, attempt.Destination.TenantID, attempt.Destination.ID, attempt.Attempt.ID); err != nil {
270+
m.logger.Ctx(ctx).Warn("failed to mark attempt evaluated",
271+
zap.Error(err),
272+
zap.String("attempt_id", attempt.Attempt.ID),
273+
zap.String("tenant_id", attempt.Destination.TenantID),
274+
zap.String("destination_id", attempt.Destination.ID),
275+
)
276+
}
277+
252278
return nil
253279
}

internal/alert/monitor_test.go

Lines changed: 87 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -504,6 +504,93 @@ func TestAlertMonitor_ExhaustedRetries_EmitFailureRetryClearsWindow(t *testing.T
504504
require.Equal(t, 2, erCalls, "Should have 2 emit attempts (1 failed + 1 succeeded)")
505505
}
506506

507+
func TestAlertMonitor_ReplayedAttempt_SkipsEvaluation(t *testing.T) {
508+
t.Parallel()
509+
ctx := context.Background()
510+
logger := testutil.CreateTestLogger(t)
511+
redisClient := testutil.CreateTestRedisClient(t)
512+
emitter := &mockAlertEmitter{}
513+
emitter.On("Emit", mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(nil)
514+
515+
monitor := alert.NewAlertMonitor(
516+
logger,
517+
redisClient,
518+
emitter,
519+
10,
520+
alert.WithAutoDisableFailureCount(2),
521+
alert.WithAlertThresholds([]int{50, 100}),
522+
)
523+
524+
dest := &alert.AlertDestination{ID: "dest_replay", TenantID: "tenant_replay"}
525+
event := &models.Event{Topic: "test.event"}
526+
attempt := alert.DeliveryAttempt{
527+
Event: event,
528+
Destination: dest,
529+
Attempt: &models.Attempt{
530+
ID: "att_replay_1",
531+
Status: "failed",
532+
Code: "500",
533+
Time: time.Now(),
534+
},
535+
}
536+
537+
// First delivery: count=1 → 50% threshold → emits
538+
require.NoError(t, monitor.HandleAttempt(ctx, attempt))
539+
require.Equal(t, 1, countEmitCalls(emitter, "alert.destination.consecutive_failure"))
540+
541+
// Replay (MQ redelivery / producer re-publish): fully evaluated → skipped
542+
require.NoError(t, monitor.HandleAttempt(ctx, attempt))
543+
assert.Equal(t, 1, countEmitCalls(emitter, "alert.destination.consecutive_failure"),
544+
"replayed attempt should not re-emit the alert")
545+
}
546+
547+
func TestAlertMonitor_ReplayedAttempt_PartialFailureRetries(t *testing.T) {
548+
// When evaluation fails after the attempt was counted (e.g. emit error),
549+
// the message is nacked and redelivered — the replay must re-run the
550+
// evaluation, not skip it, or alerts would be silently dropped.
551+
t.Parallel()
552+
ctx := context.Background()
553+
logger := testutil.CreateTestLogger(t)
554+
redisClient := testutil.CreateTestRedisClient(t)
555+
emitter := &mockAlertEmitter{}
556+
emitter.On("Emit", mock.Anything, "alert.destination.consecutive_failure", mock.Anything, mock.Anything).Return(fmt.Errorf("emit failed")).Once()
557+
emitter.On("Emit", mock.Anything, "alert.destination.consecutive_failure", mock.Anything, mock.Anything).Return(nil)
558+
559+
monitor := alert.NewAlertMonitor(
560+
logger,
561+
redisClient,
562+
emitter,
563+
10,
564+
alert.WithAutoDisableFailureCount(2),
565+
alert.WithAlertThresholds([]int{50, 100}),
566+
)
567+
568+
dest := &alert.AlertDestination{ID: "dest_partial", TenantID: "tenant_partial"}
569+
event := &models.Event{Topic: "test.event"}
570+
attempt := alert.DeliveryAttempt{
571+
Event: event,
572+
Destination: dest,
573+
Attempt: &models.Attempt{
574+
ID: "att_partial_1",
575+
Status: "failed",
576+
Code: "500",
577+
Time: time.Now(),
578+
},
579+
}
580+
581+
// First delivery: counted, but emit fails → error (entry would be nacked)
582+
require.Error(t, monitor.HandleAttempt(ctx, attempt))
583+
584+
// Replay: not marked evaluated → re-runs and emits successfully
585+
require.NoError(t, monitor.HandleAttempt(ctx, attempt))
586+
assert.Equal(t, 2, countEmitCalls(emitter, "alert.destination.consecutive_failure"),
587+
"replay after partial failure should re-run evaluation")
588+
589+
// Second replay: now fully evaluated → skipped
590+
require.NoError(t, monitor.HandleAttempt(ctx, attempt))
591+
assert.Equal(t, 2, countEmitCalls(emitter, "alert.destination.consecutive_failure"))
592+
}
593+
507594
func countEmitCalls(emitter *mockAlertEmitter, topic string) int {
508595
count := 0
509596
for _, call := range emitter.Calls {

internal/alert/store.go

Lines changed: 56 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -9,13 +9,27 @@ import (
99
)
1010

1111
const (
12-
keyPrefixAlert = "alert" // Base prefix for all alert keys
13-
keyFailures = "cf" // Set for consecutive failure attempt IDs
12+
keyPrefixAlert = "alert" // Base prefix for all alert keys
13+
keyFailures = "cf" // Set for consecutive failure attempt IDs
14+
keyEvaluated = "cfeval" // Set for fully evaluated attempt IDs
15+
alertKeyTTL = 24 * time.Hour
1416
)
1517

18+
// FailureCountResult reports the state of consecutive-failure tracking
19+
// after recording an attempt.
20+
type FailureCountResult struct {
21+
Count int // current consecutive failure count
22+
NewlyCounted bool // attempt was not previously counted (first delivery of this attempt)
23+
AlreadyEvaluated bool // attempt was fully evaluated before (marked via MarkAttemptEvaluated)
24+
}
25+
1626
// AlertStore manages alert-related data persistence
1727
type AlertStore interface {
18-
IncrementConsecutiveFailureCount(ctx context.Context, tenantID, destinationID, attemptID string) (int, error)
28+
IncrementConsecutiveFailureCount(ctx context.Context, tenantID, destinationID, attemptID string) (FailureCountResult, error)
29+
// MarkAttemptEvaluated records that an attempt's alert evaluation fully
30+
// completed, so replays (MQ redelivery, producer re-publish) can skip
31+
// re-evaluating it.
32+
MarkAttemptEvaluated(ctx context.Context, tenantID, destinationID, attemptID string) error
1933
ResetConsecutiveFailureCount(ctx context.Context, tenantID, destinationID string) error
2034
}
2135

@@ -32,32 +46,60 @@ func NewRedisAlertStore(client redis.Cmdable, deploymentID string) AlertStore {
3246
}
3347
}
3448

35-
func (s *redisAlertStore) IncrementConsecutiveFailureCount(ctx context.Context, tenantID, destinationID, attemptID string) (int, error) {
49+
func (s *redisAlertStore) IncrementConsecutiveFailureCount(ctx context.Context, tenantID, destinationID, attemptID string) (FailureCountResult, error) {
3650
key := s.getFailuresKey(destinationID)
3751

3852
// Use a transaction to ensure atomicity between SADD, SCARD, and EXPIRE operations.
3953
// SADD is idempotent — adding the same attemptID on replay is a no-op,
4054
// preventing double-counting when messages are redelivered.
4155
pipe := s.client.TxPipeline()
42-
pipe.SAdd(ctx, key, attemptID)
56+
saddCmd := pipe.SAdd(ctx, key, attemptID)
4357
scardCmd := pipe.SCard(ctx, key)
44-
pipe.Expire(ctx, key, 24*time.Hour)
58+
evaluatedCmd := pipe.SIsMember(ctx, s.getEvaluatedKey(destinationID), attemptID)
59+
pipe.Expire(ctx, key, alertKeyTTL)
4560

4661
_, err := pipe.Exec(ctx)
4762
if err != nil {
48-
return 0, fmt.Errorf("failed to execute consecutive failure count transaction: %w", err)
63+
return FailureCountResult{}, fmt.Errorf("failed to execute consecutive failure count transaction: %w", err)
64+
}
65+
66+
added, err := saddCmd.Result()
67+
if err != nil {
68+
return FailureCountResult{}, fmt.Errorf("failed to record attempt: %w", err)
4969
}
5070

5171
count, err := scardCmd.Result()
5272
if err != nil {
53-
return 0, fmt.Errorf("failed to get consecutive failure count: %w", err)
73+
return FailureCountResult{}, fmt.Errorf("failed to get consecutive failure count: %w", err)
74+
}
75+
76+
evaluated, err := evaluatedCmd.Result()
77+
if err != nil {
78+
return FailureCountResult{}, fmt.Errorf("failed to check evaluated state: %w", err)
5479
}
5580

56-
return int(count), nil
81+
return FailureCountResult{
82+
Count: int(count),
83+
NewlyCounted: added == 1,
84+
AlreadyEvaluated: evaluated,
85+
}, nil
86+
}
87+
88+
func (s *redisAlertStore) MarkAttemptEvaluated(ctx context.Context, tenantID, destinationID, attemptID string) error {
89+
key := s.getEvaluatedKey(destinationID)
90+
91+
pipe := s.client.TxPipeline()
92+
pipe.SAdd(ctx, key, attemptID)
93+
pipe.Expire(ctx, key, alertKeyTTL)
94+
95+
if _, err := pipe.Exec(ctx); err != nil {
96+
return fmt.Errorf("failed to mark attempt evaluated: %w", err)
97+
}
98+
return nil
5799
}
58100

59101
func (s *redisAlertStore) ResetConsecutiveFailureCount(ctx context.Context, tenantID, destinationID string) error {
60-
return s.client.Del(ctx, s.getFailuresKey(destinationID)).Err()
102+
return s.client.Del(ctx, s.getFailuresKey(destinationID), s.getEvaluatedKey(destinationID)).Err()
61103
}
62104

63105
func (s *redisAlertStore) deploymentPrefix() string {
@@ -70,3 +112,7 @@ func (s *redisAlertStore) deploymentPrefix() string {
70112
func (s *redisAlertStore) getFailuresKey(destinationID string) string {
71113
return fmt.Sprintf("%s%s:%s:%s", s.deploymentPrefix(), keyPrefixAlert, destinationID, keyFailures)
72114
}
115+
116+
func (s *redisAlertStore) getEvaluatedKey(destinationID string) string {
117+
return fmt.Sprintf("%s%s:%s:%s", s.deploymentPrefix(), keyPrefixAlert, destinationID, keyEvaluated)
118+
}

0 commit comments

Comments
 (0)