overleaf/libraries/logger/test/unit/loggingManagerTests.js

565 lines
18 KiB
JavaScript
Raw Normal View History

2019-03-08 11:06:24 -05:00
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')
2019-03-06 15:08:38 -05:00
2019-03-08 11:06:24 -05:00
chai.use(sinonChai)
chai.should()
const expect = chai.expect
2019-03-06 15:08:38 -05:00
2019-03-08 11:06:24 -05:00
const modulePath = path.join(__dirname, '../../logging-manager.js')
2020-07-02 06:01:23 -04:00
describe('LoggingManager', function () {
beforeEach(function () {
2019-03-08 11:06:24 -05:00
this.start = Date.now()
this.clock = sinon.useFakeTimers(this.start)
this.captureException = sinon.stub()
this.bunyanLogger = {
addStream: sinon.stub(),
debug: sinon.stub(),
error: sinon.stub(),
fatal: sinon.stub(),
info: sinon.stub(),
level: sinon.stub(),
warn: sinon.stub()
2019-03-08 11:06:24 -05:00
}
this.ravenClient = {
captureException: this.captureException,
once: sinon.stub().yields()
2019-03-08 11:06:24 -05:00
}
2020-07-06 09:53:49 -04:00
this.fetchResponse = {
text: sinon.stub().resolves('')
}
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)
}
2020-07-06 09:53:49 -04:00
this.Fetch = {
fetch: sinon.stub().resolves(this.fetchResponse)
}
this.Fs = {
readFile: sinon.stub(),
access: sinon.stub()
}
this.stackdriverStreamConfig = { stream: 'stackdriver' }
this.stackdriverClient = {
stream: sinon.stub().returns(this.stackdriverStreamConfig)
}
this.GCPLogging = {
LoggingBunyan: sinon.stub().returns(this.stackdriverClient)
}
this.LoggingManager = SandboxedModule.require(modulePath, {
globals: { console, process },
requires: {
bunyan: this.Bunyan,
raven: this.Raven,
2020-07-06 09:53:49 -04:00
'node-fetch': this.Fetch,
fs: this.Fs,
'@google-cloud/logging-bunyan': this.GCPLogging
}
2019-03-08 11:06:24 -05:00
})
this.loggerName = 'test'
this.logger = this.LoggingManager.initialize(this.loggerName)
this.logger.initializeErrorReporting('test_dsn')
})
2020-07-02 06:01:23 -04:00
afterEach(function () {
2019-03-08 11:06:24 -05:00
this.clock.restore()
})
2020-07-02 06:01:23 -04:00
describe('initialize', function () {
beforeEach(function () {
2019-03-08 11:06:24 -05:00
this.checkLogLevelStub = sinon.stub(this.LoggingManager, 'checkLogLevel')
this.Bunyan.createLogger.reset()
})
2020-07-02 06:01:23 -04:00
afterEach(function () {
2019-03-08 11:06:24 -05:00
this.checkLogLevelStub.restore()
})
2020-07-02 06:01:23 -04:00
describe('not in production', function () {
beforeEach(function () {
2019-03-08 11:06:24 -05:00
this.logger = this.LoggingManager.initialize(this.loggerName)
})
2020-07-02 06:01:23 -04:00
it('should default to log level debug', function () {
this.Bunyan.createLogger.firstCall.args[0].streams[0].level.should.equal(
2019-03-08 11:06:24 -05:00
'debug'
)
})
2020-07-02 06:01:23 -04:00
it('should not run checkLogLevel', function () {
2019-03-08 11:06:24 -05:00
this.checkLogLevelStub.should.not.have.been.called
})
})
2020-07-02 06:01:23 -04:00
describe('in production', function () {
beforeEach(function () {
2019-03-08 11:06:24 -05:00
process.env.NODE_ENV = 'production'
this.logger = this.LoggingManager.initialize(this.loggerName)
})
2019-03-08 11:06:24 -05:00
afterEach(() => delete process.env.NODE_ENV)
2020-07-02 06:01:23 -04:00
it('should default to log level warn', function () {
this.Bunyan.createLogger.firstCall.args[0].streams[0].level.should.equal(
2019-03-08 11:06:24 -05:00
'warn'
)
})
2020-07-02 06:01:23 -04:00
it('should run checkLogLevel', function () {
2019-03-08 11:06:24 -05:00
this.checkLogLevelStub.should.have.been.calledOnce
})
describe('after 1 minute', () =>
2020-07-02 06:01:23 -04:00
it('should run checkLogLevel again', function () {
2019-03-08 11:06:24 -05:00
this.clock.tick(61 * 1000)
this.checkLogLevelStub.should.have.been.calledTwice
}))
describe('after 2 minutes', () =>
2020-07-02 06:01:23 -04:00
it('should run checkLogLevel again', function () {
2019-03-08 11:06:24 -05:00
this.clock.tick(121 * 1000)
this.checkLogLevelStub.should.have.been.calledThrice
}))
})
2020-07-02 06:01:23 -04:00
describe('when LOG_LEVEL set in env', function () {
beforeEach(function () {
2019-03-08 11:06:24 -05:00
process.env.LOG_LEVEL = 'trace'
this.LoggingManager.initialize()
})
2019-03-08 11:06:24 -05:00
afterEach(() => delete process.env.LOG_LEVEL)
2020-07-02 06:01:23 -04:00
it('should use custom log level', function () {
this.Bunyan.createLogger.firstCall.args[0].streams[0].level.should.equal(
2019-03-08 11:06:24 -05:00
'trace'
)
})
})
})
2020-07-02 06:01:23 -04:00
describe('bunyan logging', function () {
beforeEach(function () {
2019-03-08 11:06:24 -05:00
this.logArgs = [{ foo: 'bar' }, 'foo', 'bar']
})
2020-07-02 06:01:23 -04:00
it('should log debug', function () {
2019-03-08 11:06:24 -05:00
this.logger.debug(this.logArgs)
this.bunyanLogger.debug.should.have.been.calledWith(this.logArgs)
2019-03-08 11:06:24 -05:00
})
2020-07-02 06:01:23 -04:00
it('should log error', function () {
2019-03-08 11:06:24 -05:00
this.logger.error(this.logArgs)
this.bunyanLogger.error.should.have.been.calledWith(this.logArgs)
2019-03-08 11:06:24 -05:00
})
2020-07-02 06:01:23 -04:00
it('should log fatal', function () {
2019-03-08 11:06:24 -05:00
this.logger.fatal(this.logArgs)
this.bunyanLogger.fatal.should.have.been.calledWith(this.logArgs)
2019-03-08 11:06:24 -05:00
})
2020-07-02 06:01:23 -04:00
it('should log info', function () {
2019-03-08 11:06:24 -05:00
this.logger.info(this.logArgs)
this.bunyanLogger.info.should.have.been.calledWith(this.logArgs)
2019-03-08 11:06:24 -05:00
})
2020-07-02 06:01:23 -04:00
it('should log warn', function () {
2019-03-08 11:06:24 -05:00
this.logger.warn(this.logArgs)
this.bunyanLogger.warn.should.have.been.calledWith(this.logArgs)
2019-03-08 11:06:24 -05:00
})
2020-07-02 06:01:23 -04:00
it('should log err', function () {
2019-03-08 11:06:24 -05:00
this.logger.err(this.logArgs)
this.bunyanLogger.error.should.have.been.calledWith(this.logArgs)
2019-03-08 11:06:24 -05:00
})
2020-07-02 06:01:23 -04:00
it('should log log', function () {
2019-03-08 11:06:24 -05:00
this.logger.log(this.logArgs)
this.bunyanLogger.info.should.have.been.calledWith(this.logArgs)
2019-03-08 11:06:24 -05:00
})
})
2020-07-02 06:01:23 -04:00
describe('logger.error', function () {
it('should report a single error to sentry', function () {
2019-03-08 11:06:24 -05:00
this.logger.error({ foo: 'bar' }, 'message')
this.captureException.called.should.equal(true)
})
2020-07-02 06:01:23 -04:00
it('should report the same error to sentry only once', function () {
2019-03-08 11:06:24 -05:00
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)
})
2020-07-02 06:01:23 -04:00
it('should report two different errors to sentry individually', function () {
2019-03-08 11:06:24 -05:00
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)
})
2020-07-02 06:01:23 -04:00
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'"
2019-03-08 11:06:24 -05:00
)
fsError.path = '/tmp/3279b8d0-da10-11e8-8255-efd98985942b'
this.logger.error({ err: fsError }, 'message')
this.captureException
.calledWith(
sinon.match.has(
2019-03-08 11:06:24 -05:00
'message',
'Error: ENOENT: no such file or directory, stat'
)
)
2019-03-08 11:06:24 -05:00
.should.equal(true)
})
2020-07-02 06:01:23 -04:00
it('for multiple errors should only report a maximum of 5 errors to sentry', function () {
2019-03-08 11:06:24 -05:00
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)
})
2020-07-02 06:01:23 -04:00
it('for multiple errors with a minute delay should report 10 errors to sentry', function () {
// the first five errors should be reported to sentry
2019-03-08 11:06:24 -05:00
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
2019-03-08 11:06:24 -05:00
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
2019-03-08 11:06:24 -05:00
this.clock.tick(this.start + 61 * 1000)
// after a minute the next five errors should be reported to sentry
2019-03-08 11:06:24 -05:00
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
2019-03-08 11:06:24 -05:00
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)
})
2020-07-02 06:01:23 -04:00
describe('reportedToSentry', function () {
it('should mark the error as reported to sentry', function () {
const err = new Error()
this.logger.error({ err }, 'message')
expect(this.captureException.called).to.equal(true)
expect(err.reportedToSentry).to.equal(true)
})
2020-07-02 06:01:23 -04:00
it('should mark two errors as reported to sentry', function () {
const err1 = new Error()
const err2 = new Error()
this.logger.error({ err: err1, err2 }, 'message')
expect(this.captureException.called).to.equal(true)
expect(err1.reportedToSentry).to.equal(true)
expect(err2.reportedToSentry).to.equal(true)
})
2020-07-02 06:01:23 -04:00
it('should not mark arbitrary objects as reported to sentry', function () {
const err = new Error()
const ctx = { foo: 'bar' }
this.logger.error({ err, ctx }, 'message')
expect(this.captureException.called).to.equal(true)
expect(ctx.reportedToSentry).to.equal(undefined)
})
})
2019-03-08 11:06:24 -05:00
})
2020-07-02 06:01:23 -04:00
describe('checkLogLevel', function () {
beforeEach(function () {
this.Fs.access.yields(null)
})
2020-07-02 06:01:23 -04:00
it('should request log level override from the config map', function () {
2019-03-08 11:06:24 -05:00
this.logger.checkLogLevel()
this.Fs.access.should.have.been.calledWithMatch(
'/logging'
)
2020-06-30 08:56:13 -04:00
this.Fs.readFile.should.have.been.calledWithMatch(
'/logging/tracingEndTime'
)
2019-03-08 11:06:24 -05:00
})
2020-07-02 06:01:23 -04:00
describe('when read errors', function () {
beforeEach(function () {
this.Fs.readFile.yields(new Error('error'))
2019-03-08 11:06:24 -05:00
this.logger.checkLogLevel()
})
2020-07-02 06:01:23 -04:00
it('should only set default level', function () {
this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith(
2019-03-08 11:06:24 -05:00
'debug'
)
})
})
2020-07-02 06:01:23 -04:00
describe('when the file is empty', function () {
beforeEach(function () {
this.Fs.readFile.yields(null, '')
2019-03-08 11:06:24 -05:00
this.logger.checkLogLevel()
})
2020-07-02 06:01:23 -04:00
it('should only set default level', function () {
this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith(
2019-03-08 11:06:24 -05:00
'debug'
)
})
})
2020-07-02 06:01:23 -04:00
describe('when time value returned that is less than current time', function () {
beforeEach(function () {
this.Fs.readFile.yields(null, '1')
2019-03-08 11:06:24 -05:00
this.logger.checkLogLevel()
})
2020-07-02 06:01:23 -04:00
it('should only set default level', function () {
this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith(
2019-03-08 11:06:24 -05:00
'debug'
)
})
})
2020-07-02 06:01:23 -04:00
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.Fs.readFile.yields(null, (this.start + 1000).toString())
2019-03-08 11:06:24 -05:00
this.logger.checkLogLevel()
})
2020-07-02 06:01:23 -04:00
it('should set trace level', function () {
this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith(
2019-03-08 11:06:24 -05:00
'trace'
)
})
})
2020-07-02 06:01:23 -04:00
describe('when level is not already set', function () {
beforeEach(function () {
this.bunyanLogger.level.returns(20)
this.Fs.readFile.yields(null, (this.start + 1000).toString())
2019-03-08 11:06:24 -05:00
this.logger.checkLogLevel()
})
2020-07-02 06:01:23 -04:00
it('should set trace level', function () {
this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith(
2019-03-08 11:06:24 -05:00
'trace'
)
})
})
describe('when /logging does not exist', function () {
beforeEach(function () {
this.Fs.access.yields(new Error)
})
describe('checkLogLevel', function() {
it('should request log level override from google meta data service', function() {
this.logger.checkLogLevel()
const options = {
headers: {
'Metadata-Flavor': 'Google'
2020-07-06 09:53:49 -04:00
}
}
2020-07-06 09:53:49 -04:00
const uri = `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime`
this.Fetch.fetch.should.have.been.calledWithMatch(uri,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)
2020-07-06 09:53:49 -04:00
this.fetchResponse.text = sinon.stub().resolves(this.start + 1000)
this.Fetch.fetch = sinon.stub().resolves(this.fetchResponse)
//this.Request.yields(null, { statusCode: 200 }, this.start + 1000)
//this.fetchResponse = sinon.stub().resolves
//{data: this.start + 1000, status: 200}
this.logger.checkLogLevel()
})
it('should set trace level', function() {
this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith(
'trace'
)
})
})
})
})
2019-03-08 11:06:24 -05:00
})
})
})
2020-07-02 06:01:23 -04:00
describe('ringbuffer', function () {
beforeEach(function () {
this.logBufferMock = [
{ msg: 'log 1' },
{ msg: 'log 2' },
{ level: 50, msg: 'error' }
2019-03-08 11:06:24 -05:00
]
})
2020-07-02 06:01:23 -04:00
describe('when ring buffer size is positive', function () {
beforeEach(function () {
2020-07-02 05:51:37 -04:00
process.env.LOG_RING_BUFFER_SIZE = '20'
2019-03-08 11:06:24 -05:00
this.logger = this.LoggingManager.initialize(this.loggerName)
this.logger.ringBuffer.records = this.logBufferMock
this.logger.error({}, 'error')
})
2020-07-02 06:01:23 -04:00
afterEach(function () {
2020-07-02 05:51:37 -04:00
process.env.LOG_RING_BUFFER_SIZE = undefined
2019-03-08 11:06:24 -05:00
})
2020-07-02 06:01:23 -04:00
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' }
2019-03-12 08:23:37 -04:00
])
2019-03-08 11:06:24 -05:00
})
})
2020-07-02 06:01:23 -04:00
describe('when ring buffer size is zero', function () {
beforeEach(function () {
2020-07-02 05:51:37 -04:00
process.env.LOG_RING_BUFFER_SIZE = '0'
2019-03-08 11:06:24 -05:00
this.logger = this.LoggingManager.initialize(this.loggerName)
this.logger.error({}, 'error')
})
2020-07-02 06:01:23 -04:00
afterEach(function () {
2020-07-02 05:51:37 -04:00
process.env.LOG_RING_BUFFER_SIZE = undefined
2019-03-11 10:27:35 -04:00
})
2020-07-02 06:01:23 -04:00
it('should not include buffered logs in error log', function () {
expect(this.bunyanLogger.error.lastCall.args[0].logBuffer).be.undefined
2019-03-08 11:06:24 -05:00
})
})
})
2020-07-02 06:01:23 -04:00
describe('stackdriver logging', function () {
describe('when STACKDRIVER_LOGGING is unset', function () {
beforeEach(function () {
2020-07-02 05:51:37 -04:00
process.env.STACKDRIVER_LOGGING = undefined
this.LoggingManager.initialize(this.loggerName)
})
2020-07-02 06:01:23 -04:00
it('is disabled', function () {
expect(this.bunyanLogger.addStream).not.to.have.been.calledWith(
this.stackdriverStreamConfig
)
})
})
2020-07-02 06:01:23 -04:00
describe('when STACKDRIVER_LOGGING is true', function () {
beforeEach(function () {
2020-07-02 05:51:37 -04:00
process.env.STACKDRIVER_LOGGING = 'true'
this.LoggingManager.initialize(this.loggerName)
})
2020-07-02 06:01:23 -04:00
it('is enabled', function () {
expect(this.bunyanLogger.addStream).to.have.been.calledWith(
this.stackdriverStreamConfig
)
})
2020-07-02 06:01:23 -04:00
it('is configured properly', function () {
expect(this.GCPLogging.LoggingBunyan).to.have.been.calledWith({
logName: this.loggerName,
serviceContext: { service: this.loggerName }
})
})
})
})
2019-03-08 11:06:24 -05:00
})