From 8d26f9ba8efd511a04228c002059db94b412ef83 Mon Sep 17 00:00:00 2001 From: Danny Avila Date: Fri, 4 Sep 2026 13:02:47 -0400 Subject: [PATCH] =?UTF-8?q?=F0=9F=A7=AF=20fix:=20Keep=20the=20give-up=20no?= =?UTF-8?q?tice=20and=20the=20retry=20budget=20honest?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Four findings from the review of ee1bac5. - The give-up was reported after the deferral write, inside the same catch. Once the increment lands the counter is durable, so `getExpiredFiles` already excludes the file; a deferral that then failed left only the generic recording error and dropped the one line naming the file and saying how to resume. Report it as soon as the increment returns, and let the deferral fail on its own. - Retry deadlines were measured from `Date.now()` after the deletion I/O, but `startExpiredFileSweep` arms its interval before the sweep runs. A one-interval delay therefore expired just *after* the next scheduled pass, which skipped the file and pushed its first retry out by a whole extra interval — and the same drift applied to every delay that is an exact multiple. Anchor deadlines to the sweep's start instead. - The threshold used `>=`, so once two nodes pushed a file past the cap every one of them past it logged the give-up: one error per replica per exhausted file rather than one actionable notice. Only the attempt that lands exactly on the cap reports it. - Retry state outlived the content it described. `processCodeOutput` reuses a record for a repeated `(filename, conversationId)` — new bytes, new storage key, and a fresh `expiredAt` from `getRetentionExpiry` — while `createFile` and `updateFile` set only supplied fields. A record carried to the cap by its previous content stayed excluded from the sweep forever, stranding the new object exactly as this PR set out to prevent; a partially failed one started the new object's budget already spent. Both write paths now clear the fields: the budget belongs to the storage a record currently points at. The retry-state fixtures in `file.spec.ts` were seeded through `createFile`, which now clears them, so they drive the real methods the sweep uses. --- packages/api/src/files/sweep.spec.ts | 64 ++++++++ packages/api/src/files/sweep.ts | 35 +++-- .../data-schemas/src/methods/file.spec.ts | 146 +++++++++++------- packages/data-schemas/src/methods/file.ts | 21 ++- 4 files changed, 193 insertions(+), 73 deletions(-) diff --git a/packages/api/src/files/sweep.spec.ts b/packages/api/src/files/sweep.spec.ts index 96b37fb1ce..9eaea0db0e 100644 --- a/packages/api/src/files/sweep.spec.ts +++ b/packages/api/src/files/sweep.spec.ts @@ -155,6 +155,7 @@ describe('expired file sweep helpers', () => { it('reports giving up once the file reaches the attempt cap', async () => { process.env.FILE_RETENTION_SWEEP_MAX_ATTEMPTS = '3'; attemptCount = 2; + deferExpiredFile.mockRejectedValue(new Error('mongo unreachable')); const getExpiredFiles = jest .fn() .mockResolvedValue([{ file_id: 'stranded-file', user: 'user-1' }]); @@ -174,11 +175,74 @@ describe('expired file sweep helpers', () => { ); expect(getExpiredFiles).toHaveBeenCalledWith(1, { maxAttempts: 3 }); + /* The counter is durable once the increment lands, so the file is + * already excluded; a deferral that fails afterwards must not swallow + * the only notice of that. */ expect(logger.error).toHaveBeenCalledWith( expect.stringContaining('Giving up on expired file stranded-file after 3 failed deletions'), ); }); + it('reports the cap once, on the attempt that reaches it', async () => { + process.env.FILE_RETENTION_SWEEP_MAX_ATTEMPTS = '3'; + attemptCount = 2; + const getExpiredFiles = jest.fn().mockResolvedValue([ + { file_id: 'stranded-file', user: 'user-1' }, + { file_id: 'stranded-file', user: 'user-1' }, + ]); + const processDeleteRequest = jest + .fn() + .mockResolvedValue({ deletedFileIds: [], failedFileIds: ['stranded-file'] }); + + await sweepExpiredFiles( + { appConfig: {} as AppConfig, limit: 2 }, + { + getExpiredFiles, + processDeleteRequest, + incrementFileDeletionAttempts, + deferExpiredFile, + logger, + }, + ); + + /* Increments returned 3 and 4. Only the one that landed on the cap + * reports it — another node past the threshold would otherwise repeat + * the notice once per replica, per file. */ + const givingUp = logger.error.mock.calls.filter(([message]) => + String(message).includes('Giving up on expired file'), + ); + expect(givingUp).toHaveLength(1); + }); + + it('anchors retry deadlines to the start of the sweep', async () => { + const getExpiredFiles = jest.fn().mockImplementation(async () => { + /* Deletion I/O pushes wall-clock past the sweep's start. Measuring + * the deadline from here would land it just after the next scheduled + * pass, costing the file a whole extra interval. */ + jest.setSystemTime(Date.now() + 30_000); + return [{ file_id: 'stuck-file', user: 'user-1' }]; + }); + const processDeleteRequest = jest + .fn() + .mockResolvedValue({ deletedFileIds: [], failedFileIds: ['stuck-file'] }); + + jest.useFakeTimers(); + const sweepStartedAt = Date.now(); + await sweepExpiredFiles( + { appConfig: {} as AppConfig, limit: 1 }, + { + getExpiredFiles, + processDeleteRequest, + incrementFileDeletionAttempts, + deferExpiredFile, + logger, + }, + ); + + const [, retryAt] = deferExpiredFile.mock.calls[0]; + expect(retryAt.getTime()).toBe(sweepStartedAt + 60 * 60 * 1000); + }); + it('keeps sweeping the batch when recording a failure fails', async () => { const getExpiredFiles = jest.fn().mockResolvedValue([ { file_id: 'stuck-file', user: 'user-1' }, diff --git a/packages/api/src/files/sweep.ts b/packages/api/src/files/sweep.ts index 75dbd6e543..99c8f87910 100644 --- a/packages/api/src/files/sweep.ts +++ b/packages/api/src/files/sweep.ts @@ -264,6 +264,11 @@ export async function sweepExpiredFiles( }: SweepDependencies, ): Promise { const maxAttempts = getFileRetentionMaxAttempts(); + /* Deadlines are anchored here rather than at the moment of failure. The + * interval timer is armed before the sweep runs, so a deadline measured + * after the deletion I/O lands just past the next scheduled pass and the + * file waits a whole extra interval. */ + const sweepStartedAt = Date.now(); const files = (await getExpiredFiles(limit, { maxAttempts })) ?? []; let resolvedAppConfig = appConfig; let deleted = 0; @@ -279,13 +284,8 @@ export async function sweepExpiredFiles( try { /* The attempt number comes from the increment rather than from the * snapshot this batch queried, so two nodes sweeping the same file - * each get a distinct one and exactly one of them observes the cap - * being reached. */ + * each get a distinct one. */ attempts = await incrementFileDeletionAttempts(file.file_id); - await deferExpiredFile( - file.file_id, - new Date(Date.now() + getExpiredFileRetryDelay(attempts)), - ); } catch (error) { logger.error( `[sweepExpiredFiles] Error recording failed deletion of expired file ${file.file_id}:`, @@ -294,12 +294,25 @@ export async function sweepExpiredFiles( return; } - if (attempts < maxAttempts) { - return; + /* Reported before the deferral, which fails independently. The counter + * is already durable, so the file is already excluded from the query + * and this line is the only notice the exclusion ever gets. Exactly the + * attempt that lands on the cap reports it — `>=` would have every + * later node past the threshold repeat it. */ + if (attempts === maxAttempts) { + logger.error( + `[sweepExpiredFiles] Giving up on expired file ${file.file_id} after ${attempts} failed deletions. Its backing storage was not removed; the record is kept so the reference survives for reconciliation. Raise FILE_RETENTION_SWEEP_MAX_ATTEMPTS to retry it.`, + ); + } + + try { + await deferExpiredFile( + file.file_id, + new Date(sweepStartedAt + getExpiredFileRetryDelay(attempts)), + ); + } catch (error) { + logger.error(`[sweepExpiredFiles] Error deferring expired file ${file.file_id}:`, error); } - logger.error( - `[sweepExpiredFiles] Giving up on expired file ${file.file_id} after ${attempts} failed deletions. Its backing storage was not removed; the record is kept so the reference survives for reconciliation. Raise FILE_RETENTION_SWEEP_MAX_ATTEMPTS to retry it.`, - ); }; for (const file of files) { diff --git a/packages/data-schemas/src/methods/file.spec.ts b/packages/data-schemas/src/methods/file.spec.ts index ce885d671d..54778e8616 100644 --- a/packages/data-schemas/src/methods/file.spec.ts +++ b/packages/data-schemas/src/methods/file.spec.ts @@ -385,40 +385,56 @@ describe('File Methods', () => { expect(files.map((file) => file.file_id)).toEqual([expiredFileId]); }); + /** Seeds a sweep-eligible file, then drives its retry state through the + * same methods the sweep itself uses. */ + const seedExpiredFile = async ({ + file_id, + expiredAt, + attempts = 0, + retryAt, + }: { + file_id: string; + expiredAt: Date; + attempts?: number; + retryAt?: Date; + }) => { + await fileMethods.createFile( + { + file_id, + user: new mongoose.Types.ObjectId(), + filename: `${file_id}.txt`, + filepath: `/uploads/${file_id}.txt`, + type: 'text/plain', + bytes: 100, + expiredAt, + }, + true, + ); + for (let i = 0; i < attempts; i++) { + await fileMethods.incrementFileDeletionAttempts(file_id); + } + if (retryAt) { + await fileMethods.deferExpiredFile(file_id, retryAt); + } + }; + it('holds back files whose deletion backoff has not elapsed', async () => { - const userId = new mongoose.Types.ObjectId(); const now = new Date('2030-01-01T00:00:00.000Z'); const readyFileId = uuidv4(); const backedOffFileId = uuidv4(); - await fileMethods.createFile( - { - file_id: backedOffFileId, - user: userId, - filename: 'backed-off.txt', - filepath: '/uploads/backed-off.txt', - type: 'text/plain', - bytes: 100, - expiredAt: new Date('2029-12-01T00:00:00.000Z'), - deletionAttempts: 2, - deletionRetryAt: new Date('2030-01-01T00:00:01.000Z'), - }, - true, - ); - await fileMethods.createFile( - { - file_id: readyFileId, - user: userId, - filename: 'ready.txt', - filepath: '/uploads/ready.txt', - type: 'text/plain', - bytes: 100, - expiredAt: new Date('2029-12-31T00:00:00.000Z'), - deletionAttempts: 2, - deletionRetryAt: new Date('2029-12-31T23:00:00.000Z'), - }, - true, - ); + await seedExpiredFile({ + file_id: backedOffFileId, + expiredAt: new Date('2029-12-01T00:00:00.000Z'), + attempts: 2, + retryAt: new Date('2030-01-01T00:00:01.000Z'), + }); + await seedExpiredFile({ + file_id: readyFileId, + expiredAt: new Date('2029-12-31T00:00:00.000Z'), + attempts: 2, + retryAt: new Date('2029-12-31T23:00:00.000Z'), + }); const files = await fileMethods.getExpiredFiles(100, { now }); @@ -426,7 +442,6 @@ describe('File Methods', () => { }); it('drops files that reached the attempt cap so they cannot starve the batch', async () => { - const userId = new mongoose.Types.ObjectId(); const now = new Date('2030-01-01T00:00:00.000Z'); const exhaustedFileId = uuidv4(); const retriableFileId = uuidv4(); @@ -434,33 +449,17 @@ describe('File Methods', () => { /* The exhausted file expired first, so without the cap it sorts to * the front of every batch and a limit-sized run of them starves * everything that expired afterwards. */ - await fileMethods.createFile( - { - file_id: exhaustedFileId, - user: userId, - filename: 'exhausted.txt', - filepath: '/uploads/exhausted.txt', - type: 'text/plain', - bytes: 100, - expiredAt: new Date('2029-01-01T00:00:00.000Z'), - deletionAttempts: 10, - deletionRetryAt: new Date('2029-06-01T00:00:00.000Z'), - }, - true, - ); - await fileMethods.createFile( - { - file_id: retriableFileId, - user: userId, - filename: 'retriable.txt', - filepath: '/uploads/retriable.txt', - type: 'text/plain', - bytes: 100, - expiredAt: new Date('2029-12-31T00:00:00.000Z'), - deletionAttempts: 9, - }, - true, - ); + await seedExpiredFile({ + file_id: exhaustedFileId, + expiredAt: new Date('2029-01-01T00:00:00.000Z'), + attempts: 10, + retryAt: new Date('2029-06-01T00:00:00.000Z'), + }); + await seedExpiredFile({ + file_id: retriableFileId, + expiredAt: new Date('2029-12-31T00:00:00.000Z'), + attempts: 9, + }); const capped = await fileMethods.getExpiredFiles(100, { now, maxAttempts: 10 }); expect(capped.map((file) => file.file_id)).toEqual([retriableFileId]); @@ -468,6 +467,39 @@ describe('File Methods', () => { const raised = await fileMethods.getExpiredFiles(100, { now, maxAttempts: 20 }); expect(raised.map((file) => file.file_id)).toEqual([exhaustedFileId, retriableFileId]); }); + + it('restarts the retry budget when a record is repurposed for new content', async () => { + const now = new Date('2030-01-01T00:00:00.000Z'); + const fileId = uuidv4(); + await seedExpiredFile({ + file_id: fileId, + expiredAt: new Date('2029-01-01T00:00:00.000Z'), + attempts: 10, + retryAt: new Date('2029-06-01T00:00:00.000Z'), + }); + expect(await fileMethods.getExpiredFiles(100, { now, maxAttempts: 10 })).toHaveLength(0); + + /* A repeated (filename, conversationId) reuses the record for a new + * code output: new bytes, new storage key, fresh retention deadline. + * Carrying the exhausted budget over would strand that new object. */ + await fileMethods.createFile( + { + file_id: fileId, + user: new mongoose.Types.ObjectId(), + filename: `${fileId}.txt`, + filepath: `/uploads/${fileId}-v2.txt`, + type: 'text/plain', + bytes: 200, + expiredAt: new Date('2029-12-31T00:00:00.000Z'), + }, + true, + ); + + const files = await fileMethods.getExpiredFiles(100, { now, maxAttempts: 10 }); + expect(files.map((file) => file.file_id)).toEqual([fileId]); + expect(files[0].deletionAttempts).toBeUndefined(); + expect(files[0].deletionRetryAt).toBeUndefined(); + }); }); describe('deferExpiredFile', () => { diff --git a/packages/data-schemas/src/methods/file.ts b/packages/data-schemas/src/methods/file.ts index 78135971b9..6faf56f1c5 100644 --- a/packages/data-schemas/src/methods/file.ts +++ b/packages/data-schemas/src/methods/file.ts @@ -9,6 +9,16 @@ export type FileOwnerScope = { tenantId?: string | null; }; +/** + * Sweep bookkeeping belongs to the storage a record currently points at, so + * a write that (re)describes its content restarts the budget. Code-output + * records are reused across turns for a repeated `(filename, conversationId)` + * — new bytes, new storage key, fresh `expiredAt` — and a record carried to + * the give-up cap by its previous content would otherwise stay excluded from + * the sweep forever, stranding the new object exactly as before. + */ +const CLEARED_DELETION_RETRY_STATE = { deletionAttempts: '', deletionRetryAt: '' } as const; + export type ExpiredFileQueryOptions = { now?: Date; /** Consecutive-failure count at which a file stops being retried. */ @@ -440,10 +450,11 @@ export function createFileMethods(mongoose: typeof import('mongoose')): { delete fileData.expiresAt; } - return File.findOneAndUpdate({ file_id: data.file_id }, fileData, { - new: true, - upsert: true, - }).lean(); + return File.findOneAndUpdate( + { file_id: data.file_id }, + { $set: fileData, $unset: CLEARED_DELETION_RETRY_STATE }, + { new: true, upsert: true }, + ).lean(); } /** @@ -471,7 +482,7 @@ export function createFileMethods(mongoose: typeof import('mongoose')): { const { file_id, ...update } = data; const updateOperation = { $set: update, - $unset: { expiresAt: '' }, + $unset: { expiresAt: '', ...CLEARED_DELETION_RETRY_STATE }, }; const query: FilterQuery = extraFilter ? { file_id, ...extraFilter } : { file_id }; return File.findOneAndUpdate(query, updateOperation, {