From 013c2a693c6c6118a4ed8e038ae180edec4a745b Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Thu, 23 Mar 2017 13:49:01 +0000 Subject: [PATCH 1/3] rate limit on logging v1.5.6 --- libraries/logger/logging-manager.coffee | 19 +++++++++++++++---- libraries/logger/package.json | 2 +- 2 files changed, 16 insertions(+), 5 deletions(-) diff --git a/libraries/logger/logging-manager.coffee b/libraries/logger/logging-manager.coffee index 4643c41dd7..2dff9d6272 100644 --- a/libraries/logger/logging-manager.coffee +++ b/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 is MAX_ERRORS then "(rate limited)" else "" + # report the exception + @captureException(attributes, message, "error#{note}") err: () -> @error.apply(this, arguments) warn: ()-> diff --git a/libraries/logger/package.json b/libraries/logger/package.json index f4b9ff841f..d7dfcc80df 100644 --- a/libraries/logger/package.json +++ b/libraries/logger/package.json @@ -6,7 +6,7 @@ "type": "git", "url": "http://github.com/sharelatex/logger-sharelatex.git" }, - "version": "1.5.5", + "version": "1.5.6", "dependencies": { "bunyan": "1.5.1", "coffee-script": "1.12.4", From c7a6f44b11d3bab909aaa93bd054f8cd9ae7fd35 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Tue, 28 Mar 2017 15:54:12 +0100 Subject: [PATCH 2/3] add unit tests --- libraries/logger/package.json | 12 +++- .../unit/coffee/loggingManagerTests.coffee | 65 +++++++++++++++++++ 2 files changed, 76 insertions(+), 1 deletion(-) create mode 100644 libraries/logger/test/unit/coffee/loggingManagerTests.coffee diff --git a/libraries/logger/package.json b/libraries/logger/package.json index d7dfcc80df..5be4136be8 100644 --- a/libraries/logger/package.json +++ b/libraries/logger/package.json @@ -9,7 +9,17 @@ "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" } } diff --git a/libraries/logger/test/unit/coffee/loggingManagerTests.coffee b/libraries/logger/test/unit/coffee/loggingManagerTests.coffee new file mode 100644 index 0000000000..307bca4a1e --- /dev/null +++ b/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 From 9c7494eb671c8953e68817467a6df88ce1a4bbc5 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Wed, 29 Mar 2017 13:34:55 +0100 Subject: [PATCH 3/3] fix off-by-one error in error count --- libraries/logger/logging-manager.coffee | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/libraries/logger/logging-manager.coffee b/libraries/logger/logging-manager.coffee index 2dff9d6272..ad6c8c4787 100644 --- a/libraries/logger/logging-manager.coffee +++ b/libraries/logger/logging-manager.coffee @@ -71,9 +71,9 @@ module.exports = Logger = @lastErrorCount = 0 @lastErrorTimeStamp = now # only report 5 errors every minute to avoid overload - if @lastErrorCount <= MAX_ERRORS + if @lastErrorCount < MAX_ERRORS # add a note if the rate limit has been hit - note = if @lastErrorCount is MAX_ERRORS then "(rate limited)" else "" + note = if @lastErrorCount+1 is MAX_ERRORS then "(rate limited)" else "" # report the exception @captureException(attributes, message, "error#{note}") err: () ->