-
Notifications
You must be signed in to change notification settings - Fork 66
fix(cloud-task): recover SSE streams that go silent instead of hanging forever #4052
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -31,6 +31,12 @@ const SSE_RECONNECT_BASE_DELAY_MS = 500; | |
| const SSE_RECONNECT_FLAT_ATTEMPTS = 3; | ||
| const SSE_RECONNECT_MAX_DELAY_MS = 30_000; | ||
| const SSE_HEALTHY_CONNECTION_MS = 60_000; | ||
| // The backend emits a keepalive at least every ~25-30s (see SSE_KEEPALIVE_INTERVAL_MS in | ||
| // packages/agent). A half-open socket (laptop sleep, unplugged NIC, NAT rebind) neither errors | ||
| // nor EOFs, so `reader.read()` awaits forever with nothing to trigger reconnect. This timeout | ||
| // treats "no bytes at all for a few keepalive intervals" as a disconnect so it flows into the | ||
| // existing reconnect/backoff machinery instead of hanging the watcher indefinitely. | ||
| const SSE_IDLE_TIMEOUT_MS = 90_000; | ||
| const EVENT_BATCH_FLUSH_MS = 16; | ||
| const EVENT_BATCH_MAX_SIZE = 50; | ||
| const SESSION_LOG_PAGE_LIMIT = 5_000; | ||
|
|
@@ -1256,12 +1262,75 @@ export class CloudTaskEngine extends TypedEventEmitter<CloudTaskEvents> { | |
| const controller = new AbortController(); | ||
| watcher.sseAbortController = controller; | ||
|
|
||
| let connectedAt = 0; | ||
| let streamWasEstablished = false; | ||
| let bytesReceived = 0; | ||
| let eventsReceived = 0; | ||
| let idleTimedOut = false; | ||
| let idleTimeoutHandle: ReturnType<typeof setTimeout> | null = null; | ||
| let idlePhase: "target_resolution" | "connection" | "stream" = | ||
| "target_resolution"; | ||
|
|
||
| const clearIdleTimeout = () => { | ||
| if (idleTimeoutHandle) { | ||
| clearTimeout(idleTimeoutHandle); | ||
| idleTimeoutHandle = null; | ||
| } | ||
| }; | ||
| const armIdleTimeout = () => { | ||
| clearIdleTimeout(); | ||
| idleTimeoutHandle = setTimeout(() => { | ||
| idleTimedOut = true; | ||
| controller.abort(); | ||
| }, SSE_IDLE_TIMEOUT_MS); | ||
| }; | ||
| const recordIdleTimeout = (details: Record<string, unknown> = {}) => { | ||
| const idleWatcher = this.watchers.get(key); | ||
| this.log.warn("Cloud task stream idle timeout, no bytes received", { | ||
| key, | ||
| phase: idlePhase, | ||
| idleTimeoutMs: SSE_IDLE_TIMEOUT_MS, | ||
| bytesReceived, | ||
| eventsReceived, | ||
| connectionDurationMs: streamWasEstablished | ||
| ? Date.now() - connectedAt | ||
| : 0, | ||
| ...details, | ||
| }); | ||
| if (idleWatcher) { | ||
| this.analytics.track(ANALYTICS_EVENTS.CLOUD_STREAM_IDLE_TIMEOUT, { | ||
| task_id: idleWatcher.taskId, | ||
| run_id: idleWatcher.runId, | ||
| team_id: idleWatcher.teamId, | ||
| idle_timeout_ms: SSE_IDLE_TIMEOUT_MS, | ||
| bytes_received: bytesReceived, | ||
| events_received: eventsReceived, | ||
| }); | ||
| } | ||
| }; | ||
|
|
||
| watcher.connStartedAt = 0; | ||
| watcher.connDataEventsReceived = 0; | ||
|
|
||
| // Resolve the read target once (proxy URL + token, or Django), reused across reconnects. | ||
| if (!watcher.streamTargetResolved) { | ||
| await this.resolveStreamTarget(watcher); | ||
| armIdleTimeout(); | ||
| try { | ||
| await this.resolveStreamTarget(watcher, controller.signal); | ||
| } catch (error) { | ||
| if (!idleTimedOut) { | ||
| return; | ||
| } | ||
| recordIdleTimeout(); | ||
| await this.handleStreamCompletion(key, { | ||
| reconnectOnDisconnect: true, | ||
| reconnectError: error, | ||
| countReconnectAttempt: true, | ||
| }); | ||
| return; | ||
| } finally { | ||
| clearIdleTimeout(); | ||
| } | ||
| const resolvedWatcher = this.watchers.get(key); | ||
| if ( | ||
| !resolvedWatcher || | ||
|
|
@@ -1340,12 +1409,11 @@ export class CloudTaskEngine extends TypedEventEmitter<CloudTaskEvents> { | |
|
|
||
| // Track how long the body stayed open so healthy long-lived connections cut by churn | ||
| // aren't penalized as failed reconnects (see SSE_HEALTHY_CONNECTION_MS). | ||
| let connectedAt = 0; | ||
| let streamWasEstablished = false; | ||
| let bytesReceived = 0; | ||
| let eventsReceived = 0; | ||
|
|
||
| // Re-armed on every read that returns a value (data or keepalive bytes), so it only fires | ||
| // when the transport has gone completely silent, not merely between infrequent events. | ||
| try { | ||
| idlePhase = "connection"; | ||
| armIdleTimeout(); | ||
| // The proxy authenticates with the run-scoped Bearer token; the Django leg uses the session. | ||
| const response = usingProxy | ||
| ? await this.streamFetch(url.toString(), { | ||
|
|
@@ -1401,13 +1469,17 @@ export class CloudTaskEngine extends TypedEventEmitter<CloudTaskEvents> { | |
| }); | ||
|
|
||
| const reader = response.body.getReader(); | ||
| idlePhase = "stream"; | ||
| armIdleTimeout(); | ||
|
|
||
| while (true) { | ||
| const { done, value } = await reader.read(); | ||
| if (done) { | ||
| break; | ||
| } | ||
|
|
||
| armIdleTimeout(); | ||
|
|
||
| if (!value) { | ||
| continue; | ||
| } | ||
|
|
@@ -1463,10 +1535,20 @@ export class CloudTaskEngine extends TypedEventEmitter<CloudTaskEvents> { | |
| } catch (error) { | ||
| this.flushLogBatch(key); | ||
|
|
||
| if (controller.signal.aborted) { | ||
| // An idle-timeout abort must fall through to the reconnect machinery below rather than | ||
| // return here like a deliberate cancel (disconnectSse/stopWatching), since nothing else | ||
| // will ever notice this connection went silent. | ||
| if (controller.signal.aborted && !idleTimedOut) { | ||
| return; | ||
| } | ||
|
|
||
| if (idleTimedOut) { | ||
| recordIdleTimeout({ | ||
| leg, | ||
| streamUrl: url.toString(), | ||
| }); | ||
| } | ||
|
|
||
|
tatoalo marked this conversation as resolved.
|
||
| // Proxy-leg 401: the read token expired or its signing key rotated. Re-resolve to mint a | ||
| // fresh token (or route back to Django) instead of failing. Django-leg 401 stays fatal below. | ||
| const unauthorizedWatcher = this.watchers.get(key); | ||
|
|
@@ -1506,6 +1588,7 @@ export class CloudTaskEngine extends TypedEventEmitter<CloudTaskEvents> { | |
| const isBackendError = error instanceof BackendStreamError; | ||
| const wasHealthyStream = | ||
| !isBackendError && | ||
| !idleTimedOut && | ||
| streamWasEstablished && | ||
| Date.now() - connectedAt >= SSE_HEALTHY_CONNECTION_MS; | ||
|
|
||
|
|
@@ -1548,6 +1631,7 @@ export class CloudTaskEngine extends TypedEventEmitter<CloudTaskEvents> { | |
| countReconnectAttempt: !isBackendError && !wasHealthyStream, | ||
| }); | ||
| } finally { | ||
| clearIdleTimeout(); | ||
| const currentWatcher = this.watchers.get(key); | ||
| if (currentWatcher?.sseAbortController === controller) { | ||
| currentWatcher.sseAbortController = null; | ||
|
|
@@ -2198,11 +2282,15 @@ export class CloudTaskEngine extends TypedEventEmitter<CloudTaskEvents> { | |
| } | ||
| } | ||
|
|
||
| private async resolveStreamTarget(watcher: WatcherState): Promise<void> { | ||
| private async resolveStreamTarget( | ||
| watcher: WatcherState, | ||
| signal: AbortSignal, | ||
| ): Promise<void> { | ||
| const url = `${watcher.apiHost}/api/projects/${watcher.teamId}/tasks/${watcher.taskId}/runs/${watcher.runId}/stream_token/`; | ||
| try { | ||
| const response = await this.auth.authenticatedFetch(url, { | ||
| method: "GET", | ||
| signal, | ||
| }); | ||
|
Comment on lines
+2285
to
2294
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Threading controller.signal into resolveStreamTarget's authenticatedFetch silently disables AuthService's default 30s request timeout, widening it to the 90s idle window (and beyond, across a 401-retry cycle)Why we think it's a valid issue
Issue descriptionBefore this PR, Suggested fixUse a dedicated, shorter-lived AbortSignal for the Prompt to fix with AI (copy-paste) |
||
| if (!response.ok) { | ||
| watcher.streamBaseUrl = null; | ||
|
|
@@ -2245,6 +2333,9 @@ export class CloudTaskEngine extends TypedEventEmitter<CloudTaskEvents> { | |
| durableStream: watcher.durableStreamEnabled, | ||
| }); | ||
| } catch (error) { | ||
| if (signal.aborted) { | ||
| throw error; | ||
| } | ||
| // Transient failure: leave unresolved so the next reconnect retries and falls back to Django. | ||
| watcher.streamBaseUrl = null; | ||
| watcher.streamReadToken = null; | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
CLOUD_STREAM_IDLE_TIMEOUT analytics event drops the connection phase and duration that the log line captures, undermining the PR's stated measurability goal
Why we think it's a valid issue
recordIdleTimeout(cloud-task-engine.ts:1287-1310), the analyticstrackcall inside it, theCloudStreamIdleTimeoutPropertiesschema (packages/shared/src/analytics-events.ts:330-337), and the siblingCloudStreamDisconnectedPropertiesschema (analytics-events.ts:318-328).log.warnpayload includesphase: idlePhase(line 1291) andconnectionDurationMs(lines 1295-1297), but theanalytics.track(CLOUD_STREAM_IDLE_TIMEOUT, ...)call (lines 1301-1308) forwards neither, and the schema (analytics-events.ts:330-337) has no field for either. So the phase dimension is computed, logged, and then dropped before analytics.CloudStreamDisconnectedProperties(analytics-events.ts:318-328) carries many dimensions (reconnect_attempts, retryable, was_bootstrapping, etc.), so enriching the idle-timeout event withphase/connection_duration_msis consistent with existing telemetry design, and the data is already computed at zero extra cost.consider. The finding is factually correct and cheap to act on, but it does not meet the should_fix bar — nothing breaks, the fix works, and aggregate measurability is intact. Note also the finding's parenthetical claim that connect/target-resolution is 'unprotected by the watchdog' is inaccurate for this PR:armIdleTimeout()is armed beforeresolveStreamTarget(line 1317) and re-armed across the connection (line 1416) and stream (line 1472) phases, so the watchdog covers all three; this does not affect the core verdict since phase segmentation is still genuinely useful.Issue description
recordIdleTimeout()builds a richthis.log.warn(...)payload that includesphase: idlePhase(one of"target_resolution" | "connection" | "stream", tracked specifically to distinguish where in the lifecycle the silence occurred) andconnectionDurationMs, but thethis.analytics.track(ANALYTICS_EVENTS.CLOUD_STREAM_IDLE_TIMEOUT, ...)call two lines below only forwardstask_id,run_id,team_id,idle_timeout_ms,bytes_received, andevents_received(matchingCloudStreamIdleTimeoutPropertiesin packages/shared/src/analytics-events.ts:330-337). NeitherphasenorconnectionDurationMsreaches the analytics schema or the tracked event at all. The PR's explicit purpose is to make this previously-invisible failure 'finally measurable' in aggregate — but the one dimension needed to separate 'hung during initial connect/target-resolution' (a different bug class, already flagged elsewhere in this review as unprotected by the watchdog) from 'went silent mid-stream after being healthy' (the PR's actual target scenario) is computed, used for local debugging, and then thrown away before it reaches the analytics pipeline. Anyone querying this new event to gauge how well the fix is working will be unable to tell which phase is timing out without cross-referencing raw logs, defeating the purpose of adding structured analytics in the first place.Suggested fix
Add
phase: idlePhaseandconnection_duration_ms(mirroringconnectionDurationMs) toCloudStreamIdleTimeoutPropertiesin packages/shared/src/analytics-events.ts and pass them through in thethis.analytics.track(...)call inrecordIdleTimeout, e.g.phase: idlePhase, connection_duration_ms: streamWasEstablished ? Date.now() - connectedAt : 0.Prompt to fix with AI (copy-paste)