From 584cd711739d28b46a7b5610251d968ee8fa9267 Mon Sep 17 00:00:00 2001 From: Hayden Faulds Date: Tue, 20 Feb 2018 14:03:43 +0000 Subject: [PATCH] fix exceeded lock timeout logging we were logging this after failing to get the lock, this stops that --- .../coffee/infrastructure/LockManager.coffee | 24 +++++++++---------- 1 file changed, 11 insertions(+), 13 deletions(-) diff --git a/services/web/app/coffee/infrastructure/LockManager.coffee b/services/web/app/coffee/infrastructure/LockManager.coffee index 4c45d8703b..f3b53beda7 100644 --- a/services/web/app/coffee/infrastructure/LockManager.coffee +++ b/services/web/app/coffee/infrastructure/LockManager.coffee @@ -11,27 +11,25 @@ module.exports = LockManager = SLOW_EXECUTION_THRESHOLD: 5000 # 5s, if execution takes longer than this then log 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 + # This error is defined here so we get a useful stacktrace 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 * 1000 timer = new metrics.Timer("lock.#{namespace}") key = "lock:web:#{namespace}:#{id}" LockManager._getLock key, namespace, (error) -> return callback(error) if error? + + # The lock can expire in redis but the process carry on. This setTimout call + # is designed to log if this happens. + countIfExceededLockTimeout = () -> + metrics.inc "lock.#{namespace}.exceeded_lock_timeout" + logger.log "exceeded lock timeout", { namespace, id, slowExecutionError } + exceededLockTimeout = setTimeout countIfExceededLockTimeout, LockManager.REDIS_LOCK_EXPIRY * 1000 + runner (error1, values...) -> LockManager._releaseLock key, (error2) -> - lockReleased = true + clearTimeout exceededLockTimeout + timeTaken = new Date - timer.start if timeTaken > LockManager.SLOW_EXECUTION_THRESHOLD logger.log "slow execution during lock", { namespace, id, timeTaken, slowExecutionError }