Skip to content

Commit 8383208

Browse files
committed
fix(knowledge): give failed documents a grace while their retries are still scheduled
The sweep treats failed as terminal — "the run that produced it has ended" — and that was true when processing ran inline. Since dispatch became asynchronous the worker writes failed and then rethrows, and the processing task retries up to three times, so failed is a resting state between attempts rather than a final one. The sweep gave it no grace at all, so it reclaimed a document mid-retry chain, deleted its embeddings, and re-dispatched with a fresh pass id: two live runs, two indexing passes, two bills, through the one state deliberately left unguarded. Aged from processingCompletedAt, which every failure write stamps, so it reads exactly when the last attempt ended rather than when the document was dispatched. Sized at the queue grace rather than a run-duration bound. What is being waited on between attempts is a re-queue behind the same global concurrency limit, not another run, so on a large backlog the next attempt starts hours after the previous one ended and a run-duration bound would still reclaim live work. The grace itself is now an expression rather than a constant — corpus over queue concurrency, times occupancy, times a contention factor — with each input documented where it can be re-measured. The previous 240 was derived from a 2,600-document corpus and sat below the drain time of the 7,730-document connector it was written for. Rounding is up: too small silently re-bills live work, too large only delays recovery of documents nothing is processing. Also withdraws the queue stamp when every dispatch in a batch fails, so a provably-undispatched document keeps next-sync recovery instead of waiting out a grace it never earned. Scoped to the batch's own ids, to rows still pending, and by compare-and-set on the exact stamp that call wrote, so a concurrent batch that re-stamped a document keeps its grace. Best-effort by design, while the stamp write still throws: a failed stamp means the grace cannot be promised and dispatching anyway is the unsafe direction, whereas a failed withdrawal only delays recovery and must not mask the dispatch error underneath it.
1 parent 1ced0b6 commit 8383208

4 files changed

Lines changed: 208 additions & 41 deletions

File tree

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

