Merge pull request #544 from sharelatex/bg-add-lockvalue-to-lockmanager

improve locking in web

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

@@ -3,20 +3,37 @@ Settings = require('settings-sharelatex')
 RedisWrapper = require("./RedisWrapper")
 rclient = RedisWrapper.client("lock")
 logger = require "logger-sharelatex"
+os = require "os"
+crypto = require "crypto"
+
+HOST = os.hostname()
+PID = process.pid
+RND = crypto.randomBytes(4).toString('hex')
+COUNT = 0
 
 module.exports = LockManager =
 	LOCK_TEST_INTERVAL: 50 # 50ms between each test of the lock
+	MAX_TEST_INTERVAL: 1000 # back off to 1s 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
 	SLOW_EXECUTION_THRESHOLD: 5000 # 5s, if execution takes longer than this then log
 
+	# Use a signed lock value as described in
+	# http://redis.io/topics/distlock#correct-implementation-with-a-single-instance
+	# to prevent accidental unlocking by multiple processes
+	randomLock : () ->
+		time = Date.now()
+		return "locked:host=#{HOST}:pid=#{PID}:random=#{RND}:time=#{time}:count=#{COUNT++}"
+
+	unlockScript: 'if redis.call("get", KEYS[1]) == ARGV[1] then return redis.call("del", KEYS[1]) else return 0 end'
+
 	runWithLock: (namespace, id, runner = ( (releaseLock = (error) ->) -> ), callback = ( (error) -> )) ->
 		# This error is defined here so we get a useful stacktrace
 		slowExecutionError = new Error "slow execution during lock"
 
 		timer = new metrics.Timer("lock.#{namespace}")
 		key = "lock:web:#{namespace}:#{id}"
-		LockManager._getLock key, namespace, (error) ->
+		LockManager._getLock key, namespace, (error, lockValue) ->
 			return callback(error) if error?
 
 			# The lock can expire in redis but the process carry on. This setTimout call
@@ -27,7 +44,7 @@ module.exports = LockManager =
 			exceededLockTimeout = setTimeout countIfExceededLockTimeout, LockManager.REDIS_LOCK_EXPIRY * 1000
 
 			runner (error1, values...) ->
-				LockManager._releaseLock key, (error2) ->
+				LockManager._releaseLock key, lockValue, (error2) ->
 					clearTimeout exceededLockTimeout
 
 					timeTaken = new Date - timer.start
@@ -39,19 +56,21 @@ module.exports = LockManager =
 					return callback(error) if error?
 					callback null, values...
 
-	_tryLock : (key, namespace, callback = (err, isFree)->)->
-		rclient.set key, "locked", "EX", LockManager.REDIS_LOCK_EXPIRY, "NX", (err, gotLock)->
+	_tryLock : (key, namespace, callback = (err, isFree, lockValue)->)->
+		lockValue = LockManager.randomLock()
+		rclient.set key, lockValue, "EX", LockManager.REDIS_LOCK_EXPIRY, "NX", (err, gotLock)->
 			return callback(err) if err?
 			if gotLock == "OK"
 				metrics.inc "lock.#{namespace}.try.success"
-				callback err, true
+				callback err, true, lockValue
 			else
 				metrics.inc "lock.#{namespace}.try.failed"
 				logger.log key: key, redis_response: gotLock, "lock is locked"
 				callback err, false
 
-	_getLock: (key, namespace, callback = (error) ->) ->
+	_getLock: (key, namespace, callback = (error, lockValue) ->) ->
 		startTime = Date.now()
+		testInterval = LockManager.LOCK_TEST_INTERVAL
 		attempts = 0
 		do attempt = () ->
 			if Date.now() - startTime > LockManager.MAX_LOCK_WAIT_TIME
@@ -59,13 +78,23 @@ module.exports = LockManager =
 				return callback(new Error("Timeout"))
 
 			attempts += 1
-			LockManager._tryLock key, namespace, (error, gotLock) ->
+			LockManager._tryLock key, namespace, (error, gotLock, lockValue) ->
 				return callback(error) if error?
 				if gotLock
 					metrics.gauge "lock.#{namespace}.get.success.tries", attempts
