From 6bc0d15d78ae4bff064656a50138a46c3f49b51d Mon Sep 17 00:00:00 2001 From: Christopher Hoskin Date: Fri, 24 Jul 2020 11:59:23 +0100 Subject: [PATCH] LOG_LEVEL_SOURCE env taking values file, gce_metadata or none, default file --- libraries/logger/logging-manager.js | 27 +- .../logger/test/unit/loggingManagerTests.js | 279 ++++++++++-------- 2 files changed, 170 insertions(+), 136 deletions(-) diff --git a/libraries/logger/logging-manager.js b/libraries/logger/logging-manager.js index 14e7cb2c35..4b384df0f1 100644 --- a/libraries/logger/logging-manager.js +++ b/libraries/logger/logging-manager.js @@ -22,7 +22,7 @@ const errSerializer = function (err) { const Logger = (module.exports = { initialize(name) { - this.useMetadata = (process.env.USE_METADATA || '').toLowerCase() === 'true' + this.logLevelSource = (process.env.LOG_LEVEL_SOURCE || 'file').toLowerCase() this.isProduction = (process.env.NODE_ENV || '').toLowerCase() === 'production' this.defaultLevel = @@ -80,14 +80,6 @@ async checkLogLevelMetadata() { } }, - async checkLogLevel() { - if (this.useMetadata) { - await this.checkLogLevelMetadata() - } else { - await this.checkLogLevelFile() - } - }, - initializeErrorReporting(sentryDsn, options) { const raven = require('raven') this.raven = new raven.Client(sentryDsn, options) @@ -274,10 +266,19 @@ async checkLogLevelMetadata() { if (this.checkInterval) { clearInterval(this.checkInterval) } - // check for log level override on startup - this.checkLogLevel() - // re-check log level every minute - this.checkInterval = setInterval(this.checkLogLevel.bind(this), 1000 * 60) + if (this.logLevelSource === 'file') { + // check for log level override on startup + this.checkLogLevelFile() + // re-check log level every minute + this.checkInterval = setInterval(this.checkLogLevelFile.bind(this), 1000 * 60) + } else if (this.logLevelSource === 'gce_metadata') { + // check for log level override on startup + this.checkLogLevelMetadata() + // re-check log level every minute + this.checkInterval = setInterval(this.checkLogLevelMetadata.bind(this), 1000 * 60) + } else if (this.logLevelSource !== 'none') { + console.log('Unrecognised log level source') + } } } }) diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index f9532875ea..ee13dbc56d 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -83,12 +83,14 @@ describe('LoggingManager', function () { describe('initialize', function () { beforeEach(function () { - this.checkLogLevelStub = sinon.stub(this.LoggingManager, 'checkLogLevel') + this.checkLogLevelFileStub = sinon.stub(this.LoggingManager, 'checkLogLevelFile') + this.checkLogLevelMetadataStub = sinon.stub(this.LoggingManager, 'checkLogLevelMetadata') this.Bunyan.createLogger.reset() }) afterEach(function () { - this.checkLogLevelStub.restore() + this.checkLogLevelFileStub.restore() + this.checkLogLevelMetadataStub.restore() }) describe('not in production', function () { @@ -103,41 +105,76 @@ describe('LoggingManager', function () { }) it('should not run checkLogLevel', function () { - this.checkLogLevelStub.should.not.have.been.called + this.checkLogLevelFileStub.should.not.have.been.called + this.checkLogLevelMetadataStub.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.logger = this.LoggingManager.initialize(this.loggerName) this.Bunyan.createLogger.firstCall.args[0].streams[0].level.should.equal( 'warn' ) }) - it('should run checkLogLevel', function () { - this.checkLogLevelStub.should.have.been.calledOnce + describe('logLevelSource file', function () { + beforeEach(function() { + this.logger = this.LoggingManager.initialize(this.loggerName) + }) + + it('should run checkLogLevel', function () { + this.checkLogLevelFileStub.should.have.been.calledOnce + }) + + describe('after 1 minute', () => + it('should run checkLogLevel again', function () { + this.clock.tick(61 * 1000) + this.checkLogLevelFileStub.should.have.been.calledTwice + })) + + describe('after 2 minutes', () => + it('should run checkLogLevel again', function () { + this.clock.tick(121 * 1000) + this.checkLogLevelFileStub.should.have.been.calledThrice + })) }) - describe('after 1 minute', () => - it('should run checkLogLevel again', function () { - this.clock.tick(61 * 1000) - this.checkLogLevelStub.should.have.been.calledTwice - })) + describe('logLevelSource gce_metadata', function () { + beforeEach(function () { + process.env.LOG_LEVEL_SOURCE = 'gce_metadata' + this.logger = this.LoggingManager.initialize(this.loggerName) + }) + + afterEach(() => delete process.env.LOG_LEVEL_SOURCE) + + it('should run checkLogLevel', function () { + this.checkLogLevelMetadataStub.should.have.been.calledOnce + }) + + describe('after 1 minute', () => + it('should run checkLogLevel again', function () { + this.clock.tick(61 * 1000) + this.checkLogLevelMetadataStub.should.have.been.calledTwice + })) + + describe('after 2 minutes', () => + it('should run checkLogLevel again', function () { + this.clock.tick(121 * 1000) + this.checkLogLevelMetadataStub.should.have.been.calledThrice + })) + }) - 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' @@ -300,10 +337,10 @@ describe('LoggingManager', function () { }) }) - describe('checkLogLevel', function () { + describe('checkLogLevelFile', function () { it('should request log level override from the config map', async function () { - await this.logger.checkLogLevel() + await this.logger.checkLogLevelFile() this.Fs.promises.readFile.should.have.been.calledWithMatch( '/logging/tracingEndTime' ) @@ -312,7 +349,7 @@ describe('LoggingManager', function () { describe('when read errors', function () { beforeEach(function () { this.Fs.promises.readFile.yields(new Error('error')) - this.logger.checkLogLevel() + this.logger.checkLogLevelFile() }) it('should only set default level', function () { @@ -325,7 +362,7 @@ describe('LoggingManager', function () { describe('when the file is empty', function () { beforeEach(function () { this.Fs.promises.readFile.yields(null, '') - this.logger.checkLogLevel() + this.logger.checkLogLevelFile() }) it('should only set default level', function () { @@ -338,7 +375,7 @@ describe('LoggingManager', function () { describe('when time value returned that is less than current time', function () { beforeEach(function () { this.Fs.promises.readFile.yields(null, '1') - this.logger.checkLogLevel() + this.logger.checkLogLevelFile() }) it('should only set default level', function () { @@ -353,7 +390,7 @@ describe('LoggingManager', function () { beforeEach(async function () { this.bunyanLogger.level.returns(10) this.Fs.promises.readFile.returns((this.start + 1000).toString()) - await this.logger.checkLogLevel() + await this.logger.checkLogLevelFile() }) it('should set trace level', function () { @@ -367,7 +404,7 @@ describe('LoggingManager', function () { beforeEach(async function () { this.bunyanLogger.level.returns(20) this.Fs.promises.readFile.returns((this.start + 1000).toString()) - await this.logger.checkLogLevel() + await this.logger.checkLogLevelFile() }) it('should set trace level', function () { @@ -376,118 +413,114 @@ describe('LoggingManager', function () { ) }) }) + }) + }) - describe('when using metadata', function () { - beforeEach(function () { - process.env.USE_METADATA = 'TRUE' - this.logger = this.LoggingManager.initialize(this.loggerName) +describe('checkLogLevelMetadata', function () { + beforeEach(function () { + this.logger = this.LoggingManager.initialize(this.loggerName) + }) + + describe('checkLogLevel', function() { + it('should request log level override from google meta data service', function() { + this.logger.checkLogLevelMetadata() + const options = { + headers: { + 'Metadata-Flavor': 'Google' + } + } + const uri = `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` + this.Fetch.should.have.been.calledWithMatch(uri,options) + }) + + describe('when request has error', function() { + beforeEach(async function() { + this.Fetch = sinon.stub().throws() + //this.Request.yields('error') + await this.logger.checkLogLevelMetadata() + }) + + 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(async function() { + this.fetchResponse.status = 404 + //this.Request.yields(null, { statusCode: 404 }) + await this.logger.checkLogLevelMetadata() + }) + + 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(async function() { + //this.Request.yields(null, { statusCode: 200 }, '1') + this.fetchResponse.text = sinon.stub().resolves('1') + await this.logger.checkLogLevelMetadata() + }) + + 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(async function() { + this.bunyanLogger.level.returns(10) + //this.Request.yields(null, { statusCode: 200 }, this.start + 1000) + this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) + //this.Fetch = sinon.stub().resolves(this.fetchResponse) + + await this.logger.checkLogLevelMetadata() }) - afterEach(function() { - process.env.USE_METADATA = undefined + 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(async function() { + this.bunyanLogger.level.returns(20) + 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} + await this.logger.checkLogLevelMetadata() }) - describe('checkLogLevel', function() { - it('should request log level override from google meta data service', function() { - this.logger.checkLogLevel() - const options = { - headers: { - 'Metadata-Flavor': 'Google' - } - } - const uri = `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` - this.Fetch.should.have.been.calledWithMatch(uri,options) - }) - - describe('when request has error', function() { - beforeEach(async function() { - this.Fetch = sinon.stub().throws() - //this.Request.yields('error') - await 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(async function() { - this.fetchResponse.status = 404 - //this.Request.yields(null, { statusCode: 404 }) - await 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(async function() { - //this.Request.yields(null, { statusCode: 200 }, '1') - this.fetchResponse.text = sinon.stub().resolves('1') - await 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(async function() { - this.bunyanLogger.level.returns(10) - //this.Request.yields(null, { statusCode: 200 }, this.start + 1000) - this.fetchResponse.text = sinon.stub().resolves(this.start + 1000) - //this.Fetch = sinon.stub().resolves(this.fetchResponse) - - await 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(async function() { - this.bunyanLogger.level.returns(20) - 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} - await this.logger.checkLogLevel() - }) - - it('should set trace level', function() { - this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( - 'trace' - ) - }) - }) - }) + it('should set trace level', function() { + this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith( + 'trace' + ) }) + }) + }) + }) - }) - }) + }) describe('ringbuffer', function () {