Merge pull request #5159 from overleaf/bg-docupdater-log-relevelling

docupdater log re-levelling

GitOrigin-RevId: c27478d48f1cb1eae022086fe7af9fe55dfacfa0

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)
 }

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(

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'
                     )

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'
           )

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'
           )

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,

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 })
     }
   })

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
     }

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 })
           }
         )

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'
     )

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

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)

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),

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'
               )

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)

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,

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)
         }
 

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)
         }
 

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)
         }
 

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 () {

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'

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)
       })

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)
       })
     })