From 2cd7b615bfe317f5eacaf1dc86475febc42d8396 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Thu, 30 Sep 2021 09:28:32 +0100 Subject: [PATCH] Merge pull request #5159 from overleaf/bg-docupdater-log-relevelling docupdater log re-levelling GitOrigin-RevId: c27478d48f1cb1eae022086fe7af9fe55dfacfa0 --- services/document-updater/app.js | 142 +++++++++--------- .../app/js/DeleteQueueManager.js | 15 +- .../app/js/DispatchManager.js | 8 +- .../app/js/DocumentManager.js | 18 +-- .../document-updater/app/js/HistoryManager.js | 10 +- .../app/js/HistoryRedisManager.js | 5 +- .../document-updater/app/js/HttpController.js | 60 ++++---- services/document-updater/app/js/Profiler.js | 2 +- .../document-updater/app/js/ProjectFlusher.js | 7 +- .../app/js/ProjectHistoryRedisManager.js | 8 +- .../document-updater/app/js/ProjectManager.js | 4 +- .../document-updater/app/js/RangesManager.js | 6 +- .../app/js/RateLimitManager.js | 4 +- .../document-updater/app/js/RedisManager.js | 14 +- .../app/js/ShareJsUpdateManager.js | 8 +- .../document-updater/app/js/UpdateManager.js | 4 +- .../document-updater/app/js/sharejs/model.js | 2 - .../app/js/sharejs/server/model.js | 2 - .../app/js/sharejs/types/model.js | 2 - .../DispatchManager/DispatchManagerTests.js | 4 +- .../js/HttpController/HttpControllerTests.js | 24 +-- .../js/RangesManager/RangesManagerTests.js | 4 +- .../unit/js/RedisManager/RedisManagerTests.js | 4 +- 23 files changed, 181 insertions(+), 176 deletions(-) diff --git a/services/document-updater/app.js b/services/document-updater/app.js index 61f254d7f2..92121cb299 100644 --- a/services/document-updater/app.js +++ b/services/document-updater/app.js @@ -30,79 +30,11 @@ Metrics.mongodb.monitor( Metrics.event_loop.monitor(logger, 100) const app = express() -app.use(Metrics.http.monitor(logger)) app.use(bodyParser.json({ limit: Settings.maxJsonRequestSize })) Metrics.injectMetricsRoute(app) DispatchManager.createAndStartDispatchers(Settings.dispatcherCount) -app.param('project_id', (req, res, next, projectId) => { - if (projectId != null && projectId.match(/^[0-9a-f]{24}$/)) { - return next() - } else { - return next(new Error('invalid project id')) - } -}) - -app.param('doc_id', (req, res, next, docId) => { - if (docId != null && docId.match(/^[0-9a-f]{24}$/)) { - return next() - } else { - return next(new Error('invalid doc id')) - } -}) - -app.get('/project/:project_id/doc/:doc_id', HttpController.getDoc) -app.get('/project/:project_id/doc/:doc_id/peek', HttpController.peekDoc) -// temporarily keep the GET method for backwards compatibility -app.get('/project/:project_id/doc', HttpController.getProjectDocsAndFlushIfOld) -// will migrate to the POST method of get_and_flush_if_old instead -app.post( - '/project/:project_id/get_and_flush_if_old', - HttpController.getProjectDocsAndFlushIfOld -) -app.post('/project/:project_id/clearState', HttpController.clearProjectState) -app.post('/project/:project_id/doc/:doc_id', HttpController.setDoc) -app.post( - '/project/:project_id/doc/:doc_id/flush', - HttpController.flushDocIfLoaded -) -app.delete('/project/:project_id/doc/:doc_id', HttpController.deleteDoc) -app.delete('/project/:project_id', HttpController.deleteProject) -app.delete('/project', HttpController.deleteMultipleProjects) -app.post('/project/:project_id', HttpController.updateProject) -app.post( - '/project/:project_id/history/resync', - HttpController.resyncProjectHistory -) -app.post('/project/:project_id/flush', HttpController.flushProject) -app.post( - '/project/:project_id/doc/:doc_id/change/:change_id/accept', - HttpController.acceptChanges -) -app.post( - '/project/:project_id/doc/:doc_id/change/accept', - HttpController.acceptChanges -) -app.delete( - '/project/:project_id/doc/:doc_id/comment/:comment_id', - HttpController.deleteComment -) - -app.get('/flush_all_projects', HttpController.flushAllProjects) -app.get('/flush_queued_projects', HttpController.flushQueuedProjects) - -app.get('/total', (req, res, next) => { - const timer = new Metrics.Timer('http.allDocList') - RedisManager.getCountOfDocsInMemory((err, count) => { - if (err) { - return next(err) - } - timer.done() - res.send({ total: count }) - }) -}) - app.get('/status', (req, res) => { if (Settings.shuttingDown) { return res.sendStatus(503) // Service unavailable @@ -177,6 +109,76 @@ app.get('/health_check', (req, res, next) => { ) }) +// record http metrics for the routes below this point +app.use(Metrics.http.monitor(logger)) + +app.param('project_id', (req, res, next, projectId) => { + if (projectId != null && projectId.match(/^[0-9a-f]{24}$/)) { + return next() + } else { + return next(new Error('invalid project id')) + } +}) + +app.param('doc_id', (req, res, next, docId) => { + if (docId != null && docId.match(/^[0-9a-f]{24}$/)) { + return next() + } else { + return next(new Error('invalid doc id')) + } +}) + +app.get('/project/:project_id/doc/:doc_id', HttpController.getDoc) +app.get('/project/:project_id/doc/:doc_id/peek', HttpController.peekDoc) +// temporarily keep the GET method for backwards compatibility +app.get('/project/:project_id/doc', HttpController.getProjectDocsAndFlushIfOld) +// will migrate to the POST method of get_and_flush_if_old instead +app.post( + '/project/:project_id/get_and_flush_if_old', + HttpController.getProjectDocsAndFlushIfOld +) +app.post('/project/:project_id/clearState', HttpController.clearProjectState) +app.post('/project/:project_id/doc/:doc_id', HttpController.setDoc) +app.post( + '/project/:project_id/doc/:doc_id/flush', + HttpController.flushDocIfLoaded +) +app.delete('/project/:project_id/doc/:doc_id', HttpController.deleteDoc) +app.delete('/project/:project_id', HttpController.deleteProject) +app.delete('/project', HttpController.deleteMultipleProjects) +app.post('/project/:project_id', HttpController.updateProject) +app.post( + '/project/:project_id/history/resync', + HttpController.resyncProjectHistory +) +app.post('/project/:project_id/flush', HttpController.flushProject) +app.post( + '/project/:project_id/doc/:doc_id/change/:change_id/accept', + HttpController.acceptChanges +) +app.post( + '/project/:project_id/doc/:doc_id/change/accept', + HttpController.acceptChanges +) +app.delete( + '/project/:project_id/doc/:doc_id/comment/:comment_id', + HttpController.deleteComment +) + +app.get('/flush_all_projects', HttpController.flushAllProjects) +app.get('/flush_queued_projects', HttpController.flushQueuedProjects) + +app.get('/total', (req, res, next) => { + const timer = new Metrics.Timer('http.allDocList') + RedisManager.getCountOfDocsInMemory((err, count) => { + if (err) { + return next(err) + } + timer.done() + res.send({ total: count }) + }) +}) + app.use((error, req, res, next) => { if (error instanceof Errors.NotFoundError) { return res.sendStatus(404) @@ -191,10 +193,10 @@ app.use((error, req, res, next) => { }) const shutdownCleanly = signal => () => { - logger.log({ signal }, 'received interrupt, cleaning up') + logger.info({ signal }, 'received interrupt, cleaning up') Settings.shuttingDown = true setTimeout(() => { - logger.log({ signal }, 'shutting down') + logger.info({ signal }, 'shutting down') process.exit() }, 10000) } diff --git a/services/document-updater/app/js/DeleteQueueManager.js b/services/document-updater/app/js/DeleteQueueManager.js index 492f8d3360..d88a9589a6 100644 --- a/services/document-updater/app/js/DeleteQueueManager.js +++ b/services/document-updater/app/js/DeleteQueueManager.js @@ -50,7 +50,7 @@ module.exports = DeleteQueueManager = { return callback(err) } if (timestamps.length === 0) { - logger.log( + logger.debug( { project_id }, 'skipping flush of queued project - no timestamps' ) @@ -67,7 +67,10 @@ module.exports = DeleteQueueManager = { return cb() } } - logger.log({ project_id, flushTimestamp }, 'flushing queued project') + logger.debug( + { project_id, flushTimestamp }, + 'flushing queued project' + ) return ProjectManager.flushAndDeleteProjectWithLocks( project_id, { skip_history_flush: false }, @@ -85,11 +88,11 @@ module.exports = DeleteQueueManager = { var flushNextProject = function () { const now = Date.now() if (now - startTime > options.timeout) { - logger.log('hit time limit on flushing old projects') + logger.debug('hit time limit on flushing old projects') return callback(null, count) } if (count > options.limit) { - logger.log('hit count limit on flushing old projects') + logger.debug('hit count limit on flushing old projects') return callback(null, count) } return RedisManager.getNextProjectToFlushAndDelete( @@ -101,7 +104,7 @@ module.exports = DeleteQueueManager = { if (project_id == null) { return callback(null, count) } - logger.log({ project_id, queueLength }, 'flushing queued project') + logger.debug({ project_id, queueLength }, 'flushing queued project') metrics.globalGauge('queued-flush-backlog', queueLength) return flushProjectIfNotModified( project_id, @@ -125,7 +128,7 @@ module.exports = DeleteQueueManager = { const LONG_DELAY = 1000 var doFlush = function () { if (Settings.shuttingDown) { - logger.warn('discontinuing background flush due to shutdown') + logger.info('discontinuing background flush due to shutdown') return } return DeleteQueueManager.flushAndDeleteOldProjects( diff --git a/services/document-updater/app/js/DispatchManager.js b/services/document-updater/app/js/DispatchManager.js index d567fade2e..0d47c66d63 100644 --- a/services/document-updater/app/js/DispatchManager.js +++ b/services/document-updater/app/js/DispatchManager.js @@ -44,7 +44,7 @@ module.exports = DispatchManager = { } const timer = new Metrics.Timer('worker.waiting') return worker.client.blpop(pendingListKey, 0, function (error, result) { - logger.log(`getting ${queueShardNumber}`, error, result) + logger.debug(`getting ${queueShardNumber}`, error, result) timer.done() if (error != null) { return callback(error) @@ -65,11 +65,11 @@ module.exports = DispatchManager = { // log everything except OpRangeNotAvailable errors, these are normal if (error != null) { // downgrade OpRangeNotAvailable and "Delete component" errors so they are not sent to sentry - const logAsWarning = + const logAsDebug = error instanceof Errors.OpRangeNotAvailableError || error instanceof Errors.DeleteMismatchError - if (logAsWarning) { - logger.warn( + if (logAsDebug) { + logger.debug( { err: error, project_id, doc_id }, 'error processing update' ) diff --git a/services/document-updater/app/js/DocumentManager.js b/services/document-updater/app/js/DocumentManager.js index b1384f642a..bb8c947548 100644 --- a/services/document-updater/app/js/DocumentManager.js +++ b/services/document-updater/app/js/DocumentManager.js @@ -63,7 +63,7 @@ module.exports = DocumentManager = { return callback(error) } if (lines == null || version == null) { - logger.log( + logger.debug( { project_id, doc_id }, 'doc not in redis so getting from persistence API' ) @@ -82,7 +82,7 @@ module.exports = DocumentManager = { if (error != null) { return callback(error) } - logger.log( + logger.debug( { project_id, doc_id, @@ -242,14 +242,14 @@ module.exports = DocumentManager = { oldLines.length > 0 && oldLines[0].text != null ) { - logger.log( + logger.debug( { doc_id, project_id, oldLines, newLines }, 'document is JSON so not updating' ) return callback(null) } - logger.log( + logger.debug( { doc_id, project_id, oldLines, newLines }, 'setting a document via http' ) @@ -350,13 +350,13 @@ module.exports = DocumentManager = { return callback(error) } if (lines == null || version == null) { - logger.log( + logger.debug( { project_id, doc_id }, 'doc is not loaded so not flushing' ) return callback(null) // TODO: return a flag to bail out, as we go on to remove doc from memory? } else { - logger.log({ project_id, doc_id, version }, 'flushing doc') + logger.debug({ project_id, doc_id, version }, 'flushing doc') return PersistenceManager.setDoc( project_id, doc_id, @@ -583,7 +583,7 @@ module.exports = DocumentManager = { }, resyncDocContents(project_id, doc_id, callback) { - logger.log({ project_id, doc_id }, 'start resyncing doc contents') + logger.debug({ project_id, doc_id }, 'start resyncing doc contents') return RedisManager.getDoc( project_id, doc_id, @@ -593,7 +593,7 @@ module.exports = DocumentManager = { } if (lines == null || version == null) { - logger.log( + logger.debug( { project_id, doc_id }, 'resyncing doc contents - not found in redis - retrieving from web' ) @@ -628,7 +628,7 @@ module.exports = DocumentManager = { } ) } else { - logger.log( + logger.debug( { project_id, doc_id }, 'resyncing doc contents - doc in redis - will queue in redis' ) diff --git a/services/document-updater/app/js/HistoryManager.js b/services/document-updater/app/js/HistoryManager.js index 107e81d979..e78441b14b 100644 --- a/services/document-updater/app/js/HistoryManager.js +++ b/services/document-updater/app/js/HistoryManager.js @@ -50,7 +50,7 @@ module.exports = HistoryManager = { } else { metrics.inc('history-flush', 1, { status: 'track-changes' }) const url = `${Settings.apis.trackchanges.url}/project/${project_id}/doc/${doc_id}/flush` - logger.log( + logger.debug( { project_id, doc_id, url, projectHistoryType }, 'flushing doc in track changes api' ) @@ -103,7 +103,7 @@ module.exports = HistoryManager = { return callback() } if (options.skip_history_flush) { - logger.log({ project_id }, 'skipping flush of project history') + logger.debug({ project_id }, 'skipping flush of project history') return callback() } metrics.inc('history-flush', 1, { status: 'project-history' }) @@ -112,7 +112,7 @@ module.exports = HistoryManager = { if (options.background) { qs.background = true } // pass on the background flush option if present - logger.log({ project_id, url, qs }, 'flushing doc in project history api') + logger.debug({ project_id, url, qs }, 'flushing doc in project history api') return request.post({ url, qs }, function (error, res, body) { if (error != null) { logger.error( @@ -169,7 +169,7 @@ module.exports = HistoryManager = { ) { // Do this in the background since it uses HTTP and so may be too // slow to wait for when processing a doc update. - logger.log( + logger.debug( { project_ops_length, project_id }, 'flushing project history api' ) @@ -205,7 +205,7 @@ module.exports = HistoryManager = { ) { // Do this in the background since it uses HTTP and so may be too // slow to wait for when processing a doc update. - logger.log( + logger.debug( { doc_ops_length, doc_id, project_id }, 'flushing track changes api' ) diff --git a/services/document-updater/app/js/HistoryRedisManager.js b/services/document-updater/app/js/HistoryRedisManager.js index 1979b89013..20cb051985 100644 --- a/services/document-updater/app/js/HistoryRedisManager.js +++ b/services/document-updater/app/js/HistoryRedisManager.js @@ -30,7 +30,10 @@ module.exports = HistoryRedisManager = { if (ops.length === 0) { return callback(new Error('cannot push no ops')) // This should never be called with no ops, but protect against a redis error if we sent an empty array to rpush } - logger.log({ project_id, doc_id }, 'marking doc in project for history ops') + logger.debug( + { project_id, doc_id }, + 'marking doc in project for history ops' + ) return rclient.sadd( Keys.docsWithHistoryOps({ project_id }), doc_id, diff --git a/services/document-updater/app/js/HttpController.js b/services/document-updater/app/js/HttpController.js index fd5792ebc2..d766ed07f7 100644 --- a/services/document-updater/app/js/HttpController.js +++ b/services/document-updater/app/js/HttpController.js @@ -34,7 +34,7 @@ function getDoc(req, res, next) { let fromVersion const docId = req.params.doc_id const projectId = req.params.project_id - logger.log({ projectId, docId }, 'getting doc via http') + logger.debug({ projectId, docId }, 'getting doc via http') const timer = new Metrics.Timer('http.getDoc') if (req.query.fromVersion != null) { @@ -52,7 +52,7 @@ function getDoc(req, res, next) { if (error) { return next(error) } - logger.log({ projectId, docId }, 'got doc via http') + logger.debug({ projectId, docId }, 'got doc via http') if (lines == null || version == null) { return next(new Errors.NotFoundError('document not found')) } @@ -72,7 +72,7 @@ function getDoc(req, res, next) { function peekDoc(req, res, next) { const docId = req.params.doc_id const projectId = req.params.project_id - logger.log({ projectId, docId }, 'peeking at doc via http') + logger.debug({ projectId, docId }, 'peeking at doc via http') RedisManager.getDoc(projectId, docId, function (error, lines, version) { if (error) { return next(error) @@ -90,14 +90,14 @@ function getProjectDocsAndFlushIfOld(req, res, next) { // exclude is string of existing docs "id:version,id:version,..." const excludeItems = req.query.exclude != null ? req.query.exclude.split(',') : [] - logger.log({ projectId, exclude: excludeItems }, 'getting docs via http') + logger.debug({ projectId, exclude: excludeItems }, 'getting docs via http') const timer = new Metrics.Timer('http.getAllDocs') const excludeVersions = {} for (const item of excludeItems) { const [id, version] = item.split(':') excludeVersions[id] = version } - logger.log( + logger.debug( { projectId, projectStateHash, excludeVersions }, 'excluding versions' ) @@ -112,7 +112,7 @@ function getProjectDocsAndFlushIfOld(req, res, next) { } else if (error) { next(error) } else { - logger.log( + logger.debug( { projectId, result: result.map(doc => `${doc._id}:${doc.v}`), @@ -128,7 +128,7 @@ function getProjectDocsAndFlushIfOld(req, res, next) { function clearProjectState(req, res, next) { const projectId = req.params.project_id const timer = new Metrics.Timer('http.clearProjectState') - logger.log({ projectId }, 'clearing project state via http') + logger.debug({ projectId }, 'clearing project state via http') ProjectManager.clearProjectState(projectId, error => { timer.done() if (error) { @@ -145,13 +145,13 @@ function setDoc(req, res, next) { const { lines, source, user_id: userId, undoing } = req.body const lineSize = getTotalSizeOfLines(lines) if (lineSize > Settings.max_doc_length) { - logger.log( + logger.warn( { projectId, docId, source, lineSize, userId }, 'document too large, returning 406 response' ) return res.sendStatus(406) } - logger.log( + logger.debug( { projectId, docId, lines, source, userId, undoing }, 'setting doc via http' ) @@ -168,7 +168,7 @@ function setDoc(req, res, next) { if (error) { return next(error) } - logger.log({ projectId, docId }, 'set doc via http') + logger.debug({ projectId, docId }, 'set doc via http') res.sendStatus(204) // No Content } ) @@ -177,14 +177,14 @@ function setDoc(req, res, next) { function flushDocIfLoaded(req, res, next) { const docId = req.params.doc_id const projectId = req.params.project_id - logger.log({ projectId, docId }, 'flushing doc via http') + logger.debug({ projectId, docId }, 'flushing doc via http') const timer = new Metrics.Timer('http.flushDoc') DocumentManager.flushDocIfLoadedWithLock(projectId, docId, error => { timer.done() if (error) { return next(error) } - logger.log({ projectId, docId }, 'flushed doc via http') + logger.debug({ projectId, docId }, 'flushed doc via http') res.sendStatus(204) // No Content }) } @@ -194,7 +194,7 @@ function deleteDoc(req, res, next) { const projectId = req.params.project_id const ignoreFlushErrors = req.query.ignore_flush_errors === 'true' const timer = new Metrics.Timer('http.deleteDoc') - logger.log({ projectId, docId }, 'deleting doc via http') + logger.debug({ projectId, docId }, 'deleting doc via http') DocumentManager.flushAndDeleteDocWithLock( projectId, docId, @@ -208,7 +208,7 @@ function deleteDoc(req, res, next) { if (error) { return next(error) } - logger.log({ projectId, docId }, 'deleted doc via http') + logger.debug({ projectId, docId }, 'deleted doc via http') res.sendStatus(204) // No Content } ) @@ -216,21 +216,21 @@ function deleteDoc(req, res, next) { function flushProject(req, res, next) { const projectId = req.params.project_id - logger.log({ projectId }, 'flushing project via http') + logger.debug({ projectId }, 'flushing project via http') const timer = new Metrics.Timer('http.flushProject') ProjectManager.flushProjectWithLocks(projectId, error => { timer.done() if (error) { return next(error) } - logger.log({ projectId }, 'flushed project via http') + logger.debug({ projectId }, 'flushed project via http') res.sendStatus(204) // No Content }) } function deleteProject(req, res, next) { const projectId = req.params.project_id - logger.log({ projectId }, 'deleting project via http') + logger.debug({ projectId }, 'deleting project via http') const options = {} if (req.query.background) { options.background = true @@ -243,7 +243,7 @@ function deleteProject(req, res, next) { if (error) { return next(error) } - logger.log({ projectId }, 'queue delete of project via http') + logger.debug({ projectId }, 'queue delete of project via http') res.sendStatus(204) }) // No Content } else { @@ -253,7 +253,7 @@ function deleteProject(req, res, next) { if (error) { return next(error) } - logger.log({ projectId }, 'deleted project via http') + logger.debug({ projectId }, 'deleted project via http') res.sendStatus(204) // No Content }) } @@ -261,11 +261,11 @@ function deleteProject(req, res, next) { function deleteMultipleProjects(req, res, next) { const projectIds = req.body.project_ids || [] - logger.log({ projectIds }, 'deleting multiple projects via http') + logger.debug({ projectIds }, 'deleting multiple projects via http') async.eachSeries( projectIds, (projectId, cb) => { - logger.log({ projectId }, 'queue delete of project via http') + logger.debug({ projectId }, 'queue delete of project via http') ProjectManager.queueFlushAndDeleteProject(projectId, cb) }, error => { @@ -283,7 +283,7 @@ function acceptChanges(req, res, next) { if (changeIds == null) { changeIds = [req.params.change_id] } - logger.log( + logger.debug( { projectId, docId }, `accepting ${changeIds.length} changes via http` ) @@ -293,7 +293,7 @@ function acceptChanges(req, res, next) { if (error) { return next(error) } - logger.log( + logger.debug( { projectId, docId }, `accepted ${changeIds.length} changes via http` ) @@ -307,14 +307,14 @@ function deleteComment(req, res, next) { doc_id: docId, comment_id: commentId, } = req.params - logger.log({ projectId, docId, commentId }, 'deleting comment via http') + logger.debug({ projectId, docId, commentId }, 'deleting comment via http') const timer = new Metrics.Timer('http.deleteComment') DocumentManager.deleteCommentWithLock(projectId, docId, commentId, error => { timer.done() if (error) { return next(error) } - logger.log({ projectId, docId, commentId }, 'deleted comment via http') + logger.debug({ projectId, docId, commentId }, 'deleted comment via http') res.sendStatus(204) // No Content }) } @@ -323,7 +323,7 @@ function updateProject(req, res, next) { const timer = new Metrics.Timer('http.updateProject') const projectId = req.params.project_id const { projectHistoryId, userId, updates = [], version } = req.body - logger.log({ projectId, updates, version }, 'updating project via http') + logger.debug({ projectId, updates, version }, 'updating project via http') ProjectManager.updateProjectWithLocks( projectId, projectHistoryId, @@ -335,7 +335,7 @@ function updateProject(req, res, next) { if (error) { return next(error) } - logger.log({ projectId }, 'updated project via http') + logger.debug({ projectId }, 'updated project via http') res.sendStatus(204) // No Content } ) @@ -345,7 +345,7 @@ function resyncProjectHistory(req, res, next) { const projectId = req.params.project_id const { projectHistoryId, docs, files } = req.body - logger.log( + logger.debug( { projectId, docs, files }, 'queuing project history resync via http' ) @@ -358,7 +358,7 @@ function resyncProjectHistory(req, res, next) { if (error) { return next(error) } - logger.log({ projectId }, 'queued project history resync via http') + logger.debug({ projectId }, 'queued project history resync via http') res.sendStatus(204) } ) @@ -393,7 +393,7 @@ function flushQueuedProjects(req, res, next) { logger.err({ err }, 'error flushing old projects') res.sendStatus(500) } else { - logger.log({ flushed }, 'flush of queued projects completed') + logger.info({ flushed }, 'flush of queued projects completed') res.send({ flushed }) } }) diff --git a/services/document-updater/app/js/Profiler.js b/services/document-updater/app/js/Profiler.js index 6f7a66a7aa..b1d5e586f7 100644 --- a/services/document-updater/app/js/Profiler.js +++ b/services/document-updater/app/js/Profiler.js @@ -52,7 +52,7 @@ module.exports = Profiler = (function () { args.updateTimes = this.updateTimes args.start = this.start args.end = new Date() - logger.log(args, this.name) + logger.debug(args, this.name) } return totalTime } diff --git a/services/document-updater/app/js/ProjectFlusher.js b/services/document-updater/app/js/ProjectFlusher.js index 12f885eb3c..da27b9962c 100644 --- a/services/document-updater/app/js/ProjectFlusher.js +++ b/services/document-updater/app/js/ProjectFlusher.js @@ -88,7 +88,7 @@ var ProjectFlusher = { }, flushAllProjects(options, callback) { - logger.log({ options }, 'flushing all projects') + logger.info({ options }, 'flushing all projects') return ProjectFlusher._getKeys( docUpdaterKeys.docsInProject({ project_id: '*' }), options.limit, @@ -123,7 +123,10 @@ var ProjectFlusher = { return success.push(project_ids[i]) } }) - logger.log({ success, failure }, 'finished flushing all projects') + logger.info( + { successCount: success.length, failureCount: failure.length }, + 'finished flushing all projects' + ) return callback(error, { success, failure }) } ) diff --git a/services/document-updater/app/js/ProjectHistoryRedisManager.js b/services/document-updater/app/js/ProjectHistoryRedisManager.js index 45e98238f4..c761f14690 100644 --- a/services/document-updater/app/js/ProjectHistoryRedisManager.js +++ b/services/document-updater/app/js/ProjectHistoryRedisManager.js @@ -77,7 +77,7 @@ module.exports = ProjectHistoryRedisManager = { } projectUpdate[entity_type] = entity_id - logger.log( + logger.debug( { project_id, projectUpdate }, 'queue rename operation to project-history' ) @@ -111,7 +111,7 @@ module.exports = ProjectHistoryRedisManager = { } projectUpdate[entity_type] = entitiy_id - logger.log( + logger.debug( { project_id, projectUpdate }, 'queue add operation to project-history' ) @@ -127,7 +127,7 @@ module.exports = ProjectHistoryRedisManager = { files, callback ) { - logger.log({ project_id, docs, files }, 'queue project structure resync') + logger.debug({ project_id, docs, files }, 'queue project structure resync') const projectUpdate = { resyncProjectStructure: { docs, files }, projectHistoryId, @@ -148,7 +148,7 @@ module.exports = ProjectHistoryRedisManager = { pathname, callback ) { - logger.log( + logger.debug( { project_id, doc_id, lines, version, pathname }, 'queue doc content resync' ) diff --git a/services/document-updater/app/js/ProjectManager.js b/services/document-updater/app/js/ProjectManager.js index 20f79f3d08..8a7420d1dd 100644 --- a/services/document-updater/app/js/ProjectManager.js +++ b/services/document-updater/app/js/ProjectManager.js @@ -47,7 +47,7 @@ function flushProjectWithLocks(projectId, _callback) { }) }) - logger.log({ projectId, docIds }, 'flushing docs') + logger.debug({ projectId, docIds }, 'flushing docs') async.series(jobs, () => { if (errors.length > 0) { callback(new Error('Errors flushing docs. See log for details')) @@ -82,7 +82,7 @@ function flushAndDeleteProjectWithLocks(projectId, options, _callback) { }) }) - logger.log({ projectId, docIds }, 'deleting docs') + logger.debug({ projectId, docIds }, 'deleting docs') async.series(jobs, () => // When deleting the project here we want to ensure that project // history is completely flushed because the project may be diff --git a/services/document-updater/app/js/RangesManager.js b/services/document-updater/app/js/RangesManager.js index 0de39134de..459fd65332 100644 --- a/services/document-updater/app/js/RangesManager.js +++ b/services/document-updater/app/js/RangesManager.js @@ -78,7 +78,7 @@ module.exports = RangesManager = { const emptyRangeCountAfter = RangesManager._emptyRangesCount(rangesTracker) const rangesWereCollapsed = emptyRangeCountAfter > emptyRangeCountBefore const response = RangesManager._getRanges(rangesTracker) - logger.log( + logger.debug( { project_id, doc_id, @@ -98,7 +98,7 @@ module.exports = RangesManager = { callback = function (error, ranges) {} } const { changes, comments } = ranges - logger.log(`accepting ${change_ids.length} changes in ranges`) + logger.debug(`accepting ${change_ids.length} changes in ranges`) const rangesTracker = new RangesTracker(changes, comments) rangesTracker.removeChangeIds(change_ids) const response = RangesManager._getRanges(rangesTracker) @@ -110,7 +110,7 @@ module.exports = RangesManager = { callback = function (error, ranges) {} } const { changes, comments } = ranges - logger.log({ comment_id }, 'deleting comment in ranges') + logger.debug({ comment_id }, 'deleting comment in ranges') const rangesTracker = new RangesTracker(changes, comments) rangesTracker.removeCommentId(comment_id) const response = RangesManager._getRanges(rangesTracker) diff --git a/services/document-updater/app/js/RateLimitManager.js b/services/document-updater/app/js/RateLimitManager.js index 48e9b0b8f1..562fe2675a 100644 --- a/services/document-updater/app/js/RateLimitManager.js +++ b/services/document-updater/app/js/RateLimitManager.js @@ -34,7 +34,7 @@ module.exports = RateLimiter = class RateLimiter { this.BaseWorkerCount, this.CurrentWorkerLimit * 0.9 ) - logger.log( + logger.debug( { currentLimit: Math.ceil(this.CurrentWorkerLimit) }, 'reducing rate limit' ) @@ -62,7 +62,7 @@ module.exports = RateLimiter = class RateLimiter { return this._adjustLimitDown() } } else { - logger.log( + logger.debug( { active: this.ActiveWorkerCount, currentLimit: Math.ceil(this.CurrentWorkerLimit), diff --git a/services/document-updater/app/js/RedisManager.js b/services/document-updater/app/js/RedisManager.js index c7e89d0f79..b3f4f94b2b 100644 --- a/services/document-updater/app/js/RedisManager.js +++ b/services/document-updater/app/js/RedisManager.js @@ -86,7 +86,7 @@ module.exports = RedisManager = { const docHash = RedisManager._computeHash(docLines) // record bytes sent to redis metrics.summary('redis.docLines', docLines.length, { status: 'set' }) - logger.log( + logger.debug( { project_id, doc_id, version, docHash, pathname, projectHistoryId }, 'putting doc in redis' ) @@ -116,13 +116,13 @@ module.exports = RedisManager = { }, removeDocFromMemory(project_id, doc_id, _callback) { - logger.log({ project_id, doc_id }, 'removing doc from redis') + logger.debug({ project_id, doc_id }, 'removing doc from redis') const callback = function (err) { if (err != null) { logger.err({ project_id, doc_id, err }, 'error removing doc from redis') return _callback(err) } else { - logger.log({ project_id, doc_id }, 'removed doc from redis') + logger.debug({ project_id, doc_id }, 'removed doc from redis') return _callback() } } @@ -169,7 +169,7 @@ module.exports = RedisManager = { if (error != null) { return callback(error) } - logger.log( + logger.debug( { project_id, newState, oldState: response[0] }, 'checking project state' ) @@ -342,7 +342,7 @@ module.exports = RedisManager = { error = new Errors.OpRangeNotAvailableError( 'doc ops range is not loaded in redis' ) - logger.warn( + logger.debug( { err: error, doc_id, length, version, start, end }, 'doc ops range is not loaded in redis' ) @@ -484,7 +484,7 @@ module.exports = RedisManager = { const newHash = RedisManager._computeHash(newDocLines) const opVersions = appliedOps.map(op => (op != null ? op.v : undefined)) - logger.log( + logger.debug( { doc_id, version: newVersion, @@ -529,7 +529,7 @@ module.exports = RedisManager = { multi.expire(keys.docOps({ doc_id }), RedisManager.DOC_OPS_TTL) // index 6 if (projectHistoryType === 'project-history') { metrics.inc('history-queue', 1, { status: 'skip-track-changes' }) - logger.log( + logger.debug( { doc_id }, 'skipping push of uncompressed ops for project using project-history' ) diff --git a/services/document-updater/app/js/ShareJsUpdateManager.js b/services/document-updater/app/js/ShareJsUpdateManager.js index 79b92dfb79..f06f005c9a 100644 --- a/services/document-updater/app/js/ShareJsUpdateManager.js +++ b/services/document-updater/app/js/ShareJsUpdateManager.js @@ -45,7 +45,7 @@ module.exports = ShareJsUpdateManager = { if (callback == null) { callback = function (error, updatedDocLines) {} } - logger.log({ project_id, doc_id, update }, 'applying sharejs updates') + logger.debug({ project_id, doc_id, update }, 'applying sharejs updates') const jobs = [] // record the update version before it is modified const incomingUpdateVersion = update.v @@ -61,7 +61,7 @@ module.exports = ShareJsUpdateManager = { if (error != null) { if (error === 'Op already submitted') { metrics.inc('sharejs.already-submitted') - logger.warn( + logger.debug( { project_id, doc_id, update }, 'op has already been submitted' ) @@ -69,7 +69,7 @@ module.exports = ShareJsUpdateManager = { ShareJsUpdateManager._sendOp(project_id, doc_id, update) } else if (/^Delete component/.test(error)) { metrics.inc('sharejs.delete-mismatch') - logger.warn( + logger.debug( { project_id, doc_id, update, shareJsErr: error }, 'sharejs delete does not match' ) @@ -82,7 +82,7 @@ module.exports = ShareJsUpdateManager = { return callback(error) } } - logger.log({ project_id, doc_id, error }, 'applied update') + logger.debug({ project_id, doc_id, error }, 'applied update') return model.getSnapshot(doc_key, (error, data) => { if (error != null) { return callback(error) diff --git a/services/document-updater/app/js/UpdateManager.js b/services/document-updater/app/js/UpdateManager.js index bf30db74b7..651c62b0eb 100644 --- a/services/document-updater/app/js/UpdateManager.js +++ b/services/document-updater/app/js/UpdateManager.js @@ -126,7 +126,7 @@ module.exports = UpdateManager = { if (error != null) { return callback(error) } - logger.log( + logger.debug( { project_id, doc_id, count: updates.length }, 'processing updates' ) @@ -235,7 +235,7 @@ module.exports = UpdateManager = { return callback(error) } if (ranges_were_collapsed) { - logger.log( + logger.debug( { project_id, doc_id, diff --git a/services/document-updater/app/js/sharejs/model.js b/services/document-updater/app/js/sharejs/model.js index aebcd8d549..9489f7c005 100644 --- a/services/document-updater/app/js/sharejs/model.js +++ b/services/document-updater/app/js/sharejs/model.js @@ -185,7 +185,6 @@ module.exports = Model = function (db, options) { } } catch (error1) { error = error1 - console.error(error.stack) return callback(error.message) } } @@ -194,7 +193,6 @@ module.exports = Model = function (db, options) { snapshot = doc.type.apply(doc.snapshot, opData.op) } catch (error2) { error = error2 - console.error(error.stack) return callback(error.message) } diff --git a/services/document-updater/app/js/sharejs/server/model.js b/services/document-updater/app/js/sharejs/server/model.js index a5682f71e3..f91149f627 100644 --- a/services/document-updater/app/js/sharejs/server/model.js +++ b/services/document-updater/app/js/sharejs/server/model.js @@ -185,7 +185,6 @@ module.exports = Model = function (db, options) { } } catch (error1) { error = error1 - console.error(error.stack) return callback(error.message) } } @@ -194,7 +193,6 @@ module.exports = Model = function (db, options) { snapshot = doc.type.apply(doc.snapshot, opData.op) } catch (error2) { error = error2 - console.error(error.stack) return callback(error.message) } diff --git a/services/document-updater/app/js/sharejs/types/model.js b/services/document-updater/app/js/sharejs/types/model.js index aebcd8d549..9489f7c005 100644 --- a/services/document-updater/app/js/sharejs/types/model.js +++ b/services/document-updater/app/js/sharejs/types/model.js @@ -185,7 +185,6 @@ module.exports = Model = function (db, options) { } } catch (error1) { error = error1 - console.error(error.stack) return callback(error.message) } } @@ -194,7 +193,6 @@ module.exports = Model = function (db, options) { snapshot = doc.type.apply(doc.snapshot, opData.op) } catch (error2) { error = error2 - console.error(error.stack) return callback(error.message) } diff --git a/services/document-updater/test/unit/js/DispatchManager/DispatchManagerTests.js b/services/document-updater/test/unit/js/DispatchManager/DispatchManagerTests.js index 4e17d58fff..283f7bd9b1 100644 --- a/services/document-updater/test/unit/js/DispatchManager/DispatchManagerTests.js +++ b/services/document-updater/test/unit/js/DispatchManager/DispatchManagerTests.js @@ -131,8 +131,8 @@ describe('DispatchManager', function () { return this.worker._waitForUpdateThenDispatchWorker(this.callback) }) - it('should log a warning', function () { - return this.logger.warn.called.should.equal(true) + it('should log a debug message', function () { + return this.logger.debug.called.should.equal(true) }) return it('should call the callback', function () { diff --git a/services/document-updater/test/unit/js/HttpController/HttpControllerTests.js b/services/document-updater/test/unit/js/HttpController/HttpControllerTests.js index 7bea76edd0..d8a2905984 100644 --- a/services/document-updater/test/unit/js/HttpController/HttpControllerTests.js +++ b/services/document-updater/test/unit/js/HttpController/HttpControllerTests.js @@ -86,7 +86,7 @@ describe('HttpController', function () { }) it('should log the request', function () { - this.logger.log + this.logger.debug .calledWith( { docId: this.doc_id, projectId: this.project_id }, 'getting doc via http' @@ -136,7 +136,7 @@ describe('HttpController', function () { }) it('should log the request', function () { - this.logger.log + this.logger.debug .calledWith( { docId: this.doc_id, projectId: this.project_id }, 'getting doc via http' @@ -223,7 +223,7 @@ describe('HttpController', function () { }) it('should log the request', function () { - this.logger.log + this.logger.debug .calledWith( { docId: this.doc_id, @@ -305,7 +305,7 @@ describe('HttpController', function () { }) it('should log the request', function () { - this.logger.log + this.logger.debug .calledWith( { projectId: this.project_id }, 'flushing project via http' @@ -365,7 +365,7 @@ describe('HttpController', function () { }) it('should log the request', function () { - this.logger.log + this.logger.debug .calledWith( { docId: this.doc_id, projectId: this.project_id }, 'flushing doc via http' @@ -431,7 +431,7 @@ describe('HttpController', function () { }) it('should log the request', function () { - this.logger.log + this.logger.debug .calledWith( { docId: this.doc_id, projectId: this.project_id }, 'deleting doc via http' @@ -512,7 +512,7 @@ describe('HttpController', function () { }) it('should log the request', function () { - this.logger.log + this.logger.debug .calledWith( { projectId: this.project_id }, 'deleting project via http' @@ -587,7 +587,7 @@ describe('HttpController', function () { }) it('should log the request', function () { - this.logger.log + this.logger.debug .calledWith( { projectId: this.project_id, docId: this.doc_id }, 'accepting 1 changes via http' @@ -622,7 +622,7 @@ describe('HttpController', function () { }) it('should log the request with the correct number of changes', function () { - this.logger.log + this.logger.debug .calledWith( { projectId: this.project_id, docId: this.doc_id }, `accepting ${this.change_ids.length} changes via http` @@ -677,7 +677,7 @@ describe('HttpController', function () { }) it('should log the request', function () { - this.logger.log + this.logger.debug .calledWith( { projectId: this.project_id, @@ -749,7 +749,7 @@ describe('HttpController', function () { }) it('should log the request', function () { - this.logger.log + this.logger.debug .calledWith( { projectId: this.project_id, exclude: [] }, 'getting docs via http' @@ -758,7 +758,7 @@ describe('HttpController', function () { }) it('should log the response', function () { - this.logger.log + this.logger.debug .calledWith( { projectId: this.project_id, result: ['1234:23', '4567:45'] }, 'got docs via http' diff --git a/services/document-updater/test/unit/js/RangesManager/RangesManagerTests.js b/services/document-updater/test/unit/js/RangesManager/RangesManagerTests.js index 6fbad0557a..c0cd994672 100644 --- a/services/document-updater/test/unit/js/RangesManager/RangesManagerTests.js +++ b/services/document-updater/test/unit/js/RangesManager/RangesManagerTests.js @@ -424,7 +424,7 @@ describe('RangesManager', function () { }) it('should log the call with the correct number of changes', function () { - return this.logger.log + return this.logger.debug .calledWith('accepting 1 changes in ranges') .should.equal(true) }) @@ -478,7 +478,7 @@ describe('RangesManager', function () { }) it('should log the call with the correct number of changes', function () { - return this.logger.log + return this.logger.debug .calledWith(`accepting ${this.change_ids.length} changes in ranges`) .should.equal(true) }) diff --git a/services/document-updater/test/unit/js/RedisManager/RedisManagerTests.js b/services/document-updater/test/unit/js/RedisManager/RedisManagerTests.js index 67ea6c7972..78341d6687 100644 --- a/services/document-updater/test/unit/js/RedisManager/RedisManagerTests.js +++ b/services/document-updater/test/unit/js/RedisManager/RedisManagerTests.js @@ -410,8 +410,8 @@ describe('RedisManager', function () { .should.equal(true) }) - return it('should log out the problem', function () { - return this.logger.warn.called.should.equal(true) + return it('should log out the problem as a debug message', function () { + return this.logger.debug.called.should.equal(true) }) })