Merge pull request #9617 from overleaf/msm-audit-log-collections

Move project/user audit logs to their own collections

GitOrigin-RevId: f6f89b3e2815c0fe5691a79eceb35b77b3c370d8

services/web/app/src/Features/Project/ProjectAuditLogHandler.js

@@ -1,7 +1,4 @@
-const OError = require('@overleaf/o-error')
-const { Project } = require('../../models/Project')
-
-const MAX_AUDIT_LOG_ENTRIES = 200
+const { ProjectAuditLogEntry } = require('../../models/ProjectAuditLogEntry')
 
 module.exports = {
   promises: {
@@ -19,22 +16,11 @@ module.exports = {
  * - message: a string detailing what happened
  */
 async function addEntry(projectId, operation, initiatorId, info = {}) {
-  const timestamp = new Date()
   const entry = {
+    projectId,
     operation,
     initiatorId,
-    timestamp,
     info,
   }
-  const result = await Project.updateOne(
-    { _id: projectId },
-    {
-      $push: {
-        auditLog: { $each: [entry], $slice: -MAX_AUDIT_LOG_ENTRIES },
-      },
-    }
-  ).exec()
-  if (result.nModified === 0) {
-    throw new OError('project not found', { projectId })
-  }
+  await ProjectAuditLogEntry.create(entry)
 }

services/web/app/src/Features/Project/ProjectDeleter.js

@@ -4,6 +4,7 @@ const { db, ObjectId } = require('../../infrastructure/mongodb')
 const { callbackify } = require('util')
 const { Project } = require('../../models/Project')
 const { DeletedProject } = require('../../models/DeletedProject')
+const { ProjectAuditLogEntry } = require('../../models/ProjectAuditLogEntry')
 const Errors = require('../Errors/Errors')
 const logger = require('@overleaf/logger')
 const DocumentUpdaterHandler = require('../DocumentUpdater/DocumentUpdaterHandler')
@@ -349,6 +350,7 @@ async function expireDeletedProject(projectId) {
       await DeletedProject.deleteOne({
         'deleterData.deletedProjectId': projectId,
       })
+      await ProjectAuditLogEntry.deleteMany({ projectId })
       return
     }
     const deletedProject = await DeletedProject.findOne({
@@ -386,6 +388,7 @@ async function expireDeletedProject(projectId) {
       }),
       ChatApiHandler.promises.destroyProject(deletedProject.project._id),
       hardDeleteDeletedFiles(deletedProject.project._id),
+      ProjectAuditLogEntry.deleteMany({ projectId }),
     ])
 
     await DeletedProject.updateOne(

services/web/app/src/Features/User/UserAuditLogHandler.js

@@ -1,9 +1,7 @@
 const OError = require('@overleaf/o-error')
-const { User } = require('../../models/User')
+const { UserAuditLogEntry } = require('../../models/UserAuditLogEntry')
 const { callbackify } = require('util')
 
-const MAX_AUDIT_LOG_ENTRIES = 200
-
 function _canHaveNoInitiatorId(operation, info) {
   if (operation === 'reset-password') return true
   if (operation === 'unlink-sso' && info.providerId === 'collabratec')
@@ -38,25 +36,15 @@ async function addEntry(userId, operation, initiatorId, ipAddress, info = {}) {
     })
   }
 
-  const timestamp = new Date()
   const entry = {
+    userId,
     operation,
     initiatorId,
     info,
     ipAddress,
-    timestamp,
-  }
-  const result = await User.updateOne(
-    { _id: userId },
-    {
-      $push: {
-        auditLog: { $each: [entry], $slice: -MAX_AUDIT_LOG_ENTRIES },
-      },
-    }
-  ).exec()
-  if (result.nModified === 0) {
-    throw new OError('user not found', { userId })
   }
+
+  await UserAuditLogEntry.create(entry)
 }
 
 const UserAuditLogHandler = {

services/web/app/src/Features/User/UserDeleter.js

@@ -3,6 +3,7 @@ const logger = require('@overleaf/logger')
 const moment = require('moment')
 const { User } = require('../../models/User')
 const { DeletedUser } = require('../../models/DeletedUser')
+const { UserAuditLogEntry } = require('../../models/UserAuditLogEntry')
 const NewsletterManager = require('../Newsletter/NewsletterManager')
 const ProjectDeleter = require('../Project/ProjectDeleter')
 const SubscriptionHandler = require('../Subscription/SubscriptionHandler')
@@ -87,7 +88,9 @@ async function expireDeletedUsersAfterDuration() {
   }
 
   for (let i = 0; i < deletedUsers.length; i++) {
-    await expireDeletedUser(deletedUsers[i].deleterData.deletedUserId)
+    const deletedUserId = deletedUsers[i].deleterData.deletedUserId
+    await expireDeletedUser(deletedUserId)
+    await UserAuditLogEntry.deleteMany({ userId: deletedUserId }).exec()
   }
 }
 

services/web/app/src/infrastructure/mongodb.js

@@ -59,6 +59,7 @@ async function setupDb() {
   db.oauthAccessTokens = internalDb.collection('oauthAccessTokens')
   db.oauthApplications = internalDb.collection('oauthApplications')
   db.oauthAuthorizationCodes = internalDb.collection('oauthAuthorizationCodes')
+  db.projectAuditLogEntries = internalDb.collection('projectAuditLogEntries')
   db.projectHistoryFailures = internalDb.collection('projectHistoryFailures')
   db.projectHistoryLabels = internalDb.collection('projectHistoryLabels')
   db.projectHistoryMetaData = internalDb.collection('projectHistoryMetaData')
@@ -78,6 +79,7 @@ async function setupDb() {
   db.teamInvites = internalDb.collection('teamInvites')
   db.templates = internalDb.collection('templates')
   db.tokens = internalDb.collection('tokens')
+  db.userAuditLogEntries = internalDb.collection('userAuditLogEntries')
   db.users = internalDb.collection('users')
   db.userstubs = internalDb.collection('userstubs')
 }

services/web/app/src/models/ProjectAuditLogEntry.js

@@ -0,0 +1,21 @@
+const mongoose = require('../infrastructure/Mongoose')
+const { Schema } = mongoose
+
+const ProjectAuditLogEntrySchema = new Schema(
+  {
+    projectId: { type: Schema.Types.ObjectId, index: true },
+    operation: { type: String },
+    initiatorId: { type: Schema.Types.ObjectId },
+    timestamp: { type: Date, default: Date.now },
+    info: { type: Object },
+  },
+  {
+    collection: 'projectAuditLogEntries',
+  }
+)
+
+exports.ProjectAuditLogEntry = mongoose.model(
+  'ProjectAuditLogEntry',
+  ProjectAuditLogEntrySchema
+)
+exports.ProjectAuditLogEntrySchema = ProjectAuditLogEntrySchema

services/web/app/src/models/UserAuditLogEntry.js

@@ -0,0 +1,22 @@
+const mongoose = require('../infrastructure/Mongoose')
+const { Schema } = mongoose
+
+const UserAuditLogEntrySchema = new Schema(
+  {
+    userId: { type: Schema.Types.ObjectId, index: true },
+    info: { type: Object },
+    initiatorId: { type: Schema.Types.ObjectId },
+    ipAddress: { type: String },
+    operation: { type: String },
+    timestamp: { type: Date, default: Date.now },
+  },
+  {
+    collection: 'userAuditLogEntries',
+  }
+)
+
+exports.UserAuditLogEntry = mongoose.model(
+  'UserAuditLogEntry',
+  UserAuditLogEntrySchema
+)
+exports.UserAuditLogEntrySchema = UserAuditLogEntrySchema

services/web/migrations/20220913105500_create_auditLog_indexes.js

@@ -0,0 +1,28 @@
+const Helpers = require('./lib/helpers')
+
+exports.tags = ['server-ce', 'server-pro', 'saas']
+
+const indexes = [
+  {
+    // expire after 2.5 years
+    expireAfterSeconds: 60 * 60 * 24 * 365 * 2.5,
+    key: {
+      timestamp: 1,
+    },
+    name: 'timestamp_1',
+  },
+]
+
+exports.migrate = async client => {
+  const { db } = client
+  await Helpers.addIndexesToCollection(db.projectAuditLogEntries, indexes)
+  await Helpers.addIndexesToCollection(db.userAuditLogEntries, indexes)
+}
+
+exports.rollback = async client => {
+  const { db } = client
+  await Promise.all([
+    Helpers.dropIndexesFromCollection(db.userAuditLogEntries, indexes),
+    Helpers.dropIndexesFromCollection(db.projectAuditLogEntries, indexes),
+  ])
+}

services/web/migrations/20220913125500_migrate_auditLog_to_collections.js

@@ -0,0 +1,13 @@
+const runScript = require('../scripts/migrate_audit_logs.js')
+
+exports.tags = ['server-ce', 'server-pro']
+
+exports.migrate = async () => {
+  const options = {
+    writeConcurrency: 10,
+    dryRun: false,
+  }
+  await runScript(options)
+}
+
+exports.rollback = async () => {}

services/web/scripts/migrate_audit_logs.js

@@ -0,0 +1,123 @@
+const { batchedUpdate } = require('./helpers/batchedUpdate')
+const { promiseMapWithLimit, promisify } = require('../app/src/util/promises')
+const { db, ObjectId, waitForDb } = require('../app/src/infrastructure/mongodb')
+const sleep = promisify(setTimeout)
+const _ = require('lodash')
+
+async function main(options) {
+  if (!options) {
+    options = {}
+  }
+  _.defaults(options, {
+    dryRun: process.env.DRY_RUN !== 'false',
+    projectId: process.env.PROJECT_ID,
+    userId: process.env.USER_ID,
+    writeConcurrency: parseInt(process.env.WRITE_CONCURRENCY, 10) || 10,
+    letUserDoubleCheckInputsFor: parseInt(
+      process.env.LET_USER_DOUBLE_CHECK_INPUTS_FOR || 10 * 1000,
+      10
+    ),
+  })
+
+  await letUserDoubleCheckInputs(options)
+
+  if (options.projectId) {
+    console.log('migrating projectId=' + options.projectId)
+    const project = await db.projects.findOne(
+      { _id: ObjectId(options.projectId) },
+      { _id: 1, auditLog: 1 }
+    )
+    await processProject(project, options)
+  } else if (options.userId) {
+    console.log('migrating userId=' + options.userId)
+    const user = await db.users.findOne(
+      { _id: ObjectId(options.userId) },
+      { _id: 1, auditLog: 1 }
+    )
+    await processUser(user, options)
+  } else {
+    await batchedUpdate(
+      'users',
+      { auditLog: { $exists: true } },
+      async (_, users) => {
+        await processUsersBatch(users, options)
+      },
+      { _id: 1, auditLog: 1 }
+    )
+  }
+}
+
+async function processUsersBatch(users, options) {
+  await promiseMapWithLimit(options.writeConcurrency, users, async user => {
+    await processUser(user, options)
+  })
+}
+
+async function processUser(user, options) {
+  const entries = user.auditLog.map(log => ({ ...log, userId: user._id }))
+  if (!options.dryRun && entries?.length > 0) {
+    await db.userAuditLogEntries.insertMany(entries)
+  }
+
+  if (!options.dryRun) {
+    await db.users.updateOne({ _id: user._id }, { $unset: { auditLog: 1 } })
+  }
+
+  const projects = await db.projects.find(
+    { owner_ref: user._id, auditLog: { $exists: true } },
+    { _id: 1, auditLog: 1 }
+  )
+  projects.forEach(project => processProject(project, options))
+}
+
+async function processProject(project, options) {
+  const entries = project.auditLog.map(log => ({
+    ...log,
+    projectId: project._id,
+  }))
+
+  if (!options.dryRun && entries?.length > 0) {
+    await db.projectAuditLogEntries.insertMany(entries)
+  }
+
+  if (!options.dryRun) {
+    await db.projects.updateOne(
+      { _id: project._id },
+      { $unset: { auditLog: 1 } }
+    )
+  }
+}
+
+async function letUserDoubleCheckInputs(options) {
+  const allOptions = {
+    ...options,
+    // batchedUpdate() environment variables
+    BATCH_DESCENDING: process.env.BATCH_DESCENDING,
+    BATCH_SIZE: process.env.BATCH_SIZE,
+    VERBOSE_LOGGING: process.env.VERBOSE_LOGGING,
+    BATCH_LAST_ID: process.env.BATCH_LAST_ID,
+    BATCH_RANGE_END: process.env.BATCH_RANGE_END,
+  }
+  console.error('Options:', JSON.stringify(allOptions, null, 2))
+  console.error(
+    'Waiting for you to double check inputs for',
+    options.letUserDoubleCheckInputsFor,
+    'ms'
+  )
+  await sleep(options.letUserDoubleCheckInputsFor)
+}
+
+module.exports = main
+
+if (require.main === module) {
+  waitForDb()
+    .then(main)
+    .then(() => {
+      console.log('Done.')
+      process.exit(0)
+    })
+    .catch(error => {
+      console.error({ error })
+      process.exit(1)
+    })
+}

services/web/test/acceptance/src/AuthenticationTests.js

@@ -59,18 +59,18 @@ describe('Authentication', function () {
     })
 
     it('should emit an user auditLog entry for the login', async function () {
-      const {
-        auditLog: [auditLogEntry],
-      } = await user.get()
+      const auditLog = await user.getAuditLog()
+      const auditLogEntry = auditLog[0]
       expect(auditLogEntry).to.exist
       expect(auditLogEntry.timestamp).to.exist
-      delete auditLogEntry.timestamp
-      expect(auditLogEntry).to.deep.equal({
-        operation: 'login',
-        ipAddress: '127.0.0.1',
-        initiatorId: ObjectId(user.id),
-        info: { method: 'Password login', captcha: 'solved' },
+      expect(auditLogEntry.initiatorId).to.deep.equal(ObjectId(user.id))
+      expect(auditLogEntry.userId).to.deep.equal(ObjectId(user.id))
+      expect(auditLogEntry.operation).to.equal('login')
+      expect(auditLogEntry.info).to.deep.equal({
+        method: 'Password login',
+        captcha: 'solved',
       })
+      expect(auditLogEntry.ipAddress).to.equal('127.0.0.1')
     })
   })
 

services/web/test/acceptance/src/CaptchaTests.js

@@ -79,7 +79,8 @@ describe('Captcha', function () {
     const { response, body } = await loginWithCaptcha('valid')
     expectSuccessfulLogin(response, body)
 
-    expect((await user.get()).auditLog.pop().info).to.deep.equal({
+    const auditLog = await user.getAuditLog()
+    expect(auditLog[0].info).to.deep.equal({
       captcha: 'solved',
       method: 'Password login',
     })
@@ -104,7 +105,8 @@ describe('Captcha', function () {
       const { response, body } = await loginWithCaptcha('')
       expectSuccessfulLogin(response, body)
 
-      expect((await user.get()).auditLog.pop().info).to.deep.equal({
+      const auditLog = await user.getAuditLog()
+      expect(auditLog[1].info).to.deep.equal({
         captcha: 'skipped',
         method: 'Password login',
       })

services/web/test/acceptance/src/helpers/User.js

@@ -44,14 +44,26 @@ class User {
     db.users.findOne({ _id: ObjectId(this._id) }, callback)
   }
 
-  getAuditLogWithoutNoise(callback) {
+  getAuditLog(callback) {
     this.get((error, user) => {
       if (error) return callback(error)
       if (!user) return callback(new Error('User not found'))
 
+      db.userAuditLogEntries
+        .find({ userId: ObjectId(this._id) })
+        .toArray((error, auditLog) => {
+          if (error) return callback(error)
+          callback(null, auditLog || [])
+        })
+    })
+  }
+
+  getAuditLogWithoutNoise(callback) {
+    this.getAuditLog((error, auditLog) => {
+      if (error) return callback(error)
       callback(
         null,
-        (user.auditLog || []).filter(entry => {
+        auditLog.filter(entry => {
           return entry.operation !== 'login'
         })
       )

services/web/test/acceptance/src/helpers/UserHelper.js

@@ -9,6 +9,9 @@ const moment = require('moment')
 const request = require('request-promise-native')
 const { db } = require('../../../../app/src/infrastructure/mongodb')
 const { ObjectId } = require('mongodb')
+const {
+  UserAuditLogEntry,
+} = require('../../../../app/src/models/UserAuditLogEntry')
 
 let globalUserNum = Settings.test.counterInit
 
@@ -201,6 +204,12 @@ class UserHelper {
       throw new Error(`no user found for args: ${JSON.stringify([...args])}`)
     }
 
+    user.auditLog = await UserAuditLogEntry.find(
+      { userId: user._id },
+      {},
+      { sort: { timestamp: 'asc' } }
+    ).exec()
+
     return new UserHelper(user)
   }
 

services/web/test/unit/src/Project/ProjectAuditLogHandlerTests.js

@@ -1,80 +0,0 @@
-const sinon = require('sinon')
-const { expect } = require('chai')
-const { ObjectId } = require('mongodb')
-const SandboxedModule = require('sandboxed-module')
-const { Project } = require('../helpers/models/Project')
-
-const MODULE_PATH =
-  '../../../../app/src/Features/Project/ProjectAuditLogHandler'
-
-describe('ProjectAuditLogHandler', function () {
-  beforeEach(function () {
-    this.projectId = ObjectId()
-    this.userId = ObjectId()
-    this.ProjectMock = sinon.mock(Project)
-    this.ProjectAuditLogHandler = SandboxedModule.require(MODULE_PATH, {
-      requires: {
-        '../../models/Project': { Project },
-      },
-    })
-  })
-
-  afterEach(function () {
-    this.ProjectMock.restore()
-  })
-
-  describe('addEntry', function () {
-    describe('success', function () {
-      beforeEach(async function () {
-        this.dbUpdate = this.ProjectMock.expects('updateOne').withArgs(
-          { _id: this.projectId },
-          {
-            $push: {
-              auditLog: {
-                $each: [
-                  {
-                    operation: 'translate',
-                    initiatorId: this.userId,
-                    info: { destinationLanguage: 'tagalog' },
-                    timestamp: sinon.match.typeOf('date'),
-                  },
-                ],
-                $slice: -200,
-              },
-            },
-          }
-        )
-        this.dbUpdate.chain('exec').resolves({ nModified: 1 })
-        this.operationId = await this.ProjectAuditLogHandler.promises.addEntry(
-          this.projectId,
-          'translate',
-          this.userId,
-          { destinationLanguage: 'tagalog' }
-        )
-      })
-
-      it('writes a log', async function () {
-        this.ProjectMock.verify()
-      })
-    })
-
-    describe('when the project does not exist', function () {
-      beforeEach(function () {
-        this.ProjectMock.expects('updateOne')
-          .chain('exec')
-          .resolves({ nModified: 0 })
-      })
-
-      it('throws an error', async function () {
-        await expect(
-          this.ProjectAuditLogHandler.promises.addEntry(
-            this.projectId,
-            'translate',
-            this.userId,
-            { destinationLanguage: 'tagalog' }
-          )
-        ).to.be.rejected
-      })
-    })
-  })
-})

services/web/test/unit/src/Project/ProjectDeleterTests.js

@@ -140,7 +140,9 @@ describe('ProjectDeleter', function () {
         destroyProject: sinon.stub().resolves(),
       },
     }
-
+    this.ProjectAuditLogEntry = {
+      deleteMany: sinon.stub().returns({ exec: sinon.stub().resolves() }),
+    }
     this.ProjectDeleter = SandboxedModule.require(modulePath, {
       requires: {
         '../../infrastructure/Features': this.Features,
@@ -160,6 +162,9 @@ describe('ProjectDeleter', function () {
         './ProjectDetailsHandler': this.ProjectDetailsHandler,
         '../../infrastructure/mongodb': { db: this.db, ObjectId },
         '../History/HistoryManager': this.HistoryManager,
+        '../../models/ProjectAuditLogEntry': {
+          ProjectAuditLogEntry: this.ProjectAuditLogEntry,
+        },
       },
     })
   })
@@ -500,6 +505,12 @@ describe('ProjectDeleter', function () {
           this.ChatApiHandler.promises.destroyProject
         ).to.have.been.calledWith(this.deletedProjects[0].project._id)
       })
+
+      it('should delete audit logs', async function () {
+        expect(this.ProjectAuditLogEntry.deleteMany).to.have.been.calledWith({
+          projectId: this.deletedProjects[0].project._id,
+        })
+      })
     })
 
     describe('when history-v1 is not available', function () {

services/web/test/unit/src/User/UserAuditLogHandlerTests.js

@@ -2,7 +2,7 @@ const sinon = require('sinon')
 const { expect } = require('chai')
 const { ObjectId } = require('mongodb')
 const SandboxedModule = require('sandboxed-module')
-const { User } = require('../helpers/models/User')
+const { UserAuditLogEntry } = require('../helpers/models/UserAuditLogEntry')
 
 const MODULE_PATH = '../../../../app/src/Features/User/UserAuditLogHandler'
 
@@ -23,22 +23,22 @@ describe('UserAuditLogHandler', function () {
       },
       ip: '0:0:0:0',
     }
-    this.UserMock = sinon.mock(User)
+    this.UserAuditLogEntryMock = sinon.mock(UserAuditLogEntry)
     this.UserAuditLogHandler = SandboxedModule.require(MODULE_PATH, {
       requires: {
-        '../../models/User': { User },
+        '../../models/UserAuditLogEntry': { UserAuditLogEntry },
       },
     })
   })
 
   afterEach(function () {
-    this.UserMock.restore()
+    this.UserAuditLogEntryMock.restore()
   })
 
   describe('addEntry', function () {
     describe('success', function () {
       beforeEach(function () {
-        this.dbUpdate = this.UserMock.expects('updateOne')
+        this.dbUpdate = this.UserAuditLogEntryMock.expects('create')
           .chain('exec')
           .resolves({ nModified: 1 })
       })
@@ -50,7 +50,7 @@ describe('UserAuditLogHandler', function () {
           this.action.ip,
           this.action.info
         )
-        this.UserMock.verify()
+        this.UserAuditLogEntryMock.verify()
       })
 
       it('updates the log for password reset operation witout a initiatorId', async function () {
@@ -63,7 +63,7 @@ describe('UserAuditLogHandler', function () {
             this.action.info
           )
         )
-        this.UserMock.verify()
+        this.UserAuditLogEntryMock.verify()
       })
 
       it('updates the log for a email removal via script', async function () {
@@ -79,31 +79,11 @@ describe('UserAuditLogHandler', function () {
             }
           )
         )
-        this.UserMock.verify()
+        this.UserAuditLogEntryMock.verify()
       })
     })
 
     describe('errors', function () {
-      describe('when the user does not exist', function () {
-        beforeEach(function () {
-          this.UserMock.expects('updateOne')
-            .chain('exec')
-            .resolves({ nModified: 0 })
-        })
-
-        it('throws an error', async function () {
-          await expect(
-            this.UserAuditLogHandler.promises.addEntry(
-              this.userId,
-              this.action.operation,
-              this.action.initiatorId,
-              this.action.ip,
-              this.action.info
-            )
-          ).to.be.rejected
-        })
-      })
-
       describe('missing parameters', function () {
         it('throws an error when no operation', async function () {
           await expect(

services/web/test/unit/src/User/UserDeleterTests.js

@@ -84,6 +84,10 @@ describe('UserDeleter', function () {
       },
     }
 
+    this.UserAuditLogEntry = {
+      deleteMany: sinon.stub().returns({ exec: sinon.stub().resolves() }),
+    }
+
     this.UserDeleter = SandboxedModule.require(modulePath, {
       requires: {
         '../../models/User': { User },
@@ -96,6 +100,9 @@ describe('UserDeleter', function () {
         '../UserMembership/UserMembershipsHandler': this.UserMembershipsHandler,
         '../Project/ProjectDeleter': this.ProjectDeleter,
         '../Institutions/InstitutionsAPI': this.InstitutionsApi,
+        '../../models/UserAuditLogEntry': {
+          UserAuditLogEntry: this.UserAuditLogEntry,
+        },
       },
     })
   })
@@ -420,6 +427,15 @@ describe('UserDeleter', function () {
         expect(deletedUser.save.called).to.be.true
       }
     })
+
+    it('deletes audit logs for all deleted users', async function () {
+      await this.UserDeleter.promises.expireDeletedUsersAfterDuration()
+      for (const deletedUser of this.deletedUsers) {
+        expect(this.UserAuditLogEntry.deleteMany).to.have.been.calledWith({
+          userId: deletedUser.deleterData.deletedUserId,
+        })
+      }
+    })
   })
 
   describe('expireDeletedUser', function () {

services/web/test/unit/src/helpers/models/UserAuditLogEntry.js

@@ -0,0 +1,3 @@
+const mockModel = require('../MockModel')
+
+module.exports = mockModel('UserAuditLogEntry')