diff --git a/services/document-updater/app/coffee/LockManager.coffee b/services/document-updater/app/coffee/LockManager.coffee index 716cac2291..8f62e46ccb 100644 --- a/services/document-updater/app/coffee/LockManager.coffee +++ b/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) diff --git a/services/document-updater/app/coffee/Profiler.coffee b/services/document-updater/app/coffee/Profiler.coffee index dc88345334..1d85f9bd98 100644 --- a/services/document-updater/app/coffee/Profiler.coffee +++ b/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 diff --git a/services/document-updater/test/unit/coffee/LockManager/tryLockTests.coffee b/services/document-updater/test/unit/coffee/LockManager/tryLockTests.coffee index 7b52f416ab..82de2f45b8 100644 --- a/services/document-updater/test/unit/coffee/LockManager/tryLockTests.coffee +++ b/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