Skip to content

Commit b9a70e4

Browse files
authored
fix(execution): give a cancelled async run its terminal metadata (#6693)
* fix(execution): give a cancelled async run its terminal metadata The staging integration suite has been failing integ-cancel-async-api-key/async-execution-becomes-cancelled: the run reports status cancelled with a null endedAt and a null duration, so the assertion fails and the dependent worker-stop check never runs. The run resource falls back to the queue job whenever no execution-log row exists yet, and a cancel that lands before the worker has written that row leaves exactly that state. Trigger.dev marks a run canceled the moment it accepts the cancellation but only stamps its finish time when the worker drains, so for the seconds in between the job is terminal with no timestamp, and the projection faithfully reports a terminal status with nothing to date it. The run writes a correct log row when it finally drains, which is why the endpoint heals itself and the alarm fires intermittently rather than always. The backend was discarding the one timestamp that is always present: the retrieve response carries a required updatedAt beside the optional finishedAt. A finish time still wins wherever it exists, so nothing that already reports correctly changes, and the fallback is taken only once the mapped status is terminal — an active run's updatedAt marks progress, and reading it as an end would retire a run that is still going. It records the server's last transition for the run rather than the reader's clock, so it stays put across polls instead of growing. Also carries the duration on a fifth cancellation write, in the internal cancel route, that the earlier pass missed because its sweep covered lib and not app. * refactor(execution): derive a cancelled run's terminal fields in one place The five cancellation paths each hand-assembled the same four-key payload for the workflow-execution log, and one of them had already drifted: the direct cancel never cleared `execution_deadline_at`, leaving a cancelled row carrying the deadline of an attempt that had stopped running. Extract the payload so the key set cannot vary between them, and leave the paths themselves alone — they differ in handle, claim predicate, whether they read the row back, and what they do when the claim is lost, so they stay separate statements. Bind the end instant through the `started_at` column encoder rather than a pre-stringified ISO literal. `check:sql-date-binding` exists to enforce exactly that binding; the literal passed only because it was already a string. Collapse the duration expression to one `COALESCE` over a valueless-`ELSE` `CASE`, which builds the elapsed fragment once instead of in both branches, and reuse it for the stale-execution sweeper, which carried its own copy along with a second int4 ceiling constant. Document the invariants the fix depends on where a reader meets them: that `total_duration_ms` means wall clock for a terminal row and active time for a paused one, and that a terminal job must carry its transition instant.
1 parent c6047ef commit b9a70e4

16 files changed

Lines changed: 274 additions & 64 deletions

File tree

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

Lines changed: 19 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -37,6 +37,21 @@ function flattenConditions(condition: unknown): MockCondition[] {
3737
return [node, ...(node.conditions?.flatMap((child) => flattenConditions(child)) ?? [])]
3838
}
3939

40+
function hasToSQL(value: unknown): value is { toSQL: () => { sql: string; params: unknown[] } } {
41+
return typeof value === 'object' && value !== null && 'toSQL' in value
42+
}
43+
44+
/**
45+
* Collects the leaves of a nested `sql` expression. The duration expression is
46+
* built by a shared helper, so the values it binds sit one level below the
47+
* fragment this route assembles rather than directly in its own params.
48+
*/
49+
function flattenSqlParams(expression: { sql: string; params: unknown[] }): unknown[] {
50+
return expression.params.flatMap((param) =>
51+
hasToSQL(param) ? flattenSqlParams(param.toSQL()) : [param]
52+
)
53+
}
54+
4055
function createRequest() {
4156
return createMockRequest(
4257
'GET',
@@ -96,11 +111,7 @@ describe('stale execution cleanup deadline grace', () => {
96111
'toSQL' in value &&
97112
value.toSQL().sql.includes('EXTRACT(EPOCH')
98113
)
99-
const totalDurationExpression = update.totalDurationMs.toSQL()
100-
const cleanupTimestamp = totalDurationExpression.params.find(
101-
(value): value is { toSQL: () => { sql: string; params: unknown[] } } =>
102-
typeof value === 'object' && value !== null && 'toSQL' in value
103-
)
114+
const totalDurationLeaves = flattenSqlParams(update.totalDurationMs.toSQL())
104115

105116
expect(errorExpression.sql).toContain('CASE')
106117
expect(errorExpression.sql).toContain('IS NOT NULL')
@@ -111,11 +122,9 @@ describe('stale execution cleanup deadline grace', () => {
111122
)
112123
expect(staleDurationExpression?.toSQL().sql).toContain('ROUND')
113124
expect(staleDurationExpression?.toSQL().params).toContain(workflowExecutionLogs.startedAt)
114-
expect(totalDurationExpression.sql).toContain('LEAST')
115-
expect(totalDurationExpression.sql).toContain('ROUND')
116-
expect(totalDurationExpression.params).toContain(2_147_483_647)
117-
expect(totalDurationExpression.params).toContain(workflowExecutionLogs.startedAt)
118-
expect(cleanupTimestamp?.toSQL().params).toEqual([new Date('2026-08-03T12:10:00.000Z')])
125+
expect(totalDurationLeaves).toContain(2_147_483_647)
126+
expect(totalDurationLeaves).toContain(workflowExecutionLogs.startedAt)
127+
expect(totalDurationLeaves).toContainEqual(new Date('2026-08-03T12:10:00.000Z'))
119128
expect(update.endedAt).toEqual(new Date('2026-08-03T12:10:00.000Z'))
120129
} finally {
121130
vi.useRealTimers()

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

Lines changed: 2 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@ import {
2525
} from '@/lib/core/execution-limits'
2626
import { withRouteHandler } from '@/lib/core/utils/with-route-handler'
2727
import type { DbTransaction } from '@/lib/db/types'
28+
import { elapsedDurationMsSql } from '@/lib/logs/execution/duration'
2829
import { deleteFile } from '@/lib/uploads/core/storage-service'
2930

3031
const logger = createLogger('CleanupStaleExecutions')
@@ -33,7 +34,6 @@ const STALE_THRESHOLD_MS = getExecutionReservationTtlMs()
3334
const STALE_THRESHOLD_MINUTES = Math.ceil(STALE_THRESHOLD_MS / 60000)
3435
const GENERIC_STALE_PROCESSING_ERROR = `Job terminated: stuck in processing for more than ${STALE_THRESHOLD_MINUTES} minutes`
3536
const EXECUTION_DEADLINE_ERROR = getTimeoutErrorMessage(undefined)
36-
const MAX_INT32 = 2_147_483_647
3737
/**
3838
* Table jobs run as detached workers with progress heartbeats, independently of workflow timeout
3939
* policy. Preserve their historical 90-minute task window plus five-minute cleanup grace.
@@ -154,10 +154,7 @@ export const GET = withRouteHandler(async (request: NextRequest) => {
154154
const staleDurationMinutes = sql<number>`ROUND(
155155
EXTRACT(EPOCH FROM (${cleanupTimestamp} - ${workflowExecutionLogs.startedAt})) / 60
156156
)::integer`
157-
const totalDurationMs = sql<number>`LEAST(
158-
${MAX_INT32},
159-
ROUND(EXTRACT(EPOCH FROM (${cleanupTimestamp} - ${workflowExecutionLogs.startedAt})) * 1000)
160-
)::integer`
157+
const totalDurationMs = elapsedDurationMsSql(now)
161158
let workflowRowsConsidered = 0
162159
while (workflowRowsConsidered < WORKFLOW_EXECUTION_MAX_ROWS_PER_RUN) {
163160
const limit = Math.min(

apps/sim/app/api/workflows/[id]/executions/[executionId]/cancel/route.test.ts

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1320,6 +1320,7 @@ describe('POST /api/workflows/[id]/executions/[executionId]/cancel', () => {
13201320
expect(mockSet).toHaveBeenCalledWith({
13211321
status: 'cancelled',
13221322
endedAt: expect.any(Date),
1323+
totalDurationMs: expect.anything(),
13231324
executionDeadlineAt: null,
13241325
})
13251326
})
@@ -1340,6 +1341,7 @@ describe('POST /api/workflows/[id]/executions/[executionId]/cancel', () => {
13401341
expect(mockSet).toHaveBeenCalledWith({
13411342
status: 'cancelled',
13421343
endedAt: expect.any(Date),
1344+
totalDurationMs: expect.anything(),
13431345
executionDeadlineAt: null,
13441346
})
13451347
})

apps/sim/app/api/workflows/[id]/executions/[executionId]/cancel/route.ts

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,7 @@ import {
2424
} from '@/lib/execution/cancellation'
2525
import { createExecutionEventWriter, readExecutionMetaState } from '@/lib/execution/event-buffer'
2626
import { abortManualExecution } from '@/lib/execution/manual-cancellation'
27+
import { cancelledExecutionLogFields } from '@/lib/logs/execution/cancellation'
2728
import { workflowExecutionOriginSql } from '@/lib/logs/execution-origin'
2829
import { captureServerEvent } from '@/lib/posthog/server'
2930
import {
@@ -215,7 +216,7 @@ async function claimExecutionLogCancellation(args: {
215216
const now = new Date()
216217
const [cancelledExecution] = await db
217218
.update(workflowExecutionLogs)
218-
.set({ status: 'cancelled', endedAt: now, executionDeadlineAt: null })
219+
.set(cancelledExecutionLogFields(now))
219220
.where(
220221
and(
221222
eq(workflowExecutionLogs.executionId, args.executionId),

apps/sim/lib/core/async-jobs/backends/trigger-dev.test.ts

Lines changed: 74 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -331,6 +331,80 @@ describe('TriggerDevJobQueue status mapping', () => {
331331

332332
await expect(queue.getJob('run-1')).resolves.toMatchObject({ status: jobStatus })
333333
})
334+
335+
it('dates a run cancelled before it was dequeued by its last transition', async () => {
336+
mockRetrieve.mockResolvedValueOnce({
337+
id: 'run-1',
338+
payload: {},
339+
status: 'CANCELED',
340+
taskIdentifier: 'workflow-execution',
341+
createdAt: new Date('2026-08-05T12:00:00.000Z'),
342+
updatedAt: new Date('2026-08-05T12:00:02.000Z'),
343+
})
344+
const queue = new TriggerDevJobQueue()
345+
346+
await expect(queue.getJob('run-1')).resolves.toMatchObject({
347+
status: 'cancelled',
348+
startedAt: undefined,
349+
completedAt: new Date('2026-08-05T12:00:02.000Z'),
350+
})
351+
})
352+
353+
it('dates a run cancelled mid-flight by its last transition until it drains', async () => {
354+
mockRetrieve.mockResolvedValueOnce({
355+
id: 'run-1',
356+
payload: {},
357+
status: 'CANCELED',
358+
taskIdentifier: 'workflow-execution',
359+
createdAt: new Date('2026-08-05T12:00:00.000Z'),
360+
startedAt: new Date('2026-08-05T12:00:01.000Z'),
361+
updatedAt: new Date('2026-08-05T12:00:03.000Z'),
362+
})
363+
const queue = new TriggerDevJobQueue()
364+
365+
await expect(queue.getJob('run-1')).resolves.toMatchObject({
366+
status: 'cancelled',
367+
startedAt: new Date('2026-08-05T12:00:01.000Z'),
368+
completedAt: new Date('2026-08-05T12:00:03.000Z'),
369+
})
370+
})
371+
372+
it('prefers the reported finish over the last transition once the run has drained', async () => {
373+
mockRetrieve.mockResolvedValueOnce({
374+
id: 'run-1',
375+
payload: {},
376+
status: 'COMPLETED',
377+
taskIdentifier: 'workflow-execution',
378+
createdAt: new Date('2026-08-05T12:00:00.000Z'),
379+
startedAt: new Date('2026-08-05T12:00:01.000Z'),
380+
finishedAt: new Date('2026-08-05T12:00:04.000Z'),
381+
updatedAt: new Date('2026-08-05T12:00:09.000Z'),
382+
})
383+
const queue = new TriggerDevJobQueue()
384+
385+
await expect(queue.getJob('run-1')).resolves.toMatchObject({
386+
status: 'completed',
387+
completedAt: new Date('2026-08-05T12:00:04.000Z'),
388+
})
389+
})
390+
391+
it('leaves a still-running job with no completion instant', async () => {
392+
mockRetrieve.mockResolvedValueOnce({
393+
id: 'run-1',
394+
payload: {},
395+
status: 'EXECUTING',
396+
taskIdentifier: 'workflow-execution',
397+
createdAt: new Date('2026-08-05T12:00:00.000Z'),
398+
startedAt: new Date('2026-08-05T12:00:01.000Z'),
399+
updatedAt: new Date('2026-08-05T12:00:03.000Z'),
400+
})
401+
const queue = new TriggerDevJobQueue()
402+
403+
await expect(queue.getJob('run-1')).resolves.toMatchObject({
404+
status: 'processing',
405+
completedAt: undefined,
406+
})
407+
})
334408
})
335409

336410
describe('TriggerDevJobQueue cancellation', () => {

apps/sim/lib/core/async-jobs/backends/trigger-dev.ts

Lines changed: 31 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@ import {
1717
type JobQueueBackend,
1818
type JobStatus,
1919
type JobType,
20+
TERMINAL_JOB_STATUSES,
2021
validateMaxDurationSeconds,
2122
} from '@/lib/core/async-jobs/types'
2223
import { recordExecutionCancellationBackendResult } from '@/lib/core/execution-limits/metrics'
@@ -213,6 +214,32 @@ function mapTriggerDevStatus(status: string): JobStatus {
213214
}
214215
}
215216

217+
/**
218+
* Dates the end of a run that trigger.dev already reports as terminal.
219+
*
220+
* A cancellation flips the run to `CANCELED` the moment it is accepted, but
221+
* `finishedAt` is only stamped once the worker actually drains — seconds later,
222+
* or never for a run that was cancelled before it was ever dequeued. A reader
223+
* polling inside that window sees a terminal job carrying no completion
224+
* instant, and every consumer that derives an end timestamp or an elapsed
225+
* duration from it reports null.
226+
*
227+
* `updatedAt` is trigger.dev's own record of when the run last changed, so for
228+
* a terminal run it dates that final transition rather than the read. It is
229+
* consulted only once the status is terminal: an active run's `updatedAt`
230+
* describes progress, not an ending, and reporting it would end a run that is
231+
* still going.
232+
*/
233+
function resolveRunCompletedAt(
234+
finishedAt: Date | string | undefined,
235+
updatedAt: Date | string | undefined,
236+
status: JobStatus
237+
): Date | undefined {
238+
if (finishedAt) return new Date(finishedAt)
239+
if (!TERMINAL_JOB_STATUSES.includes(status)) return undefined
240+
return updatedAt ? new Date(updatedAt) : undefined
241+
}
242+
216243
/**
217244
* Adapter that wraps the trigger.dev SDK to conform to JobQueueBackend interface.
218245
*/
@@ -379,14 +406,16 @@ export class TriggerDevJobQueue implements JobQueueBackend {
379406
: undefined,
380407
}
381408

409+
const status = mapTriggerDevStatus(run.status)
410+
382411
return {
383412
id: run.id,
384413
type: run.taskIdentifier as JobType,
385414
payload: run.payload,
386-
status: mapTriggerDevStatus(run.status),
415+
status,
387416
createdAt: run.createdAt ? new Date(run.createdAt) : new Date(),
388417
startedAt: run.startedAt ? new Date(run.startedAt) : undefined,
389-
completedAt: run.finishedAt ? new Date(run.finishedAt) : undefined,
418+
completedAt: resolveRunCompletedAt(run.finishedAt, run.updatedAt, status),
390419
attempts: run.attemptCount ?? 1,
391420
maxAttempts: 3,
392421
error: run.error?.message,

apps/sim/lib/core/async-jobs/types.ts

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,13 @@ export const JOB_STATUS = {
2929

3030
export type JobStatus = (typeof JOB_STATUS)[keyof typeof JOB_STATUS]
3131

32+
/** The statuses a job cannot leave; every one of them requires a `completedAt`. */
33+
export const TERMINAL_JOB_STATUSES: readonly JobStatus[] = [
34+
JOB_STATUS.COMPLETED,
35+
JOB_STATUS.FAILED,
36+
JOB_STATUS.CANCELLED,
37+
]
38+
3239
export type JobType =
3340
| 'workflow-execution'
3441
| 'schedule-execution'
@@ -84,6 +91,14 @@ export interface Job<TPayload = unknown, TOutput = unknown> {
8491
status: JobStatus
8592
createdAt: Date
8693
startedAt?: Date
94+
/**
95+
* When the job reached its current status, required whenever that status is
96+
* one of `TERMINAL_JOB_STATUSES`. Consumers derive both an end timestamp and
97+
* an elapsed duration from it, so a terminal job that omits it reports null
98+
* for each. A backend reading an eventually-consistent source must supply its
99+
* best-known transition instant rather than leaving this unset — never the
100+
* time of the read, which grows on every poll.
101+
*/
87102
completedAt?: Date
88103
attempts: number
89104
maxAttempts: number

apps/sim/lib/execution/cancel-workflow-execution.ts

Lines changed: 2 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,7 @@ import {
1212
} from '@/lib/execution/cancellation'
1313
import { createExecutionEventWriter, readExecutionMetaState } from '@/lib/execution/event-buffer'
1414
import { abortManualExecution } from '@/lib/execution/manual-cancellation'
15-
import { elapsedDurationMsSql } from '@/lib/logs/execution/duration'
15+
import { cancelledExecutionLogFields } from '@/lib/logs/execution/cancellation'
1616
import { captureServerEvent } from '@/lib/posthog/server'
1717
import {
1818
cancelWorkflowGroupExecution,
@@ -381,11 +381,7 @@ export async function cancelWorkflowExecution(
381381
const cancelledAt = new Date()
382382
await db
383383
.update(workflowExecutionLogs)
384-
.set({
385-
status: 'cancelled',
386-
endedAt: cancelledAt,
387-
totalDurationMs: elapsedDurationMsSql(cancelledAt),
388-
})
384+
.set(cancelledExecutionLogFields(cancelledAt))
389385
.where(
390386
and(
391387
eq(workflowExecutionLogs.executionId, executionId),
Lines changed: 49 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,49 @@
1+
/**
2+
* @vitest-environment node
3+
*/
4+
5+
import { describe, expect, it, vi } from 'vitest'
6+
7+
vi.unmock('drizzle-orm')
8+
vi.unmock('@sim/db')
9+
vi.unmock('@sim/db/schema')
10+
11+
process.env.DATABASE_URL ??= 'postgresql://user:pass@localhost:5432/test'
12+
13+
const { PgDialect } = await import('drizzle-orm/pg-core')
14+
const { cancelledExecutionLogFields } = await import('@/lib/logs/execution/cancellation')
15+
16+
describe('cancelledExecutionLogFields', () => {
17+
/**
18+
* The five cancellation paths spread this payload into their own `.set()`.
19+
* Hand-assembling it at each one had already dropped `executionDeadlineAt` at
20+
* a single site, so the point of the factory is that the key set cannot vary
21+
* between them — a field added here without a reason reaches all five.
22+
*/
23+
it('writes exactly the terminal fields, deadline cleared', () => {
24+
const endedAt = new Date('2026-08-13T12:00:05.000Z')
25+
26+
const fields = cancelledExecutionLogFields(endedAt)
27+
28+
expect(Object.keys(fields).sort()).toEqual([
29+
'endedAt',
30+
'executionDeadlineAt',
31+
'status',
32+
'totalDurationMs',
33+
])
34+
expect(fields.status).toBe('cancelled')
35+
expect(fields.endedAt).toBe(endedAt)
36+
expect(fields.executionDeadlineAt).toBeNull()
37+
})
38+
39+
/** `ended_at` and `total_duration_ms` must describe the same instant. */
40+
it('derives the duration from the same instant it ends the run at', () => {
41+
const endedAt = new Date('2026-08-13T12:00:05.000Z')
42+
43+
const { params } = new PgDialect().sqlToQuery(
44+
cancelledExecutionLogFields(endedAt).totalDurationMs
45+
)
46+
47+
expect(params).toContain(endedAt.toISOString())
48+
})
49+
})
Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,23 @@
1+
import { elapsedDurationMsSql } from '@/lib/logs/execution/duration'
2+
3+
/**
4+
* The fields every terminal cancellation sets on a `workflow_execution_logs`
5+
* row, ready to spread into `.set()`.
6+
*
7+
* The five cancellation paths — direct, workflow-group with and without a
8+
* sidecar, paused, and the async cancel route — differ in their database
9+
* handle, their claim predicate, whether they read the row back, and what they
10+
* do when the claim is lost, so they remain separate statements. What they must
11+
* not differ in is the row they leave behind, and hand-assembling this payload
12+
* at each one had already dropped `executionDeadlineAt` at a single site,
13+
* leaving a cancelled run still carrying the deadline of an attempt that had
14+
* stopped running.
15+
*/
16+
export function cancelledExecutionLogFields(endedAt: Date) {
17+
return {
18+
status: 'cancelled' as const,
19+
endedAt,
20+
totalDurationMs: elapsedDurationMsSql(endedAt),
21+
executionDeadlineAt: null,
22+
}
23+
}

0 commit comments

Comments
 (0)