Merge pull request #12 from sharelatex/ew-use-ring-buffer
Use Ring Buffer, Decaffeinate, Update Bunyan
This commit is contained in:
Ersun Warncke
@@ -0,0 +1,44 @@
|
||||
{
|
||||
"extends": [
|
||||
"standard",
|
||||
"prettier",
|
||||
"prettier/standard"
|
||||
],
|
||||
"plugins": [
|
||||
"mocha",
|
||||
"chai-expect",
|
||||
"chai-friendly"
|
||||
],
|
||||
"env": {
|
||||
"mocha": true
|
||||
},
|
||||
"globals": {
|
||||
"expect": true,
|
||||
"define": true,
|
||||
},
|
||||
"settings": {
|
||||
},
|
||||
"rules": {
|
||||
"max-len": ["error", {
|
||||
"ignoreUrls": true,
|
||||
// Ignore long describe/it test blocks, long import/require statements
|
||||
"ignorePattern": "(^\\s*(it|describe)\\s*\\(['\"]|^import\\s*.*\\s*from\\s*['\"]|^.*\\s*=\\s*require\\(['\"])"
|
||||
}],
|
||||
|
||||
// Add some mocha specific rules
|
||||
"mocha/handle-done-callback": "error",
|
||||
"mocha/no-exclusive-tests": "error",
|
||||
"mocha/no-global-tests": "error",
|
||||
"mocha/no-identical-title": "error",
|
||||
"mocha/no-nested-tests": "error",
|
||||
"mocha/no-pending-tests": "error",
|
||||
"mocha/no-skipped-tests": "error",
|
||||
|
||||
// Add some chai specific rules
|
||||
"chai-expect/missing-assertion": "error",
|
||||
"chai-expect/terminating-properties": "error",
|
||||
// Swap the no-unused-expressions rule with a more chai-friendly one
|
||||
"no-unused-expressions": 0,
|
||||
"chai-friendly/no-unused-expressions": "error"
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,4 @@
|
||||
{
|
||||
"semi": false,
|
||||
"singleQuote": true
|
||||
}
|
||||
@@ -1,2 +1 @@
|
||||
require("coffee-script/register")
|
||||
module.exports = require('./logging-manager');
|
||||
module.exports = require('./logging-manager.js')
|
||||
|
||||
@@ -1,129 +0,0 @@
|
||||
bunyan = require('bunyan')
|
||||
request = require('request')
|
||||
|
||||
module.exports = Logger =
|
||||
initialize: (name) ->
|
||||
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 isProduction
|
||||
# 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)
|
||||
@lastErrorTimeStamp = 0 # for rate limiting on sentry reporting
|
||||
@lastErrorCount = 0
|
||||
|
||||
captureException: (attributes, message, level) ->
|
||||
# handle case of logger.error "message"
|
||||
if typeof attributes is 'string'
|
||||
attributes = {err: new Error(attributes)}
|
||||
# extract any error object
|
||||
error = attributes.err or attributes.error
|
||||
# avoid reporting errors twice
|
||||
for key, value of attributes
|
||||
return if value instanceof Error && value.reportedToSentry
|
||||
# include our log message in the error report
|
||||
if not error?
|
||||
error = {message: message} if typeof message is 'string'
|
||||
else if message?
|
||||
attributes.description = message
|
||||
# report the error
|
||||
if error?
|
||||
# capture attributes and use *_id objects as tags
|
||||
tags = {}
|
||||
extra = {}
|
||||
for key, value of attributes
|
||||
tags[key] = value if key.match(/_id/) and typeof value == 'string'
|
||||
extra[key] = value
|
||||
# capture req object if available
|
||||
req = attributes.req
|
||||
if req?
|
||||
extra.req =
|
||||
method: req.method
|
||||
url: req.originalUrl
|
||||
query: req.query
|
||||
headers: req.headers
|
||||
ip: req.ip
|
||||
# recreate error objects that have been converted to a normal object
|
||||
if !(error instanceof Error) and typeof error is "object"
|
||||
newError = new Error(error.message)
|
||||
for own key, value of error
|
||||
newError[key] = value
|
||||
error = newError
|
||||
# filter paths from the message to avoid duplicate errors in sentry
|
||||
# (e.g. errors from `fs` methods which have a path attribute)
|
||||
try
|
||||
error.message = error.message.replace(" '#{error.path}'", '') if error.path
|
||||
# send the error to sentry
|
||||
try
|
||||
@raven.captureException(error, {tags: tags, extra: extra, level: level})
|
||||
# put a flag on the errors to avoid reporting them multiple times
|
||||
for key, value of attributes
|
||||
value.reportedToSentry = true if value instanceof Error
|
||||
catch
|
||||
return # ignore any errors
|
||||
|
||||
debug : () ->
|
||||
@logger.debug.apply(@logger, arguments)
|
||||
info : ()->
|
||||
@logger.info.apply(@logger, arguments)
|
||||
log : ()->
|
||||
@logger.info.apply(@logger, arguments)
|
||||
error: (attributes, message, args...)->
|
||||
@logger.error(attributes, message, args...)
|
||||
if @raven?
|
||||
MAX_ERRORS = 5 # maximum number of errors in 1 minute
|
||||
now = new Date()
|
||||
# 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: ()->
|
||||
@logger.warn.apply(@logger, arguments)
|
||||
fatal: (attributes, message, callback = () ->) ->
|
||||
@logger.fatal(attributes, message)
|
||||
if @raven?
|
||||
cb = (e) -> # call the callback once after 'logged' or 'error' event
|
||||
callback()
|
||||
cb = () ->
|
||||
@captureException(attributes, message, "fatal")
|
||||
@raven.once 'logged', cb
|
||||
@raven.once 'error', cb
|
||||
else
|
||||
callback()
|
||||
|
||||
Logger.initialize("default-sharelatex")
|
||||
@@ -0,0 +1,231 @@
|
||||
const bunyan = require('bunyan')
|
||||
const request = require('request')
|
||||
|
||||
const Logger = module.exports = {
|
||||
initialize(name) {
|
||||
this.isProduction =
|
||||
(process.env['NODE_ENV'] || '').toLowerCase() === 'production'
|
||||
this.defaultLevel =
|
||||
process.env['LOG_LEVEL'] || (this.isProduction ? 'warn' : 'debug')
|
||||
this.loggerName = name
|
||||
this.ringBufferSize = parseInt(process.env['LOG_RING_BUFFER_SIZE']) || 0
|
||||
const loggerStreams = [
|
||||
{
|
||||
level: this.defaultLevel,
|
||||
stream: process.stdout
|
||||
}
|
||||
]
|
||||
if (this.ringBufferSize > 0) {
|
||||
this.ringBuffer = new bunyan.RingBuffer({limit: this.ringBufferSize})
|
||||
loggerStreams.push({
|
||||
level: 'trace',
|
||||
type: 'raw',
|
||||
stream: this.ringBuffer
|
||||
})
|
||||
}
|
||||
else {
|
||||
this.ringBuffer = null
|
||||
}
|
||||
this.logger = bunyan.createLogger({
|
||||
name,
|
||||
serializers: bunyan.stdSerializers,
|
||||
streams: loggerStreams
|
||||
})
|
||||
if (this.isProduction) {
|
||||
// clear interval if already set
|
||||
if (this.checkInterval) {
|
||||
clearInterval(this.checkInterval)
|
||||
}
|
||||
// check for log level override on startup
|
||||
this.checkLogLevel()
|
||||
// re-check log level every minute
|
||||
const checkLogLevel = () => this.checkLogLevel()
|
||||
this.checkInterval = setInterval(checkLogLevel, 1000 * 60)
|
||||
}
|
||||
return this
|
||||
},
|
||||
|
||||
checkLogLevel() {
|
||||
const options = {
|
||||
headers: {
|
||||
'Metadata-Flavor': 'Google'
|
||||
},
|
||||
uri: `http://metadata.google.internal/computeMetadata/v1/project/attributes/${
|
||||
this.loggerName
|
||||
}-setLogLevelEndTime`
|
||||
}
|
||||
request(options, (err, response, body) => {
|
||||
if (err) {
|
||||
this.logger.level(this.defaultLevel)
|
||||
return
|
||||
}
|
||||
if (parseInt(body) > Date.now()) {
|
||||
this.logger.level('trace')
|
||||
} else {
|
||||
this.logger.level(this.defaultLevel)
|
||||
}
|
||||
})
|
||||
},
|
||||
|
||||
initializeErrorReporting(sentry_dsn, options) {
|
||||
const raven = require('raven')
|
||||
this.raven = new raven.Client(sentry_dsn, options)
|
||||
this.lastErrorTimeStamp = 0 // for rate limiting on sentry reporting
|
||||
this.lastErrorCount = 0
|
||||
},
|
||||
|
||||
captureException(attributes, message, level) {
|
||||
// handle case of logger.error "message"
|
||||
let key, value
|
||||
if (typeof attributes === 'string') {
|
||||
attributes = { err: new Error(attributes) }
|
||||
}
|
||||
// extract any error object
|
||||
let error = attributes.err || attributes.error
|
||||
// avoid reporting errors twice
|
||||
for (key in attributes) {
|
||||
value = attributes[key]
|
||||
if (value instanceof Error && value.reportedToSentry) {
|
||||
return
|
||||
}
|
||||
}
|
||||
// include our log message in the error report
|
||||
if (error == null) {
|
||||
if (typeof message === 'string') {
|
||||
error = { message }
|
||||
}
|
||||
} else if (message != null) {
|
||||
attributes.description = message
|
||||
}
|
||||
// report the error
|
||||
if (error != null) {
|
||||
// capture attributes and use *_id objects as tags
|
||||
const tags = {}
|
||||
const extra = {}
|
||||
for (key in attributes) {
|
||||
value = attributes[key]
|
||||
if (key.match(/_id/) && typeof value === 'string') {
|
||||
tags[key] = value
|
||||
}
|
||||
extra[key] = value
|
||||
}
|
||||
// capture req object if available
|
||||
const { req } = attributes
|
||||
if (req != null) {
|
||||
extra.req = {
|
||||
method: req.method,
|
||||
url: req.originalUrl,
|
||||
query: req.query,
|
||||
headers: req.headers,
|
||||
ip: req.ip
|
||||
}
|
||||
}
|
||||
// recreate error objects that have been converted to a normal object
|
||||
if (!(error instanceof Error) && typeof error === 'object') {
|
||||
const newError = new Error(error.message)
|
||||
for (key of Object.keys(error || {})) {
|
||||
value = error[key]
|
||||
newError[key] = value
|
||||
}
|
||||
error = newError
|
||||
}
|
||||
// filter paths from the message to avoid duplicate errors in sentry
|
||||
// (e.g. errors from `fs` methods which have a path attribute)
|
||||
try {
|
||||
if (error.path) {
|
||||
error.message = error.message.replace(` '${error.path}'`, '')
|
||||
}
|
||||
} catch (error1) {}
|
||||
// send the error to sentry
|
||||
try {
|
||||
this.raven.captureException(error, { tags, extra, level })
|
||||
// put a flag on the errors to avoid reporting them multiple times
|
||||
return (() => {
|
||||
const result = []
|
||||
for (key in attributes) {
|
||||
value = attributes[key]
|
||||
if (value instanceof Error) {
|
||||
result.push((value.reportedToSentry = true))
|
||||
} else {
|
||||
result.push(undefined)
|
||||
}
|
||||
}
|
||||
return result
|
||||
})()
|
||||
} catch (error2) {
|
||||
return
|
||||
}
|
||||
}
|
||||
},
|
||||
|
||||
debug() {
|
||||
return this.logger.debug.apply(this.logger, arguments)
|
||||
},
|
||||
|
||||
info() {
|
||||
return this.logger.info.apply(this.logger, arguments)
|
||||
},
|
||||
|
||||
log() {
|
||||
return this.logger.info.apply(this.logger, arguments)
|
||||
},
|
||||
|
||||
error(attributes, message, ...args) {
|
||||
if (this.ringBuffer !== null && Array.isArray(this.ringBuffer.records)) {
|
||||
attributes.logBuffer = this.ringBuffer.records.filter(function (record) {
|
||||
return record.level !== 50
|
||||
})
|
||||
}
|
||||
this.logger.error(attributes, message, ...Array.from(args))
|
||||
if (this.raven != null) {
|
||||
const MAX_ERRORS = 5 // maximum number of errors in 1 minute
|
||||
const now = new Date()
|
||||
// have we recently reported an error?
|
||||
const recentSentryReport = now - this.lastErrorTimeStamp < 60 * 1000
|
||||
// if so, increment the error count
|
||||
if (recentSentryReport) {
|
||||
this.lastErrorCount++
|
||||
} else {
|
||||
this.lastErrorCount = 0
|
||||
this.lastErrorTimeStamp = now
|
||||
}
|
||||
// only report 5 errors every minute to avoid overload
|
||||
if (this.lastErrorCount < MAX_ERRORS) {
|
||||
// add a note if the rate limit has been hit
|
||||
const note =
|
||||
this.lastErrorCount + 1 === MAX_ERRORS ? '(rate limited)' : ''
|
||||
// report the exception
|
||||
return this.captureException(attributes, message, `error${note}`)
|
||||
}
|
||||
}
|
||||
},
|
||||
|
||||
err() {
|
||||
return this.error.apply(this, arguments)
|
||||
},
|
||||
|
||||
warn() {
|
||||
return this.logger.warn.apply(this.logger, arguments)
|
||||
},
|
||||
|
||||
fatal(attributes, message, callback) {
|
||||
if (callback == null) {
|
||||
callback = function() {}
|
||||
}
|
||||
this.logger.fatal(attributes, message)
|
||||
if (this.raven != null) {
|
||||
var cb = function(e) {
|
||||
// call the callback once after 'logged' or 'error' event
|
||||
callback()
|
||||
return (cb = function() {})
|
||||
}
|
||||
this.captureException(attributes, message, 'fatal')
|
||||
this.raven.once('logged', cb)
|
||||
return this.raven.once('error', cb)
|
||||
} else {
|
||||
return callback()
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
Logger.initialize('default-sharelatex')
|
||||
@@ -6,21 +6,33 @@
|
||||
"type": "git",
|
||||
"url": "http://github.com/sharelatex/logger-sharelatex.git"
|
||||
},
|
||||
"version": "1.6.0",
|
||||
"version": "1.7.0",
|
||||
"scripts": {
|
||||
"test": "mocha --require coffee-script/register test/**/*.coffee"
|
||||
"test": "mocha test/**/*.js",
|
||||
"format": "prettier-eslint '**/*.js' --list-different",
|
||||
"format:fix": "prettier-eslint '**/*.js' --write",
|
||||
"lint": "eslint -f unix ."
|
||||
},
|
||||
"dependencies": {
|
||||
"bunyan": "1.5.1",
|
||||
"coffee-script": "1.12.4",
|
||||
"raven": "^1.1.3",
|
||||
"request": "^2.88.0"
|
||||
"bunyan": "1.8.12",
|
||||
"raven": "1.1.3",
|
||||
"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"
|
||||
"chai": "4.2.0",
|
||||
"eslint": "^4.18.1",
|
||||
"eslint-config-prettier": "^3.1.0",
|
||||
"eslint-config-standard": "^11.0.0",
|
||||
"eslint-plugin-chai-expect": "^1.1.1",
|
||||
"eslint-plugin-chai-friendly": "^0.4.1",
|
||||
"eslint-plugin-import": "^2.9.0",
|
||||
"eslint-plugin-mocha": "^5.2.0",
|
||||
"eslint-plugin-node": "^6.0.0",
|
||||
"eslint-plugin-promise": "^3.6.0",
|
||||
"eslint-plugin-standard": "^3.0.1",
|
||||
"mocha": "5.2.0",
|
||||
"sandboxed-module": "2.0.3",
|
||||
"sinon": "7.2.3",
|
||||
"sinon-chai": "3.3.0"
|
||||
}
|
||||
}
|
||||
|
||||
@@ -1,234 +0,0 @@
|
||||
SandboxedModule = require("sandboxed-module")
|
||||
chai = require("chai")
|
||||
path = require("path")
|
||||
sinon = require("sinon")
|
||||
sinonChai = require("sinon-chai")
|
||||
|
||||
chai.use(sinonChai)
|
||||
chai.should()
|
||||
|
||||
modulePath = path.join __dirname, '../../../logging-manager.coffee'
|
||||
|
||||
describe 'LoggingManager', ->
|
||||
|
||||
beforeEach ->
|
||||
@start = Date.now()
|
||||
@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: @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")
|
||||
|
||||
afterEach ->
|
||||
@clock.restore()
|
||||
|
||||
describe 'initialize', ->
|
||||
beforeEach ->
|
||||
@LoggingManager.checkLogLevel = sinon.stub()
|
||||
@Bunyan.createLogger.reset()
|
||||
|
||||
describe "not in production", ->
|
||||
beforeEach ->
|
||||
@LoggingManager.initialize()
|
||||
|
||||
it 'should default to log level debug', ->
|
||||
@Bunyan.createLogger.should.have.been.calledWithMatch level: "debug"
|
||||
|
||||
it 'should not run checkLogLevel', ->
|
||||
@LoggingManager.checkLogLevel.should.not.have.been.called
|
||||
|
||||
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')
|
||||
@@ -0,0 +1,386 @@
|
||||
const SandboxedModule = require('sandboxed-module')
|
||||
const bunyan = require('bunyan')
|
||||
const chai = require('chai')
|
||||
const path = require('path')
|
||||
const sinon = require('sinon')
|
||||
const sinonChai = require('sinon-chai')
|
||||
|
||||
chai.use(sinonChai)
|
||||
chai.should()
|
||||
|
||||
const modulePath = path.join(__dirname, '../../logging-manager.js')
|
||||
|
||||
describe('LoggingManager', function() {
|
||||
beforeEach(function() {
|
||||
this.start = Date.now()
|
||||
this.clock = sinon.useFakeTimers(this.start)
|
||||
this.captureException = sinon.stub()
|
||||
this.mockBunyanLogger = {
|
||||
debug: sinon.stub(),
|
||||
error: sinon.stub(),
|
||||
fatal: sinon.stub(),
|
||||
info: sinon.stub(),
|
||||
level: sinon.stub(),
|
||||
warn: sinon.stub()
|
||||
}
|
||||
this.mockRavenClient = {
|
||||
captureException: this.captureException,
|
||||
once: sinon.stub().yields()
|
||||
}
|
||||
this.LoggingManager = SandboxedModule.require(modulePath, {
|
||||
globals: { console },
|
||||
requires: {
|
||||
bunyan: (this.Bunyan = {
|
||||
createLogger: sinon.stub().returns(this.mockBunyanLogger),
|
||||
RingBuffer: bunyan.RingBuffer
|
||||
}),
|
||||
raven: (this.Raven = {
|
||||
Client: sinon.stub().returns(this.mockRavenClient)
|
||||
}),
|
||||
request: (this.Request = sinon.stub())
|
||||
}
|
||||
})
|
||||
this.loggerName = 'test'
|
||||
this.logger = this.LoggingManager.initialize(this.loggerName)
|
||||
this.logger.initializeErrorReporting('test_dsn')
|
||||
})
|
||||
|
||||
afterEach(function() {
|
||||
this.clock.restore()
|
||||
})
|
||||
|
||||
describe('initialize', function() {
|
||||
beforeEach(function() {
|
||||
this.checkLogLevelStub = sinon.stub(this.LoggingManager, 'checkLogLevel')
|
||||
this.Bunyan.createLogger.reset()
|
||||
})
|
||||
|
||||
afterEach(function() {
|
||||
this.checkLogLevelStub.restore()
|
||||
})
|
||||
|
||||
describe('not in production', function() {
|
||||
beforeEach(function() {
|
||||
this.logger = this.LoggingManager.initialize(this.loggerName)
|
||||
})
|
||||
|
||||
it('should default to log level debug', function() {
|
||||
this.Bunyan.createLogger.firstCall.args[0].streams[0].level.should.equal(
|
||||
'debug'
|
||||
)
|
||||
})
|
||||
|
||||
it('should not run checkLogLevel', function() {
|
||||
this.checkLogLevelStub.should.not.have.been.called
|
||||
})
|
||||
})
|
||||
|
||||
describe('in production', function() {
|
||||
beforeEach(function() {
|
||||
process.env.NODE_ENV = 'production'
|
||||
this.logger = this.LoggingManager.initialize(this.loggerName)
|
||||
})
|
||||
|
||||
afterEach(() => delete process.env.NODE_ENV)
|
||||
|
||||
it('should default to log level warn', function() {
|
||||
this.Bunyan.createLogger.firstCall.args[0].streams[0].level.should.equal(
|
||||
'warn'
|
||||
)
|
||||
})
|
||||
|
||||
it('should run checkLogLevel', function() {
|
||||
this.checkLogLevelStub.should.have.been.calledOnce
|
||||
})
|
||||
|
||||
describe('after 1 minute', () =>
|
||||
it('should run checkLogLevel again', function() {
|
||||
this.clock.tick(61 * 1000)
|
||||
this.checkLogLevelStub.should.have.been.calledTwice
|
||||
}))
|
||||
|
||||
describe('after 2 minutes', () =>
|
||||
it('should run checkLogLevel again', function() {
|
||||
this.clock.tick(121 * 1000)
|
||||
this.checkLogLevelStub.should.have.been.calledThrice
|
||||
}))
|
||||
})
|
||||
|
||||
describe('when LOG_LEVEL set in env', function() {
|
||||
beforeEach(function() {
|
||||
process.env.LOG_LEVEL = 'trace'
|
||||
this.LoggingManager.initialize()
|
||||
})
|
||||
|
||||
afterEach(() => delete process.env.LOG_LEVEL)
|
||||
|
||||
it('should use custom log level', function() {
|
||||
this.Bunyan.createLogger.firstCall.args[0].streams[0].level.should.equal(
|
||||
'trace'
|
||||
)
|
||||
})
|
||||
})
|
||||
})
|
||||
|
||||
describe('bunyan logging', function() {
|
||||
beforeEach(function() {
|
||||
this.logArgs = [{ foo: 'bar' }, 'foo', 'bar']
|
||||
})
|
||||
|
||||
it('should log debug', function() {
|
||||
this.logger.debug(this.logArgs)
|
||||
this.mockBunyanLogger.debug.should.have.been.calledWith(this.logArgs)
|
||||
})
|
||||
|
||||
it('should log error', function() {
|
||||
this.logger.error(this.logArgs)
|
||||
this.mockBunyanLogger.error.should.have.been.calledWith(this.logArgs)
|
||||
})
|
||||
|
||||
it('should log fatal', function() {
|
||||
this.logger.fatal(this.logArgs)
|
||||
this.mockBunyanLogger.fatal.should.have.been.calledWith(this.logArgs)
|
||||
})
|
||||
|
||||
it('should log info', function() {
|
||||
this.logger.info(this.logArgs)
|
||||
this.mockBunyanLogger.info.should.have.been.calledWith(this.logArgs)
|
||||
})
|
||||
|
||||
it('should log warn', function() {
|
||||
this.logger.warn(this.logArgs)
|
||||
this.mockBunyanLogger.warn.should.have.been.calledWith(this.logArgs)
|
||||
})
|
||||
|
||||
it('should log err', function() {
|
||||
this.logger.err(this.logArgs)
|
||||
this.mockBunyanLogger.error.should.have.been.calledWith(this.logArgs)
|
||||
})
|
||||
|
||||
it('should log log', function() {
|
||||
this.logger.log(this.logArgs)
|
||||
this.mockBunyanLogger.info.should.have.been.calledWith(this.logArgs)
|
||||
})
|
||||
})
|
||||
|
||||
describe('logger.error', function() {
|
||||
it('should report a single error to sentry', function() {
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.captureException.called.should.equal(true)
|
||||
})
|
||||
|
||||
it('should report the same error to sentry only once', function() {
|
||||
const error1 = new Error('this is the error')
|
||||
this.logger.error({ foo: error1 }, 'first message')
|
||||
this.logger.error({ bar: error1 }, 'second message')
|
||||
this.captureException.callCount.should.equal(1)
|
||||
})
|
||||
|
||||
it('should report two different errors to sentry individually', function() {
|
||||
const error1 = new Error('this is the error')
|
||||
const error2 = new Error('this is the error')
|
||||
this.logger.error({ foo: error1 }, 'first message')
|
||||
this.logger.error({ bar: error2 }, 'second message')
|
||||
this.captureException.callCount.should.equal(2)
|
||||
})
|
||||
|
||||
it('should remove the path from fs errors', function() {
|
||||
const 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'
|
||||
this.logger.error({ err: fsError }, 'message')
|
||||
this.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', function() {
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.captureException.callCount.should.equal(5)
|
||||
})
|
||||
|
||||
it('for multiple errors with a minute delay should report 10 errors to sentry', function() {
|
||||
// the first five errors should be reported to sentry
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
// the following errors should not be reported
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
// allow a minute to pass
|
||||
this.clock.tick(this.start + 61 * 1000)
|
||||
// after a minute the next five errors should be reported to sentry
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
// the following errors should not be reported to sentry
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.logger.error({ foo: 'bar' }, 'message')
|
||||
this.captureException.callCount.should.equal(10)
|
||||
})
|
||||
})
|
||||
|
||||
describe('checkLogLevel', function() {
|
||||
it('should request log level override from google meta data service', function() {
|
||||
this.logger.checkLogLevel()
|
||||
const options = {
|
||||
headers: {
|
||||
'Metadata-Flavor': 'Google'
|
||||
},
|
||||
uri: `http://metadata.google.internal/computeMetadata/v1/project/attributes/${
|
||||
this.loggerName
|
||||
}-setLogLevelEndTime`
|
||||
}
|
||||
this.Request.should.have.been.calledWithMatch(options)
|
||||
})
|
||||
|
||||
describe('when request has error', function() {
|
||||
beforeEach(function() {
|
||||
this.Request.yields('error')
|
||||
this.logger.checkLogLevel()
|
||||
})
|
||||
|
||||
it('should only set default level', function() {
|
||||
this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith(
|
||||
'debug'
|
||||
)
|
||||
})
|
||||
})
|
||||
|
||||
describe('when statusCode is not 200', function() {
|
||||
beforeEach(function() {
|
||||
this.Request.yields(null, { statusCode: 404 })
|
||||
this.logger.checkLogLevel()
|
||||
})
|
||||
|
||||
it('should only set default level', function() {
|
||||
this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith(
|
||||
'debug'
|
||||
)
|
||||
})
|
||||
})
|
||||
|
||||
describe('when time value returned that is less than current time', function() {
|
||||
beforeEach(function() {
|
||||
this.Request.yields(null, { statusCode: 200 }, '1')
|
||||
this.logger.checkLogLevel()
|
||||
})
|
||||
|
||||
it('should only set default level', function() {
|
||||
this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith(
|
||||
'debug'
|
||||
)
|
||||
})
|
||||
})
|
||||
|
||||
describe('when time value returned that is less than current time', function() {
|
||||
describe('when level is already set', function() {
|
||||
beforeEach(function() {
|
||||
this.mockBunyanLogger.level.returns(10)
|
||||
this.Request.yields(null, { statusCode: 200 }, this.start + 1000)
|
||||
this.logger.checkLogLevel()
|
||||
})
|
||||
|
||||
it('should set trace level', function() {
|
||||
this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith(
|
||||
'trace'
|
||||
)
|
||||
})
|
||||
})
|
||||
|
||||
describe('when level is not already set', function() {
|
||||
beforeEach(function() {
|
||||
this.mockBunyanLogger.level.returns(20)
|
||||
this.Request.yields(null, { statusCode: 200 }, this.start + 1000)
|
||||
this.logger.checkLogLevel()
|
||||
})
|
||||
|
||||
it('should set trace level', function() {
|
||||
this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith(
|
||||
'trace'
|
||||
)
|
||||
})
|
||||
})
|
||||
})
|
||||
})
|
||||
|
||||
describe('ringbuffer', function() {
|
||||
beforeEach(function() {
|
||||
this.logBufferMock = [
|
||||
{
|
||||
msg: 'log 1'
|
||||
},
|
||||
{
|
||||
msg: 'log 2'
|
||||
},
|
||||
{
|
||||
level: 50,
|
||||
msg: 'error'
|
||||
}
|
||||
]
|
||||
})
|
||||
|
||||
describe('when ring buffer size is positive', function() {
|
||||
beforeEach(function() {
|
||||
process.env['LOG_RING_BUFFER_SIZE'] = '20'
|
||||
this.logger = this.LoggingManager.initialize(this.loggerName)
|
||||
this.logger.ringBuffer.records = this.logBufferMock
|
||||
this.logger.error({}, 'error')
|
||||
})
|
||||
|
||||
afterEach(function() {
|
||||
process.env['LOG_RING_BUFFER_SIZE'] = undefined
|
||||
})
|
||||
|
||||
it('should include buffered logs in error log and filter out error logs in buffer', function() {
|
||||
this.mockBunyanLogger.error.lastCall.args[0].logBuffer.should.deep.equal([
|
||||
{
|
||||
msg: 'log 1'
|
||||
},
|
||||
{
|
||||
msg: 'log 2'
|
||||
},
|
||||
])
|
||||
})
|
||||
})
|
||||
|
||||
describe('when ring buffer size is zero', function() {
|
||||
beforeEach(function() {
|
||||
process.env['LOG_RING_BUFFER_SIZE'] = '0'
|
||||
this.logger = this.LoggingManager.initialize(this.loggerName)
|
||||
this.logger.error({}, 'error')
|
||||
})
|
||||
|
||||
afterEach(function() {
|
||||
process.env['LOG_RING_BUFFER_SIZE'] = undefined
|
||||
})
|
||||
|
||||
it('should not include buffered logs in error log', function() {
|
||||
chai.expect(this.mockBunyanLogger.error.lastCall.args[0].logBuffer).be
|
||||
.undefined
|
||||
})
|
||||
})
|
||||
})
|
||||
})
|
||||
Reference in New Issue
Block a user