From 70a90690158b9bc0bf4182c28c4c901228f9d49c Mon Sep 17 00:00:00 2001 From: Jakob Ackermann Date: Mon, 6 Jul 2026 12:14:37 +0200 Subject: [PATCH] [web] add retries to history calls in compile from history (#35191) * [web] add retries to history calls in compile from history * [web] address review feedback GitOrigin-RevId: f22e0d1515dd22a0a43a0faf28c370e4f196e1da --- .../app/src/Features/Compile/ClsiManager.mjs | 67 ++++- .../web/app/src/Features/Errors/Errors.js | 3 + .../src/Features/History/HistoryManager.mjs | 8 +- .../unit/src/Compile/ClsiManager.test.mjs | 259 +++++++++++------- .../HistoryManager.sequential.test.mjs | 21 ++ 5 files changed, 251 insertions(+), 107 deletions(-) diff --git a/services/web/app/src/Features/Compile/ClsiManager.mjs b/services/web/app/src/Features/Compile/ClsiManager.mjs index 23eaf6230d..fe815129c4 100644 --- a/services/web/app/src/Features/Compile/ClsiManager.mjs +++ b/services/web/app/src/Features/Compile/ClsiManager.mjs @@ -43,6 +43,10 @@ const CLSI_COOKIES_ENABLED = (Settings.clsiCookie?.key ?? '') !== '' // The timeout in services/clsi/app.js is 10 minutes, so we'll be on the safe side with 12 minutes const COMPILE_REQUEST_TIMEOUT_MS = 12 * 60 * 1000 +// Number of times to attempt each project-history operation (flush, chunk +// fetch) when compiling from history before giving up. +const HISTORY_MAX_ATTEMPTS = 3 + // Enable clsi-cache for all compiles for 20min when detecting low capacity. const ENABLE_COMPILE_FROM_CACHE_ON_503_MS = 20 * 60 * 1000 let enableCompileFromCacheUntil = 0 @@ -924,13 +928,57 @@ function collectGlobalBlobsFromRawSnapshot(rawSnapshot, globalBlobs) { } } +/** + * Run an async project-history operation. + * + * Try at most HISTORY_MAX_ATTEMPTS times before throwing an error. + * + * @template T + * @param {() => Promise} fn + * @param {string} metricName + * @param {string} msg + * @param {object} info + * @return {Promise} + */ +async function withRetries(fn, metricName, msg, info) { + let lastErr + for (let attempt = 1; attempt <= HISTORY_MAX_ATTEMPTS; attempt++) { + if (lastErr) { + Metrics.inc(metricName) + logger.warn({ err: lastErr, attempt, ...info }, `${msg}, retrying`) + } + try { + return await fn() + } catch (err) { + lastErr = err + } + } + throw OError.tag(lastErr, msg, info) +} + +/** + * Flush pending updates to project-history before compiling from history, + * retrying on any error. + * + * @param {string} projectId + * @param {string} historyId + */ +async function _flushHistoryForCompile(projectId, historyId) { + await withRetries( + () => HistoryManager.promises.flushProject(projectId), + 'compile-from-history-flush-retry', + 'failed to flush project for compile-from-history', + { projectId, historyId } + ) +} + async function _buildRequestFromHistoryFull( projectId, historyId, options, project ) { - await HistoryManager.promises.flushProject(projectId) + await _flushHistoryForCompile(projectId, historyId) const [ { chunk: { @@ -940,7 +988,12 @@ async function _buildRequestFromHistoryFull( }, /* ensureNoResyncPending throws */ ] = await Promise.all([ - HistoryManager.promises.getLatestHistoryWithHistoryId(historyId), + withRetries( + () => HistoryManager.promises.getLatestHistoryWithHistoryId(historyId), + 'compile-from-history-chunk-retry', + 'failed to get history chunk', + { projectId, historyId } + ), HistoryManager.promises.ensureNoResyncPending(projectId), ]) const rawChangeOperations = _rawChangeOperationsFromChanges(rawChanges) @@ -965,7 +1018,7 @@ async function _buildRequestFromHistoryIncremental( project, baseHistoryVersion ) { - await HistoryManager.promises.flushProject(projectId) + await _flushHistoryForCompile(projectId, historyId) const rawChangeOperations = [] let hasMore = true let since = baseHistoryVersion @@ -973,7 +1026,13 @@ async function _buildRequestFromHistoryIncremental( while (hasMore) { let changes ;[{ changes, hasMore } /* resyncPending throws */] = await Promise.all([ - HistoryManager.promises.getChangesWithHistoryId(historyId, { since }), + withRetries( + () => + HistoryManager.promises.getChangesWithHistoryId(historyId, { since }), + 'compile-from-history-changes-retry', + 'failed to get history changes', + { projectId, historyId, since } + ), HistoryManager.promises.ensureNoResyncPending(projectId), ]) since += changes.length diff --git a/services/web/app/src/Features/Errors/Errors.js b/services/web/app/src/Features/Errors/Errors.js index 313ab60bee..fbb5cf35b7 100644 --- a/services/web/app/src/Features/Errors/Errors.js +++ b/services/web/app/src/Features/Errors/Errors.js @@ -68,6 +68,8 @@ class V1HistoryNotSyncedError extends BackwardCompatibleError {} class ProjectHistoryDisabledError extends BackwardCompatibleError {} +class HistoryResyncPendingError extends OError {} + class V1ConnectionError extends BackwardCompatibleError {} class UnconfirmedEmailError extends BackwardCompatibleError {} @@ -405,6 +407,7 @@ 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 b6ea680de0..0e95daa197 100644 --- a/services/web/app/src/Features/History/HistoryManager.mjs +++ b/services/web/app/src/Features/History/HistoryManager.mjs @@ -14,7 +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 } from '../Errors/Errors.js' +import { NotFoundError, HistoryResyncPendingError } from '../Errors/Errors.js' const HISTORY_V1_URL = settings.apis.v1_history.url const HISTORY_V1_BASIC_AUTH = { @@ -323,7 +323,11 @@ async function ensureNoResyncPending(projectId) { const { resyncPending } = await fetchJson( `${settings.apis.project_history.url}/project/${projectId}/resync-pending` ) - if (resyncPending) throw new OError('broken history with pending resync') + if (resyncPending) { + throw new HistoryResyncPendingError('broken history with pending resync', { + projectId, + }) + } } async function getDebugInfo(projectId) { diff --git a/services/web/test/unit/src/Compile/ClsiManager.test.mjs b/services/web/test/unit/src/Compile/ClsiManager.test.mjs index 77017de9f4..f5740cf188 100644 --- a/services/web/test/unit/src/Compile/ClsiManager.test.mjs +++ b/services/web/test/unit/src/Compile/ClsiManager.test.mjs @@ -3,6 +3,7 @@ import { setTimeout } from 'node:timers/promises' import sinon from 'sinon' import tk from 'timekeeper' import { RequestFailedError } from '@overleaf/fetch-utils' +import Errors from '../../../../app/src/Features/Errors/Errors.js' import _ from 'lodash' const FILESTORE_URL = 'http://filestore.example.com' @@ -204,6 +205,16 @@ describe('ClsiManager', function () { ctx.HistoryManager = { promises: { flushProject: sinon.stub().resolves(), + getLatestHistoryWithHistoryId: sinon.stub().resolves({ + chunk: { + history: { snapshot: { files: {} }, changes: [] }, + startVersion: 0, + }, + }), + getChangesWithHistoryId: sinon + .stub() + .resolves({ changes: [], hasMore: false }), + ensureNoResyncPending: sinon.stub().resolves(), }, getFilestoreBlobURL: sinon.stub().callsFake((historyId, hash) => { if (hash === GLOBAL_BLOB_HASH) { @@ -290,6 +301,12 @@ describe('ClsiManager', function () { default: ctx.HistoryManager, })) + // Re-export the real Errors module so instanceof checks in ClsiManager use + // the same class instances as this test. + vi.doMock('../../../../app/src/Features/Errors/Errors.js', () => ({ + default: Errors, + })) + vi.doMock( '../../../../app/src/Features/Analytics/AnalyticsManager', () => ({ @@ -517,10 +534,36 @@ describe('ClsiManager', function () { }) }) - describe('with compile from history fallback to incremental', function () { + describe('with compile from history', function () { const buildId = '18fbe9e7564-30dcb2f71250c690' - beforeEach(async function (ctx) { + function makeLockedError() { + return new RequestFailedError( + 'http://project-history/project/x/flush', + { method: 'POST' }, + { status: 423 }, + '{"message":"redis lock is taken"}' + ) + } + + function sendHistoryRequest(ctx, options = {}) { + return ctx.ClsiManager.promises.sendRequest( + null, + ctx.project._id, + ctx.user_id, + { + compileBackendClass: 'free', + compileGroup: 'standard', + timeout: 100, + compileFromHistory: true, + incrementalCompilesEnabled: true, + rootResourcePath: 'main.tex', + ...options, + } + ) + } + + beforeEach(function (ctx) { ctx.outputFiles = [ { url: `/project/${ctx.project_id}/user/${ctx.user_id}/build/${buildId}/output/output.pdf`, @@ -542,8 +585,8 @@ describe('ClsiManager', function () { }) ) ctx.responseBody.compile.buildId = buildId - ctx.timeout = 100 - ctx.HistoryManager.promises.flushProject.rejects() + + // stubs for the legacy compile fallback path const doc = ctx.docs['/main.tex'] ctx.DocumentUpdaterHandler.promises.getProjectDocsIfMatch.resolves([ { _id: doc._id, lines: doc.lines, v: 123 }, @@ -551,119 +594,133 @@ describe('ClsiManager', function () { ctx.ProjectEntityHandler.getAllDocPathsFromProject.returns({ 'mock-doc-id-1': 'main.tex', }) - ctx.result = await ctx.ClsiManager.promises.sendRequest( - null, - ctx.project._id, - ctx.user_id, - { - compileBackendClass: 'free', - compileGroup: 'standard', - timeout: ctx.timeout, - compileFromHistory: true, - incrementalCompilesEnabled: true, - } - ) }) - it('should send the request to the CLSI', function (ctx) { - const doc = ctx.docs['/main.tex'] - ctx.FetchUtils.fetchStringWithResponse.should.have.been.calledWith( - sinon.match( - url => - url.host === CLSI_HOST && - url.pathname === - `/project/${ctx.project._id}/user/${ctx.user_id}/compile` && - url.searchParams.get('compileBackendClass') === 'free' && - url.searchParams.get('compileGroup') === 'standard' - ), - { - method: 'POST', - json: sinon.match({ - compile: { - options: { - compiler: ctx.project.compiler, - imageName: ctx.project.imageName, - timeout: ctx.timeout, - draft: false, - compileGroup: 'standard', - metricsMethod: 'standard', - stopOnFirstError: false, - syncType: 'incremental', - syncState: '01234567890abcdef', - }, - rootResourcePath: 'main.tex', - resources: [ - { path: 'main.tex', content: doc.lines.join('\n') }, - ], - }, - }), - headers: { - Accept: 'application/json', - 'Content-Type': 'application/json', - Cookie: `${ctx.clsiCookieKey}=${ctx.clsiServerId}`, - }, - signal: sinon.match.instanceOf(AbortSignal), - } - ) - }) + describe('when the flush fails then succeeds', function () { + beforeEach(async function (ctx) { + ctx.HistoryManager.promises.flushProject + .onFirstCall() + .rejects(makeLockedError()) + .onSecondCall() + .resolves() + ctx.result = await sendHistoryRequest(ctx, { baseHistoryVersion: -1 }) + }) - it('should compute the hash with the full project', function (ctx) { - ctx.ClsiStateManager.computeHash.should.have.been.calledWithMatch({ - rootFolder: ctx.project.rootFolder, + it('should retry the flush', function (ctx) { + expect(ctx.HistoryManager.promises.flushProject.callCount).to.equal(2) + }) + + it('should compile from history without downgrading', function (ctx) { + 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') }) }) - it('should get the project with the required fields', function (ctx) { - ctx.ProjectGetter.promises.getProject.should.have.been.calledWith( - ctx.project._id, - { - compiler: 1, - rootDoc_id: 1, - imageName: 1, - rootFolder: 1, - 'overleaf.history.id': 1, - } - ) + describe('when the flush fails on every attempt', function () { + beforeEach(async function (ctx) { + // any error is retried, not just a locked (423) response + ctx.HistoryManager.promises.flushProject.rejects(new Error('boom')) + ctx.result = await sendHistoryRequest(ctx, { baseHistoryVersion: -1 }) + }) + + it('should retry up to the maximum before giving up', 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 + ).to.have.been.calledWith(ctx.project._id) + expect(ctx.result.status).to.equal('success') + }) }) - it('should get only the live docs from the docupdater with a background flush in docupdater', function (ctx) { - ctx.DocumentUpdaterHandler.promises.getProjectDocsIfMatch.should.have.been.calledWith( - ctx.project._id - ) + describe('when getting the latest history fails once (full sync)', function () { + beforeEach(async function (ctx) { + ctx.HistoryManager.promises.getLatestHistoryWithHistoryId + .onFirstCall() + .rejects(new Error('history-v1 unavailable')) + ctx.result = await sendHistoryRequest(ctx, { baseHistoryVersion: -1 }) + }) + + it('should retry the chunk fetch once and succeed', function (ctx) { + expect( + ctx.HistoryManager.promises.getLatestHistoryWithHistoryId.callCount + ).to.equal(2) + expect(ctx.result.status).to.equal('success') + }) }) - it('should not get any docs from mongo', function (ctx) { - ctx.ProjectEntityHandler.promises.getAllDocs.should.not.have.been.calledWith( - ctx.project._id - ) + describe('when getting changes fails once (incremental sync)', function () { + beforeEach(async function (ctx) { + ctx.HistoryManager.promises.getChangesWithHistoryId + .onFirstCall() + .rejects(new Error('history-v1 unavailable')) + ctx.result = await sendHistoryRequest(ctx, { baseHistoryVersion: 5 }) + }) + + it('should retry the chunk fetch once and succeed', function (ctx) { + expect( + ctx.HistoryManager.promises.getChangesWithHistoryId.callCount + ).to.equal(2) + expect(ctx.result.status).to.equal('success') + }) }) - it('should not get any of the files', function (ctx) { - ctx.ProjectEntityHandler.promises.getAllFiles.should.not.have.been - .called + describe('when getting the chunk fails on every attempt', function () { + beforeEach(async function (ctx) { + ctx.HistoryManager.promises.getLatestHistoryWithHistoryId.rejects( + new Error('history-v1 unavailable') + ) + ctx.result = await sendHistoryRequest(ctx, { baseHistoryVersion: -1 }) + }) + + it('should retry up to the maximum before giving up', function (ctx) { + expect( + ctx.HistoryManager.promises.getLatestHistoryWithHistoryId.callCount + ).to.equal(3) + }) + + it('should fall back to a legacy compile', function (ctx) { + expect( + ctx.DocumentUpdaterHandler.promises.getProjectDocsIfMatch + ).to.have.been.calledWith(ctx.project._id) + expect(ctx.result.status).to.equal('success') + }) }) - it('should return the status and output files', function (ctx) { - expect(ctx.result.status).to.equal('success') - expect(ctx.result.outputFiles.map(f => f.path)).to.have.members( - ctx.outputFiles.map(f => f.path) - ) - }) + describe('when a resync is pending', function () { + beforeEach(async function (ctx) { + ctx.HistoryManager.promises.ensureNoResyncPending.rejects( + new Errors.HistoryResyncPendingError( + 'broken history with pending resync' + ) + ) + ctx.result = await sendHistoryRequest(ctx, { baseHistoryVersion: -1 }) + }) - it('should return the buildId', function (ctx) { - expect(ctx.result.buildId).to.equal(buildId) - }) + it('should fall back to a legacy compile', function (ctx) { + expect( + ctx.DocumentUpdaterHandler.promises.getProjectDocsIfMatch + ).to.have.been.calledWith(ctx.project._id) + expect(ctx.result.status).to.equal('success') + }) - it('should persist the cookie from the response', function (ctx) { - expect( - ctx.ClsiCookieManager.promises.setServerId - ).to.have.been.calledWith( - ctx.project._id, - ctx.user_id, - 'standard', - 'free', - `${ctx.newClsiServerId}1` - ) + it('should get the project with the legacy compile fields', function (ctx) { + ctx.ProjectGetter.promises.getProject.should.have.been.calledWith( + ctx.project._id, + { + compiler: 1, + rootDoc_id: 1, + imageName: 1, + rootFolder: 1, + 'overleaf.history.id': 1, + } + ) + }) }) }) 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 cf5929558e..d527a1251a 100644 --- a/services/web/test/unit/src/History/HistoryManager.sequential.test.mjs +++ b/services/web/test/unit/src/History/HistoryManager.sequential.test.mjs @@ -191,6 +191,27 @@ 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 = {