Skip to content

Commit 22467af

Browse files
committed
fix(clickhouse): stop silently dropping terminal lifecycle events
Terminal sandbox lifecycle events (killed/paused/checkpointed) were delivered to ClickHouse through a non-blocking, fixed-size queue that drops on overflow with no retry and no back-pressure. Under a burst of kills the orchestrator logs the kill but the row never lands in sandbox_events, so billing/audit disagree with the logs. - batcher: add PushWithContext (bounded-blocking) so a caller can apply back-pressure instead of dropping the instant the queue is full. - batcher: retry a failed flush with capped backoff before dropping the batch (flag-gated, default off for static batchers). - events delivery: route terminal events through PushWithContext with a flag-controlled timeout; non-terminal high-volume events keep the non-blocking Push, so the hot path is unchanged. - events delivery: add a per-event-type drop counter (sandbox_events.delivery.dropped) so terminal-event loss is alertable. Fixes #3770
1 parent 2d8ffd3 commit 22467af

5 files changed

Lines changed: 429 additions & 4 deletions

File tree

‎packages/clickhouse/pkg/batcher/batcher.go‎

Lines changed: 84 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -206,6 +206,37 @@ func (b *Batcher[T]) Push(item T) error {
206206
}
207207
}
208208

209+
// PushWithContext enqueues an item, blocking until the queue has room or ctx is
210+
// done. Unlike Push (which drops immediately when the queue is full), it gives
211+
// bounded back-pressure so a caller can avoid silently losing an item it cares
212+
// about. On ctx cancellation/timeout the item is dropped and ErrBatcherQueueFull
213+
// is returned, matching Push's drop accounting.
214+
//
215+
// The RLock is held for the duration of the blocking send. Stop takes the write
216+
// lock before closing the channel, so it cannot close ch while a send is in
217+
// flight here; it instead waits (bounded by ctx) for this to return. That both
218+
// prevents a send-on-closed panic and lets in-flight terminal events settle
219+
// during a graceful stop.
220+
func (b *Batcher[T]) PushWithContext(ctx context.Context, item T) error {
221+
b.mu.RLock()
222+
defer b.mu.RUnlock()
223+
224+
if !b.started {
225+
return ErrBatcherNotStarted
226+
}
227+
228+
select {
229+
case b.ch <- item:
230+
mQueueLen.Record(ctx, int64(len(b.ch)), b.attrs)
231+
232+
return nil
233+
case <-ctx.Done():
234+
mItemsDropped.Add(ctx, 1, b.attrs)
235+
236+
return ErrBatcherQueueFull
237+
}
238+
}
239+
209240
// QueueLen returns the number of items pending in the queue.
210241
func (b *Batcher[T]) QueueLen() int {
211242
return len(b.ch)
@@ -219,6 +250,7 @@ func (b *Batcher[T]) processBatches(ctx context.Context) {
219250

220251
// Runtime limits belong to this goroutine; public fields remain startup options.
221252
maxBatchSize, maxDelay := b.limits(ctx, b.MaxBatchSize, b.MaxDelay)
253+
maxRetries := b.flushRetries(ctx)
222254
recordConfig := func() {
223255
mMaxBatchSize.Record(ctx, int64(maxBatchSize), b.attrs)
224256
mMaxDelay.Record(ctx, maxDelay.Milliseconds(), b.attrs)
@@ -242,7 +274,7 @@ func (b *Batcher[T]) processBatches(ctx context.Context) {
242274
mFlushWaitDuration.Record(ctx, time.Since(batchStartTime).Milliseconds(), b.attrs)
243275
start := time.Now()
244276
result := "success"
245-
if err := b.Func(ctx, batch); err != nil {
277+
if err := b.flushWithRetry(ctx, batch, maxRetries); err != nil {
246278
result = "error"
247279
b.ErrorHandler(err)
248280
}
@@ -278,6 +310,7 @@ func (b *Batcher[T]) processBatches(ctx context.Context) {
278310
case <-refreshC:
279311
previousDelay := maxDelay
280312
maxBatchSize, maxDelay = b.limits(ctx, maxBatchSize, maxDelay)
313+
maxRetries = b.flushRetries(ctx)
281314
if maxDelay != previousDelay {
282315
remaining := maxDelay
283316
if len(batch) > 0 {
@@ -312,3 +345,53 @@ func (b *Batcher[T]) limits(ctx context.Context, size int, delay time.Duration)
312345

313346
return size, delay
314347
}
348+
349+
// flushRetries is the number of extra flush attempts after the first failure.
350+
// Static batchers (no feature-flag client) do not retry, preserving legacy
351+
// drop-on-first-error behavior. A negative flag value is treated as zero.
352+
func (b *Batcher[T]) flushRetries(ctx context.Context) int {
353+
if b.flags == nil {
354+
return 0
355+
}
356+
if n := b.flags.IntFlag(ctx, featureflags.ClickhouseBatcherFlushMaxRetries, featureflags.BatcherContext(b.name)); n > 0 {
357+
return n
358+
}
359+
360+
return 0
361+
}
362+
363+
// flushWithRetry calls Func, retrying up to maxRetries extra times with a short
364+
// capped exponential backoff when it fails, so a transient ClickHouse blip does
365+
// not discard an entire batch. It returns the last error if every attempt
366+
// fails (the caller then drops the batch, as before). Each retry increments
367+
// batcher.flushes{result="retry"} so repeated failures are visible before loss.
368+
// Retrying here blocks the batch loop, which is the intended back-pressure; the
369+
// total added delay is bounded (maxRetries * capped backoff).
370+
func (b *Batcher[T]) flushWithRetry(ctx context.Context, batch []T, maxRetries int) error {
371+
const (
372+
baseBackoff = 50 * time.Millisecond
373+
maxBackoff = 2 * time.Second
374+
)
375+
376+
var err error
377+
for attempt := 0; ; attempt++ {
378+
if err = b.Func(ctx, batch); err == nil {
379+
return nil
380+
}
381+
if attempt >= maxRetries {
382+
return err
383+
}
384+
385+
mFlushes.Add(ctx, 1, b.attrs, metric.WithAttributes(attribute.String("result", "retry")))
386+
387+
backoff := baseBackoff << attempt
388+
if backoff <= 0 || backoff > maxBackoff {
389+
backoff = maxBackoff
390+
}
391+
select {
392+
case <-time.After(backoff):
393+
case <-ctx.Done():
394+
return err
395+
}
396+
}
397+
}
Lines changed: 158 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,158 @@
1+
package batcher
2+
3+
import (
4+
"context"
5+
"errors"
6+
"sync"
7+
"sync/atomic"
8+
"testing"
9+
"time"
10+
11+
"github.com/launchdarkly/go-sdk-common/v3/ldvalue"
12+
"github.com/launchdarkly/go-server-sdk/v7/testhelpers/ldtestdata"
13+
"github.com/stretchr/testify/require"
14+
15+
"github.com/e2b-dev/infra/packages/shared/pkg/featureflags"
16+
)
17+
18+
// blockFirstFlush returns a BatcherFunc that, on its first call only, signals
19+
// entered and then blocks until release is closed; every later flush returns
20+
// immediately. This lets a test pin the processor on a full queue without the
21+
// Func re-blocking on subsequent batches.
22+
func blockFirstFlush[T any](entered chan<- struct{}, release <-chan struct{}) func(context.Context, []T) error {
23+
var once sync.Once
24+
25+
return func(context.Context, []T) error {
26+
once.Do(func() {
27+
close(entered)
28+
<-release
29+
})
30+
31+
return nil
32+
}
33+
}
34+
35+
// PushWithContext blocks while the queue is full and succeeds once the
36+
// processor drains a slot, instead of dropping like the non-blocking Push.
37+
func TestBatcherPushWithContextBlocksThenSucceeds(t *testing.T) {
38+
t.Parallel()
39+
release := make(chan struct{})
40+
entered := make(chan struct{})
41+
b, err := NewBatcher(blockFirstFlush[int](entered, release),
42+
BatcherOptions{MaxDelay: time.Hour, MaxBatchSize: 1, QueueSize: 1})
43+
require.NoError(t, err)
44+
require.NoError(t, b.Start(t.Context()))
45+
defer b.Stop()
46+
47+
// First item is picked up by the processor and blocks it in Func.
48+
require.NoError(t, b.Push(1))
49+
<-entered
50+
// Queue (cap 1) now fills.
51+
require.NoError(t, b.Push(2))
52+
require.ErrorIs(t, b.Push(3), ErrBatcherQueueFull, "non-blocking Push drops on a full queue")
53+
54+
// A bounded-blocking push on the full queue succeeds once Func returns and
55+
// the processor pulls the queued item, freeing a slot.
56+
done := make(chan error, 1)
57+
go func() { done <- b.PushWithContext(t.Context(), 4) }()
58+
time.Sleep(20 * time.Millisecond)
59+
select {
60+
case err := <-done:
61+
t.Fatalf("PushWithContext returned early (%v); it should have blocked on the full queue", err)
62+
default:
63+
}
64+
close(release)
65+
require.NoError(t, <-done, "PushWithContext should succeed after a slot frees up")
66+
}
67+
68+
// PushWithContext drops (and does not block forever) when its context expires
69+
// while the queue stays full.
70+
func TestBatcherPushWithContextTimesOut(t *testing.T) {
71+
t.Parallel()
72+
release := make(chan struct{})
73+
entered := make(chan struct{})
74+
b, err := NewBatcher(blockFirstFlush[int](entered, release),
75+
BatcherOptions{MaxDelay: time.Hour, MaxBatchSize: 1, QueueSize: 1})
76+
require.NoError(t, err)
77+
require.NoError(t, b.Start(t.Context()))
78+
defer func() { close(release); b.Stop() }()
79+
80+
require.NoError(t, b.Push(1))
81+
<-entered
82+
require.NoError(t, b.Push(2)) // queue full
83+
84+
ctx, cancel := context.WithTimeout(t.Context(), 30*time.Millisecond)
85+
defer cancel()
86+
require.ErrorIs(t, b.PushWithContext(ctx, 3), ErrBatcherQueueFull,
87+
"a terminal push whose deadline elapses on a stuck queue is dropped, not blocked forever")
88+
}
89+
90+
func TestBatcherPushWithContextNotStarted(t *testing.T) {
91+
t.Parallel()
92+
b, err := NewBatcher[int](func(context.Context, []int) error { return nil }, BatcherOptions{})
93+
require.NoError(t, err)
94+
require.ErrorIs(t, b.PushWithContext(t.Context(), 1), ErrBatcherNotStarted)
95+
}
96+
97+
// A transient flush failure is retried (per the flag) and the batch is
98+
// delivered rather than dropped on the first error.
99+
func TestBatcherFlushRetriesThenSucceeds(t *testing.T) {
100+
t.Parallel()
101+
source := ldtestdata.DataSource()
102+
source.Update(source.Flag(featureflags.ClickhouseBatcherFlushMaxRetries.Key()).ValueForAll(ldvalue.Int(3)))
103+
source.Update(source.Flag(featureflags.ClickhouseBatcherMaxBatchSize.Key()).ValueForAll(ldvalue.Int(1)))
104+
ff, err := featureflags.NewClientWithDatasource(source)
105+
require.NoError(t, err)
106+
defer ff.Close(context.WithoutCancel(t.Context()))
107+
108+
var calls atomic.Int32
109+
delivered := make(chan int, 1)
110+
b, err := NewBatcher(func(_ context.Context, batch []int) error {
111+
if calls.Add(1) < 3 {
112+
return errors.New("transient clickhouse error")
113+
}
114+
delivered <- len(batch)
115+
116+
return nil
117+
}, BatcherOptions{Name: "retry-test", FeatureFlags: ff, MaxDelay: time.Hour, MaxBatchSize: 1, QueueSize: 4})
118+
require.NoError(t, err)
119+
require.NoError(t, b.Start(t.Context()))
120+
defer b.Stop()
121+
122+
require.NoError(t, b.Push(1))
123+
select {
124+
case n := <-delivered:
125+
require.Equal(t, 1, n)
126+
case <-time.After(5 * time.Second):
127+
t.Fatal("batch was not delivered within timeout; retry did not recover the transient failure")
128+
}
129+
require.GreaterOrEqual(t, calls.Load(), int32(3), "expected the flush to be retried until success")
130+
}
131+
132+
// With retries disabled (no flag client), a flush failure drops the batch after
133+
// a single attempt — the legacy behavior is preserved.
134+
func TestBatcherFlushNoRetryByDefault(t *testing.T) {
135+
t.Parallel()
136+
var calls atomic.Int32
137+
handled := make(chan error, 1)
138+
b, err := NewBatcher(func(_ context.Context, _ []int) error {
139+
calls.Add(1)
140+
141+
return errors.New("boom")
142+
}, BatcherOptions{
143+
MaxDelay: time.Hour, MaxBatchSize: 1, QueueSize: 4,
144+
ErrorHandler: func(err error) { handled <- err },
145+
})
146+
require.NoError(t, err)
147+
require.NoError(t, b.Start(t.Context()))
148+
defer b.Stop()
149+
150+
require.NoError(t, b.Push(1))
151+
select {
152+
case <-handled:
153+
case <-time.After(5 * time.Second):
154+
t.Fatal("ErrorHandler was not called")
155+
}
156+
time.Sleep(50 * time.Millisecond)
157+
require.Equal(t, int32(1), calls.Load(), "static batcher must not retry (legacy drop-on-first-error)")
158+
}

0 commit comments

Comments
 (0)