diff --git a/controller/coarse_reverse.js b/controller/coarse_reverse.js index 158c8b0a..e49dc8c9 100644 --- a/controller/coarse_reverse.js +++ b/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(); }); diff --git a/controller/libpostal.js b/controller/libpostal.js index 6c913cd7..9a034ac2 100644 --- a/controller/libpostal.js +++ b/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(); } diff --git a/controller/place.js b/controller/place.js index b2efdf04..c96c34b6 100644 --- a/controller/place.js +++ b/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); }); } diff --git a/controller/placeholder.js b/controller/placeholder.js index 48e7dfd5..9245351b 100644 --- a/controller/placeholder.js +++ b/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(); }); diff --git a/controller/search.js b/controller/search.js index a8bee3e4..ba8250ce 100644 --- a/controller/search.js +++ b/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); }); } diff --git a/controller/search_with_ids.js b/controller/search_with_ids.js index a8af0b74..15694d5f 100644 --- a/controller/search_with_ids.js +++ b/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); }); }