Merge pull request #49 from sharelatex/bg-add-redis-timeout

add redis timeout

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

@@ -34,5 +34,6 @@ module.exports = class RateLimiter
 				@_adjustLimitDown()
 		else
 			logger.log {active: @ActiveWorkerCount, currentLimit: Math.ceil(@CurrentWorkerLimit)}, "hit rate limit"
-			@_trackAndRun task, callback # only return after task completes
-			@_adjustLimitUp()
+			@_trackAndRun task, (err) =>
+				@_adjustLimitUp() if !err? # don't increment rate limit if there was an error
+				callback(err) # only return after task completes

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

@@ -7,6 +7,12 @@ metrics = require('./Metrics')
 Errors = require "./Errors"
 crypto = require "crypto"
 
+# Sometimes Redis calls take an unexpectedly long time.  We have to be
+# quick with Redis calls because we're holding a lock that expires
+# after 30 seconds. We can't let any errors in the rest of the stack
+# hold us up, and need to bail out quickly if there is a problem.
+MAX_REDIS_REQUEST_LENGTH = 5000 # 5 seconds
+
 # Make times easy to read
 minutes = 60 # seconds for Redis expire
 
@@ -93,9 +99,12 @@ module.exports = RedisManager =
 		multi.get keys.projectKey(doc_id:doc_id)
 		multi.get keys.ranges(doc_id:doc_id)
 		multi.exec (error, [docLines, version, storedHash, doc_project_id, ranges])->
-			timer.done()
+			timeSpan = timer.done()
 			return callback(error) if error?
-
+			# check if request took too long and bail out.  only do this for
+			# get, because it is the first call in each update, so if this
+			# passes we'll assume others have a reasonable chance to succeed.
+			return callback(new Error("redis getDoc exceeded timeout")) if timeSpan > MAX_REDIS_REQUEST_LENGTH
 			# check sha1 hash value if present
 			if docLines? and storedHash?
 				computedHash = RedisManager._computeHash(docLines)

services/document-updater/test/unit/coffee/RedisManager/RedisManagerTests.coffee

@@ -39,7 +39,11 @@ describe "RedisManager", ->
 				"./Metrics": @metrics =
 					inc: sinon.stub()
 					Timer: class Timer
+						constructor: () ->
+							this.start = new Date()
 						done: () ->
+							timeSpan = new Date - this.start
+							return timeSpan
 				"./Errors": Errors
 			globals:
 				JSON: @JSON = JSON
@@ -148,6 +152,24 @@ describe "RedisManager", ->
 					.should.equal true
 
 
+		describe "with a slow request to redis", ->
+			beforeEach ->
+				@rclient.exec = sinon.stub().callsArgWith(0, null, [@jsonlines, @version, @badHash, @project_id, @json_ranges])
+				@clock = sinon.useFakeTimers();
+				@rclient.exec = (cb) =>
+					@clock.tick(6000);
+					cb(null, [@jsonlines, @version, @another_project_id, @json_ranges])
+
+				@RedisManager.getDoc @project_id, @doc_id, @callback
+
+			afterEach ->
+				@clock.restore()
+
+			it 'should return an error', ->
+				@callback
+					.calledWith(new Error("redis getDoc exceeded timeout"))
+					.should.equal true
+
 		describe "getDoc with an invalid project id", ->
 			beforeEach ->
 				@another_project_id = "project-id-456"