Merge pull request #10 from sharelatex/ew-check-log-level

check dynamic log level in gce metadata

libraries/logger/logging-manager.coffee

@@ -1,14 +1,34 @@
 bunyan = require('bunyan')
+request = require('request')
 
 module.exports = Logger =
 	initialize: (name) ->
-		level = process.env['LOG_LEVEL'] or "debug"
+		isProduction = process.env['NODE_ENV']?.toLowerCase() == 'production'
+		@defaultLevel = process.env['LOG_LEVEL'] or if isProduction then "warn" else  "debug"
+		@loggerName = name
 		@logger = bunyan.createLogger
 			name: name
 			serializers: bunyan.stdSerializers
-			level: level
+			level: @defaultLevel
+		if isProduction
+			# check for log level override on startup
+			@.checkLogLevel()
+			# re-check log level every minute
+			checkLogLevel = () => @.checkLogLevel()
+			setInterval(checkLogLevel, 1000 * 60)
 		return @
 
+	checkLogLevel: () ->
+		options =
+			headers:
+				"Metadata-Flavor": "Google"
+			uri: "http://metadata.google.internal/computeMetadata/v1/project/attributes/#{@loggerName}-setLogLevelEndTime"
+		request options, (err, response, body) =>
+			if parseInt(body) > Date.now()
+				@logger.level('trace')
+			else
+				@logger.level(@defaultLevel)
+
 	initializeErrorReporting: (sentry_dsn, options) ->
 		raven = require "raven"
 		@raven = new raven.Client(sentry_dsn, options)
@@ -94,7 +114,7 @@ module.exports = Logger =
 		@error.apply(this, arguments)
 	warn: ()->
 		@logger.warn.apply(@logger, arguments)
-	fatal: (attributes, message, callback) ->
+	fatal: (attributes, message, callback = () ->) ->
 		@logger.fatal(attributes, message)
 		if @raven?
 			cb = (e) -> # call the callback once after 'logged' or 'error' event

libraries/logger/package.json

@@ -6,20 +6,21 @@
     "type": "git",
     "url": "http://github.com/sharelatex/logger-sharelatex.git"
   },
-  "version": "1.5.9",
+  "version": "1.6.0",
+  "scripts": {
+    "test": "mocha --require coffee-script/register test/**/*.coffee"
+  },
   "dependencies": {
     "bunyan": "1.5.1",
-    "chai": "",
     "coffee-script": "1.12.4",
-    "grunt": "^0.4.5",
-    "grunt-bunyan": "^0.5.0",
-    "grunt-contrib-clean": "^0.6.0",
-    "grunt-contrib-coffee": "^0.11.0",
-    "grunt-execute": "^0.2.2",
-    "grunt-mocha-test": "^0.11.0",
     "raven": "^1.1.3",
-    "sandboxed-module": "",
-    "sinon": "",
-    "timekeeper": "^1.0.0"
+    "request": "^2.88.0"
+  },
+  "devDependencies": {
+    "chai": "^4.2.0",
+    "mocha": "^5.2.0",
+    "sandboxed-module": "0.2.0",
+    "sinon": "^7.2.3",
+    "sinon-chai": "^3.3.0"
   }
 }

libraries/logger/test/unit/coffee/loggingManagerTests.coffee

@@ -1,86 +1,234 @@
-# run this with 
-# ./node_modules/.bin/mocha --reporter tap --compilers coffee:coffee-script/register test/unit/coffee/loggingManagerTests.coffee
-
-require('coffee-script')
-chai = require('chai')
-should = chai.should()
-expect = chai.expect
-path = require('path')
-modulePath = path.join __dirname, '../../../logging-manager.coffee'
-SandboxedModule = require('sandboxed-module')
+SandboxedModule = require("sandboxed-module")
+chai = require("chai")
+path = require("path")
 sinon = require("sinon")
-tk = require("timekeeper")
+sinonChai = require("sinon-chai")
+
+chai.use(sinonChai)
+chai.should()
+
+modulePath = path.join __dirname, '../../../logging-manager.coffee'
 
-describe 'logger.error', ->
+describe 'LoggingManager', ->
 
 	beforeEach ->
-		@captureException = sinon.stub()
 		@start = Date.now()
