diff --git a/controller/coarse_reverse.js b/controller/coarse_reverse.js index c4b943744..ac6429738 100644 --- a/controller/coarse_reverse.js +++ b/controller/coarse_reverse.js @@ -114,7 +114,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'); @@ -125,11 +125,7 @@ function setup(service, should_execute) { const effective_layers = getEffectiveLayers(req.clean.layers); debugLog.push(req, {effective_layers: effective_layers}); - const centroid = { - lat: req.clean['point.lat'], - lon: req.clean['point.lon'] - }; - + const start = Date.now(); service(req, (err, results, metadata) => { // if there's an error, log it and bail if (err) { @@ -160,7 +156,7 @@ function setup(service, should_execute) { res.data.push(doc); } } - debugLog.stopTimer(req, initialTime); + debugLog.push(req, { duration: Date.now() - start }); return next(); }); diff --git a/controller/libpostal.js b/controller/libpostal.js index c2f7cf360..a789cfe31 100644 --- a/controller/libpostal.js +++ b/controller/libpostal.js @@ -68,8 +68,7 @@ function setup(libpostalService, should_execute) { return next(); } - const initialTime = debugLog.beginTimer(req); - + const start = Date.now(); libpostalService(req, (err, response) => { if (err) { @@ -101,15 +100,14 @@ function setup(libpostalService, should_execute) { req.clean.parsed_text.country = iso3166.convertISO2ToISO3(req.clean.parsed_text.country); } - debugLog.push(req, {parsed_text: req.clean.parsed_text}); - + debugLog.push(req, { + parsed_text: req.clean.parsed_text, + duration: Date.now() - start + }); } - debugLog.stopTimer(req, initialTime); return next(); - }); - } return controller; diff --git a/controller/place.js b/controller/place.js index 7e660891f..1ec97f997 100644 --- a/controller/place.js +++ b/controller/place.js @@ -6,6 +6,7 @@ const logger = require('pelias-logger').get('api'); const Debug = require('../helper/debug'); const debugLog = new Debug('controller:place'); +// @todo: remove this and replace with the predicate function requestHasErrors(request) { return _.get(request, 'errors', []).length > 0; } @@ -34,20 +35,19 @@ function setup( apiConfig, esclient ){ const operation = retry.operation(operationOptions); //generate Elasticsearch mget entries based on GID - const cmd = req.clean.ids.map( function(id) { + const cmd = req.clean.ids.map((id) => { return { _index: apiConfig.indexName, _id: `${id.source}:${id.layer}:${id.id}` }; }); - logger.debug( '[ES req]', cmd ); - debugLog.push(req, {ES_req: cmd}); + logger.debug('[ES req]', cmd); operation.attempt((currentAttempt) => { - const initialTime = debugLog.beginTimer(req); + const start = Date.now(); - mgetService( esclient, cmd, function( err, docs, data) { + mgetService(esclient, cmd, (err, docs, data) => { const message = { controller: 'place', queryType: 'place', @@ -62,7 +62,10 @@ function setup( apiConfig, esclient ){ // (handles bookkeeping of maxRetries) // only consider for status 408 (request timeout) if (isRequestTimeout(err) && operation.retry(err)) { - debugLog.stopTimer(req, initialTime, `request timed out on attempt ${currentAttempt}, retrying`); + debugLog.push(req, { + warning: `request timed out on attempt ${currentAttempt}, retrying`, + duration: Date.now() - start + }); return; } @@ -88,7 +91,10 @@ function setup( apiConfig, esclient ){ next(); }); - debugLog.stopTimer(req, initialTime); + debugLog.push(req, { + ES_req: cmd, + duration: Date.now() - start + }); }); } diff --git a/controller/placeholder.js b/controller/placeholder.js index 45291ac00..ff0b274f4 100644 --- a/controller/placeholder.js +++ b/controller/placeholder.js @@ -252,9 +252,8 @@ function setup(placeholderService, do_geometric_filters_apply, should_execute) { if (!should_execute(req, res)) { return next(); } - const initialTime = debugLog.beginTimer(req); + const start = Date.now(); - placeholderService(req, (err, results) => { logger.info('placeholder', { response_time: Date.now() - start, @@ -305,7 +304,9 @@ function setup(placeholderService, do_geometric_filters_apply, should_execute) { debugLog.push(req, (results || [])); } - debugLog.stopTimer(req, initialTime); + debugLog.push(req, { + duration: Date.now() - start + }); return next(); }); diff --git a/controller/search.js b/controller/search.js index 992055246..44691d5af 100644 --- a/controller/search.js +++ b/controller/search.js @@ -4,6 +4,7 @@ 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; @@ -17,8 +18,6 @@ function setup( peliasConfig, esclient, query, should_execute ){ return next(); } - const debugLog = new Debug('controller:search'); - let cleanOutput = _.cloneDeep(req.clean); if (logging.isDNT(req)) { cleanOutput = logging.removeFields(cleanOutput); @@ -86,7 +85,8 @@ function setup( peliasConfig, esclient, query, should_execute ){ }); operation.attempt((currentAttempt) => { - const initialTime = debugLog.beginTimer(req, `Attempt ${currentAttempt}`); + const start = Date.now(); + // query elasticsearch searchService( esclient, cmd, function( err, docs, meta, data ){ @@ -113,7 +113,10 @@ function setup( peliasConfig, esclient, query, should_execute ){ // (handles bookkeeping of maxRetries) // only consider for status 408 (request timeout) if (isRequestTimeout(err) && operation.retry(err)) { - debugLog.stopTimer(req, initialTime, 'request timed out, retrying'); + debugLog.push(req, { + warning: `request timed out on attempt ${currentAttempt}, retrying`, + duration: Date.now() - start + }); return; } @@ -160,7 +163,9 @@ function setup( peliasConfig, esclient, query, should_execute ){ } next(); }); - debugLog.stopTimer(req, initialTime); + debugLog.push(req, { + duration: Date.now() - start + }); }); } diff --git a/controller/structured_libpostal.js b/controller/structured_libpostal.js index 6f9f7919f..b6ae94e9d 100644 --- a/controller/structured_libpostal.js +++ b/controller/structured_libpostal.js @@ -1,7 +1,6 @@ const _ = require('lodash'); const Debug = require('../helper/debug'); const debugLog = new Debug('controller:libpostal'); -const logger = require('pelias-logger').get('api'); // Find field in libpostal response function findField(response, field, replacementField) { @@ -24,8 +23,7 @@ function setup(libpostalService, should_execute) { return next(); } - const initialTime = debugLog.beginTimer(req); - + const start = Date.now(); libpostalService(req, (err, response) => { if (err) { // push err.message or err onto req.errors @@ -69,11 +67,12 @@ function setup(libpostalService, should_execute) { // the address field no longer means anything since it's been parsed, so remove it delete req.clean.parsed_text.address; - debugLog.push(req, {parsed_text: response}); - + debugLog.push(req, { + parsed_text: response, + duration: Date.now() - start + }); } - - debugLog.stopTimer(req, initialTime); + return next(); }); diff --git a/helper/debug.js b/helper/debug.js index 7e6b5c76f..7ca37fe42 100644 --- a/helper/debug.js +++ b/helper/debug.js @@ -24,31 +24,6 @@ class Debug { req.debug.push({ [this.name]: value }); } } - - beginTimer(req, message) { - if (!Debug.isEnabled(req)) { return; } - - if (Debug.validMessage(message)) { - this.push(req, `Timer Began. ${message}`); - } else { - this.push(req, `Timer Began.`); - } - - return Date.now(); - } - - stopTimer(req, timer, message) { - if (!Debug.isEnabled(req)) { return; } - - // measure elapsed duration - const elapsed = _.isFinite(timer) ? (Date.now() - timer) : -1; - - if (Debug.validMessage(message)) { - this.push(req, `Timer Stopped. ${elapsed} ms. ${message}`); - } else { - this.push(req, `Timer Stopped. ${elapsed} ms`); - } - } } module.exports = Debug; diff --git a/middleware/interpolate.js b/middleware/interpolate.js index 1f2e0600c..59c8c3ef2 100644 --- a/middleware/interpolate.js +++ b/middleware/interpolate.js @@ -62,9 +62,8 @@ function setup(service, should_execute, interpolationConfiguration) { const street_results = _.get(res, 'data', []).filter(result => result.layer === 'street'); // perform interpolations asynchronously for all relevant hits - const initialTime = debugLog.beginTimer(req); - const startTime = Date.now(); + const start = Date.now(); const logInfo = { controller: 'interpolation', //technically middleware, but stay consistent with other log lines street_count: street_results.length, @@ -148,9 +147,11 @@ function setup(service, should_execute, interpolationConfiguration) { // log and continue - logInfo.total_response_time = Date.now() - startTime; + logInfo.total_response_time = Date.now() - start; logger.info('interpolation', logInfo); - debugLog.stopTimer(req, initialTime); + debugLog.push(req, { + duration: Date.now() - start + }); next(); }); }; diff --git a/test/unit/controller/placeholder.js b/test/unit/controller/placeholder.js index 90f544f89..25834427b 100644 --- a/test/unit/controller/placeholder.js +++ b/test/unit/controller/placeholder.js @@ -197,7 +197,7 @@ module.exports.tests.success = (test, common) => { const logger = mock_logger(); const placeholder_service = (req, callback) => { - t.deepEqual(req, { param1: 'param1 value', clean: { enableDebug: true }, debug: [ { 'controller:placeholder': 'Timer Began.' } ] }); + t.deepEqual(req, { param1: 'param1 value', clean: { enableDebug: true }}); callback(null, response); }; @@ -300,9 +300,8 @@ module.exports.tests.success = (test, common) => { t.deepEquals(res, expected_res); t.ok(logger.isDebugMessage('[controller:placeholder] [result_count:2]')); - t.equal(req.debug[0]['controller:placeholder'], 'Timer Began.'); - t.deepEqual(req.debug[1]['controller:placeholder'], response); - t.match(req.debug[2]['controller:placeholder'], /Timer Stopped. \d+ ms/); + t.deepEqual(req.debug[0]['controller:placeholder'], response); + t.true(req.debug[1]['controller:placeholder'].hasOwnProperty('duration')); t.end(); }); diff --git a/test/unit/helper/debug.js b/test/unit/helper/debug.js index 3eb3002c0..5e7204fc0 100644 --- a/test/unit/helper/debug.js +++ b/test/unit/helper/debug.js @@ -21,18 +21,6 @@ module.exports.tests.debug = function(test, common) { t.end(); }); - test('don\'t start timer if enableDebug is false', (t) => { - const debugLog = new Debug('debugger'); - const req = { - clean: { - enableDebug: false - } - }; - debugLog.beginTimer(req, 'This should not be pushed'); - t.deepEquals(req.debug, undefined); - t.end(); - }); - test('don\'t push debug message if req.clean is empty', (t) => { const debugLog = new Debug('debugger'); const req = { @@ -53,13 +41,9 @@ module.exports.tests.debug = function(test, common) { 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(); }); @@ -80,22 +64,6 @@ module.exports.tests.debug = function(test, common) { 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(); - }); - }; module.exports.all = function (tape, common) {