Merge pull request #7906 from overleaf/em-downgrade-logs

Downgrade all INFO logs to DEBUG

GitOrigin-RevId: 05ed582ef0721fcada059f0ad158565f50feca27

services/track-changes/app/js/DiffManager.js

@@ -127,7 +127,7 @@ module.exports = DiffManager = {
     if (callback == null) {
       callback = function () {}
     }
-    logger.log(
+    logger.debug(
       { project_id, doc_id, version },
       'getting document before version'
     )
@@ -162,7 +162,7 @@ module.exports = DiffManager = {
           return callback(error)
         }
 
-        logger.log(
+        logger.debug(
           {
             docVersion: version,
             lastUpdateVersion: lastUpdate != null ? lastUpdate.v : undefined,

services/track-changes/app/js/DocstoreManager.js

@@ -5,7 +5,7 @@ const Errors = require('./Errors')
 
 function peekDocument(projectId, docId, callback) {
   const url = `${Settings.apis.docstore.url}/project/${projectId}/doc/${docId}/peek`
-  logger.log(
+  logger.debug(
     { project_id: projectId, doc_id: docId },
     'getting doc from docstore'
   )
@@ -19,7 +19,7 @@ function peekDocument(projectId, docId, callback) {
       } catch (error) {
         return callback(error)
       }
-      logger.log(
+      logger.debug(
         { project_id: projectId, doc_id: docId, version: body.version },
         'got doc from docstore'
       )

services/track-changes/app/js/DocumentUpdaterManager.js

@@ -21,7 +21,7 @@ module.exports = DocumentUpdaterManager = {
       callback = function () {}
     }
 
-    logger.log({ project_id, doc_id }, 'getting doc from document updater')
+    logger.debug({ project_id, doc_id }, 'getting doc from document updater')
     return request.get(url, function (error, res, body) {
       if (error != null) {
         return callback(error)
@@ -33,7 +33,7 @@ module.exports = DocumentUpdaterManager = {
           error = error1
           return callback(error)
         }
-        logger.log(
+        logger.debug(
           { project_id, doc_id, version: body.version },
           'got doc from document updater'
         )
@@ -66,7 +66,7 @@ module.exports = DocumentUpdaterManager = {
       callback = function () {}
     }
     const url = `${Settings.apis.documentupdater.url}/project/${project_id}/doc/${doc_id}`
-    logger.log({ project_id, doc_id }, 'setting doc in document updater')
+    logger.debug({ project_id, doc_id }, 'setting doc in document updater')
     return request.post(
       {
         url,

services/track-changes/app/js/HealthChecker.js

@@ -21,7 +21,7 @@ module.exports = {
   check(callback) {
     const project_id = ObjectId(settings.trackchanges.healthCheck.project_id)
     const url = `http://localhost:${port}/project/${project_id}`
-    logger.log({ project_id }, 'running health check')
+    logger.debug({ project_id }, 'running health check')
     const jobs = [
       cb =>
         request.get(

services/track-changes/app/js/HttpController.js

@@ -30,7 +30,7 @@ module.exports = HttpController = {
     }
     const { doc_id } = req.params
     const { project_id } = req.params
-    logger.log({ project_id, doc_id }, 'compressing doc history')
+    logger.debug({ project_id, doc_id }, 'compressing doc history')
     return UpdatesManager.processUncompressedUpdatesWithLock(
       project_id,
       doc_id,
@@ -48,7 +48,7 @@ module.exports = HttpController = {
       next = function () {}
     }
     const { project_id } = req.params
-    logger.log({ project_id }, 'compressing project history')
+    logger.debug({ project_id }, 'compressing project history')
     return UpdatesManager.processUncompressedUpdatesForProject(
       project_id,
       function (error) {
@@ -66,7 +66,7 @@ module.exports = HttpController = {
       next = function () {}
     }
     const limit = req.query.limit != null ? parseInt(req.query.limit, 10) : -1
-    logger.log({ limit }, 'flushing all projects')
+    logger.debug({ limit }, 'flushing all projects')
     return UpdatesManager.flushAll(limit, function (error, result) {
       if (error != null) {
         return next(error)
@@ -78,7 +78,7 @@ module.exports = HttpController = {
           .status(200)
           .send(`${status}\nwould flush:\n${all.join('\n')}\n`)
       } else if (failed.length > 0) {
-        logger.log({ failed, succeeded }, 'error flushing projects')
+        logger.debug({ failed, succeeded }, 'error flushing projects')
         return res
           .status(500)
           .send(`${status}\nfailed to flush:\n${failed.join('\n')}\n`)
@@ -96,13 +96,13 @@ module.exports = HttpController = {
     if (next == null) {
       next = function () {}
     }
-    logger.log('checking dangling updates')
+    logger.debug('checking dangling updates')
     return UpdatesManager.getDanglingUpdates(function (error, result) {
       if (error != null) {
         return next(error)
       }
       if (result.length > 0) {
-        logger.log({ dangling: result }, 'found dangling updates')
+        logger.debug({ dangling: result }, 'found dangling updates')
         return res.status(500).send(`dangling updates:\n${result.join('\n')}\n`)
       } else {
         return res.status(200).send('no dangling updates found\n')
@@ -116,7 +116,7 @@ module.exports = HttpController = {
     }
     const { doc_id } = req.params
     const { project_id } = req.params
-    logger.log({ project_id, doc_id }, 'checking doc history')
+    logger.debug({ project_id, doc_id }, 'checking doc history')
     return DiffManager.getDocumentBeforeVersion(
       project_id,
       doc_id,
@@ -161,7 +161,7 @@ module.exports = HttpController = {
       to = null
     }
 
-    logger.log({ project_id, doc_id, from, to }, 'getting diff')
+    logger.debug({ project_id, doc_id, from, to }, 'getting diff')
     return DiffManager.getDiff(
       project_id,
       doc_id,
@@ -207,7 +207,7 @@ module.exports = HttpController = {
 
   zipProject(req, res, next) {
     const { project_id: projectId } = req.params
-    logger.log({ projectId }, 'exporting project history as zip file')
+    logger.debug({ projectId }, 'exporting project history as zip file')
     ZipManager.makeTempDirectory((err, tmpdir) => {
       if (err) {
         return next(err)
@@ -234,7 +234,7 @@ module.exports = HttpController = {
     //  - multiple updates form a pack
     // Flush updates per pack onto the wire.
     const { project_id } = req.params
-    logger.log({ project_id }, 'exporting project history')
+    logger.debug({ project_id }, 'exporting project history')
     UpdatesManager.exportProject(
       project_id,
       function (err, { updates, userIds }, confirmWrite) {
@@ -317,7 +317,7 @@ module.exports = HttpController = {
     }
     const { project_id } = req.params
     const { doc_id } = req.params
-    logger.log({ project_id, doc_id }, 'pushing all finalised changes to s3')
+    logger.debug({ project_id, doc_id }, 'pushing all finalised changes to s3')
     return PackManager.pushOldPacks(project_id, doc_id, function (error) {
       if (error != null) {
         return next(error)
@@ -332,7 +332,7 @@ module.exports = HttpController = {
     }
     const { project_id } = req.params
     const { doc_id } = req.params
-    logger.log({ project_id, doc_id }, 'pulling all packs from s3')
+    logger.debug({ project_id, doc_id }, 'pulling all packs from s3')
     return PackManager.pullOldPacks(project_id, doc_id, function (error) {
       if (error != null) {
         return next(error)

services/track-changes/app/js/MongoAWS.js

@@ -64,7 +64,7 @@ module.exports = MongoAWS = {
       return callback(new Error('invalid pack id'))
     }
 
-    logger.log({ project_id, doc_id, pack_id }, 'uploading data to s3')
+    logger.debug({ project_id, doc_id, pack_id }, 'uploading data to s3')
 
     const upload = createStream(S3S.WriteStream, project_id, doc_id, pack_id)
 
@@ -85,7 +85,7 @@ module.exports = MongoAWS = {
         return callback(error)
       }
       return zlib.gzip(uncompressedData, function (err, buf) {
-        logger.log(
+        logger.debug(
           {
             project_id,
             doc_id,
@@ -101,7 +101,10 @@ module.exports = MongoAWS = {
         upload.on('error', err => callback(err))
         upload.on('finish', function () {
           Metrics.inc('archive-pack')
-          logger.log({ project_id, doc_id, pack_id }, 'upload to s3 completed')
+          logger.debug(
+            { project_id, doc_id, pack_id },
+            'upload to s3 completed'
+          )
           return callback(null)
         })
         upload.write(buf)
@@ -129,7 +132,7 @@ module.exports = MongoAWS = {
       return callback(new Error('invalid pack id'))
     }
 
-    logger.log({ project_id, doc_id, pack_id }, 'downloading data from s3')
+    logger.debug({ project_id, doc_id, pack_id }, 'downloading data from s3')
 
     const download = createStream(S3S.ReadStream, project_id, doc_id, pack_id)
 
@@ -140,7 +143,7 @@ module.exports = MongoAWS = {
     const gunzip = zlib.createGunzip()
     gunzip.setEncoding('utf8')
     gunzip.on('error', function (err) {
-      logger.log(
+      logger.debug(
         { project_id, doc_id, pack_id, err },
         'error uncompressing gzip stream'
       )
@@ -152,7 +155,10 @@ module.exports = MongoAWS = {
     outputStream.on('error', err => callback(err))
     outputStream.on('end', function () {
       let object
-      logger.log({ project_id, doc_id, pack_id }, 'download from s3 completed')
+      logger.debug(
+        { project_id, doc_id, pack_id },
+        'download from s3 completed'
+      )
       try {
         object = JSON.parse(parts.join(''))
       } catch (e) {
@@ -186,7 +192,10 @@ module.exports = MongoAWS = {
         Metrics.inc('unarchive-pack')
         // allow the object to expire, we can always retrieve it again
         object.expiresAt = new Date(Date.now() + 7 * DAYS)
-        logger.log({ project_id, doc_id, pack_id }, 'inserting object from s3')
+        logger.debug(
+          { project_id, doc_id, pack_id },
+          'inserting object from s3'
+        )
         return db.docHistory.insertOne(object, (err, confirmation) => {
           if (err) return callback(err)
           object._id = confirmation.insertedId

services/track-changes/app/js/PackManager.js

@@ -217,7 +217,7 @@ module.exports = PackManager = {
       newPack.expiresAt = new Date(Date.now() + 7 * DAYS)
       newPack.last_checked = new Date(Date.now() + 30 * DAYS) // never check temporary packs
     }
-    logger.log(
+    logger.debug(
       { project_id, doc_id, newUpdates },
       'inserting updates into new pack'
     )
@@ -271,7 +271,7 @@ module.exports = PackManager = {
     if (lastUpdate.expiresAt && temporary) {
       update.$set.expiresAt = new Date(Date.now() + 7 * DAYS)
     }
-    logger.log(
+    logger.debug(
       { project_id, doc_id, lastUpdate, newUpdates },
       'appending updates to existing pack'
     )
@@ -402,7 +402,7 @@ module.exports = PackManager = {
           pack._id.toString()
         )
         const packIdsToFetch = _.difference(allPackIds, loadedPackIds)
-        logger.log(
+        logger.debug(
           { project_id, doc_id, loadedPackIds, allPackIds, packIdsToFetch },
           'analysed packs'
         )
@@ -418,7 +418,7 @@ module.exports = PackManager = {
             if (err != null) {
               return callback(err)
             }
-            logger.log({ project_id, doc_id }, 'done unarchiving')
+            logger.debug({ project_id, doc_id }, 'done unarchiving')
             return callback()
           }
         )
@@ -663,7 +663,7 @@ module.exports = PackManager = {
             if (err != null) {
               return callback(err)
             }
-            logger.log(
+            logger.debug(
               { project_id, doc_id, newPacks },
               'added new packs to index'
             )
@@ -769,7 +769,7 @@ module.exports = PackManager = {
             return result1
           })()
           if (newPacks.length) {
-            logger.log(
+            logger.debug(
               { project_id, doc_id, n: newPacks.length },
               'found new packs'
             )
@@ -959,7 +959,7 @@ module.exports = PackManager = {
           return callback(err)
         }
       )
-    logger.log({ project_id, doc_id }, 'processing old packs')
+    logger.debug({ project_id, doc_id }, 'processing old packs')
     return db.docHistory.findOne({ _id: pack_id }, function (err, pack) {
       if (err != null) {
         return markAsChecked(err)
@@ -998,7 +998,7 @@ module.exports = PackManager = {
                       ? unarchivedPacks.length
                       : undefined)
                   ) {
-                    logger.log(
+                    logger.debug(
                       { project_id, doc_id },
                       'no packs need archiving'
                     )
@@ -1012,7 +1012,7 @@ module.exports = PackManager = {
                       if (err != null) {
                         return markAsChecked(err)
                       }
-                      logger.log({ project_id, doc_id }, 'done processing')
+                      logger.debug({ project_id, doc_id }, 'done processing')
                       return markAsChecked()
                     }
                   )
@@ -1031,13 +1031,16 @@ module.exports = PackManager = {
     const age = (Date.now() - pack.meta.end_ts) / DAYS
     if (age < 30) {
       // always keep if less than 1 month old
-      logger.log({ project_id, doc_id, pack_id, age }, 'less than 30 days old')
+      logger.debug(
+        { project_id, doc_id, pack_id, age },
+        'less than 30 days old'
+      )
       return callback()
     }
     // compute an archiving threshold which decreases for each month of age
     const archive_threshold = 30 / age
     if (sz > archive_threshold || n > archive_threshold || age > 90) {
-      logger.log(
+      logger.debug(
         { project_id, doc_id, pack_id, age, archive_threshold, sz, n },
         'meets archive threshold'
       )
@@ -1048,7 +1051,7 @@ module.exports = PackManager = {
         callback
       )
     } else {
-      logger.log(
+      logger.debug(
         { project_id, doc_id, pack_id, age, archive_threshold, sz, n },
         'does not meet archive threshold'
       )
@@ -1071,7 +1074,7 @@ module.exports = PackManager = {
   },
 
   _markPackAsFinalised(project_id, doc_id, pack_id, callback) {
-    logger.log({ project_id, doc_id, pack_id }, 'marking pack as finalised')
+    logger.debug({ project_id, doc_id, pack_id }, 'marking pack as finalised')
     return db.docHistory.updateOne(
       { _id: pack_id },
       { $set: { finalised: true } },
@@ -1080,7 +1083,7 @@ module.exports = PackManager = {
   },
 
   updateIndexIfNeeded(project_id, doc_id, callback) {
-    logger.log({ project_id, doc_id }, 'archiving old packs')
+    logger.debug({ project_id, doc_id }, 'archiving old packs')
     return PackManager.getIndexWithKeys(doc_id, function (err, index) {
       if (err != null) {
         return callback(err)
@@ -1094,7 +1097,7 @@ module.exports = PackManager = {
   },
 
   markPackAsChecked(project_id, doc_id, pack_id, callback) {
-    logger.log({ project_id, doc_id, pack_id }, 'marking pack as checked')
+    logger.debug({ project_id, doc_id, pack_id }, 'marking pack as checked')
     return db.docHistory.updateOne(
       { _id: pack_id },
       { $currentDate: { last_checked: true } },
@@ -1119,7 +1122,7 @@ module.exports = PackManager = {
         return result
       })()
       if (unArchivedPacks.length) {
-        logger.log(
+        logger.debug(
           { project_id, doc_id, n: unArchivedPacks.length },
           'find unarchived packs'
         )
@@ -1131,7 +1134,7 @@ module.exports = PackManager = {
   // Archive locking flags
 
   checkArchiveNotInProgress(project_id, doc_id, pack_id, callback) {
-    logger.log(
+    logger.debug(
       { project_id, doc_id, pack_id },
       'checking if archive in progress'
     )
@@ -1157,7 +1160,7 @@ module.exports = PackManager = {
   },
 
   markPackAsArchiveInProgress(project_id, doc_id, pack_id, callback) {
-    logger.log(
+    logger.debug(
       { project_id, doc_id },
       'marking pack as archive in progress status'
     )
@@ -1175,7 +1178,7 @@ module.exports = PackManager = {
         if (!result.value) {
           return callback(new Error('archive is already in progress'))
         }
-        logger.log(
+        logger.debug(
           { project_id, doc_id, pack_id },
           'marked as archive in progress'
         )
@@ -1185,7 +1188,7 @@ module.exports = PackManager = {
   },
 
   clearPackAsArchiveInProgress(project_id, doc_id, pack_id, callback) {
-    logger.log(
+    logger.debug(
       { project_id, doc_id, pack_id },
       'clearing as archive in progress'
     )
@@ -1200,7 +1203,7 @@ module.exports = PackManager = {
   },
 
   markPackAsArchived(project_id, doc_id, pack_id, callback) {
-    logger.log({ project_id, doc_id, pack_id }, 'marking pack as archived')
+    logger.debug({ project_id, doc_id, pack_id }, 'marking pack as archived')
     return db.docHistoryIndex.findOneAndUpdate(
       {
         _id: ObjectId(doc_id.toString()),
@@ -1215,7 +1218,7 @@ module.exports = PackManager = {
         if (!result.value) {
           return callback(new Error('archive is not marked as progress'))
         }
-        logger.log({ project_id, doc_id, pack_id }, 'marked as archived')
+        logger.debug({ project_id, doc_id, pack_id }, 'marked as archived')
         return callback()
       }
     )
@@ -1229,7 +1232,7 @@ module.exports = PackManager = {
         if (err) {
           return callback(err)
         }
-        logger.log({ project_id, doc_id, pack_id }, 'set expiry on pack')
+        logger.debug({ project_id, doc_id, pack_id }, 'set expiry on pack')
         return callback()
       }
     )

services/track-changes/app/js/PackWorker.js

@@ -64,7 +64,7 @@ if (!source.match(/^[0-9]+$/)) {
 
 let shutDownRequested = false
 const shutDownTimer = setTimeout(function () {
-  logger.log('pack timed out, requesting shutdown')
+  logger.debug('pack timed out, requesting shutdown')
   // start the shutdown on the next pack
   shutDownRequested = true
   // do a hard shutdown after a further 5 minutes
@@ -75,20 +75,20 @@ const shutDownTimer = setTimeout(function () {
   return hardTimeout.unref()
 }, TIMEOUT)
 
-logger.log(
+logger.debug(
   `checking for updates, limit=${LIMIT}, delay=${DOCUMENT_PACK_DELAY}, timeout=${TIMEOUT}`
 )
 
 const finish = function () {
   if (shutDownTimer != null) {
-    logger.log('cancelling timeout')
+    logger.debug('cancelling timeout')
     clearTimeout(shutDownTimer)
   }
-  logger.log('closing db')
+  logger.debug('closing db')
   callbackify(closeDb)(function () {
-    logger.log('closing LockManager Redis Connection')
+    logger.debug('closing LockManager Redis Connection')
     return LockManager.close(function () {
-      logger.log(
+      logger.debug(
         { processedCount: COUNT, allCount: TOTAL },
         'ready to exit from pack archive worker'
       )
@@ -101,7 +101,7 @@ const finish = function () {
   })
 }
 
-process.on('exit', code => logger.log({ code }, 'pack archive worker exited'))
+process.on('exit', code => logger.debug({ code }, 'pack archive worker exited'))
 
 const processUpdates = pending =>
   async.eachSeries(
@@ -110,9 +110,9 @@ const processUpdates = pending =>
       let _id
       ;({ _id, project_id, doc_id } = result)
       COUNT++
-      logger.log({ project_id, doc_id }, `processing ${COUNT}/${TOTAL}`)
+      logger.debug({ project_id, doc_id }, `processing ${COUNT}/${TOTAL}`)
       if (project_id == null || doc_id == null) {
-        logger.log(
+        logger.debug(
           { project_id, doc_id },
           'skipping pack, missing project/doc id'
         )
@@ -164,7 +164,7 @@ const ObjectIdFromDate = function (date) {
 waitForDb()
   .then(() => {
     if (pending != null) {
-      logger.log(`got ${pending.length} entries from ${source}`)
+      logger.debug(`got ${pending.length} entries from ${source}`)
       processUpdates(pending)
     } else {
       processFromOneWeekAgo()
@@ -194,13 +194,13 @@ function processFromOneWeekAgo() {
     .limit(LIMIT)
     .toArray(function (err, results) {
       if (err != null) {
-        logger.log({ err }, 'error checking for updates')
+        logger.debug({ err }, 'error checking for updates')
         finish()
         return
       }
       pending = _.uniq(results, false, result => result.doc_id.toString())
       TOTAL = pending.length
-      logger.log(`found ${TOTAL} documents to archive`)
+      logger.debug(`found ${TOTAL} documents to archive`)
       return processUpdates(pending)
     })
 }

services/track-changes/app/js/RestoreManager.js

@@ -20,7 +20,7 @@ module.exports = RestoreManager = {
     if (callback == null) {
       callback = function () {}
     }
-    logger.log({ project_id, doc_id, version, user_id }, 'restoring document')
+    logger.debug({ project_id, doc_id, version, user_id }, 'restoring document')
     return DiffManager.getDocumentBeforeVersion(
       project_id,
       doc_id,

services/track-changes/app/js/UpdateTrimmer.js

@@ -36,7 +36,7 @@ module.exports = UpdateTrimmer = {
               if (error != null) {
                 return callback(error)
               }
-              logger.log({ project_id, details }, 'got details')
+              logger.debug({ project_id, details }, 'got details')
               if (
                 __guard__(
                   details != null ? details.features : undefined,

services/track-changes/app/js/UpdatesManager.js

@@ -182,7 +182,7 @@ module.exports = UpdatesManager = {
               return callback(error)
             }
             if (result != null) {
-              logger.log(
+              logger.debug(
                 {
                   project_id,
                   doc_id,
@@ -257,7 +257,7 @@ module.exports = UpdatesManager = {
               )
               return callback(error)
             }
-            logger.log(
+            logger.debug(
               { project_id, doc_id, rawUpdates },
               'retrieved raw updates from redis'
             )
@@ -270,7 +270,7 @@ module.exports = UpdatesManager = {
                 if (error != null) {
                   return callback(error)
                 }
-                logger.log(
+                logger.debug(
                   { project_id, doc_id },
                   'compressed and saved doc updates'
                 )
@@ -285,7 +285,7 @@ module.exports = UpdatesManager = {
                     }
                     if (length === UpdatesManager.REDIS_READ_BATCH_SIZE) {
                       // There might be more updates
-                      logger.log(
+                      logger.debug(
                         { project_id, doc_id },
                         'continuing processing updates'
                       )
@@ -300,7 +300,7 @@ module.exports = UpdatesManager = {
                         0
                       )
                     } else {
-                      logger.log(
+                      logger.debug(
                         { project_id, doc_id },
                         'all raw updates processed'
                       )
@@ -416,7 +416,7 @@ module.exports = UpdatesManager = {
       if (error != null) {
         return callback(error)
       }
-      logger.log(
+      logger.debug(
         {
           count: project_ids != null ? project_ids.length : undefined,
           project_ids,
@@ -497,7 +497,7 @@ module.exports = UpdatesManager = {
         return task(function (error, project_doc_ids) {
           if (error) return callback(error)
           const dangling_doc_ids = _.difference(all_doc_ids, project_doc_ids)
-          logger.log(
+          logger.debug(
             { all_doc_ids, all_project_ids, project_doc_ids, dangling_doc_ids },
             'checking for dangling doc ids'
           )

services/track-changes/app/js/WebApiManager.js

@@ -43,7 +43,7 @@ module.exports = WebApiManager = {
           return callback(error)
         }
         if (res.statusCode === 404) {
-          logger.log({ url }, 'got 404 from web api')
+          logger.debug({ url }, 'got 404 from web api')
           return callback(null, null)
         }
         if (res.statusCode >= 200 && res.statusCode < 300) {
@@ -63,7 +63,7 @@ module.exports = WebApiManager = {
       callback = function () {}
     }
     const url = `/user/${user_id}/personal_info`
-    logger.log({ user_id }, 'getting user info from web')
+    logger.debug({ user_id }, 'getting user info from web')
     return WebApiManager.sendRequest(url, function (error, body) {
       let user
       if (error != null) {
@@ -95,7 +95,7 @@ module.exports = WebApiManager = {
       callback = function () {}
     }
     const url = `/project/${project_id}/details`
-    logger.log({ project_id }, 'getting project details from web')
+    logger.debug({ project_id }, 'getting project details from web')
     return WebApiManager.sendRequest(url, function (error, body) {
       let project
       if (error != null) {

services/track-changes/app/js/ZipManager.js

@@ -33,7 +33,7 @@ async function getLatestContent(projectId, docId, lastUpdateVersion) {
 }
 
 async function rewindDoc(projectId, docId, zipfile) {
-  logger.log({ projectId, docId }, 'rewinding document')
+  logger.debug({ projectId, docId }, 'rewinding document')
 
   // Prepare to rewind content