Skip to content

Commit 38d7e23

Browse files
authored
fix(telemetry): add circuit breaker and shutdown draining to TelemetryService (#1070)
* fix(telemetry): add circuit breaker and shutdown draining to TelemetryService * fix(telemetry): fix circuit breaker off-by-one, allSettled on shutdown * fix(telemetry): bound client.shutdown() phase, strengthen breaker test
1 parent d395525 commit 38d7e23

4 files changed

Lines changed: 581 additions & 6 deletions

File tree

packages/telemetry/src/TelemetryService.ts

Lines changed: 129 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -7,14 +7,66 @@ import {
77
type TelemetrySetting,
88
} from "@roo-code/types"
99

10+
/**
11+
* Events prone to retry-storm-style repetition (e.g. a broken embedder config
12+
* re-triggering on every file-system event). Guarded by a circuit breaker in
13+
* `captureEvent` so a single broken install can't flood the Product Analytics
14+
* quota. Tracked per-event via a sliding time window, independent of any
15+
* other telemetry the same install may also be sending.
16+
*/
17+
const CIRCUIT_BREAKER_GUARDED_EVENTS = new Set<TelemetryEventName>([TelemetryEventName.CODE_INDEX_ERROR])
18+
19+
/** Captures of a guarded event within the counting window allowed before the breaker trips. */
20+
const CIRCUIT_BREAKER_MAX_IN_WINDOW = 50
21+
22+
/** Rolling window over which guarded-event occurrences are counted. */
23+
const CIRCUIT_BREAKER_WINDOW_MS = 10 * 60 * 1000
24+
25+
/** How long a tripped breaker stays tripped before allowing captures again. */
26+
const CIRCUIT_BREAKER_COOLDOWN_MS = 10 * 60 * 1000
27+
28+
/**
29+
* Upper bound applied separately to each phase of shutdown(): draining in-flight capture
30+
* calls, then awaiting client.shutdown(). deactivate() awaits shutdown() before terminal
31+
* cleanup, so an unbounded wait in either phase (e.g. a capture stuck on network I/O, or
32+
* a client's own shutdown() -- posthog-node defaults to a 30s internal timeout -- never
33+
* settling) would block the extension host from ever finishing deactivation. Losing an
34+
* in-flight capture, or a client's graceful flush, on timeout is an acceptable tradeoff
35+
* against blocking shutdown indefinitely. Worst case, shutdown() takes up to roughly
36+
* 2 * SHUTDOWN_PHASE_TIMEOUT_MS.
37+
*/
38+
const SHUTDOWN_PHASE_TIMEOUT_MS = 3000
39+
1040
/**
1141
* TelemetryService wrapper class that defers initialization.
1242
* This ensures that we only create the various clients after environment
1343
* variables are loaded.
1444
*/
1545
export class TelemetryService {
46+
// Timestamps of recent guarded-event occurrences, per event name, oldest first.
47+
private guardedEventOccurrences = new Map<TelemetryEventName, number[]>()
48+
private trippedUntil = new Map<TelemetryEventName, number>()
49+
50+
// In-flight client.capture()/captureException() promises. captureEvent/captureException are
51+
// synchronous (void-returning) for callers, but the underlying client calls are async (e.g.
52+
// PostHogTelemetryClient awaits property enrichment before enqueueing). Tracked here so
53+
// shutdown() can drain them before flushing/closing the clients -- otherwise a capture that's
54+
// still mid-flight when shutdown() runs could be lost entirely.
55+
private pendingClientCalls = new Set<Promise<unknown>>()
56+
57+
// Set at the start of shutdown() so new captureEvent/captureException calls stop being
58+
// tracked (and, once clients are closing, stop being sent) instead of racing the drain.
59+
private isShuttingDown = false
60+
1661
constructor(private clients: TelemetryClient[]) {}
1762

63+
private trackPendingClientCall(promise: Promise<unknown>): void {
64+
// Never let a rejected client call surface as an unhandled rejection or block shutdown.
65+
const tracked = promise.catch(() => undefined)
66+
this.pendingClientCalls.add(tracked)
67+
void tracked.finally(() => this.pendingClientCalls.delete(tracked))
68+
}
69+
1870
public register(client: TelemetryClient): void {
1971
this.clients.push(client)
2072
}
@@ -51,18 +103,60 @@ export class TelemetryService {
51103
this.clients.forEach((client) => client.updateTelemetryState(isOptedIn))
52104
}
53105

106+
/**
107+
* Checks whether a guarded event should be dropped by the circuit breaker,
108+
* updating the breaker's internal state as a side effect. Tracked entirely
109+
* independently of other event names -- unrelated telemetry from the same
110+
* install must never mask (or count towards) a guarded-event burst.
111+
*/
112+
private shouldDropForCircuitBreaker(eventName: TelemetryEventName): boolean {
113+
if (!CIRCUIT_BREAKER_GUARDED_EVENTS.has(eventName)) {
114+
return false
115+
}
116+
117+
const now = Date.now()
118+
119+
const trippedUntil = this.trippedUntil.get(eventName)
120+
if (trippedUntil !== undefined) {
121+
if (now < trippedUntil) {
122+
return true
123+
}
124+
125+
// Cooldown elapsed - reset and allow this capture through.
126+
this.trippedUntil.delete(eventName)
127+
this.guardedEventOccurrences.delete(eventName)
128+
}
129+
130+
const windowStart = now - CIRCUIT_BREAKER_WINDOW_MS
131+
const occurrences = (this.guardedEventOccurrences.get(eventName) ?? []).filter((ts) => ts > windowStart)
132+
occurrences.push(now)
133+
this.guardedEventOccurrences.set(eventName, occurrences)
134+
135+
if (occurrences.length >= CIRCUIT_BREAKER_MAX_IN_WINDOW) {
136+
this.trippedUntil.set(eventName, now + CIRCUIT_BREAKER_COOLDOWN_MS)
137+
this.guardedEventOccurrences.delete(eventName)
138+
return true
139+
}
140+
141+
return false
142+
}
143+
54144
/**
55145
* Generic method to capture any type of event with specified properties
56146
* @param eventName The event name to capture
57147
* @param properties The event properties
58148
*/
59149
// eslint-disable-next-line @typescript-eslint/no-explicit-any
60150
public captureEvent(eventName: TelemetryEventName, properties?: Record<string, any>): void {
61-
if (!this.isReady) {
151+
if (!this.isReady || this.isShuttingDown) {
152+
return
153+
}
154+
155+
if (this.shouldDropForCircuitBreaker(eventName)) {
62156
return
63157
}
64158

65-
this.clients.forEach((client) => client.capture({ event: eventName, properties }))
159+
this.clients.forEach((client) => this.trackPendingClientCall(client.capture({ event: eventName, properties })))
66160
}
67161

68162
/**
@@ -71,11 +165,13 @@ export class TelemetryService {
71165
* @param additionalProperties Additional properties to include with the exception
72166
*/
73167
public captureException(error: Error, additionalProperties?: Record<string, unknown>): void {
74-
if (!this.isReady) {
168+
if (!this.isReady || this.isShuttingDown) {
75169
return
76170
}
77171

78-
this.clients.forEach((client) => client.captureException(error, additionalProperties))
172+
this.clients.forEach((client) =>
173+
this.trackPendingClientCall(client.captureException(error, additionalProperties)),
174+
)
79175
}
80176

81177
public captureTaskCreated(taskId: string): void {
@@ -263,7 +359,35 @@ export class TelemetryService {
263359
return
264360
}
265361

266-
this.clients.forEach((client) => client.shutdown())
362+
// Stop accepting new captures immediately, before draining -- otherwise a steady trickle
363+
// of new calls (e.g. from a teardown-time error handler) could keep pendingClientCalls
364+
// non-empty indefinitely and the drain loop below would never terminate on its own.
365+
this.isShuttingDown = true
366+
367+
// Drain any in-flight capture/captureException calls first, so a client's shutdown()
368+
// (which flushes its queue) can't run ahead of a capture that hasn't been enqueued yet.
369+
// Loop rather than a single snapshot: a call already in flight when draining started may
370+
// itself still be tracked by the time we check again. Bounded by a timeout so a capture
371+
// stuck on network I/O that never resolves/rejects can't block deactivate() forever --
372+
// losing that one capture is an acceptable tradeoff against hanging terminal cleanup.
373+
const drainStart = Date.now()
374+
while (this.pendingClientCalls.size > 0 && Date.now() - drainStart < SHUTDOWN_PHASE_TIMEOUT_MS) {
375+
await Promise.race([
376+
Promise.all(this.pendingClientCalls),
377+
new Promise((resolve) => setTimeout(resolve, SHUTDOWN_PHASE_TIMEOUT_MS - (Date.now() - drainStart))),
378+
])
379+
}
380+
381+
// Bound client shutdown the same way as the drain above: posthog-node's own shutdown()
382+
// defaults to a 30s internal timeout when called with no argument (as PostHogTelemetryClient
383+
// does), and TelemetryClient#shutdown() takes no timeout parameter to pass one through. Racing
384+
// against our own timer here, instead of just awaiting client.shutdown() directly, keeps
385+
// deactivate() from blocking for up to 30s on a client that never settles.
386+
// allSettled, not all: one client rejecting must not stop us from awaiting the others.
387+
await Promise.race([
388+
Promise.allSettled(this.clients.map((client) => client.shutdown())),
389+
new Promise((resolve) => setTimeout(resolve, SHUTDOWN_PHASE_TIMEOUT_MS)),
390+
])
267391
}
268392

269393
private static _instance: TelemetryService | null = null
Lines changed: 148 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,148 @@
1+
// pnpm --filter @roo-code/telemetry test src/__tests__/TelemetryService.circuit-breaker.test.ts
2+
3+
import { TelemetryEventName, type TelemetryClient } from "@roo-code/types"
4+
5+
import { TelemetryService } from "../TelemetryService"
6+
7+
describe("TelemetryService circuit breaker", () => {
8+
let mockClient: TelemetryClient
9+
10+
beforeEach(() => {
11+
vi.useFakeTimers()
12+
vi.setSystemTime(0)
13+
14+
mockClient = {
15+
setProvider: vi.fn(),
16+
capture: vi.fn().mockResolvedValue(undefined),
17+
captureException: vi.fn().mockResolvedValue(undefined),
18+
updateTelemetryState: vi.fn(),
19+
isTelemetryEnabled: vi.fn().mockReturnValue(true),
20+
shutdown: vi.fn().mockResolvedValue(undefined),
21+
}
22+
})
23+
24+
afterEach(() => {
25+
vi.useRealTimers()
26+
})
27+
28+
it("passes through captures under the trip threshold", () => {
29+
const service = new TelemetryService([mockClient])
30+
31+
for (let i = 0; i < 49; i++) {
32+
service.captureEvent(TelemetryEventName.CODE_INDEX_ERROR, { i })
33+
}
34+
35+
expect(mockClient.capture).toHaveBeenCalledTimes(49)
36+
})
37+
38+
it("trips at the 50th CODE_INDEX_ERROR capture within the window and drops further ones", () => {
39+
const service = new TelemetryService([mockClient])
40+
41+
for (let i = 0; i < 49; i++) {
42+
service.captureEvent(TelemetryEventName.CODE_INDEX_ERROR, { i })
43+
}
44+
expect(mockClient.capture).toHaveBeenCalledTimes(49)
45+
46+
// 50th capture trips the breaker but is itself dropped.
47+
service.captureEvent(TelemetryEventName.CODE_INDEX_ERROR, { i: 49 })
48+
expect(mockClient.capture).toHaveBeenCalledTimes(49)
49+
50+
// Keeps dropping while tripped.
51+
service.captureEvent(TelemetryEventName.CODE_INDEX_ERROR, { i: 50 })
52+
expect(mockClient.capture).toHaveBeenCalledTimes(49)
53+
})
54+
55+
it("re-allows captures after the cooldown window elapses", () => {
56+
const service = new TelemetryService([mockClient])
57+
58+
for (let i = 0; i < 50; i++) {
59+
service.captureEvent(TelemetryEventName.CODE_INDEX_ERROR, { i })
60+
}
61+
expect(mockClient.capture).toHaveBeenCalledTimes(49)
62+
63+
// Just under 10 minutes - still tripped.
64+
vi.setSystemTime(10 * 60 * 1000 - 1)
65+
service.captureEvent(TelemetryEventName.CODE_INDEX_ERROR, { i: 50 })
66+
expect(mockClient.capture).toHaveBeenCalledTimes(49)
67+
68+
// Cooldown elapsed - one more error gets through.
69+
vi.setSystemTime(10 * 60 * 1000)
70+
service.captureEvent(TelemetryEventName.CODE_INDEX_ERROR, { i: 51 })
71+
expect(mockClient.capture).toHaveBeenCalledTimes(50)
72+
})
73+
74+
it("does not reset the guarded count when unrelated events are interleaved", () => {
75+
// A real broken install still does normal things (creates/completes other tasks)
76+
// while a subsystem like code-index is stuck in a retry loop. Unrelated telemetry
77+
// must not mask the CODE_INDEX_ERROR burst by resetting its count.
78+
const service = new TelemetryService([mockClient])
79+
80+
for (let i = 0; i < 25; i++) {
81+
service.captureEvent(TelemetryEventName.CODE_INDEX_ERROR, { i })
82+
service.captureEvent(TelemetryEventName.TASK_CREATED, { taskId: `task-${i}` })
83+
}
84+
// 25 CODE_INDEX_ERROR so far - still under the threshold of 50.
85+
expect(mockClient.capture).toHaveBeenCalledTimes(25 + 25)
86+
87+
for (let i = 25; i < 49; i++) {
88+
service.captureEvent(TelemetryEventName.CODE_INDEX_ERROR, { i })
89+
service.captureEvent(TelemetryEventName.TASK_CREATED, { taskId: `task-${i}` })
90+
}
91+
// 49 CODE_INDEX_ERROR so far - still under the threshold of 50.
92+
expect(mockClient.capture).toHaveBeenCalledTimes(49 + 49)
93+
94+
// 50th CODE_INDEX_ERROR trips the breaker (and is itself dropped); TASK_CREATED
95+
// events are never guarded.
96+
service.captureEvent(TelemetryEventName.CODE_INDEX_ERROR, { i: 49 })
97+
service.captureEvent(TelemetryEventName.TASK_CREATED, { taskId: "task-49" })
98+
expect(mockClient.capture).toHaveBeenCalledTimes(49 + 50)
99+
100+
// Further CODE_INDEX_ERROR captures are dropped even though unrelated events keep flowing.
101+
service.captureEvent(TelemetryEventName.CODE_INDEX_ERROR, { i: 50 })
102+
service.captureEvent(TelemetryEventName.TASK_CREATED, { taskId: "task-50" })
103+
expect(mockClient.capture).toHaveBeenCalledTimes(49 + 51)
104+
})
105+
106+
it("expires old occurrences outside the counting window instead of trapping the breaker open forever", () => {
107+
// A slow trickle of CODE_INDEX_ERROR (below the burst rate) should never trip the
108+
// breaker, since old occurrences age out of the window rather than accumulating forever.
109+
const service = new TelemetryService([mockClient])
110+
111+
for (let i = 0; i < 60; i++) {
112+
service.captureEvent(TelemetryEventName.CODE_INDEX_ERROR, { i })
113+
// Advance well past the counting window between each one.
114+
vi.setSystemTime(Date.now() + 60 * 1000)
115+
}
116+
117+
expect(mockClient.capture).toHaveBeenCalledTimes(60)
118+
})
119+
120+
it("does not guard other event names", () => {
121+
const service = new TelemetryService([mockClient])
122+
123+
for (let i = 0; i < 200; i++) {
124+
service.captureEvent(TelemetryEventName.TOOL_USED, { tool: "read_file" })
125+
}
126+
127+
expect(mockClient.capture).toHaveBeenCalledTimes(200)
128+
})
129+
130+
it("returns early on the not-ready (zero-client) branch without touching circuit breaker state", () => {
131+
// captureEvent's !this.isReady check runs before shouldDropForCircuitBreaker, so with
132+
// no clients registered, guarded-event bookkeeping should never be reached.
133+
const service = new TelemetryService([])
134+
135+
for (let i = 0; i < 50; i++) {
136+
service.captureEvent(TelemetryEventName.CODE_INDEX_ERROR, { i })
137+
}
138+
139+
expect(mockClient.capture).not.toHaveBeenCalled()
140+
141+
// Prove the 50 zero-client calls didn't count towards the breaker: once a client is
142+
// registered, the very next capture must still go through instead of being dropped.
143+
service.register(mockClient)
144+
service.captureEvent(TelemetryEventName.CODE_INDEX_ERROR, { i: 50 })
145+
146+
expect(mockClient.capture).toHaveBeenCalledTimes(1)
147+
})
148+
})

0 commit comments

Comments
 (0)