add extra metrics around locking

services/web/app/coffee/Features/Project/ProjectEntityMongoUpdateHandler.coffee

@@ -13,20 +13,23 @@ ProjectGetter = require('./ProjectGetter')
 ProjectLocator = require('./ProjectLocator')
 SafePath = require './SafePath'
 
+LOCK_NAMESPACE = "mongoTransaction"
+
 wrapWithLock = (methodWithoutLock) ->
 	# This lock is used whenever we read or write to an existing project's
 	# structure. Some operations to project structure cannot be done atomically
 	# in mongo, this lock is used to prevent reading the structure between two
 	# parts of a staged update.
 	methodWithLock = (project_id, args..., callback) ->
-		lockKey = ProjectEntityMongoUpdateHandler.getProjectMongoLockKey project_id
-		LockManager.runWithLock lockKey,
+		LockManager.runWithLock LOCK_NAMESPACE, project_id,
 			(cb) -> methodWithoutLock project_id, args..., cb
 			callback
 	methodWithLock.withoutLock = methodWithoutLock
 	methodWithLock
 
 module.exports = ProjectEntityMongoUpdateHandler = self =
+	LOCK_NAMESPACE: LOCK_NAMESPACE
+
 	addDoc: wrapWithLock (project_id, folder_id, doc, callback = (err, result) ->) ->
 		ProjectGetter.getProjectWithoutLock project_id, {rootFolder:true, name:true}, (err, project) ->
 			if err?
@@ -166,9 +169,6 @@ module.exports = ProjectEntityMongoUpdateHandler = self =
 						return callback(err)
 					callback null, folder, parentFolder_id
 
-	getProjectMongoLockKey: (project_id) ->
-		"lock:web:mongoTransaction:{#{project_id}}"
-
 	_removeElementFromMongoArray: (model, model_id, path, callback = (err, project) ->)->
 		conditions = {_id:model_id}
 		update = {"$unset":{}}

services/web/app/coffee/Features/Project/ProjectEntityUpdateHandler.coffee

@@ -18,13 +18,14 @@ ProjectEntityMongoUpdateHandler = require('./ProjectEntityMongoUpdateHandler')
 SafePath = require './SafePath'
 TpdsUpdateSender = require('../ThirdPartyDataStore/TpdsUpdateSender')
 
+LOCK_NAMESPACE = "sequentialProjectStructureUpdateLock"
+
 wrapWithLock = (methodWithoutLock) ->
 	# This lock is used to make sure that the project structure updates are made
 	# sequentially. In particular the updates must be made in mongo and sent to
 	# the doc-updater in the same order.
 	methodWithLock = (project_id, args..., callback) ->
-		lockKey = "lock:web:sequentialProjectStructureUpdateLock:{#{project_id}}"
-		LockManager.runWithLock lockKey,
+		LockManager.runWithLock LOCK_NAMESPACE, project_id,
 			(cb) -> methodWithoutLock project_id, args..., cb
 			callback
 	methodWithLock.withoutLock = methodWithoutLock

services/web/app/coffee/Features/Project/ProjectGetter.coffee

@@ -36,8 +36,7 @@ module.exports = ProjectGetter =
 
 		if projection?.rootFolder || Object.keys(projection).length == 0
 			ProjectEntityMongoUpdateHandler = require './ProjectEntityMongoUpdateHandler'
-			lockKey = ProjectEntityMongoUpdateHandler.getProjectMongoLockKey project_id
-			LockManager.runWithLock lockKey,
+			LockManager.runWithLock ProjectEntityMongoUpdateHandler.LOCK_NAMESPACE, project_id,
 				(cb) -> ProjectGetter.getProjectWithoutLock project_id, projection, cb
 				callback
 		else

services/web/app/coffee/infrastructure/LockManager.coffee

@@ -7,13 +7,36 @@ logger = require "logger-sharelatex"
 module.exports = LockManager =
 	LOCK_TEST_INTERVAL: 50 # 50ms between each test of the lock
 	MAX_LOCK_WAIT_TIME: 10000 # 10s maximum time to spend trying to get the lock
-	REDIS_LOCK_EXPIRY: 30 # seconds. Time until lock auto expires in redis.
+	REDIS_LOCK_EXPIRY: 30 # seconds. Time until lock auto expires in redis
+	SLOW_EXECUTION_THRESHOLD: 5000 # 5s, if execution takes longer than this then log
 
