Skip to content

Commit e384c9a

Browse files
committed
fix(logs): record how long a cancelled run had been going
A cancelled run got an end timestamp and no duration. Every other terminal transition writes both — the completion path sets them together, and a paused run already records its elapsed time — but cancellation writes the log row directly rather than through completion, so it had no in-memory duration to store and simply omitted the column. That is not cosmetic. `GET /api/v2/logs` filters on `minDurationMs` and `maxDurationMs`, and a null column drops the row out of every such query, so cancellations are invisible to exactly the searches someone runs when investigating cancellations. The published contract also says the end timestamp is null only while a run is active, which a cancelled run is not. Both cancellation writes now derive the duration in the same statement from the row's own `started_at`, through one shared expression so the two cannot drift apart the way they did from the completion path. The end instant is computed once and reused, so the stamped end and the derived duration describe the same moment rather than two clock reads. The instant is bound as an explicit `timestamp` rather than a `Date`: `started_at` is `timestamp without time zone` holding a UTC wall clock, and a driver-bound date would infer `timestamptz` and make the interval depend on the session zone. The floor of one millisecond matches the completion path, so a run cancelled inside its first millisecond still records that it ran.
1 parent 264d4f3 commit e384c9a

6 files changed

Lines changed: 111 additions & 2 deletions

