Merge pull request #946 from pelias/add-debug-logs

More debug logs to controllers

controller/coarse_reverse.js

@@ -1,6 +1,8 @@
 const logger = require('pelias-logger').get('coarse_reverse');
 const _ = require('lodash');
 const Document = require('pelias-model').Document;
+const Debug = require('../helper/debug');
+const debugLog = new Debug('controller:coarse_reverse');
 
 // do not change order, other functionality depends on most-to-least granular order
 const coarse_granularities = [
@@ -102,7 +104,7 @@ function setup(service, should_execute) {
     if (!should_execute(req, res)) {
       return next();
     }
-
+    const initialTime = debugLog.beginTimer(req);
     // return a warning to the caller that boundary.circle.radius will be ignored
     if (!_.isUndefined(req.clean['boundary.circle.radius'])) {
       req.warnings.push('boundary.circle.radius is not applicable for coarse reverse');
@@ -111,6 +113,7 @@ function setup(service, should_execute) {
     // because coarse reverse is called when non-coarse reverse didn't return
     //  anything, treat requested layers as if it didn't contain non-coarse layers
     const effective_layers = getEffectiveLayers(req.clean.layers);
+    debugLog.push(req, {effective_layers: effective_layers});
 
     const centroid = {
       lat: req.clean['point.lat'],
@@ -140,7 +143,7 @@ function setup(service, should_execute) {
       if (hasResultsAtRequestedLayers(applicable_results, effective_layers)) {
         res.data.push(synthesizeDoc(applicable_results));
       }
-
+      debugLog.stopTimer(req, initialTime);
       return next();
 
     });

controller/libpostal.js

@@ -1,6 +1,8 @@
 const text_analyzer = require('pelias-text-analyzer');
 const _ = require('lodash');
 const iso3166 = require('iso3166-1');
+const Debug = require('../helper/debug');
+const debugLog = new Debug('controller:libpostal');
 
 function setup(should_execute) {
   function controller( req, res, next ){
@@ -8,7 +10,7 @@ function setup(should_execute) {
     if (!should_execute(req, res)) {
       return next();
     }
-
+    const initialTime = debugLog.beginTimer(req);
     // parse text with query parser
     const parsed_text = text_analyzer.parse(req.clean.text);
 
@@ -19,8 +21,9 @@ function setup(should_execute) {
       }
 
       req.clean.parsed_text = parsed_text;
+      debugLog.push(req, {parsed_text: req.clean.parsed_text});
     }
-
+    debugLog.stopTimer(req, initialTime);
     return next();
 
   }

controller/place.js

@@ -5,6 +5,8 @@ const retry = require('retry');
 
 const mgetService = require('../service/mget');
 const logger = require('pelias-logger').get('api');
+const Debug = require('../helper/debug');
+const debugLog = new Debug('controller:place');
 
 function requestHasErrors(request) {
   return _.get(request, 'errors', []).length > 0;
@@ -42,14 +44,18 @@ function setup( apiConfig, esclient ){
     });
 
     logger.debug( '[ES req]', cmd );
+    debugLog.push(req, {ES_req: cmd});
 
     operation.attempt((currentAttempt) => {
+      const initialTime = debugLog.beginTimer(req);
+
       mgetService( esclient, cmd, function( err, docs ) {
         // returns true if the operation should be attempted again
         // (handles bookkeeping of maxRetries)
         // only consider for status 408 (request timeout)
         if (isRequestTimeout(err) && operation.retry(err)) {
           logger.info(`request timed out on attempt ${currentAttempt}, retrying`);
+          debugLog.stopTimer(req, initialTime, `request timed out on attempt ${currentAttempt}, retrying`);
           return;
         }
 
@@ -81,6 +87,7 @@ function setup( apiConfig, esclient ){
 
         next();
       });
+      debugLog.stopTimer(req, initialTime);
     });
 
   }

controller/placeholder.js

@@ -2,6 +2,8 @@ const _ = require('lodash');
 const logger = require('pelias-logger').get('api');
 const Document = require('pelias-model').Document;
 const geolib = require('geolib');
+const Debug = require('../helper/debug');
+const debugLog = new Debug('controller:placeholder');
 
 // composition of toNumber and isFinite, useful for single call to convert a value
 //  to a number, then checking to see if it's finite
@@ -225,6 +227,7 @@ function setup(placeholderService, do_geometric_filters_apply, should_execute) {
     if (!should_execute(req, res)) {
       return next();
     }
+    const initialTime = debugLog.beginTimer(req);
 
     placeholderService(req, (err, results) => {
       if (err) {
@@ -263,8 +266,11 @@ function setup(placeholderService, do_geometric_filters_apply, should_execute) {
         ];
 
         logger.info(messageParts.join(' '));
+        debugLog.push(req, messageParts[1].slice(1,-1));
+        debugLog.push(req, res.data);
       }
 
+      debugLog.stopTimer(req, initialTime);
       return next();
     });
 

controller/predicates/has_request_errors.js

@@ -1,5 +1,13 @@
 const _ = require('lodash');
+const Debug = require('../../helper/debug');
+const debugLog = new Debug('controller:predicates:has_request_errors');
+const stackTraceLine = require('../../helper/stackTraceLine');
 
-module.exports = (request, response) => {
-  return _.get(request, 'errors', []).length > 0;
+module.exports = (req, res) => {
+  const has_request_errors = _.get(req, 'errors', []).length > 0;
+  debugLog.push(req, () => ({
+    reply: has_request_errors,
+    stack_trace: stackTraceLine()
+  }));
+  return has_request_errors;
 };

controller/predicates/has_request_parameter.js

@@ -1,4 +1,15 @@
 const _ = require('lodash');
+const Debug = require('../../helper/debug');
+const debugLog = new Debug('controller:predicates:has_request_parameter');
+const stackTraceLine = require('../../helper/stackTraceLine');
 
 // returns true IFF req.clean has a key with the supplied name
-module.exports = (parameter) => (req, res) => (_.has(req, ['clean', parameter]));
+module.exports = (parameter) => (req, res) => {
+  const has_request_parameter = _.has(req, ['clean', parameter]);
+
+  debugLog.push(req, () => ({
+    reply: {[parameter]: has_request_parameter},
+    stack_trace: stackTraceLine()
+  }));
+  return has_request_parameter;
+};

controller/predicates/has_response_data.js

@@ -1,5 +1,13 @@
 const _ = require('lodash');
+const Debug = require('../../helper/debug');
+const debugLog = new Debug('controller:predicates:has_response_data');
+const stackTraceLine = require('../../helper/stackTraceLine');
 
 module.exports = (request, response) => {
-  return _.get(response, 'data', []).length > 0;
+  const has_response_data = _.get(response, 'data', []).length > 0;
+  debugLog.push(request, () => ({
+    reply: has_response_data,
+    stack_trace: stackTraceLine()
+  }));
+  return has_response_data;
 };

controller/predicates/has_results_at_layers.js

@@ -1,5 +1,7 @@
 const _ = require('lodash');
-
+const Debug = require('../../helper/debug');
+const debugLog = new Debug('controller:predicates:has_results_at_layers');
+const stackTraceLine = require('../../helper/stackTraceLine');
 // returns a function that returns true if any result.layer is in any of the
 // supplied layers using array intersection
 
@@ -7,13 +9,19 @@ const _ = require('lodash');
 
 module.exports = (layers) => {
   return (request, response) => {
-    return !_.isEmpty(
+    const has_results_at_layers = !_.isEmpty(
       _.intersection(
         // convert layers to an array if it isn't already one
         _.castArray(layers),
         // pull all the layer properties into an array
         _.map(response.data, _.property('layer'))
     ));
+
+    debugLog.push(request, () => ({
+    reply: {[layers]: has_results_at_layers},
+    stack_trace: stackTraceLine()
+    }));
+    return has_results_at_layers;
   };
 
 };

controller/predicates/is_addressit_parse.js

@@ -1,4 +1,14 @@
 const _ = require('lodash');
+const Debug = require('../../helper/debug');
+const debugLog = new Debug('controller:predicates:is_addressit_parse');
+const stackTraceLine = require('../../helper/stackTraceLine');
 
 // returns true IFF req.clean.parser is addressit
-module.exports = (req, res) => (_.get(req, 'clean.parser') === 'addressit');
+module.exports = (req, res) => {
+  const is_addressit_parse = _.get(req, 'clean.parser') === 'addressit';
+  debugLog.push(req, () => ({
+    reply: is_addressit_parse,
+    stack_trace: stackTraceLine()
+  }));
+  return is_addressit_parse;
+};

controller/predicates/is_admin_only_analysis.js

@@ -1,18 +1,22 @@
 const _ = require('lodash');
 const Debug = require('../../helper/debug');
 const debugLog = new Debug('controller:predicates:is_admin_only_analysis');
+const stackTraceLine = require('../../helper/stackTraceLine');
 
 module.exports = (request, response) => {
   if (!request.clean.hasOwnProperty('parsed_text')) {
-    debugLog.push(request, false + '(no parsed_text)');
+    debugLog.push(request, false + ' (no parsed_text)');
     return false;
   }
 
   // return true only if all non-admin properties of parsed_text are empty
-   const is_admin_only_analysis = ['number', 'street', 'query', 'category', 'postalcode'].every((prop) => {
+  const is_admin_only_analysis = ['number', 'street', 'query', 'category', 'postalcode'].every((prop) => {
     return _.isEmpty(request.clean.parsed_text[prop]);
   });
 
-  debugLog.push(request, is_admin_only_analysis);
+  debugLog.push(request, () => ({
+    reply: is_admin_only_analysis,
+    stack_trace: stackTraceLine()
+  }));
   return is_admin_only_analysis;
 };

controller/predicates/is_coarse_reverse.js

@@ -2,12 +2,15 @@ const _ = require('lodash');
 const Debug = require('../../helper/debug');
 const debugLog = new Debug('controller:predicates:is_coarse_reverse');
 const non_coarse_layers = ['address', 'street', 'venue'];
+const stackTraceLine = require('../../helper/stackTraceLine');
 
 module.exports = (req, res) => {
   // returns true if layers is undefined, empty, or contains 'address', 'street', or 'venue'
   const is_coarse_reverse = !_.isEmpty(req.clean.layers) &&
           _.isEmpty(_.intersection(req.clean.layers, non_coarse_layers));
-
-  debugLog.push(req, is_coarse_reverse);
+  debugLog.push(req, () => ({
+    reply: is_coarse_reverse,
+    stack_trace: stackTraceLine()
+  }));
   return is_coarse_reverse;
 };

controller/predicates/is_only_non_admin_layers.js

@@ -1,7 +1,16 @@
 const _ = require('lodash');
+const Debug = require('../../helper/debug');
+const debugLog = new Debug('controller:predicates:is_only_non_admin_layers');
+const stackTraceLine = require('../../helper/stackTraceLine');
 
 // return true IFF req.clean.layers is empty OR there are non-venue/address/street layers
-module.exports = (req, res) => (
-  !_.isEmpty(_.get(req, 'clean.layers', [])) &&
-  _.isEmpty(_.difference(req.clean.layers, ['venue', 'address', 'street']))
-);
+module.exports = (req, res) => {
+  const is_only_non_admin_layers = !_.isEmpty(_.get(req, 'clean.layers', [])) &&
+  _.isEmpty(_.difference(req.clean.layers, ['venue', 'address', 'street']));
+
+  debugLog.push(req, () => ({
+    reply: is_only_non_admin_layers,
+    stack_trace: stackTraceLine()
+  }));
+  return is_only_non_admin_layers;
+};

controller/predicates/is_request_sources_only_whosonfirst.js

@@ -1,9 +1,17 @@
 const _ = require('lodash');
+const Debug = require('../../helper/debug');
+const debugLog = new Debug('controller:predicates:is_request_sources_only_whosonfirst');
+const stackTraceLine = require('../../helper/stackTraceLine');
 
 // returns true IFF 'whosonfirst' is the only requested source
-module.exports = (req, res) => (
-  _.isEqual(
+module.exports = (req, res) => {
+  const is_request_sources_only_whosonfirst = _.isEqual(
     _.get(req, 'clean.sources', []),
     ['whosonfirst']
-  )
-);
+  );
+  debugLog.push(req, () => ({
+    reply: is_request_sources_only_whosonfirst,
+    stack_trace: stackTraceLine()
+  }));
+  return is_request_sources_only_whosonfirst;
+};

controller/search.js

@@ -7,7 +7,6 @@ const logger = require('pelias-logger').get('api');
 const logging = require( '../helper/logging' );
 const retry = require('retry');
 const Debug = require('../helper/debug');
-const debugLog = new Debug('controller:search');
 
 function isRequestTimeout(err) {
   return _.get(err, 'status') === 408;
@@ -18,7 +17,9 @@ function setup( apiConfig, esclient, query, should_execute ){
     if (!should_execute(req, res)) {
       return next();
     }
-    debugLog.beginTimer(req);
+
+    const debugLog = new Debug('controller:search');
+
     let cleanOutput = _.cloneDeep(req.clean);
     if (logging.isDNT(req)) {
       cleanOutput = logging.removeFields(cleanOutput);
@@ -30,7 +31,7 @@ function setup( apiConfig, esclient, query, should_execute ){
 
     // if there's no query to call ES with, skip the service
     if (_.isUndefined(renderedQuery)) {
-      debugLog.stopTimer(req, 'No query to call ES with. Skipping');
+      debugLog.push(req, 'No query to call ES with. Skipping');
       return next();
     }
 
@@ -54,8 +55,10 @@ function setup( apiConfig, esclient, query, should_execute ){
     };
 
     logger.debug( '[ES req]', cmd );
+    debugLog.push(req, {ES_req: cmd});
 
     operation.attempt((currentAttempt) => {
+      const initialTime = debugLog.beginTimer(req, `Attempt ${currentAttempt}`);
       // query elasticsearch
       searchService( esclient, cmd, function( err, docs, meta ){
         // returns true if the operation should be attempted again
@@ -63,7 +66,7 @@ function setup( apiConfig, esclient, query, should_execute ){
         // only consider for status 408 (request timeout)
         if (isRequestTimeout(err) && operation.retry(err)) {
           logger.info(`request timed out on attempt ${currentAttempt}, retrying`);
-          debugLog.stopTimer(req, 'request timed out, retrying');
+          debugLog.stopTimer(req, initialTime, 'request timed out, retrying');
           return;
         }
 
@@ -110,7 +113,7 @@ function setup( apiConfig, esclient, query, should_execute ){
         logger.debug('[ES response]', docs);
         next();
       });
-      debugLog.stopTimer(req);
+      debugLog.stopTimer(req, initialTime);
     });
 
   }

controller/search_with_ids.js

@@ -4,6 +4,8 @@ const searchService = require('../service/search');
 const logger = require('pelias-logger').get('api');
 const logging = require( '../helper/logging' );
 const retry = require('retry');
+const Debug = require('../helper/debug');
+const debugLog = new Debug('controller:search_with_ids');
 
 function isRequestTimeout(err) {
   return _.get(err, 'status') === 408;
@@ -26,6 +28,7 @@ function setup( apiConfig, esclient, query, should_execute ){
 
     // if there's no query to call ES with, skip the service
     if (_.isUndefined(renderedQuery)) {
+      debugLog.push(req, `No query to call ES with. Skipping`);
       return next();
     }
 
@@ -49,8 +52,10 @@ function setup( apiConfig, esclient, query, should_execute ){
     };
 
     logger.debug( '[ES req]', cmd );
+    debugLog.push(req, {ES_req: cmd});
 
     operation.attempt((currentAttempt) => {
+      const initialTime = debugLog.beginTimer(req, `Attempt ${currentAttempt}`);
       // query elasticsearch
       searchService( esclient, cmd, function( err, docs, meta ){
         // returns true if the operation should be attempted again
@@ -58,6 +63,7 @@ function setup( apiConfig, esclient, query, should_execute ){
         // only consider for status 408 (request timeout)
         if (isRequestTimeout(err) && operation.retry(err)) {
           logger.info(`request timed out on attempt ${currentAttempt}, retrying`);
+          debugLog.stopTimer(req, initialTime, `request timed out on attempt ${currentAttempt}, retrying`);
           return;
         }
 
@@ -95,6 +101,11 @@ function setup( apiConfig, esclient, query, should_execute ){
             ];
 
             logger.info(messageParts.join(' '));
+            debugLog.push(req, {queryType: {
+              [renderedQuery.type] : {
+                es_result_count: parseInt(messageParts[2].slice(17, -1))
+              }
+            }});
 
           }
 
@@ -102,7 +113,7 @@ function setup( apiConfig, esclient, query, should_execute ){
         logger.debug('[ES response]', docs);
         next();
       });
-
+      debugLog.stopTimer(req, initialTime);
     });
 
   }

helper/debug.js

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

helper/stackTraceLine.js

@@ -0,0 +1,13 @@
+'use strict';
+
+module.exports = () => {
+  const stack = new Error().stack.split('\n');
+  let targetLine;
+
+  stack.forEach((line) => {
+    if(line.indexOf('at controller') !== -1) {
+      targetLine = line.trim();
+    }
+  });
+  return targetLine;
+};

test/unit/helper/debug.js

@@ -50,35 +50,50 @@ module.exports.tests.debug = function(test, common) {
         enableDebug: true
       }
     };
-    const expected_req = {
-      debug: [
-        {
-          debugger: 'This should be pushed'
-        },
-        {
-          debugger: 'Timer Began: Timer 1'
-        }
-      ]
-    };
+    const expected_req = [
+      {
+        debugger: 'This should be pushed'
+      },
+      {
+        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);
-      t.end();
-    }, 2);
+    const expected_req = [
+      {
+        debugger: 'This should be pushed'
+      }
+    ];
+    debugLog.push(req, () => ('This should be pushed'));
+    t.deepEquals(req.debug, expected_req);
+    t.end();
+  });
 
+  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();
   });
 
 };

test/unit/helper/stackTraceLine.js

@@ -0,0 +1,20 @@
+const stackTraceLine = require('../../../helper/stackTraceLine');
+
+module.exports.tests = {};
+module.exports.tests.stackTrace = (test, common) => {
+  test('No exceptions thrown when function is called', (t) => {
+    t.doesNotThrow(stackTraceLine, 'No exceptions thrown');
+    t.end();
+  });
+};
+
+module.exports.all = function (tape, common) {
+
+  function test(name, testFunction) {
+    return tape('[helper] stackTraceLine: ' + name, testFunction);
+  }
+
+  for( var testCase in module.exports.tests ){
+    module.exports.tests[testCase](test, common);
+  }
+};

test/unit/run.js

@@ -35,6 +35,7 @@ var tests = [
   require('./helper/logging'),
   require('./helper/type_mapping'),
   require('./helper/sizeCalculator'),
+  require('./helper/stackTraceLine'),
   require('./middleware/access_log'),
   require('./middleware/accuracy'),
   require('./middleware/assignLabels'),