diff --git a/services/document-updater/app/coffee/RedisBackend.coffee b/services/document-updater/app/coffee/RedisBackend.coffee index b414b0c4cf..da51cbbacf 100644 --- a/services/document-updater/app/coffee/RedisBackend.coffee +++ b/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? diff --git a/services/document-updater/test/unit/coffee/RedisBackend/RedisBackendTests.coffee b/services/document-updater/test/unit/coffee/RedisBackend/RedisBackendTests.coffee index 5493f3ef6d..e5d2c1756b 100644 --- a/services/document-updater/test/unit/coffee/RedisBackend/RedisBackendTests.coffee +++ b/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 ->