github/overleaf
1
0
Fork 0
mirror of https://github.com/overleaf/overleaf.git synced 2024-11-07 20:31:06 -05:00
Code Issues Projects Releases Packages Wiki Activity

Merge pull request #16 from overleaf/em-stackdriver

Browse source 
Add option to log to Stackdriver
This commit is contained in:
Eric Mc Sween 2019-10-28 08:32:15 -04:00 committed by GitHub
commit 7be3c208fd
5 changed files with 3273 additions and 118 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

6
libraries/logger/.eslintrc
View file

@ -19,12 +19,6 @@
"settings": {
},
"rules": {
"max-len": ["error", {
"ignoreUrls": true,
// Ignore long describe/it test blocks, long import/require statements
"ignorePattern": "(^\\s*(it|describe)\\s*\\(['\"]|^import\\s*.*\\s*from\\s*['\"]|^.*\\s*=\\s*require\\(['\"])"
}],
// Add some mocha specific rules
"mocha/handle-done-callback": "error",
"mocha/no-exclusive-tests": "error",

126
libraries/logger/logging-manager.js
View file

@ -1,11 +1,14 @@
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) {
if (!err || !err.stack)
return err;
const errSerializer = function(err) {
if (!err || !err.stack) {
return err
}
return {
message: err.message,
name: err.name,
@ -13,34 +16,16 @@ const errSerializer = function (err) {
info: OError.getFullInfo(err),
code: err.code,
signal: err.signal
};
};
}
}
const Logger = module.exports = {
const Logger = (module.exports = {
initialize(name) {
this.isProduction =
(process.env['NODE_ENV'] || '').toLowerCase() === 'production'
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
},
@ -69,9 +46,7 @@ const Logger = module.exports = {
headers: {
'Metadata-Flavor': 'Google'
},
uri: `http://metadata.google.internal/computeMetadata/v1/project/attributes/${
this.loggerName
}-setLogLevelEndTime`
uri: `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime`
}
request(options, (err, response, body) => {
if (err) {
@ -86,9 +61,9 @@ const Logger = module.exports = {
})
},
initializeErrorReporting(sentry_dsn, options) {
initializeErrorReporting(sentryDsn, options) {
const raven = require('raven')
this.raven = new raven.Client(sentry_dsn, options)
this.raven = new raven.Client(sentryDsn, options)
this.lastErrorTimeStamp = 0 // for rate limiting on sentry reporting
this.lastErrorCount = 0
},
@ -154,25 +129,21 @@ const Logger = module.exports = {
if (error.path) {
error.message = error.message.replace(` '${error.path}'`, '')
}
} catch (error1) {}
// send the error to sentry
try {
// send the error to sentry
this.raven.captureException(error, { tags, extra, level })
// put a flag on the errors to avoid reporting them multiple times
return (() => {
const result = []
for (key in attributes) {
value = attributes[key]
if (value instanceof Error) {
result.push((value.reportedToSentry = true))
} else {
result.push(undefined)
}
const result = []
for (key in attributes) {
value = attributes[key]
if (value instanceof Error) {
value.reportedToSentry = true
}
return result
})()
} catch (error2) {
return
}
} catch (err) {
// ignore Raven errors
}
}
},
@ -191,7 +162,7 @@ const Logger = module.exports = {
error(attributes, message, ...args) {
if (this.ringBuffer !== null && Array.isArray(this.ringBuffer.records)) {
attributes.logBuffer = this.ringBuffer.records.filter(function (record) {
attributes.logBuffer = this.ringBuffer.records.filter(function(record) {
return record.level !== 50
})
}
@ -244,7 +215,46 @@ 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)
}
}
}
})
Logger.initialize('default-sharelatex')

3114
libraries/logger/package-lock.json generated Normal file
View file

File diff suppressed because it is too large Load diff

9
libraries/logger/package.json
View file

@ -7,7 +7,7 @@
"url": "http://github.com/sharelatex/logger-sharelatex.git"
},
"license": "AGPL-3.0-only",
"version": "1.8.0",
"version": "1.9.0",
"scripts": {
"test": "mocha test/**/*.js",
"format": "prettier-eslint '**/*.js' --list-different",
@ -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",
@ -32,7 +34,8 @@
"eslint-plugin-node": "^6.0.0",
"eslint-plugin-promise": "^3.6.0",
"eslint-plugin-standard": "^3.0.1",
"mocha": "5.2.0",
"mocha": "^5.2.0",
"prettier": "^1.18.2",
"sandboxed-module": "2.0.3",
"sinon": "7.2.3",
"sinon-chai": "3.3.0"

136
libraries/logger/test/unit/loggingManagerTests.js
View file

@ -7,6 +7,7 @@ const sinonChai = require('sinon-chai')
chai.use(sinonChai)
chai.should()
const expect = chai.expect
const modulePath = path.join(__dirname, '../../logging-manager.js')
@ -15,7 +16,8 @@ describe('LoggingManager', function() {
this.start = Date.now()
this.clock = sinon.useFakeTimers(this.start)
this.captureException = sinon.stub()
this.mockBunyanLogger = {
this.bunyanLogger = {
addStream: sinon.stub(),
debug: sinon.stub(),
error: sinon.stub(),
fatal: sinon.stub(),
@ -23,25 +25,36 @@ describe('LoggingManager', function() {
level: sinon.stub(),
warn: sinon.stub()
}
this.mockRavenClient = {
this.ravenClient = {
captureException: this.captureException,
once: sinon.stub().yields()
}
this.Bunyan = {
createLogger: sinon.stub().returns(this.bunyanLogger),
RingBuffer: bunyan.RingBuffer,
stdSerializers: {
req: sinon.stub(),
res: sinon.stub()
}
}
this.Raven = {
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 = {
createLogger: sinon.stub().returns(this.mockBunyanLogger),
RingBuffer: bunyan.RingBuffer,
stdSerializers: {
req: sinon.stub(),
res: sinon.stub()
}
}),
raven: (this.Raven = {
Client: sinon.stub().returns(this.mockRavenClient)
}),
request: (this.Request = sinon.stub())
bunyan: this.Bunyan,
raven: this.Raven,
request: this.Request,
'@google-cloud/logging-bunyan': this.GCPLogging
}
})
this.loggerName = 'test'
@ -133,37 +146,37 @@ describe('LoggingManager', function() {
it('should log debug', function() {
this.logger.debug(this.logArgs)
this.mockBunyanLogger.debug.should.have.been.calledWith(this.logArgs)
this.bunyanLogger.debug.should.have.been.calledWith(this.logArgs)
})
it('should log error', function() {
this.logger.error(this.logArgs)
this.mockBunyanLogger.error.should.have.been.calledWith(this.logArgs)
this.bunyanLogger.error.should.have.been.calledWith(this.logArgs)
})
it('should log fatal', function() {
this.logger.fatal(this.logArgs)
this.mockBunyanLogger.fatal.should.have.been.calledWith(this.logArgs)
this.bunyanLogger.fatal.should.have.been.calledWith(this.logArgs)
})
it('should log info', function() {
this.logger.info(this.logArgs)
this.mockBunyanLogger.info.should.have.been.calledWith(this.logArgs)
this.bunyanLogger.info.should.have.been.calledWith(this.logArgs)
})
it('should log warn', function() {
this.logger.warn(this.logArgs)
this.mockBunyanLogger.warn.should.have.been.calledWith(this.logArgs)
this.bunyanLogger.warn.should.have.been.calledWith(this.logArgs)
})
it('should log err', function() {
this.logger.err(this.logArgs)
this.mockBunyanLogger.error.should.have.been.calledWith(this.logArgs)
this.bunyanLogger.error.should.have.been.calledWith(this.logArgs)
})
it('should log log', function() {
this.logger.log(this.logArgs)
this.mockBunyanLogger.info.should.have.been.calledWith(this.logArgs)
this.bunyanLogger.info.should.have.been.calledWith(this.logArgs)
})
})
@ -253,9 +266,7 @@ describe('LoggingManager', function() {
headers: {
'Metadata-Flavor': 'Google'
},
uri: `http://metadata.google.internal/computeMetadata/v1/project/attributes/${
this.loggerName
}-setLogLevelEndTime`
uri: `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime`
}
this.Request.should.have.been.calledWithMatch(options)
})
@ -267,7 +278,7 @@ describe('LoggingManager', function() {
})
it('should only set default level', function() {
this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith(
this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith(
'debug'
)
})
@ -280,7 +291,7 @@ describe('LoggingManager', function() {
})
it('should only set default level', function() {
this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith(
this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith(
'debug'
)
})
@ -293,22 +304,22 @@ describe('LoggingManager', function() {
})
it('should only set default level', function() {
this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith(
this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith(
'debug'
)
})
})
describe('when time value returned that is less than current time', function() {
describe('when time value returned that is more than current time', function() {
describe('when level is already set', function() {
beforeEach(function() {
this.mockBunyanLogger.level.returns(10)
this.bunyanLogger.level.returns(10)
this.Request.yields(null, { statusCode: 200 }, this.start + 1000)
this.logger.checkLogLevel()
})
it('should set trace level', function() {
this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith(
this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith(
'trace'
)
})
@ -316,13 +327,13 @@ describe('LoggingManager', function() {
describe('when level is not already set', function() {
beforeEach(function() {
this.mockBunyanLogger.level.returns(20)
this.bunyanLogger.level.returns(20)
this.Request.yields(null, { statusCode: 200 }, this.start + 1000)
this.logger.checkLogLevel()
})
it('should set trace level', function() {
this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith(
this.bunyanLogger.level.should.have.been.calledOnce.and.calledWith(
'trace'
)
})
@ -333,16 +344,9 @@ describe('LoggingManager', function() {
describe('ringbuffer', function() {
beforeEach(function() {
this.logBufferMock = [
{
msg: 'log 1'
},
{
msg: 'log 2'
},
{
level: 50,
msg: 'error'
}
{ msg: 'log 1' },
{ msg: 'log 2' },
{ level: 50, msg: 'error' }
]
})
@ -359,13 +363,9 @@ describe('LoggingManager', function() {
})
it('should include buffered logs in error log and filter out error logs in buffer', function() {
this.mockBunyanLogger.error.lastCall.args[0].logBuffer.should.deep.equal([
{
msg: 'log 1'
},
{
msg: 'log 2'
},
this.bunyanLogger.error.lastCall.args[0].logBuffer.should.deep.equal([
{ msg: 'log 1' },
{ msg: 'log 2' }
])
})
})
@ -382,8 +382,42 @@ describe('LoggingManager', function() {
})
it('should not include buffered logs in error log', function() {
chai.expect(this.mockBunyanLogger.error.lastCall.args[0].logBuffer).be
.undefined
expect(this.bunyanLogger.error.lastCall.args[0].logBuffer).be.undefined
})
})
})
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 }
})
})
})
})