[project-history] trim logging (#23408)

* [project-history] trim logging when projectVersion is out of order

* [editor-core] record reason rather than full pathname when not clean

* [editor-core] remove pathname from error messages

* [project-history] avoid logging updates when historyId is inconsistent

* [project-history] avoid logging failed history-v1 requests repeatedly

* [project-history] log once when doc version is out of order in chunk

GitOrigin-RevId: 5ac431ac87b57c00fac9d5ab486ca305b1775372

libraries/overleaf-editor-core/lib/file_map.js

@@ -22,7 +22,7 @@ class NonUniquePathnameError extends PathnameError {
    * @param {string[]} pathnames
    */
   constructor(pathnames) {
-    super('pathnames are not unique: ' + pathnames, { pathnames })
+    super('pathnames are not unique', { pathnames })
     this.pathnames = pathnames
   }
 }
@@ -30,9 +30,13 @@ class NonUniquePathnameError extends PathnameError {
 class BadPathnameError extends PathnameError {
   /**
    * @param {string} pathname
+   * @param {string} reason
    */
-  constructor(pathname) {
-    super(pathname + ' is not a valid pathname', { pathname })
+  constructor(pathname, reason) {
+    if (pathname.length > 10) {
+      pathname = pathname.slice(0, 5) + '...' + pathname.slice(-5)
+    }
+    super('invalid pathname', { reason, pathname })
     this.pathname = pathname
   }
 }
@@ -42,7 +46,7 @@ class PathnameConflictError extends PathnameError {
    * @param {string} pathname
    */
   constructor(pathname) {
-    super(`pathname '${pathname}' conflicts with another file`, { pathname })
+    super('pathname conflicts with another file', { pathname })
     this.pathname = pathname
   }
 }
@@ -52,7 +56,7 @@ class FileNotFoundError extends PathnameError {
    * @param {string} pathname
    */
   constructor(pathname) {
-    super(`file ${pathname} does not exist`, { pathname })
+    super('file does not exist', { pathname })
     this.pathname = pathname
   }
 }
@@ -315,8 +319,9 @@ function checkPathnamesAreUnique(files) {
  */
 function checkPathname(pathname) {
   assert.nonEmptyString(pathname, 'bad pathname')
-  if (safePathname.isClean(pathname)) return
-  throw new FileMap.BadPathnameError(pathname)
+  const [isClean, reason] = safePathname.isCleanDebug(pathname)
+  if (isClean) return
+  throw new FileMap.BadPathnameError(pathname, reason)
 }
 
 /**

libraries/overleaf-editor-core/lib/safe_pathname.js

@@ -64,17 +64,57 @@ function cleanPart(filename) {
  * @return {String}
  */
 exports.clean = function (pathname) {
+  return exports.cleanDebug(pathname)[0]
+}
+
+/**
+ * See clean
+ * @param {string} pathname
+ * @return {[string,string]}
+ */
+exports.cleanDebug = function (pathname) {
+  let prev = pathname
+  let reason = ''
+
+  /**
+   * @param {string} label
+   */
+  function recordReasonIfChanged(label) {
+    if (pathname === prev) return
+    if (reason) reason += ','
+    reason += label
+    prev = pathname
+  }
   pathname = path.normalize(pathname)
-  pathname = pathname.replace(/\\/g, '/') // workaround for IE
-  pathname = pathname.replace(/\/+/g, '/') // no multiple slashes
-  pathname = pathname.replace(/^(\/.*)$/, '_$1') // no leading /
-  pathname = pathname.replace(/^(.+)\/$/, '$1') // no trailing /
-  pathname = pathname.replace(/^ *(.*)$/, '$1') // no leading spaces
-  pathname = pathname.replace(/^(.*[^ ]) *$/, '$1') // no trailing spaces
+  recordReasonIfChanged('normalize')
+
+  pathname = pathname.replace(/\\/g, '/')
+  recordReasonIfChanged('workaround for IE')
+
+  pathname = pathname.replace(/\/+/g, '/')
+  recordReasonIfChanged('no multiple slashes')
+
+  pathname = pathname.replace(/^(\/.*)$/, '_$1')
+  recordReasonIfChanged('no leading /')
+
+  pathname = pathname.replace(/^(.+)\/$/, '$1')
+  recordReasonIfChanged('no trailing /')
+
+  pathname = pathname.replace(/^ *(.*)$/, '$1')
+  recordReasonIfChanged('no leading spaces')
+
+  pathname = pathname.replace(/^(.*[^ ]) *$/, '$1')
+  recordReasonIfChanged('no trailing spaces')
+
   if (pathname.length === 0) pathname = '_'
+  recordReasonIfChanged('empty')
+
   pathname = pathname.split('/').map(cleanPart).join('/')
+  recordReasonIfChanged('cleanPart')
+
   pathname = pathname.replace(BLOCKED_FILE_RX, '@$1')
-  return pathname
+  recordReasonIfChanged('BLOCKED_FILE_RX')
+  return [pathname, reason]
 }
 
 /**
@@ -84,9 +124,19 @@ exports.clean = function (pathname) {
  * @return {Boolean}
  */
 exports.isClean = function pathnameIsClean(pathname) {
-  return (
-    exports.clean(pathname) === pathname &&
-    pathname.length <= MAX_PATH &&
-    pathname.length > 0
-  )
+  return exports.isCleanDebug(pathname)[0]
+}
+
+/**
+ * A pathname is clean (see clean) and not too long.
+ *
+ * @param {string} pathname
+ * @return {[boolean,string]}
+ */
+exports.isCleanDebug = function (pathname) {
+  if (pathname.length > MAX_PATH) return [false, 'MAX_PATH']
+  if (pathname.length === 0) return [false, 'empty']
+  const [cleanPathname, reason] = exports.cleanDebug(pathname)
+  if (cleanPathname !== pathname) return [false, reason]
+  return [true, '']
 }

libraries/overleaf-editor-core/test/safe_pathname.test.js

@@ -5,10 +5,11 @@ const ot = require('..')
 const safePathname = ot.safePathname
 
 describe('safePathname', function () {
-  function expectClean(input, output) {
+  function expectClean(input, output, reason = '') {
     // check expected output and also idempotency
-    const cleanedInput = safePathname.clean(input)
+    const [cleanedInput, gotReason] = safePathname.cleanDebug(input)
     expect(cleanedInput).to.equal(output)
+    expect(gotReason).to.equal(reason)
     expect(safePathname.clean(cleanedInput)).to.equal(cleanedInput)
     expect(safePathname.isClean(cleanedInput)).to.be.true
   }
@@ -22,44 +23,56 @@ describe('safePathname', function () {
     expect(safePathname.isClean('rm -rf /')).to.be.falsy
 
     // replace invalid characters with underscores
-    expectClean('test-s*\u0001\u0002m\u0007st\u0008.jpg', 'test-s___m_st_.jpg')
+    expectClean(
+      'test-s*\u0001\u0002m\u0007st\u0008.jpg',
+      'test-s___m_st_.jpg',
+      'cleanPart'
+    )
 
     // keep slashes, normalize paths, replace ..
-    expectClean('./foo', 'foo')
-    expectClean('../foo', '__/foo')
-    expectClean('foo/./bar', 'foo/bar')
-    expectClean('foo/../bar', 'bar')
-    expectClean('../../tricky/foo.bar', '__/__/tricky/foo.bar')
-    expectClean('foo/../../tricky/foo.bar', '__/tricky/foo.bar')
-    expectClean('foo/bar/../../tricky/foo.bar', 'tricky/foo.bar')
-    expectClean('foo/bar/baz/../../tricky/foo.bar', 'foo/tricky/foo.bar')
+    expectClean('./foo', 'foo', 'normalize')
+    expectClean('../foo', '__/foo', 'cleanPart')
+    expectClean('foo/./bar', 'foo/bar', 'normalize')
+    expectClean('foo/../bar', 'bar', 'normalize')
+    expectClean('../../tricky/foo.bar', '__/__/tricky/foo.bar', 'cleanPart')
+    expectClean(
+      'foo/../../tricky/foo.bar',
+      '__/tricky/foo.bar',
+      'normalize,cleanPart'
+    )
+    expectClean('foo/bar/../../tricky/foo.bar', 'tricky/foo.bar', 'normalize')
+    expectClean(
+      'foo/bar/baz/../../tricky/foo.bar',
+      'foo/tricky/foo.bar',
+      'normalize'
+    )
 
     // remove illegal chars even when there is no extension
-    expectClean('**foo', '__foo')
+    expectClean('**foo', '__foo', 'cleanPart')
 
     // remove windows file paths
-    expectClean('c:\\temp\\foo.txt', 'c:/temp/foo.txt')
+    expectClean('c:\\temp\\foo.txt', 'c:/temp/foo.txt', 'workaround for IE')
 
     // do not allow a leading slash (relative paths only)
-    expectClean('/foo', '_/foo')
-    expectClean('//foo', '_/foo')
+    expectClean('/foo', '_/foo', 'no leading /')
+    expectClean('//foo', '_/foo', 'normalize,no leading /')
 
     // do not allow multiple leading slashes
-    expectClean('//foo', '_/foo')
+    expectClean('//foo', '_/foo', 'normalize,no leading /')
 
     // do not allow a trailing slash
-    expectClean('/', '_')
-    expectClean('foo/', 'foo')
-    expectClean('foo.tex/', 'foo.tex')
+    expectClean('/', '_', 'no leading /,no trailing /')
+    expectClean('foo/', 'foo', 'no trailing /')
+    expectClean('foo.tex/', 'foo.tex', 'no trailing /')
 
     // do not allow multiple trailing slashes
-    expectClean('//', '_')
-    expectClean('///', '_')
-    expectClean('foo//', 'foo')
+    expectClean('//', '_', 'normalize,no leading /,no trailing /')
+    expectClean('///', '_', 'normalize,no leading /,no trailing /')
+    expectClean('foo//', 'foo', 'normalize,no trailing /')
 
     // file and folder names that consist of . and .. are not OK
-    expectClean('.', '_')
-    expectClean('..', '__')
+    expectClean('.', '_', 'cleanPart')
+    expectClean('..', '__', 'cleanPart')
     // we will allow name with more dots e.g. ... and ....
     expectClean('...', '...')
     expectClean('....', '....')
@@ -82,10 +95,10 @@ describe('safePathname', function () {
     expectClean('a b.png', 'a b.png')
 
     // leading and trailing spaces are not OK
-    expectClean(' foo', 'foo')
-    expectClean('  foo', 'foo')
-    expectClean('foo ', 'foo')
-    expectClean('foo  ', 'foo')
+    expectClean(' foo', 'foo', 'no leading spaces')
+    expectClean('  foo', 'foo', 'no leading spaces')
+    expectClean('foo ', 'foo', 'no trailing spaces')
+    expectClean('foo  ', 'foo', 'no trailing spaces')
 
     // reserved file names on Windows should not be OK, but we already have
     // some in the old system, so have to allow them for now
@@ -100,14 +113,14 @@ describe('safePathname', function () {
     // there's no particular reason to allow multiple slashes; sometimes people
     // seem to rename files to URLs (https://domain/path) in an attempt to
     // upload a file, and this results in an empty directory name
-    expectClean('foo//bar.png', 'foo/bar.png')
-    expectClean('foo///bar.png', 'foo/bar.png')
+    expectClean('foo//bar.png', 'foo/bar.png', 'normalize')
+    expectClean('foo///bar.png', 'foo/bar.png', 'normalize')
 
     // Check javascript property handling
     expectClean('foo/prototype', 'foo/prototype') // OK as part of a pathname
     expectClean('prototype/test.txt', 'prototype/test.txt')
-    expectClean('prototype', '@prototype') // not OK as whole pathname
-    expectClean('hasOwnProperty', '@hasOwnProperty')
-    expectClean('**proto**', '@__proto__')
+    expectClean('prototype', '@prototype', 'BLOCKED_FILE_RX') // not OK as whole pathname
+    expectClean('hasOwnProperty', '@hasOwnProperty', 'BLOCKED_FILE_RX')
+    expectClean('**proto**', '@__proto__', 'cleanPart,BLOCKED_FILE_RX')
   })
 })

services/project-history/app/js/HistoryStoreManager.js

@@ -122,7 +122,8 @@ function _requestChunk(options, callback) {
       chunk.chunk == null ||
       chunk.chunk.startVersion == null
     ) {
-      return callback(new OError('unexpected response'))
+      const { path } = options
+      return callback(new OError('unexpected response', { path }))
     }
     callback(null, chunk)
   })
@@ -130,28 +131,36 @@ function _requestChunk(options, callback) {
 
 function _getLatestProjectVersion(projectId, chunk, callback) {
   // find the initial project version
-  let projectVersion =
-    chunk.chunk.history.snapshot && chunk.chunk.history.snapshot.projectVersion
-  // keep track of any errors
+  const projectVersionInSnapshot = chunk.chunk.history.snapshot?.projectVersion
+  let projectVersion = projectVersionInSnapshot
+  const chunkStartVersion = chunk.chunk.startVersion
+  // keep track of any first error
   let error = null
   // iterate over the changes in chunk to find the most recent project version
-  for (const change of chunk.chunk.history.changes || []) {
-    if (change.projectVersion != null) {
+  for (const [changeIdx, change] of (
+    chunk.chunk.history.changes || []
+  ).entries()) {
+    const projectVersionInChange = change.projectVersion
+    if (projectVersionInChange != null) {
       if (
         projectVersion != null &&
-        Versions.lt(change.projectVersion, projectVersion)
+        Versions.lt(projectVersionInChange, projectVersion)
       ) {
-        logger.warn(
-          { projectId, chunk, projectVersion, change },
-          'project structure version out of order in chunk'
-        )
         if (!error) {
           error = new Errors.OpsOutOfOrderError(
-            'project structure version out of order'
+            'project structure version out of order',
+            {
+              projectId,
+              chunkStartVersion,
+              projectVersionInSnapshot,
+              changeIdx,
+              projectVersion,
+              projectVersionInChange,
+            }
           )
         }
       } else {
-        projectVersion = change.projectVersion
+        projectVersion = projectVersionInChange
       }
     }
   }
@@ -177,16 +186,16 @@ function _getLatestV2DocVersions(projectId, chunk, callback) {
           v2DocVersions[docId].v != null &&
           Versions.lt(v, v2DocVersions[docId].v)
         ) {
-          logger.warn(
-            {
-              projectId,
-              docId,
-              changeVersion: docInfo,
-              previousVersion: v2DocVersions[docId],
-            },
-            'doc version out of order in chunk'
-          )
           if (!error) {
+            logger.warn(
+              {
+                projectId,
+                docId,
+                changeVersion: docInfo,
+                previousVersion: v2DocVersions[docId],
+              },
+              'doc version out of order in chunk'
+            )
             error = new Errors.OpsOutOfOrderError('doc version out of order')
           }
         } else {
@@ -250,7 +259,6 @@ export function sendChanges(
           statusCode: error.statusCode,
           body: error.body,
         })
-        logger.warn({ error, projectId, historyId, endVersion }, error.message)
         return callback(error)
       }
       callback()
@@ -592,7 +600,6 @@ function _requestHistoryService(options, callback) {
         `history store a non-success status code: ${res.statusCode}`,
         { method, url, qs, statusCode: res.statusCode }
       )
-      logger.warn({ err: error }, error.message)
       callback(error)
     }
   })

services/project-history/app/js/UpdatesProcessor.js

@@ -269,17 +269,12 @@ export function _getHistoryId(projectId, updates, callback) {
         idFromUpdates = update.projectHistoryId.toString()
       } else if (idFromUpdates !== update.projectHistoryId.toString()) {
         metrics.inc('updates.batches.project-history-id.inconsistent-update')
-        logger.warn(
-          {
+        return callback(
+          new OError('inconsistent project history id between updates', {
             projectId,
-            updates,
             idFromUpdates,
             currentId: update.projectHistoryId,
-          },
-          'inconsistent project history id between updates'
-        )
-        return callback(
-          new OError('inconsistent project history id between updates')
+          })
         )
       }
     }
@@ -340,15 +335,11 @@ function _handleOpsOutOfOrderError(projectId, projectHistoryId, err, ...rest) {
     // Bypass ops-out-of-order errors in the stored chunk when in forceDebug mode
     if (failureRecord != null && failureRecord.forceDebug === true) {
       logger.warn(
-        { projectId, projectHistoryId },
+        { err, projectId, projectHistoryId },
         'ops out of order in chunk, forced continue'
       )
       callback(null, ...results) // return results without error
     } else {
-      logger.warn(
-        { projectId, projectHistoryId },
-        'ops out of order in chunk, returning error'
-      )
       callback(err, ...results)
     }
   })