[project-history] report a resync that is still pending after a flush (#36122)

GitOrigin-RevId: ccd4390048c09f732531d2e02a40336fce88a952
This commit is contained in:
Jakob Ackermann
2026-09-17 11:45:55 +00:00
committed by Copybot
parent 9be1b4edb4
commit eb36edac6d
19 changed files with 588 additions and 151 deletions
@@ -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',
@@ -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 {}
@@ -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({
+15 -5
View File
@@ -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 {
@@ -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) => {
@@ -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 (
@@ -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 () {
@@ -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()
@@ -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([])
})
})
})
})
@@ -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)
}
@@ -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)
})
@@ -59,7 +59,7 @@ describe('RetryManager', function () {
},
{
project_id: this.projectId6,
error: 'OError: sync ongoing',
error: 'SyncOngoingError: sync ongoing',
attempts: 10,
resyncAttempts: 2,
},
@@ -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 () {
@@ -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
})
})
})
@@ -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
@@ -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,
@@ -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,
},
@@ -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
@@ -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 = {