From cb300b79eac60ec39f4a942ca91e88828d55d7f7 Mon Sep 17 00:00:00 2001 From: Eric Mc Sween Date: Thu, 24 Oct 2019 16:41:46 -0400 Subject: [PATCH] Add option to log to Stackdriver When the environment variable STACKDRIVER_LOGGING is set to true, logs are sent to Stackdriver in addition to stdout. --- libraries/logger/logging-manager.js | 74 +++++++++++-------- libraries/logger/package.json | 4 +- .../logger/test/unit/loggingManagerTests.js | 46 +++++++++++- 3 files changed, 93 insertions(+), 31 deletions(-) diff --git a/libraries/logger/logging-manager.js b/libraries/logger/logging-manager.js index 541d612137..f840771a8e 100644 --- a/libraries/logger/logging-manager.js +++ b/libraries/logger/logging-manager.js @@ -1,6 +1,8 @@ const bunyan = require('bunyan') const request = require('request') +const yn = require('yn') const OError = require('@overleaf/o-error') +const GCPLogging = require('@google-cloud/logging-bunyan') // bunyan error serializer const errSerializer = function(err) { @@ -24,23 +26,6 @@ const Logger = (module.exports = { this.defaultLevel = process.env['LOG_LEVEL'] || (this.isProduction ? 'warn' : 'debug') this.loggerName = name - this.ringBufferSize = parseInt(process.env['LOG_RING_BUFFER_SIZE']) || 0 - const loggerStreams = [ - { - level: this.defaultLevel, - stream: process.stdout - } - ] - if (this.ringBufferSize > 0) { - this.ringBuffer = new bunyan.RingBuffer({ limit: this.ringBufferSize }) - loggerStreams.push({ - level: 'trace', - type: 'raw', - stream: this.ringBuffer - }) - } else { - this.ringBuffer = null - } this.logger = bunyan.createLogger({ name, serializers: { @@ -48,19 +33,11 @@ const Logger = (module.exports = { req: bunyan.stdSerializers.req, res: bunyan.stdSerializers.res }, - streams: loggerStreams + streams: [{ level: this.defaultLevel, stream: process.stdout }] }) - if (this.isProduction) { - // clear interval if already set - if (this.checkInterval) { - clearInterval(this.checkInterval) - } - // check for log level override on startup - this.checkLogLevel() - // re-check log level every minute - const checkLogLevel = () => this.checkLogLevel() - this.checkInterval = setInterval(checkLogLevel, 1000 * 60) - } + this._setupRingBuffer() + this._setupStackdriver() + this._setupLogLevelChecker() return this }, @@ -238,6 +215,45 @@ const Logger = (module.exports = { } else { return callback() } + }, + + _setupRingBuffer() { + this.ringBufferSize = parseInt(process.env['LOG_RING_BUFFER_SIZE']) || 0 + if (this.ringBufferSize > 0) { + this.ringBuffer = new bunyan.RingBuffer({ limit: this.ringBufferSize }) + this.logger.addStream({ + level: 'trace', + type: 'raw', + stream: this.ringBuffer + }) + } else { + this.ringBuffer = null + } + }, + + _setupStackdriver() { + const stackdriverEnabled = yn(process.env['STACKDRIVER_LOGGING']) + if (!stackdriverEnabled) { + return + } + const stackdriverClient = new GCPLogging.LoggingBunyan({ + logName: this.loggerName, + serviceContext: { service: this.loggerName } + }) + this.logger.addStream(stackdriverClient.stream(this.defaultLevel)) + }, + + _setupLogLevelChecker() { + if (this.isProduction) { + // clear interval if already set + 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) + } } }) diff --git a/libraries/logger/package.json b/libraries/logger/package.json index 09515adc53..ba27b8848f 100644 --- a/libraries/logger/package.json +++ b/libraries/logger/package.json @@ -15,10 +15,12 @@ "lint": "eslint -f unix ." }, "dependencies": { + "@google-cloud/logging-bunyan": "^2.0.0", "@overleaf/o-error": "^2.0.0", "bunyan": "1.8.12", "raven": "1.1.3", - "request": "2.88.0" + "request": "2.88.0", + "yn": "^3.1.1" }, "devDependencies": { "chai": "4.2.0", diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index 4a55717ec6..f94d92f9cf 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -17,6 +17,7 @@ describe('LoggingManager', function() { this.clock = sinon.useFakeTimers(this.start) this.captureException = sinon.stub() this.bunyanLogger = { + addStream: sinon.stub(), debug: sinon.stub(), error: sinon.stub(), fatal: sinon.stub(), @@ -40,12 +41,20 @@ describe('LoggingManager', function() { Client: sinon.stub().returns(this.ravenClient) } this.Request = 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, - request: this.Request + request: this.Request, + '@google-cloud/logging-bunyan': this.GCPLogging } }) this.loggerName = 'test' @@ -377,4 +386,39 @@ describe('LoggingManager', function() { }) }) }) + + describe('stackdriver logging', function() { + describe('when STACKDRIVER_LOGGING is unset', function() { + beforeEach(function() { + process.env['STACKDRIVER_LOGGING'] = undefined + this.LoggingManager.initialize(this.loggerName) + }) + + it('is disabled', function() { + expect(this.bunyanLogger.addStream).not.to.have.been.calledWith( + this.stackdriverStreamConfig + ) + }) + }) + + describe('when STACKDRIVER_LOGGING is true', function() { + beforeEach(function() { + process.env['STACKDRIVER_LOGGING'] = 'true' + this.LoggingManager.initialize(this.loggerName) + }) + + it('is enabled', function() { + expect(this.bunyanLogger.addStream).to.have.been.calledWith( + this.stackdriverStreamConfig + ) + }) + + it('is configured properly', function() { + expect(this.GCPLogging.LoggingBunyan).to.have.been.calledWith({ + logName: this.loggerName, + serviceContext: { service: this.loggerName } + }) + }) + }) + }) })