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 expect = chai.expect 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.bunyanLogger = { debug: sinon.stub(), error: sinon.stub(), fatal: sinon.stub(), info: sinon.stub(), level: sinon.stub(), warn: sinon.stub() } this.ravenClient = { captureException: this.captureException, once: sinon.stub().yields() } this.Bunyan = { createLogger: sinon.stub().returns(this.bunyanLogger), RingBuffer: bunyan.RingBuffer, stdSerializers: { req: sinon.stub(), res: sinon.stub() } } this.Raven = { Client: sinon.stub().returns(this.ravenClient) } this.Request = sinon.stub() this.LoggingManager = SandboxedModule.require(modulePath, { globals: { console, process }, requires: { bunyan: this.Bunyan, raven: this.Raven, request: this.Request } }) 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.bunyanLogger.debug.should.have.been.calledWith(this.logArgs) }) it('should log error', function() { this.logger.error(this.logArgs) this.bunyanLogger.error.should.have.been.calledWith(this.logArgs) }) it('should log fatal', function() { this.logger.fatal(this.logArgs) this.bunyanLogger.fatal.should.have.been.calledWith(this.logArgs) }) it('should log info', function() { this.logger.info(this.logArgs) this.bunyanLogger.info.should.have.been.calledWith(this.logArgs) }) it('should log warn', function() { this.logger.warn(this.logArgs) this.bunyanLogger.warn.should.have.been.calledWith(this.logArgs) }) it('should log err', function() { this.logger.err(this.logArgs) this.bunyanLogger.error.should.have.been.calledWith(this.logArgs) }) it('should log log', function() { this.logger.log(this.logArgs) this.bunyanLogger.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.bunyanLogger.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.bunyanLogger.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.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( 'debug' ) }) }) describe('when time value returned that is more than current time', function() { describe('when level is already set', function() { beforeEach(function() { this.bunyanLogger.level.returns(10) this.Request.yields(null, { statusCode: 200 }, this.start + 1000) this.logger.checkLogLevel() }) it('should set trace level', function() { this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( 'trace' ) }) }) describe('when level is not already set', function() { beforeEach(function() { this.bunyanLogger.level.returns(20) this.Request.yields(null, { statusCode: 200 }, this.start + 1000) this.logger.checkLogLevel() }) it('should set trace level', function() { this.bunyanLogger.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.bunyanLogger.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() { expect(this.bunyanLogger.error.lastCall.args[0].logBuffer).be.undefined }) }) }) })