Custom Logger.js

Logger.js

/* eslint-disable class-methods-use-this */
const { Console } = require('console');

/**
 Logging levels conform to the severity ordering specified by RFC5424:
 severity of all levels is assumed to be numerically ascending from most
 important to least important.
 https://tools.ietf.org/html/rfc5424
 */

class Logger {
  constructor(log, functionName = 'local', setting = null, env = null) {
    this.log = log;
    this.functionName = functionName;
    this.setting = (setting || process.env.LOGLEVEL || 'info').toLowerCase();
    this.env = (env || process.env.STAGE || 'dev').toLowerCase();
  }

  getFuncName() {
    return this.functionName;
  }

  /**
   * This MUST be filled out with current lambda name. Otherwise our logs will get
   * polluted when sent to kibana
   * @param value
   */
  setFuncName(value) {
    if (value === undefined || value === '') {
      return;
    }
    this.functionName = value;
  }

  /**
   *
   * @param message
   * @param errorObj: Actual Error object Ex: Error('This is an error object')
   */
  error(message, errorObj) {
    const logLevel = 'error';
    if (this.shouldLog(logLevel)) {
      this.log.error(this.formatMessage(logLevel, message, errorObj));
    }
  }

  /**
   *
   * @param message
   */
  warn(message) {
    const logLevel = 'warn';
    if (this.shouldLog(logLevel)) {
      this.log.warn(this.formatMessage(logLevel, message));
    }
  }

  /**
   *
   * @param message
   */
  info(message) {
    const logLevel = 'info';
    if (this.shouldLog(logLevel)) {
      this.log.info(this.formatMessage(logLevel, message));
    }
  }

  /**
   *
   * @param message
   */
  verbose(message) {
    const logLevel = 'verbose';
    if (this.shouldLog(logLevel)) {
      this.log.info(this.formatMessage(logLevel, message));
    }
  }

  /**
   *
   * @param message
   */
  debug(message) {
    const logLevel = 'debug';
    if (this.shouldLog(logLevel)) {
      this.log.debug(this.formatMessage(logLevel, message));
    }
  }

  /**
   *
   * @param message
   */
  silly(message) {
    const logLevel = 'silly';
    if (this.shouldLog(logLevel)) {
      this.log.debug(this.formatMessage(logLevel, message));
    }
  }

  /**
   * Decider that checks if current message should be logged based on log level
   * @param level - current log level
   * @returns {boolean}
   */
  shouldLog(level) {
    if (this.setting === level || this.setting === '*') {
      return true;
    }
    const loggerLevel = this.levelLookup(this.setting);
    const lookup = this.levelLookup(level);
    return lookup <= loggerLevel;
  }

  levelLookup(level) {
    const number = {
      error: 0,
      warn: 1,
      info: 2,
      verbose: 3,
      debug: 4,
      silly: 5,
    };
    return number[level];
  }
  /**
   * This logger is written to complement with ELK's indexing capabilities
   * The log messages are nested in a key called lambda so we can isolate indexing errors
   * for kibana if any.
   *
   * @param logLevel
   * @param message
   * @param error
   * @returns {json message sent to log}
   * @private
   */
  formatMessage(logLevel, message, error) {
    const funcName = this.getFuncName();
    const lambdaMessage = {};
    if (message.constructor === Object) {
      Object.assign(lambdaMessage, message);
    } else if (message.constructor === String) {
      lambdaMessage.message = message;
    } else {
      lambdaMessage.message = message.toString();
    }
    if (error && (error instanceof Error)) {
      lambdaMessage.error = error.stack;
    }
    const finalMsg = {
      level: logLevel,
      app: 'aws-lambda',
      env: this.env,
      lambdaName: funcName,
    };
    finalMsg[funcName] = lambdaMessage;
    return JSON.stringify(finalMsg);
  }
}

const Log = new Logger(new Console(process.stdout, process.stderr));
module.exports = Log;


///////////////////////////////////////// Specs below. Should be separate file. 

/* eslint-disable global-require,class-methods-use-this,
no-unused-expressions,prefer-arrow-callback,func-names,prefer-destructuring */

require('mocha-sinon');
const sinon = require('sinon');

const expect = global.expect;

