diff --git a/apps/api/src/jobs/staleCommandReaper.test.ts b/apps/api/src/jobs/staleCommandReaper.test.ts index 2ebd5b298..149435e51 100644 --- a/apps/api/src/jobs/staleCommandReaper.test.ts +++ b/apps/api/src/jobs/staleCommandReaper.test.ts @@ -936,6 +936,102 @@ describe('reapStaleSoftwareDeploymentResults', () => { }); +// #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); + }); + + // 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 + // "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(); + }); +}); + // #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 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) ───