check dynamic log level in gce metadata

This commit is contained in:
Ersun Warncke 2019-01-22 13:31:05 +00:00
parent 6c3a28d963
commit 8764c7378b
3 changed files with 254 additions and 86 deletions

View file

@ -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

View file

@ -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"
}
}

View file

@ -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')