import { promisify } from 'util' import logger from '@overleaf/logger' import async from 'async' import metrics from '@overleaf/metrics' import Settings from '@overleaf/settings' import OError from '@overleaf/o-error' import * as HistoryStoreManager from './HistoryStoreManager.js' import * as UpdateTranslator from './UpdateTranslator.js' import * as BlobManager from './BlobManager.js' import * as RedisManager from './RedisManager.js' import * as ErrorRecorder from './ErrorRecorder.js' import * as LockManager from './LockManager.js' import * as UpdateCompressor from './UpdateCompressor.js' import * as WebApiManager from './WebApiManager.js' import * as SyncManager from './SyncManager.js' import * as Versions from './Versions.js' import * as Errors from './Errors.js' import { Profiler } from './Profiler.js' const keys = Settings.redis.lock.key_schema export const REDIS_READ_BATCH_SIZE = 500 /** * Container for functions that need to be mocked in tests * * TODO: Rewrite tests in terms of exported functions only */ export const _mocks = {} export function getRawUpdates(projectId, batchSize, callback) { RedisManager.getRawUpdatesBatch(projectId, batchSize, (error, batch) => { if (error != null) { return callback(OError.tag(error)) } let updates try { updates = RedisManager.parseDocUpdates(batch.rawUpdates) } catch (error) { return callback(OError.tag(error)) } _getHistoryId(projectId, updates, (error, historyId) => { if (error != null) { return callback(OError.tag(error)) } HistoryStoreManager.getMostRecentChunk( projectId, historyId, (error, chunk) => { if (error != null) { return callback(OError.tag(error)) } callback(null, { project_id: projectId, chunk, updates }) } ) }) }) } // Process all updates for a project, only check project-level information once export function processUpdatesForProject(projectId, callback) { LockManager.runWithLock( keys.projectHistoryLock({ project_id: projectId }), (extendLock, releaseLock) => { _countAndProcessUpdates( projectId, extendLock, REDIS_READ_BATCH_SIZE, releaseLock ) }, (error, queueSize) => { if (error) { OError.tag(error) } ErrorRecorder.record(projectId, queueSize, error, callback) // clear the timestamp in the background if the queue is now empty RedisManager.clearDanglingFirstOpTimestamp(projectId, () => {}) } ) } export function processUpdatesForProjectUsingBisect( projectId, amountToProcess, callback ) { LockManager.runWithLock( keys.projectHistoryLock({ project_id: projectId }), (extendLock, releaseLock) => { _countAndProcessUpdates( projectId, extendLock, amountToProcess, releaseLock ) }, (error, queueSize) => { if (amountToProcess === 0 || queueSize === 0) { // no further processing possible if (error != null) { ErrorRecorder.record( projectId, queueSize, OError.tag(error), callback ) } else { callback() } } else { if (error != null) { // decrease the batch size when we hit an error processUpdatesForProjectUsingBisect( projectId, Math.floor(amountToProcess / 2), callback ) } else { // otherwise continue processing with the same batch size processUpdatesForProjectUsingBisect( projectId, amountToProcess, callback ) } } } ) } export function processSingleUpdateForProject(projectId, callback) { LockManager.runWithLock( keys.projectHistoryLock({ project_id: projectId }), ( extendLock, releaseLock // set the batch size to 1 for single-stepping ) => { _countAndProcessUpdates(projectId, extendLock, 1, releaseLock) }, ( error, queueSize // no need to clear the flush marker when single stepping ) => { // it will be cleared up on the next background flush if // the queue is empty ErrorRecorder.record(projectId, queueSize, error, callback) } ) } _mocks._countAndProcessUpdates = ( projectId, extendLock, batchSize, callback ) => { RedisManager.countUnprocessedUpdates(projectId, (error, queueSize) => { if (error != null) { return callback(OError.tag(error)) } if (queueSize > 0) { logger.debug({ projectId, queueSize }, 'processing uncompressed updates') RedisManager.getUpdatesInBatches( projectId, batchSize, (updates, cb) => { _processUpdatesBatch(projectId, updates, extendLock, cb) }, error => { // Unconventional callback signature. The caller needs the queue size // even when an error is thrown in order to record the queue size in // the projectHistoryFailures collection. We'll have to find another // way to achieve this when we promisify. callback(error, queueSize) } ) } else { logger.debug({ projectId }, 'no updates to process') callback(null, queueSize) } }) } function _countAndProcessUpdates(...args) { _mocks._countAndProcessUpdates(...args) } 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) => { if (error != null) { return callback(OError.tag(error)) } if (historyId == null) { logger.debug( { projectId }, 'discarding updates as project does not use history' ) return callback() } _processUpdates(projectId, historyId, updates, extendLock, error => { if (error != null) { return callback(OError.tag(error)) } callback() }) }) } export function _getHistoryId(projectId, updates, callback) { let idFromUpdates = null // check that all updates have the same history id for (const update of updates) { if (update.projectHistoryId != null) { if (idFromUpdates == null) { idFromUpdates = update.projectHistoryId.toString() } else if (idFromUpdates !== update.projectHistoryId.toString()) { metrics.inc('updates.batches.project-history-id.inconsistent-update') logger.warn( { projectId, updates, idFromUpdates, currentId: update.projectHistoryId, }, 'inconsistent project history id between updates' ) return callback( new OError('inconsistent project history id between updates') ) } } } WebApiManager.getHistoryId(projectId, (error, idFromWeb) => { if (error != null && idFromUpdates != null) { // present only on updates // 404s from web are an error metrics.inc('updates.batches.project-history-id.from-updates') return callback(null, idFromUpdates) } else if (error != null) { return callback(OError.tag(error)) } if (idFromWeb == null && idFromUpdates == null) { // present on neither web nor updates callback(null, null) } else if (idFromWeb != null && idFromUpdates == null) { // present only on web metrics.inc('updates.batches.project-history-id.from-web') callback(null, idFromWeb) } else if (idFromWeb == null && idFromUpdates != null) { // present only on updates metrics.inc('updates.batches.project-history-id.from-updates') callback(null, idFromUpdates) } else if (idFromWeb.toString() !== idFromUpdates.toString()) { // inconsistent between web and updates metrics.inc('updates.batches.project-history-id.inconsistent-with-web') logger.warn( { projectId, idFromWeb, idFromUpdates, updates, }, 'inconsistent project history id between updates and web' ) callback( new OError('inconsistent project history id between updates and web') ) } else { // the same on web and updates metrics.inc('updates.batches.project-history-id.from-updates') callback(null, idFromWeb) } }) } function _handleOpsOutOfOrderError(projectId, projectHistoryId, err, ...rest) { const adjustedLength = Math.max(rest.length, 1) const results = rest.slice(0, adjustedLength - 1) const callback = rest[adjustedLength - 1] ErrorRecorder.getFailureRecord(projectId, (error, failureRecord) => { if (error != null) { return callback(error) } // Bypass ops-out-of-order errors in the stored chunk when in forceDebug mode if (failureRecord != null && failureRecord.forceDebug === true) { logger.warn( { projectId, projectHistoryId }, 'ops out of order in chunk, forced continue' ) callback(null, ...results) // return results without error } else { logger.warn( { projectId, projectHistoryId }, 'ops out of order in chunk, returning error' ) callback(err, ...results) } }) } function _getMostRecentVersionWithDebug(projectId, projectHistoryId, callback) { HistoryStoreManager.getMostRecentVersion( projectId, projectHistoryId, (err, ...results) => { if (err instanceof Errors.OpsOutOfOrderError) { _handleOpsOutOfOrderError( projectId, projectHistoryId, err, ...results, callback ) } else { callback(err, ...results) } } ) } export function _processUpdates( projectId, projectHistoryId, updates, extendLock, callback ) { const profile = new Profiler('_processUpdates', { project_id: projectId, projectHistoryId, }) // skip updates first if we're in a sync, we might not need to do anything else SyncManager.skipUpdatesDuringSync( projectId, updates, (error, filteredUpdates, newSyncState) => { profile.log('skipUpdatesDuringSync') if (error != null) { return callback(error) } if (filteredUpdates.length === 0) { // return early if there are no updates to apply return SyncManager.setResyncState(projectId, newSyncState, callback) } // only make request to history service if we have actual updates to process _getMostRecentVersionWithDebug( projectId, projectHistoryId, (error, baseVersion, projectStructureAndDocVersions) => { if (projectStructureAndDocVersions == null) { projectStructureAndDocVersions = { project: null, docs: {} } } profile.log('getMostRecentVersion') if (error != null) { return callback(error) } async.waterfall( [ cb => { cb = profile.wrap('expandSyncUpdates', cb) SyncManager.expandSyncUpdates( projectId, projectHistoryId, filteredUpdates, extendLock, cb ) }, (expandedUpdates, cb) => { let unappliedUpdates try { unappliedUpdates = _skipAlreadyAppliedUpdates( projectId, expandedUpdates, projectStructureAndDocVersions ) } catch (err) { return cb(err) } profile.log('skipAlreadyAppliedUpdates') const compressedUpdates = UpdateCompressor.compressRawUpdates(unappliedUpdates) const timeTaken = profile .log('compressRawUpdates') .getTimeDelta() if (timeTaken >= 1000) { logger.debug( { projectId, updates: unappliedUpdates, timeTaken }, 'slow compression of raw updates' ) } cb = profile.wrap('createBlobs', cb) BlobManager.createBlobsForUpdates( projectId, projectHistoryId, compressedUpdates, extendLock, cb ) }, (updatesWithBlobs, cb) => { let changes try { changes = UpdateTranslator.convertToChanges( projectId, updatesWithBlobs ).map(change => change.toRaw()) } catch (err) { return cb(err) } finally { profile.log('convertToChanges') } cb(null, changes) }, (changes, cb) => { let change const numChanges = changes.length const byteLength = Buffer.byteLength( JSON.stringify(changes), 'utf8' ) let numOperations = 0 for (change of changes) { if (change.operations != null) { numOperations += change.operations.length } } metrics.timing('history-store.request.changes', numChanges, 1) metrics.timing('history-store.request.bytes', byteLength, 1) metrics.timing( 'history-store.request.operations', numOperations, 1 ) // thresholds taken from write_latex/main/lib/history_exporter.rb if (numChanges > 1000) { metrics.inc('history-store.request.exceeds-threshold.changes') } if (byteLength > Math.pow(1024, 2)) { metrics.inc('history-store.request.exceeds-threshold.bytes') const changeLengths = changes.map(change => Buffer.byteLength(JSON.stringify(change), 'utf8') ) logger.warn( { projectId, byteLength, changeLengths }, 'change size exceeds limit' ) } cb = profile.wrap('sendChanges', cb) // this is usually the longest request, so extend the lock before starting it extendLock(error => { if (error != null) { return cb(error) } if (changes.length === 0) { return cb() } // avoid unnecessary requests to history service HistoryStoreManager.sendChanges( projectId, projectHistoryId, changes, baseVersion, cb ) }) }, cb => { cb = profile.wrap('setResyncState', cb) SyncManager.setResyncState(projectId, newSyncState, cb) }, ], error => { profile.end() callback(error) } ) } ) } ) } _mocks._skipAlreadyAppliedUpdates = ( projectId, updates, projectStructureAndDocVersions ) => { function alreadySeenProjectVersion(previousProjectStructureVersion, update) { return ( UpdateTranslator.isProjectStructureUpdate(update) && previousProjectStructureVersion != null && update.version != null && Versions.gte(previousProjectStructureVersion, update.version) ) } function alreadySeenDocVersion(previousDocVersions, update) { if (UpdateTranslator.isTextUpdate(update) && update.v != null) { const docId = update.doc return ( previousDocVersions[docId] != null && previousDocVersions[docId].v != null && Versions.gte(previousDocVersions[docId].v, update.v) ) } else { return false } } // check that the incoming updates are in the correct order (we do not // want to send out of order updates to the history service) let incomingProjectStructureVersion = null const incomingDocVersions = {} for (const update of updates) { if (alreadySeenProjectVersion(incomingProjectStructureVersion, update)) { logger.warn( { projectId, update, incomingProjectStructureVersion }, 'incoming project structure updates are out of order' ) throw new Errors.OpsOutOfOrderError( 'project structure version out of order on incoming updates' ) } else if (alreadySeenDocVersion(incomingDocVersions, update)) { logger.warn( { projectId, update, incomingDocVersions }, 'incoming doc updates are out of order' ) throw new Errors.OpsOutOfOrderError( 'doc version out of order on incoming updates' ) } // update the current project structure and doc versions if (UpdateTranslator.isProjectStructureUpdate(update)) { incomingProjectStructureVersion = update.version } else if (UpdateTranslator.isTextUpdate(update)) { incomingDocVersions[update.doc] = { v: update.v } } } // discard updates already applied const updatesToApply = [] const previousProjectStructureVersion = projectStructureAndDocVersions.project const previousDocVersions = projectStructureAndDocVersions.docs if (projectStructureAndDocVersions != null) { const updateProjectVersions = [] for (const update of updates) { if (update != null && update.version != null) { updateProjectVersions.push(update.version) } } logger.debug( { projectId, projectStructureAndDocVersions, updateProjectVersions }, 'comparing updates with existing project versions' ) } for (const update of updates) { if (alreadySeenProjectVersion(previousProjectStructureVersion, update)) { metrics.inc('updates.discarded_project_structure_version') logger.debug( { projectId, update, previousProjectStructureVersion }, 'discarding previously applied project structure update' ) continue } if (alreadySeenDocVersion(previousDocVersions, update)) { metrics.inc('updates.discarded_doc_version') logger.debug( { projectId, update, previousDocVersions }, 'discarding previously applied doc update' ) continue } // remove non-BMP characters from resync updates that have bypassed the normal docupdater flow _sanitizeUpdate(update) // if all checks above are ok then accept the update updatesToApply.push(update) } return updatesToApply } export function _skipAlreadyAppliedUpdates(...args) { return _mocks._skipAlreadyAppliedUpdates(...args) } function _sanitizeUpdate(update) { // adapted from docupdater's UpdateManager, we should clean these in docupdater // too but we already have queues with this problem so we will handle it here // too for robustness. // Replace high and low surrogate characters with 'replacement character' (\uFFFD) const removeBadChars = str => str.replace(/[\uD800-\uDFFF]/g, '\uFFFD') // clean up any bad chars in resync diffs if (update.op) { for (const op of update.op) { if (op.i != null) { op.i = removeBadChars(op.i) } } } // clean up any bad chars in resync new docs if (update.docLines != null) { update.docLines = removeBadChars(update.docLines) } return update } export const promises = { processUpdatesForProject: promisify(processUpdatesForProject), }