From f86ee4a40f2202550f27e808c2d96cbeb93acbed Mon Sep 17 00:00:00 2001 From: Adam Rousell Date: Wed, 16 Aug 2017 14:35:29 +0200 Subject: [PATCH 01/11] Added postalcode rules for node-postal call and fallbacks --- middleware/confidenceScoreFallback.js | 20 ++++++++++++++------ middleware/trimByGranularityStructured.js | 2 ++ query/search.js | 16 +++++++++++++++- 3 files changed, 31 insertions(+), 7 deletions(-) diff --git a/middleware/confidenceScoreFallback.js b/middleware/confidenceScoreFallback.js index 472dd841..488bd721 100644 --- a/middleware/confidenceScoreFallback.js +++ b/middleware/confidenceScoreFallback.js @@ -76,6 +76,8 @@ function checkFallbackLevel(req, hit) { return 0.8; case 'street': return 0.8; + case 'postalcode': + return 0.8; case 'localadmin': case 'locality': case 'borough': @@ -137,38 +139,44 @@ const fallbackRules = [ expectedLayers: ['street'] }, { - name: 'neighbourhood', + name: 'postalcode', notSet: ['query', 'number', 'street'], + set: ['postalcode'], + expectedLayers: ['postalcode'] + }, + { + name: 'neighbourhood', + notSet: ['query', 'number', 'street', 'postalcode'], set: ['neighbourhood'], expectedLayers: ['neighbourhood'] }, { name: 'borough', - notSet: ['query', 'number', 'street', 'neighbourhood'], + notSet: ['query', 'number', 'street', 'postalcode', 'neighbourhood'], set: ['borough'], expectedLayers: ['borough'] }, { name: 'city', - notSet: ['query', 'number', 'street', 'neighbourhood', 'borough'], + notSet: ['query', 'number', 'street', 'postalcode', 'neighbourhood', 'borough'], set: ['city'], expectedLayers: ['borough', 'locality', 'localadmin'] }, { name: 'county', - notSet: ['query', 'number', 'street', 'neighbourhood', 'borough', 'city'], + notSet: ['query', 'number', 'street', 'postalcode', 'neighbourhood', 'borough', 'city'], set: ['county'], expectedLayers: ['county'] }, { name: 'state', - notSet: ['query', 'number', 'street', 'neighbourhood', 'borough', 'city', 'county'], + notSet: ['query', 'number', 'street', 'postalcode', 'neighbourhood', 'borough', 'city', 'county'], set: ['state'], expectedLayers: ['region'] }, { name: 'country', - notSet: ['query', 'number', 'street', 'neighbourhood', 'borough', 'city', 'county', 'state'], + notSet: ['query', 'number', 'street', 'postalcode', 'neighbourhood', 'borough', 'city', 'county', 'state'], set: ['country'], expectedLayers: ['country'] } diff --git a/middleware/trimByGranularityStructured.js b/middleware/trimByGranularityStructured.js index 1fe94ce8..5bf4685b 100644 --- a/middleware/trimByGranularityStructured.js +++ b/middleware/trimByGranularityStructured.js @@ -24,6 +24,7 @@ const layers = [ 'venue', 'address', 'street', + 'postalcode', 'neighbourhood', ['borough', 'locality'], 'localadmin', @@ -46,6 +47,7 @@ const explicit_borough_layers = [ 'venue', 'address', 'street', + 'postalcode', 'neighbourhood', 'borough', 'locality', diff --git a/query/search.js b/query/search.js index ce3ac639..991e239c 100644 --- a/query/search.js +++ b/query/search.js @@ -135,7 +135,7 @@ function getQuery(vs) { logger.info(`[query:search] [search_input_type:${determineQueryType(vs)}]`); - if (hasStreet(vs) || isPostalCodeOnly(vs)) { + if (hasStreet(vs) || isPostalCodeOnly(vs) || isPostalCodeWithCountry(vs)) { return { type: 'fallback', body: fallbackQuery.render(vs) @@ -182,4 +182,18 @@ function isPostalCodeOnly(vs) { } + +function isPostalCodeWithCountry(vs) { + var isSet = (layer) => { + return vs.isset(`input:${layer}`); + }; + + var allowedFields = ['postcode', 'country']; + var disallowedFields = ['query', 'category', 'housenumber', 'street', 'locality', + 'neighbourhood', 'borough', 'county', 'region']; + + return allowedFields.every(isSet) && + !disallowedFields.some(isSet); +} + module.exports = generateQuery; From af03e706b21e197a0eb0ba1cc1fe082f22b84c57 Mon Sep 17 00:00:00 2001 From: Lily He Date: Mon, 7 Aug 2017 17:45:59 -0400 Subject: [PATCH 02/11] debug push takes function & beginTimer returns Date --- helper/debug.js | 61 ++++++++++++++++++++++----------------- test/unit/helper/debug.js | 49 ++++++++++++++++++++----------- 2 files changed, 67 insertions(+), 43 deletions(-) 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/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(); }); }; From 7ecf770d790a644cd06786b902d158ad49481b9c Mon Sep 17 00:00:00 2001 From: Lily He Date: Mon, 7 Aug 2017 18:15:03 -0400 Subject: [PATCH 03/11] create stackTraceLine helper to debug predicates --- helper/stackTraceLine.js | 13 +++++++++++++ test/unit/helper/stackTraceLine.js | 20 ++++++++++++++++++++ test/unit/run.js | 1 + 3 files changed, 34 insertions(+) create mode 100644 helper/stackTraceLine.js create mode 100644 test/unit/helper/stackTraceLine.js 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/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 8299672d..328e7fb6 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'), From 9ee50253120091806176e6fae362d0be3737472f Mon Sep 17 00:00:00 2001 From: Lily He Date: Mon, 7 Aug 2017 18:19:02 -0400 Subject: [PATCH 04/11] predicates debugging prints stack trace snippet --- controller/predicates/has_request_errors.js | 12 ++++++++++-- controller/predicates/has_request_parameter.js | 13 ++++++++++++- controller/predicates/has_response_data.js | 10 +++++++++- controller/predicates/has_results_at_layers.js | 12 ++++++++++-- controller/predicates/is_addressit_parse.js | 12 +++++++++++- controller/predicates/is_admin_only_analysis.js | 10 +++++++--- controller/predicates/is_coarse_reverse.js | 7 +++++-- .../predicates/is_only_non_admin_layers.js | 17 +++++++++++++---- .../is_request_sources_only_whosonfirst.js | 16 ++++++++++++---- 9 files changed, 89 insertions(+), 20 deletions(-) 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; +}; From 12a1dcba0891c144cd1ae6c83317d161cde91d7a Mon Sep 17 00:00:00 2001 From: Lily He Date: Mon, 7 Aug 2017 18:21:26 -0400 Subject: [PATCH 05/11] update controller debug timers to new format --- controller/coarse_reverse.js | 7 +++++-- controller/libpostal.js | 6 ++++-- controller/place.js | 7 ++++++- controller/placeholder.js | 5 +++++ controller/search.js | 13 ++++++++----- controller/search_with_ids.js | 13 ++++++++++++- 6 files changed, 40 insertions(+), 11 deletions(-) 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); }); } From ad1d88ac628d84f7101d83ce27966ee47e54f1f4 Mon Sep 17 00:00:00 2001 From: Lily He Date: Thu, 10 Aug 2017 15:29:17 -0400 Subject: [PATCH 06/11] log libpostal and placeholder responses to debug --- controller/libpostal.js | 1 + controller/placeholder.js | 1 + 2 files changed, 2 insertions(+) diff --git a/controller/libpostal.js b/controller/libpostal.js index 9a034ac2..8f275dd9 100644 --- a/controller/libpostal.js +++ b/controller/libpostal.js @@ -21,6 +21,7 @@ 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/placeholder.js b/controller/placeholder.js index 9245351b..edba469a 100644 --- a/controller/placeholder.js +++ b/controller/placeholder.js @@ -267,6 +267,7 @@ 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); From 9405a8f3707f91514901f88706b13d917b636166 Mon Sep 17 00:00:00 2001 From: Lily He Date: Thu, 7 Sep 2017 16:46:56 -0400 Subject: [PATCH 07/11] correct timer timings for controller debug logs --- controller/place.js | 6 ++++-- controller/search.js | 6 +++--- controller/search_with_ids.js | 6 +++--- 3 files changed, 10 insertions(+), 8 deletions(-) diff --git a/controller/place.js b/controller/place.js index c96c34b6..2b5490aa 100644 --- a/controller/place.js +++ b/controller/place.js @@ -22,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 @@ -47,13 +47,15 @@ function setup( apiConfig, esclient ){ 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, retrying'); + debugLog.stopTimer(req, initialTime, `request timed out on attempt ${currentAttempt}, retrying`); return; } diff --git a/controller/search.js b/controller/search.js index ba8250ce..721c0dde 100644 --- a/controller/search.js +++ b/controller/search.js @@ -18,8 +18,7 @@ function setup( apiConfig, esclient, query, should_execute ){ return next(); } - const debugLog = new Debug(req, 'controller:search'); - const initialTime = debugLog.beginTimer(req); + const debugLog = new Debug('controller:search'); let cleanOutput = _.cloneDeep(req.clean); if (logging.isDNT(req)) { @@ -32,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, initialTime, 'No query to call ES with. Skipping'); + debugLog.push(req, 'No query to call ES with. Skipping'); return next(); } @@ -59,6 +58,7 @@ function setup( apiConfig, esclient, query, should_execute ){ 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 diff --git a/controller/search_with_ids.js b/controller/search_with_ids.js index 15694d5f..75c14aea 100644 --- a/controller/search_with_ids.js +++ b/controller/search_with_ids.js @@ -17,7 +17,6 @@ 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); @@ -29,7 +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.stopTimer(req, initialTime, 'No query to call ES with. Skipping'); + debugLog.push(req, `No query to call ES with. Skipping`); return next(); } @@ -56,6 +55,7 @@ function setup( apiConfig, esclient, query, should_execute ){ 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 +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'); + debugLog.stopTimer(req, initialTime, `request timed out on attempt ${currentAttempt}, retrying`); return; } From d298ef495a03fe7895466215a32d294357b12c7f Mon Sep 17 00:00:00 2001 From: Julian Simioni Date: Fri, 8 Sep 2017 16:07:07 -0400 Subject: [PATCH 08/11] Skip CI Docker Image builds on Greenkeeper branches We most likely will not want these Docker images and they can fail due to characters in branch names that are not valid in Docker image tags. Note: because CircleCI appears to allow only using sh, rather than bash, we use the method from https://stackoverflow.com/questions/229551/string-contains-in-bash/20460402#2046040 Fixes https://github.com/pelias/api/issues/975 --- .circleci/docker.sh | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/.circleci/docker.sh b/.circleci/docker.sh index 562de3db..655799d4 100644 --- a/.circleci/docker.sh +++ b/.circleci/docker.sh @@ -6,6 +6,11 @@ DATE=`date +%Y-%m-%d` DOCKER_REPOSITORY="pelias" DOCKER_PROJECT="${DOCKER_REPOSITORY}/${CIRCLE_PROJECT_REPONAME}" +# skip builds on greenkeeper branches +if [ "${CIRCLE_BRANCH##greenkeeper}" ]; then + exit 0 +fi + # the name of the image that represents the "branch", that is an image that will be updated over time with the git branch # the production branch is changed to "latest", otherwise the git branch becomes the name of the version if [[ "${CIRCLE_BRANCH}" == "production" ]]; then From 8d7c01dcbe9182d62da579b1d8f744984ecc8084 Mon Sep 17 00:00:00 2001 From: Adam Rousell Date: Tue, 12 Sep 2017 09:24:57 +0200 Subject: [PATCH 09/11] Added tests for postcode fix --- .../middleware/confidenceScoreFallback.js | 51 +++++++++++++++++++ .../middleware/trimByGranularityStructured.js | 46 +++++++++++++++++ 2 files changed, 97 insertions(+) diff --git a/test/unit/middleware/confidenceScoreFallback.js b/test/unit/middleware/confidenceScoreFallback.js index 3e783de7..7bca1c33 100644 --- a/test/unit/middleware/confidenceScoreFallback.js +++ b/test/unit/middleware/confidenceScoreFallback.js @@ -442,6 +442,57 @@ module.exports.tests.confidenceScore = function(test, common) { t.equal(res.data[0].match_type, 'fallback', 'fallback match indicated'); t.end(); }); + + test('address fallback to postal code should have a score set to 0.8', function(t) { + var req = { + clean: { + text: '123 Main St, City, NM, USA, 1234', + parsed_text: { + number: 123, + street: 'Main St', + state: 'NM', + country: 'USA', + postalcode: '1234' + } + } + }; + var res = { + data: [{ + layer: 'postalcode' + }], + meta: { + query_type: 'fallback' + } + }; + confidenceScore(req, res, function() {}); + t.equal(res.data[0].confidence, 0.8, 'score was set'); + t.equal(res.data[0].match_type, 'fallback', 'fallback match indicated'); + t.end(); + }); + + test('matching address search with postalcode and country should have an exact match with score of 1.0', function(t) { + var req = { + clean: { + text: 'USA, 1234', + parsed_text: { + country: 'USA', + postalcode: '1234' + } + } + }; + var res = { + data: [{ + layer: 'postalcode' + }], + meta: { + query_type: 'fallback' + } + }; + confidenceScore(req, res, function() {}); + t.equal(res.data[0].confidence, 1, 'score was set'); + t.equal(res.data[0].match_type, 'exact', 'exact match indicated'); + t.end(); + }); }; diff --git a/test/unit/middleware/trimByGranularityStructured.js b/test/unit/middleware/trimByGranularityStructured.js index 8e5fe498..17025a57 100644 --- a/test/unit/middleware/trimByGranularityStructured.js +++ b/test/unit/middleware/trimByGranularityStructured.js @@ -21,6 +21,7 @@ module.exports.tests.trimByGranularity = function(test, common) { { name: 'venue 2', _matched_queries: ['fallback.venue'] }, { name: 'address 1', _matched_queries: ['fallback.address'] }, { name: 'street 1', _matched_queries: ['fallback.street'] }, + { name: 'postalcode 1', _matched_queries: ['fallback.postalcode'] }, { name: 'neighbourhood 1', _matched_queries: ['fallback.neighbourhood'] }, { name: 'borough 1', _matched_queries: ['fallback.borough'] }, { name: 'locality 1', _matched_queries: ['fallback.locality'] }, @@ -58,6 +59,7 @@ module.exports.tests.trimByGranularity = function(test, common) { { name: 'address 1', _matched_queries: ['fallback.address'] }, { name: 'address 2', _matched_queries: ['fallback.address'] }, { name: 'street 1', _matched_queries: ['fallback.street'] }, + { name: 'postalcode 1', _matched_queries: ['fallback.postalcode'] }, { name: 'neighbourhood 1', _matched_queries: ['fallback.neighbourhood'] }, { name: 'borough 1', _matched_queries: ['fallback.borough'] }, { name: 'locality 1', _matched_queries: ['fallback.locality'] }, @@ -94,6 +96,7 @@ module.exports.tests.trimByGranularity = function(test, common) { data: [ { name: 'street 1', _matched_queries: ['fallback.street'] }, { name: 'street 2', _matched_queries: ['fallback.street'] }, + { name: 'postalcode 1', _matched_queries: ['fallback.postalcode'] }, { name: 'neighbourhood 1', _matched_queries: ['fallback.neighbourhood'] }, { name: 'borough 1', _matched_queries: ['fallback.borough'] }, { name: 'locality 1', _matched_queries: ['fallback.locality'] }, @@ -122,6 +125,49 @@ module.exports.tests.trimByGranularity = function(test, common) { testIt(); }); + + test('all records with fallback.* matched_queries name should retain only postalcodes when they are most granular', function(t) { + var req = { + clean: { + parsed_text: { + borough: 'borough value' + } + } + }; + + var res = { + data: [ + { name: 'postalcode 1', _matched_queries: ['fallback.postalcode'] }, + { name: 'postalcode 2', _matched_queries: ['fallback.postalcode'] }, + { name: 'neighbourhood 1', _matched_queries: ['fallback.neighbourhood'] }, + { name: 'borough 1', _matched_queries: ['fallback.borough'] }, + { name: 'borough 2', _matched_queries: ['fallback.borough'] }, + { name: 'locality 1', _matched_queries: ['fallback.locality'] }, + { name: 'localadmin 1', _matched_queries: ['fallback.localadmin'] }, + { name: 'county 1', _matched_queries: ['fallback.county'] }, + { name: 'macrocounty 1', _matched_queries: ['fallback.macrocounty'] }, + { name: 'region 1', _matched_queries: ['fallback.region'] }, + { name: 'macroregion 1', _matched_queries: ['fallback.macroregion'] }, + { name: 'dependency 1', _matched_queries: ['fallback.dependency'] }, + { name: 'country 1', _matched_queries: ['fallback.country'] }, + { name: 'unknown', _matched_queries: ['fallback.unknown'] } + ] + }; + + var expected_data = [ + { name: 'postalcode 1', _matched_queries: ['fallback.postalcode'] }, + { name: 'postalcode 2', _matched_queries: ['fallback.postalcode'] }, + ]; + + function testIt() { + trimByGranularity(req, res, function() { + t.deepEquals(res.data, expected_data, 'only postalcode records should be here'); + t.end(); + }); + } + + testIt(); + }); test('all records with fallback.* matched_queries name should retain only neighbourhoods when they are most granular', function(t) { var req = { clean: {} }; From 0b8925f318974434f11240492bb58445dfb4db22 Mon Sep 17 00:00:00 2001 From: "greenkeeper[bot]" Date: Thu, 14 Sep 2017 16:41:52 +0000 Subject: [PATCH 10/11] fix(package): update joi to version 11.0.1 Closes #987 --- package.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/package.json b/package.json index 43a4f7e3..c5f731a9 100644 --- a/package.json +++ b/package.json @@ -49,7 +49,7 @@ "geolib": "^2.0.18", "iso-639-3": "^1.0.0", "iso3166-1": "^0.3.0", - "joi": "^10.5.2", + "joi": "^11.0.1", "locale": "^0.1.0", "lodash": "^4.17.4", "markdown": "0.5.0", From 4f74818742ca765449de672e96243fd31b3a305f Mon Sep 17 00:00:00 2001 From: Julian Simioni Date: Thu, 14 Sep 2017 12:56:35 -0400 Subject: [PATCH 11/11] Fix CircleCI script to skip Greenkeeper branch builds Somehow I completely failed at copying code [from StackOverflow](https://speakerdeck.com/noelrap/the-road-to-legacy-is-paved-with-good-intentions) in https://github.com/pelias/api/pull/983. Instead of skipping Docker image builds only for branches with greenkeeper in the name, it _always_ skipped the build! Connects https://github.com/pelias/dockerfiles/issues/21 --- .circleci/docker.sh | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.circleci/docker.sh b/.circleci/docker.sh index 655799d4..1acd51cb 100644 --- a/.circleci/docker.sh +++ b/.circleci/docker.sh @@ -7,7 +7,7 @@ DOCKER_REPOSITORY="pelias" DOCKER_PROJECT="${DOCKER_REPOSITORY}/${CIRCLE_PROJECT_REPONAME}" # skip builds on greenkeeper branches -if [ "${CIRCLE_BRANCH##greenkeeper}" ]; then +if [[ -z "${CIRCLE_BRANCH##*greenkeeper*}" ]]; then exit 0 fi