Skip to content

Commit 3b4d9e9

Browse files
BillLeoutsakosvl346Bill Leoutsakoswaleedlatif1
authored
fix(schedule): reconcile interrupted schedule executions (#6780)
* fix schedule execution recovery * simplify schedule recovery provider handling * fix(schedules): stop reconciliation rewriting healthy carriers and index its scan Follow-up hardening on the schedule recovery reconciliation. Reconciliation settled every carrier it examined, including ones that had already reached a terminal status and recorded their own outcome. Because the normal completion path never stamps the reconciled marker, each successful run's carrier was picked up on the next tick and rewritten: `completedAt` bumped, `error` nulled and `output` replaced with a recovery stub, all of which `GET /api/jobs/[jobId]` surfaces. A completed carrier whose execution log had aged out was additionally flipped to failed. Settle only carriers still in flight; a terminal one is owed schedule accounting and the marker, nothing more. The recovery scan matched no index. There was none on `async_jobs.updated_at`, and the unreconciled-terminal branch tested a jsonb extraction, so the whole OR fell back to a sequential scan and sort of `async_jobs` on every tick. Add the partial index, and spell the branch's status list and metadata key as SQL literals: Postgres cannot prove a parameterised predicate implies a literal index predicate, so a bound key would have left the new index unused. Irrecoverable carrier tombstones were exempted from retention with no secondary expiry, so the one class of row that can never reconcile grew without bound. Give them a longer bounded window instead. `WORKFLOW_EXECUTION_MAX_ROWS_PER_RUN` had become a per-status budget when the stale-execution sweep gained its `redacting` pass, silently doubling the per-run cap. Share the budget across both passes, and add the matching partial indexes so the second pass keeps an index rather than seq-scanning. Also consolidates the carrier metadata keys, their predicates and the jsonb merge into one module -- the two routes were the writer and reader of the same keys with no shared symbol, so a rename type-checked clean while silently breaking retention. * fix(schedules): rotate deferred carriers and stop the redacting sweep failing live runs Addresses the review findings on the reconciliation hardening. A carrier whose accounting was deferred got no write at all, so it kept its `updatedAt` and stayed at the head of the `updatedAt`-ordered recovery batch on every tick, starving every other claimed carrier and never becoming eligible for retention. This was a regression from the previous commit: settling used to bump the timestamp for every examined row, and skipping the settle for already-terminal carriers removed the bump with it. A payload with no `scheduledFor` can never reconcile, so such a row pinned a batch slot permanently. Bump `updatedAt` unconditionally and keep only the reconciled marker conditional. The stale-execution sweep terminalized `redacting` logs on the execution deadline. That deadline bounds execution, while `redacting` covers payload masking after the run already finished -- so a run that used most of its budget entered redaction with the deadline due, and the sweep failed it five minutes later while the worker was still masking. Schedule recovery then read the log as a failed occurrence and counted a failure that never happened, even though the worker's terminal write later restored `completed`. Sweep `redacting` on the generic stale window only. `getScheduleNextRunAt` falls back to a daily cadence when a schedule has no cron expression. Deployment cannot persist such a schedule, so the branch is unreachable, but this change widened its use from failure recovery to every outcome -- log a warning when it fires rather than silently guessing a cadence. `executionDeadlineAt` was missing from the shared `workflowExecutionLogs` schema mock, so it read as `undefined` and assertions comparing against that column were trivially true. Add it. * refactor(schedules): drop vestigial recovery code and close a builder gap Follow-ups from a full re-read of the change. No behavior change except the removed dead code paths. The metadata merge stripped a `scheduleRecoveryBlocked` key on every write. That key has never been written by any shipped code -- it appears nowhere in staging and nowhere in history outside this branch -- so the strip guarded against a state that cannot exist, at the cost of an extra jsonb operation and a bind parameter on every reconciliation write. `processScheduleItem` set `carrierObservedOrLookupUncertain` immediately before returning on an ambiguous enqueue. The flag is only read from the surrounding catch block, which a normal return skips, so the assignment was dead and read as though it were load-bearing. Replaced with a comment stating why the occurrence is preserved. The stale-execution sweep carried two near-identical `jsonb_set` templates that differed only in their error expression, kept flat because the test mock renders nested SQL fragments as placeholders. The suite now has a recursive renderer, so the error expression is a named per-status value and there is one `jsonb_set`. Success was the only schedule outcome without a named update builder, which left `executeScheduleJob` using two idioms for the same guarded write and left the update shape untested. Add `buildScheduleSuccessUpdate` beside its cancellation and failure siblings, use it from both call sites, and cover it the way `buildScheduleCancellationUpdate` is covered -- a mutation of its `failedCount` reset previously passed every suite. --------- Co-authored-by: Bill Leoutsakos <billleoutsakos@Bills-MacBook-Pro.local> Co-authored-by: Waleed Latif <walif6@gmail.com>
1 parent 85902eb commit 3b4d9e9

14 files changed

Lines changed: 21764 additions & 398 deletions

File tree

apps/sim/app/api/cron/cleanup-stale-executions/route.test.ts

Lines changed: 197 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,16 @@ import { asyncJobs, tableJobs, workflowExecutionLogs } from '@sim/db/schema'
55
import { createLogger } from '@sim/logger'
66
import { createMockRequest, dbChainMockFns, queueTableRows, resetDbChainMock } from '@sim/testing'
77
import { beforeEach, describe, expect, it, vi } from 'vitest'
8-
import { MAX_JOB_DURATION_SECONDS, MIN_JOB_DURATION_SECONDS } from '@/lib/core/async-jobs'
8+
import {
9+
JOB_RETENTION_HOURS,
10+
MAX_JOB_DURATION_SECONDS,
11+
MIN_JOB_DURATION_SECONDS,
12+
} from '@/lib/core/async-jobs'
13+
import {
14+
SCHEDULE_CARRIER_IRRECOVERABLE_METADATA_KEY,
15+
SCHEDULE_CARRIER_IRRECOVERABLE_RETENTION_HOURS,
16+
SCHEDULE_CARRIER_RECONCILED_METADATA_KEY,
17+
} from '@/lib/workflows/schedules/carrier-metadata'
918

1019
const { mockDeleteFile, mockVerifyCronAuth } = vi.hoisted(() => ({
1120
mockDeleteFile: vi.fn().mockResolvedValue(undefined),
@@ -27,6 +36,7 @@ interface MockCondition {
2736
conditions?: unknown[]
2837
left?: unknown
2938
right?: unknown
39+
column?: unknown
3040
values?: unknown
3141
toSQL?: () => { sql: string; params: unknown[] }
3242
}
@@ -61,6 +71,33 @@ function createRequest() {
6171
)
6272
}
6373

74+
/** Recursively renders a mocked drizzle fragment, expanding nested fragments. */
75+
function renderSql(fragment: unknown): string {
76+
if (fragment === null || fragment === undefined) return ''
77+
if (typeof fragment !== 'object') return String(fragment)
78+
const candidate = fragment as { rawSql?: string; strings?: string[]; values?: unknown[] }
79+
if (typeof candidate.rawSql === 'string') return candidate.rawSql
80+
if (!candidate.strings) return ''
81+
return candidate.strings
82+
.map((part, index) =>
83+
index < (candidate.values?.length ?? 0)
84+
? `${part}${renderSql(candidate.values?.[index])}`
85+
: part
86+
)
87+
.join('')
88+
}
89+
90+
/** Recursively collects the non-fragment bind values of a mocked fragment. */
91+
function collectSqlParams(fragment: unknown): unknown[] {
92+
if (!fragment || typeof fragment !== 'object') return []
93+
const candidate = fragment as { values?: unknown[] }
94+
if (!candidate.values) return []
95+
return candidate.values.flatMap((value) => {
96+
const nested = collectSqlParams(value)
97+
return nested.length > 0 ? nested : [value]
98+
})
99+
}
100+
64101
describe('stale execution cleanup deadline grace', () => {
65102
beforeEach(() => {
66103
vi.clearAllMocks()
@@ -103,25 +140,18 @@ describe('stale execution cleanup deadline grace', () => {
103140
totalDurationMs: { toSQL: () => { sql: string; params: unknown[] } }
104141
executionData: { toSQL: () => { sql: string; params: unknown[] } }
105142
}
106-
const errorExpression = update.executionData.toSQL()
107-
const staleDurationExpression = errorExpression.params.find(
108-
(value): value is { toSQL: () => { sql: string; params: unknown[] } } =>
109-
typeof value === 'object' &&
110-
value !== null &&
111-
'toSQL' in value &&
112-
value.toSQL().sql.includes('EXTRACT(EPOCH')
113-
)
114143
const totalDurationLeaves = flattenSqlParams(update.totalDurationMs.toSQL())
115-
116-
expect(errorExpression.sql).toContain('CASE')
117-
expect(errorExpression.sql).toContain('IS NOT NULL')
118-
expect(errorExpression.params).toContain(workflowExecutionLogs.executionDeadlineAt)
119-
expect(errorExpression.params).toContain('Execution timed out')
120-
expect(errorExpression.params).toContain(
121-
'Execution terminated: worker timeout or crash after '
122-
)
123-
expect(staleDurationExpression?.toSQL().sql).toContain('ROUND')
124-
expect(staleDurationExpression?.toSQL().params).toContain(workflowExecutionLogs.startedAt)
144+
const renderedError = renderSql(update.executionData)
145+
const errorLeaves = collectSqlParams(update.executionData)
146+
147+
expect(renderedError).toContain('CASE')
148+
expect(renderedError).toContain('IS NOT NULL')
149+
expect(renderedError).toContain('ROUND')
150+
expect(renderedError).toContain('EXTRACT(EPOCH')
151+
expect(errorLeaves).toContain(workflowExecutionLogs.executionDeadlineAt)
152+
expect(errorLeaves).toContain('Execution timed out')
153+
expect(errorLeaves).toContain('Execution terminated: worker timeout or crash after ')
154+
expect(errorLeaves).toContain(workflowExecutionLogs.startedAt)
125155
expect(totalDurationLeaves).toContain(2_147_483_647)
126156
expect(totalDurationLeaves).toContain(workflowExecutionLogs.startedAt)
127157
expect(totalDurationLeaves).toContainEqual(new Date('2026-08-03T12:10:00.000Z'))
@@ -131,6 +161,50 @@ describe('stale execution cleanup deadline grace', () => {
131161
}
132162
})
133163

164+
it('sweeps redacting logs on the generic window, never the execution deadline', async () => {
165+
const response = await GET(createRequest())
166+
167+
expect(response.status).toBe(200)
168+
const redactingPredicates = dbChainMockFns.where.mock.calls
169+
.map(([condition]) => flattenConditions(condition))
170+
.filter((conditions) =>
171+
conditions.some(
172+
(condition) =>
173+
condition.type === 'eq' &&
174+
condition.left === workflowExecutionLogs.status &&
175+
condition.right === 'redacting'
176+
)
177+
)
178+
179+
expect(redactingPredicates.length).toBeGreaterThan(0)
180+
for (const conditions of redactingPredicates) {
181+
expect(
182+
conditions.some((condition) => condition.left === workflowExecutionLogs.executionDeadlineAt)
183+
).toBe(false)
184+
expect(
185+
conditions.some(
186+
(condition) =>
187+
condition.type === 'lt' && condition.left === workflowExecutionLogs.startedAt
188+
)
189+
).toBe(true)
190+
}
191+
})
192+
193+
it('terminalizes stale running and redacting execution logs', async () => {
194+
const response = await GET(createRequest())
195+
196+
expect(response.status).toBe(200)
197+
const statusPredicates = dbChainMockFns.where.mock.calls
198+
.flatMap(([condition]) => flattenConditions(condition))
199+
.filter(
200+
(condition) => condition.type === 'eq' && condition.left === workflowExecutionLogs.status
201+
)
202+
203+
expect(statusPredicates.map(({ right }) => right)).toEqual(
204+
expect.arrayContaining(['running', 'redacting'])
205+
)
206+
})
207+
134208
it('reports a worker cleanup deadline while preserving the generic stale fallback', async () => {
135209
queueTableRows(asyncJobs, [{ id: 'async-job-1' }])
136210
dbChainMockFns.returning.mockResolvedValueOnce([{ id: 'async-job-1' }])
@@ -175,6 +249,108 @@ describe('stale execution cleanup deadline grace', () => {
175249
)
176250
})
177251

252+
it('leaves pending and processing schedule jobs to schedule recovery', async () => {
253+
const response = await GET(createRequest())
254+
255+
expect(response.status).toBe(200)
256+
const activeAsyncPredicates = dbChainMockFns.where.mock.calls
257+
.map(([condition]) => flattenConditions(condition))
258+
.filter((conditions) =>
259+
conditions.some(
260+
(condition) =>
261+
condition.type === 'ne' &&
262+
condition.left === asyncJobs.type &&
263+
condition.right === 'schedule-execution'
264+
)
265+
)
266+
267+
expect(
268+
activeAsyncPredicates.some((conditions) =>
269+
conditions.some(
270+
(condition) =>
271+
condition.type === 'eq' &&
272+
condition.left === asyncJobs.status &&
273+
condition.right === 'processing'
274+
)
275+
)
276+
).toBe(true)
277+
expect(
278+
activeAsyncPredicates.some((conditions) =>
279+
conditions.some(
280+
(condition) =>
281+
condition.type === 'eq' &&
282+
condition.left === asyncJobs.status &&
283+
condition.right === 'pending'
284+
)
285+
)
286+
).toBe(true)
287+
})
288+
289+
it('retains terminal schedule carriers until reconciliation is recorded', async () => {
290+
const response = await GET(createRequest())
291+
292+
expect(response.status).toBe(200)
293+
const retentionConditions = dbChainMockFns.where.mock.calls.flatMap(([condition]) =>
294+
flattenConditions(condition)
295+
)
296+
const reconciliationMarker = retentionConditions.find((condition) =>
297+
renderSql(condition).includes(SCHEDULE_CARRIER_RECONCILED_METADATA_KEY)
298+
)
299+
300+
expect(collectSqlParams(reconciliationMarker)).toContain(asyncJobs.metadata)
301+
expect(
302+
retentionConditions.some(
303+
(condition) =>
304+
condition.type === 'ne' &&
305+
condition.left === asyncJobs.type &&
306+
condition.right === 'schedule-execution'
307+
)
308+
).toBe(true)
309+
})
310+
311+
it('spells carrier metadata keys as SQL literals so the partial index matches', async () => {
312+
const response = await GET(createRequest())
313+
314+
expect(response.status).toBe(200)
315+
const reconciliationMarker = dbChainMockFns.where.mock.calls
316+
.flatMap(([condition]) => flattenConditions(condition))
317+
.find((condition) => renderSql(condition).includes(SCHEDULE_CARRIER_RECONCILED_METADATA_KEY))
318+
319+
expect(renderSql(reconciliationMarker)).toContain(
320+
`'${SCHEDULE_CARRIER_RECONCILED_METADATA_KEY}'`
321+
)
322+
expect(collectSqlParams(reconciliationMarker)).not.toContain(
323+
SCHEDULE_CARRIER_RECONCILED_METADATA_KEY
324+
)
325+
})
326+
327+
it('deletes irrecoverable schedule carrier tombstones once their longer window lapses', async () => {
328+
const response = await GET(createRequest())
329+
330+
expect(response.status).toBe(200)
331+
const retentionConditions = dbChainMockFns.where.mock.calls.flatMap(([condition]) =>
332+
flattenConditions(condition)
333+
)
334+
const irrecoverableExclusion = retentionConditions.find((condition) =>
335+
renderSql(condition).includes(SCHEDULE_CARRIER_IRRECOVERABLE_METADATA_KEY)
336+
)
337+
338+
expect(renderSql(irrecoverableExclusion)).toContain("<> 'true'")
339+
expect(collectSqlParams(irrecoverableExclusion)).toContain(asyncJobs.metadata)
340+
341+
const tombstoneWindow = retentionConditions.filter(
342+
(condition) =>
343+
condition.type === 'lt' &&
344+
condition.left === asyncJobs.completedAt &&
345+
condition.right instanceof Date
346+
)
347+
const oldest = Math.min(...tombstoneWindow.map(({ right }) => (right as Date).getTime()))
348+
const newest = Math.max(...tombstoneWindow.map(({ right }) => (right as Date).getTime()))
349+
expect(newest - oldest).toBe(
350+
(SCHEDULE_CARRIER_IRRECOVERABLE_RETENTION_HOURS - JOB_RETENTION_HOURS) * 60 * 60 * 1000
351+
)
352+
})
353+
178354
it('keeps table-job heartbeat cleanup independent from workflow timeout policy', async () => {
179355
vi.useFakeTimers()
180356
vi.setSystemTime(new Date('2026-08-03T12:00:00.000Z'))
@@ -220,8 +396,8 @@ describe('stale execution cleanup deadline grace', () => {
220396
const response = await GET(createRequest())
221397

222398
expect(response.status).toBe(200)
223-
expect(dbChainMockFns.transaction).toHaveBeenCalledTimes(7)
224-
expect(dbChainMockFns.for).toHaveBeenCalledTimes(7)
399+
expect(dbChainMockFns.transaction).toHaveBeenCalledTimes(8)
400+
expect(dbChainMockFns.for).toHaveBeenCalledTimes(8)
225401
for (const [strength, options] of dbChainMockFns.for.mock.calls) {
226402
expect(strength).toBe('update')
227403
expect(options).toEqual({ skipLocked: true })

0 commit comments

Comments
 (0)