fix(logs): record how long a cancelled run had been going - #6686
Conversation
|
The latest updates on your projects. Learn more about Vercel for GitHub. |
PR SummaryMedium Risk Overview This PR introduces Paused ( Reviewed by Cursor Bugbot for commit c744245. Configure here. |
Greptile SummaryThe PR records elapsed duration whenever an active workflow execution is cancelled, keeping terminal log rows compatible with duration-based filtering.
Confidence Score: 5/5The PR appears safe to merge. The saturation now bounds elapsed duration before the integer cast, so the previously reported overflow can no longer prevent cancellation terminal writes, and no other blocking failure remains.
|
| Filename | Overview |
|---|---|
| apps/sim/lib/logs/execution/duration.ts | Defines the shared elapsed-duration expression; the added pre-cast saturation closes the previously reported integer-overflow path. |
| apps/sim/lib/execution/cancel-workflow-execution.ts | Records a cancellation timestamp and derived duration in the direct terminal log update. |
| apps/sim/lib/table/workflow-group-cancellation.ts | Adds duration recording to both workflow-group cancellation branches while retaining transactional status guards. |
| apps/sim/lib/workflows/executor/human-in-the-loop-manager.ts | Adds the shared duration expression to the human-in-the-loop terminal cancellation update. |
| apps/sim/lib/logs/execution/duration.test.ts | Verifies the generated SQL includes timestamp handling, bounds, paused-run preservation, and resumed-run recomputation. |
Reviews (4): Last reviewed commit: "fix(logs): only a paused run keeps the d..." | Re-trigger Greptile
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.
The column is `integer`, so an untimed run cancelled after roughly twenty-five days overflowed the cast. That cost more than the duration it was recording: the direct write is caught and logged, so the row would have stayed `running` with no end timestamp at all, and the workflow-group write would have failed its transaction and taken the whole cancellation with it. Saturating keeps the terminal write. A duration wrong in its last digits is a smaller lie than a run that never ended.
Review found the first pass had only covered two of four terminal cancellation writes. The two it missed spell the timestamp `endedAt: now` rather than `endedAt: new Date()`, so the search that found the first pair could never have found them — and one of them is the common case: a workflow-group run with a live cell sidecar takes that branch, and the direct cancel skips its own log update whenever group cancellation handled the run, so it was the only writer for those cancellations. The other is the paused-cancellation write, which the first pass reported as already correct on the strength of that same search. A paused run records its duration when it pauses; cancelling it did not. All four now derive the duration the same way, and the sweep for the remaining ones went over every `status: 'cancelled'` write rather than one spelling of the timestamp beside it.
05d0d67 to
d903a3e
Compare
|
@cursor review |
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.
|
@cursor review |
Preserving any duration already on the row was too broad. Resuming flips the log back to running and leaves the pause checkpoint value behind, so a resumed run carries a stale reading while it is accruing time again; cancelling it would have frozen that pre-resume figure and disagreed with the resume completion path, which measures wall clock. What separates the two is the row's status rather than whether the column is populated. A paused run is not accruing, so its recorded active duration stands. A running one recomputes.
|
@cursor review |
There was a problem hiding this comment.
✅ Bugbot reviewed your changes and found no new issues!
Comment @cursor review or bugbot run to trigger another review on this PR
Reviewed by Cursor Bugbot for commit c744245. Configure here.
A cancelled run got an end timestamp and no duration.
Every other terminal transition writes both —
completeWorkflowExecutionsets them together, and a paused run already records its elapsed time — but cancellation writes the log row directly rather than going through completion, so it had no in-memory duration to store and simply omitted the column.Why it matters
GET /api/v2/logsfilters onminDurationMs/maxDurationMs. 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 states the end timestamp is null only "while the run is active" — which a cancelled run is not.Two sites, one shared expression
lib/execution/cancel-workflow-execution.ts.set({ status: 'cancelled', endedAt: new Date() })lib/table/workflow-group-cancellation.ts.set({ status: 'cancelled', endedAt: new Date(), executionDeadlineAt: null })Both now derive the duration in the same statement from the row's own
started_at, through one shared expression — the two drifting apart from the completion path is what produced this bug, so a second copy would just reset the clock on it.The end instant is computed once in JS and reused, so the stamped end and the derived duration describe the same moment rather than two clock reads.
Two deliberate details
Bound as an explicit
::timestamp, not aDate.started_atistimestamp without time zoneholding a UTC wall clock; a driver-boundDateinferstimestamptz, which would make the interval depend on the session zone. Given the release just spent effort pinning exactly that, the cast is the safe form.Floored at 1ms, matching
Math.max(1, durationMs)in the completion path, so a run cancelled inside its first millisecond still records that it ran — and the value stays a validintegerfor the column.Verification
PgDialect, matching the existing precedent inprune-metadata-sql.test.tsrather than inventing a pattern. Rawsqltemplates are otherwise hidden by the global drizzle mocks until they run against Postgres.check:audits26/26 — all clean. No contract changed, so no OpenAPI drift.Not changed
The paused-cancellation path already records its duration and is deliberately skipped by these writes (
!pausedCancelled), so it needed nothing.