Merge pull request #23 from overleaf/csh-metadata-fallback-node-fetch

Support file and GCE metadata as log level sources

libraries/logger/logging-manager.js

@@ -1,4 +1,5 @@
 const bunyan = require('bunyan')
+const fetch = require('node-fetch')
 const fs = require('fs')
 const yn = require('yn')
 const OError = require('@overleaf/o-error')
@@ -21,6 +22,7 @@ const errSerializer = function (err) {
 
 const Logger = (module.exports = {
   initialize(name) {
+    this.logLevelSource = (process.env.LOG_LEVEL_SOURCE || 'file').toLowerCase()
     this.isProduction =
       (process.env.NODE_ENV || '').toLowerCase() === 'production'
     this.defaultLevel =
@@ -41,18 +43,33 @@ const Logger = (module.exports = {
     return this
   },
 
-  checkLogLevel() {
-    fs.readFile('/logging/tracingEndTime', (error, end) => {
-      if (error || !end) {
-        this.logger.level(this.defaultLevel)
-        return
-      }
-      if (parseInt(end) > Date.now()) {
+  async checkLogLevel() {
+    try {
+      const end = await this.getTracingEndTime()
+      if (parseInt(end, 10) > Date.now()) {
         this.logger.level('trace')
       } else {
         this.logger.level(this.defaultLevel)
       }
-    })
+    } catch (err) {
+      this.logger.level(this.defaultLevel)
+    }
+  },
+
+  async getTracingEndTimeFile() {
+    return fs.promises.readFile('/logging/tracingEndTime')
+  },
+
+  async getTracingEndTimeMetadata() {
+    const options = {
+      headers: {
+        'Metadata-Flavor': 'Google'
+      }
+    }
+    const uri = `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime`
+    const res = await fetch(uri, options)
+    if (!res.ok) throw new Error('Metadata not okay')
+    return res.text()
   },
 
   initializeErrorReporting(sentryDsn, options) {
@@ -241,6 +258,16 @@ const Logger = (module.exports = {
       if (this.checkInterval) {
         clearInterval(this.checkInterval)
       }
+      if (this.logLevelSource === 'file') {
+        this.getTracingEndTime = this.getTracingEndTimeFile
+      } else if (this.logLevelSource === 'gce_metadata') {
+        this.getTracingEndTime = this.getTracingEndTimeMetadata
+      } else if (this.logLevelSource === 'none') {
+        return
+      } else {
+        console.log('Unrecognised log level source')
+        return
+      }
       // check for log level override on startup
       this.checkLogLevel()
       // re-check log level every minute

libraries/logger/package.json

@@ -7,9 +7,9 @@
     "url": "http://github.com/sharelatex/logger-sharelatex.git"
   },
   "license": "AGPL-3.0-only",
-  "version": "2.1.1",
+  "version": "2.2.0",
   "scripts": {
-    "test": "mocha test/**/*.js",
+    "test": "mocha --grep=$MOCHA_GREP test/**/*.js",
     "format": "prettier-eslint $PWD'/**/*.js' --list-different",
     "format:fix": "prettier-eslint $PWD'/**/*.js' --write",
     "lint": "eslint -f unix ."
@@ -18,6 +18,7 @@
     "@google-cloud/logging-bunyan": "^3.0.0",
     "@overleaf/o-error": "^3.0.0",
     "bunyan": "^1.8.14",
+    "node-fetch": "^2.6.0",
     "raven": "^2.6.4",
     "yn": "^4.0.0"
   },

libraries/logger/test/unit/loggingManagerTests.js

@@ -29,6 +29,11 @@ describe('LoggingManager', function () {
       captureException: this.captureException,
       once: sinon.stub().yields()
     }
+    this.fetchResponse = {
+      text: sinon.stub().resolves(''),
+      status: 200,
+      ok: true
+    }
     this.Bunyan = {
       createLogger: sinon.stub().returns(this.bunyanLogger),
       RingBuffer: bunyan.RingBuffer,
@@ -40,8 +45,12 @@ describe('LoggingManager', function () {
     this.Raven = {
       Client: sinon.stub().returns(this.ravenClient)
     }
+    this.Fetch = sinon.stub().resolves(this.fetchResponse)
     this.Fs = {
-      readFile: sinon.stub()
+      readFile: sinon.stub(),
+      promises: {
+        readFile: sinon.stub()
+      }
     }
     this.stackdriverStreamConfig = { stream: 'stackdriver' }
     this.stackdriverClient = {
@@ -55,6 +64,7 @@ describe('LoggingManager', function () {
       requires: {
         bunyan: this.Bunyan,
         raven: this.Raven,
+        'node-fetch': this.Fetch,
         fs: this.Fs,
         '@google-cloud/logging-bunyan': this.GCPLogging
       }
@@ -70,7 +80,9 @@ describe('LoggingManager', function () {
 
   describe('initialize', function () {
     beforeEach(function () {
-      this.checkLogLevelStub = sinon.stub(this.LoggingManager, 'checkLogLevel')
+      this.checkLogLevelStub = sinon
+        .stub(this.LoggingManager, 'checkLogLevel')
+        .resolves('')
       this.Bunyan.createLogger.reset()
     })
 
@@ -108,21 +120,23 @@ describe('LoggingManager', function () {
         )
       })
 
-      it('should run checkLogLevel', function () {
-        this.checkLogLevelStub.should.have.been.calledOnce
+      describe('logLevelSource file', function () {
+        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('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 () {
@@ -287,18 +301,20 @@ describe('LoggingManager', function () {
     })
   })
 
-  describe('checkLogLevel', function () {
-    it('should request log level override from the config map', function () {
-      this.logger.checkLogLevel()
-      this.Fs.readFile.should.have.been.calledWithMatch(
+  describe('checkLogLevelFile', function () {
+    it('should request log level override from the config map', async function () {
+      this.logger.getTracingEndTime = this.logger.getTracingEndTimeFile
+      await this.logger.checkLogLevel()
+      this.Fs.promises.readFile.should.have.been.calledWithMatch(
         '/logging/tracingEndTime'
       )
     })
 
     describe('when read errors', function () {
-      beforeEach(function () {
-        this.Fs.readFile.yields(new Error('error'))
-        this.logger.checkLogLevel()
+      beforeEach(async function () {
+        this.Fs.promises.readFile.throws(new Error('test read error'))
+        this.logger.getTracingEndTime = this.logger.getTracingEndTimeFile
+        await this.logger.checkLogLevel()
       })
 
       it('should only set default level', function () {
@@ -309,9 +325,10 @@ describe('LoggingManager', function () {
     })
 
     describe('when the file is empty', function () {
-      beforeEach(function () {
-        this.Fs.readFile.yields(null, '')
-        this.logger.checkLogLevel()
+      beforeEach(async function () {
+        this.Fs.promises.readFile.returns('')
+        this.logger.getTracingEndTime = this.logger.getTracingEndTimeFile
+        await this.logger.checkLogLevel()
       })
 
       it('should only set default level', function () {
@@ -322,9 +339,10 @@ describe('LoggingManager', function () {
     })
 
     describe('when time value returned that is less than current time', function () {
-      beforeEach(function () {
-        this.Fs.readFile.yields(null, '1')
-        this.logger.checkLogLevel()
+      beforeEach(async function () {
+        this.Fs.promises.readFile.returns('1')
+        this.logger.getTracingEndTime = this.logger.getTracingEndTimeFile
+        await this.logger.checkLogLevel()
       })
 
       it('should only set default level', function () {
@@ -336,10 +354,11 @@ describe('LoggingManager', function () {
 
     describe('when time value returned that is more than current time', function () {
       describe('when level is already set', function () {
-        beforeEach(function () {
+        beforeEach(async function () {
           this.bunyanLogger.level.returns(10)
-          this.Fs.readFile.yields(null, (this.start + 1000).toString())
-          this.logger.checkLogLevel()
+          this.Fs.promises.readFile.returns((this.start + 1000).toString())
+          this.logger.getTracingEndTime = this.logger.getTracingEndTimeFile
+          await this.logger.checkLogLevel()
         })
 
         it('should set trace level', function () {
@@ -350,10 +369,11 @@ describe('LoggingManager', function () {
       })
 
       describe('when level is not already set', function () {
-        beforeEach(function () {
+        beforeEach(async function () {
           this.bunyanLogger.level.returns(20)
-          this.Fs.readFile.yields(null, (this.start + 1000).toString())
-          this.logger.checkLogLevel()
+          this.Fs.promises.readFile.returns((this.start + 1000).toString())
+          this.logger.getTracingEndTime = this.logger.getTracingEndTimeFile
+          await this.logger.checkLogLevel()
         })
 
         it('should set trace level', function () {
@@ -365,6 +385,107 @@ describe('LoggingManager', function () {
     })
   })
 
+  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', async function () {
+        this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata
+        await 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.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata
+          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.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata
+          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.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata
+          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.fetchResponse.text = sinon
+              .stub()
+              .resolves((this.start + 1000).toString())
+            this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata
+
+            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).toString())
+            this.Fetch.fetch = sinon.stub().resolves(this.fetchResponse)
+            this.logger.getTracingEndTime = this.logger.getTracingEndTimeMetadata
+
+            await 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 = [