mirror of
https://github.com/overleaf/overleaf.git
synced 2024-11-21 20:47:08 -05:00
use ring buffer for logging and include with error
This commit is contained in:
Ersun Warncke
parent
5a6e00e12b
commit
83597e8723
6 changed files with 615 additions and 724 deletions
|
|
@ -1 +1 @@
|
|||
module.exports = require('./logging-manager.js');
|
||||
module.exports = require("./logging-manager.js");
|
||||
|
|
|
|||
|
|
@ -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')
|
||||
|
|
@ -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");
|
||||
|
|
|
|||
99
libraries/logger/package-lock.json
generated
99
libraries/logger/package-lock.json
generated
|
|
@ -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",
|
||||
|
|
|
|||
|
|
@ -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"
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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;
|
||||
});
|
||||
});
|
||||
});
|
||||
});
|
||||
|
|
|
|||
Loading…
Reference in a new issue