Skip to content

Commit 6c4c289

Browse files
committed
fix(logs): resolve marker store split-brain by latest-timestamp-wins + drain on force-fail
- When a Redis marker write falls back to SQL, Redis and the row can each hold a marker for a different block; reads/folds previously preferred Redis unconditionally and could pick a stale value. Now the completion fold, the in-flight detail read, and the force-fail fold all pick the marker with the later timestamp (pickLatestStartedMarker/pickLatestCompletedMarker; markExecutionAsFailed uses a monotonic SQL guard). - markAsFailed now drains pending per-block marker writes (not just the completion promise) before folding, so a force-fail racing onBlockStart/onBlockComplete still captures the latest breadcrumb.
1 parent 08f54ef commit 6c4c289

5 files changed

Lines changed: 94 additions & 8 deletions

File tree

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

Lines changed: 10 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -41,6 +41,8 @@ import {
4141
clearProgressMarkers,
4242
type ExecutionProgressMarkers,
4343
getProgressMarkers,
44+
pickLatestCompletedMarker,
45+
pickLatestStartedMarker,
4446
} from '@/lib/logs/execution/progress-markers'
4547
import { snapshotService } from '@/lib/logs/execution/snapshot/service'
4648
import {
@@ -459,10 +461,14 @@ export class ExecutionLogger implements IExecutionLoggerService {
459461
} = params
460462
const traceSpanCount = countTraceSpans(traceSpans)
461463

462-
const lastStartedBlock =
463-
progressMarkers?.lastStartedBlock ?? existingExecutionData?.lastStartedBlock
464-
const lastCompletedBlock =
465-
progressMarkers?.lastCompletedBlock ?? existingExecutionData?.lastCompletedBlock
464+
const lastStartedBlock = pickLatestStartedMarker(
465+
progressMarkers?.lastStartedBlock,
466+
existingExecutionData?.lastStartedBlock
467+
)
468+
const lastCompletedBlock = pickLatestCompletedMarker(
469+
progressMarkers?.lastCompletedBlock,
470+
existingExecutionData?.lastCompletedBlock
471+
)
466472

467473
return {
468474
...(existingExecutionData?.environment

apps/sim/lib/logs/execution/logging-session.ts

Lines changed: 16 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1018,8 +1018,14 @@ export class LoggingSession {
10181018
}
10191019
}
10201020

1021+
/**
1022+
* Force-fail the execution. Waits for any in-flight completion and drains
1023+
* pending per-block marker writes first, so a force-fail racing
1024+
* onBlockStart/onBlockComplete still captures the latest breadcrumb in the fold.
1025+
*/
10211026
async markAsFailed(errorMessage?: string): Promise<void> {
10221027
await this.waitForCompletion()
1028+
await this.drainPendingProgressWrites()
10231029
await LoggingSession.markExecutionAsFailed(
10241030
this.executionId,
10251031
errorMessage,
@@ -1060,10 +1066,18 @@ export class LoggingSession {
10601066
to_jsonb('force_failed'::text)
10611067
)`
10621068
if (markers?.lastStartedBlock) {
1063-
executionData = sql`jsonb_set(${executionData}, ARRAY['lastStartedBlock'], ${JSON.stringify(markers.lastStartedBlock)}::jsonb)`
1069+
const startedAt = markers.lastStartedBlock.startedAt
1070+
const startedJson = JSON.stringify(markers.lastStartedBlock)
1071+
executionData = sql`CASE WHEN COALESCE(jsonb_extract_path_text(execution_data, 'lastStartedBlock', 'startedAt'), '') <= ${startedAt}
1072+
THEN jsonb_set(${executionData}, ARRAY['lastStartedBlock'], ${startedJson}::jsonb)
1073+
ELSE ${executionData} END`
10641074
}
10651075
if (markers?.lastCompletedBlock) {
1066-
executionData = sql`jsonb_set(${executionData}, ARRAY['lastCompletedBlock'], ${JSON.stringify(markers.lastCompletedBlock)}::jsonb)`
1076+
const endedAt = markers.lastCompletedBlock.endedAt
1077+
const completedJson = JSON.stringify(markers.lastCompletedBlock)
1078+
executionData = sql`CASE WHEN COALESCE(jsonb_extract_path_text(execution_data, 'lastCompletedBlock', 'endedAt'), '') <= ${endedAt}
1079+
THEN jsonb_set(${executionData}, ARRAY['lastCompletedBlock'], ${completedJson}::jsonb)
1080+
ELSE ${executionData} END`
10671081
}
10681082

10691083
await db

apps/sim/lib/logs/execution/progress-markers.test.ts

Lines changed: 25 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,8 @@ vi.mock('@/lib/core/execution-limits', () => ({
2424
import {
2525
clearProgressMarkers,
2626
getProgressMarkers,
27+
pickLatestCompletedMarker,
28+
pickLatestStartedMarker,
2729
setLastCompletedBlock,
2830
setLastStartedBlock,
2931
} from '@/lib/logs/execution/progress-markers'
@@ -175,4 +177,27 @@ describe('progress-markers', () => {
175177
expect(mockRedis.del).not.toHaveBeenCalled()
176178
})
177179
})
180+
181+
describe('latest-wins pickers (stale-store safety)', () => {
182+
const older = { ...startedMarker, blockId: 'old', startedAt: '2026-06-27T10:00:00.000Z' }
183+
const newer = { ...startedMarker, blockId: 'new', startedAt: '2026-06-27T10:00:05.000Z' }
184+
185+
it('returns the defined side when the other is undefined', () => {
186+
expect(pickLatestStartedMarker(older, undefined)).toBe(older)
187+
expect(pickLatestStartedMarker(undefined, newer)).toBe(newer)
188+
expect(pickLatestStartedMarker(undefined, undefined)).toBeUndefined()
189+
})
190+
191+
it('picks the later startedAt regardless of argument order (row newer than Redis still wins)', () => {
192+
expect(pickLatestStartedMarker(older, newer)).toBe(newer)
193+
expect(pickLatestStartedMarker(newer, older)).toBe(newer)
194+
})
195+
196+
it('picks the later endedAt for completed markers', () => {
197+
const c1 = { ...completedMarker, endedAt: '2026-06-27T10:00:01.000Z' }
198+
const c2 = { ...completedMarker, endedAt: '2026-06-27T10:00:09.000Z' }
199+
expect(pickLatestCompletedMarker(c1, c2)).toBe(c2)
200+
expect(pickLatestCompletedMarker(c2, c1)).toBe(c2)
201+
})
202+
})
178203
})

apps/sim/lib/logs/execution/progress-markers.ts

Lines changed: 26 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -122,6 +122,32 @@ export interface ExecutionProgressMarkers {
122122
lastCompletedBlock?: ExecutionLastCompletedBlock
123123
}
124124

125+
/**
126+
* Pick the later of two last-started markers by `startedAt`. Markers can split
127+
* across stores — a failed Redis write falls back to the row, so an earlier
128+
* successful Redis write may coexist with a newer row marker (or vice versa).
129+
* Choosing by timestamp keeps the freshest breadcrumb regardless of which store
130+
* holds it. ISO UTC timestamps compare correctly lexicographically.
131+
*/
132+
export function pickLatestStartedMarker(
133+
a: ExecutionLastStartedBlock | undefined,
134+
b: ExecutionLastStartedBlock | undefined
135+
): ExecutionLastStartedBlock | undefined {
136+
if (!a) return b
137+
if (!b) return a
138+
return a.startedAt >= b.startedAt ? a : b
139+
}
140+
141+
/** Pick the later of two last-completed markers by `endedAt`. See {@link pickLatestStartedMarker}. */
142+
export function pickLatestCompletedMarker(
143+
a: ExecutionLastCompletedBlock | undefined,
144+
b: ExecutionLastCompletedBlock | undefined
145+
): ExecutionLastCompletedBlock | undefined {
146+
if (!a) return b
147+
if (!b) return a
148+
return a.endedAt >= b.endedAt ? a : b
149+
}
150+
125151
function safeJsonParse(raw: string | undefined): unknown {
126152
if (!raw) return undefined
127153
try {

apps/sim/lib/logs/fetch-log-detail.ts

Lines changed: 17 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,12 @@ import {
99
} from '@sim/db/schema'
1010
import { and, eq, type SQL } from 'drizzle-orm'
1111
import type { CostLedger } from '@/lib/api/contracts/logs'
12-
import { getProgressMarkers } from '@/lib/logs/execution/progress-markers'
12+
import {
13+
type ExecutionProgressMarkers,
14+
getProgressMarkers,
15+
pickLatestCompletedMarker,
16+
pickLatestStartedMarker,
17+
} from '@/lib/logs/execution/progress-markers'
1318
import { materializeExecutionData } from '@/lib/logs/execution/trace-store'
1419
import { checkWorkspaceAccess } from '@/lib/workspaces/permissions/utils'
1520

@@ -174,6 +179,15 @@ export async function fetchLogDetail({
174179
log.status === 'running' || log.status === 'pending'
175180
? ((await getProgressMarkers(log.executionId)) ?? {})
176181
: {}
182+
const rowMarkers = (executionData ?? {}) as ExecutionProgressMarkers
183+
const mergedStartedBlock = pickLatestStartedMarker(
184+
liveMarkers.lastStartedBlock,
185+
rowMarkers.lastStartedBlock
186+
)
187+
const mergedCompletedBlock = pickLatestCompletedMarker(
188+
liveMarkers.lastCompletedBlock,
189+
rowMarkers.lastCompletedBlock
190+
)
177191

178192
return {
179193
id: log.id,
@@ -200,7 +214,8 @@ export async function fetchLogDetail({
200214
executionData: {
201215
totalDuration: log.totalDurationMs,
202216
...executionData,
203-
...liveMarkers,
217+
...(mergedStartedBlock ? { lastStartedBlock: mergedStartedBlock } : {}),
218+
...(mergedCompletedBlock ? { lastCompletedBlock: mergedCompletedBlock } : {}),
204219
enhanced: true as const,
205220
},
206221
files: log.files ?? null,

0 commit comments

Comments
 (0)