-	runWithLock: (key, runner = ( (releaseLock = (error) ->) -> ), callback = ( (error) -> )) ->
+	runWithLock: (namespace, id, runner = ( (releaseLock = (error) ->) -> ), callback = ( (error) -> )) ->
+
+		# The lock can expire in redis but the process carry on. This setTimout call
+		# is designed to log if this happens.
+		#
+		# error is defined here so we get a useful stacktrace
+		lockReleased = false
+		slowExecutionError = new Error "slow execution during lock"
+		countIfExceededLockTimeout = () ->
+			if !lockReleased
+				metrics.inc "lock.#{namespace}.exceeded_lock_timeout"
+				logger.log "exceeded lock timeout", { namespace, id, slowExecutionError }
+
+		setTimeout countIfExceededLockTimeout, LockManager.REDIS_LOCK_EXPIRY
+
+		timer = new metrics.Timer("lock.#{namespace}")
+		key = "lock:web:#{namespace}:#{id}"
 		LockManager._getLock key, (error) ->
 			return callback(error) if error?
 			runner (error1, values...) ->
 				LockManager._releaseLock key, (error2) ->
+					lockReleased = true
+					timeTaken = new Date - timer.start
+					if timeTaken > LockManager.SLOW_EXECUTION_THRESHOLD
+						logger.log "slow execution during lock", { namespace, id, timeTaken, slowExecutionError }
+
+					timer.done()
 					error = error1 or error2
 					return callback(error) if error?
 					callback null, values...

services/web/test/acceptance/coffee/ProjectStructureMongoLockTest.coffee

@@ -31,12 +31,11 @@ describe "ProjectStructureMongoLock", ->
 				ProjectCreationHandler.createBlankProject user._id, 'locked-project', (err, project) =>
 					throw err if err?
 					@locked_project = project
-					lockKey = ProjectEntityMongoUpdateHandler.getProjectMongoLockKey @locked_project._id
-					LockManager._getLock lockKey, done
+					@lock_key = "lock:web:#{ProjectEntityMongoUpdateHandler.LOCK_NAMESPACE}:#{project._id}"
+					LockManager._getLock @lock_key, done
 
 		after (done) ->
-			lockKey = ProjectEntityMongoUpdateHandler.getProjectMongoLockKey @locked_project._id
-			LockManager._releaseLock lockKey, done
+			LockManager._releaseLock @lock_key, done
 
 		describe 'interacting with the locked project', ->
 			LOCKING_UPDATE_METHODS = ['addDoc', 'addFile', 'mkdirp', 'moveEntity', 'renameEntity', 'addFolder']

services/web/test/unit/coffee/Project/ProjectEntityMongoUpdateHandlerTests.coffee

@@ -37,7 +37,7 @@ describe 'ProjectEntityMongoUpdateHandler', ->
 			'../../models/Folder': Folder:@FolderModel
 			"../../infrastructure/LockManager":@LockManager =
 				runWithLock:
-					sinon.spy((key, runner, callback) -> runner(callback))
+					sinon.spy((namespace, id, runner, callback) -> runner(callback))
 			'../../models/Project': Project:@ProjectModel = {}
 			'./ProjectEntityHandler': @ProjectEntityHandler = {}
 			'./ProjectLocator': @ProjectLocator = {}

services/web/test/unit/coffee/Project/ProjectEntityUpdateHandlerTests.coffee

@@ -53,7 +53,7 @@ describe 'ProjectEntityUpdateHandler', ->
 			'../FileStore/FileStoreHandler':@FileStoreHandler
 			"../../infrastructure/LockManager":@LockManager =
 				runWithLock:
-					sinon.spy((key, runner, callback) -> runner(callback))
+					sinon.spy((namespace, id, runner, callback) -> runner(callback))
 			'../../models/Project': Project:@ProjectModel = {}
 			"./ProjectGetter": @ProjectGetter = {}
 			'./ProjectLocator': @ProjectLocator = {}

services/web/test/unit/coffee/Project/ProjectGetterTests.coffee

@@ -20,7 +20,7 @@ describe "ProjectGetter", ->
 			"../../models/Project": Project: @Project = {}
 			"../Collaborators/CollaboratorsHandler": @CollaboratorsHandler = {}
 			"../../infrastructure/LockManager": @LockManager =
-					runWithLock : sinon.spy((key, runner, callback) -> runner(callback))
+					runWithLock : sinon.spy((namespace, id, runner, callback) -> runner(callback))
 			'./ProjectEntityMongoUpdateHandler':
 					lockKey: (project_id) -> project_id
 			"logger-sharelatex":