From ffea31290cd5cd1db29772d0745c465e4461e04e Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Tue, 11 Jul 2017 14:25:26 +0100 Subject: [PATCH 1/5] return total time from the profile .end() method --- .../document-updater/app/coffee/Profiler.coffee | 17 +++++++++-------- 1 file changed, 9 insertions(+), 8 deletions(-) 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 From 54c0fc1180b20ce52d943459d3deadab561af304 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Tue, 11 Jul 2017 14:25:59 +0100 Subject: [PATCH 2/5] put a 5 second timeout in getting redis lock --- services/document-updater/app/coffee/LockManager.coffee | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/services/document-updater/app/coffee/LockManager.coffee b/services/document-updater/app/coffee/LockManager.coffee index 716cac2291..cd6df46878 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,8 +39,11 @@ 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 + callback err, false # took too long to get the lock, bail out + else + callback err, true, lockValue else metrics.inc "doc-blocking" profile.log("doc is locked").end() From bb0dc4b4d5a2885529b2c804ece5f1460cf78788 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Wed, 12 Jul 2017 10:45:23 +0100 Subject: [PATCH 3/5] release the lock if it took too long to acquire it --- services/document-updater/app/coffee/LockManager.coffee | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/services/document-updater/app/coffee/LockManager.coffee b/services/document-updater/app/coffee/LockManager.coffee index cd6df46878..0aa1e3695e 100644 --- a/services/document-updater/app/coffee/LockManager.coffee +++ b/services/document-updater/app/coffee/LockManager.coffee @@ -41,7 +41,10 @@ module.exports = LockManager = metrics.inc "doc-not-blocking" timeTaken = profile.log("got lock").end() if timeTaken > MAX_REDIS_REQUEST_LENGTH - callback err, false # took too long to get the lock, bail out + # 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 err, true, lockValue else From d2730c8d6b7da77acb408d22c573b3b97ddae1b1 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Wed, 12 Jul 2017 10:45:44 +0100 Subject: [PATCH 4/5] unit tests for locking timeouts --- .../coffee/LockManager/tryLockTests.coffee | 38 ++++++++++++++++++- 1 file changed, 37 insertions(+), 1 deletion(-) 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 From c21cc013f3fe9fb9c60da7c6b91124c7bd0d1d2b Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Wed, 12 Jul 2017 10:47:23 +0100 Subject: [PATCH 5/5] use null instead of err in callbacks on success --- .../document-updater/app/coffee/LockManager.coffee | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/services/document-updater/app/coffee/LockManager.coffee b/services/document-updater/app/coffee/LockManager.coffee index 0aa1e3695e..8f62e46ccb 100644 --- a/services/document-updater/app/coffee/LockManager.coffee +++ b/services/document-updater/app/coffee/LockManager.coffee @@ -46,11 +46,11 @@ module.exports = LockManager = return callback(err) if err? # error freeing lock callback null, false # tell caller they didn't get the lock else - callback err, true, lockValue + 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() @@ -81,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) @@ -99,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)