overleaf/libraries/logger/test/unit/loggingManagerTests.js

/*
 * 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 chai = require("chai");
const path = require("path");
const sinon = require("sinon");
const sinonChai = require("sinon-chai");

chai.use(sinonChai);
chai.should();

const modulePath = path.join(__dirname, '../../logging-manager.js');

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)}),
				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();
	});

	describe('initialize', function() {
		beforeEach(function() {
			this.checkLogLevelStub = sinon.stub(this.LoggingManager.prototype, "checkLogLevel");
			this.Bunyan.createLogger.reset();
		});

		afterEach(function () {
			this.checkLogLevelStub.restore()
		})

		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.should.have.been.calledWithMatch({level: "debug"});
			});

			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)
			});

			afterEach(() => delete process.env.NODE_ENV);

			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;
			});

			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("when LOG_LEVEL set in env", function() {
			beforeEach(function() {
				process.env.LOG_LEVEL = "trace";
				this.LoggingManager.initialize();
			});

			afterEach(() => delete process.env.LOG_LEVEL);

			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" ];});

		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 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 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 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);
		});

		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 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 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('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');
			});
		});

		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');
			});
		});

		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');
			});
		});

		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');
				});
			});

			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');
				});
			});
		});
	});
});