diff --git a/libraries/logger/.eslintrc b/libraries/logger/.eslintrc new file mode 100644 index 0000000000..b0db54a22f --- /dev/null +++ b/libraries/logger/.eslintrc @@ -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" + } +} diff --git a/libraries/logger/.prettierrc b/libraries/logger/.prettierrc new file mode 100644 index 0000000000..b2095be81e --- /dev/null +++ b/libraries/logger/.prettierrc @@ -0,0 +1,4 @@ +{ + "semi": false, + "singleQuote": true +} diff --git a/libraries/logger/index.js b/libraries/logger/index.js index dedfe4be5d..6cd6f9ef8b 100755 --- a/libraries/logger/index.js +++ b/libraries/logger/index.js @@ -1,2 +1 @@ -require("coffee-script/register") -module.exports = require('./logging-manager'); +module.exports = require('./logging-manager.js') diff --git a/libraries/logger/logging-manager.coffee b/libraries/logger/logging-manager.coffee deleted file mode 100644 index a7d4e6d27b..0000000000 --- a/libraries/logger/logging-manager.coffee +++ /dev/null @@ -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") diff --git a/libraries/logger/logging-manager.js b/libraries/logger/logging-manager.js new file mode 100644 index 0000000000..cf702ac821 --- /dev/null +++ b/libraries/logger/logging-manager.js @@ -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') diff --git a/libraries/logger/package.json b/libraries/logger/package.json index 96d8d7dd8a..381905ff23 100644 --- a/libraries/logger/package.json +++ b/libraries/logger/package.json @@ -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" } } diff --git a/libraries/logger/test/unit/coffee/loggingManagerTests.coffee b/libraries/logger/test/unit/coffee/loggingManagerTests.coffee deleted file mode 100644 index 04dd848c25..0000000000 --- a/libraries/logger/test/unit/coffee/loggingManagerTests.coffee +++ /dev/null @@ -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') diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js new file mode 100644 index 0000000000..dc8ac244b2 --- /dev/null +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -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 + }) + }) + }) +})