From 0778182fdbb80e4eb96e2aa570fa0543a2e529b6 Mon Sep 17 00:00:00 2001 From: Billy Dunn Date: Fri, 7 Aug 2026 11:22:56 -0500 Subject: [PATCH 1/2] fix(api): honour the script's own timeoutSeconds in the stale reaper (#3190) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit reapStaleScriptExecutions used a flat `300s + 5min grace` deadline for every execution and never read the script's own `timeoutSeconds`. That is wrong in both directions: a legitimately long-running script was reaped and reported as "no response from agent" while it was still executing correctly, and a short-timeout script sat pending far past its own contract. The deadline now comes from the script row via getCommandTimeoutMs — the same helper reapStaleDeviceCommands already uses a few lines above — so there is one source of truth for how long a script may take rather than a second copy that can drift. Both the SQL pre-filter and the per-row re-check use it. The re-check matters: leaving that on a fixed constant would keep enforcing the old floor and make the change inert for exactly the short-timeout case the issue describes. `script_executions.script_id` is NOT NULL, so the join to `scripts` cannot drop rows. Executions whose script carries the default 300s are unaffected: the old constant was precisely getCommandTimeoutMs's default result. Claude-Session: https://claude.ai/code/session_01RUup17Z6KMH9jSkhBBhRJ1 --- apps/api/src/jobs/staleCommandReaper.test.ts | 60 ++++++++++++++++++++ apps/api/src/jobs/staleCommandReaper.ts | 35 ++++++++++-- apps/api/src/services/commandTimeouts.ts | 6 +- 3 files changed, 94 insertions(+), 7 deletions(-) diff --git a/apps/api/src/jobs/staleCommandReaper.test.ts b/apps/api/src/jobs/staleCommandReaper.test.ts index 2ebd5b298..c38d369d6 100644 --- a/apps/api/src/jobs/staleCommandReaper.test.ts +++ b/apps/api/src/jobs/staleCommandReaper.test.ts @@ -941,6 +941,66 @@ describe('reapStaleSoftwareDeploymentResults', () => { // stamped `timeout` / "no response from agent". That is false whenever a terminal // device_commands row exists — the agent DID answer. On one live instance 89 // executions read `timeout` while their command had completed with output. +// #3190: the reaper used a flat 300s+grace deadline for every execution and +// ignored the script's own `timeoutSeconds`, which is wrong in both directions. +// These two cases are the issue's two symptoms, and each one flips if the +// per-script deadline is reverted to a constant. +describe('reapStaleScriptExecutions per-script timeout (#3190)', () => { + beforeEach(() => { + vi.resetAllMocks(); + }); + + function arrangeExec(opts: { timeoutSeconds: number; ageMs: number }) { + const createdAt = new Date(Date.now() - opts.ageMs); + selectMock + .mockReturnValueOnce(selectChain([ + { + id: 'exec-1', + status: 'pending', + scriptId: 'script-1', + createdAt, + startedAt: null, + timeoutSeconds: opts.timeoutSeconds, + }, + ])) + // the #3097 device-command lookup — no terminal row, so the guard is inert + .mockReturnValueOnce(selectChain([])); + + const execSet = vi.fn((_values: Record) => ({ + where: vi.fn(() => ({ returning: vi.fn().mockResolvedValue([{ id: 'exec-1' }]) })), + })); + updateMock.mockImplementation((table: unknown) => { + if (table === scriptExecutionsTable) return { set: execSet }; + throw new Error(`Unexpected table update: ${String(table)}`); + }); + return { execSet }; + } + + it('reaps a short-timeout script once its own deadline has passed', async () => { + // 30s script => 30s + 5min grace = 5.5min. At 7 minutes it is overdue. + // Under the old flat 10-minute deadline this row was skipped, so the + // execution sat pending far past its own contract. + const { execSet } = arrangeExec({ timeoutSeconds: 30, ageMs: 7 * 60 * 1000 }); + + const reaped = await reapStaleScriptExecutions(); + + expect(reaped).toBe(1); + expect(execSet).toHaveBeenCalledTimes(1); + }); + + it('leaves a long-timeout script alone while it is still within its deadline', async () => { + // 1h script => 1h + 5min grace. At 30 minutes it is still running legally. + // Under the old flat 10-minute deadline this was reaped and reported as + // "no response from agent" while the script was working correctly. + const { execSet } = arrangeExec({ timeoutSeconds: 3600, ageMs: 30 * 60 * 1000 }); + + const reaped = await reapStaleScriptExecutions(); + + expect(reaped).toBe(0); + expect(execSet).not.toHaveBeenCalled(); + }); +}); + describe('reapStaleScriptExecutions terminal-command guard (#3097)', () => { const longAgo = new Date(Date.now() - 60 * 60 * 1000); diff --git a/apps/api/src/jobs/staleCommandReaper.ts b/apps/api/src/jobs/staleCommandReaper.ts index 38531f765..952736945 100644 --- a/apps/api/src/jobs/staleCommandReaper.ts +++ b/apps/api/src/jobs/staleCommandReaper.ts @@ -6,6 +6,7 @@ import { deviceCommands, scriptExecutions, scriptExecutionBatches, + scripts, patchJobs, patchJobResults, deployments, @@ -21,11 +22,11 @@ import { STALE_BACKUP_REAP_MARKER, } from '../db/schema'; import { getBullMQConnection } from '../services/redis'; -import { getCommandTimeoutMs, EXCLUDED_COMMAND_TYPES } from '../services/commandTimeouts'; +import { getCommandTimeoutMs, EXCLUDED_COMMAND_TYPES, SCRIPT_GRACE_BUFFER_MS } from '../services/commandTimeouts'; import { captureException } from '../services/sentry'; import { recordBackupCommandTimeout, recordRestoreTimeout } from '../services/backupMetrics'; import { revokeViewerSession } from '../services/viewerTokenRevocation'; -import { queueBackupStopCommand } from '../services/commandQueue'; +import { queueBackupStopCommand, CommandTypes } from '../services/commandQueue'; import { envInt } from '../utils/envInt'; const QUEUE_NAME = 'stale-command-reaper'; @@ -287,9 +288,23 @@ export async function reapStaleDeviceCommands(): Promise { } export async function reapStaleScriptExecutions(): Promise { - // Default script timeout + grace buffer (300s script + 300s grace = 10 min) - const defaultTimeoutMs = 300 * 1000 + 5 * 60 * 1000; - const conservativeCutoff = new Date(Date.now() - defaultTimeoutMs); + // #3190: this used to be a flat `300s + 5min grace` for every execution, + // ignoring the script's own `timeoutSeconds`. That is wrong in both + // directions: a legitimately long script was reaped and reported as stale + // while it was still running correctly, and a short-timeout script sat + // pending far past its own contract. + // + // The deadline now comes from the script row, through the same + // `getCommandTimeoutMs` used by the device-command reaper above — one source + // of truth for "how long may a script take", rather than a second copy that + // can drift from it. + // + // The SQL pre-filter uses the grace buffer alone as a conservative floor: + // `timeoutSeconds` is a non-negative integer, so every per-script deadline is + // at least SCRIPT_GRACE_BUFFER_MS and nothing younger than that can be due. + // Rows selected here are re-checked per row below against their own script's + // deadline, mirroring reapStaleDeviceCommands. + const conservativeCutoff = new Date(Date.now() - SCRIPT_GRACE_BUFFER_MS); const staleExecs = await db .select({ @@ -298,8 +313,10 @@ export async function reapStaleScriptExecutions(): Promise { scriptId: scriptExecutions.scriptId, createdAt: scriptExecutions.createdAt, startedAt: scriptExecutions.startedAt, + timeoutSeconds: scripts.timeoutSeconds, }) .from(scriptExecutions) + .innerJoin(scripts, eq(scripts.id, scriptExecutions.scriptId)) .where( and( inArray(scriptExecutions.status, ['pending', 'queued', 'running']), @@ -313,11 +330,17 @@ export async function reapStaleScriptExecutions(): Promise { let reaped = 0; for (const exec of staleExecs) { + // The per-row deadline must use the script's own value too. Leaving this + // check on a fixed constant would keep enforcing the old floor and make + // the fix inert for exactly the short-timeout case #3190 describes. + const timeoutMs = getCommandTimeoutMs(CommandTypes.SCRIPT, { + timeoutSeconds: exec.timeoutSeconds, + }); const referenceTime = exec.status === 'running' && exec.startedAt ? exec.startedAt.getTime() : exec.createdAt.getTime(); - if (now - referenceTime < defaultTimeoutMs) continue; + if (now - referenceTime < timeoutMs) continue; // #3097: this lookup used to happen AFTER the update, purely to find the // batch. It runs first now because it also answers whether the agent diff --git a/apps/api/src/services/commandTimeouts.ts b/apps/api/src/services/commandTimeouts.ts index ddb08ce35..1b68c40d5 100644 --- a/apps/api/src/services/commandTimeouts.ts +++ b/apps/api/src/services/commandTimeouts.ts @@ -13,7 +13,11 @@ const TWO_HOURS = 2 * 60 * 60 * 1000; // sit before the generic reaper closes it out. const SEVEN_DAYS = 7 * 24 * 60 * 60 * 1000; const DEFAULT_TIMEOUT_MS = THIRTY_MINUTES; -const SCRIPT_GRACE_BUFFER_MS = 5 * 60 * 1000; // extra buffer on top of per-script timeout +// Extra buffer on top of a script's own timeout, so the agent-side timeout +// always fires first. Exported because the stale reaper needs it as the floor +// for its SQL pre-filter: every per-script deadline is at least this long, so +// nothing younger than the buffer can be due (#3190). +export const SCRIPT_GRACE_BUFFER_MS = 5 * 60 * 1000; const DEFAULT_SCRIPT_TIMEOUT_S = 300; // ── Commands that should never be reaped (interactive sessions) ─── From cba838e854d8c1d0e11c04990ce51c03b253d7b0 Mon Sep 17 00:00:00 2001 From: Billy Dunn Date: Fri, 7 Aug 2026 14:36:07 -0500 Subject: [PATCH 2/2] test(api): fix comment placement and cover the running reference-time branch (#3190) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Review follow-up on #3213. The new #3190 describe block was inserted directly under the #3097 terminal-guard rationale, orphaning that comment from the block it documents and making it read as the preamble to the wrong tests. Moved it back above its own describe. Also adds the third case Todd flagged: nothing in this file had ever exercised the reference-time branch. That was tolerable when the deadline was one flat constant, but now that it is per-script, which timestamp we measure from and how long the budget is interact — so a regression there would ship green. Old createdAt, recent startedAt, short script: measuring from createdAt would reap it, measuring from startedAt does not. Confirmed failing against the previous behaviour: forcing referenceTime to createdAt fails exactly this new case and leaves the other 36 passing. Claude-Session: https://claude.ai/code/session_01RUup17Z6KMH9jSkhBBhRJ1 --- apps/api/src/jobs/staleCommandReaper.test.ts | 46 +++++++++++++++++--- 1 file changed, 41 insertions(+), 5 deletions(-) diff --git a/apps/api/src/jobs/staleCommandReaper.test.ts b/apps/api/src/jobs/staleCommandReaper.test.ts index c38d369d6..149435e51 100644 --- a/apps/api/src/jobs/staleCommandReaper.test.ts +++ b/apps/api/src/jobs/staleCommandReaper.test.ts @@ -936,11 +936,6 @@ describe('reapStaleSoftwareDeploymentResults', () => { }); -// #3097: script results submitted over the HTTP path never reach -// `script_executions`, so the row stays pending, lands in this reaper, and was -// stamped `timeout` / "no response from agent". That is false whenever a terminal -// device_commands row exists — the agent DID answer. On one live instance 89 -// executions read `timeout` while their command had completed with output. // #3190: the reaper used a flat 300s+grace deadline for every execution and // ignored the script's own `timeoutSeconds`, which is wrong in both directions. // These two cases are the issue's two symptoms, and each one flips if the @@ -988,6 +983,42 @@ describe('reapStaleScriptExecutions per-script timeout (#3190)', () => { expect(execSet).toHaveBeenCalledTimes(1); }); + // Pins the `running` reference-time branch, which had no coverage anywhere in + // this file. It only mattered once the deadline became per-script: "which + // timestamp do we measure from" and "how long is the budget" now interact, so + // a regression in either could otherwise ship green. Old createdAt, recent + // startedAt, short script — measuring from createdAt would reap it, measuring + // from startedAt correctly does not. + it('measures a running execution from startedAt, not createdAt', async () => { + const createdAt = new Date(Date.now() - 60 * 60 * 1000); + const startedAt = new Date(Date.now() - 60 * 1000); + selectMock + .mockReturnValueOnce(selectChain([ + { + id: 'exec-1', + status: 'running', + scriptId: 'script-1', + createdAt, + startedAt, + timeoutSeconds: 30, + }, + ])) + .mockReturnValueOnce(selectChain([])); + + const execSet = vi.fn((_values: Record) => ({ + where: vi.fn(() => ({ returning: vi.fn().mockResolvedValue([{ id: 'exec-1' }]) })), + })); + updateMock.mockImplementation((table: unknown) => { + if (table === scriptExecutionsTable) return { set: execSet }; + throw new Error(`Unexpected table update: ${String(table)}`); + }); + + const reaped = await reapStaleScriptExecutions(); + + expect(reaped).toBe(0); + expect(execSet).not.toHaveBeenCalled(); + }); + it('leaves a long-timeout script alone while it is still within its deadline', async () => { // 1h script => 1h + 5min grace. At 30 minutes it is still running legally. // Under the old flat 10-minute deadline this was reaped and reported as @@ -1001,6 +1032,11 @@ describe('reapStaleScriptExecutions per-script timeout (#3190)', () => { }); }); +// #3097: script results submitted over the HTTP path never reach +// `script_executions`, so the row stays pending, lands in this reaper, and was +// stamped `timeout` / "no response from agent". That is false whenever a terminal +// device_commands row exists — the agent DID answer. On one live instance 89 +// executions read `timeout` while their command had completed with output. describe('reapStaleScriptExecutions terminal-command guard (#3097)', () => { const longAgo = new Date(Date.now() - 60 * 60 * 1000);