-					callback(null)
+					callback(null, lockValue)
 				else
-					setTimeout attempt, LockManager.LOCK_TEST_INTERVAL
+					setTimeout attempt, testInterval
+					# back off when the lock is taken to avoid overloading
+					testInterval = Math.min(testInterval * 2, LockManager.MAX_TEST_INTERVAL)
 
-	_releaseLock: (key, callback)->
-		rclient.del key, callback
+	_releaseLock: (key, lockValue, callback)->
+		rclient.eval LockManager.unlockScript, 1, key, lockValue, (err, result) ->
+			if err?
+				return callback(err)
+			else if result? and result isnt 1 # successful unlock should release exactly one key
+				logger.error {key:key, lockValue:lockValue, redis_err:err, redis_result:result}, "unlocking error"
+				metrics.inc "unlock-error"
+				return callback(new Error("tried to release timed out lock"))
+			else
+				callback(null,result)

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

@@ -22,6 +22,7 @@ describe "ProjectStructureMongoLock", ->
 		before (done) ->
 			# We want to instantly fail if the lock is taken
 			LockManager.MAX_LOCK_WAIT_TIME = 1
+			@lockValue = "lock-value"
 			userDetails =
 				holdingAccount:false,
 				email: 'test@example.com'
@@ -33,11 +34,13 @@ describe "ProjectStructureMongoLock", ->
 					@locked_project = project
 					namespace = ProjectEntityMongoUpdateHandler.LOCK_NAMESPACE
 					@lock_key = "lock:web:#{namespace}:#{project._id}"
-					LockManager._getLock @lock_key, namespace, done
+					LockManager._getLock @lock_key, namespace, (err, lockValue) =>
+						@lockValue = lockValue
+						done()
 			return
 
 		after (done) ->
-			LockManager._releaseLock @lock_key, done
+			LockManager._releaseLock @lock_key, @lockValue, done
 
 		describe 'interacting with the locked project', ->
 			LOCKING_UPDATE_METHODS = ['addDoc', 'addFile', 'mkdirp', 'moveEntity', 'renameEntity', 'addFolder']

services/web/test/unit/coffee/infrastructure/LockManager/ReleasingTheLock.coffee

@@ -3,23 +3,25 @@ assert = require('assert')
 path = require('path')
 modulePath = path.join __dirname, '../../../../../app/js/infrastructure/LockManager.js'
 lockKey = "lock:web:{#{5678}}"
+lockValue = "123456"
 SandboxedModule = require('sandboxed-module')
 
 describe 'LockManager - releasing the lock', ()->
 
-	deleteStub = sinon.stub().callsArgWith(1)
+	deleteStub = sinon.stub().callsArgWith(4)
 	mocks =
 		"logger-sharelatex": log:->
 
 		"./RedisWrapper":
 			client: ()->
 				auth:->
-				del:deleteStub
-	
-	LockManager = SandboxedModule.require(modulePath, requires: mocks)
+				eval:deleteStub
 
+	LockManager = SandboxedModule.require(modulePath, requires: mocks)
+	LockManager.unlockScript = "this is the unlock script"
+	
 	it 'should put a all data into memory', (done)->
-		LockManager._releaseLock lockKey, ->
-			deleteStub.calledWith(lockKey).should.equal true
+		LockManager._releaseLock lockKey, lockValue, ->
+			deleteStub.calledWith(LockManager.unlockScript, 1, lockKey, lockValue).should.equal true
 			done()
 

services/web/test/unit/coffee/infrastructure/LockManager/tryLockTests.coffee

@@ -22,10 +22,11 @@ describe 'LockManager - trying the lock', ->
 	describe "when the lock is not set", ->
 		beforeEach ->
 			@set.callsArgWith(5, null, "OK")
+			@LockManager.randomLock = sinon.stub().returns("random-lock-value")
 			@LockManager._tryLock @key, @namespace, @callback
 
 		it "should set the lock key with an expiry if it is not set", ->
-			@set.calledWith(@key, "locked", "EX", 30, "NX")
+			@set.calledWith(@key, "random-lock-value", "EX", 30, "NX")
 				.should.equal true
 
 		it "should return the callback with true", ->