-		tk.travel(new Date(@start))
+		@clock = sinon.useFakeTimers(@start)
+		@captureException = sinon.stub()
+		@mockBunyanLogger =
+			debug: sinon.stub()
+			error: sinon.stub()
+			fatal: sinon.stub()
+			info: sinon.stub()
+			level: sinon.stub()
+			warn: sinon.stub()
+		@mockRavenClient =
+			captureException: @captureException
+			once: sinon.stub().yields()
 		@LoggingManager = SandboxedModule.require modulePath, requires:
-			'bunyan': {createLogger: sinon.stub().returns({error:sinon.stub()})}
-			'raven': {Client: sinon.stub().returns({captureException:@captureException})}
-		@logger = @LoggingManager.initialize("test")
+			bunyan: @Bunyan = createLogger: sinon.stub().returns(@mockBunyanLogger)
+			raven:  @Raven = Client: sinon.stub().returns(@mockRavenClient)
+			request: @Request = sinon.stub()
+		@loggerName = "test"
+		@logger = @LoggingManager.initialize(@loggerName)
 		@logger.initializeErrorReporting("test_dsn")
 
-	it 'should report a single error to sentry', () ->
-		@logger.error {foo:'bar'}, "message"
-		@captureException.called.should.equal true
-
-	it 'should report the same error to sentry only once', () ->
-		error1 = new Error('this is the error')
-		@logger.error {foo: error1}, "first message"
-		@logger.error {bar: error1}, "second message"
-		@captureException.callCount.should.equal 1
-
-	it 'should report two different errors to sentry individually', () ->
-		error1 = new Error('this is the error')
-		error2 = new Error('this is the error')
-		@logger.error {foo: error1}, "first message"
-		@logger.error {bar: error2}, "second message"
-		@captureException.callCount.should.equal 2
-
-	it 'should remove the path from fs errors', () ->
-		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"
-		@logger.error {err: fsError}, "message"
-		@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', () ->
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@captureException.callCount.should.equal 5
-
-	it 'for multiple errors with a minute delay should report 10 errors to sentry', () ->
-		# the first five errors should be reported to sentry
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		# the following errors should not be reported
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		# allow a minute to pass
-		tk.travel(new Date(@start + 61*10000));
-		# after a minute the next five errors should be reported to sentry
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		# the following errors should not be reported to sentry
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@logger.error {foo:'bar'}, "message"
-		@captureException.callCount.should.equal 10
+	afterEach ->
+		@clock.restore()
+
+	describe 'initialize', ->
+		beforeEach ->
+			@LoggingManager.checkLogLevel = sinon.stub()
+			@Bunyan.createLogger.reset()
+
+		describe "not in production", ->
+			beforeEach ->
+				@LoggingManager.initialize()
+
+			it 'should default to log level debug', ->
+				@Bunyan.createLogger.should.have.been.calledWithMatch level: "debug"
+
+			it 'should not run checkLogLevel', ->
+				@LoggingManager.checkLogLevel.should.not.have.been.called
+
+		describe "in production", ->
+			beforeEach ->
+				process.env.NODE_ENV = 'production'
+				@LoggingManager.initialize()
+
+			afterEach ->
+				delete process.env.NODE_ENV
+
+			it 'should default to log level warn', ->
+				@Bunyan.createLogger.should.have.been.calledWithMatch level: "warn"
+
+			it 'should run checkLogLevel', ->
+				@LoggingManager.checkLogLevel.should.have.been.calledOnce
+
+			describe 'after 1 minute', ->
+				it 'should run checkLogLevel again', ->
+					@clock.tick(61*1000)
+					@LoggingManager.checkLogLevel.should.have.been.calledTwice
+
+			describe 'after 2 minutes', ->
+				it 'should run checkLogLevel again', ->
+					@clock.tick(121*1000)
+					@LoggingManager.checkLogLevel.should.have.been.calledThrice
+
+		describe "when LOG_LEVEL set in env", ->
+			beforeEach ->
+				process.env.LOG_LEVEL = "trace"
+				@LoggingManager.initialize()
+
+			afterEach ->
+				delete process.env.LOG_LEVEL
+
+			it "should use custom log level", ->
+				@Bunyan.createLogger.should.have.been.calledWithMatch level: "trace"
+
+	describe 'bunyan logging', ->
+		beforeEach ->
+			@logArgs = [ foo: "bar", "foo", "bar" ]
+
+		it 'should log debug', ->
+			@logger.debug @logArgs
+			@mockBunyanLogger.debug.should.have.been.calledWith @logArgs
+
+		it 'should log error', ->
+			@logger.error @logArgs
+			@mockBunyanLogger.error.should.have.been.calledWith @logArgs
+
+		it 'should log fatal', ->
+			@logger.fatal @logArgs
+			@mockBunyanLogger.fatal.should.have.been.calledWith @logArgs
+
+		it 'should log info', ->
+			@logger.info @logArgs
+			@mockBunyanLogger.info.should.have.been.calledWith @logArgs
+
+		it 'should log warn', ->
+			@logger.warn @logArgs
+			@mockBunyanLogger.warn.should.have.been.calledWith @logArgs
+
+		it 'should log err', ->
+			@logger.err @logArgs
+			@mockBunyanLogger.error.should.have.been.calledWith @logArgs
+
+		it 'should log log', ->
+			@logger.log @logArgs
+			@mockBunyanLogger.info.should.have.been.calledWith @logArgs
+
+	describe 'logger.error', ->
+		it 'should report a single error to sentry', () ->
+			@logger.error {foo:'bar'}, "message"
+			@captureException.called.should.equal true
+
+		it 'should report the same error to sentry only once', () ->
+			error1 = new Error('this is the error')
+			@logger.error {foo: error1}, "first message"
+			@logger.error {bar: error1}, "second message"
+			@captureException.callCount.should.equal 1
+
+		it 'should report two different errors to sentry individually', () ->
+			error1 = new Error('this is the error')
+			error2 = new Error('this is the error')
+			@logger.error {foo: error1}, "first message"
+			@logger.error {bar: error2}, "second message"
+			@captureException.callCount.should.equal 2
+
+		it 'should remove the path from fs errors', () ->
+			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"
+			@logger.error {err: fsError}, "message"
+			@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', () ->
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@captureException.callCount.should.equal 5
+
+		it 'for multiple errors with a minute delay should report 10 errors to sentry', () ->
+			# the first five errors should be reported to sentry
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			# the following errors should not be reported
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			# allow a minute to pass
+			@clock.tick(@start+ 61*1000)
+			# after a minute the next five errors should be reported to sentry
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			# the following errors should not be reported to sentry
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@logger.error {foo:'bar'}, "message"
+			@captureException.callCount.should.equal 10
+
+	describe 'checkLogLevel', ->
+		it 'should request log level override from google meta data service', ->
+			@LoggingManager.checkLogLevel()
+			options =
+				headers:
+					"Metadata-Flavor": "Google"
+				uri: "http://metadata.google.internal/computeMetadata/v1/project/attributes/#{@loggerName}-setLogLevelEndTime"
+			@Request.should.have.been.calledWithMatch options
+
+		describe 'when request has error', ->
+			beforeEach ->
+				@Request.yields "error"
+				@LoggingManager.checkLogLevel()
+
+			it "should only set default level", ->
+				@mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith('debug')
+
+		describe 'when statusCode is not 200', ->
+			beforeEach ->
+				@Request.yields null, statusCode: 404
+				@LoggingManager.checkLogLevel()
+
+			it "should only set default level", ->
+				@mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith('debug')
+
+		describe 'when time value returned that is less than current time', ->
+			beforeEach ->
+				@Request.yields null, statusCode: 200, '1'
+				@LoggingManager.checkLogLevel()
+
+			it "should only set default level", ->
+				@mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith('debug')
+
+		describe 'when time value returned that is less than current time', ->
+			describe 'when level is already set', ->
+				beforeEach ->
+					@mockBunyanLogger.level.returns(10)
+					@Request.yields null, statusCode: 200, @start + 1000
+					@LoggingManager.checkLogLevel()
+
+				it "should set trace level", ->
+					@mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith('trace')
+
+			describe 'when level is not already set', ->
+				beforeEach ->
+					@mockBunyanLogger.level.returns(20)
+					@Request.yields null, statusCode: 200, @start + 1000
+					@LoggingManager.checkLogLevel()
+
+				it "should set trace level", ->
+					@mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith('trace')