File tree

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

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -281,4 +281,17 @@ describe('cancelWorkflowExecution', () => {
281281
expect(mockPublishWorkflowGroupCancellationEvent).not.toHaveBeenCalled()
282282
expect(mockUpdateSet).toHaveBeenCalledWith(expect.objectContaining({ status: 'cancelled' }))
283283
})
284+
285+
/**
286+
* A cancelled run is terminal, so it owes the same two fields every other
287+
* terminal write records. Without the duration it is invisible to the
288+
* `minDurationMs`/`maxDurationMs` filters on `GET /api/v2/logs`.
289+
*/
290+
it('records how long the cancelled run had been going, not just when it stopped', async () => {
291+
await cancelWorkflowExecution(INPUT)
292+
293+
const [values] = mockUpdateSet.mock.calls.at(-1) as [Record<string, unknown>]
294+
expect(values.endedAt).toBeInstanceOf(Date)
295+
expect(values.totalDurationMs).toBeDefined()
296+
})
284297
})

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

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -12,6 +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'
1516
import { captureServerEvent } from '@/lib/posthog/server'
1617
import {
1718
cancelWorkflowGroupExecution,
@@ -377,9 +378,14 @@ export async function cancelWorkflowExecution(
377378
!pausedCancelled
378379
) {
379380
try {
381+
const cancelledAt = new Date()
380382
await db
381383
.update(workflowExecutionLogs)
382-
.set({ status: 'cancelled', endedAt: new Date() })
384+
.set({
385+
status: 'cancelled',
386+
endedAt: cancelledAt,
387+
totalDurationMs: elapsedDurationMsSql(cancelledAt),
388+
})
383389
.where(
384390
and(
385391
eq(workflowExecutionLogs.executionId, executionId),
Lines changed: 52 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,52 @@
1+
/**
2+
* @vitest-environment node
3+
*/
4+
5+
// Renders the real expression against the real drizzle dialect and schema. It
6+
// is a raw `sql` template, so a rendering or type-cast bug only surfaces when
7+
// Postgres executes it — the global drizzle/schema mocks would hide it.
8+
import { describe, expect, it, vi } from 'vitest'
9+
10+
vi.unmock('drizzle-orm')
11+
vi.unmock('@sim/db')
12+
vi.unmock('@sim/db/schema')
13+
14+
process.env.DATABASE_URL ??= 'postgresql://user:pass@localhost:5432/test'
15+
16+
const { PgDialect } = await import('drizzle-orm/pg-core')
17+
const { elapsedDurationMsSql } = await import('@/lib/logs/execution/duration')
18+
19+
function render(endedAt: Date) {
20+
return new PgDialect().sqlToQuery(elapsedDurationMsSql(endedAt))
21+
}
22+
23+
describe('elapsedDurationMsSql', () => {
24+
it('measures against the row started_at rather than a second clock read', () => {
25+
const { sql } = render(new Date('2026-08-13T12:00:05.000Z'))
26+
27+
expect(sql).toContain('"started_at"')
28+
expect(sql).not.toContain('now()')
29+
})
30+
31+
/**
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.
35+
*/
36+
it('binds the end instant as a zone-free timestamp', () => {
37+
const { sql, params } = render(new Date('2026-08-13T12:00:05.000Z'))
38+
39+
expect(sql).toContain('::timestamp')
40+
expect(params).toEqual(['2026-08-13T12:00:05.000Z'])
41+
expect(params.some((param) => Array.isArray(param))).toBe(false)
42+
})
43+
44+
/** The column is `integer`, and a sub-millisecond run still ran. */
45+
it('yields a whole number of milliseconds, floored at one', () => {
46+
const { sql } = render(new Date('2026-08-13T12:00:05.000Z'))
47+
48+
expect(sql).toContain('GREATEST(1,')
49+
expect(sql).toContain('ROUND(')
50+
expect(sql).toContain('::integer')
51+
})
52+
})
Lines changed: 25 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,25 @@
1+
import { workflowExecutionLogs } from '@sim/db/schema'
2+
import { type SQL, sql } from 'drizzle-orm'
3+
4+
/**
5+
* Elapsed run time for a terminal write that does not go through
6+
* `completeWorkflowExecution`, expressed against the row's own `started_at`.
7+
*
8+
* Cancellation writes the log row directly rather than through the completion
9+
* path, so it has no in-memory duration to store. Deriving it in the same
10+
* statement keeps `ended_at` and `total_duration_ms` describing one instant,
11+
* and keeps a cancelled run visible to the duration filters on
12+
* `GET /api/v2/logs` — a null there reads as "no duration recorded" and drops
13+
* the run out of every `minDurationMs`/`maxDurationMs` query.
14+
*
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.
19+
*
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.
22+
*/
23+
export function elapsedDurationMsSql(endedAt: Date): SQL<number> {
24+
return sql<number>`GREATEST(1, ROUND(EXTRACT(EPOCH FROM (${endedAt.toISOString()}::timestamp - ${workflowExecutionLogs.startedAt})) * 1000))::integer`
25+
}

apps/sim/lib/table/workflow-group-cancellation.test.ts

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -218,9 +218,15 @@ describe('cancelWorkflowGroupExecution', () => {
218218
})
219219

220220
expect(dbChainMockFns.update).toHaveBeenCalledOnce()
221+
/**
222+
* `totalDurationMs` is derived in-statement from the row's `started_at`, so
223+
* a cancelled run carries the duration every other terminal write records
224+
* and stays visible to the `/api/v2/logs` duration filters.
225+
*/
221226
expect(dbChainMockFns.set).toHaveBeenCalledWith({
222227
status: 'cancelled',
223228
endedAt: expect.any(Date),
229+
totalDurationMs: expect.anything(),
224230
executionDeadlineAt: null,
225231
})
226232
const logUpdateValues = collectConditionValues(dbChainMockFns.where.mock.calls[2]?.[0])

apps/sim/lib/table/workflow-group-cancellation.ts

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@ import { tableRowExecutions, userTableDefinitions, workflowExecutionLogs } from
33
import { createLogger } from '@sim/logger'
44
import { toError } from '@sim/utils/errors'
55
import { and, eq, inArray } from 'drizzle-orm'
6+
import { elapsedDurationMsSql } from '@/lib/logs/execution/duration'
67
import { appendTableEvent } from '@/lib/table/events'
78

89
const logger = createLogger('WorkflowGroupCancellation')
@@ -149,9 +150,15 @@ export async function cancelWorkflowGroupExecution(
149150
return { result: { kind: 'already_cancelled_without_sidecar' } as const }
150151
}
151152

153+
const cancelledAt = new Date()
152154
const [cancelledLog] = await tx
153155
.update(workflowExecutionLogs)
154-
.set({ status: 'cancelled', endedAt: new Date(), executionDeadlineAt: null })
156+
.set({
157+
status: 'cancelled',
158+
endedAt: cancelledAt,
159+
totalDurationMs: elapsedDurationMsSql(cancelledAt),
160+
executionDeadlineAt: null,
161+
})
155162
.where(
156163
and(
157164
eq(workflowExecutionLogs.workspaceId, options.workspaceId),

0 commit comments

Comments
 (0)