Merge pull request #3 from sharelatex/bg-rate-limit

rate limit on logging

libraries/logger/logging-manager.coffee

@@ -11,6 +11,7 @@ module.exports = Logger =
 		raven = require "raven"
 		@raven = new raven.Client(sentry_dsn, options)
 		@lastErrorTimeStamp = 0 # for rate limiting on sentry reporting
+		@lastErrorCount = 0
 
 	captureException: (attributes, message, level) ->
 		# handle case of logger.error "message"
@@ -59,12 +60,22 @@ module.exports = Logger =
 	error: (attributes, message, args...)->
 		@logger.error(attributes, message, args...)
 		if @raven?
+			MAX_ERRORS = 5 # maximum number of errors in 1 minute
 			now = new Date()
-			rateLimited = (now - @lastErrorTimeStamp) < 30 * 1000
-			# only report one error every thirty seconds to avoid overload
-			if not rateLimited
-				@captureException(attributes, message, "error")
+			# have we recently reported an error?
+			recentSentryReport = (now - @lastErrorTimeStamp) < 60 * 1000
+			# if so, increment the error count
+			if recentSentryReport
+				@lastErrorCount++
+			else
+				@lastErrorCount = 0
 				@lastErrorTimeStamp = now
+			# only report 5 errors every minute to avoid overload
+			if @lastErrorCount < MAX_ERRORS
+				# add a note if the rate limit has been hit
+				note = if @lastErrorCount+1 is MAX_ERRORS then "(rate limited)" else ""
+				# report the exception
+				@captureException(attributes, message, "error#{note}")
 	err: () ->
 		@error.apply(this, arguments)
 	warn: ()->

libraries/logger/package.json

@@ -6,10 +6,20 @@
     "type": "git",
     "url": "http://github.com/sharelatex/logger-sharelatex.git"
   },
-  "version": "1.5.5",
+  "version": "1.5.6",
   "dependencies": {
     "bunyan": "1.5.1",
+    "chai": "",
     "coffee-script": "1.12.4",
-    "raven": "^1.1.3"
+    "grunt": "^0.4.5",
+    "grunt-bunyan": "^0.5.0",
+    "grunt-contrib-clean": "^0.6.0",
+    "grunt-contrib-coffee": "^0.11.0",
+    "grunt-execute": "^0.2.2",
+    "grunt-mocha-test": "^0.11.0",
+    "raven": "^1.1.3",
+    "sandboxed-module": "",
+    "sinon": "",
+    "timekeeper": "^1.0.0"
   }
 }

libraries/logger/test/unit/coffee/loggingManagerTests.coffee

@@ -0,0 +1,65 @@
+require('coffee-script')
+chai = require('chai')
+should = chai.should()
+expect = chai.expect
+path = require('path')
+modulePath = path.join __dirname, '../../../logging-manager.coffee'
+SandboxedModule = require('sandboxed-module')
+sinon = require("sinon")
+tk = require("timekeeper")
+
+describe 'logger.error', ->
+
+	beforeEach ->
+		@captureException = sinon.stub()
+		@start = Date.now()
+		tk.travel(new Date(@start))
+		@LoggingManager = SandboxedModule.require modulePath, requires:
+			'bunyan': {createLogger: sinon.stub().returns({error:sinon.stub()})}
+			'raven': {Client: sinon.stub().returns({captureException:@captureException})}
+		@logger = @LoggingManager.initialize("test")
+		@logger.initializeErrorReporting("test_dsn")
+
+	it 'should report a single error to sentry', () ->
+		@logger.error {foo:'bar'}, "message"
+		@captureException.called.should.equal true
+
+
+	it 'for multiple errors should only report a maximum of 5 errors to sentry', () ->
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@captureException.callCount.should.equal 5
+
+	it 'for multiple errors with a minute delay should report 10 errors to sentry', () ->
+		# the first five errors should be reported to sentry
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		# the following errors should not be reported
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		# allow a minute to pass
+		tk.travel(new Date(@start + 61*10000));
+		# after a minute the next five errors should be reported to sentry
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		# the following errors should not be reported to sentry
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@logger.error {foo:'bar'}, "message"
+		@captureException.callCount.should.equal 10