diff --git a/src/server.ts b/src/server.ts index 4d6b92502..ac1ecc183 100644 --- a/src/server.ts +++ b/src/server.ts @@ -7,6 +7,7 @@ import { resolveUserContextFromHeaders } from "@/middleware/ensure-user/resolve" import { ProjectRepository } from "@/server/features/projects/repositories/ProjectRepository"; import { SamSessionRepository } from "@/server/features/sam/SamSessionRepository"; import { runScheduledRankChecks } from "@/server/features/rank-tracking/services/scheduledRankChecks"; +import { reconcileStuckRankCheckRuns } from "@/server/features/rank-tracking/services/rankCheckReconciler"; import { reconcileStaleAudits } from "@/server/features/audit/services/auditReconciler"; import { getOrCreateOrganizationCustomer } from "@/server/billing/subscription"; import { isHostedServerAuthMode } from "@/server/lib/runtime-env"; @@ -193,6 +194,7 @@ export default { let watchdogError: unknown; try { await withPgClient(() => reconcileStaleAudits()); + await withPgClient(() => reconcileStuckRankCheckRuns()); } catch (err) { watchdogError = err; console.error("[cron] Stale-audit reconcile failed:", err); diff --git a/src/server/features/rank-tracking/services/rankCheckFinalize.test.ts b/src/server/features/rank-tracking/services/rankCheckFinalize.test.ts new file mode 100644 index 000000000..6bdbfc467 --- /dev/null +++ b/src/server/features/rank-tracking/services/rankCheckFinalize.test.ts @@ -0,0 +1,107 @@ +import { beforeEach, describe, expect, it, vi } from "vitest"; +import { completeRankCheckRunFromSnapshots } from "./rankCheckFinalize"; + +const mocks = vi.hoisted(() => ({ + getSnapshotsForRun: vi.fn(), + updateRun: vi.fn(), + updateConfig: vi.fn(), +})); + +vi.mock( + "@/server/features/rank-tracking/repositories/RankTrackingRepository", + () => ({ RankTrackingRepository: mocks }), +); + +const baseRun = { + id: "run_1", + configId: "config_1", + projectId: "project_1", + status: "running" as const, + keywordsTotal: 2, + keywordsChecked: 2, + isSubsetRun: false, + errorMessage: null, + startedAt: "2026-09-12T06:00:00.000Z", + completedAt: null, +}; + +describe("completeRankCheckRunFromSnapshots", () => { + beforeEach(() => { + mocks.getSnapshotsForRun.mockReset(); + mocks.updateRun.mockReset(); + mocks.updateConfig.mockReset(); + mocks.updateRun.mockResolvedValue(undefined); + mocks.updateConfig.mockResolvedValue(undefined); + }); + + it("completes a running run when every keyword has a snapshot", async () => { + mocks.getSnapshotsForRun.mockResolvedValue([ + { trackingKeywordId: "kw_1" }, + { trackingKeywordId: "kw_1" }, + { trackingKeywordId: "kw_2" }, + ]); + + const result = await completeRankCheckRunFromSnapshots({ run: baseRun }); + + expect(result).toMatchObject({ + keywordsChecked: 2, + keywordsTotal: 2, + }); + expect(mocks.updateRun).toHaveBeenCalledWith( + "run_1", + expect.objectContaining({ + status: "completed", + keywordsChecked: 2, + completedAt: expect.any(String), + }), + ); + expect(mocks.updateConfig).toHaveBeenCalledWith( + "config_1", + "project_1", + expect.objectContaining({ + lastCheckedAt: expect.any(String), + lastSkipReason: null, + }), + ); + }); + + it("skips when snapshot coverage is still incomplete and requireFullCoverage is set", async () => { + mocks.getSnapshotsForRun.mockResolvedValue([ + { trackingKeywordId: "kw_1" }, + ]); + + await expect( + completeRankCheckRunFromSnapshots({ + run: baseRun, + requireFullCoverage: true, + }), + ).resolves.toBeNull(); + expect(mocks.updateRun).not.toHaveBeenCalled(); + }); + + it("completes partial coverage when requireFullCoverage is off", async () => { + mocks.getSnapshotsForRun.mockResolvedValue([ + { trackingKeywordId: "kw_1" }, + ]); + + const result = await completeRankCheckRunFromSnapshots({ run: baseRun }); + expect(result).toMatchObject({ keywordsChecked: 1, keywordsTotal: 2 }); + expect(mocks.updateRun).toHaveBeenCalledWith( + "run_1", + expect.objectContaining({ + status: "completed", + keywordsChecked: 1, + errorMessage: "1 keyword(s) could not be checked", + }), + ); + }); + + it("skips terminal runs", async () => { + await expect( + completeRankCheckRunFromSnapshots({ + run: { ...baseRun, status: "completed" }, + }), + ).resolves.toBeNull(); + expect(mocks.getSnapshotsForRun).not.toHaveBeenCalled(); + }); +}); diff --git a/src/server/features/rank-tracking/services/rankCheckFinalize.ts b/src/server/features/rank-tracking/services/rankCheckFinalize.ts new file mode 100644 index 000000000..d552720ff --- /dev/null +++ b/src/server/features/rank-tracking/services/rankCheckFinalize.ts @@ -0,0 +1,73 @@ +import { RankTrackingRepository } from "@/server/features/rank-tracking/repositories/RankTrackingRepository"; + +type RunRow = NonNullable< + Awaited> +>; + +/** + * Flip an in-flight rank check to completed from already-written snapshots. + * + * Scheduled DFS checks write snapshots incrementally, then a separate finalize + * step flips status. If that step dies (telemetry hang, isolate kill, workflow + * retention) the API hides positions because results only read completed runs. + * Callers use this to finish the status flip without re-probing DataForSEO. + * + * When `requireFullCoverage` is true (watchdog / stale reclaim), returns null + * unless every expected keyword already has a snapshot — so a still-collecting + * run is left alone. The workflow finalize path passes false and always closes + * the run (matching prior finalize behavior, including partial/error cases). + */ +export async function completeRankCheckRunFromSnapshots(input: { + run: RunRow; + batchError?: string | null; + requireFullCoverage?: boolean; +}): Promise<{ + keywordsChecked: number; + keywordsTotal: number; + completedAt: string; +} | null> { + const { run } = input; + if (run.status === "completed" || run.status === "failed") { + return null; + } + + const snapshots = await RankTrackingRepository.getSnapshotsForRun(run.id); + const keywordsChecked = new Set(snapshots.map((s) => s.trackingKeywordId)) + .size; + const keywordsTotal = run.keywordsTotal || keywordsChecked; + + if (input.requireFullCoverage) { + if (keywordsChecked === 0 || keywordsChecked < keywordsTotal) { + return null; + } + } + + const completedAt = new Date().toISOString(); + const incompleteCount = Math.max(keywordsTotal - keywordsChecked, 0); + + let errorMessage: string | undefined; + if (input.batchError) { + errorMessage = `Completed ${keywordsChecked} of ${keywordsTotal} keyword(s). Error: ${input.batchError}`; + } else if (incompleteCount > 0) { + errorMessage = `${incompleteCount} keyword(s) could not be checked`; + } + + // Flipping status away from 'pending'/'running' releases the partial-index + // slot for the next run. Do this before any telemetry. + await RankTrackingRepository.updateRun(run.id, { + status: "completed", + keywordsChecked, + completedAt, + ...(errorMessage ? { errorMessage } : {}), + }); + + // Clear any previous skip reason on success. + // Note: nextCheckAt is NOT set here — the cron handler advances it eagerly + // before starting the workflow to prevent retry storms. + await RankTrackingRepository.updateConfig(run.configId, run.projectId, { + lastCheckedAt: completedAt, + lastSkipReason: null, + }); + + return { keywordsChecked, keywordsTotal, completedAt }; +} diff --git a/src/server/features/rank-tracking/services/rankCheckReconciler.ts b/src/server/features/rank-tracking/services/rankCheckReconciler.ts new file mode 100644 index 000000000..6f0854462 --- /dev/null +++ b/src/server/features/rank-tracking/services/rankCheckReconciler.ts @@ -0,0 +1,73 @@ +import { and, asc, inArray, lt } from "drizzle-orm"; +import { db } from "@/db"; +import { rankCheckRuns } from "@/db/schema"; +import { completeRankCheckRunFromSnapshots } from "@/server/features/rank-tracking/services/rankCheckFinalize"; +import { failRunIfActive } from "@/server/features/rank-tracking/services/rankCheckRunGuards"; + +/** + * Snapshots for a finished DFS collect are usually present minutes before the + * finalize step runs. Give the live workflow that window, then complete from + * DB state so positions stop staying invisible behind status=running. + */ +const SNAPSHOT_FINALIZE_GRACE_MS = 3 * 60 * 1000; + +/** In-flight runs older than this with no complete snapshots get failed. */ +const STALE_INCOMPLETE_MS = 25 * 60 * 1000; + +const WATCHDOG_BATCH_LIMIT = 100; + +/** + * Cron watchdog: finish (or fail) rank_check_runs stuck in pending/running + * after their workflow should have finalized. + */ +export async function reconcileStuckRankCheckRuns() { + const snapshotGraceCutoff = new Date( + Date.now() - SNAPSHOT_FINALIZE_GRACE_MS, + ).toISOString(); + const incompleteCutoff = new Date( + Date.now() - STALE_INCOMPLETE_MS, + ).toISOString(); + + const stuck = await db + .select() + .from(rankCheckRuns) + .where( + and( + inArray(rankCheckRuns.status, ["pending", "running"]), + lt(rankCheckRuns.startedAt, snapshotGraceCutoff), + ), + ) + .orderBy(asc(rankCheckRuns.startedAt)) + .limit(WATCHDOG_BATCH_LIMIT); + + for (const run of stuck) { + try { + const completed = await completeRankCheckRunFromSnapshots({ + run, + requireFullCoverage: true, + }); + if (completed) { + console.log( + `[rank-check] watchdog completed run ${run.id} from snapshots (${completed.keywordsChecked}/${completed.keywordsTotal})`, + ); + continue; + } + + if (run.startedAt < incompleteCutoff) { + await failRunIfActive( + run.id, + "Rank check timed out before finalizing", + run, + ); + console.log( + `[rank-check] watchdog failed stale incomplete run ${run.id}`, + ); + } + } catch (error) { + console.error( + `[rank-check] watchdog failed to reconcile ${run.id}:`, + error, + ); + } + } +} diff --git a/src/server/features/rank-tracking/services/rankCheckRunGuards.ts b/src/server/features/rank-tracking/services/rankCheckRunGuards.ts index 19bd3ec8c..551db18a2 100644 --- a/src/server/features/rank-tracking/services/rankCheckRunGuards.ts +++ b/src/server/features/rank-tracking/services/rankCheckRunGuards.ts @@ -1,6 +1,7 @@ import { env } from "cloudflare:workers"; import type { BillingCustomerContext } from "@/server/billing/subscription"; import { RankTrackingRepository } from "@/server/features/rank-tracking/repositories/RankTrackingRepository"; +import { completeRankCheckRunFromSnapshots } from "@/server/features/rank-tracking/services/rankCheckFinalize"; import type { RankCheckTriggerResult, RankTrackingConfig, @@ -212,7 +213,15 @@ export async function beginRankCheckRun(input: { ageMs: Date.now() - new Date(blocker.startedAt).getTime(), }); if (staleReason) { - await failRunIfActive(blocker.id, staleReason, blocker); + // Prefer completing from snapshots over failing — failing still hides + // paid DFS results (results SQL filters to status=completed). + const completed = await completeRankCheckRunFromSnapshots({ + run: blocker, + requireFullCoverage: true, + }); + if (!completed) { + await failRunIfActive(blocker.id, staleReason, blocker); + } continue; // slot is free now — retry insert } } diff --git a/src/server/lib/posthog.ts b/src/server/lib/posthog.ts index c73141a32..cdcf43e4e 100644 --- a/src/server/lib/posthog.ts +++ b/src/server/lib/posthog.ts @@ -42,7 +42,12 @@ export async function captureServerError( } catch (posthogError) { console.error("posthog server capture failed", posthogError); } finally { - await client.shutdown().catch(() => {}); + // Bound shutdown: an indefinite PostHog flush has wedged Worker/workflow + // steps after the real work finished (rank-check finalize hung on this). + await Promise.race([ + client.shutdown().catch(() => {}), + new Promise((resolve) => setTimeout(resolve, 1500)), + ]); } } @@ -71,6 +76,9 @@ export async function captureServerEvent(args: { } catch (posthogError) { console.error("posthog server capture failed", posthogError); } finally { - await client.shutdown().catch(() => {}); + await Promise.race([ + client.shutdown().catch(() => {}), + new Promise((resolve) => setTimeout(resolve, 1500)), + ]); } } diff --git a/src/server/workflows/RankCheckWorkflow.ts b/src/server/workflows/RankCheckWorkflow.ts index f056ee7b0..5164c59d6 100644 --- a/src/server/workflows/RankCheckWorkflow.ts +++ b/src/server/workflows/RankCheckWorkflow.ts @@ -7,6 +7,7 @@ import { NonRetryableError } from "cloudflare:workflows"; import { withPgClient } from "@/db"; import type { BillingCustomerContext } from "@/server/billing/subscription"; import { RankTrackingRepository } from "@/server/features/rank-tracking/repositories/RankTrackingRepository"; +import { completeRankCheckRunFromSnapshots } from "@/server/features/rank-tracking/services/rankCheckFinalize"; import { failRunIfActive } from "@/server/features/rank-tracking/services/rankCheckRunGuards"; import { runLiveCheck, @@ -155,42 +156,17 @@ async function finalizeRankCheckRun(input: { return; } - const nowIso = new Date().toISOString(); - - // Snapshots were written incrementally by each batch step. - // Count from DB to get the authoritative keyword count. - const snapshots = await RankTrackingRepository.getSnapshotsForRun( - input.runId, - ); - const keywordsChecked = new Set(snapshots.map((s) => s.trackingKeywordId)) - .size; - - const keywordsTotal = run.keywordsTotal || keywordsChecked; - const incompleteCount = keywordsTotal - keywordsChecked; - - let errorMessage: string | undefined; - if (input.batchError) { - errorMessage = `Completed ${keywordsChecked} of ${keywordsTotal} keyword(s). Error: ${input.batchError}`; - } else if (incompleteCount > 0) { - errorMessage = `${incompleteCount} keyword(s) could not be checked`; - } - - // Flipping status away from 'pending'/'running' is what releases the - // partial-index slot for the next run. - await RankTrackingRepository.updateRun(input.runId, { - status: "completed", - keywordsChecked, - completedAt: nowIso, - ...(errorMessage ? { errorMessage } : {}), + // Status flip first. Awaiting PostHog shutdown after DFS snapshots were + // written has left status=running so the API hid positions. + const completed = await completeRankCheckRunFromSnapshots({ + run, + batchError: input.batchError, }); + if (!completed) { + return; + } - // Clear any previous skip reason on success. - // Note: nextCheckAt is NOT set here — the cron handler advances it eagerly - // before starting the workflow to prevent retry storms. - await RankTrackingRepository.updateConfig(input.configId, input.projectId, { - lastCheckedAt: nowIso, - lastSkipReason: null, - }); + const { keywordsChecked, keywordsTotal } = completed; // One-line summary per run so fallback rates are visible in Workers Logs. // Keys match the PostHog event properties for log/event correlation. @@ -198,32 +174,36 @@ async function finalizeRankCheckRun(input: { ? ` queue_tasks=${input.queueStats.queueTasks} queue_collected=${input.queueStats.queueCollected} fallback_tasks=${input.queueStats.fallbackTasks} fallback_checked=${input.queueStats.fallbackChecked}` : ""; // Error text can echo vendor/user content — keep it one line and bounded. - const errorSummary = errorMessage - ? ` error="${errorMessage.replace(/\s+/g, " ").slice(0, 200)}"` + const errorSummary = input.batchError + ? ` error="${input.batchError.replace(/\s+/g, " ").slice(0, 200)}"` : ""; console.log( `[rank-check] ${input.runId} completed org=${input.billingCustomer.organizationId} project=${input.projectId} trigger=${input.trigger} keywords=${keywordsChecked}/${keywordsTotal}${queueSummary}${errorSummary}`, ); - await captureServerEvent({ - distinctId: input.billingCustomer.userId, - event: "rank_tracking:check_complete", - organizationId: input.billingCustomer.organizationId, - properties: { - project_id: input.projectId, - status: "completed", - trigger: input.trigger, - keywords_checked: keywordsChecked, - ...(input.queueStats - ? { - queue_tasks: input.queueStats.queueTasks, - queue_collected: input.queueStats.queueCollected, - fallback_tasks: input.queueStats.fallbackTasks, - fallback_checked: input.queueStats.fallbackChecked, - } - : {}), - }, - }); + // Never await PostHog here: shutdown flush can hang past the step timeout + // and leave the workflow wedged even after the DB status flip. + void Promise.resolve( + captureServerEvent({ + distinctId: input.billingCustomer.userId, + event: "rank_tracking:check_complete", + organizationId: input.billingCustomer.organizationId, + properties: { + project_id: input.projectId, + status: "completed", + trigger: input.trigger, + keywords_checked: keywordsChecked, + ...(input.queueStats + ? { + queue_tasks: input.queueStats.queueTasks, + queue_collected: input.queueStats.queueCollected, + fallback_tasks: input.queueStats.fallbackTasks, + fallback_checked: input.queueStats.fallbackChecked, + } + : {}), + }, + }), + ).catch(() => {}); } async function markRankCheckRunFailed(input: { @@ -247,16 +227,18 @@ async function markRankCheckRunFailed(input: { }); } - await captureServerEvent({ - distinctId: input.billingCustomer.userId, - event: "rank_tracking:check_complete", - organizationId: input.billingCustomer.organizationId, - properties: { - project_id: input.projectId, - status: "failed", - error: errorMessage, - }, - }); + void Promise.resolve( + captureServerEvent({ + distinctId: input.billingCustomer.userId, + event: "rank_tracking:check_complete", + organizationId: input.billingCustomer.organizationId, + properties: { + project_id: input.projectId, + status: "failed", + error: errorMessage, + }, + }), + ).catch(() => {}); } export class RankCheckWorkflow extends WorkflowEntrypoint<