LOG_LEVEL_SOURCE env taking values file, gce_metadata or none, default file

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')
+      }
     }
   }
 })

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('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'
-                )
-              })
-            })
-          })
+      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()
         })
 
+        it('should set trace level', function() {
+          this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith(
+            'trace'
+          )
+        })
+      })
+    })
+  })
+
 
 
 
 
         
-      })
-    })
+
   })
 
   describe('ringbuffer', function () {