update controller debug timers to new format

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);
 
@@ -20,7 +22,7 @@ function setup(should_execute) {
 
       req.clean.parsed_text = 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;
@@ -20,7 +22,7 @@ function setup( apiConfig, esclient ){
     if (requestHasErrors(req)){
       return next();
     }
-
+    const initialTime = debugLog.beginTimer(req);
     // options for retry
     // maxRetries is from the API config with default of 3
     // factor of 1 means that each retry attempt will esclient requestTimeout
@@ -42,6 +44,7 @@ function setup( apiConfig, esclient ){
     });
 
     logger.debug( '[ES req]', cmd );
+    debugLog.push(req, {ES_req: cmd});
 
     operation.attempt((currentAttempt) => {
       mgetService( esclient, cmd, function( err, docs ) {
@@ -50,6 +53,7 @@ function setup( apiConfig, esclient ){
         // 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, retrying');
           return;
         }
 
@@ -81,6 +85,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,10 @@ function setup(placeholderService, do_geometric_filters_apply, should_execute) {
         ];
 
         logger.info(messageParts.join(' '));
+        debugLog.push(req, messageParts[1].slice(1,-1));
       }
 
+      debugLog.stopTimer(req, initialTime);
       return next();
     });
 

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,10 @@ function setup( apiConfig, esclient, query, should_execute ){
     if (!should_execute(req, res)) {
       return next();
     }
-    debugLog.beginTimer(req);
+
+    const debugLog = new Debug(req, 'controller:search');
+    const initialTime = debugLog.beginTimer(req);
+
     let cleanOutput = _.cloneDeep(req.clean);
     if (logging.isDNT(req)) {
       cleanOutput = logging.removeFields(cleanOutput);
@@ -30,7 +32,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.stopTimer(req, initialTime, 'No query to call ES with. Skipping');
       return next();
     }
 
@@ -54,6 +56,7 @@ function setup( apiConfig, esclient, query, should_execute ){
     };
 
     logger.debug( '[ES req]', cmd );
+    debugLog.push(req, {ES_req: cmd});
 
     operation.attempt((currentAttempt) => {
       // query elasticsearch
@@ -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;
@@ -15,6 +17,7 @@ function setup( apiConfig, esclient, query, should_execute ){
       return next();
     }
 
+    const initialTime = debugLog.beginTimer(req);
     const cleanOutput = _.cloneDeep(req.clean);
     if (logging.isDNT(req)) {
       logging.removeFields(cleanOutput);
@@ -26,6 +29,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, initialTime, 'No query to call ES with. Skipping');
       return next();
     }
 
@@ -49,6 +53,7 @@ function setup( apiConfig, esclient, query, should_execute ){
     };
 
     logger.debug( '[ES req]', cmd );
+    debugLog.push(req, {ES_req: cmd});
 
     operation.attempt((currentAttempt) => {
       // query elasticsearch
@@ -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, 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);
     });
 
   }