-
Notifications
You must be signed in to change notification settings - Fork 3.8k
fix(logs): record how long a cancelled run had been going #6686
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Merged
Merged
Changes from all commits
Commits
Show all changes
5 commits
Select commit
Hold shift + click to select a range
8af5877
fix(logs): record how long a cancelled run had been going
waleedlatif1 d4e33ae
fix(logs): saturate the cancelled-run duration at the column ceiling
waleedlatif1 d903a3e
fix(logs): record the duration on the other two cancellation writes
waleedlatif1 7aa0850
fix(logs): let a recorded duration outlive a later cancellation
waleedlatif1 c744245
fix(logs): only a paused run keeps the duration it recorded
waleedlatif1 File filter
Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
There are no files selected for viewing
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,91 @@ | ||
| /** | ||
| * @vitest-environment node | ||
| */ | ||
|
|
||
| // Renders the real expression against the real drizzle dialect and schema. It | ||
| // is a raw `sql` template, so a rendering or type-cast bug only surfaces when | ||
| // Postgres executes it — the global drizzle/schema mocks would hide it. | ||
| import { describe, expect, it, vi } from 'vitest' | ||
|
|
||
| vi.unmock('drizzle-orm') | ||
| vi.unmock('@sim/db') | ||
| vi.unmock('@sim/db/schema') | ||
|
|
||
| process.env.DATABASE_URL ??= 'postgresql://user:pass@localhost:5432/test' | ||
|
|
||
| const { PgDialect } = await import('drizzle-orm/pg-core') | ||
| const { elapsedDurationMsSql } = await import('@/lib/logs/execution/duration') | ||
|
|
||
| function render(endedAt: Date) { | ||
| return new PgDialect().sqlToQuery(elapsedDurationMsSql(endedAt)) | ||
| } | ||
|
|
||
| describe('elapsedDurationMsSql', () => { | ||
| it('measures against the row started_at rather than a second clock read', () => { | ||
| const { sql } = render(new Date('2026-08-13T12:00:05.000Z')) | ||
|
|
||
| expect(sql).toContain('"started_at"') | ||
| expect(sql).not.toContain('now()') | ||
| }) | ||
|
|
||
| /** | ||
| * `started_at` is `timestamp without time zone` holding a UTC wall clock. A | ||
| * driver-bound `Date` infers `timestamptz`, which would make the interval | ||
| * depend on the session zone; the explicit cast is what keeps it stable. | ||
| */ | ||
| it('binds the end instant as a zone-free timestamp', () => { | ||
| const { sql, params } = render(new Date('2026-08-13T12:00:05.000Z')) | ||
|
|
||
| expect(sql).toContain('::timestamp') | ||
| expect(params).toContain('2026-08-13T12:00:05.000Z') | ||
| expect(params.some((param) => Array.isArray(param))).toBe(false) | ||
| }) | ||
|
|
||
| /** The column is `integer`, and a sub-millisecond run still ran. */ | ||
| it('yields a whole number of milliseconds, floored at one', () => { | ||
| const { sql } = render(new Date('2026-08-13T12:00:05.000Z')) | ||
|
|
||
| expect(sql).toContain('GREATEST(1,') | ||
| expect(sql).toContain('ROUND(') | ||
| expect(sql).toContain('::integer') | ||
| }) | ||
|
|
||
| /** | ||
| * An untimed run cancelled after ~24.8 days exceeds `integer`. Without the | ||
| * ceiling the cast raises, and the terminal write is lost entirely — the row | ||
| * stays `running` with no end timestamp, which is worse than a saturated | ||
| * duration. | ||
| */ | ||
| it('saturates at the column ceiling instead of overflowing the cast', () => { | ||
| const { sql, params } = render(new Date('2026-08-13T12:00:05.000Z')) | ||
|
|
||
| expect(sql).toContain('LEAST(') | ||
| expect(params).toContain(2_147_483_647) | ||
| }) | ||
|
|
||
| /** | ||
| * A paused run records its *active* duration at the pause checkpoint. Elapsed | ||
| * wall clock through a later cancel includes the time it sat waiting, so | ||
| * overwriting would silently redefine what the column means for that run. | ||
| */ | ||
| it('keeps the duration a paused run already recorded', () => { | ||
| const { sql } = render(new Date('2026-08-13T12:00:05.000Z')) | ||
|
|
||
| expect(sql).toContain(`"status" = 'pending' THEN COALESCE(`) | ||
| expect(sql).toContain('"total_duration_ms"') | ||
| }) | ||
|
|
||
| /** | ||
| * Resuming flips the row back to `running` and leaves the checkpoint value | ||
| * behind, so a resumed run carries a stale duration while it is accruing time | ||
| * again. Preserving it would freeze a cancelled run at its pre-resume reading. | ||
| */ | ||
| it('recomputes for a running row rather than trusting a stale checkpoint', () => { | ||
| const { sql } = render(new Date('2026-08-13T12:00:05.000Z')) | ||
|
|
||
| const elseBranch = sql.slice(sql.indexOf('ELSE')) | ||
| expect(elseBranch).toContain('LEAST(') | ||
| expect(elseBranch).not.toContain('COALESCE(') | ||
| expect(elseBranch).not.toContain('"total_duration_ms"') | ||
| }) | ||
| }) |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,49 @@ | ||
| import { workflowExecutionLogs } from '@sim/db/schema' | ||
| import { type SQL, sql } from 'drizzle-orm' | ||
|
|
||
| /** | ||
| * Elapsed run time for a terminal write that does not go through | ||
| * `completeWorkflowExecution`, expressed against the row's own `started_at`. | ||
| * | ||
| * Cancellation writes the log row directly rather than through the completion | ||
| * path, so it has no in-memory duration to store. Deriving it in the same | ||
| * statement keeps `ended_at` and `total_duration_ms` describing one instant, | ||
| * and keeps a cancelled run visible to the duration filters on | ||
| * `GET /api/v2/logs` — a null there reads as "no duration recorded" and drops | ||
| * the run out of every `minDurationMs`/`maxDurationMs` query. | ||
| * | ||
| * `ended_at` is bound as an explicit `timestamp` rather than a `Date`, because | ||
| * `started_at` is `timestamp without time zone` holding a UTC wall clock: an | ||
| * ISO string casts to the same naive reading, while a driver-bound `Date` | ||
| * would infer `timestamptz` and make the interval depend on the session zone. | ||
| * | ||
| * Floored at 1ms to match `completeWorkflowExecution`, so a cancellation that | ||
| * lands inside the same millisecond as the start still records that it ran. | ||
| * | ||
| * Saturated at the column's own ceiling rather than left to overflow. The | ||
| * column is `integer`, so an untimed run cancelled after ~24.8 days would | ||
| * otherwise raise `numeric_value_out_of_range` — which costs more than the | ||
| * duration it was recording: the direct write is caught and logged, leaving | ||
| * the row `running` with no end timestamp at all, and the workflow-group write | ||
| * fails its transaction and takes the whole cancellation with it. A saturated | ||
| * duration is wrong in the last digit; a failed terminal write is wrong about | ||
| * whether the run ended. | ||
| * | ||
| * A duration a *paused* run already recorded wins, and only that one. Pausing | ||
| * writes the run's active duration at the checkpoint, which elapsed wall clock | ||
| * through a later cancel would redefine to include the time it sat waiting. | ||
| * | ||
| * The status is what distinguishes it, not merely the column being populated: | ||
| * resuming flips the row back to `running` and leaves that checkpoint value | ||
| * behind, so a resumed run carries a stale duration while it is once again | ||
| * accruing time. Keeping it there would freeze a cancelled run at its | ||
| * pre-resume reading and disagree with the resume completion path, which | ||
| * measures wall clock. A `running` row therefore always recomputes; only a | ||
| * `pending` one — paused, and not accruing — keeps what it has. | ||
| */ | ||
| const INT4_MAX_MS = 2_147_483_647 | ||
|
|
||
| export function elapsedDurationMsSql(endedAt: Date): SQL<number> { | ||
| const elapsed = sql`LEAST(${INT4_MAX_MS}, GREATEST(1, ROUND(EXTRACT(EPOCH FROM (${endedAt.toISOString()}::timestamp - ${workflowExecutionLogs.startedAt})) * 1000)))::integer` | ||
| return sql<number>`CASE WHEN ${workflowExecutionLogs.status} = 'pending' THEN COALESCE(${workflowExecutionLogs.totalDurationMs}, ${elapsed}) ELSE ${elapsed} END` | ||
| } |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Oops, something went wrong.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Uh oh!
There was an error while loading. Please reload this page.