Merge pull request #64 from overleaf/bg-downgrade-delete-component-error

downgrade delete component error

services/document-updater/README.md

@@ -9,3 +9,4 @@ License
 The code in this repository is released under the GNU AFFERO GENERAL PUBLIC LICENSE, version 3. A copy can be found in the `LICENSE` file.
 
 Copyright (c) Overleaf, 2014-2019.
+

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

@@ -28,7 +28,7 @@ module.exports = DispatchManager =
 							# log everything except OpRangeNotAvailable errors, these are normal
 							if error? 
 								# downgrade OpRangeNotAvailable and "Delete component" errors so they are not sent to sentry
-								logAsWarning = (error instanceof Errors.OpRangeNotAvailableError) || ((typeof error is' string') && error.match(/^Delete component/))
+								logAsWarning = (error instanceof Errors.OpRangeNotAvailableError) || (error instanceof Errors.DeleteMismatchError)
 								if logAsWarning
 									logger.warn err: error, project_id: project_id, doc_id: doc_id, "error processing update"
 								else

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

@@ -19,7 +19,15 @@ ProjectStateChangedError = (message) ->
 	return error
 ProjectStateChangedError.prototype.__proto__ = Error.prototype
 
+DeleteMismatchError = (message) ->
+	error = new Error(message)
+	error.name = "DeleteMismatchError"
+	error.__proto__ = DeleteMismatchError.prototype
+	return error
+DeleteMismatchError.prototype.__proto__ = Error.prototype
+
 module.exports = Errors =
 	NotFoundError: NotFoundError
 	OpRangeNotAvailableError: OpRangeNotAvailableError
 	ProjectStateChangedError: ProjectStateChangedError
+	DeleteMismatchError: DeleteMismatchError

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

@@ -7,6 +7,8 @@ Keys = require "./UpdateKeys"
 util = require "util"
 RealTimeRedisManager = require "./RealTimeRedisManager"
 crypto = require "crypto"
+metrics = require('./Metrics')
+Errors = require("./Errors")
 
 ShareJsModel:: = {}
 util.inherits ShareJsModel, EventEmitter
@@ -36,9 +38,15 @@ module.exports = ShareJsUpdateManager =
 		model.applyOp doc_key, update, (error) ->
 			if error?
 				if error == "Op already submitted"
+					metrics.inc "sharejs.already-submitted"
 					logger.warn {project_id, doc_id, update}, "op has already been submitted"
 					update.dup = true
 					ShareJsUpdateManager._sendOp(project_id, doc_id, update)
+				else if /^Delete component/.test(error)
+					metrics.inc "sharejs.delete-mismatch"
+					logger.warn {project_id, doc_id, update, shareJsErr: error}, "sharejs delete does not match"
+					error = new Errors.DeleteMismatchError("Delete component does not match")
+					return callback(error)
 				else
 					return callback(error)
 			logger.log project_id: project_id, doc_id: doc_id, error: error, "applied update"

services/document-updater/test/acceptance/coffee/ApplyingUpdatesToADocTests.coffee

@@ -235,7 +235,7 @@ describe "Applying updates to a doc", ->
 			JSON.parse(message).should.deep.include {
 				project_id: @project_id,
 				doc_id: @doc_id,
-				error:'Delete component \'not the correct content\' does not match deleted text \'one\ntwo\nthree\''
+				error:'Delete component does not match'
 			}
 
 	describe "with enough updates to flush to the track changes api", ->

services/document-updater/test/unit/coffee/DispatchManager/DispatchManagerTests.coffee

@@ -3,19 +3,20 @@ chai = require('chai')
 should = chai.should()
 modulePath = "../../../../app/js/DispatchManager.js"
 SandboxedModule = require('sandboxed-module')
-
+Errors = require "../../../../app/js/Errors.js"
 
 describe "DispatchManager", ->
 	beforeEach ->
 		@timeout(3000)
 		@DispatchManager = SandboxedModule.require modulePath, requires:
 			"./UpdateManager" : @UpdateManager = {}
-			"logger-sharelatex": @logger = { log: sinon.stub() }
+			"logger-sharelatex": @logger = { log: sinon.stub(), error: sinon.stub(), warn: sinon.stub() }
 			"settings-sharelatex": @settings =
 				redis:
 					realtime: {}
 			"redis-sharelatex": @redis = {}
 			"./RateLimitManager": {}
+			"./Errors": Errors
 			"./Metrics":
 				Timer: ->
 					done: ->
@@ -38,23 +39,51 @@ describe "DispatchManager", ->
 				@doc_id = "doc-id-123"
 				@doc_key = "#{@project_id}:#{@doc_id}"
 				@client.blpop = sinon.stub().callsArgWith(2, null, ["pending-updates-list", @doc_key])
-				@UpdateManager.processOutstandingUpdatesWithLock = sinon.stub().callsArg(2)
-				
-				@worker._waitForUpdateThenDispatchWorker @callback
-				
-			it "should call redis with BLPOP", ->
-				@client.blpop
-					.calledWith("pending-updates-list", 0)
-					.should.equal true
-					
-			it "should call processOutstandingUpdatesWithLock", ->
-				@UpdateManager.processOutstandingUpdatesWithLock
-					.calledWith(@project_id, @doc_id)
-					.should.equal true
-					
-			it "should call the callback", ->
-				@callback.called.should.equal true
-				
+
+			describe "in the normal case", ->
+				beforeEach ->
+					@UpdateManager.processOutstandingUpdatesWithLock = sinon.stub().callsArg(2)
+					@worker._waitForUpdateThenDispatchWorker @callback
+
+				it "should call redis with BLPOP", ->
+					@client.blpop
+						.calledWith("pending-updates-list", 0)
+						.should.equal true
+						
+				it "should call processOutstandingUpdatesWithLock", ->
+					@UpdateManager.processOutstandingUpdatesWithLock
+						.calledWith(@project_id, @doc_id)
+						.should.equal true
+
+				it "should not log any errors", ->
+					@logger.error.called.should.equal false
+					@logger.warn.called.should.equal false
+
+				it "should call the callback", ->
+					@callback.called.should.equal true
+
+			describe "with an error", ->
+				beforeEach ->
+					@UpdateManager.processOutstandingUpdatesWithLock = sinon.stub().callsArgWith(2, new Error("a generic error"))
+					@worker._waitForUpdateThenDispatchWorker @callback
+
+				it "should log an error", ->
+					@logger.error.called.should.equal true
+
+				it "should call the callback", ->
+					@callback.called.should.equal true
+
+			describe "with a 'Delete component' error", ->
+				beforeEach ->
+					@UpdateManager.processOutstandingUpdatesWithLock = sinon.stub().callsArgWith(2, new Errors.DeleteMismatchError())
+					@worker._waitForUpdateThenDispatchWorker @callback
+
+				it "should log a warning", ->
+					@logger.warn.called.should.equal true
+
+				it "should call the callback", ->
+					@callback.called.should.equal true
+
 		describe "run", ->
 			it "should call _waitForUpdateThenDispatchWorker until shutting down", (done) ->
 				callCount = 0

services/document-updater/test/unit/coffee/ShareJsUpdateManager/ShareJsUpdateManagerTests.coffee

@@ -18,6 +18,7 @@ describe "ShareJsUpdateManager", ->
 				"redis-sharelatex" : createClient: () => @rclient = auth:->
 				"logger-sharelatex": @logger = { log: sinon.stub() }
 				"./RealTimeRedisManager": @RealTimeRedisManager = {}
+				"./Metrics": @metrics = { inc: sinon.stub() }
 			globals:
 				clearTimeout: @clearTimeout = sinon.stub()