Timeout secondary requests if they take longer than 200ms

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

@@ -6,6 +6,7 @@ Metrics = require "metrics-sharelatex"
 
 class Client
 	constructor: (@clients) ->
+		@SECONDARY_TIMEOUT = 200
 		@HEARTBEAT_TIMEOUT = 2000
 		
 	multi: () ->
@@ -56,14 +57,24 @@ class Client
 
 class MultiClient
 	constructor: (@clients) ->
+		@SECONDARY_TIMEOUT = 200
 	
 	exec: (callback) ->
 		primaryError = null
 		primaryResult = null
-		jobs = @clients.map (client) ->
-			(cb) ->
+		jobs = @clients.map (client) =>
+			(cb) =>
+				cb = _.once(cb)
 				timer = new Metrics.Timer("redis.#{client.driver}.exec")
-				client.rclient.exec (error, result) ->
+				
+				timeout = null
+				if !client.primary
+					logger.warn {timeout: @SECONDARY_TIMEOUT}, "starting timeout exec"
+					timeout = setTimeout () ->
+						cb(new Error("backend timed out"))
+					, @SECONDARY_TIMEOUT
+
+				client.rclient.exec (error, result) =>
 					timer.done()
 					if client.driver == "ioredis"
 						# ioredis returns an results like:
@@ -84,6 +95,8 @@ class MultiClient
 					if client.primary
 						primaryError = error
 						primaryResult = result
+					if timeout?
+						clearTimeout(timeout)
 					cb(error, result)
 		async.parallel jobs, (error, results) ->
 			if error?
@@ -112,18 +125,29 @@ for command, key_pos of COMMANDS
 		Client.prototype[command] = (args..., callback) ->
 			primaryError = null
 			primaryResult = null
-			jobs = @clients.map (client) ->
-				(cb) ->
+			jobs = @clients.map (client) =>
+				(cb) =>
+					cb = _.once(cb)
 					key_builder = args[key_pos]
 					key = key_builder(client.key_schema)
 					args_with_key = args.slice(0)
 					args_with_key[key_pos] = key
 					timer = new Metrics.Timer("redis.#{client.driver}.#{command}")
-					client.rclient[command] args_with_key..., (error, result...) ->
+					
+					timeout = null
+					if !client.primary
+						logger.warn {timeout: @SECONDARY_TIMEOUT}, "starting timeout #{command}"
+						timeout = setTimeout () ->
+							cb(new Error("backend timed out"))
+						, @SECONDARY_TIMEOUT
+					
+					client.rclient[command] args_with_key..., (error, result...) =>
 						timer.done()
 						if client.primary
 							primaryError = error
 							primaryResult = result
+						if timeout?
+							clearTimeout(timeout)
 						cb(error, result...)
 			async.parallel jobs, (error, results) ->
 				if error?

services/document-updater/test/unit/coffee/RedisBackend/RedisBackendTests.coffee

@@ -200,6 +200,44 @@ describe "RedisBackend", ->
 				@rclient_ioredis.eval
 					.calledWith(@script, @key_count, "Blocking:{#{@doc_id}}", @value)
 					.should.equal true
+		
+		describe "when the secondary takes longer than SECONDARY_TIMEOUT", ->
+			beforeEach (done) ->
+				@client.SECONDARY_TIMEOUT = 10
+				@content = "bar"
+				@rclient_redis.get = sinon.stub()
+				@rclient_redis.get.withArgs("doclines:#{@doc_id}").yields(null, @content)
+				@rclient_ioredis.get = (key, cb) =>
+					key.should.equal "doclines:{#{@doc_id}}"
+					setTimeout () =>
+						cb(null, @content)
+					, @client.SECONDARY_TIMEOUT * 2
+				@client.get RedisKeyBuilder.docLines({doc_id: @doc_id}), (error, @result) =>
+					done(error)
+		
+			it "should log out an error for the backend", ->
+				@logger.error
+					.calledWith({err: new Error("backend timed out")}, "error in redis backend")
+					.should.equal true
+
+		describe "when the primary takes longer than SECONDARY_TIMEOUT", ->
+			beforeEach (done) ->
+				@client.SECONDARY_TIMEOUT = 10
+				@content = "bar"
+				@rclient_ioredis.get = sinon.stub()
+				@rclient_ioredis.get.withArgs("doclines:{#{@doc_id}}").yields(null, @content)
+				@rclient_redis.get = (key, cb) =>
+					key.should.equal "doclines:#{@doc_id}"
+					setTimeout () =>
+						cb(null, @content)
+					, @client.SECONDARY_TIMEOUT * 2
+				@client.get RedisKeyBuilder.docLines({doc_id: @doc_id}), (error, @result) =>
+					done(error)
+		
+			it "should not consider this an error", ->
+				@logger.error
+					.called
+					.should.equal false
 
 	describe "multi commands", ->
 		beforeEach ->
@@ -333,6 +371,50 @@ describe "RedisBackend", ->
 						err: @error
 					}, "error in redis backend")
 					.should.equal true
+
+		describe "when the secondary takes longer than SECONDARY_TIMEOUT", ->
+			beforeEach (done) ->
+				@rclient_redis.get = sinon.stub()
+				@rclient_redis.exec = sinon.stub().yields(null, [@doclines, @version])
+				@rclient_ioredis.get = sinon.stub()
+				@rclient_ioredis.exec = (cb) =>
+					setTimeout () =>
+						cb(null, [ [null, @doclines], [null, @version] ])
+					, 20
+				
+				multi = @client.multi()
+				multi.SECONDARY_TIMEOUT = 10
+				multi.get RedisKeyBuilder.docLines({doc_id: @doc_id})
+				multi.get RedisKeyBuilder.docVersion({doc_id: @doc_id})
+				multi.exec (error, @result) =>
+					done(error)
+		
+			it "should log out an error for the backend", ->
+				@logger.error
+					.calledWith({err: new Error("backend timed out")}, "error in redis backend")
+					.should.equal true
+
+		describe "when the primary takes longer than SECONDARY_TIMEOUT", ->
+			beforeEach (done) ->
+				@rclient_redis.get = sinon.stub()
+				@rclient_redis.exec = (cb) =>
+					setTimeout () =>
+						cb(null, [@doclines, @version])
+					, 20
+				@rclient_ioredis.get = sinon.stub()
+				@rclient_ioredis.exec = sinon.stub().yields(null, [ [null, @doclines], [null, @version] ])
+			
+				multi = @client.multi()
+				multi.SECONDARY_TIMEOUT = 10
+				multi.get RedisKeyBuilder.docLines({doc_id: @doc_id})
+				multi.get RedisKeyBuilder.docVersion({doc_id: @doc_id})
+				multi.exec (error, @result) =>
+					done(error)
+		
+			it "should not consider this an error", ->
+				@logger.error
+					.called
+					.should.equal false
 	
 	describe "_healthCheckNodeRedisClient", ->
 		beforeEach ->