Skip to content

Commit 7aa0850

Browse files
committed
fix(logs): let a recorded duration outlive a later cancellation
A paused run measures its own active duration at the pause checkpoint. The previous commit then had cancellation overwrite that with wall clock from the start, which quietly redefines the column for those runs to include the time the run spent waiting rather than working — filling a gap by discarding an answer someone else had already computed. The duration now coalesces onto whatever the row already carries, so a cancellation only supplies the value when nothing else did. Every other cancellation path leaves the column null, so the change is inert there.
1 parent d903a3e commit 7aa0850

2 files changed

Lines changed: 21 additions & 1 deletion

File tree

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

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -62,4 +62,17 @@ describe('elapsedDurationMsSql', () => {
6262
expect(sql).toContain('LEAST(')
6363
expect(params).toContain(2_147_483_647)
6464
})
65+
66+
/**
67+
* A paused run records its *active* duration at the pause checkpoint. Elapsed
68+
* wall clock through a later cancel includes the time it sat waiting, so
69+
* overwriting would silently redefine what the column means for that run.
70+
*/
71+
it('keeps a duration the row already carries', () => {
72+
const { sql } = render(new Date('2026-08-13T12:00:05.000Z'))
73+
74+
expect(sql).toContain('COALESCE(')
75+
expect(sql.indexOf('COALESCE(')).toBeLessThan(sql.indexOf('LEAST('))
76+
expect(sql).toContain('"total_duration_ms"')
77+
})
6578
})

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

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -28,9 +28,16 @@ import { type SQL, sql } from 'drizzle-orm'
2828
* fails its transaction and takes the whole cancellation with it. A saturated
2929
* duration is wrong in the last digit; a failed terminal write is wrong about
3030
* whether the run ended.
31+
*
32+
* A duration already on the row wins. This fills a gap; it does not restate an
33+
* answer someone else computed. The case that makes the difference is a paused
34+
* run: it records its *active* duration at the pause checkpoint, and elapsed
35+
* wall clock through a later cancel would silently redefine that to include the
36+
* time it sat waiting. On the paths where the column is still null — every
37+
* other cancellation — the coalesce is inert.
3138
*/
3239
const INT4_MAX_MS = 2_147_483_647
3340

3441
export function elapsedDurationMsSql(endedAt: Date): SQL<number> {
35-
return sql<number>`LEAST(${INT4_MAX_MS}, GREATEST(1, ROUND(EXTRACT(EPOCH FROM (${endedAt.toISOString()}::timestamp - ${workflowExecutionLogs.startedAt})) * 1000)))::integer`
42+
return sql<number>`COALESCE(${workflowExecutionLogs.totalDurationMs}, LEAST(${INT4_MAX_MS}, GREATEST(1, ROUND(EXTRACT(EPOCH FROM (${endedAt.toISOString()}::timestamp - ${workflowExecutionLogs.startedAt})) * 1000)))::integer)`
3643
}

0 commit comments

Comments
 (0)