feat(timer): add timer to logger, same api as logger

index.js

@@ -1,7 +1,6 @@
 'use strict';
 
 const Logger = require('./src/logger/logger');
-const Timer = require('./src/timer/timer');
 const isNamespaceEnabled = require('./src/enabled/enabled');
 const contextMiddlewareFactory = require('./src/context-middleware-factory/context-middleware-factory');
 
@@ -17,7 +16,6 @@ function logFactory(namespace, options) {
 }
 
 logFactory.Logger = Logger;
-logFactory.Timer = Timer;
 logFactory.getNamespaces = function() {
   return process.env.DEBUG || '';
 };

src/index.spec.js

@@ -16,14 +16,14 @@ describe('LogFactory', function() {
     const logger = logFactory('mongo');
 
     expect(logger).to.be.an.instanceOf(Logger);
-    expect(logger.enabled).to.be.true;
+    expect(logger.isEnabled()).to.be.true;
   });
 
   it('should return a disabled log instance when different', function() {
     const logger = logFactory('redis');
 
     expect(logger).to.be.an.instanceOf(Logger);
-    expect(logger.enabled).to.be.false;
+    expect(logger.isEnabled()).to.be.false;
   });
 
   it('should be mockable through public interface', function() {

src/logger/logger.js

@@ -4,41 +4,51 @@ const config = require('../config');
 const continuationLocalStorage = require('cls-hooked');
 const _ = require('lodash');
 const STACK_TRACE_LIMIT = 4000;
+const Timer = require('../timer/timer');
 
 const logMethodFactory = function(level) {
   return function(action, data) {
-    if (!this.enabled) {
+    if (!this._enabled) {
       return;
     }
 
-    const namespace = continuationLocalStorage.getNamespace('session');
-    const storage = (namespace && namespace.active) ? _.omit(namespace.active, 'id', '_ns_name') : {};
+    const contextNamespace = continuationLocalStorage.getNamespace('session');
+    const contextStorage = (contextNamespace && contextNamespace.active) ?
+      _.omit(contextNamespace.active, 'id', '_ns_name') : {};
 
     console.log(JSON.stringify(Object.assign(
       {
-        name: this.namespace,
+        name: this._namespace,
         action: action,
         level: config.levels[level].number,
         time: new Date().toISOString()
       },
-      storage,
+      contextStorage,
       data
     )));
   }
 };
 
 class Logger {
   constructor(namespace, enabled) {
-    this.namespace = namespace;
-    this.enabled = enabled;
+    this._namespace = namespace;
+    this._enabled = enabled;
   }
 
-  fromError(action, error, options = {}) {
+  isEnabled() {
+    return this._enabled;
+  }
+
+  fromError(action, error, data = {}) {
     this.error(action, Object.assign({
       error_name: error.name,
       error_stack: this._shortenStackTrace(error),
       error_message: error.message
-    }, options));
+    }, data));
+  }
+
+  timer() {
+    return new Timer(this);
   }
 
   _shortenStackTrace(error) {

src/logger/logger.spec.js

@@ -41,6 +41,17 @@ describe('Logger', function() {
     expect(console.log).not.to.have.been.called;
   });
 
+  it('should not call log info method when disabled', function() {
+    logger = new Logger('mongo', false);
+    const timer = logger.timer();
+    const infoStub = this.sandbox.stub(logger, 'info');
+
+    this.clock.tick(100);
+    timer.info('hi');
+
+    expect(infoStub).to.have.been.calledWith('hi', { duration: 100 });
+  });
+
   it('should log error with action', function() {
     const error = new Error('failed');
 

src/setup.spec.js

@@ -10,9 +10,12 @@ global.expect = chai.expect;
 
 beforeEach(function () {
   this.sandbox = sinon.sandbox.create();
+  this.clock = sinon.useFakeTimers();
 });
 
 afterEach(function () {
   this.sandbox.restore();
   this.sandbox = undefined;
+  this.clock.restore();
+  this.clock = undefined;
 });

src/timer/timer.js

@@ -1,15 +1,40 @@
 'use strict';
 
+const logMethodFactory = function(level) {
+  return function(action, data) {
+    this._logger[level](
+      action,
+      Object.assign({ duration: this._duration() }, data)
+    );
+  }
+};
+
 class Timer {
-  constructor() {
-    this.start = new Date().getTime();
+  constructor(logger) {
+    this._logger = logger;
+    this._start = new Date().getTime();
   }
 
-  elapsedTime() {
+  fromError(action, error, data = {}) {
+    this._logger.fromError(
+      action,
+      error,
+      Object.assign({ duration: this._duration() }, data)
+    );
+  }
+
+  _duration() {
     const end = new Date().getTime();
 
-    return end - this.start;
+    return end - this._start;
   }
 }
 
+Timer.prototype.trace = logMethodFactory('trace');
+Timer.prototype.debug = logMethodFactory('debug');
+Timer.prototype.info = logMethodFactory('info');
+Timer.prototype.warn = logMethodFactory('warn');
+Timer.prototype.error = logMethodFactory('error');
+Timer.prototype.fatal = logMethodFactory('fatal');
+
 module.exports = Timer;

src/timer/timer.spec.js

@@ -0,0 +1,29 @@
+'use strict';
+
+const Logger = require('../logger/logger');
+const Timer = require('./timer');
+
+describe('Timer', function() {
+  it('should log elapsed time', function() {
+    const logger = new Logger('test', false);
+    const infoStub = this.sandbox.stub(logger, 'info');
+    const timer = new Timer(logger);
+
+    this.clock.tick(100);
+    timer.info('time', { customer_id: 10 });
+
+    expect(infoStub).to.have.been. calledWith('time', { customer_id: 10, duration: 100 });
+  });
+
+  it('should log elapsed time with error', function() {
+    const logger = new Logger('test', false);
+    const errorStub = this.sandbox.stub(logger, 'fromError');
+    const timer = new Timer(logger);
+    const error = new Error('intended');
+
+    this.clock.tick(100);
+    timer.fromError('time', error, { customer_id: 10 });
+
+    expect(errorStub).to.have.been. calledWith('time', error, { customer_id: 10, duration: 100 });
+  });
+});