Merge pull request #54 from sharelatex/bg-timeout-on-slow-lock

add timeout on slow lock

services/document-updater/app/coffee/LockManager.coffee

@@ -14,6 +14,8 @@ PID = process.pid
 RND = crypto.randomBytes(4).toString('hex')
 COUNT = 0
 
+MAX_REDIS_REQUEST_LENGTH = 5000 # 5 seconds
+
 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
@@ -37,12 +39,18 @@ module.exports = LockManager =
 			return callback(err) if err?
 			if gotLock == "OK"
 				metrics.inc "doc-not-blocking"
-				profile.log("got lock").end()
-				callback err, true, lockValue
+				timeTaken = profile.log("got lock").end()
+				if timeTaken > MAX_REDIS_REQUEST_LENGTH
+					# took too long, so try to free the lock
+					LockManager.releaseLock doc_id, lockValue, (err, result) ->
+						return callback(err) if err? # error freeing lock
+						callback null, false # tell caller they didn't get the lock
+				else
+					callback null, true, lockValue
 			else
 				metrics.inc "doc-blocking"
 				profile.log("doc is locked").end()
-				callback err, false
+				callback null, false
 
 	getLock: (doc_id, callback = (error, lockValue) ->) ->
 		startTime = Date.now()
@@ -73,10 +81,10 @@ module.exports = LockManager =
 			exists = parseInt exists
 			if exists == 1
 				metrics.inc "doc-blocking"
-				callback err, false
+				callback null, false
 			else
 				metrics.inc "doc-not-blocking"
-				callback err, true
+				callback null, true
 
 	releaseLock: (doc_id, lockValue, callback)->
 		key = keys.blockingKey(doc_id:doc_id)
@@ -91,4 +99,4 @@ module.exports = LockManager =
 				return callback(new Error("tried to release timed out lock"))
 			else
 				profile.log("unlockScript:ok").end()
-				callback(err,result)
+				callback(null,result)

services/document-updater/app/coffee/Profiler.coffee

@@ -23,11 +23,12 @@ module.exports = class Profiler
 
 	end: (message) ->
 		totalTime = deltaMs(@t, @t0)
-		return if totalTime < @LOG_CUTOFF_TIME # skip anything less than cutoff
-		args = {}
-		for k,v of @args
-			args[k] = v
-		args.updateTimes = @updateTimes
-		args.start = @start
-		args.end = new Date()
-		logger.log args, @name
+		if totalTime > @LOG_CUTOFF_TIME # log anything greater than cutoff
+			args = {}
+			for k,v of @args
+				args[k] = v
+			args.updateTimes = @updateTimes
+			args.start = @start
+			args.end = new Date()
+			logger.log args, @name
+		return totalTime

services/document-updater/test/unit/coffee/LockManager/tryLockTests.coffee

@@ -19,7 +19,7 @@ describe 'LockManager - trying the lock', ->
 						key_schema:
 							blockingKey: ({doc_id}) -> "Blocking:#{doc_id}"
 			}
-			"./Profiler": class Profiler
+			"./Profiler": @Profiler = class Profiler
 				log: sinon.stub().returns { end: sinon.stub() }
 				end: sinon.stub()
 
@@ -48,3 +48,39 @@ describe 'LockManager - trying the lock', ->
 		it "should return the callback with false", ->
 			@callback.calledWith(null, false).should.equal true
 
+	describe "when it takes a long time for redis to set the lock", ->
+		beforeEach ->
+			@Profiler.prototype.end = () -> 7000 # take a long time
+			@Profiler.prototype.log = sinon.stub().returns { end: @Profiler.prototype.end }
+			@lockValue = "mock-lock-value"
+			@LockManager.randomLock = sinon.stub().returns @lockValue
+			@LockManager.releaseLock = sinon.stub().callsArgWith(2,null)
+			@set.callsArgWith(5, null, "OK")
+
+		describe "in all cases", ->
+			beforeEach ->
+				@LockManager.tryLock @doc_id, @callback
+
+			it "should set the lock key with an expiry if it is not set", ->
+				@set.calledWith("Blocking:#{@doc_id}", @lockValue, "EX", 30, "NX")
+					.should.equal true
+
+			it "should try to release the lock", ->
+				@LockManager.releaseLock.calledWith(@doc_id, @lockValue).should.equal true
+
+		describe "if the lock is released successfully", ->
+			beforeEach ->
+				@LockManager.releaseLock = sinon.stub().callsArgWith(2,null)
+				@LockManager.tryLock @doc_id, @callback
+
+			it "should return the callback with false", ->
+				@callback.calledWith(null, false).should.equal true
+
+		describe "if the lock has already timed out", ->
+			beforeEach ->
+				@LockManager.releaseLock = sinon.stub().callsArgWith(2, new Error("tried to release timed out lock"))
+				@LockManager.tryLock @doc_id, @callback
+
+			it "should return the callback with an error", ->
+				e = new Error("tried to release timed out lock")
+				@callback.calledWith(e).should.equal true