describe('Logger', function () {
  const stubLog = () => proxyquire('../src/common/Logger', {});
  const Log = stubLog();
  describe('#new', function () {
    context('Logger is instantiated', function () {
      it('should not throw errors', function (done) {
        expect(() => { Log; }).to.not.throw();
        done();
      });
      it('returns functionName, setting, and env', function () {
        expect(Log.functionName).to.equal('local');
        expect(Log.setting).to.equal('info');
        expect(Log.env).to.equal('dev');
      });
      it('returns an log object', function () {
        expect(typeof (Log.log)).to.eql('object');
      });
    });
  });

  describe('#getFuncName', function () {
    it('should return a string', function () {
      expect(Log.getFuncName()).to.have.string('local');
    });
    describe('#setFuncName', function () {
      it('should set the new_name for the logger', function () {
        Log.setFuncName('new_name');
        expect(Log.getFuncName()).to.have.string('new_name');
        Log.setFuncName('local'); // return back to default name
      });
    });
  });

  describe('#shouldLog', function () {
    context('when log level is silly', function () {
      process.env.LOGLEVEL = 'silly';
      const shouldLogStub = () => proxyquire('../src/common/Logger', {});
      const newShouldLogStub = shouldLogStub();
      it('returns info for this.setting', function () {
        expect(newShouldLogStub.setting).to.equal('silly');
      });
      it('returns boolean with expected behaviors', function () {
        expect(newShouldLogStub.shouldLog('error')).to.be.true;
        expect(newShouldLogStub.shouldLog('warn')).to.be.true;
        expect(newShouldLogStub.shouldLog('info')).to.be.true;
        expect(newShouldLogStub.shouldLog('verbose')).to.be.true;
        expect(newShouldLogStub.shouldLog('debug')).to.be.true;
        expect(newShouldLogStub.shouldLog('silly')).to.be.true;
      });
      it('logs error level messages', function () {
        sinon.spy(newShouldLogStub.log, 'error');
        newShouldLogStub.error('If this message does not appear, test fails', Error('Testing'));
        newShouldLogStub.log.error.called.should.be.true;
        newShouldLogStub.log.error.restore();
      });
      it('logs info level messages', function () {
        sinon.spy(newShouldLogStub.log, 'info');
        newShouldLogStub.info('If this message does not appear, test fails');
        newShouldLogStub.log.info.called.should.be.true;
        newShouldLogStub.log.info.restore();
      });
      it('logs silly level messages', function () {
        sinon.spy(newShouldLogStub.log, 'debug');
        newShouldLogStub.silly('If this message does not appear, test fails');
        newShouldLogStub.log.debug.called.should.be.true;
        newShouldLogStub.log.debug.restore();
      });
    });
  });

  context('when log level is silly', function () {
    process.env.LOGLEVEL = 'silly';
    const Log3 = () => proxyquire('../src/common/Logger', {});
    const stubLog3 = Log3();
    const parentKeys = ['level', 'app', 'env', 'lambdaName'];
    const childKeys = ['message'];

    describe('#error', function () {
      it('creates message that handles Error object', function () {
        const errorStub = this.sinon.stub(stubLog3.log, 'error');
        stubLog3.error('Test Error Format', Error('Message'));
        const message = JSON.parse(errorStub.lastCall.lastArg);
        expect(message.local.error).to.not.be.null;
      });
    });
    describe('#warn', function () {
      it('calls creates a key call error and populates it with values', function () {
        const warnStub = this.sinon.stub(stubLog3.log, 'warn');
        stubLog3.warn('Warning Message');
        const message = JSON.parse(warnStub.lastCall.lastArg);
        expect(message).to.contain.keys(parentKeys);
        expect(message.local).to.contain.keys(childKeys);
      });
    });
    describe('#info', function () {
      it('calls creates a key call error and populates it with values', function () {
        const infoStub = this.sinon.stub(stubLog3.log, 'info');
        stubLog3.info('Warning Message');
        const message = JSON.parse(infoStub.lastCall.lastArg);
        expect(message).to.contain.keys(parentKeys);
        expect(message.local).to.contain.keys(childKeys);
      });
    });
    describe('#verbose', function () {
      it('calls creates a key call error and populates it with values', function () {
        const verboseStub = this.sinon.stub(stubLog3.log, 'info');
        stubLog3.verbose('Warning Message');
        const message = JSON.parse(verboseStub.lastCall.lastArg);
        expect(message).to.contain.keys(parentKeys);
        expect(message.local).to.contain.keys(childKeys);
      });
    });
    describe('#debug', function () {
      it('calls creates a key call error and populates it with values', function () {
        const debugStub = this.sinon.stub(stubLog3.log, 'debug');
        stubLog3.debug('Warning Message');
        const message = JSON.parse(debugStub.lastCall.lastArg);
        expect(message).to.contain.keys(parentKeys);
        expect(message.local).to.contain.keys(childKeys);
      });
    });
    describe('#silly', function () {
      it('calls creates a key call error and populates it with values', function () {
        const sillyStub = this.sinon.stub(stubLog3.log, 'debug');
        stubLog3.debug('Warning Message');
        const message = JSON.parse(sillyStub.lastCall.lastArg);
        expect(message).to.contain.keys(parentKeys);
        expect(message.local).to.contain.keys(childKeys);
      });
    });
  });
  describe('#levelLookup', function () {
    context('when correct log level is given', function () {
      it('returns the correct number for various log levels', function () {
        expect(Log.levelLookup('error')).to.equal(0);
        expect(Log.levelLookup('warn')).to.equal(1);
        expect(Log.levelLookup('info')).to.equal(2);
        expect(Log.levelLookup('verbose')).to.equal(3);
        expect(Log.levelLookup('debug')).to.equal(4);
        expect(Log.levelLookup('silly')).to.equal(5);
      });
    });
    context('when wrong log level is given', function () {
      it('returns undefined', function () {
        expect(Log.levelLookup('blah')).to.equal(undefined);
      });
    });
  });

  describe('#formatMessage', function () {
    context('when message is an Object', function () {
      it('returns expected message format', function () {
        this.logLevel = 'blah';
        this.message = { k1: 'v1', message: 'message' };
        this.expectedResponse = JSON.stringify({
          level: 'blah',
          app: 'aws-lambda',
          env: 'dev',
          lambdaName: 'local',
          local: { k1: 'v1', message: 'message' },
        });
        expect(Log.formatMessage(this.logLevel, this.message)).to.equal(this.expectedResponse);
      });
    });
  });
});