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..8f275dd9 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); @@ -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(); } diff --git a/controller/place.js b/controller/place.js index b2efdf04..2b5490aa 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; @@ -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); }); } diff --git a/controller/placeholder.js b/controller/placeholder.js index 48e7dfd5..edba469a 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,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(); }); diff --git a/controller/predicates/has_request_errors.js b/controller/predicates/has_request_errors.js index ccc13361..da9b40b4 100644 --- a/controller/predicates/has_request_errors.js +++ b/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; }; diff --git a/controller/predicates/has_request_parameter.js b/controller/predicates/has_request_parameter.js index 4567f4df..81e04b0f 100644 --- a/controller/predicates/has_request_parameter.js +++ b/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; +}; diff --git a/controller/predicates/has_response_data.js b/controller/predicates/has_response_data.js index a61907d4..bc870863 100644 --- a/controller/predicates/has_response_data.js +++ b/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; }; diff --git a/controller/predicates/has_results_at_layers.js b/controller/predicates/has_results_at_layers.js index bb1cfcae..e7a389d0 100644 --- a/controller/predicates/has_results_at_layers.js +++ b/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; }; }; diff --git a/controller/predicates/is_addressit_parse.js b/controller/predicates/is_addressit_parse.js index 48060eed..288b173c 100644 --- a/controller/predicates/is_addressit_parse.js +++ b/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; +}; diff --git a/controller/predicates/is_admin_only_analysis.js b/controller/predicates/is_admin_only_analysis.js index 7ecbd4bb..f164f4da 100644 --- a/controller/predicates/is_admin_only_analysis.js +++ b/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; }; diff --git a/controller/predicates/is_coarse_reverse.js b/controller/predicates/is_coarse_reverse.js index 55df78f5..f96679a2 100644 --- a/controller/predicates/is_coarse_reverse.js +++ b/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; }; diff --git a/controller/predicates/is_only_non_admin_layers.js b/controller/predicates/is_only_non_admin_layers.js index f36ab097..eed765c8 100644 --- a/controller/predicates/is_only_non_admin_layers.js +++ b/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; +}; diff --git a/controller/predicates/is_request_sources_only_whosonfirst.js b/controller/predicates/is_request_sources_only_whosonfirst.js index c3071ffb..8554e0c2 100644 --- a/controller/predicates/is_request_sources_only_whosonfirst.js +++ b/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; +}; diff --git a/controller/search.js b/controller/search.js index a8bee3e4..721c0dde 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,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); }); } diff --git a/controller/search_with_ids.js b/controller/search_with_ids.js index a8af0b74..75c14aea 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; @@ -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); }); } diff --git a/helper/debug.js b/helper/debug.js index 13a90c1a..cf8b833c 100644 --- a/helper/debug.js +++ b/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; diff --git a/helper/stackTraceLine.js b/helper/stackTraceLine.js new file mode 100644 index 00000000..67e56de2 --- /dev/null +++ b/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; +}; diff --git a/test/unit/helper/debug.js b/test/unit/helper/debug.js index 319b3af6..3eb3002c 100644 --- a/test/unit/helper/debug.js +++ b/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(); }); }; diff --git a/test/unit/helper/stackTraceLine.js b/test/unit/helper/stackTraceLine.js new file mode 100644 index 00000000..379b2664 --- /dev/null +++ b/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); + } +}; diff --git a/test/unit/run.js b/test/unit/run.js index e09bc037..0cd9d4c9 100644 --- a/test/unit/run.js +++ b/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'),