From 8764c7378be929002689a3d70f334b1d8f067847 Mon Sep 17 00:00:00 2001 From: Ersun Warncke Date: Tue, 22 Jan 2019 13:31:05 +0000 Subject: [PATCH 1/2] check dynamic log level in gce metadata --- libraries/logger/logging-manager.coffee | 25 +- libraries/logger/package.json | 21 +- .../unit/coffee/loggingManagerTests.coffee | 294 +++++++++++++----- 3 files changed, 254 insertions(+), 86 deletions(-) diff --git a/libraries/logger/logging-manager.coffee b/libraries/logger/logging-manager.coffee index b0999ace08..509dbcc026 100644 --- a/libraries/logger/logging-manager.coffee +++ b/libraries/logger/logging-manager.coffee @@ -1,14 +1,33 @@ bunyan = require('bunyan') +request = require('request') module.exports = Logger = initialize: (name) -> - level = process.env['LOG_LEVEL'] or "debug" + @defaultLevel = process.env['LOG_LEVEL'] or if process.env["NODE_ENV"] == 'production' then "warn" else "debug" + @loggerName = name @logger = bunyan.createLogger name: name serializers: bunyan.stdSerializers - level: level + level: @defaultLevel + if process.env["NODE_ENV"] == 'production' + # check for log level override on startup + @.checkLogLevel() + # re-check log level every minute + checkLogLevel = () => @.checkLogLevel() + setInterval(checkLogLevel, 1000 * 60) return @ + checkLogLevel: () -> + options = + headers: + "Metadata-Flavor": "Google" + uri: "http://metadata.google.internal/computeMetadata/v1/project/attributes/#{@loggerName}-setLogLevelEndTime" + request options, (err, response, body) => + if parseInt(body) > Date.now() + @logger.level('trace') + else + @logger.level(@defaultLevel) + initializeErrorReporting: (sentry_dsn, options) -> raven = require "raven" @raven = new raven.Client(sentry_dsn, options) @@ -94,7 +113,7 @@ module.exports = Logger = @error.apply(this, arguments) warn: ()-> @logger.warn.apply(@logger, arguments) - fatal: (attributes, message, callback) -> + fatal: (attributes, message, callback = () ->) -> @logger.fatal(attributes, message) if @raven? cb = (e) -> # call the callback once after 'logged' or 'error' event diff --git a/libraries/logger/package.json b/libraries/logger/package.json index ddd8d8971f..69f5260d40 100644 --- a/libraries/logger/package.json +++ b/libraries/logger/package.json @@ -7,19 +7,20 @@ "url": "http://github.com/sharelatex/logger-sharelatex.git" }, "version": "1.5.9", + "scripts": { + "test": "mocha --require coffee-script/register test/**/*.coffee" + }, "dependencies": { "bunyan": "1.5.1", - "chai": "", "coffee-script": "1.12.4", - "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" + "request": "^2.88.0" + }, + "devDependencies": { + "chai": "^4.2.0", + "mocha": "^5.2.0", + "sandboxed-module": "0.2.0", + "sinon": "^7.2.3", + "sinon-chai": "^3.3.0" } } diff --git a/libraries/logger/test/unit/coffee/loggingManagerTests.coffee b/libraries/logger/test/unit/coffee/loggingManagerTests.coffee index ab2a1dba0c..04dd848c25 100644 --- a/libraries/logger/test/unit/coffee/loggingManagerTests.coffee +++ b/libraries/logger/test/unit/coffee/loggingManagerTests.coffee @@ -1,86 +1,234 @@ -# run this with -# ./node_modules/.bin/mocha --reporter tap --compilers coffee:coffee-script/register test/unit/coffee/loggingManagerTests.coffee - -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') +SandboxedModule = require("sandboxed-module") +chai = require("chai") +path = require("path") sinon = require("sinon") -tk = require("timekeeper") +sinonChai = require("sinon-chai") -describe 'logger.error', -> +chai.use(sinonChai) +chai.should() + +modulePath = path.join __dirname, '../../../logging-manager.coffee' + +describe 'LoggingManager', -> beforeEach -> - @captureException = sinon.stub() @start = Date.now() - tk.travel(new Date(@start)) + @clock = sinon.useFakeTimers(@start) + @captureException = sinon.stub() + @mockBunyanLogger = + debug: sinon.stub() + error: sinon.stub() + fatal: sinon.stub() + info: sinon.stub() + level: sinon.stub() + warn: sinon.stub() + @mockRavenClient = + captureException: @captureException + once: sinon.stub().yields() @LoggingManager = SandboxedModule.require modulePath, requires: - 'bunyan': {createLogger: sinon.stub().returns({error:sinon.stub()})} - 'raven': {Client: sinon.stub().returns({captureException:@captureException})} - @logger = @LoggingManager.initialize("test") + bunyan: @Bunyan = createLogger: sinon.stub().returns(@mockBunyanLogger) + raven: @Raven = Client: sinon.stub().returns(@mockRavenClient) + request: @Request = sinon.stub() + @loggerName = "test" + @logger = @LoggingManager.initialize(@loggerName) @logger.initializeErrorReporting("test_dsn") - it 'should report a single error to sentry', () -> - @logger.error {foo:'bar'}, "message" - @captureException.called.should.equal true + afterEach -> + @clock.restore() - it 'should report the same error to sentry only once', () -> - error1 = new Error('this is the error') - @logger.error {foo: error1}, "first message" - @logger.error {bar: error1}, "second message" - @captureException.callCount.should.equal 1 + describe 'initialize', -> + beforeEach -> + @LoggingManager.checkLogLevel = sinon.stub() + @Bunyan.createLogger.reset() - it 'should report two different errors to sentry individually', () -> - error1 = new Error('this is the error') - error2 = new Error('this is the error') - @logger.error {foo: error1}, "first message" - @logger.error {bar: error2}, "second message" - @captureException.callCount.should.equal 2 + describe "not in production", -> + beforeEach -> + @LoggingManager.initialize() - it 'should remove the path from fs errors', () -> - fsError = new Error("Error: ENOENT: no such file or directory, stat '/tmp/3279b8d0-da10-11e8-8255-efd98985942b'") - fsError.path = "/tmp/3279b8d0-da10-11e8-8255-efd98985942b" - @logger.error {err: fsError}, "message" - @captureException.calledWith(sinon.match.has('message', 'Error: ENOENT: no such file or directory, stat')).should.equal true + it 'should default to log level debug', -> + @Bunyan.createLogger.should.have.been.calledWithMatch level: "debug" - 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 'should not run checkLogLevel', -> + @LoggingManager.checkLogLevel.should.not.have.been.called - 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 + describe "in production", -> + beforeEach -> + process.env.NODE_ENV = 'production' + @LoggingManager.initialize() + + afterEach -> + delete process.env.NODE_ENV + + it 'should default to log level warn', -> + @Bunyan.createLogger.should.have.been.calledWithMatch level: "warn" + + it 'should run checkLogLevel', -> + @LoggingManager.checkLogLevel.should.have.been.calledOnce + + describe 'after 1 minute', -> + it 'should run checkLogLevel again', -> + @clock.tick(61*1000) + @LoggingManager.checkLogLevel.should.have.been.calledTwice + + describe 'after 2 minutes', -> + it 'should run checkLogLevel again', -> + @clock.tick(121*1000) + @LoggingManager.checkLogLevel.should.have.been.calledThrice + + describe "when LOG_LEVEL set in env", -> + beforeEach -> + process.env.LOG_LEVEL = "trace" + @LoggingManager.initialize() + + afterEach -> + delete process.env.LOG_LEVEL + + it "should use custom log level", -> + @Bunyan.createLogger.should.have.been.calledWithMatch level: "trace" + + describe 'bunyan logging', -> + beforeEach -> + @logArgs = [ foo: "bar", "foo", "bar" ] + + it 'should log debug', -> + @logger.debug @logArgs + @mockBunyanLogger.debug.should.have.been.calledWith @logArgs + + it 'should log error', -> + @logger.error @logArgs + @mockBunyanLogger.error.should.have.been.calledWith @logArgs + + it 'should log fatal', -> + @logger.fatal @logArgs + @mockBunyanLogger.fatal.should.have.been.calledWith @logArgs + + it 'should log info', -> + @logger.info @logArgs + @mockBunyanLogger.info.should.have.been.calledWith @logArgs + + it 'should log warn', -> + @logger.warn @logArgs + @mockBunyanLogger.warn.should.have.been.calledWith @logArgs + + it 'should log err', -> + @logger.err @logArgs + @mockBunyanLogger.error.should.have.been.calledWith @logArgs + + it 'should log log', -> + @logger.log @logArgs + @mockBunyanLogger.info.should.have.been.calledWith @logArgs + + describe 'logger.error', -> + it 'should report a single error to sentry', () -> + @logger.error {foo:'bar'}, "message" + @captureException.called.should.equal true + + it 'should report the same error to sentry only once', () -> + error1 = new Error('this is the error') + @logger.error {foo: error1}, "first message" + @logger.error {bar: error1}, "second message" + @captureException.callCount.should.equal 1 + + it 'should report two different errors to sentry individually', () -> + error1 = new Error('this is the error') + error2 = new Error('this is the error') + @logger.error {foo: error1}, "first message" + @logger.error {bar: error2}, "second message" + @captureException.callCount.should.equal 2 + + it 'should remove the path from fs errors', () -> + fsError = new Error("Error: ENOENT: no such file or directory, stat '/tmp/3279b8d0-da10-11e8-8255-efd98985942b'") + fsError.path = "/tmp/3279b8d0-da10-11e8-8255-efd98985942b" + @logger.error {err: fsError}, "message" + @captureException.calledWith(sinon.match.has('message', 'Error: ENOENT: no such file or directory, stat')).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 + @clock.tick(@start+ 61*1000) + # 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 + + describe 'checkLogLevel', -> + it 'should request log level override from google meta data service', -> + @LoggingManager.checkLogLevel() + options = + headers: + "Metadata-Flavor": "Google" + uri: "http://metadata.google.internal/computeMetadata/v1/project/attributes/#{@loggerName}-setLogLevelEndTime" + @Request.should.have.been.calledWithMatch options + + describe 'when request has error', -> + beforeEach -> + @Request.yields "error" + @LoggingManager.checkLogLevel() + + it "should only set default level", -> + @mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith('debug') + + describe 'when statusCode is not 200', -> + beforeEach -> + @Request.yields null, statusCode: 404 + @LoggingManager.checkLogLevel() + + it "should only set default level", -> + @mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith('debug') + + describe 'when time value returned that is less than current time', -> + beforeEach -> + @Request.yields null, statusCode: 200, '1' + @LoggingManager.checkLogLevel() + + it "should only set default level", -> + @mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith('debug') + + describe 'when time value returned that is less than current time', -> + describe 'when level is already set', -> + beforeEach -> + @mockBunyanLogger.level.returns(10) + @Request.yields null, statusCode: 200, @start + 1000 + @LoggingManager.checkLogLevel() + + it "should set trace level", -> + @mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith('trace') + + describe 'when level is not already set', -> + beforeEach -> + @mockBunyanLogger.level.returns(20) + @Request.yields null, statusCode: 200, @start + 1000 + @LoggingManager.checkLogLevel() + + it "should set trace level", -> + @mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith('trace') From 128c9f7c3911bf442b2bf7fc8fb7c3823342c6a0 Mon Sep 17 00:00:00 2001 From: Ersun Warncke Date: Tue, 29 Jan 2019 12:00:14 -0400 Subject: [PATCH 2/2] lower case prod check, bump version --- libraries/logger/logging-manager.coffee | 5 +++-- libraries/logger/package.json | 2 +- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/libraries/logger/logging-manager.coffee b/libraries/logger/logging-manager.coffee index 509dbcc026..a7d4e6d27b 100644 --- a/libraries/logger/logging-manager.coffee +++ b/libraries/logger/logging-manager.coffee @@ -3,13 +3,14 @@ request = require('request') module.exports = Logger = initialize: (name) -> - @defaultLevel = process.env['LOG_LEVEL'] or if process.env["NODE_ENV"] == 'production' then "warn" else "debug" + isProduction = process.env['NODE_ENV']?.toLowerCase() == 'production' + @defaultLevel = process.env['LOG_LEVEL'] or if isProduction then "warn" else "debug" @loggerName = name @logger = bunyan.createLogger name: name serializers: bunyan.stdSerializers level: @defaultLevel - if process.env["NODE_ENV"] == 'production' + if isProduction # check for log level override on startup @.checkLogLevel() # re-check log level every minute diff --git a/libraries/logger/package.json b/libraries/logger/package.json index 69f5260d40..96d8d7dd8a 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.9", + "version": "1.6.0", "scripts": { "test": "mocha --require coffee-script/register test/**/*.coffee" },