Skip to content

Commit 1ced0b6

Browse files
authored
fix(knowledge): stop the stuck-document sweep reclaiming still-queued documents (#6921)
* fix(knowledge): stop the stuck-document sweep reclaiming still-queued documents The sweep gave 'processing' a staleness cutoff but gave 'pending' and 'failed' none, and the only cross-run guard was uploadedAt < syncStartedAt, which scopes within a sync but not across them. That was harmless while document processing awaited inline: documents were terminal by the time a sync ended. Since dispatch became asynchronous they sit 'pending' until a worker picks them up, so the next sync deleted their embeddings, reset them, and re-dispatched while the original runs were still executing — and each re-dispatch mints a fresh pass id, so it billed again. Queued documents now get a grace period derived from queue drain time rather than run duration: the processing queue's concurrency is 20 and global across workspaces, so a 2,600-document corpus takes roughly two hours to drain. The existing 45-minute threshold bounds a run, not a wait, and would still reclaim live documents on any corpus over about 900. No column records dispatch time, so the signal is processingStartedAt falling back to uploadedAt. The sweep now stamps that column when it re-dispatches, and the user-triggered retry stamps it instead of clearing it — without both, only a document's first dispatch was protected and the sweep churned once per sync forever on anything that kept waiting. The grace narrows the duplicate-billing window but cannot close it: a re-dispatch mints a new request id and the Trigger idempotency key is scoped per dispatch by design. Closing it durably needs a document-scoped key or a dispatch-generation column, recorded in TSDoc and deliberately not built here. * fix(knowledge): record dispatch time in its own column instead of overloading the start time Two review findings on this PR traced to the same root: the queue grace was reading processingStartedAt, a column that means something else. Externally, a pending row carrying a dispatch timestamp reported a processing start time for work that had not started. Internally, updateDocument sets a document pending and refreshes uploadedAt while leaving the previous run's processingStartedAt in place, and completion never clears it — so the sweep aged a re-dispatched document from a leftover stamp rather than its actual dispatch, and could reclaim it inside the grace window while the earlier queue entry was still live. That reopens the duplicate-billing race this PR closes. processing_queued_at is written on every re-dispatch and read by the sweep; processingStartedAt goes back to meaning what its name says, so its external contract is byte-identical to before this PR. Not stamped on first dispatch: the row is created and dispatched inside the same sync run, so uploadedAt is already accurate there and a guarded write per upload would buy no behavior. The internal document route returns a full table row through a passthrough schema, so the new column would have shipped as an undeclared raw Date. Declared and serialized explicitly instead. * fix(knowledge): stamp the queue time in the dispatch funnel, not at each call site Giving dispatch its own column was not enough. The connector content-update path updates a row in place with pending status and a fresh uploadedAt while leaving every prior-run processing column intact, so a document dispatched once already carried a stale queue stamp, the refreshed uploadedAt was never consulted, and the row aged from a dead run's timestamp — the same bug one level down. "Written on dispatch and only on dispatch" is now structural rather than a convention three call sites remember: the stamp lives in processDocumentsWithQueue, which every one of the nine dispatch paths already goes through, so none can forget it. The sweep's and the retry's own stamps are kept because they land inside the same transaction as their reset, so a document keeps its grace even if the dispatch that follows throws. The funnel also clears processingStartedAt, guarded on the row still being pending so it cannot disturb a worker's compare-and-set. That closes the API-facing half at its source: a pending row can no longer report a start time from any path, including the content-update path no serializer would have seen.
1 parent 2074afe commit 1ced0b6

11 files changed

Lines changed: 20513 additions & 21 deletions

File tree

apps/sim/lib/api/contracts/knowledge/documents.ts

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -267,6 +267,8 @@ export const documentDataSchema = z
267267
tokenCount: z.number(),
268268
characterCount: z.number(),
269269
processingStatus: z.enum(['pending', 'processing', 'completed', 'failed']),
270+
/** When indexing was last dispatched to a worker, which precedes a worker starting it. */
271+
processingQueuedAt: nullableWireDateSchema.optional(),
270272
processingStartedAt: nullableWireDateSchema.optional(),
271273
processingCompletedAt: nullableWireDateSchema.optional(),
272274
processingError: z.string().nullable().optional(),

apps/sim/lib/knowledge/api/internal-route.ts

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -60,6 +60,7 @@ function serializeNullableDate(date: Date | string | null): string | null {
6060
export function toInternalKnowledgeDocument<
6161
T extends {
6262
uploadedAt: Date | string
63+
processingQueuedAt?: Date | string | null
6364
processingStartedAt?: Date | string | null
6465
processingCompletedAt?: Date | string | null
6566
date1?: Date | string | null
@@ -69,6 +70,7 @@ export function toInternalKnowledgeDocument<
6970
return documentDataSchema.parse({
7071
...document,
7172
uploadedAt: serializeDate(document.uploadedAt),
73+
processingQueuedAt: serializeNullableDate(document.processingQueuedAt ?? null),
7274
processingStartedAt: serializeNullableDate(document.processingStartedAt ?? null),
7375
processingCompletedAt: serializeNullableDate(document.processingCompletedAt ?? null),
7476
date1: serializeNullableDate(document.date1 ?? null),

apps/sim/lib/knowledge/connectors/sync-engine.test.ts

Lines changed: 123 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@ import { beforeEach, describe, expect, it, vi } from 'vitest'
77
import {
88
classifySuspectListing,
99
evaluateListingSafety,
10+
isStuckDocumentSweepEligible,
1011
mergeHydratedDocument,
1112
type PreviousListingObservation,
1213
} from '@/lib/knowledge/connectors/sync-engine'
@@ -702,3 +703,125 @@ describe('mergeHydratedDocument', () => {
702703
expect(merged.sourceUrl).toBe('https://example.com/a')
703704
})
704705
})
706+
707+
describe('isStuckDocumentSweepEligible', () => {
708+
const now = new Date('2026-08-20T12:00:00.000Z')
709+
const minutesBefore = (minutes: number) => new Date(now.getTime() - minutes * 60 * 1000)
710+
711+
const candidate = (
712+
processingStatus: string,
713+
overrides: {
714+
processingQueuedAt?: Date | null
715+
processingStartedAt?: Date | null
716+
uploadedAt?: Date
717+
} = {}
718+
) => ({
719+
processingStatus,
720+
processingQueuedAt: overrides.processingQueuedAt ?? null,
721+
processingStartedAt: overrides.processingStartedAt ?? null,
722+
uploadedAt: overrides.uploadedAt ?? minutesBefore(5),
723+
})
724+
725+
it('leaves a document dispatched by the previous sync and still queued alone', () => {
726+
expect(
727+
isStuckDocumentSweepEligible(candidate('pending', { uploadedAt: minutesBefore(90) }), now)
728+
).toBe(false)
729+
})
730+
731+
it('leaves a document the sweep itself re-dispatched alone while it waits', () => {
732+
expect(
733+
isStuckDocumentSweepEligible(
734+
candidate('pending', {
735+
processingQueuedAt: minutesBefore(90),
736+
uploadedAt: minutesBefore(60 * 48),
737+
}),
738+
now
739+
)
740+
).toBe(false)
741+
})
742+
743+
it('reclaims a queued document once the grace period has passed', () => {
744+
expect(
745+
isStuckDocumentSweepEligible(candidate('pending', { uploadedAt: minutesBefore(241) }), now)
746+
).toBe(true)
747+
expect(
748+
isStuckDocumentSweepEligible(
749+
candidate('pending', {
750+
processingQueuedAt: minutesBefore(241),
751+
uploadedAt: minutesBefore(60 * 48),
752+
}),
753+
now
754+
)
755+
).toBe(true)
756+
})
757+
758+
it('holds a queued document at the grace boundary', () => {
759+
expect(
760+
isStuckDocumentSweepEligible(candidate('pending', { uploadedAt: minutesBefore(240) }), now)
761+
).toBe(false)
762+
})
763+
764+
it('reclaims a failed document with no grace', () => {
765+
expect(isStuckDocumentSweepEligible(candidate('failed'), now)).toBe(true)
766+
expect(
767+
isStuckDocumentSweepEligible(
768+
candidate('failed', { processingStartedAt: minutesBefore(1) }),
769+
now
770+
)
771+
).toBe(true)
772+
})
773+
774+
it('reclaims a processing document only once its run is stale', () => {
775+
expect(
776+
isStuckDocumentSweepEligible(
777+
candidate('processing', { processingStartedAt: minutesBefore(44) }),
778+
now
779+
)
780+
).toBe(false)
781+
expect(
782+
isStuckDocumentSweepEligible(
783+
candidate('processing', { processingStartedAt: minutesBefore(46) }),
784+
now
785+
)
786+
).toBe(true)
787+
})
788+
789+
it('reclaims a processing document with no start time', () => {
790+
expect(isStuckDocumentSweepEligible(candidate('processing'), now)).toBe(true)
791+
})
792+
793+
it('ignores a start time a worker left on a document that was requeued', () => {
794+
expect(
795+
isStuckDocumentSweepEligible(
796+
candidate('pending', {
797+
processingQueuedAt: minutesBefore(90),
798+
processingStartedAt: minutesBefore(60 * 48),
799+
uploadedAt: minutesBefore(60 * 72),
800+
}),
801+
now
802+
)
803+
).toBe(false)
804+
})
805+
806+
it('gives a document whose content was just updated the full grace period', () => {
807+
expect(
808+
isStuckDocumentSweepEligible(
809+
candidate('pending', {
810+
processingQueuedAt: null,
811+
processingStartedAt: minutesBefore(60 * 48),
812+
uploadedAt: minutesBefore(5),
813+
}),
814+
now
815+
)
816+
).toBe(false)
817+
})
818+
819+
it('never reclaims a completed document', () => {
820+
expect(
821+
isStuckDocumentSweepEligible(
822+
candidate('completed', { uploadedAt: minutesBefore(60 * 48) }),
823+
now
824+
)
825+
).toBe(false)
826+
})
827+
})

apps/sim/lib/knowledge/connectors/sync-engine.ts

Lines changed: 111 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -10,7 +10,7 @@ import { createLogger } from '@sim/logger'
1010
import { getErrorMessage, toError } from '@sim/utils/errors'
1111
import { generateId } from '@sim/utils/id'
1212
import { randomInt } from '@sim/utils/random'
13-
import { and, desc, eq, gt, inArray, isNotNull, isNull, lt, ne, or, sql } from 'drizzle-orm'
13+
import { and, desc, eq, gt, inArray, isNotNull, isNull, lt, ne, sql } from 'drizzle-orm'
1414
import { decryptApiKey } from '@/lib/api-key/crypto'
1515
import {
1616
assertBillingAttributionSnapshot,
@@ -58,9 +58,91 @@ const CONTENT_INFLIGHT_BUDGET_BYTES = 64 * 1024 * 1024
5858
const MAX_PAGES = 500
5959
const MAX_SAFE_TITLE_LENGTH = 200
6060
const STALE_PROCESSING_MINUTES = 45
61+
/**
62+
* Grace period a document that is merely *queued* gets before the stuck-document
63+
* sweep may reclaim it.
64+
*
65+
* `STALE_PROCESSING_MINUTES` bounds a run that has already begun — `maxDuration`
66+
* (10m) x `maxAttempts` (3) on `knowledge-process-document` is 30 minutes, so 45
67+
* covers it with headroom. Queue *wait* is a different quantity: it is
68+
* backlog / concurrency, not run duration. `document-processing-queue` has a
69+
* global `concurrencyLimit` of 20 shared by every workspace, and a single large
70+
* connector corpus is on the order of the 2,600-document site
71+
* `CONNECTOR_SYNC_MAX_DURATION_SECONDS` was raised for — 130 waves of 20, which
72+
* at roughly a minute of occupancy per document drains in about two hours, and
73+
* longer while other workspaces hold slots. Four hours is about twice that
74+
* drain, an order of magnitude above the one-hour sync ceiling, and still well
75+
* under the 1,440-minute default sync interval, so a default-configured
76+
* connector waits no longer for recovery than it already did.
77+
*/
78+
const QUEUED_DISPATCH_GRACE_MINUTES = 240
6179
const RETRY_WINDOW_DAYS = 7
6280
const MAX_CONSECUTIVE_FAILURES = 10
6381

82+
/** The processing state the stuck-document sweep decides on, one row at a time. */
83+
export interface StuckDocumentSweepCandidate {
84+
processingStatus: string
85+
processingQueuedAt: Date | null
86+
processingStartedAt: Date | null
87+
uploadedAt: Date
88+
}
89+
90+
/**
91+
* Decides whether the sweep may reclaim one document — delete its embeddings,
92+
* reset it, and dispatch it again.
93+
*
94+
* Since document processing is dispatched to `knowledge-process-document`
95+
* rather than awaited inline, a document sits at `pending` from dispatch until
96+
* a worker claims it; `processing` is only written once a worker has actually
97+
* started. Reclaiming a `pending` document therefore risks racing a run that is
98+
* still queued, which both duplicates its work and bills a second indexing
99+
* pass, so queued documents get {@link QUEUED_DISPATCH_GRACE_MINUTES} before
100+
* they are considered lost.
101+
*
102+
* Queue wait is measured from `processingQueuedAt`, written by every path that
103+
* re-dispatches an existing document — this sweep and the user-facing retry.
104+
* It falls back to `uploadedAt` when NULL, which covers a document dispatched
105+
* by the sync that created it (`uploadedAt` then sits within that sync's own
106+
* runtime, an over-estimate bounded by the one-hour sync ceiling) and rows
107+
* written before the column existed.
108+
*
109+
* `failed` gets no grace. It is a terminal state: the run that produced it has
110+
* ended, so re-dispatching cannot duplicate live work, and it is the state the
111+
* user-facing retry path also operates from.
112+
*
113+
* This narrows the duplicate-dispatch window; it cannot close it. A grace
114+
* period is a timing guarantee, and no timing guarantee is a correctness one:
115+
* a document queued for longer than the grace is still reclaimed while its
116+
* original run waits, and Trigger.dev will not deduplicate the second dispatch
117+
* because the idempotency key `processDocumentsWithQueue` uses is
118+
* `doc-process-<documentId>-<requestId>` with a fresh `requestId` per dispatch
119+
* — scoped per dispatch by design, so it blocks intra-dispatch retries and
120+
* nothing else. Each duplicate run mints its own indexing pass and bills for
121+
* it, which is the double-billing `451d2ccbde` closed for the inline path.
122+
* Closing it durably needs state, not timing: a document-scoped idempotency
123+
* key, or a dispatch-generation column the worker carries and checks before
124+
* indexing, so a superseded run declines to bill. That is a larger change than
125+
* this hotfix.
126+
*/
127+
export function isStuckDocumentSweepEligible(doc: StuckDocumentSweepCandidate, now: Date): boolean {
128+
switch (doc.processingStatus) {
129+
case 'failed':
130+
return true
131+
case 'pending': {
132+
const queuedAt = doc.processingQueuedAt ?? doc.uploadedAt
133+
return now.getTime() - queuedAt.getTime() > QUEUED_DISPATCH_GRACE_MINUTES * 60 * 1000
134+
}
135+
case 'processing': {
136+
if (!doc.processingStartedAt) return true
137+
return (
138+
now.getTime() - doc.processingStartedAt.getTime() > STALE_PROCESSING_MINUTES * 60 * 1000
139+
)
140+
}
141+
default:
142+
return false
143+
}
144+
}
145+
64146
/** Sanitizes a document title for use in S3 storage keys. */
65147
function sanitizeStorageTitle(title: string): string {
66148
return title.replace(/[^a-zA-Z0-9.-]/g, '_').slice(0, MAX_SAFE_TITLE_LENGTH)
@@ -1368,45 +1450,47 @@ export async function executeSync(
13681450
throw new Error(`Knowledge base ${connector.knowledgeBaseId} was deleted during sync`)
13691451
}
13701452

1371-
// Retry stuck documents that failed, never started, or were abandoned mid-processing.
1372-
// Only retry docs uploaded BEFORE this sync — docs added in the current sync
1373-
// are still processing asynchronously and would cause a duplicate processing race.
1374-
// Documents stuck in 'processing' beyond STALE_PROCESSING_MINUTES are considered
1375-
// abandoned (e.g. the Trigger.dev task process exited before processing completed).
1376-
// Documents uploaded more than RETRY_WINDOW_DAYS ago are not retried.
1377-
const staleProcessingCutoff = new Date(Date.now() - STALE_PROCESSING_MINUTES * 60 * 1000)
1378-
const stuckDocs = await db
1453+
/**
1454+
* Reclaims documents this connector left unfinished: a terminated attempt, a
1455+
* dispatch that never produced a run, or a run abandoned mid-processing.
1456+
*
1457+
* The query narrows to this connector's non-terminal documents inside the
1458+
* `RETRY_WINDOW_DAYS` window and excludes anything created by this sync;
1459+
* {@link isStuckDocumentSweepEligible} then makes the per-document decision,
1460+
* so the age rules live in one place rather than being split between SQL and
1461+
* TypeScript. Skipped (oversized) documents are recorded as content-less
1462+
* `failed` rows with no storage key and can never be reprocessed, so they are
1463+
* excluded outright.
1464+
*/
1465+
const sweepEvaluatedAt = new Date()
1466+
const sweepCandidates = await db
13791467
.select({
13801468
id: document.id,
13811469
fileUrl: document.fileUrl,
13821470
filename: document.filename,
13831471
fileSize: document.fileSize,
13841472
mimeType: document.mimeType,
1473+
processingStatus: document.processingStatus,
1474+
processingQueuedAt: document.processingQueuedAt,
1475+
processingStartedAt: document.processingStartedAt,
1476+
uploadedAt: document.uploadedAt,
13851477
})
13861478
.from(document)
13871479
.where(
13881480
and(
13891481
eq(document.connectorId, connectorId),
1390-
or(
1391-
inArray(document.processingStatus, ['pending', 'failed']),
1392-
and(
1393-
eq(document.processingStatus, 'processing'),
1394-
or(
1395-
isNull(document.processingStartedAt),
1396-
lt(document.processingStartedAt, staleProcessingCutoff)
1397-
)
1398-
)
1399-
),
1482+
inArray(document.processingStatus, ['pending', 'failed', 'processing']),
14001483
lt(document.uploadedAt, syncStartedAt),
14011484
gt(document.uploadedAt, retryCutoff),
14021485
eq(document.userExcluded, false),
1403-
// Skipped (oversized) docs are recorded as content-less failed rows with no
1404-
// storage key; they cannot be reprocessed, so exclude them from retry.
14051486
isNotNull(document.storageKey),
14061487
isNull(document.archivedAt),
14071488
isNull(document.deletedAt)
14081489
)
14091490
)
1491+
const stuckDocs = sweepCandidates.filter((doc) =>
1492+
isStuckDocumentSweepEligible(doc, sweepEvaluatedAt)
1493+
)
14101494

14111495
if (stuckDocs.length > 0) {
14121496
logger.info(`Retrying ${stuckDocs.length} stuck documents`, { connectorId })
@@ -1451,6 +1535,12 @@ export async function executeSync(
14511535
.update(document)
14521536
.set({
14531537
processingStatus: 'pending',
1538+
/**
1539+
* Records when this re-dispatch was queued, so a later sweep can
1540+
* tell a document still waiting for a worker from one whose
1541+
* dispatch was lost. See {@link isStuckDocumentSweepEligible}.
1542+
*/
1543+
processingQueuedAt: sweepEvaluatedAt,
14541544
processingStartedAt: null,
14551545
processingCompletedAt: null,
14561546
processingError: null,

0 commit comments

Comments
 (0)