Skip to content

Commit 34ed113

Browse files
committed
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 bef36e1 commit 34ed113

13 files changed

Lines changed: 167 additions & 74 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.ts

Lines changed: 2 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -24,7 +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 { elapsedDurationMsSql } from '@/lib/logs/execution/duration'
27+
import { cancelledExecutionLogFields } from '@/lib/logs/execution/cancellation'
2828
import { workflowExecutionOriginSql } from '@/lib/logs/execution-origin'
2929
import { captureServerEvent } from '@/lib/posthog/server'
3030
import {
@@ -216,12 +216,7 @@ async function claimExecutionLogCancellation(args: {
216216
const now = new Date()
217217
const [cancelledExecution] = await db
218218
.update(workflowExecutionLogs)
219-
.set({
220-
status: 'cancelled',
221-
endedAt: now,
222-
totalDurationMs: elapsedDurationMsSql(now),
223-
executionDeadlineAt: null,
224-
})
219+
.set(cancelledExecutionLogFields(now))
225220
.where(
226221
and(
227222
eq(workflowExecutionLogs.executionId, args.executionId),

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

Lines changed: 1 addition & 6 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,12 +214,6 @@ function mapTriggerDevStatus(status: string): JobStatus {
213214
}
214215
}
215216

216-
const TERMINAL_JOB_STATUSES: readonly JobStatus[] = [
217-
JOB_STATUS.COMPLETED,
218-
JOB_STATUS.FAILED,
219-
JOB_STATUS.CANCELLED,
220-
]
221-
222217
/**
223218
* Dates the end of a run that trigger.dev already reports as terminal.
224219
*

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+
}

apps/sim/lib/logs/execution/duration.test.ts

Lines changed: 25 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -29,14 +29,16 @@ describe('elapsedDurationMsSql', () => {
2929
})
3030

3131
/**
32-
* `started_at` is `timestamp without time zone` holding a UTC wall clock. A
33-
* driver-bound `Date` infers `timestamptz`, which would make the interval
34-
* depend on the session zone; the explicit cast is what keeps it stable.
32+
* `started_at` is `timestamp without time zone` holding a UTC wall clock. The
33+
* end instant is bound through that column's mapper, which emits a UTC ISO
34+
* string; the explicit cast drops the offset to the same naive reading rather
35+
* than leaving the interval to depend on how Postgres resolves the operator.
3536
*/
3637
it('binds the end instant as a zone-free timestamp', () => {
3738
const { sql, params } = render(new Date('2026-08-13T12:00:05.000Z'))
3839

39-
expect(sql).toContain('::timestamp')
40+
expect(sql).toContain('::timestamp -')
41+
expect(sql).not.toContain('::timestamptz')
4042
expect(params).toContain('2026-08-13T12:00:05.000Z')
4143
expect(params.some((param) => Array.isArray(param))).toBe(false)
4244
})
@@ -71,8 +73,7 @@ describe('elapsedDurationMsSql', () => {
7173
it('keeps the duration a paused run already recorded', () => {
7274
const { sql } = render(new Date('2026-08-13T12:00:05.000Z'))
7375

74-
expect(sql).toContain(`"status" = 'pending' THEN COALESCE(`)
75-
expect(sql).toContain('"total_duration_ms"')
76+
expect(sql).toContain(`"status" = 'pending' THEN "workflow_execution_logs"."total_duration_ms"`)
7677
})
7778

7879
/**
@@ -83,9 +84,23 @@ describe('elapsedDurationMsSql', () => {
8384
it('recomputes for a running row rather than trusting a stale checkpoint', () => {
8485
const { sql } = render(new Date('2026-08-13T12:00:05.000Z'))
8586

86-
const elseBranch = sql.slice(sql.indexOf('ELSE'))
87-
expect(elseBranch).toContain('LEAST(')
88-
expect(elseBranch).not.toContain('COALESCE(')
89-
expect(elseBranch).not.toContain('"total_duration_ms"')
87+
const fallback = sql.slice(sql.indexOf('END,'))
88+
expect(fallback).toContain('LEAST(')
89+
expect(fallback).not.toContain('"total_duration_ms"')
90+
})
91+
92+
/**
93+
* The preserved-checkpoint rule and the elapsed fallback are one `COALESCE`
94+
* over a valueless-`ELSE` `CASE`, not a `CASE` repeating the elapsed
95+
* expression in both branches. `status` is `NOT NULL` and `started_at` is
96+
* `NOT NULL`, so the `CASE` yields NULL exactly for a non-`pending` row or a
97+
* `pending` row that never recorded one — the two cases that must fall
98+
* through — and the fallback can never itself be NULL.
99+
*/
100+
it('builds the elapsed expression once', () => {
101+
const { sql, params } = render(new Date('2026-08-13T12:00:05.000Z'))
102+
103+
expect(sql.match(/LEAST\(/g)).toHaveLength(1)
104+
expect(params).toHaveLength(2)
90105
})
91106
})

apps/sim/lib/logs/execution/duration.ts

Lines changed: 17 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,8 @@
11
import { workflowExecutionLogs } from '@sim/db/schema'
22
import { type SQL, sql } from 'drizzle-orm'
33

4+
const INT4_MAX_MS = 2_147_483_647
5+
46
/**
57
* Elapsed run time for a terminal write that does not go through
68
* `completeWorkflowExecution`, expressed against the row's own `started_at`.
@@ -12,13 +14,19 @@ import { type SQL, sql } from 'drizzle-orm'
1214
* `GET /api/v2/logs` — a null there reads as "no duration recorded" and drops
1315
* the run out of every `minDurationMs`/`maxDurationMs` query.
1416
*
15-
* `ended_at` is bound as an explicit `timestamp` rather than a `Date`, because
16-
* `started_at` is `timestamp without time zone` holding a UTC wall clock: an
17-
* ISO string casts to the same naive reading, while a driver-bound `Date`
18-
* would infer `timestamptz` and make the interval depend on the session zone.
17+
* `ended_at` is bound through `started_at`'s own column mapper and cast to
18+
* `timestamp`, because that column is `timestamp without time zone` holding a
19+
* UTC wall clock. The cast is what pins the reading: the mapper emits a UTC ISO
20+
* instant, and casting it drops the offset to the same naive wall clock the
21+
* column stores. Left uncast the interval would depend on Postgres resolving
22+
* the subtraction to the `timestamp` overload rather than `timestamptz`, and
23+
* getting that wrong yields a duration in the wrong zone rather than an error.
1924
*
20-
* Floored at 1ms to match `completeWorkflowExecution`, so a cancellation that
21-
* lands inside the same millisecond as the start still records that it ran.
25+
* Floored at 1ms to match the `Math.max(1, durationMs)` the completion path
26+
* applies, so a cancellation landing inside the same millisecond as the start
27+
* still records that it ran. The floor doubles as the guard against a negative
28+
* interval, which is otherwise reachable whenever the clock that stamped
29+
* `started_at` runs ahead of the one cancelling.
2230
*
2331
* Saturated at the column's own ceiling rather than left to overflow. The
2432
* column is `integer`, so an untimed run cancelled after ~24.8 days would
@@ -41,9 +49,8 @@ import { type SQL, sql } from 'drizzle-orm'
4149
* measures wall clock. A `running` row therefore always recomputes; only a
4250
* `pending` one — paused, and not accruing — keeps what it has.
4351
*/
44-
const INT4_MAX_MS = 2_147_483_647
45-
4652
export function elapsedDurationMsSql(endedAt: Date): SQL<number> {
47-
const elapsed = sql`LEAST(${INT4_MAX_MS}, GREATEST(1, ROUND(EXTRACT(EPOCH FROM (${endedAt.toISOString()}::timestamp - ${workflowExecutionLogs.startedAt})) * 1000)))::integer`
48-
return sql<number>`CASE WHEN ${workflowExecutionLogs.status} = 'pending' THEN COALESCE(${workflowExecutionLogs.totalDurationMs}, ${elapsed}) ELSE ${elapsed} END`
53+
const endedAtParam = sql.param(endedAt, workflowExecutionLogs.startedAt)
54+
const elapsed = sql`LEAST(${INT4_MAX_MS}, GREATEST(1, ROUND(EXTRACT(EPOCH FROM (${endedAtParam}::timestamp - ${workflowExecutionLogs.startedAt})) * 1000)))::integer`
55+
return sql<number>`COALESCE(CASE WHEN ${workflowExecutionLogs.status} = 'pending' THEN ${workflowExecutionLogs.totalDurationMs} END, ${elapsed})`
4956
}

0 commit comments

Comments
 (0)