fix(cloud-task): recover SSE streams that go silent instead of hanging forever - #4052
Conversation
…t instead of hanging The stream-read loop in `cloud-task-engine.ts` awaited `reader.read()` with no idle deadline. A half-open socket (laptop sleep, unplugged NIC, NAT rebind) never throws and never EOFs, so the read just hangs forever — the watcher stays "connected" and never reaches the existing reconnect/backoff/error machinery. The only way out was force-quitting the app. This adds an idle watchdog that re-arms on every byte received (data or keepalive) and aborts the connection if the stream goes fully silent for 90s (a few keepalive intervals). The abort now flows into the existing reconnect logic instead of being treated as an intentional cancel, and a new `Cloud stream idle timeout` analytics event makes this failure mode visible for the first time. Generated-By: PostHog Code Task-Id: 2fd7edf4-3fde-47ab-b7e5-3564b2f6b246
|
😎 Merged successfully - details. |
🦔 ReviewHog reviewed this pull requestFound 0 must fix, 0 should fix, 2 consider. Published 2 findings (view the review). |
|
React Doctor found no issues in the changed files. 🎉 Reviewed by React Doctor for commit |
Generated-By: PostHog Code Task-Id: 92b56d91-0d15-416f-8ab9-2b32e3cb3e34
|
ReviewHog Alpha 🦔 If you find any issues helpful - please reply "valid", "invalid", etc., for evaluation purposes 🙏 |
Generated-By: PostHog Code Task-Id: 92b56d91-0d15-416f-8ab9-2b32e3cb3e34
|
/trunk merge |
| 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, | ||
| }); | ||
| } | ||
| }; |
There was a problem hiding this comment.
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
- Checked:
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). - Found: The premise is accurate. The
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. - Found: The sibling event
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. - Impact: This is a real, accurate gap that mildly weakens the PR's stated measurability goal — segmenting idle timeouts by lifecycle phase (connect vs mid-stream) requires cross-referencing raw logs. But it is not a runtime defect: the event still fires and supports aggregate counting, phase remains available in logs for individual debugging, and no user is affected. It is observability polish rather than a correctness/security/reliability bug.
- Priority: Lowering to
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 rich this.log.warn(...) payload that includes phase: idlePhase (one of "target_resolution" | "connection" | "stream", tracked specifically to distinguish where in the lifecycle the silence occurred) and connectionDurationMs, but the this.analytics.track(ANALYTICS_EVENTS.CLOUD_STREAM_IDLE_TIMEOUT, ...) call two lines below only forwards task_id, run_id, team_id, idle_timeout_ms, bytes_received, and events_received (matching CloudStreamIdleTimeoutProperties in packages/shared/src/analytics-events.ts:330-337). Neither phase nor connectionDurationMs reaches 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: idlePhase and connection_duration_ms (mirroring connectionDurationMs) to CloudStreamIdleTimeoutProperties in packages/shared/src/analytics-events.ts and pass them through in the this.analytics.track(...) call in recordIdleTimeout, e.g. phase: idlePhase, connection_duration_ms: streamWasEstablished ? Date.now() - connectedAt : 0.
Prompt to fix with AI (copy-paste)
## Context
@packages/core/src/cloud-task/cloud-task-engine.ts#L1287-1310
<issue_description>
`recordIdleTimeout()` builds a rich `this.log.warn(...)` payload that includes `phase: idlePhase` (one of `"target_resolution" | "connection" | "stream"`, tracked specifically to distinguish where in the lifecycle the silence occurred) and `connectionDurationMs`, but the `this.analytics.track(ANALYTICS_EVENTS.CLOUD_STREAM_IDLE_TIMEOUT, ...)` call two lines below only forwards `task_id`, `run_id`, `team_id`, `idle_timeout_ms`, `bytes_received`, and `events_received` (matching `CloudStreamIdleTimeoutProperties` in packages/shared/src/analytics-events.ts:330-337). Neither `phase` nor `connectionDurationMs` reaches 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.
</issue_description>
<issue_validation>
- **Checked:** `recordIdleTimeout` (cloud-task-engine.ts:1287-1310), the analytics `track` call inside it, the `CloudStreamIdleTimeoutProperties` schema (packages/shared/src/analytics-events.ts:330-337), and the sibling `CloudStreamDisconnectedProperties` schema (analytics-events.ts:318-328).
- **Found:** The premise is accurate. The `log.warn` payload includes `phase: idlePhase` (line 1291) and `connectionDurationMs` (lines 1295-1297), but the `analytics.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.
- **Found:** The sibling event `CloudStreamDisconnectedProperties` (analytics-events.ts:318-328) carries many dimensions (reconnect_attempts, retryable, was_bootstrapping, etc.), so enriching the idle-timeout event with `phase`/`connection_duration_ms` is consistent with existing telemetry design, and the data is already computed at zero extra cost.
- **Impact:** This is a real, accurate gap that mildly weakens the PR's stated measurability goal — segmenting idle timeouts by lifecycle phase (connect vs mid-stream) requires cross-referencing raw logs. But it is not a runtime defect: the event still fires and supports aggregate counting, phase remains available in logs for individual debugging, and no user is affected. It is observability polish rather than a correctness/security/reliability bug.
- **Priority:** Lowering to `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 before `resolveStreamTarget` (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_validation>
## Task
Investigate the issue and solve it
<potential_solution>
Add `phase: idlePhase` and `connection_duration_ms` (mirroring `connectionDurationMs`) to `CloudStreamIdleTimeoutProperties` in packages/shared/src/analytics-events.ts and pass them through in the `this.analytics.track(...)` call in `recordIdleTimeout`, e.g. `phase: idlePhase, connection_duration_ms: streamWasEstablished ? Date.now() - connectedAt : 0`.
</potential_solution>
| 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, | ||
| }); |
There was a problem hiding this comment.
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
- Checked:
resolveStreamTarget(cloud-task-engine.ts:2285-2347), theCLOUD_TASK_AUTHadapter binding (apps/code/src/main/di/container.ts:456-460),AuthService.authenticatedFetch+executeAuthenticatedFetch(auth.ts:212-243, 440-454),AUTH_FETCH_TIMEOUT_MS(auth.ts:44), thearmIdleTimeoutcall site (cloud-task-engine.ts:1317), and the sibling call sites (fetchTaskRunline 2356, stream fetch line 1424). - Found: The mechanism is real. The adapter forwards
initverbatim toAuthService.authenticatedFetch(fetch, url, init)(container.ts:457-460), andexecuteAuthenticatedFetchusessignal: init.signal ?? AbortSignal.timeout(AUTH_FETCH_TIMEOUT_MS)(auth.ts:452) — so passingcontroller.signal(line 2293) does suppress the 30s fallback, and the 401/403 retry reuses the sameinit.signal(auth.ts:232-239).armIdleTimeout()(line 1317) is not re-armed during resolution, so the wholeresolveStreamTarget(both attempts + refresh) shares one 90s window.fetchTaskRun(line 2356) passes no signal and is unaffected, as the finding states. - Impact: The consequence is milder than the title claims. It is not security-relevant (a request-timeout duration is not an auth/permission/leak control) and not a contract break — the
??in auth.ts:452 is an explicit, by-design override point, and passing a caller signal is using the API as intended (the same pattern is used for the real stream fetch at line 1424). A hungstream_tokenfetch is still bounded: at 90s the watchdog aborts,recordIdleTimeout()runs, andhandleStreamCompletion({reconnectOnDisconnect:true})reconnects (lines 1321-1330). So the worst case is recovery in ~90s instead of ~30s for a rare hung metadata fetch, always ending in a graceful reconnect — no wrong results, data loss, or indefinite hang. - Priority: Lowering to
consider. The mechanism is verifiably correct and there is a genuine calibration mismatch worth author awareness — 90s is justified in the PR as "a few multiples of the keepalive interval" for the silent-stream phase, but a one-shot target-resolution fetch inherits it with no such rationale, and the per-attempt bound is lost across the 401 retry. That makes the suggested dedicatedAbortSignal.any([controller.signal, AbortSignal.timeout(30_000)])a reasonable refinement. But the overstated security/contract framing and the bounded, self-recovering real impact keep it below the should_fix bar; it is real-but-minor, so it stays on record at the lowest level rather than being surfaced.
Issue description
Before this PR, resolveStreamTarget's call to this.auth.authenticatedFetch(url, { method: "GET" }) passed no signal. AuthService.executeAuthenticatedFetch (packages/core/src/auth/auth.ts:449-453) falls back to signal: init.signal ?? AbortSignal.timeout(AUTH_FETCH_TIMEOUT_MS) (30_000ms, auth.ts:44) whenever the caller doesn't supply its own signal — so this fetch was always implicitly bounded to 30s, even though nothing in cloud-task-engine.ts armed that bound explicitly. This PR now passes signal (armed via armIdleTimeout() at line 1317, SSE_IDLE_TIMEOUT_MS = 90_000) into that same call (line 2293). Because init.signal is now truthy, AuthService's ?? fallback never kicks in, and the 30s guarantee is silently replaced by the 90s idle-watchdog window. Worse, authenticatedFetch internally does an initial fetch, and on 401/403 calls refreshAccessToken() then retries with a second fetch using the same init.signal (auth.ts:212-243) — so a 401-then-refresh-then-retry sequence during target resolution now shares one 90s budget across both attempts plus the token refresh, instead of each attempt getting its own fresh 30s window as before. This is an unannounced side effect of the PR (the description only discusses the read-loop's idle detection, not a 3x widening of the token-resolution request's timeout) and silently overrides an existing, security-relevant default bound that other unmodified call sites in this same file (e.g. fetchTaskRun, the command/cancel endpoints) still rely on.
Suggested fix
Use a dedicated, shorter-lived AbortSignal for the resolveStreamTarget fetch (e.g. AbortSignal.any([controller.signal, AbortSignal.timeout(AUTH_FETCH_TIMEOUT_MS)]), mirroring the pattern already used in packages/core/src/llm-gateway/llm-gateway.ts where a purpose-built timeoutController is combined with the caller's signal) instead of reusing the SSE idle-watchdog's 90s window verbatim for a one-shot metadata fetch. This preserves both the deliberate-cancel behavior (aborting via controller) and the original ≤30s bound per HTTP attempt.
Prompt to fix with AI (copy-paste)
## Context
@packages/core/src/cloud-task/cloud-task-engine.ts#L2285-2294
@packages/core/src/cloud-task/cloud-task-engine.ts#L1315-1319
<issue_description>
Before this PR, `resolveStreamTarget`'s call to `this.auth.authenticatedFetch(url, { method: "GET" })` passed no `signal`. `AuthService.executeAuthenticatedFetch` (packages/core/src/auth/auth.ts:449-453) falls back to `signal: init.signal ?? AbortSignal.timeout(AUTH_FETCH_TIMEOUT_MS)` (30_000ms, auth.ts:44) whenever the caller doesn't supply its own signal — so this fetch was always implicitly bounded to 30s, even though nothing in cloud-task-engine.ts armed that bound explicitly. This PR now passes `signal` (armed via `armIdleTimeout()` at line 1317, `SSE_IDLE_TIMEOUT_MS = 90_000`) into that same call (line 2293). Because `init.signal` is now truthy, AuthService's `??` fallback never kicks in, and the 30s guarantee is silently replaced by the 90s idle-watchdog window. Worse, `authenticatedFetch` internally does an initial fetch, and on 401/403 calls `refreshAccessToken()` then retries with a second fetch using the *same* `init.signal` (auth.ts:212-243) — so a 401-then-refresh-then-retry sequence during target resolution now shares one 90s budget across both attempts plus the token refresh, instead of each attempt getting its own fresh 30s window as before. This is an unannounced side effect of the PR (the description only discusses the read-loop's idle detection, not a 3x widening of the token-resolution request's timeout) and silently overrides an existing, security-relevant default bound that other unmodified call sites in this same file (e.g. `fetchTaskRun`, the command/cancel endpoints) still rely on.
</issue_description>
<issue_validation>
- **Checked:** `resolveStreamTarget` (cloud-task-engine.ts:2285-2347), the `CLOUD_TASK_AUTH` adapter binding (apps/code/src/main/di/container.ts:456-460), `AuthService.authenticatedFetch` + `executeAuthenticatedFetch` (auth.ts:212-243, 440-454), `AUTH_FETCH_TIMEOUT_MS` (auth.ts:44), the `armIdleTimeout` call site (cloud-task-engine.ts:1317), and the sibling call sites (`fetchTaskRun` line 2356, stream fetch line 1424).
- **Found:** The mechanism is real. The adapter forwards `init` verbatim to `AuthService.authenticatedFetch(fetch, url, init)` (container.ts:457-460), and `executeAuthenticatedFetch` uses `signal: init.signal ?? AbortSignal.timeout(AUTH_FETCH_TIMEOUT_MS)` (auth.ts:452) — so passing `controller.signal` (line 2293) does suppress the 30s fallback, and the 401/403 retry reuses the same `init.signal` (auth.ts:232-239). `armIdleTimeout()` (line 1317) is not re-armed during resolution, so the whole `resolveStreamTarget` (both attempts + refresh) shares one 90s window. `fetchTaskRun` (line 2356) passes no signal and is unaffected, as the finding states.
- **Impact:** The consequence is milder than the title claims. It is not security-relevant (a request-timeout duration is not an auth/permission/leak control) and not a contract break — the `??` in auth.ts:452 is an explicit, by-design override point, and passing a caller signal is using the API as intended (the same pattern is used for the real stream fetch at line 1424). A hung `stream_token` fetch is still bounded: at 90s the watchdog aborts, `recordIdleTimeout()` runs, and `handleStreamCompletion({reconnectOnDisconnect:true})` reconnects (lines 1321-1330). So the worst case is recovery in ~90s instead of ~30s for a rare hung metadata fetch, always ending in a graceful reconnect — no wrong results, data loss, or indefinite hang.
- **Priority:** Lowering to `consider`. The mechanism is verifiably correct and there is a genuine calibration mismatch worth author awareness — 90s is justified in the PR as "a few multiples of the keepalive interval" for the silent-stream phase, but a one-shot target-resolution fetch inherits it with no such rationale, and the per-attempt bound is lost across the 401 retry. That makes the suggested dedicated `AbortSignal.any([controller.signal, AbortSignal.timeout(30_000)])` a reasonable refinement. But the overstated security/contract framing and the bounded, self-recovering real impact keep it below the should_fix bar; it is real-but-minor, so it stays on record at the lowest level rather than being surfaced.
</issue_validation>
## Task
Investigate the issue and solve it
<potential_solution>
Use a dedicated, shorter-lived AbortSignal for the `resolveStreamTarget` fetch (e.g. `AbortSignal.any([controller.signal, AbortSignal.timeout(AUTH_FETCH_TIMEOUT_MS)])`, mirroring the pattern already used in `packages/core/src/llm-gateway/llm-gateway.ts` where a purpose-built `timeoutController` is combined with the caller's signal) instead of reusing the SSE idle-watchdog's 90s window verbatim for a one-shot metadata fetch. This preserves both the deliberate-cancel behavior (aborting via `controller`) and the original ≤30s bound per HTTP attempt.
</potential_solution>
Problem
while (true) { await reader.read() }inpackages/core/src/cloud-task/cloud-task-engine.ts) has no idle deadline. A half-open socket neither throws nor EOFs, so the read just hangs — nothing ever triggers the engine's existing reconnect/backoff/error machinery.errorstate), and there is no periodic refetch to paper over it.Changes
connectSse: it re-arms on every byte received (a real event or a keepalive) and aborts the connection if the stream goes fully silent for 90s (a few multiples of the backend's keepalive interval).Cloud stream idle timeoutanalytics event so this previously-invisible failure mode is finally measurable.How did you test this?
pnpm --filter @posthog/core exec vitest run src/cloud-task/cloud-task.test.ts— 73/73 passing.pnpm --filter @posthog/core typecheckandpnpm exec biome lint packages/core— clean.Agent context
retryUnhealthyCloudSessions()beyondstatus === "error"and adding a manual refresh-from-source action, per the linked report. Skipped both here: once the idle watchdog turns a silent hang into a real disconnect, the watcher correctly cycles through reconnect/error states again, so the existing focus/network-reconnect sweep (which already targetsstatus === "error") covers the case without changes. A manual refresh action is a separate, larger UI feature and not needed to close the reported symptom.Automatic notifications
Created with PostHog from an inbox report.