From 83597e8723d474812a24bf2592e00c04ff8e5367 Mon Sep 17 00:00:00 2001 From: Ersun Warncke Date: Fri, 8 Mar 2019 10:09:44 -0400 Subject: [PATCH] use ring buffer for logging and include with error --- libraries/logger/index.js | 2 +- .../loggingManagerTests.coffee | 234 ------- libraries/logger/logging-manager.js | 417 +++++++------ libraries/logger/package-lock.json | 99 ++- libraries/logger/package.json | 16 +- .../logger/test/unit/loggingManagerTests.js | 571 ++++++++++-------- 6 files changed, 615 insertions(+), 724 deletions(-) delete mode 100644 libraries/logger/logger-tests-coffee/loggingManagerTests.coffee diff --git a/libraries/logger/index.js b/libraries/logger/index.js index b8877921d5..aeca420019 100755 --- a/libraries/logger/index.js +++ b/libraries/logger/index.js @@ -1 +1 @@ -module.exports = require('./logging-manager.js'); +module.exports = require("./logging-manager.js"); diff --git a/libraries/logger/logger-tests-coffee/loggingManagerTests.coffee b/libraries/logger/logger-tests-coffee/loggingManagerTests.coffee deleted file mode 100644 index 04dd848c25..0000000000 --- a/libraries/logger/logger-tests-coffee/loggingManagerTests.coffee +++ /dev/null @@ -1,234 +0,0 @@ -SandboxedModule = require("sandboxed-module") -chai = require("chai") -path = require("path") -sinon = require("sinon") -sinonChai = require("sinon-chai") - -chai.use(sinonChai) -chai.should() - -modulePath = path.join __dirname, '../../../logging-manager.coffee' - -describe 'LoggingManager', -> - - beforeEach -> - @start = Date.now() - @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: @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") - - 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') diff --git a/libraries/logger/logging-manager.js b/libraries/logger/logging-manager.js index f57ce9ca9d..d791844204 100644 --- a/libraries/logger/logging-manager.js +++ b/libraries/logger/logging-manager.js @@ -1,221 +1,220 @@ -/* - * decaffeinate suggestions: - * DS101: Remove unnecessary use of Array.from - * DS102: Remove unnecessary code created because of implicit returns - * DS203: Remove `|| {}` from converted for-own loops - * DS205: Consider reworking code to avoid use of IIFEs - * DS207: Consider shorter variations of null checks - * Full docs: https://github.com/decaffeinate/decaffeinate/blob/master/docs/suggestions.md - */ +const bunyan = require("bunyan"); +const request = require("request"); -const bunyan = require('bunyan'); -const request = require('request'); +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.ringBuffer = new bunyan.RingBuffer({ + limit: process.env["LOG_RING_BUFFER_SIZE"] || 30 + }); + this.logger = bunyan.createLogger({ + name, + serializers: bunyan.stdSerializers, + streams: [ + { + level: this.defaultLevel, + stream: process.stdout + }, + { + level: "trace", + type: "raw", + stream: this.ringBuffer + } + ] + }); + 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); + } + return this; + }, -const LOG_METHODS = [ - 'debug', 'info', 'log', 'error', 'err', 'warn', 'fatal' -] + checkLogLevel() { + const options = { + headers: { + "Metadata-Flavor": "Google" + }, + uri: `http://metadata.google.internal/computeMetadata/v1/project/attributes/${ + this.loggerName + }-setLogLevelEndTime` + }; + request(options, (err, response, body) => { + if (parseInt(body) > Date.now()) { + this.logger.level("trace"); + } else { + this.logger.level(this.defaultLevel); + } + }); + }, -class Logger { + initializeErrorReporting(sentry_dsn, options) { + const raven = require("raven"); + this.raven = new raven.Client(sentry_dsn, options); + this.lastErrorTimeStamp = 0; // for rate limiting on sentry reporting + this.lastErrorCount = 0; + }, - constructor(name) { - const isProduction = (process.env['NODE_ENV'] || '').toLowerCase() === 'production'; - this.defaultLevel = process.env['LOG_LEVEL'] || (isProduction ? "warn" : "debug"); - this.loggerName = name; - this.logger = bunyan.createLogger({ - name, - serializers: bunyan.stdSerializers, - level: this.defaultLevel - }); - if (isProduction) { - // check for log level override on startup - this.checkLogLevel(); - // re-check log level every minute - const checkLogLevel = () => this.checkLogLevel(); - setInterval(checkLogLevel, 1000 * 60); - } - return this; - } + captureException(attributes, message, level) { + // handle case of logger.error "message" + let key, value; + if (typeof attributes === "string") { + attributes = { err: new Error(attributes) }; + } + // extract any error object + let error = attributes.err || attributes.error; + // avoid reporting errors twice + for (key in attributes) { + value = attributes[key]; + if (value instanceof Error && value.reportedToSentry) { + return; + } + } + // include our log message in the error report + if (error == null) { + if (typeof message === "string") { + error = { message }; + } + } else if (message != null) { + attributes.description = message; + } + // report the error + if (error != null) { + // capture attributes and use *_id objects as tags + const tags = {}; + const extra = {}; + for (key in attributes) { + value = attributes[key]; + if (key.match(/_id/) && typeof value === "string") { + tags[key] = value; + } + extra[key] = value; + } + // capture req object if available + const { req } = attributes; + if (req != null) { + extra.req = { + method: req.method, + url: req.originalUrl, + query: req.query, + headers: req.headers, + ip: req.ip + }; + } + // recreate error objects that have been converted to a normal object + if (!(error instanceof Error) && typeof error === "object") { + const newError = new Error(error.message); + for (key of Object.keys(error || {})) { + value = error[key]; + newError[key] = value; + } + error = newError; + } + // filter paths from the message to avoid duplicate errors in sentry + // (e.g. errors from `fs` methods which have a path attribute) + try { + if (error.path) { + error.message = error.message.replace(` '${error.path}'`, ""); + } + } catch (error1) {} + // send the error to sentry + try { + 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); + } + } + return result; + })(); + } catch (error2) { + return; + } + } + }, - checkLogLevel() { - const options = { - headers: { - "Metadata-Flavor": "Google" - }, - uri: `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` - }; - return request(options, (err, response, body) => { - if (parseInt(body) > Date.now()) { - return this.logger.level('trace'); - } else { - return this.logger.level(this.defaultLevel); - } - }); - } + debug() { + return this.logger.debug.apply(this.logger, arguments); + }, - initializeErrorReporting(sentry_dsn, options) { - const raven = require("raven"); - this.raven = new raven.Client(sentry_dsn, options); - this.lastErrorTimeStamp = 0; // for rate limiting on sentry reporting - return this.lastErrorCount = 0; - } + info() { + return this.logger.info.apply(this.logger, arguments); + }, - captureException(attributes, message, level) { - // handle case of logger.error "message" - let key, value; - if (typeof attributes === 'string') { - attributes = {err: new Error(attributes)}; - } - // extract any error object - let error = attributes.err || attributes.error; - // avoid reporting errors twice - for (key in attributes) { - value = attributes[key]; - if (value instanceof Error && value.reportedToSentry) { return; } - } - // include our log message in the error report - if ((error == null)) { - if (typeof message === 'string') { error = {message}; } - } else if (message != null) { - attributes.description = message; - } - // report the error - if (error != null) { - // capture attributes and use *_id objects as tags - const tags = {}; - const extra = {}; - for (key in attributes) { - value = attributes[key]; - if (key.match(/_id/) && (typeof value === 'string')) { tags[key] = value; } - extra[key] = value; - } - // capture req object if available - const { req } = attributes; - if (req != null) { - extra.req = { - method: req.method, - url: req.originalUrl, - query: req.query, - headers: req.headers, - ip: req.ip - }; - } - // recreate error objects that have been converted to a normal object - if (!(error instanceof Error) && (typeof error === "object")) { - const newError = new Error(error.message); - for (key of Object.keys(error || {})) { - value = error[key]; - newError[key] = value; - } - error = newError; - } - // filter paths from the message to avoid duplicate errors in sentry - // (e.g. errors from `fs` methods which have a path attribute) - try { - if (error.path) { error.message = error.message.replace(` '${error.path}'`, ''); } - } catch (error1) {} - // send the error to sentry - try { - 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); - } - } - return result; - })(); - } catch (error2) { - return; - } - } - } + log() { + return this.logger.info.apply(this.logger, arguments); + }, - debug() { - return this.logger.debug.apply(this.logger, arguments); - } + error(attributes, message, ...args) { + if (this.isProduction) { + attributes.logBuffer = this.ringBuffer.records; + } + this.logger.error(attributes, message, ...Array.from(args)); + if (this.raven != null) { + const MAX_ERRORS = 5; // maximum number of errors in 1 minute + const now = new Date(); + // have we recently reported an error? + const recentSentryReport = now - this.lastErrorTimeStamp < 60 * 1000; + // if so, increment the error count + if (recentSentryReport) { + this.lastErrorCount++; + } else { + this.lastErrorCount = 0; + this.lastErrorTimeStamp = now; + } + // only report 5 errors every minute to avoid overload + if (this.lastErrorCount < MAX_ERRORS) { + // add a note if the rate limit has been hit + const note = + this.lastErrorCount + 1 === MAX_ERRORS ? "(rate limited)" : ""; + // report the exception + return this.captureException(attributes, message, `error${note}`); + } + } + }, - info(){ - return this.logger.info.apply(this.logger, arguments); - } + err() { + return this.error.apply(this, arguments); + }, - log(){ - return this.logger.info.apply(this.logger, arguments); - } + warn() { + return this.logger.warn.apply(this.logger, arguments); + }, - error(attributes, message, ...args){ - this.logger.error(attributes, message, ...Array.from(args)); - if (this.raven != null) { - const MAX_ERRORS = 5; // maximum number of errors in 1 minute - const now = new Date(); - // have we recently reported an error? - const recentSentryReport = (now - this.lastErrorTimeStamp) < (60 * 1000); - // if so, increment the error count - if (recentSentryReport) { - this.lastErrorCount++; - } else { - this.lastErrorCount = 0; - this.lastErrorTimeStamp = now; - } - // only report 5 errors every minute to avoid overload - if (this.lastErrorCount < MAX_ERRORS) { - // add a note if the rate limit has been hit - const note = (this.lastErrorCount+1) === MAX_ERRORS ? "(rate limited)" : ""; - // report the exception - return this.captureException(attributes, message, `error${note}`); - } - } - } + fatal(attributes, message, callback) { + if (callback == null) { + callback = function() {}; + } + this.logger.fatal(attributes, message); + if (this.raven != null) { + var cb = function(e) { + // call the callback once after 'logged' or 'error' event + callback(); + return (cb = function() {}); + }; + this.captureException(attributes, message, "fatal"); + this.raven.once("logged", cb); + return this.raven.once("error", cb); + } else { + return callback(); + } + } +}; - err() { - return this.error.apply(this, arguments); - } - - warn(){ - return this.logger.warn.apply(this.logger, arguments); - } - - fatal(attributes, message, callback) { - if (callback == null) { callback = function() {}; } - this.logger.fatal(attributes, message); - if (this.raven != null) { - var cb = function(e) { // call the callback once after 'logged' or 'error' event - callback(); - return cb = function() {}; - }; - this.captureException(attributes, message, "fatal"); - this.raven.once('logged', cb); - return this.raven.once('error', cb); - } else { - return callback(); - } - } -} - -let defaultLogger -// initialize default logger if not already initialized -if (!global.__logger_sharelatex__default_logger__) { - global.__logger_sharelatex__default_logger__ = defaultLogger = new Logger("default-sharelatex") -} -else { - defaultLogger = global.__logger_sharelatex__default_logger__ -} - -// support old interface for creating new Logger instances -Logger.initialize = function initialize(name) { - return new Logger(name) -} -// add a static method for each log method that will use the default logger -for (const logMethod of LOG_METHODS) { - Logger[logMethod] = function () { - return defaultLogger[logMethod].apply(defaultLogger, arguments) - } -} -// return default logger -Logger.defaultLogger = function defaultLogger () { - return defaultLogger -} - -module.exports = Logger +Logger.initialize("default-sharelatex"); diff --git a/libraries/logger/package-lock.json b/libraries/logger/package-lock.json index 2a3b42cf20..c76f298483 100644 --- a/libraries/logger/package-lock.json +++ b/libraries/logger/package-lock.json @@ -76,6 +76,14 @@ "integrity": "sha512-jgsaNduz+ndvGyFt3uSuWqvy4lCnIJiovtouQN5JZHOKCS2QuhEdbcQHFhVksz2N2U9hXJo8odG7ETyWlEeuDw==", "dev": true }, + "async-hook-jl": { + "version": "1.7.6", + "resolved": "https://registry.npmjs.org/async-hook-jl/-/async-hook-jl-1.7.6.tgz", + "integrity": "sha512-gFaHkFfSxTjvoxDMYqDuGHlcRyUuamF8s+ZTtJdDzqjws4mCt7v0vuV79/E2Wr2/riMQgtG4/yUtXWs1gZ7JMg==", + "requires": { + "stack-chain": "^1.3.7" + } + }, "asynckit": { "version": "0.4.0", "resolved": "https://registry.npmjs.org/asynckit/-/asynckit-0.4.0.tgz", @@ -120,11 +128,12 @@ "dev": true }, "bunyan": { - "version": "1.5.1", - "resolved": "https://registry.npmjs.org/bunyan/-/bunyan-1.5.1.tgz", - "integrity": "sha1-X259RMQ7lS9WsPQTCeOrEjkbTi0=", + "version": "1.8.12", + "resolved": "https://registry.npmjs.org/bunyan/-/bunyan-1.8.12.tgz", + "integrity": "sha1-8VDw9nSKvdcq6uhPBEA74u8RN5c=", "requires": { - "dtrace-provider": "~0.6", + "dtrace-provider": "~0.8", + "moment": "^2.10.6", "mv": "~2", "safe-json-stringify": "~1" } @@ -154,6 +163,16 @@ "integrity": "sha1-V00xLt2Iu13YkS6Sht1sCu1KrII=", "dev": true }, + "cls-hooked": { + "version": "4.2.2", + "resolved": "https://registry.npmjs.org/cls-hooked/-/cls-hooked-4.2.2.tgz", + "integrity": "sha512-J4Xj5f5wq/4jAvcdgoGsL3G103BtWpZrMo8NEinRltN+xpTZdI+M38pyQqhuFU/P792xkMFvnKSf+Lm81U1bxw==", + "requires": { + "async-hook-jl": "^1.7.6", + "emitter-listener": "^1.0.1", + "semver": "^5.4.1" + } + }, "combined-stream": { "version": "1.0.7", "resolved": "https://registry.npmjs.org/combined-stream/-/combined-stream-1.0.7.tgz", @@ -221,12 +240,12 @@ "dev": true }, "dtrace-provider": { - "version": "0.6.0", - "resolved": "https://registry.npmjs.org/dtrace-provider/-/dtrace-provider-0.6.0.tgz", - "integrity": "sha1-CweNVReTfYcxAUUtkUZzdVe3XlE=", + "version": "0.8.7", + "resolved": "https://registry.npmjs.org/dtrace-provider/-/dtrace-provider-0.8.7.tgz", + "integrity": "sha1-3JObTT4GIM/gwc2APQ0tftBP/QQ=", "optional": true, "requires": { - "nan": "^2.0.8" + "nan": "^2.10.0" } }, "ecc-jsbn": { @@ -238,6 +257,14 @@ "safer-buffer": "^2.1.0" } }, + "emitter-listener": { + "version": "1.1.2", + "resolved": "https://registry.npmjs.org/emitter-listener/-/emitter-listener-1.1.2.tgz", + "integrity": "sha512-Bt1sBAGFHY9DKY+4/2cV6izcKJUf5T7/gkdmkxzX/qv9CcGH8xSwVRW5mtX03SWJtRTWSOpzCuWN9rBFYZepZQ==", + "requires": { + "shimmer": "^1.2.0" + } + }, "escape-string-regexp": { "version": "1.0.5", "resolved": "https://registry.npmjs.org/escape-string-regexp/-/escape-string-regexp-1.0.5.tgz", @@ -507,6 +534,12 @@ } } }, + "moment": { + "version": "2.24.0", + "resolved": "https://registry.npmjs.org/moment/-/moment-2.24.0.tgz", + "integrity": "sha512-bV7f+6l2QigeBBZSM/6yTNq4P2fNpSWj/0e7jQcy87A8e7o2nAfP/34/2ky5Vw4B9S446EtIhodAzkFCcR4dQg==", + "optional": true + }, "ms": { "version": "2.0.0", "resolved": "https://registry.npmjs.org/ms/-/ms-2.0.0.tgz", @@ -611,15 +644,22 @@ "integrity": "sha512-N5ZAX4/LxJmF+7wN74pUD6qAh9/wnvdQcjq9TZjevvXzSUo7bfmw91saqMjzGS2xq91/odN2dW/WOl7qQHNDGA==" }, "raven": { - "version": "1.2.1", - "resolved": "https://registry.npmjs.org/raven/-/raven-1.2.1.tgz", - "integrity": "sha1-lJwTTbAooZC3u/j3kKrlQbfAIL0=", + "version": "1.1.3", + "resolved": "https://registry.npmjs.org/raven/-/raven-1.1.3.tgz", + "integrity": "sha1-QnPBrm005CMPUbLAEEGjK5Iygio=", "requires": { "cookie": "0.3.1", "json-stringify-safe": "5.0.1", "lsmod": "1.0.0", "stack-trace": "0.0.9", "uuid": "3.0.0" + }, + "dependencies": { + "uuid": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/uuid/-/uuid-3.0.0.tgz", + "integrity": "sha1-Zyj8BFnEUNeWqZwxg3VpvfZy1yg=" + } } }, "request": { @@ -697,18 +737,28 @@ "stack-trace": "0.0.9" } }, + "semver": { + "version": "5.6.0", + "resolved": "https://registry.npmjs.org/semver/-/semver-5.6.0.tgz", + "integrity": "sha512-RS9R6R35NYgQn++fkDWaOmqGoj4Ek9gGs+DPxNUZKuwE183xjJroKvyo1IzVFeXvUrvmALy6FWD5xrdJT25gMg==" + }, + "shimmer": { + "version": "1.2.1", + "resolved": "https://registry.npmjs.org/shimmer/-/shimmer-1.2.1.tgz", + "integrity": "sha512-sQTKC1Re/rM6XyFM6fIAGHRPVGvyXfgzIDvzoq608vM+jeyVD0Tu1E6Np0Kc2zAIFWIj963V2800iF/9LPieQw==" + }, "sinon": { - "version": "7.2.7", - "resolved": "https://registry.npmjs.org/sinon/-/sinon-7.2.7.tgz", - "integrity": "sha512-rlrre9F80pIQr3M36gOdoCEWzFAMDgHYD8+tocqOw+Zw9OZ8F84a80Ds69eZfcjnzDqqG88ulFld0oin/6rG/g==", + "version": "7.2.3", + "resolved": "https://registry.npmjs.org/sinon/-/sinon-7.2.3.tgz", + "integrity": "sha512-i6j7sqcLEqTYqUcMV327waI745VASvYuSuQMCjbAwlpAeuCgKZ3LtrjDxAbu+GjNQR0FEDpywtwGCIh8GicNyg==", "dev": true, "requires": { - "@sinonjs/commons": "^1.3.1", - "@sinonjs/formatio": "^3.2.1", - "@sinonjs/samsam": "^3.2.0", + "@sinonjs/commons": "^1.3.0", + "@sinonjs/formatio": "^3.1.0", + "@sinonjs/samsam": "^3.0.2", "diff": "^3.5.0", - "lolex": "^3.1.0", - "nise": "^1.4.10", + "lolex": "^3.0.0", + "nise": "^1.4.8", "supports-color": "^5.5.0" }, "dependencies": { @@ -745,6 +795,11 @@ "tweetnacl": "~0.14.0" } }, + "stack-chain": { + "version": "1.3.7", + "resolved": "https://registry.npmjs.org/stack-chain/-/stack-chain-1.3.7.tgz", + "integrity": "sha1-0ZLJ/06moiyUxN1FkXHj8AzqEoU=" + }, "stack-trace": { "version": "0.0.9", "resolved": "https://registry.npmjs.org/stack-trace/-/stack-trace-0.0.9.tgz", @@ -803,9 +858,9 @@ } }, "uuid": { - "version": "3.0.0", - "resolved": "https://registry.npmjs.org/uuid/-/uuid-3.0.0.tgz", - "integrity": "sha1-Zyj8BFnEUNeWqZwxg3VpvfZy1yg=" + "version": "3.3.2", + "resolved": "https://registry.npmjs.org/uuid/-/uuid-3.3.2.tgz", + "integrity": "sha512-yXJmeNaw3DnnKAOKJE51sL/ZaYfWJRl1pK9dr19YFCu0ObS231AB1/LbqTKRAQ5kw8A90rA6fr4riOUpTZvQZA==" }, "verror": { "version": "1.10.0", diff --git a/libraries/logger/package.json b/libraries/logger/package.json index cd6b0ac64e..692ba2b815 100644 --- a/libraries/logger/package.json +++ b/libraries/logger/package.json @@ -6,20 +6,20 @@ "type": "git", "url": "http://github.com/sharelatex/logger-sharelatex.git" }, - "version": "1.6.0", + "version": "1.7.0", "scripts": { "test": "mocha test/**/*.js" }, "dependencies": { - "bunyan": "1.5.1", - "raven": "^1.1.3", - "request": "^2.88.0" + "bunyan": "1.8.12", + "raven": "1.1.3", + "request": "2.88.0" }, "devDependencies": { - "chai": "^4.2.0", - "mocha": "^5.2.0", + "chai": "4.2.0", + "mocha": "5.2.0", "sandboxed-module": "2.0.3", - "sinon": "^7.2.3", - "sinon-chai": "^3.3.0" + "sinon": "7.2.3", + "sinon-chai": "3.3.0" } } diff --git a/libraries/logger/test/unit/loggingManagerTests.js b/libraries/logger/test/unit/loggingManagerTests.js index a808ac5f2c..a1f505d258 100644 --- a/libraries/logger/test/unit/loggingManagerTests.js +++ b/libraries/logger/test/unit/loggingManagerTests.js @@ -1,9 +1,5 @@ -/* - * decaffeinate suggestions: - * DS102: Remove unnecessary code created because of implicit returns - * Full docs: https://github.com/decaffeinate/decaffeinate/blob/master/docs/suggestions.md - */ const SandboxedModule = require("sandboxed-module"); +const bunyan = require("bunyan"); const chai = require("chai"); const path = require("path"); const sinon = require("sinon"); @@ -12,291 +8,366 @@ const sinonChai = require("sinon-chai"); chai.use(sinonChai); chai.should(); -const modulePath = path.join(__dirname, '../../logging-manager.js'); +const modulePath = path.join(__dirname, "../../logging-manager.js"); -describe('LoggingManager', function() { +describe("LoggingManager", function() { + beforeEach(function() { + this.start = Date.now(); + this.clock = sinon.useFakeTimers(this.start); + this.captureException = sinon.stub(); + this.mockBunyanLogger = { + debug: sinon.stub(), + error: sinon.stub(), + fatal: sinon.stub(), + info: sinon.stub(), + level: sinon.stub(), + warn: sinon.stub() + }; + this.mockRavenClient = { + captureException: this.captureException, + once: sinon.stub().yields() + }; + this.LoggingManager = SandboxedModule.require(modulePath, { + globals: { console }, + requires: { + bunyan: (this.Bunyan = { + createLogger: sinon.stub().returns(this.mockBunyanLogger), + RingBuffer: bunyan.RingBuffer + }), + raven: (this.Raven = { + Client: sinon.stub().returns(this.mockRavenClient) + }), + request: (this.Request = sinon.stub()) + } + }); + this.loggerName = "test"; + this.logger = this.LoggingManager.initialize(this.loggerName); + this.logger.initializeErrorReporting("test_dsn"); + }); - beforeEach(function() { - this.start = Date.now(); - this.clock = sinon.useFakeTimers(this.start); - this.captureException = sinon.stub(); - this.mockBunyanLogger = { - debug: sinon.stub(), - error: sinon.stub(), - fatal: sinon.stub(), - info: sinon.stub(), - level: sinon.stub(), - warn: sinon.stub() - }; - this.mockRavenClient = { - captureException: this.captureException, - once: sinon.stub().yields() - }; - this.LoggingManager = SandboxedModule.require(modulePath, { - globals: { console }, - requires: { - bunyan: (this.Bunyan = {createLogger: sinon.stub().returns(this.mockBunyanLogger)}), - raven: (this.Raven = {Client: sinon.stub().returns(this.mockRavenClient)}), - request: (this.Request = sinon.stub()), - }, - }); - this.loggerName = "test"; - this.logger = this.LoggingManager.initialize(this.loggerName); - this.logger.initializeErrorReporting("test_dsn"); - }); + afterEach(function() { + this.clock.restore(); + }); - afterEach(function() { - this.clock.restore(); - }); + describe("initialize", function() { + beforeEach(function() { + this.checkLogLevelStub = sinon.stub(this.LoggingManager, "checkLogLevel"); + this.Bunyan.createLogger.reset(); + }); - describe('initialize', function() { - beforeEach(function() { - this.checkLogLevelStub = sinon.stub(this.LoggingManager.prototype, "checkLogLevel"); - this.Bunyan.createLogger.reset(); - }); + afterEach(function() { + this.checkLogLevelStub.restore(); + }); - afterEach(function () { - this.checkLogLevelStub.restore() - }) + describe("not in production", function() { + beforeEach(function() { + this.logger = this.LoggingManager.initialize(this.loggerName); + }); - describe("not in production", function() { - beforeEach(function() { - this.logger = this.LoggingManager.initialize(this.loggerName) - }); + it("should default to log level debug", function() { + this.Bunyan.createLogger.firstCall.args[0].streams[0].level.should.equal( + "debug" + ); + }); - it('should default to log level debug', function() { - this.Bunyan.createLogger.should.have.been.calledWithMatch({level: "debug"}); - }); + it("should not run checkLogLevel", function() { + this.checkLogLevelStub.should.not.have.been.called; + }); + }); - it('should not run checkLogLevel', function() { - this.checkLogLevelStub.should.not.have.been.called; - }); - }); + describe("in production", function() { + beforeEach(function() { + process.env.NODE_ENV = "production"; + this.logger = this.LoggingManager.initialize(this.loggerName); + }); - describe("in production", function() { - beforeEach(function() { - process.env.NODE_ENV = 'production'; - this.logger = this.LoggingManager.initialize(this.loggerName) - }); + afterEach(() => delete process.env.NODE_ENV); - afterEach(() => delete process.env.NODE_ENV); + it("should default to log level warn", function() { + this.Bunyan.createLogger.firstCall.args[0].streams[0].level.should.equal( + "warn" + ); + }); - it('should default to log level warn', function() { - this.Bunyan.createLogger.should.have.been.calledWithMatch({level: "warn"}); - }); + it("should run checkLogLevel", function() { + this.checkLogLevelStub.should.have.been.calledOnce; + }); - 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 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 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"; + this.LoggingManager.initialize(); + }); - describe("when LOG_LEVEL set in env", function() { - beforeEach(function() { - process.env.LOG_LEVEL = "trace"; - this.LoggingManager.initialize(); - }); + afterEach(() => delete process.env.LOG_LEVEL); - afterEach(() => delete process.env.LOG_LEVEL); + it("should use custom log level", function() { + this.Bunyan.createLogger.firstCall.args[0].streams[0].level.should.equal( + "trace" + ); + }); + }); + }); - it("should use custom log level", function() { - this.Bunyan.createLogger.should.have.been.calledWithMatch({level: "trace"}); - }); - }); - }); + describe("bunyan logging", function() { + beforeEach(function() { + this.logArgs = [{ foo: "bar" }, "foo", "bar"]; + }); - describe('bunyan logging', function() { - beforeEach(function() { - this.logArgs = [ {foo: "bar"}, "foo", "bar" ];}); + it("should log debug", function() { + this.logger.debug(this.logArgs); + this.mockBunyanLogger.debug.should.have.been.calledWith(this.logArgs); + }); - it('should log debug', function() { - this.logger.debug(this.logArgs); - this.mockBunyanLogger.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); + }); - it('should log error', function() { - this.logger.error(this.logArgs); - this.mockBunyanLogger.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); + }); - it('should log fatal', function() { - this.logger.fatal(this.logArgs); - this.mockBunyanLogger.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); + }); - it('should log info', function() { - this.logger.info(this.logArgs); - this.mockBunyanLogger.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); + }); - it('should log warn', function() { - this.logger.warn(this.logArgs); - this.mockBunyanLogger.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); + }); - it('should log err', function() { - this.logger.err(this.logArgs); - this.mockBunyanLogger.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); + }); + }); - it('should log log', function() { - this.logger.log(this.logArgs); - this.mockBunyanLogger.info.should.have.been.calledWith(this.logArgs); - }); - }); + describe("logger.error", function() { + it("should report a single error to sentry", function() { + this.logger.error({ foo: "bar" }, "message"); + this.captureException.called.should.equal(true); + }); - describe('logger.error', function() { - it('should report a single error to sentry', function() { - this.logger.error({foo:'bar'}, "message"); - this.captureException.called.should.equal(true); - }); + it("should report the same error to sentry only once", function() { + const error1 = new Error("this is the error"); + this.logger.error({ foo: error1 }, "first message"); + this.logger.error({ bar: error1 }, "second message"); + this.captureException.callCount.should.equal(1); + }); - it('should report the same error to sentry only once', function() { - const error1 = new Error('this is the error'); - this.logger.error({foo: error1}, "first message"); - this.logger.error({bar: error1}, "second message"); - this.captureException.callCount.should.equal(1); - }); + it("should report two different errors to sentry individually", function() { + const error1 = new Error("this is the error"); + const error2 = new Error("this is the error"); + this.logger.error({ foo: error1 }, "first message"); + this.logger.error({ bar: error2 }, "second message"); + this.captureException.callCount.should.equal(2); + }); - it('should report two different errors to sentry individually', function() { - const error1 = new Error('this is the error'); - const error2 = new Error('this is the error'); - this.logger.error({foo: error1}, "first message"); - this.logger.error({bar: error2}, "second message"); - this.captureException.callCount.should.equal(2); - }); + it("should remove the path from fs errors", function() { + const 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"; + this.logger.error({ err: fsError }, "message"); + this.captureException + .calledWith( + sinon.match.has( + "message", + "Error: ENOENT: no such file or directory, stat" + ) + ) + .should.equal(true); + }); - it('should remove the path from fs errors', function() { - const 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"; - this.logger.error({err: fsError}, "message"); - this.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", function() { + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.captureException.callCount.should.equal(5); + }); - it('for multiple errors should only report a maximum of 5 errors to sentry', function() { - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.captureException.callCount.should.equal(5); - }); + it("for multiple errors with a minute delay should report 10 errors to sentry", function() { + // the first five errors should be reported to sentry + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + // the following errors should not be reported + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + // allow a minute to pass + this.clock.tick(this.start + 61 * 1000); + // after a minute the next five errors should be reported to sentry + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + // the following errors should not be reported to sentry + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.logger.error({ foo: "bar" }, "message"); + this.captureException.callCount.should.equal(10); + }); + }); - it('for multiple errors with a minute delay should report 10 errors to sentry', function() { - // the first five errors should be reported to sentry - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - // the following errors should not be reported - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - // allow a minute to pass - this.clock.tick(this.start+ (61*1000)); - // after a minute the next five errors should be reported to sentry - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - // the following errors should not be reported to sentry - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.logger.error({foo:'bar'}, "message"); - this.captureException.callCount.should.equal(10); - }); - }); + describe("checkLogLevel", function() { + it("should request log level override from google meta data service", function() { + this.logger.checkLogLevel(); + const options = { + headers: { + "Metadata-Flavor": "Google" + }, + uri: `http://metadata.google.internal/computeMetadata/v1/project/attributes/${ + this.loggerName + }-setLogLevelEndTime` + }; + this.Request.should.have.been.calledWithMatch(options); + }); - describe('checkLogLevel', function() { - it('should request log level override from google meta data service', function() { - this.logger.checkLogLevel(); - const options = { - headers: { - "Metadata-Flavor": "Google" - }, - uri: `http://metadata.google.internal/computeMetadata/v1/project/attributes/${this.loggerName}-setLogLevelEndTime` - }; - this.Request.should.have.been.calledWithMatch(options); - }); + describe("when request has error", function() { + beforeEach(function() { + this.Request.yields("error"); + this.logger.checkLogLevel(); + }); - describe('when request has error', function() { - beforeEach(function() { - this.Request.yields("error"); - this.logger.checkLogLevel(); - }); + it("should only set default level", function() { + this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith( + "debug" + ); + }); + }); - it("should only set default level", function() { - this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith('debug'); - }); - }); + describe("when statusCode is not 200", function() { + beforeEach(function() { + this.Request.yields(null, { statusCode: 404 }); + this.logger.checkLogLevel(); + }); - describe('when statusCode is not 200', function() { - beforeEach(function() { - this.Request.yields(null, {statusCode: 404}); - this.logger.checkLogLevel(); - }); + it("should only set default level", function() { + this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith( + "debug" + ); + }); + }); - it("should only set default level", function() { - this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith('debug'); - }); - }); + describe("when time value returned that is less than current time", function() { + beforeEach(function() { + this.Request.yields(null, { statusCode: 200 }, "1"); + this.logger.checkLogLevel(); + }); - describe('when time value returned that is less than current time', function() { - beforeEach(function() { - this.Request.yields(null, {statusCode: 200}, '1'); - this.logger.checkLogLevel(); - }); + it("should only set default level", function() { + this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith( + "debug" + ); + }); + }); - it("should only set default level", function() { - this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith('debug'); - }); - }); + describe("when time value returned that is less than current time", function() { + describe("when level is already set", function() { + beforeEach(function() { + this.mockBunyanLogger.level.returns(10); + this.Request.yields(null, { statusCode: 200 }, this.start + 1000); + this.logger.checkLogLevel(); + }); - describe('when time value returned that is less than current time', function() { - describe('when level is already set', function() { - beforeEach(function() { - this.mockBunyanLogger.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( + "trace" + ); + }); + }); - it("should set trace level", function() { - this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith('trace'); - }); - }); + describe("when level is not already set", function() { + beforeEach(function() { + this.mockBunyanLogger.level.returns(20); + this.Request.yields(null, { statusCode: 200 }, this.start + 1000); + this.logger.checkLogLevel(); + }); - describe('when level is not already set', function() { - beforeEach(function() { - this.mockBunyanLogger.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( + "trace" + ); + }); + }); + }); + }); - it("should set trace level", function() { - this.mockBunyanLogger.level.should.have.been.calledOnce.and.calledWith('trace'); - }); - }); - }); - }); + describe("ringbuffer", function() { + beforeEach(function() { + this.logBufferMock = [ + { + msg: "log 1" + }, + { + msg: "log 2" + } + ]; + }); + + describe("in production", function() { + beforeEach(function() { + process.env["NODE_ENV"] = "production"; + this.logger = this.LoggingManager.initialize(this.loggerName); + this.logger.ringBuffer.records = this.logBufferMock; + this.logger.error({}, "error"); + }); + + afterEach(function() { + process.env["NODE_ENV"] = undefined; + }); + + it("should include buffered logs in error log", function() { + this.mockBunyanLogger.error.lastCall.args[0].logBuffer.should.equal( + this.logBufferMock + ); + }); + }); + + describe("not in production", function() { + beforeEach(function() { + this.logger = this.LoggingManager.initialize(this.loggerName); + this.logger.ringBuffer.records = this.logBufferMock; + this.logger.error({}, "error"); + }); + + it("should not include buffered logs in error log", function() { + chai.expect(this.mockBunyanLogger.error.lastCall.args[0].logBuffer).be + .undefined; + }); + }); + }); });