Lines changed: 72 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -713,26 +713,38 @@ describe('isStuckDocumentSweepEligible', () => {
713713
overrides: {
714714
processingQueuedAt?: Date | null
715715
processingStartedAt?: Date | null
716+
processingCompletedAt?: Date | null
716717
uploadedAt?: Date
717718
} = {}
718719
) => ({
719720
processingStatus,
720721
processingQueuedAt: overrides.processingQueuedAt ?? null,
721722
processingStartedAt: overrides.processingStartedAt ?? null,
723+
processingCompletedAt: overrides.processingCompletedAt ?? null,
722724
uploadedAt: overrides.uploadedAt ?? minutesBefore(5),
723725
})
724726

727+
/**
728+
* Pinned to the derivation in sync-engine (corpus 7,730 / concurrency 20 x
729+
* 1 minute occupancy x 2 contention). A change to any input should fail here
730+
* so it is re-checked deliberately rather than absorbed silently.
731+
*/
732+
const GRACE_MINUTES = 773
733+
725734
it('leaves a document dispatched by the previous sync and still queued alone', () => {
726735
expect(
727-
isStuckDocumentSweepEligible(candidate('pending', { uploadedAt: minutesBefore(90) }), now)
736+
isStuckDocumentSweepEligible(
737+
candidate('pending', { uploadedAt: minutesBefore(GRACE_MINUTES - 1) }),
738+
now
739+
)
728740
).toBe(false)
729741
})
730742

731743
it('leaves a document the sweep itself re-dispatched alone while it waits', () => {
732744
expect(
733745
isStuckDocumentSweepEligible(
734746
candidate('pending', {
735-
processingQueuedAt: minutesBefore(90),
747+
processingQueuedAt: minutesBefore(GRACE_MINUTES - 1),
736748
uploadedAt: minutesBefore(60 * 48),
737749
}),
738750
now
@@ -742,12 +754,15 @@ describe('isStuckDocumentSweepEligible', () => {
742754

743755
it('reclaims a queued document once the grace period has passed', () => {
744756
expect(
745-
isStuckDocumentSweepEligible(candidate('pending', { uploadedAt: minutesBefore(241) }), now)
757+
isStuckDocumentSweepEligible(
758+
candidate('pending', { uploadedAt: minutesBefore(GRACE_MINUTES + 1) }),
759+
now
760+
)
746761
).toBe(true)
747762
expect(
748763
isStuckDocumentSweepEligible(
749764
candidate('pending', {
750-
processingQueuedAt: minutesBefore(241),
765+
processingQueuedAt: minutesBefore(GRACE_MINUTES + 1),
751766
uploadedAt: minutesBefore(60 * 48),
752767
}),
753768
now
@@ -757,15 +772,63 @@ describe('isStuckDocumentSweepEligible', () => {
757772

758773
it('holds a queued document at the grace boundary', () => {
759774
expect(
760-
isStuckDocumentSweepEligible(candidate('pending', { uploadedAt: minutesBefore(240) }), now)
775+
isStuckDocumentSweepEligible(
776+
candidate('pending', { uploadedAt: minutesBefore(GRACE_MINUTES) }),
777+
now
778+
)
779+
).toBe(false)
780+
})
781+
782+
it('leaves a failed document alone while its Trigger retries may still run', () => {
783+
expect(
784+
isStuckDocumentSweepEligible(
785+
candidate('failed', { processingCompletedAt: minutesBefore(1) }),
786+
now
787+
)
761788
).toBe(false)
762789
})
763790

764-
it('reclaims a failed document with no grace', () => {
765-
expect(isStuckDocumentSweepEligible(candidate('failed'), now)).toBe(true)
791+
it('ages a failed document from its last attempt, not from its dispatch', () => {
792+
expect(
793+
isStuckDocumentSweepEligible(
794+
candidate('failed', {
795+
processingQueuedAt: minutesBefore(60 * 48),
796+
processingCompletedAt: minutesBefore(1),
797+
uploadedAt: minutesBefore(60 * 72),
798+
}),
799+
now
800+
)
801+
).toBe(false)
802+
})
803+
804+
it('reclaims a failed document once no retry of it can still be live', () => {
805+
expect(
806+
isStuckDocumentSweepEligible(
807+
candidate('failed', { processingCompletedAt: minutesBefore(GRACE_MINUTES + 1) }),
808+
now
809+
)
810+
).toBe(true)
811+
})
812+
813+
it('holds a failed document at the grace boundary', () => {
814+
expect(
815+
isStuckDocumentSweepEligible(
816+
candidate('failed', { processingCompletedAt: minutesBefore(GRACE_MINUTES) }),
817+
now
818+
)
819+
).toBe(false)
820+
})
821+
822+
it('falls back to the dispatch stamp when a failed row never recorded completion', () => {
823+
expect(
824+
isStuckDocumentSweepEligible(
825+
candidate('failed', { processingQueuedAt: minutesBefore(1), uploadedAt: minutesBefore(1) }),
826+
now
827+
)
828+
).toBe(false)
766829
expect(
767830
isStuckDocumentSweepEligible(
768-
candidate('failed', { processingStartedAt: minutesBefore(1) }),
831+
candidate('failed', { processingQueuedAt: minutesBefore(GRACE_MINUTES + 1) }),
769832
now
770833
)
771834
).toBe(true)
@@ -794,7 +857,7 @@ describe('isStuckDocumentSweepEligible', () => {
794857
expect(
795858
isStuckDocumentSweepEligible(
796859
candidate('pending', {
797-
processingQueuedAt: minutesBefore(90),
860+
processingQueuedAt: minutesBefore(GRACE_MINUTES - 1),
798861
processingStartedAt: minutesBefore(60 * 48),
799862
uploadedAt: minutesBefore(60 * 72),
800863
}),

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

Lines changed: 58 additions & 26 deletions
Original file line numberDiff line numberDiff line change
@@ -58,24 +58,37 @@ 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+
/** Largest connector corpus observed in production, which sets the queue drain to beat. */
62+
const LARGEST_OBSERVED_CORPUS_DOCUMENTS = 7_730
63+
/** `document-processing-queue`'s `concurrencyLimit` — global, shared by every workspace. */
64+
const PROCESSING_QUEUE_CONCURRENCY = 20
65+
/** Wall time a typical document occupies a queue slot, parse through embedding. */
66+
const TYPICAL_DOCUMENT_OCCUPANCY_MINUTES = 1
67+
/** Headroom for the queue being shared: another tenant's backlog cuts our share of it. */
68+
const QUEUE_CONTENTION_FACTOR = 2
6169
/**
62-
* Grace period a document that is merely *queued* gets before the stuck-document
63-
* sweep may reclaim it.
70+
* Grace period a document waiting on the processing queue gets before the
71+
* stuck-document sweep may reclaim it.
6472
*
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.
73+
* Derived rather than chosen, so the next person can re-run the arithmetic with
74+
* their own numbers instead of trusting this one: the sweep must not reclaim a
75+
* document that a full queue drain has simply not reached yet, so the grace is
76+
* that drain — corpus / concurrency x per-document occupancy — times a
77+
* contention factor for the queue being shared across workspaces. At the values
78+
* above that is 7,730 / 20 x 1 x 2 = 773 minutes, just under thirteen hours.
79+
*
80+
* Each input is measurable and should be re-measured when it moves: corpus size
81+
* from the largest connector in production, concurrency from
82+
* `knowledge-process-document`'s queue config, occupancy from run durations.
83+
* Note the failure mode is asymmetric — too small silently re-bills live work,
84+
* too large only delays recovery of documents nothing is processing — so round
85+
* up, never down.
7786
*/
78-
const QUEUED_DISPATCH_GRACE_MINUTES = 240
87+
const QUEUED_DISPATCH_GRACE_MINUTES = Math.ceil(
88+
(LARGEST_OBSERVED_CORPUS_DOCUMENTS / PROCESSING_QUEUE_CONCURRENCY) *
89+
TYPICAL_DOCUMENT_OCCUPANCY_MINUTES *
90+
QUEUE_CONTENTION_FACTOR
91+
)
7992
const RETRY_WINDOW_DAYS = 7
8093
const MAX_CONSECUTIVE_FAILURES = 10
8194

@@ -84,6 +97,7 @@ export interface StuckDocumentSweepCandidate {
8497
processingStatus: string
8598
processingQueuedAt: Date | null
8699
processingStartedAt: Date | null
100+
processingCompletedAt: Date | null
87101
uploadedAt: Date
88102
}
89103

@@ -99,16 +113,28 @@ export interface StuckDocumentSweepCandidate {
99113
* pass, so queued documents get {@link QUEUED_DISPATCH_GRACE_MINUTES} before
100114
* they are considered lost.
101115
*
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.
116+
* Queue wait is measured from `processingQueuedAt`, stamped by
117+
* `processDocumentsWithQueue` — the funnel every dispatch passes through — so
118+
* no caller can dispatch without recording when. It falls back to `uploadedAt`
119+
* when NULL, which covers rows written before the column existed.
120+
*
121+
* `failed` is not a terminal state and gets the same grace. `processDocumentAsync`
122+
* records the failure and then rethrows, so `knowledge-process-document` retries
123+
* it up to `maxAttempts` (3): between attempts the row reads `failed` while a
124+
* live run is scheduled to pick it up again. The gap between attempts is bounded
125+
* by the queue, not by run duration — a retried run re-enters the same queue
126+
* behind the same global concurrency limit — so `maxDuration` x `maxAttempts`
127+
* (30 minutes) and `STALE_PROCESSING_MINUTES` are both far too short to be safe
128+
* here: on the very backlog this grace exists for, the next attempt starts hours
129+
* after the last one ended. `failed` is therefore aged from
130+
* `processingCompletedAt`, the instant the last attempt ended, which every
131+
* failure write stamps.
108132
*
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.
133+
* A document whose retries genuinely exhaust is still recovered: its final
134+
* failure stops moving `processingCompletedAt`, so one grace later it becomes
135+
* eligible and the next sync re-dispatches it. Recovery is delayed by the grace,
136+
* never lost. The user-facing retry stays immediate — it writes `pending` and
137+
* dispatches without consulting the sweep at all.
112138
*
113139
* This narrows the duplicate-dispatch window; it cannot close it. A grace
114140
* period is a timing guarantee, and no timing guarantee is a correctness one:
@@ -126,8 +152,13 @@ export interface StuckDocumentSweepCandidate {
126152
*/
127153
export function isStuckDocumentSweepEligible(doc: StuckDocumentSweepCandidate, now: Date): boolean {
128154
switch (doc.processingStatus) {
129-
case 'failed':
130-
return true
155+
case 'failed': {
156+
const lastAttemptEndedAt =
157+
doc.processingCompletedAt ?? doc.processingQueuedAt ?? doc.uploadedAt
158+
return (
159+
now.getTime() - lastAttemptEndedAt.getTime() > QUEUED_DISPATCH_GRACE_MINUTES * 60 * 1000
160+
)
161+
}
131162
case 'pending': {
132163
const queuedAt = doc.processingQueuedAt ?? doc.uploadedAt
133164
return now.getTime() - queuedAt.getTime() > QUEUED_DISPATCH_GRACE_MINUTES * 60 * 1000
@@ -1473,6 +1504,7 @@ export async function executeSync(
14731504
processingStatus: document.processingStatus,
14741505
processingQueuedAt: document.processingQueuedAt,
14751506
processingStartedAt: document.processingStartedAt,
1507+
processingCompletedAt: document.processingCompletedAt,
14761508
uploadedAt: document.uploadedAt,
14771509
})
14781510
.from(document)

apps/sim/lib/knowledge/documents/retry-processing-grace.test.ts

Lines changed: 32 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,7 @@
11
/**
22
* @vitest-environment node
33
*/
4-
import { dbChainMock, dbChainMockFns, resetDbChainMock } from '@sim/testing'
4+
import { dbChainMock, dbChainMockFns, flattenMockConditions, resetDbChainMock } from '@sim/testing'
55
import { beforeEach, describe, expect, it, vi } from 'vitest'
66

77
vi.mock('@sim/db', () => dbChainMock)
@@ -74,6 +74,7 @@ describe('retryDocumentProcessing requeue stamp', () => {
7474
processingStatus: values.processingStatus as string,
7575
processingQueuedAt: values.processingQueuedAt as Date | null,
7676
processingStartedAt: values.processingStartedAt as Date | null,
77+
processingCompletedAt: values.processingCompletedAt as Date | null,
7778
uploadedAt,
7879
},
7980
sweptAt
@@ -86,6 +87,7 @@ describe('retryDocumentProcessing requeue stamp', () => {
8687
processingStatus: 'pending',
8788
processingQueuedAt: null,
8889
processingStartedAt: null,
90+
processingCompletedAt: null,
8991
uploadedAt,
9092
},
9193
sweptAt
@@ -121,7 +123,7 @@ describe('processDocumentsWithQueue dispatch stamp', () => {
121123
const after = Date.now()
122124

123125
const stampCall = dbChainMockFns.set.mock.calls.find(
124-
(call) => (call[0] as Record<string, unknown> | undefined)?.processingQueuedAt !== undefined
126+
(call) => (call[0] as Record<string, unknown> | undefined)?.processingQueuedAt instanceof Date
125127
)
126128
expect(stampCall).toBeDefined()
127129
const values = stampCall?.[0] as Record<string, unknown>
@@ -132,4 +134,32 @@ describe('processDocumentsWithQueue dispatch stamp', () => {
132134
expect(stamp.getTime()).toBeLessThanOrEqual(after)
133135
expect(values.processingStartedAt).toBeNull()
134136
})
137+
138+
it('withdraws the stamp when every dispatch fails', async () => {
139+
await dispatch()
140+
141+
const withdrawal = dbChainMockFns.set.mock.calls.find(
142+
(call) => (call[0] as Record<string, unknown> | undefined)?.processingQueuedAt === null
143+
)
144+
expect(withdrawal).toBeDefined()
145+
})
146+
147+
it('scopes the withdrawal to this batch, to pending rows, and to its own stamp', async () => {
148+
await dispatch()
149+
150+
const stampCall = dbChainMockFns.set.mock.calls.find(
151+
(call) => (call[0] as Record<string, unknown> | undefined)?.processingQueuedAt instanceof Date
152+
)
153+
const stamp = (stampCall?.[0] as Record<string, unknown>).processingQueuedAt as Date
154+
155+
const scoped = dbChainMockFns.where.mock.calls.some((call) => {
156+
const nodes = flattenMockConditions(call[0])
157+
return (
158+
nodes.some((node) => node.type === 'inArray' && Array.isArray(node.values)) &&
159+
nodes.some((node) => node.type === 'eq' && node.right === 'pending') &&
160+
nodes.some((node) => node.type === 'eq' && node.right === stamp)
161+
)
162+
})
163+
expect(scoped).toBe(true)
164+
})
135165
})

apps/sim/lib/knowledge/documents/service.ts

Lines changed: 46 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -706,6 +706,36 @@ async function markDocumentsQueued(documentIds: string[], queuedAt: Date): Promi
706706
.where(and(inArray(document.id, documentIds), eq(document.processingStatus, 'pending')))
707707
}
708708

709+
/**
710+
* Withdraws a queue stamp whose dispatch provably never happened.
711+
*
712+
* {@link markDocumentsQueued} runs before dispatch on purpose — `batchTrigger`
713+
* chunks, so a batch can half-succeed, and stamping afterwards would leave the
714+
* runs that did start with no stamp and no grace. The cost of that ordering is
715+
* that a batch where *every* dispatch failed still carries a fresh stamp, and
716+
* recovery sweeps would honour a grace period the documents did not earn. Total
717+
* failure is the one case where nothing was dispatched, so the stamp can be
718+
* taken back and the next sweep is free to reclaim them immediately.
719+
*
720+
* Scoped three ways so it can only ever undo its own write: to the ids in this
721+
* batch, to rows still `pending` (a worker that has since claimed one keeps its
722+
* timestamps — see {@link markDocumentsQueued}), and to the exact stamp this
723+
* call wrote, so a concurrent dispatch that has already re-stamped a document
724+
* is left alone.
725+
*/
726+
async function clearDocumentsQueued(documentIds: string[], queuedAt: Date): Promise<void> {
727+
await db
728+
.update(document)
729+
.set({ processingQueuedAt: null })
730+
.where(
731+
and(
732+
inArray(document.id, documentIds),
733+
eq(document.processingStatus, 'pending'),
734+
eq(document.processingQueuedAt, queuedAt)
735+
)
736+
)
737+
}
738+
709739
/**
710740
* Dispatches document processing jobs via Trigger.dev's `batchTrigger` when
711741
* available, or in-process otherwise. Throws only when every dispatch fails;
@@ -728,10 +758,9 @@ export async function processDocumentsWithQueue(
728758
buildJobPayload(doc, knowledgeBaseId, processingOptions, requestId, billingContext)
729759
)
730760

731-
await markDocumentsQueued(
732-
createdDocuments.map((doc) => doc.documentId),
733-
new Date()
734-
)
761+
const documentIds = createdDocuments.map((doc) => doc.documentId)
762+
const queuedAt = new Date()
763+
await markDocumentsQueued(documentIds, queuedAt)
735764

736765
const useTrigger = isTriggerAvailable()
737766
logger.info(
@@ -748,6 +777,19 @@ export async function processDocumentsWithQueue(
748777
)
749778

750779
if (dispatched === 0) {
780+
/**
781+
* Best-effort, unlike the stamp itself: failing to write the stamp means the
782+
* grace cannot be promised and dispatching anyway is the unsafe direction, so
783+
* that write throws. Failing to withdraw one only delays recovery by a grace
784+
* period, so it must not mask the dispatch failure that is the real error.
785+
*/
786+
try {
787+
await clearDocumentsQueued(documentIds, queuedAt)
788+
} catch (error) {
789+
logger.warn(`[${requestId}] Failed to withdraw the queue stamp after a failed dispatch`, {
790+
error: getErrorMessage(error),
791+
})
792+
}
751793
throw new Error(`All ${jobPayloads.length} document processing dispatches failed`)
752794
}
753795
}

0 commit comments

Comments
 (0)