From 5e68f03c25f360489c6d62e3d6a0c13ac517b92b Mon Sep 17 00:00:00 2001 From: "allyblockcast[bot]" Date: Wed, 5 Aug 2026 12:40:52 +0000 Subject: [PATCH 1/2] fix(productivity-review): derive active duration from run execution, not checkout (BLO-22016) `elapsedMs` was computed from issue.startedAt (stamped at checkout) or executionLockedAt, so a run that sat queued for hours before dispatch counted as "active" work and tripped false-positive long_active_duration reviews (BLO-18846 / run 9e49405e: ~17.75h queued, 0 tokens executed). Anchor the active episode to the earliest run that has actually started executing since the current checkout instead. A queued-but-never-executed run now yields no active duration; a genuinely long-running or stalled executing run still trips the threshold. Co-Authored-By: Paperclip --- .../productivity-review-service.test.ts | 130 +++++++++++++++++- server/src/services/productivity-review.ts | 36 ++++- 2 files changed, 159 insertions(+), 7 deletions(-) diff --git a/server/src/__tests__/productivity-review-service.test.ts b/server/src/__tests__/productivity-review-service.test.ts index 47ab55e888d9..0741b3e6859e 100644 --- a/server/src/__tests__/productivity-review-service.test.ts +++ b/server/src/__tests__/productivity-review-service.test.ts @@ -114,6 +114,14 @@ describeEmbeddedPostgres("productivity review service", () => { parentId?: string | null; originKind?: string; executionPolicy?: Record | null; + // BLO-22016: active duration is now derived from a run's own `startedAt`, + // not from issue checkout time. By default, seeding an explicit + // `startedAt` also seeds a matching "running" heartbeat run that + // actually started then, so existing long-active/monitor/approval-gate + // fixtures keep representing a genuinely executing episode. Pass + // `activeRun: false` to opt out (e.g. to simulate a checked-out issue + // whose run never executed, or a 100%-routine-origin sampling window). + activeRun?: boolean; }) { const companyId = randomUUID(); const ownerUserId = randomUUID(); @@ -122,6 +130,16 @@ describeEmbeddedPostgres("productivity review service", () => { const issueId = randomUUID(); const issuePrefix = `PR${companyId.replace(/-/g, "").slice(0, 6).toUpperCase()}`; const createdAt = new Date("2026-04-28T10:00:00.000Z"); + const status = opts?.status ?? "in_progress"; + const startedAt = opts?.startedAt ?? createdAt; + // BLO-22016: default to seeding a matching run whenever a fixture + // explicitly backdates `startedAt` to simulate an aged episode — that's + // what nearly every caller in this file wants (a genuinely executing + // episode for long-active/monitor/approval-gate suppression tests), not + // a checked-out issue whose run never ran. Pass `activeRun: false` + // explicitly to opt out (e.g. to simulate the queued-never-executed + // case this bug fix targets, or a 100%-routine-origin sampling window). + const shouldSeedActiveRun = opts?.activeRun ?? Boolean(opts?.startedAt); await db.insert(companies).values({ id: companyId, @@ -165,14 +183,14 @@ describeEmbeddedPostgres("productivity review service", () => { id: issueId, companyId, title: "Implement data import", - status: opts?.status ?? "in_progress", + status, priority: "medium", assigneeAgentId: coderId, parentId: opts?.parentId ?? null, originKind: opts?.originKind ?? "manual", issueNumber: 1, identifier: `${issuePrefix}-1`, - startedAt: opts?.startedAt ?? createdAt, + startedAt, monitorNextCheckAt: opts?.monitorNextCheckAt ?? null, monitorScheduledBy: opts?.monitorScheduledBy ?? null, monitorLastTriggeredAt: opts?.monitorLastTriggeredAt ?? null, @@ -182,6 +200,21 @@ describeEmbeddedPostgres("productivity review service", () => { updatedAt: createdAt, }); + if (status === "in_progress" && shouldSeedActiveRun) { + await db.insert(heartbeatRuns).values({ + id: randomUUID(), + companyId, + agentId: coderId, + status: "running", + invocationSource: "assignment", + triggerDetail: "system", + startedAt, + contextSnapshot: { issueId, taskId: issueId }, + createdAt: startedAt, + updatedAt: startedAt, + }); + } + return { companyId, ownerUserId, managerId, coderId, issueId, issuePrefix, createdAt }; } @@ -936,6 +969,93 @@ describeEmbeddedPostgres("productivity review service", () => { expect(hold.held).toBe(false); }); + // BLO-22016: `issue.startedAt` is stamped at checkout, before a run has + // necessarily been dispatched. An issue checked out long ago whose run is + // still queued (never executed) must not accrue active duration or trip + // `long_active_duration` -- the platform hasn't started the work yet, the + // assignee hasn't stalled on it. + it("does not create a long-active review when the checked-out issue's run has never executed (BLO-22016)", async () => { + const now = new Date("2026-04-28T12:00:00.000Z"); + const seeded = await seedAssignedIssue({ + status: "in_progress", + startedAt: new Date(now.getTime() - 17.75 * 60 * 60 * 1000), + activeRun: false, + }); + await db.insert(heartbeatRuns).values({ + id: randomUUID(), + companyId: seeded.companyId, + agentId: seeded.coderId, + status: "queued", + invocationSource: "assignment", + triggerDetail: "system", + startedAt: null, + contextSnapshot: { issueId: seeded.issueId, taskId: seeded.issueId }, + createdAt: new Date(now.getTime() - 17.75 * 60 * 60 * 1000), + updatedAt: new Date(now.getTime() - 17.75 * 60 * 60 * 1000), + }); + + const result = await productivityReviewService(db).reconcileProductivityReviews({ + now, + companyId: seeded.companyId, + }); + + expect(result.created).toBe(0); + expect(await listProductivityReviews(seeded.companyId)).toHaveLength(0); + }); + + // Same shape, but no run row exists at all yet (nothing dispatched since checkout). + it("does not create a long-active review for a checked-out issue with zero runs (BLO-22016)", async () => { + const now = new Date("2026-04-28T12:00:00.000Z"); + const seeded = await seedAssignedIssue({ + status: "in_progress", + startedAt: new Date(now.getTime() - 7 * 60 * 60 * 1000), + activeRun: false, + }); + + const result = await productivityReviewService(db).reconcileProductivityReviews({ + now, + companyId: seeded.companyId, + }); + + expect(result.created).toBe(0); + expect(await listProductivityReviews(seeded.companyId)).toHaveLength(0); + }); + + // A run that actually started (even if it later failed) still anchors the + // active episode to its own `startedAt`, so a genuinely long-running or + // long-stalled *executing* run still trips the threshold -- this guards + // against fixing BLO-22016 by simply desensitizing the detector. + it("still creates a long-active review once the queued run actually starts executing (BLO-22016 control)", async () => { + const now = new Date("2026-04-28T12:00:00.000Z"); + const seeded = await seedAssignedIssue({ + status: "in_progress", + startedAt: new Date(now.getTime() - 17.75 * 60 * 60 * 1000), + activeRun: false, + }); + await db.insert(heartbeatRuns).values({ + id: randomUUID(), + companyId: seeded.companyId, + agentId: seeded.coderId, + status: "running", + invocationSource: "assignment", + triggerDetail: "system", + startedAt: new Date(now.getTime() - 7 * 60 * 60 * 1000), + contextSnapshot: { issueId: seeded.issueId, taskId: seeded.issueId }, + createdAt: new Date(now.getTime() - 17.75 * 60 * 60 * 1000), + updatedAt: new Date(now.getTime() - 7 * 60 * 60 * 1000), + }); + + const result = await productivityReviewService(db).reconcileProductivityReviews({ + now, + companyId: seeded.companyId, + }); + + expect(result.created).toBe(1); + const [review] = await listProductivityReviews(seeded.companyId); + expect(review?.description).toContain("Primary trigger: `long_active_duration`"); + expect(review?.description).toContain("current active episode has lasted 7h"); + }); + // BLO-19848: `long_active_duration` measured raw wall-clock from // issues.started_at to now with no reference to whether anything was actually // executing, so an issue pinned by a non-live executionRunId kept accruing @@ -1104,7 +1224,8 @@ describeEmbeddedPostgres("productivity review service", () => { expect(review?.description).toContain("Excluded as non-live execution hold"); }); - it("excludes only the silent tail when a running holder goes quiet mid-episode (BLO-19848)", async () => { const now = new Date("2026-04-28T12:00:00.000Z"); + it("excludes only the silent tail when a running holder goes quiet mid-episode (BLO-19848)", async () => { + const now = new Date("2026-04-28T12:00:00.000Z"); const episodeStart = new Date(now.getTime() - 7 * 60 * 60 * 1000); const seeded = await seedAssignedIssue({ status: "in_progress", startedAt: episodeStart }); await pinExecutionRun({ @@ -3851,6 +3972,9 @@ describeEmbeddedPostgres("productivity review service", () => { const seeded = await seedAssignedIssue({ status: "in_progress", startedAt: new Date(now.getTime() - 7 * 60 * 60 * 1000), + // The default companion run (BLO-22016) is not routine-origin, which + // would break the "100% routine" premise this test depends on. + activeRun: false, }); await insertRuns({ companyId: seeded.companyId, diff --git a/server/src/services/productivity-review.ts b/server/src/services/productivity-review.ts index 022c3c91f2ca..ac2c87d836c8 100644 --- a/server/src/services/productivity-review.ts +++ b/server/src/services/productivity-review.ts @@ -357,9 +357,8 @@ function latestDate(...values: Array) { * * Returns the clamp point — the last moment still attributable to the run — so * the episode is truncated when live work stopped rather than dropped to zero. - * An issue with no execution holder at all returns null and keeps full - * wall-clock accounting: that is an unowned `in_progress` issue, which is - * genuine stalling and exactly what the trigger should still catch. + * An issue with no execution holder at all returns null; BLO-22016's + * activeExecutionEpisodeStart decides whether any run has actually started. */ function nonLiveExecutionHoldSince( issue: IssueRow, @@ -435,6 +434,35 @@ function liveSegmentStartedAt(executionRun: HeartbeatRunRow | null, now: Date): return parkEndedAt; } +/** + * BLO-22016: `issue.startedAt` is stamped at checkout time (see + * `issueService.checkout`), not when a run actually begins executing. A + * checked-out issue can sit behind a scheduler backlog or provider capacity + * gate for hours before its first run dispatches, and that queueing was + * being counted as "active" work, manufacturing `long_active_duration` + * false positives (BLO-18846 / run `9e49405e`: ~17.75h queued, 0 tokens). + * + * Anchor the active episode to the earliest run that has actually started + * executing (`run.startedAt` populated) since the current checkout, instead + * of the checkout timestamp itself. `latestRuns` is not pre-scoped to the + * current episode (it is the issue's most recent runs overall), so runs + * that started before this checkout are excluded. An issue whose run(s) + * are still queued/scheduled and have never executed has no active episode + * yet, so this returns null and the caller treats elapsed duration as + * absent rather than zero-but-growing. + */ +function activeExecutionEpisodeStart(issue: IssueRow, latestRuns: HeartbeatRunRow[]): Date | null { + const checkoutAt = coerceDate(issue.startedAt) ?? coerceDate(issue.executionLockedAt); + if (!checkoutAt) return null; + let earliest: Date | null = null; + for (const run of latestRuns) { + const startedAt = coerceDate(run.startedAt); + if (!startedAt || startedAt.getTime() < checkoutAt.getTime()) continue; + if (!earliest || startedAt.getTime() < earliest.getTime()) earliest = startedAt; + } + return earliest; +} + function isTerminalIssueStatus(status: string | null | undefined) { return status === "done" || status === "cancelled"; } @@ -2073,7 +2101,7 @@ export function productivityReviewService(db: Db, deps?: ProductivityReviewServi const activeRunCount = latestRuns.filter((run) => ACTIVE_RUN_STATUSES.includes(run.status as (typeof ACTIVE_RUN_STATUSES)[number]), ).length; - const activeStartedAt = sourceIssue.startedAt ?? sourceIssue.executionLockedAt ?? null; + const activeStartedAt = activeExecutionEpisodeStart(sourceIssue, latestRuns); // BLO-19848: clamp the episode end to the last moment execution was // attributable to a live run, so a wedged holder cannot accrue "active" // time on work that already finished. See nonLiveExecutionHoldSince. From d0830191cd7ceda98b28d6d660aac20db52a151a Mon Sep 17 00:00:00 2001 From: Omar Ramadan Date: Thu, 6 Aug 2026 00:08:55 -0700 Subject: [PATCH 2/2] fix(productivity-review): query active episode start --- .../productivity-review-service.test.ts | 61 +++++++++++++++++++ server/src/services/productivity-review.ts | 35 ++++++----- 2 files changed, 82 insertions(+), 14 deletions(-) diff --git a/server/src/__tests__/productivity-review-service.test.ts b/server/src/__tests__/productivity-review-service.test.ts index 0741b3e6859e..cb20f7f45279 100644 --- a/server/src/__tests__/productivity-review-service.test.ts +++ b/server/src/__tests__/productivity-review-service.test.ts @@ -1056,6 +1056,67 @@ describeEmbeddedPostgres("productivity review service", () => { expect(review?.description).toContain("current active episode has lasted 7h"); }); + it("keeps long-active review timing independent of the bounded run-streak sample (BLO-22016)", async () => { + const now = new Date("2026-04-28T12:00:00.000Z"); + const seeded = await seedAssignedIssue({ + status: "in_progress", + startedAt: new Date(now.getTime() - 8 * 60 * 60 * 1000), + activeRun: false, + }); + const earliestStartedAt = new Date(now.getTime() - 7 * 60 * 60 * 1000); + const recentRuns: Array = Array.from({ length: 100 }, (_, index) => { + const createdAt = new Date(now.getTime() - index * 60_000); + return { + id: randomUUID(), + companyId: seeded.companyId, + agentId: seeded.coderId, + status: "succeeded", + invocationSource: "assignment", + triggerDetail: "system", + startedAt: createdAt, + finishedAt: new Date(createdAt.getTime() + 30_000), + contextSnapshot: { issueId: seeded.issueId, taskId: seeded.issueId }, + livenessState: "advanced", + nextAction: "Continue processing the next batch.", + createdAt, + updatedAt: createdAt, + }; + }); + await db.insert(heartbeatRuns).values([ + ...recentRuns, + { + id: randomUUID(), + companyId: seeded.companyId, + agentId: seeded.coderId, + status: "succeeded", + invocationSource: "assignment", + triggerDetail: "system", + startedAt: earliestStartedAt, + finishedAt: new Date(earliestStartedAt.getTime() + 30_000), + contextSnapshot: { issueId: seeded.issueId, taskId: seeded.issueId }, + livenessState: "advanced", + nextAction: "Started the active episode.", + createdAt: earliestStartedAt, + updatedAt: earliestStartedAt, + }, + ]); + + const result = await productivityReviewService(db).reconcileProductivityReviews({ + now, + companyId: seeded.companyId, + thresholds: { + noCommentStreakRuns: 1_000, + highChurnHourly: 1_000, + highChurnSixHours: 1_000, + }, + }); + + expect(result.created).toBe(1); + const [review] = await listProductivityReviews(seeded.companyId); + expect(review?.description).toContain("Primary trigger: `long_active_duration`"); + expect(review?.description).toContain("current active episode has lasted 7h"); + }); + // BLO-19848: `long_active_duration` measured raw wall-clock from // issues.started_at to now with no reference to whether anything was actually // executing, so an issue pinned by a non-live executionRunId kept accruing diff --git a/server/src/services/productivity-review.ts b/server/src/services/productivity-review.ts index ac2c87d836c8..0d8dbd3db5ab 100644 --- a/server/src/services/productivity-review.ts +++ b/server/src/services/productivity-review.ts @@ -444,23 +444,30 @@ function liveSegmentStartedAt(executionRun: HeartbeatRunRow | null, now: Date): * * Anchor the active episode to the earliest run that has actually started * executing (`run.startedAt` populated) since the current checkout, instead - * of the checkout timestamp itself. `latestRuns` is not pre-scoped to the - * current episode (it is the issue's most recent runs overall), so runs - * that started before this checkout are excluded. An issue whose run(s) + * of the checkout timestamp itself. This deliberately queries outside the + * `latestRuns` streak sample: that sample is capped at MAX_RUNS_FOR_STREAK + * and ordered newest-first, so it cannot be authoritative for the first run + * once an issue has a long post-checkout run history. An issue whose run(s) * are still queued/scheduled and have never executed has no active episode - * yet, so this returns null and the caller treats elapsed duration as - * absent rather than zero-but-growing. + * yet, so this returns null and the caller treats elapsed duration as absent + * rather than zero-but-growing. */ -function activeExecutionEpisodeStart(issue: IssueRow, latestRuns: HeartbeatRunRow[]): Date | null { +async function activeExecutionEpisodeStart(db: Db, issue: IssueRow, agent: AgentRow): Promise { const checkoutAt = coerceDate(issue.startedAt) ?? coerceDate(issue.executionLockedAt); if (!checkoutAt) return null; - let earliest: Date | null = null; - for (const run of latestRuns) { - const startedAt = coerceDate(run.startedAt); - if (!startedAt || startedAt.getTime() < checkoutAt.getTime()) continue; - if (!earliest || startedAt.getTime() < earliest.getTime()) earliest = startedAt; - } - return earliest; + const [row] = await db + .select({ startedAt: sql`min(${heartbeatRuns.startedAt})` }) + .from(heartbeatRuns) + .where( + and( + eq(heartbeatRuns.companyId, issue.companyId), + eq(heartbeatRuns.agentId, agent.id), + issueRunScopeSql(issue.id), + sql`${heartbeatRuns.startedAt} is not null`, + sql`${heartbeatRuns.startedAt} >= ${checkoutAt.toISOString()}::timestamptz`, + ), + ); + return coerceDate(row?.startedAt); } function isTerminalIssueStatus(status: string | null | undefined) { @@ -2101,7 +2108,7 @@ export function productivityReviewService(db: Db, deps?: ProductivityReviewServi const activeRunCount = latestRuns.filter((run) => ACTIVE_RUN_STATUSES.includes(run.status as (typeof ACTIVE_RUN_STATUSES)[number]), ).length; - const activeStartedAt = activeExecutionEpisodeStart(sourceIssue, latestRuns); + const activeStartedAt = await activeExecutionEpisodeStart(db, sourceIssue, sourceAgent); // BLO-19848: clamp the episode end to the last moment execution was // attributable to a live run, so a wedged holder cannot accrue "active" // time on work that already finished. See nonLiveExecutionHoldSince.