debug push takes function & beginTimer returns Date

helper/debug.js

@@ -6,38 +6,47 @@ class Debug {
     this.name = moduleName || 'unnamed module';
   }
 
-  push(req, debugMsg){
-    if (!_.isEmpty(req.clean) && req.clean.enableDebug){
+  push(req, value){
+    if (!req || _.isEmpty(req.clean) || !req.clean.enableDebug){
+      return;
+    }
     req.debug = req.debug || [];
-      // remove the extra space character
-      req.debug.push({[this.name]: debugMsg});
-    //  req.debug.push(`[${this.name}] ${debugMsg}`);
+    switch(typeof value) {
+      case 'function':
+        req.debug.push({[this.name]: value()});
+        break;
+      default:
+        req.debug.push({[this.name]: value});
     }
   }
-  // optional debugMsg passed to timer
+
   beginTimer(req, debugMsg){
-    if (!_.isEmpty(req.clean) && req.clean.enableDebug){
-      // internal object debugTimers. Doesn't get displayed in geocodeJSON
-      req.debugTimers = req.debugTimers || {};
-      req.debugTimers[this.name] = Date.now();
+     if (req && !_.isEmpty(req.clean) && req.clean.enableDebug){
+       // debugMsg is optional
+       this.push(req, () => {
          if (debugMsg){
-        this.push(req, `Timer Began: ${debugMsg}`);
+           return `Timer Began. ${debugMsg}`;
          } else {
-        this.push(req, `Timer Began`);
+           return `Timer Began`;
          }
+       });
+       return Date.now();
      }
    }
 
-  stopTimer(req, debugMsg){
-    if (!_.isEmpty(req.clean) && req.clean.enableDebug){
-      let timeElapsed = Date.now() - req.debugTimers[this.name];
+  stopTimer(req, startTime, debugMsg){
+    if (req && !_.isEmpty(req.clean) && req.clean.enableDebug){
+      let timeElapsed = Date.now() - startTime;
+        this.push(req, () => {
           if (debugMsg){
-        this.push(req, `Timer Stopped: ${timeElapsed} ms: ${debugMsg}`);
+            return `Timer Stopped. ${timeElapsed} ms. ${debugMsg}`;
           } else {
-        this.push(req, `Timer Stopped: ${timeElapsed} ms`);
+            return `Timer Stopped. ${timeElapsed} ms`;
           }
+        });
       }
     }
+
 }
 
 module.exports = Debug;

test/unit/helper/debug.js

@@ -50,35 +50,50 @@ module.exports.tests.debug = function(test, common) {
         enableDebug: true
       }
     };
-    const expected_req = {
-      debug: [
+    const expected_req = [
       {
         debugger: 'This should be pushed'
       },
       {
-          debugger: 'Timer Began: Timer 1'
+        debugger: 'Timer Began. Timer 1'
       }
-      ]
-    };
+    ];
     debugLog.push(req, 'This should be pushed');
     debugLog.beginTimer(req, 'Timer 1');
+    t.deepEquals(req.debug, expected_req);
     t.end();
   });
 
-  test('Timer should return positive number of milliseconds', (t) => {
+  test('Push messages can take output of function', (t) => {
     const debugLog = new Debug('debugger');
     const req = {
       clean: {
         enableDebug: true
       }
     };
-    debugLog.beginTimer(req);
-    setTimeout(() => {
-      debugLog.stopTimer(req);
-      t.deepEquals(parseInt(req.debug[1].debugger.slice(15, -3)) > 0, true);
+    const expected_req = [
+      {
+        debugger: 'This should be pushed'
+      }
+    ];
+    debugLog.push(req, () => ('This should be pushed'));
+    t.deepEquals(req.debug, expected_req);
     t.end();
-    }, 2);
+  });
 
+  test('Timer should return number of milliseconds', (t) => {
+    const debugLog = new Debug('debugger');
+    const req = {
+      clean: {
+        enableDebug: true
+      }
+    };
+    const timer = debugLog.beginTimer(req);
+    debugLog.stopTimer(req, timer);
+    // Checks that there is a debug message
+    // that matches the pattern "Timer Stopped. [number] ms"
+    t.deepEquals(req.debug[1].debugger.match(/Timer Stopped\. \d+ ms/i).length, 1);
+    t.end();
   });
 
 };