From eb36edac6d2c660c00731339ea326341554451f4 Mon Sep 17 00:00:00 2001 From: Jakob Ackermann Date: Mon, 3 Aug 2026 16:43:11 +0200 Subject: [PATCH] [project-history] report a resync that is still pending after a flush (#36122) GitOrigin-RevId: ccd4390048c09f732531d2e02a40336fce88a952 --- .../project-history/app/js/ErrorRecorder.js | 3 +- services/project-history/app/js/Errors.js | 1 + .../project-history/app/js/HttpController.js | 24 +-- .../project-history/app/js/SyncManager.js | 20 ++- .../app/js/UpdatesProcessor.js | 102 +++++++++++- services/project-history/app/js/server.js | 3 + .../acceptance/js/NumericProjectIdTests.js | 81 +++++---- .../test/acceptance/js/SendingUpdatesTests.js | 63 +++++++ .../test/acceptance/js/SyncTests.js | 97 ++++++++++- .../js/helpers/ProjectHistoryClient.js | 9 +- .../js/HttpController/HttpControllerTests.js | 3 +- .../unit/js/RetryManager/RetryManagerTests.js | 2 +- .../unit/js/SyncManager/SyncManagerTests.js | 50 +++++- .../UpdatesManager/UpdatesProcessorTests.js | 155 +++++++++++++++++- .../app/src/Features/Compile/ClsiManager.mjs | 43 ++--- .../web/app/src/Features/Errors/Errors.js | 3 - .../src/Features/History/HistoryManager.mjs | 18 +- .../unit/src/Compile/ClsiManager.test.mjs | 41 ++++- .../HistoryManager.sequential.test.mjs | 21 --- 19 files changed, 588 insertions(+), 151 deletions(-) diff --git a/services/project-history/app/js/ErrorRecorder.js b/services/project-history/app/js/ErrorRecorder.js index 4977229779..96fc3233c7 100644 --- a/services/project-history/app/js/ErrorRecorder.js +++ b/services/project-history/app/js/ErrorRecorder.js @@ -198,7 +198,8 @@ const SHORT_ERROR_NAMES = { 'Error: failed to extend lock': 'lock-overrun', 'Error: tried to release timed out lock': 'lock-overrun', 'Error: Timeout': 'lock-overrun', - 'Error: sync ongoing': 'sync-ongoing', + 'Error: sync ongoing': 'sync-ongoing', // pre-SyncOngoingError entries + 'SyncOngoingError: sync ongoing': 'sync-ongoing', 'SyncError: unexpected resyncProjectStructure update': 'sync-error', '[object Error]': 'unknown-error-object', 'UpdateWithUnknownFormatError: update with unknown format': 'unknown-format', diff --git a/services/project-history/app/js/Errors.js b/services/project-history/app/js/Errors.js index 2365a538d9..1cfe0b9e8a 100644 --- a/services/project-history/app/js/Errors.js +++ b/services/project-history/app/js/Errors.js @@ -5,6 +5,7 @@ export const SYNC_ONGOING_ERROR_MESSAGE = 'sync ongoing' export class NotFoundError extends OError {} export class BadRequestError extends OError {} export class SyncError extends OError {} +export class SyncOngoingError extends OError {} export class OpsOutOfOrderError extends OError {} export class InconsistentChunkError extends OError {} export class UpdateWithUnknownFormatError extends OError {} diff --git a/services/project-history/app/js/HttpController.js b/services/project-history/app/js/HttpController.js index c92c7a5c7c..9ebe4680c6 100644 --- a/services/project-history/app/js/HttpController.js +++ b/services/project-history/app/js/HttpController.js @@ -234,7 +234,7 @@ export function initializeProject(req, res, next) { const flushProjectSchema = z.object({ params: z.strictObject({ - project_id: historyIdSchema, + project_id: zz.objectId(), }), query: z.strictObject({ debug: z.stringbool().default(false), @@ -252,7 +252,7 @@ const flushProjectSchema = z.object({ // when this route's REQ_VALIDATION_MODE instrumentation is removed. const flushProjectFallbackSchema = z.object({ params: z.object({ - project_id: historyIdSchema, + project_id: zz.objectId(), }), query: z.object({ debug: z.stringbool().default(false), @@ -429,7 +429,7 @@ export function getDiff(req, res, next) { const getFileTreeDiffSchema = z.object({ params: z.strictObject({ - project_id: historyIdSchema, + project_id: zz.objectId(), }), query: z.strictObject({ from: z.coerce.number().int(), @@ -441,7 +441,7 @@ const getFileTreeDiffSchema = z.object({ // when this route's REQ_VALIDATION_MODE instrumentation is removed. const getFileTreeDiffFallbackSchema = z.object({ params: z.object({ - project_id: historyIdSchema, + project_id: zz.objectId(), }), query: z.object({ from: z.coerce.number().int(), @@ -466,7 +466,7 @@ export function getFileTreeDiff(req, res, next) { const getUpdatesSchema = z.object({ params: z.strictObject({ - project_id: historyIdSchema, + project_id: zz.objectId(), }), query: z.strictObject({ before: z.coerce.number().int().optional(), @@ -478,7 +478,7 @@ const getUpdatesSchema = z.object({ // when this route's REQ_VALIDATION_MODE instrumentation is removed. const getUpdatesFallbackSchema = z.object({ params: z.object({ - project_id: historyIdSchema, + project_id: zz.objectId(), }), query: z.object({ before: z.coerce.number().int().optional(), @@ -587,7 +587,7 @@ export function getDebugInfo(req, res, next) { const latestVersionSchema = z.object({ params: z.strictObject({ - project_id: historyIdSchema, + project_id: zz.objectId(), }), }) @@ -595,7 +595,7 @@ const latestVersionSchema = z.object({ // when this route's REQ_VALIDATION_MODE instrumentation is removed. const latestVersionFallbackSchema = z.object({ params: z.object({ - project_id: historyIdSchema, + project_id: zz.objectId(), }), }) @@ -970,7 +970,7 @@ export function resyncProject(req, res, next) { return next(error) } // flush the sync operations - UpdatesProcessor.processUpdatesForProject(projectId, error => { + UpdatesProcessor.flushResyncUpdates(projectId, error => { if (error != null) { return next(error) } @@ -983,7 +983,7 @@ export function resyncProject(req, res, next) { return next(error) } // flush the sync operations - UpdatesProcessor.processUpdatesForProject(projectId, error => { + UpdatesProcessor.flushResyncUpdates(projectId, error => { if (error != null) { return next(error) } @@ -1100,7 +1100,7 @@ export function getLabels(req, res, next) { const createLabelSchema = z.object({ params: z.strictObject({ - project_id: historyIdSchema, + project_id: zz.objectId(), // vestigial: no route mounts createLabel with a :user_id param, so this // is always undefined; kept only to preserve the params/body dual-read // rollout behaviour below (see the comment at its use site) @@ -1119,7 +1119,7 @@ const createLabelSchema = z.object({ // when this route's REQ_VALIDATION_MODE instrumentation is removed. const createLabelFallbackSchema = z.object({ params: z.object({ - project_id: historyIdSchema, + project_id: zz.objectId(), user_id: zz.objectId().optional(), }), body: z.object({ diff --git a/services/project-history/app/js/SyncManager.js b/services/project-history/app/js/SyncManager.js index 254c7d1aa5..2ecb32eb9e 100644 --- a/services/project-history/app/js/SyncManager.js +++ b/services/project-history/app/js/SyncManager.js @@ -17,6 +17,7 @@ import { NeedFullProjectStructureResyncError, SYNC_ONGOING_ERROR_MESSAGE, SyncError, + SyncOngoingError, } from './Errors.js' import { db, ObjectId } from './mongodb.js' import * as SnapshotManager from './SnapshotManager.js' @@ -104,11 +105,11 @@ async function startResyncWithoutLock(projectId, options) { const syncState = await getResyncState(projectId) if (syncState.isSyncOngoing()) { - if (syncState.isSyncStuck()) { - const stuckDocPaths = Array.from(syncState.resyncDocContents) - const stuckClearCount = syncState.stuckClearCount + const stuckDocPaths = Array.from(syncState.resyncDocContents) + const stuckClearCount = syncState.stuckClearCount - if (stuckClearCount >= MAX_STUCK_CLEAR_ATTEMPTS) { + if (syncState.isSyncStuck()) { + if (syncState.isSyncPermanentlyStuck()) { await _recordStuckClearInSyncState(projectId, stuckDocPaths) Metrics.inc('project_history_sync_stuck_permanent') // Log error only on first permanent-stuck detection to avoid spam @@ -138,7 +139,12 @@ async function startResyncWithoutLock(projectId, options) { Metrics.inc('project_history_sync_stuck_cleared') await _recordStuckClearInSyncState(projectId, stuckDocPaths) } else { - throw new OError(SYNC_ONGOING_ERROR_MESSAGE) + throw new SyncOngoingError(SYNC_ONGOING_ERROR_MESSAGE, { + projectId, + stuckClearCount: stuckClearCount + 1, + stuckDocPaths, + resyncPendingSince: syncState.resyncPendingSince, + }) } } syncState.setOrigin(options.origin || { kind: 'history-resync' }) @@ -573,6 +579,10 @@ class SyncState { Date.now() - this.resyncPendingSince.getTime() > SYNC_STUCK_TIMEOUT_MS ) } + + isSyncPermanentlyStuck() { + return this.stuckClearCount >= MAX_STUCK_CLEAR_ATTEMPTS + } } class SyncUpdateExpander { diff --git a/services/project-history/app/js/UpdatesProcessor.js b/services/project-history/app/js/UpdatesProcessor.js index b4895c012d..ffc2d6a8fd 100644 --- a/services/project-history/app/js/UpdatesProcessor.js +++ b/services/project-history/app/js/UpdatesProcessor.js @@ -121,16 +121,47 @@ export function startResyncAndProcessUpdatesUnderLock( // Process all updates for a project, only check project-level information once export function processUpdatesForProject(projectId, callback) { + _processUpdatesForProjectWithLock( + projectId, + { checkResyncState: true }, + callback + ) +} + +// Process all updates for a project without asserting the resync state afterwards. +// Used right after starting a resync, where a pending resync is the expected state. +export function flushResyncUpdates(projectId, callback) { + _processUpdatesForProjectWithLock( + projectId, + { checkResyncState: false }, + callback + ) +} + +function _processUpdatesForProjectWithLock( + projectId, + { checkResyncState }, + callback +) { const startTimeMs = Date.now() LockManager.runWithLock( keys.projectHistoryLock({ project_id: projectId }), (extendLock, releaseLock) => { - _countAndProcessUpdates( - projectId, - extendLock, - REDIS_READ_BATCH_SIZE, - releaseLock - ) + if (checkResyncState) { + _flushAndCheckResyncState( + projectId, + extendLock, + REDIS_READ_BATCH_SIZE, + releaseLock + ) + } else { + _countAndProcessUpdates( + projectId, + extendLock, + REDIS_READ_BATCH_SIZE, + releaseLock + ) + } }, (flushError, { queueSize, resyncNeeded } = {}) => { if (flushError) { @@ -379,7 +410,7 @@ _mocks._countAndProcessUpdates = ( ) } else { logger.debug({ projectId }, 'no updates to process') - callback(null, queueSize) + callback(null, { queueSize, resyncNeeded: false }) } }) } @@ -388,6 +419,63 @@ function _countAndProcessUpdates(...args) { _mocks._countAndProcessUpdates(...args) } +// Never rejects: the caller needs the flush result even when the flush failed, in +// order to record the queue size in projectHistoryFailures. +function _countAndProcessUpdatesAsync(projectId, extendLock, batchSize) { + return new Promise(resolve => { + _countAndProcessUpdates(projectId, extendLock, batchSize, (error, result) => + resolve({ error, result }) + ) + }) +} + +function _syncOngoingError(projectId, syncState) { + return new Errors.SyncOngoingError(Errors.SYNC_ONGOING_ERROR_MESSAGE, { + projectId, + stuckClearCount: syncState.stuckClearCount, + stuckDocPaths: Array.from(syncState.resyncDocContents), + resyncPendingSince: syncState.resyncPendingSince, + resyncProjectStructure: syncState.resyncProjectStructure, + }) +} + +// Runs under the project lock, after the queue has been drained. A resync that is +// still pending at this point never received its updates: web queues them all before +// the resync request returns. Fail the flush, the history may be inconsistent and +// callers must not rely on it. +async function _flushAndCheckResyncStateAsync( + projectId, + extendLock, + batchSize +) { + const extendLockAsync = promisify(extendLock) + let result + try { + const flush = await _countAndProcessUpdatesAsync( + projectId, + extendLock, + batchSize + ) + result = flush.result + if (flush.error) return { error: flush.error, result } + + await extendLockAsync() + const syncState = await SyncManager.promises.getResyncState(projectId) + if (syncState.isSyncOngoing()) { + return { error: _syncOngoingError(projectId, syncState), result } + } + return { result } + } catch (error) { + return { error: OError.tag(error), result } + } +} + +function _flushAndCheckResyncState(projectId, extendLock, batchSize, callback) { + _flushAndCheckResyncStateAsync(projectId, extendLock, batchSize).then( + ({ error, result }) => callback(error || null, result) + ) +} + function _processUpdatesBatch(projectId, updates, extendLock, callback) { // If the project doesn't have a history then we can bail out here _getHistoryId(projectId, updates, (error, historyId) => { diff --git a/services/project-history/app/js/server.js b/services/project-history/app/js/server.js index 6b5a54100a..723828d5d6 100644 --- a/services/project-history/app/js/server.js +++ b/services/project-history/app/js/server.js @@ -52,6 +52,9 @@ app.use(function (error, req, res, next) { res.sendStatus(400) } else if (error instanceof Errors.InconsistentChunkError) { res.sendStatus(422) + } else if (error instanceof Errors.SyncOngoingError) { + logger.error({ err: error, req }, error.message) + res.sendStatus(409) } else if (error instanceof Errors.TooManyRequestsError) { res.status(429).set('Retry-After', 300).end() } else if ( diff --git a/services/project-history/test/acceptance/js/NumericProjectIdTests.js b/services/project-history/test/acceptance/js/NumericProjectIdTests.js index de0af69dd8..bfb3f5b115 100644 --- a/services/project-history/test/acceptance/js/NumericProjectIdTests.js +++ b/services/project-history/test/acceptance/js/NumericProjectIdTests.js @@ -1,8 +1,12 @@ import { expect } from 'chai' +import assert from 'node:assert' import nock from 'nock' import * as ProjectHistoryApp from './helpers/ProjectHistoryApp.js' import * as ProjectHistoryClient from './helpers/ProjectHistoryClient.js' -import { fetchStringWithResponse } from '@overleaf/fetch-utils' +import { + fetchStringWithResponse, + RequestFailedError, +} from '@overleaf/fetch-utils' const MockHistoryStore = () => nock('http://127.0.0.1:3100') const MockWeb = () => nock('http://127.0.0.1:3000') @@ -67,12 +71,50 @@ describe('NumericProjectId', function () { }) } - it('should accept numeric project_id for flush', async function () { - const { response } = await makeRequest({ + // Endpoints that flush need the resync state, which is keyed by ObjectId, so + // they only accept a mongo project id. An invalid path param is reported as a + // 404, see handleValidationError. + async function expectRejected(options) { + try { + await makeRequest(options) + assert.fail('request should have failed') + } catch (error) { + if (error instanceof RequestFailedError) { + expect(error.response.status).to.equal(404) + } else { + throw error + } + } + } + + it('should reject numeric project_id for flush', async function () { + await expectRejected({ method: 'POST', url: `http://127.0.0.1:3054/project/${this.numericProjectId}/flush`, }) - expect(response.status).to.equal(204) + }) + + it('should reject numeric project_id for filetree diff', async function () { + await expectRejected({ + method: 'GET', + url: `http://127.0.0.1:3054/project/${this.numericProjectId}/filetree/diff`, + qs: { from: 7, to: 8 }, + }) + }) + + it('should reject numeric project_id for updates', async function () { + await expectRejected({ + method: 'GET', + url: `http://127.0.0.1:3054/project/${this.numericProjectId}/updates`, + qs: { min_count: 1 }, + }) + }) + + it('should reject numeric project_id for version', async function () { + await expectRejected({ + method: 'GET', + url: `http://127.0.0.1:3054/project/${this.numericProjectId}/version`, + }) }) it('should accept numeric project_id for dump', async function () { @@ -83,32 +125,6 @@ describe('NumericProjectId', function () { expect(response.status).to.equal(200) }) - it('should accept numeric project_id for filetree diff', async function () { - const { response } = await makeRequest({ - method: 'GET', - url: `http://127.0.0.1:3054/project/${this.numericProjectId}/filetree/diff`, - qs: { from: 7, to: 8 }, - }) - expect(response.status).to.equal(200) - }) - - it('should accept numeric project_id for updates', async function () { - const { response } = await makeRequest({ - method: 'GET', - url: `http://127.0.0.1:3054/project/${this.numericProjectId}/updates`, - qs: { min_count: 1 }, - }) - expect(response.status).to.equal(200) - }) - - it('should accept numeric project_id for version', async function () { - const { response } = await makeRequest({ - method: 'GET', - url: `http://127.0.0.1:3054/project/${this.numericProjectId}/version`, - }) - expect(response.status).to.equal(200) - }) - it('should accept numeric project_id for snapshot', async function () { const { response } = await makeRequest({ method: 'GET', @@ -125,8 +141,8 @@ describe('NumericProjectId', function () { expect(response.status).to.equal(200) }) - it('should accept numeric project_id for createLabel', async function () { - const { response } = await makeRequest({ + it('should reject numeric project_id for createLabel', async function () { + await expectRejected({ method: 'POST', url: `http://127.0.0.1:3054/project/${this.numericProjectId}/labels`, json: { @@ -135,7 +151,6 @@ describe('NumericProjectId', function () { user_id: '507f1f77bcf86cd799439011', }, }) - expect(response.status).to.equal(200) }) it('should accept numeric history_id for getProjectBlob', async function () { diff --git a/services/project-history/test/acceptance/js/SendingUpdatesTests.js b/services/project-history/test/acceptance/js/SendingUpdatesTests.js index fb88d779f5..6662357676 100644 --- a/services/project-history/test/acceptance/js/SendingUpdatesTests.js +++ b/services/project-history/test/acceptance/js/SendingUpdatesTests.js @@ -801,6 +801,69 @@ describe('Sending Updates', function () { }) }) + describe('bisect mode', function () { + it('should stop when the queue is empty', async function () { + // Regression: the flush reported the queue size of an empty queue as a bare + // number, so the `queueSize === 0` check never matched and the bisect kept + // processing the empty queue with the same batch size. + const { statusCode } = await ProjectHistoryClient.flushProject( + this.projectId, + { bisect: true } + ) + expect(statusCode).to.equal(204) + }) + + it('should send updates to the history store', async function () { + const fileHash = '0a207c060e61f3b88eaee0a8cd0696f46fb155eb' + + MockHistoryStore() + .get(`/api/projects/${historyId}/latest/history`) + .reply(200, { + chunk: { + startVersion: 0, + history: { + snapshot: {}, + changes: [], + }, + }, + }) + + const createBlob = MockHistoryStore() + .put(`/api/projects/${historyId}/blobs/${fileHash}`, 'a\nb') + .reply(201) + + const addFile = MockHistoryStore() + .post(`/api/projects/${historyId}/legacy_changes`, body => { + expect(body).to.deep.equal([ + olAddDocUpdate(this.doc, this.userId, this.timestamp, fileHash), + ]) + return true + }) + .query({ end_version: 0 }) + .reply(204) + + await ProjectHistoryClient.pushRawUpdate( + this.projectId, + slAddDocUpdate(historyId, this.doc, this.userId, this.timestamp, 'a\nb') + ) + + const { statusCode } = await ProjectHistoryClient.flushProject( + this.projectId, + { bisect: true } + ) + expect(statusCode).to.equal(204) + + assert( + createBlob.isDone(), + '/api/projects/:historyId/blobs/:hash should have been called' + ) + assert( + addFile.isDone(), + `/api/projects/${historyId}/changes should have been called` + ) + }) + }) + describe('compressing updates', function () { beforeEach(function () { MockHistoryStore() diff --git a/services/project-history/test/acceptance/js/SyncTests.js b/services/project-history/test/acceptance/js/SyncTests.js index 37f9e490e8..9dd1d87ee8 100644 --- a/services/project-history/test/acceptance/js/SyncTests.js +++ b/services/project-history/test/acceptance/js/SyncTests.js @@ -161,7 +161,12 @@ describe('Syncing with web and doc-updater', function () { } await ProjectHistoryClient.pushRawUpdate(this.project_id, update) - await ProjectHistoryClient.flushProject(this.project_id) + // The resync stays pending: this test only queues the structure + // update, not the resyncDocContent updates it asks for. + const res = await ProjectHistoryClient.flushProject(this.project_id, { + allowErrors: true, + }) + expect(res.statusCode).to.equal(409) assert( createBlob.isDone(), @@ -917,7 +922,12 @@ describe('Syncing with web and doc-updater', function () { } await ProjectHistoryClient.pushRawUpdate(this.project_id, update) - await ProjectHistoryClient.flushProject(this.project_id) + // The resync stays pending: this test only queues the structure + // update, not the resyncDocContent updates it asks for. + const res = await ProjectHistoryClient.flushProject(this.project_id, { + allowErrors: true, + }) + expect(res.statusCode).to.equal(409) assert( deleteFile.isDone(), @@ -2795,8 +2805,12 @@ describe('Syncing with web and doc-updater', function () { ) // Step 3: Flush — processes structure update, adds /main.tex to resyncDocContents - // This succeeds (204) but leaves sync in an incomplete state - await ProjectHistoryClient.flushProject(this.project_id) + // The updates are applied, but the flush reports the incomplete sync + const flush = await ProjectHistoryClient.flushProject( + this.project_id, + { allowErrors: true } + ) + expect(flush.statusCode).to.equal(409) // Step 4: Verify the sync state is stuck const syncState = await ProjectHistoryClient.getSyncState( @@ -2823,7 +2837,11 @@ describe('Syncing with web and doc-updater', function () { // Step 6: Flush again — the text update should be silently skipped // because the doc is in resyncDocContents (sync "ongoing") - await ProjectHistoryClient.flushProject(this.project_id) + const flushAgain = await ProjectHistoryClient.flushProject( + this.project_id, + { allowErrors: true } + ) + expect(flushAgain.statusCode).to.equal(409) // Step 7: Verify the sync state is STILL stuck (text update was skipped) const syncStateAfter = await ProjectHistoryClient.getSyncState( @@ -2851,11 +2869,24 @@ describe('Syncing with web and doc-updater', function () { assert.fail('resync should have failed') } catch (error) { if (error instanceof RequestFailedError) { - expect(error.response.status).to.equal(500) + expect(error.response.status).to.equal(409) } else { throw error } } + + expect(loggerError).to.have.been.calledWith( + sinon.match({ + err: sinon.match({ + name: 'SyncOngoingError', + message: 'sync ongoing', + info: sinon.match({ + projectId: this.project_id, + stuckDocPaths: ['/main.tex'], + }), + }), + }) + ) }) it('should recover with a hard resync (force=true)', async function () { @@ -2876,7 +2907,9 @@ describe('Syncing with web and doc-updater', function () { this.project_id, structureUpdate ) - await ProjectHistoryClient.flushProject(this.project_id) + await ProjectHistoryClient.flushProject(this.project_id, { + allowErrors: true, + }) // Verify stuck const syncState = await ProjectHistoryClient.getSyncState( @@ -2941,6 +2974,56 @@ describe('Syncing with web and doc-updater', function () { expect(syncState.resyncProjectStructure).to.equal(true) expect(syncState.lastStuckDocPaths).to.deep.equal(['/main.tex']) }) + + it('should report a pending resync at the end of a flush', async function () { + await ProjectHistoryClient.injectStuckSyncState(this.project_id, [ + '/main.tex', + ]) + + const requestResync = MockWeb() + .post(`/project/${this.project_id}/history/resync`) + .reply(204) + + const res = await ProjectHistoryClient.flushProject(this.project_id, { + allowErrors: true, + }) + expect(res.statusCode).to.equal(409) + + // The flush only reports, it does not start a resync of its own + assert(!requestResync.isDone(), 'should not have requested a resync') + const syncState = await ProjectHistoryClient.getSyncState( + this.project_id + ) + expect(syncState.resyncProjectStructure).to.equal(false) + expect(syncState.resyncDocContents).to.deep.equal(['/main.tex']) + }) + + it('should not report a resync that completes during the flush', async function () { + await ProjectHistoryClient.resyncHistory(this.project_id) + + await ProjectHistoryClient.pushRawUpdate(this.project_id, { + projectHistoryId: historyId, + resyncProjectStructure: { + docs: [{ path: '/main.tex' }], + files: [], + }, + meta: { ts: this.timestamp }, + }) + await ProjectHistoryClient.pushRawUpdate(this.project_id, { + path: '/main.tex', + doc: this.doc_id, + resyncDocContent: { content: 'a\nb' }, + meta: { ts: this.timestamp }, + }) + + await ProjectHistoryClient.flushProject(this.project_id) + + const syncState = await ProjectHistoryClient.getSyncState( + this.project_id + ) + expect(syncState.resyncProjectStructure).to.equal(false) + expect(syncState.resyncDocContents).to.deep.equal([]) + }) }) }) }) diff --git a/services/project-history/test/acceptance/js/helpers/ProjectHistoryClient.js b/services/project-history/test/acceptance/js/helpers/ProjectHistoryClient.js index e52a68da0e..68d087a6da 100644 --- a/services/project-history/test/acceptance/js/helpers/ProjectHistoryClient.js +++ b/services/project-history/test/acceptance/js/helpers/ProjectHistoryClient.js @@ -30,11 +30,12 @@ export async function initializeProject(historyId) { } export async function flushProject(projectId, options = {}) { + const url = new URL(`http://127.0.0.1:3054/project/${projectId}/flush`) + if (options.bisect) { + url.searchParams.set('bisect', 'true') + } try { - const response = await fetchNothing( - `http://127.0.0.1:3054/project/${projectId}/flush`, - { method: 'POST' } - ) + const response = await fetchNothing(url.toString(), { method: 'POST' }) if (!options.allowErrors) { expect(response.status).to.equal(204) } diff --git a/services/project-history/test/unit/js/HttpController/HttpControllerTests.js b/services/project-history/test/unit/js/HttpController/HttpControllerTests.js index 58268c7b6c..50079f5933 100644 --- a/services/project-history/test/unit/js/HttpController/HttpControllerTests.js +++ b/services/project-history/test/unit/js/HttpController/HttpControllerTests.js @@ -9,6 +9,7 @@ describe('HttpController', function () { beforeEach(async function () { this.UpdatesProcessor = { processUpdatesForProject: sinon.stub().yields(), + flushResyncUpdates: sinon.stub().yields(), } this.SummarizedUpdatesManager = { getSummarizedProjectUpdates: sinon.stub(), @@ -298,7 +299,7 @@ describe('HttpController', function () { }) it('should flush the queue', function () { - this.UpdatesProcessor.processUpdatesForProject + this.UpdatesProcessor.flushResyncUpdates .calledWith(this.projectId) .should.equal(true) }) diff --git a/services/project-history/test/unit/js/RetryManager/RetryManagerTests.js b/services/project-history/test/unit/js/RetryManager/RetryManagerTests.js index b0645430e6..3324c17b77 100644 --- a/services/project-history/test/unit/js/RetryManager/RetryManagerTests.js +++ b/services/project-history/test/unit/js/RetryManager/RetryManagerTests.js @@ -59,7 +59,7 @@ describe('RetryManager', function () { }, { project_id: this.projectId6, - error: 'OError: sync ongoing', + error: 'SyncOngoingError: sync ongoing', attempts: 10, resyncAttempts: 2, }, diff --git a/services/project-history/test/unit/js/SyncManager/SyncManagerTests.js b/services/project-history/test/unit/js/SyncManager/SyncManagerTests.js index d643aacbe0..608d2cf8c0 100644 --- a/services/project-history/test/unit/js/SyncManager/SyncManagerTests.js +++ b/services/project-history/test/unit/js/SyncManager/SyncManagerTests.js @@ -11,7 +11,10 @@ import { } from 'overleaf-editor-core' import { UnprocessableError } from 'overleaf-editor-core/lib/errors.js' import { strict as esmock } from 'esmock' -import { FileContentEmptyError } from '../../../../app/js/Errors.js' +import { + FileContentEmptyError, + SyncOngoingError, +} from '../../../../app/js/Errors.js' const { ObjectId } = mongodb const MODULE_PATH = '../../../../app/js/SyncManager.js' @@ -242,15 +245,16 @@ describe('SyncManager', function () { it('returns an error if already syncing', async function () { await expect( this.SyncManager.promises.startResync(this.projectId) - ).to.be.rejectedWith('sync ongoing') + ).to.be.rejectedWith(SyncOngoingError, 'sync ongoing') }) }) describe('if doc content sync in is progress', function () { beforeEach(async function () { + this.resyncPendingSince = new Date() const syncState = { resyncDocContents: ['/foo.tex'], - resyncPendingSince: new Date(), + resyncPendingSince: this.resyncPendingSince, } this.db.projectHistorySyncState.findOne.resolves(syncState) }) @@ -258,7 +262,19 @@ describe('SyncManager', function () { it('returns an error if already syncing', async function () { await expect( this.SyncManager.promises.startResync(this.projectId) - ).to.be.rejectedWith('sync ongoing') + ).to.be.rejectedWith(SyncOngoingError, 'sync ongoing') + }) + + it('includes the stuck context in the error', async function () { + const error = await this.SyncManager.promises + .startResync(this.projectId) + .catch(err => err) + expect(error.info).to.deep.equal({ + projectId: this.projectId, + stuckClearCount: 1, + stuckDocPaths: ['/foo.tex'], + resyncPendingSince: this.resyncPendingSince, + }) }) }) @@ -324,7 +340,7 @@ describe('SyncManager', function () { it('throws sync ongoing and does not clear', async function () { await expect( this.SyncManager.promises.startResync(this.projectId) - ).to.be.rejectedWith('sync ongoing') + ).to.be.rejectedWith(SyncOngoingError, 'sync ongoing') expect( this.Metrics.inc.calledWith('project_history_sync_stuck_cleared') ).to.be.false @@ -369,6 +385,30 @@ describe('SyncManager', function () { }) }) + describe('isSyncPermanentlyStuck', function () { + it('is false below the auto-clear limit', async function () { + this.db.projectHistorySyncState.findOne.resolves({ + resyncDocContents: ['/foo.tex'], + stuckClearCount: 4, + }) + const syncState = await this.SyncManager.promises.getResyncState( + this.projectId + ) + expect(syncState.isSyncPermanentlyStuck()).to.be.false + }) + + it('is true at the auto-clear limit', async function () { + this.db.projectHistorySyncState.findOne.resolves({ + resyncDocContents: ['/foo.tex'], + stuckClearCount: 5, + }) + const syncState = await this.SyncManager.promises.getResyncState( + this.projectId + ) + expect(syncState.isSyncPermanentlyStuck()).to.be.true + }) + }) + describe('setResyncState', function () { describe('when the sync is starting', function () { beforeEach(function () { diff --git a/services/project-history/test/unit/js/UpdatesManager/UpdatesProcessorTests.js b/services/project-history/test/unit/js/UpdatesManager/UpdatesProcessorTests.js index fcc0918e11..8759ad5e3a 100644 --- a/services/project-history/test/unit/js/UpdatesManager/UpdatesProcessorTests.js +++ b/services/project-history/test/unit/js/UpdatesManager/UpdatesProcessorTests.js @@ -5,9 +5,19 @@ import * as Errors from '../../../../app/js/Errors.js' const MODULE_PATH = '../../../../app/js/UpdatesProcessor.js' +function makeSyncState({ ongoing = false } = {}) { + return { + stuckClearCount: 0, + resyncDocContents: new Set(ongoing ? ['/main.tex'] : []), + resyncProjectStructure: false, + resyncPendingSince: new Date(), + isSyncOngoing: () => ongoing, + } +} + describe('UpdatesProcessor', function () { beforeEach(async function () { - this.extendLock = sinon.stub() + this.extendLock = sinon.stub().yields() this.BlobManager = { createBlobsForUpdates: sinon.stub(), } @@ -20,7 +30,10 @@ describe('UpdatesProcessor', function () { runner(this.extendLock, callback) ), } - this.RedisManager = {} + this.RedisManager = { + clearDanglingFirstOpTimestamp: sinon.stub().yields(), + countUnprocessedUpdates: sinon.stub(), + } this.UpdateCompressor = { compressRawUpdatesWithMetricsCb: sinon.stub(), } @@ -36,10 +49,14 @@ describe('UpdatesProcessor', function () { expandSyncUpdates: sinon.stub(), setResyncState: sinon.stub().yields(), skipUpdatesDuringSync: sinon.stub(), + promises: { + getResyncState: sinon.stub().resolves(makeSyncState()), + }, } this.ErrorRecorder = { getLastFailure: sinon.stub(), record: sinon.stub().yields(null, { attempts: 1 }), + clearError: sinon.stub().yields(), } this.RetryManager = { isFirstFailure: sinon.stub().returns(true), @@ -132,6 +149,140 @@ describe('UpdatesProcessor', function () { .calledWith(this.project_id, this.queueSize, this.error) .should.equal(true) }) + + it('does not check the resync state', function () { + this.SyncManager.promises.getResyncState.should.not.have.been.called + }) + }) + }) + + describe('_countAndProcessUpdates', function () { + describe('when the queue is empty', function () { + beforeEach(function (done) { + this.RedisManager.countUnprocessedUpdates.yields(null, 0) + this.UpdatesProcessor._mocks._countAndProcessUpdates( + this.project_id, + this.extendLock, + 1, + (error, result) => { + this.error = error + this.result = result + done() + } + ) + }) + + it('reports the flush result as an object', function () { + expect(this.error).to.not.exist + expect(this.result).to.deep.equal({ queueSize: 0, resyncNeeded: false }) + }) + }) + }) + + describe('processUpdatesForProjectUsingBisect', function () { + describe('when the queue is empty', function () { + beforeEach(function (done) { + this.RedisManager.countUnprocessedUpdates.yields(null, 0) + this.UpdatesProcessor.processUpdatesForProjectUsingBisect( + this.project_id, + this.UpdatesProcessor.REDIS_READ_BATCH_SIZE, + done + ) + }) + + it('stops instead of processing the empty queue again', function () { + expect(this.RedisManager.countUnprocessedUpdates.callCount).to.equal(1) + }) + }) + }) + + describe('checking the resync state after a flush', function () { + beforeEach(function () { + // the resync state is keyed by ObjectId, so this needs a real project id + this.project_id = '507f1f77bcf86cd799439011' + this.queueSize = 3 + this.ErrorRecorder.getLastFailure.yields() + this.countAndProcessUpdates = sinon + .stub() + .callsArgWith(3, null, { queueSize: this.queueSize }) + this.UpdatesProcessor._mocks._countAndProcessUpdates = + this.countAndProcessUpdates + this.flush = projectId => + new Promise(resolve => { + this.UpdatesProcessor.processUpdatesForProject(projectId, resolve) + }) + }) + + describe('when no resync is pending', function () { + beforeEach(async function () { + this.err = await this.flush(this.project_id) + }) + + it('succeeds', function () { + expect(this.err).to.not.exist + expect(this.countAndProcessUpdates.callCount).to.equal(1) + }) + }) + + describe('when a resync is still pending', function () { + beforeEach(async function () { + this.SyncManager.promises.getResyncState.resolves( + makeSyncState({ ongoing: true }) + ) + this.err = await this.flush(this.project_id) + }) + + it('fails the flush with a sync ongoing error', function () { + expect(this.err).to.be.instanceof(Errors.SyncOngoingError) + expect(this.err.info).to.include({ + projectId: this.project_id, + stuckClearCount: 0, + }) + }) + + it('records the error with the queue size', function () { + this.ErrorRecorder.record.should.have.been.calledWith( + this.project_id, + this.queueSize + ) + }) + }) + + describe('when reading the resync state fails', function () { + beforeEach(async function () { + this.SyncManager.promises.getResyncState.rejects( + new Error('mongo is down') + ) + this.err = await this.flush(this.project_id) + }) + + it('fails the flush with that error', function () { + expect(this.err.message).to.equal('mongo is down') + }) + + it('still records the error with the queue size', function () { + this.ErrorRecorder.record.should.have.been.calledWith( + this.project_id, + this.queueSize + ) + }) + }) + + describe('flushResyncUpdates', function () { + beforeEach(function (done) { + this.SyncManager.promises.getResyncState.resolves( + makeSyncState({ ongoing: true }) + ) + this.UpdatesProcessor.flushResyncUpdates(this.project_id, err => { + this.err = err + done() + }) + }) + + it('does not check the resync state', function () { + expect(this.err).to.not.exist + this.SyncManager.promises.getResyncState.should.not.have.been.called + }) }) }) diff --git a/services/web/app/src/Features/Compile/ClsiManager.mjs b/services/web/app/src/Features/Compile/ClsiManager.mjs index 57fa48e473..5500aa29f9 100644 --- a/services/web/app/src/Features/Compile/ClsiManager.mjs +++ b/services/web/app/src/Features/Compile/ClsiManager.mjs @@ -979,23 +979,17 @@ async function _buildRequestFromHistoryFull( project ) { await _flushHistoryForCompile(projectId, historyId) - const [ - { - chunk: { - history: { snapshot: rawSnapshot, changes: rawChanges }, - startVersion, - }, + const { + chunk: { + history: { snapshot: rawSnapshot, changes: rawChanges }, + startVersion, }, - /* ensureNoResyncPending throws */ - ] = await Promise.all([ - withRetries( - () => HistoryManager.promises.getLatestHistoryWithHistoryId(historyId), - 'compile-from-history-chunk-retry', - 'failed to get history chunk', - { projectId, historyId } - ), - HistoryManager.promises.ensureNoResyncPending(projectId), - ]) + } = await withRetries( + () => HistoryManager.promises.getLatestHistoryWithHistoryId(historyId), + 'compile-from-history-chunk-retry', + 'failed to get history chunk', + { projectId, historyId } + ) const rawChangeOperations = _rawChangeOperationsFromChanges(rawChanges) const globalBlobs = _collectGlobalBlobs(rawChangeOperations) collectGlobalBlobsFromRawSnapshot(rawSnapshot, globalBlobs) @@ -1025,16 +1019,13 @@ async function _buildRequestFromHistoryIncremental( let size = 0 while (hasMore) { let changes - ;[{ changes, hasMore } /* resyncPending throws */] = await Promise.all([ - withRetries( - () => - HistoryManager.promises.getChangesWithHistoryId(historyId, { since }), - 'compile-from-history-changes-retry', - 'failed to get history changes', - { projectId, historyId, since } - ), - HistoryManager.promises.ensureNoResyncPending(projectId), - ]) + ;({ changes, hasMore } = await withRetries( + () => + HistoryManager.promises.getChangesWithHistoryId(historyId, { since }), + 'compile-from-history-changes-retry', + 'failed to get history changes', + { projectId, historyId, since } + )) since += changes.length const newRawChangeOperations = _rawChangeOperationsFromChanges(changes) size += Buffer.from(JSON.stringify(newRawChangeOperations)).byteLength diff --git a/services/web/app/src/Features/Errors/Errors.js b/services/web/app/src/Features/Errors/Errors.js index 9e4f167d74..cc4ac0048f 100644 --- a/services/web/app/src/Features/Errors/Errors.js +++ b/services/web/app/src/Features/Errors/Errors.js @@ -70,8 +70,6 @@ class V1HistoryNotSyncedError extends BackwardCompatibleError {} class ProjectHistoryDisabledError extends BackwardCompatibleError {} -class HistoryResyncPendingError extends OError {} - class V1ConnectionError extends BackwardCompatibleError {} class UnconfirmedEmailError extends BackwardCompatibleError {} @@ -412,7 +410,6 @@ module.exports = { UnsupportedExportRecordsError, V1HistoryNotSyncedError, ProjectHistoryDisabledError, - HistoryResyncPendingError, V1ConnectionError, UnconfirmedEmailError, EmailExistsError, diff --git a/services/web/app/src/Features/History/HistoryManager.mjs b/services/web/app/src/Features/History/HistoryManager.mjs index 1958c51c31..d74f33e8b0 100644 --- a/services/web/app/src/Features/History/HistoryManager.mjs +++ b/services/web/app/src/Features/History/HistoryManager.mjs @@ -14,11 +14,7 @@ import ProjectGetter from '../Project/ProjectGetter.mjs' import HistoryBackupDeletionHandler from './HistoryBackupDeletionHandler.mjs' import { db, waitForDb } from '../../infrastructure/mongodb.mjs' import Metrics from '@overleaf/metrics' -import { - NotFoundError, - HistoryResyncPendingError, - FileTooLargeError, -} from '../Errors/Errors.js' +import { NotFoundError, FileTooLargeError } from '../Errors/Errors.js' const HISTORY_V1_URL = settings.apis.v1_history.url const HISTORY_V1_BASIC_AUTH = { @@ -336,17 +332,6 @@ async function getLatestZipWithHistoryId(historyId) { return { stream, historyVersion: response.headers.get('X-History-Version') } } -async function ensureNoResyncPending(projectId) { - const { resyncPending } = await fetchJson( - `${settings.apis.project_history.url}/project/${projectId}/resync-pending` - ) - if (resyncPending) { - throw new HistoryResyncPendingError('broken history with pending resync', { - projectId, - }) - } -} - async function getDebugInfo(projectId) { return await fetchJson( `${settings.apis.project_history.url}/project/${projectId}/debug-info` @@ -538,7 +523,6 @@ export default { getProjectBlobStats, getBlobStats, getLatestHistoryWithHistoryId, - ensureNoResyncPending, getDebugInfo, getHistoryFailures, }, diff --git a/services/web/test/unit/src/Compile/ClsiManager.test.mjs b/services/web/test/unit/src/Compile/ClsiManager.test.mjs index d50ffd30d0..5b37ab17ed 100644 --- a/services/web/test/unit/src/Compile/ClsiManager.test.mjs +++ b/services/web/test/unit/src/Compile/ClsiManager.test.mjs @@ -214,7 +214,6 @@ describe('ClsiManager', function () { getChangesWithHistoryId: sinon .stub() .resolves({ changes: [], hasMore: false }), - ensureNoResyncPending: sinon.stub().resolves(), }, getFilestoreBlobURL: sinon.stub().callsFake((historyId, hash) => { if (hash === GLOBAL_BLOB_HASH) { @@ -546,6 +545,14 @@ describe('ClsiManager', function () { ) } + function makeResyncPendingError() { + return new RequestFailedError( + 'http://project-history/project/x/flush', + { method: 'POST' }, + { status: 422 } + ) + } + function sendHistoryRequest(ctx, options = {}) { return ctx.ClsiManager.promises.sendRequest( null, @@ -692,16 +699,38 @@ describe('ClsiManager', function () { }) }) - describe('when a resync is pending', function () { + describe('when the flush reports a pending resync then succeeds', function () { beforeEach(async function (ctx) { - ctx.HistoryManager.promises.ensureNoResyncPending.rejects( - new Errors.HistoryResyncPendingError( - 'broken history with pending resync' - ) + ctx.HistoryManager.promises.flushProject + .onFirstCall() + .rejects(makeResyncPendingError()) + .onSecondCall() + .resolves() + ctx.result = await sendHistoryRequest(ctx, { baseHistoryVersion: -1 }) + }) + + it('should compile from history without downgrading', function (ctx) { + expect(ctx.HistoryManager.promises.flushProject.callCount).to.equal(2) + expect(ctx.HistoryManager.promises.getLatestHistoryWithHistoryId).to + .have.been.called + expect(ctx.DocumentUpdaterHandler.promises.getProjectDocsIfMatch).to + .not.have.been.called + expect(ctx.result.status).to.equal('success') + }) + }) + + describe('when the flush reports a pending resync', function () { + beforeEach(async function (ctx) { + ctx.HistoryManager.promises.flushProject.rejects( + makeResyncPendingError() ) ctx.result = await sendHistoryRequest(ctx, { baseHistoryVersion: -1 }) }) + it('should retry the flush, the resync updates may arrive', function (ctx) { + expect(ctx.HistoryManager.promises.flushProject.callCount).to.equal(3) + }) + it('should fall back to a legacy compile', function (ctx) { expect( ctx.DocumentUpdaterHandler.promises.getProjectDocsIfMatch diff --git a/services/web/test/unit/src/History/HistoryManager.sequential.test.mjs b/services/web/test/unit/src/History/HistoryManager.sequential.test.mjs index baa6c86cee..bc17b5dc76 100644 --- a/services/web/test/unit/src/History/HistoryManager.sequential.test.mjs +++ b/services/web/test/unit/src/History/HistoryManager.sequential.test.mjs @@ -200,27 +200,6 @@ describe('HistoryManager', function () { }) }) - describe('ensureNoResyncPending', function () { - const projectId = 'project-123' - - it('should resolve when no resync is pending', async function (ctx) { - ctx.FetchUtils.fetchJson.resolves({ resyncPending: false }) - await ctx.HistoryManager.promises.ensureNoResyncPending(projectId) - ctx.FetchUtils.fetchJson.should.have.been.calledWithMatch( - `${ctx.settings.apis.project_history.url}/project/${projectId}/resync-pending` - ) - }) - - it('should throw a HistoryResyncPendingError when a resync is pending', async function (ctx) { - ctx.FetchUtils.fetchJson.resolves({ resyncPending: true }) - const error = await ctx.HistoryManager.promises - .ensureNoResyncPending(projectId) - .catch(err => err) - expect(error).to.be.an('error') - expect(error.name).to.equal('HistoryResyncPendingError') - }) - }) - describe('injectUserDetails', function () { beforeEach(function (ctx) { ctx.user1 = {