From cafb7d9277401638108b2de2b9c2439ec6303006 Mon Sep 17 00:00:00 2001 From: Lily He Date: Thu, 3 Aug 2017 17:38:11 -0400 Subject: [PATCH 1/2] created new debug helper class and debug sanitizer --- helper/debug.js | 43 +++++ middleware/geocodeJSON.js | 1 + sanitizer/_debug.js | 23 +++ sanitizer/autocomplete.js | 1 + sanitizer/defer_to_addressit.js | 1 + sanitizer/nearby.js | 1 + sanitizer/place.js | 1 + sanitizer/reverse.js | 1 + sanitizer/search.js | 1 + sanitizer/search_fallback.js | 29 --- sanitizer/structured_geocoding.js | 1 + test/unit/helper/debug.js | 95 ++++++++++ test/unit/run.js | 2 + test/unit/sanitizer/_debug.js | 65 +++++++ test/unit/sanitizer/autocomplete.js | 9 + test/unit/sanitizer/defer_to_addressit.js | 43 ++++- test/unit/sanitizer/nearby.js | 9 + test/unit/sanitizer/place.js | 9 + test/unit/sanitizer/reverse.js | 9 + test/unit/sanitizer/search.js | 9 + test/unit/sanitizer/search_fallback.js | 197 -------------------- test/unit/sanitizer/structured_geocoding.js | 9 + 22 files changed, 327 insertions(+), 232 deletions(-) create mode 100644 helper/debug.js create mode 100644 sanitizer/_debug.js delete mode 100644 sanitizer/search_fallback.js create mode 100644 test/unit/helper/debug.js create mode 100644 test/unit/sanitizer/_debug.js delete mode 100644 test/unit/sanitizer/search_fallback.js diff --git a/helper/debug.js b/helper/debug.js new file mode 100644 index 00000000..13a90c1a --- /dev/null +++ b/helper/debug.js @@ -0,0 +1,43 @@ +'use strict'; +const _ = require('lodash'); + +class Debug { + constructor(moduleName){ + 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}`); + } + } + // 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`); + } + } + } + + 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`); + } + } + } +} + +module.exports = Debug; diff --git a/middleware/geocodeJSON.js b/middleware/geocodeJSON.js index 442e017e..75cfd301 100644 --- a/middleware/geocodeJSON.js +++ b/middleware/geocodeJSON.js @@ -64,6 +64,7 @@ function convertToGeocodeJSON(req, res, next, opts) { // OPTIONAL. Warnings and errors. addMessages(req, 'warnings', res.body.geocoding); addMessages(req, 'errors', res.body.geocoding); + addMessages(req, 'debug', res.body.geocoding); // OPTIONAL // Freeform diff --git a/sanitizer/_debug.js b/sanitizer/_debug.js new file mode 100644 index 00000000..809abf32 --- /dev/null +++ b/sanitizer/_debug.js @@ -0,0 +1,23 @@ +var _ = require('lodash'); + +function _sanitize(raw, clean){ + const messages = {errors: [], warnings: []}; + + if(!_.isUndefined(raw.debug) ){ + clean.enableDebug = (typeof raw.debug === 'string') ? isTruthy(raw.debug.toLowerCase()) : isTruthy( raw.debug ); + } + return messages; +} + +function _expected() { + return [{ name: 'debug' }]; +} + +function isTruthy(val) { + return _.includes( ['true', '1', 1, true], val ); +} + +module.exports = () => ({ + sanitize: _sanitize, + expected: _expected +}); diff --git a/sanitizer/autocomplete.js b/sanitizer/autocomplete.js index 85fcec86..c26a3b44 100644 --- a/sanitizer/autocomplete.js +++ b/sanitizer/autocomplete.js @@ -5,6 +5,7 @@ var sanitizeAll = require('../sanitizer/sanitizeAll'); module.exports.middleware = (_api_pelias_config) => { var sanitizers = { singleScalarParameters: require('../sanitizer/_single_scalar_parameters')(), + debug: require('../sanitizer/_debug')(), text: require('../sanitizer/_text_addressit')(), tokenizer: require('../sanitizer/_tokenizer')(), size: require('../sanitizer/_size')(10, 10, 10), diff --git a/sanitizer/defer_to_addressit.js b/sanitizer/defer_to_addressit.js index 7fa47e6c..0f53eda5 100644 --- a/sanitizer/defer_to_addressit.js +++ b/sanitizer/defer_to_addressit.js @@ -1,5 +1,6 @@ const sanitizeAll = require('../sanitizer/sanitizeAll'), sanitizers = { + debug: require('../sanitizer/_debug')(), text: require('../sanitizer/_text_addressit')() }; diff --git a/sanitizer/nearby.js b/sanitizer/nearby.js index a26b93a3..8aa727bd 100644 --- a/sanitizer/nearby.js +++ b/sanitizer/nearby.js @@ -4,6 +4,7 @@ var type_mapping = require('../helper/type_mapping'); // add categories to the sanitizer list var sanitizers = { singleScalarParameters: require('../sanitizer/_single_scalar_parameters')(), + debug: require('../sanitizer/_debug')(), quattroshapes_deprecation: require('../sanitizer/_deprecate_quattroshapes')(), layers: require('../sanitizer/_targets')('layers', type_mapping.layer_mapping), sources: require('../sanitizer/_targets')('sources', type_mapping.source_mapping), diff --git a/sanitizer/place.js b/sanitizer/place.js index 4ab7af16..ce220d64 100644 --- a/sanitizer/place.js +++ b/sanitizer/place.js @@ -2,6 +2,7 @@ var sanitizeAll = require('../sanitizer/sanitizeAll'), sanitizers = { singleScalarParameters: require('../sanitizer/_single_scalar_parameters')(), + debug: require('../sanitizer/_debug')(), ids: require('../sanitizer/_ids')(), private: require('../sanitizer/_flag_bool')('private', false) }; diff --git a/sanitizer/reverse.js b/sanitizer/reverse.js index 1ecb92e1..f43d0845 100644 --- a/sanitizer/reverse.js +++ b/sanitizer/reverse.js @@ -3,6 +3,7 @@ var type_mapping = require('../helper/type_mapping'); var sanitizeAll = require('../sanitizer/sanitizeAll'), sanitizers = { singleScalarParameters: require('../sanitizer/_single_scalar_parameters')(), + debug: require('../sanitizer/_debug')(), quattroshapes_deprecation: require('../sanitizer/_deprecate_quattroshapes')(), layers: require('../sanitizer/_targets')('layers', type_mapping.layer_mapping), sources: require('../sanitizer/_targets')('sources', type_mapping.source_mapping), diff --git a/sanitizer/search.js b/sanitizer/search.js index 9db5f900..c8e7282f 100644 --- a/sanitizer/search.js +++ b/sanitizer/search.js @@ -4,6 +4,7 @@ var sanitizeAll = require('../sanitizer/sanitizeAll'); module.exports.middleware = (_api_pelias_config) => { var sanitizers = { singleScalarParameters: require('../sanitizer/_single_scalar_parameters')(), + debug: require('../sanitizer/_debug')(), quattroshapes_deprecation: require('../sanitizer/_deprecate_quattroshapes')(), text: require('../sanitizer/_text')(), size: require('../sanitizer/_size')(/* use defaults*/), diff --git a/sanitizer/search_fallback.js b/sanitizer/search_fallback.js deleted file mode 100644 index 6c8297be..00000000 --- a/sanitizer/search_fallback.js +++ /dev/null @@ -1,29 +0,0 @@ -var sanitizeAll = require('../sanitizer/sanitizeAll'), - sanitizers = { - text: require('../sanitizer/_text_addressit')() - }; - -var logger = require('pelias-logger').get('api'); -var logging = require( '../helper/logging' ); -var _ = require('lodash'); - -// middleware -module.exports.middleware = function( req, res, next ){ - // if res.data already has results then don't call the _text_autocomplete sanitizer - // this has been put into place for when the libpostal integration way of querying - // ES doesn't return anything and we want to fallback to the old logic - if (_.get(res, 'data', []).length > 0) { - return next(); - } - - // log the query that caused a fallback since libpostal+new-queries didn't return anything - if (req.path === '/v1/search') { - const queryText = logging.isDNT(req) ? '[text removed]' : req.clean.text; - logger.info(`fallback queryText: ${queryText}`); - } - // calls to sanitize the input - // omits check if parameters are valid since it only calls _text_addressit - sanitizeAll.sanitize(req, sanitizers); - next(); - -}; diff --git a/sanitizer/structured_geocoding.js b/sanitizer/structured_geocoding.js index b84d843c..388949ea 100644 --- a/sanitizer/structured_geocoding.js +++ b/sanitizer/structured_geocoding.js @@ -5,6 +5,7 @@ var sanitizeAll = require('../sanitizer/sanitizeAll'); module.exports.middleware = (_api_pelias_config) => { var sanitizers = { singleScalarParameters: require('../sanitizer/_single_scalar_parameters')(), + debug: require('../sanitizer/_debug')(), quattroshapes_deprecation: require('../sanitizer/_deprecate_quattroshapes')(), synthesize_analysis: require('../sanitizer/_synthesize_analysis')(), iso2_to_iso3: require('../sanitizer/_iso2_to_iso3')(), diff --git a/test/unit/helper/debug.js b/test/unit/helper/debug.js new file mode 100644 index 00000000..319b3af6 --- /dev/null +++ b/test/unit/helper/debug.js @@ -0,0 +1,95 @@ +const Debug = require('../../../helper/debug'); + +module.exports.tests = {}; + +module.exports.tests.debug = function(test, common) { + test('initialize the debugger with a name', (t) => { + const debugLog = new Debug('debugger'); + t.deepEquals(debugLog.name, 'debugger'); + t.end(); + }); + + test('don\'t push debug message if enableDebug is false', (t) => { + const debugLog = new Debug('debugger'); + const req = { + clean: { + enableDebug: false + } + }; + debugLog.push(req, 'This should not be pushed'); + t.deepEquals(req.debug, undefined); + 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 = { + clean: {} + }; + debugLog.push('This should not be pushed'); + t.deepEquals(req.debug, undefined); + t.end(); + }); + + test('Push messages if enableDebug is true', (t) => { + const debugLog = new Debug('debugger'); + const req = { + clean: { + enableDebug: true + } + }; + const expected_req = { + debug: [ + { + debugger: 'This should be pushed' + }, + { + debugger: 'Timer Began: Timer 1' + } + ] + }; + debugLog.push(req, 'This should be pushed'); + debugLog.beginTimer(req, 'Timer 1'); + t.end(); + }); + + test('Timer should return positive number of milliseconds', (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); + + }); + +}; + +module.exports.all = function (tape, common) { + + function test(name, testFunction) { + return tape('[helper] debug: ' + 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 d95c0e45..e616231e 100644 --- a/test/unit/run.js +++ b/test/unit/run.js @@ -29,6 +29,7 @@ var tests = [ require('./controller/predicates/is_only_non_admin_layers'), require('./controller/predicates/is_request_sources_only_whosonfirst'), require('./controller/predicates/is_service_enabled'), + require('./helper/debug'), require('./helper/diffPlaces'), require('./helper/geojsonify'), require('./helper/logging'), @@ -63,6 +64,7 @@ var tests = [ require('./query/structured_geocoding'), require('./query/text_parser'), require('./sanitizer/_boundary_country'), + require('./sanitizer/_debug'), require('./sanitizer/_flag_bool'), require('./sanitizer/_geonames_deprecation'), require('./sanitizer/_geonames_warnings'), diff --git a/test/unit/sanitizer/_debug.js b/test/unit/sanitizer/_debug.js new file mode 100644 index 00000000..61dfe8bc --- /dev/null +++ b/test/unit/sanitizer/_debug.js @@ -0,0 +1,65 @@ +const sanitizer = require('../../../sanitizer/_debug')(); + +module.exports.tests = {}; + +module.exports.tests.sanitize_debug = function(test, common) { + ['true', '1', 1, true, 'TRUE', 'TrUe'].forEach((value) => { + test('debug flag is on', function(t) { + const raw = { debug: value }; + const clean = {}; + const expected_clean = { enableDebug: true }; + + const messages = sanitizer.sanitize(raw, clean); + + t.deepEquals(clean, expected_clean); + t.deepEqual(messages.errors, [], 'no error returned'); + t.deepEqual(messages.warnings, [], 'no warnings returned'); + t.end(); + }); + }); + + ['false', false, '0', 0, 'value', {}].forEach((value) => { + test('non-truthy values should set clean.debug to false', function(t) { + const raw = { debug: value }; + const clean = {}; + const expected_clean = { enableDebug: false }; + + const messages = sanitizer.sanitize(raw, clean); + + t.deepEquals(clean, expected_clean); + t.deepEqual(messages.errors, [], 'no error returned'); + t.deepEqual(messages.warnings, [], 'no warnings returned'); + t.end(); + }); + }); + + test('undefined default flag should not set clean.debug', function(t) { + const raw = {}; + const clean = {}; + const expected_clean = {}; + + const messages = sanitizer.sanitize(raw, clean); + + t.deepEquals(clean, expected_clean); + t.deepEqual(messages.errors, [], 'no error returned'); + t.deepEqual(messages.warnings, [], 'no warnings returned'); + t.end(); + }); + + test('return an array of expected parameters in object form for validation', (t) => { + const expected = [{ name: 'debug' }]; + const validParameters = sanitizer.expected(); + t.deepEquals(validParameters, expected); + t.end(); + }); +}; + +module.exports.all = function (tape, common) { + function test(name, testFunction) { + return tape('SANITIZE _debug ' + name, testFunction); + } + + for( var testCase in module.exports.tests ){ + module.exports.tests[testCase](test, common); + } +}; diff --git a/test/unit/sanitizer/autocomplete.js b/test/unit/sanitizer/autocomplete.js index db46765e..dadb546e 100644 --- a/test/unit/sanitizer/autocomplete.js +++ b/test/unit/sanitizer/autocomplete.js @@ -16,6 +16,14 @@ module.exports.tests.sanitizers = function(test, common) { } }; }, + '../sanitizer/_debug': () => { + return { + sanitize: () => { + called_sanitizers.push('_debug'); + return { errors: [], warnings: [] }; + } + }; + }, '../sanitizer/_text_addressit': function () { return { sanitize: () => { @@ -117,6 +125,7 @@ module.exports.tests.sanitizers = function(test, common) { const expected_sanitizers = [ '_single_scalar_parameters', + '_debug', '_text_addressit', '_tokenizer', '_size', diff --git a/test/unit/sanitizer/defer_to_addressit.js b/test/unit/sanitizer/defer_to_addressit.js index 156d575a..b0971cbf 100644 --- a/test/unit/sanitizer/defer_to_addressit.js +++ b/test/unit/sanitizer/defer_to_addressit.js @@ -19,7 +19,14 @@ module.exports.tests.sanitize = (test, common) => { } }; }, - 'pelias-logger': logger + 'pelias-logger': logger, + '../sanitizer/_debug': () => { + return { + sanitize: () => { + t.fail('_debug should not have been called'); + } + }; + } })(() => false); defer_to_addressit({}, {}, () => { @@ -30,7 +37,7 @@ module.exports.tests.sanitize = (test, common) => { }); test('verify that _text_addressit sanitizer was called when should_execute returns true', (t) => { - t.plan(2); + t.plan(3); const logger = mock_logger(); @@ -48,7 +55,15 @@ module.exports.tests.sanitize = (test, common) => { 'pelias-logger': logger, '../helper/logging': { isDNT: () => false - } + }, + '../sanitizer/_debug': () => { + return { + sanitize: () => { + t.pass('_debug should have been called'); + return { errors: [], warnings: [] }; + } + }; + }, })(() => true); const req = { @@ -66,7 +81,7 @@ module.exports.tests.sanitize = (test, common) => { }); test('query should not be logged if path != \'/v1/search\'', (t) => { - t.plan(2); + t.plan(3); const logger = mock_logger(); @@ -81,7 +96,15 @@ module.exports.tests.sanitize = (test, common) => { } }; }, - 'pelias-logger': logger + 'pelias-logger': logger, + '../sanitizer/_debug': () => { + return { + sanitize: () => { + t.pass('_debug should have been called'); + return { errors: [], warnings: [] }; + } + }; + }, })(() => true); const req = { @@ -99,7 +122,7 @@ module.exports.tests.sanitize = (test, common) => { }); test('query should be logged as [text removed] if private', (t) => { - t.plan(2); + t.plan(3); const logger = mock_logger(); @@ -117,6 +140,14 @@ module.exports.tests.sanitize = (test, common) => { 'pelias-logger': logger, '../helper/logging': { isDNT: () => true + }, + '../sanitizer/_debug': () => { + return { + sanitize: () => { + t.pass('_debug should have been called'); + return { errors: [], warnings: [] }; + } + }; } })(() => true); diff --git a/test/unit/sanitizer/nearby.js b/test/unit/sanitizer/nearby.js index d2d11f1f..a9ea6db6 100644 --- a/test/unit/sanitizer/nearby.js +++ b/test/unit/sanitizer/nearby.js @@ -18,6 +18,14 @@ module.exports.tests.sanitize = function(test, common) { } }; }, + '../sanitizer/_debug': () => { + return { + sanitize: () => { + called_sanitizers.push('_debug'); + return { errors: [], warnings: [] }; + } + }; + }, '../sanitizer/_deprecate_quattroshapes': function () { return { sanitize: () => { @@ -106,6 +114,7 @@ module.exports.tests.sanitize = function(test, common) { const expected_sanitizers = [ '_single_scalar_parameters', + '_debug', '_deprecate_quattroshapes', '_targets/layers', '_targets/sources', diff --git a/test/unit/sanitizer/place.js b/test/unit/sanitizer/place.js index b55946f8..2a47e391 100644 --- a/test/unit/sanitizer/place.js +++ b/test/unit/sanitizer/place.js @@ -18,6 +18,14 @@ module.exports.tests.sanitize = function(test, common) { } }; }, + '../sanitizer/_debug': () => { + return { + sanitize: () => { + called_sanitizers.push('_debug'); + return { errors: [], warnings: [] }; + } + }; + }, '../sanitizer/_ids': function () { return { sanitize: () => { @@ -42,6 +50,7 @@ module.exports.tests.sanitize = function(test, common) { const expected_sanitizers = [ '_single_scalar_parameters', + '_debug', '_ids', '_flag_bool' ]; diff --git a/test/unit/sanitizer/reverse.js b/test/unit/sanitizer/reverse.js index cb1edf9c..aafaa6e9 100644 --- a/test/unit/sanitizer/reverse.js +++ b/test/unit/sanitizer/reverse.js @@ -18,6 +18,14 @@ module.exports.tests.sanitize = function(test, common) { } }; }, + '../sanitizer/_debug': () => { + return { + sanitize: () => { + called_sanitizers.push('_debug'); + return { errors: [], warnings: [] }; + } + }; + }, '../sanitizer/_deprecate_quattroshapes': function () { return { sanitize: () => { @@ -98,6 +106,7 @@ module.exports.tests.sanitize = function(test, common) { const expected_sanitizers = [ '_single_scalar_parameters', + '_debug', '_deprecate_quattroshapes', '_targets/layers', '_targets/sources', diff --git a/test/unit/sanitizer/search.js b/test/unit/sanitizer/search.js index 420c3a87..e4192029 100644 --- a/test/unit/sanitizer/search.js +++ b/test/unit/sanitizer/search.js @@ -30,6 +30,14 @@ module.exports.tests.sanitize = (test, common) => { } }; }, + '../sanitizer/_debug': () => { + return { + sanitize: () => { + called_sanitizers.push('_debug'); + return { errors: [], warnings: [] }; + } + }; + }, '../sanitizer/_text': function () { return { sanitize: () => { @@ -131,6 +139,7 @@ module.exports.tests.sanitize = (test, common) => { const expected_sanitizers = [ '_single_scalar_parameters', + '_debug', '_deprecate_quattroshapes', '_text', '_size', diff --git a/test/unit/sanitizer/search_fallback.js b/test/unit/sanitizer/search_fallback.js deleted file mode 100644 index 49c7294b..00000000 --- a/test/unit/sanitizer/search_fallback.js +++ /dev/null @@ -1,197 +0,0 @@ -var proxyquire = require('proxyquire').noCallThru(); - -module.exports.tests = {}; - -module.exports.tests.sanitize = function(test, common) { - test('verify that all sanitizers were called as expected when `res` is undefined', function(t) { - var called_sanitizers = []; - - // rather than re-verify the functionality of all the sanitizers, this test just verifies that they - // were all called correctly - var search = proxyquire('../../../sanitizer/search_fallback', { - '../sanitizer/_text_addressit': function () { - return { - sanitize: () => { - called_sanitizers.push('_text_addressit'); - return { errors: [], warnings: [] }; - } - }; - } - }); - - var expected_sanitizers = [ - '_text_addressit' - ]; - - var req = {}; - - search.middleware(req, undefined, function(){ - t.deepEquals(called_sanitizers, expected_sanitizers); - t.end(); - }); - - }); - - test('verify that all sanitizers were called as expected when `res` has no `data` property', function(t) { - var called_sanitizers = []; - - // rather than re-verify the functionality of all the sanitizers, this test just verifies that they - // were all called correctly - var search = proxyquire('../../../sanitizer/search_fallback', { - '../sanitizer/_text_addressit': function () { - return { - sanitize: () => { - called_sanitizers.push('_text_addressit'); - return { errors: [], warnings: [] }; - } - }; - }, - }); - - var expected_sanitizers = [ - '_text_addressit' - ]; - - var req = {}; - var res = {}; - - search.middleware(req, res, function(){ - t.deepEquals(called_sanitizers, expected_sanitizers); - t.end(); - }); - - }); - - test('verify that all sanitizers were called as expected when res.data is empty', function(t) { - var called_sanitizers = []; - - // rather than re-verify the functionality of all the sanitizers, this test just verifies that they - // were all called correctly - var search = proxyquire('../../../sanitizer/search_fallback', { - '../sanitizer/_text_addressit': function () { - return { - sanitize: () => { - called_sanitizers.push('_text_addressit'); - return { errors: [], warnings: [] }; - } - }; - }, - }); - - var expected_sanitizers = [ - '_text_addressit' - ]; - - var req = {}; - var res = { - data: [] - }; - - search.middleware(req, res, function(){ - t.deepEquals(called_sanitizers, expected_sanitizers); - t.end(); - }); - - }); - - test('non-empty res.data should not call the _text_autocomplete sanitizer', function(t) { - var called_sanitizers = []; - - // rather than re-verify the functionality of all the sanitizers, this test just verifies that they - // were all called correctly - var search = proxyquire('../../../sanitizer/search_fallback', { - '../sanitizer/_text_autocomplete': function() { - throw new Error('_text_autocomplete sanitizer should not have been called'); - } - }); - - var expected_sanitizers = []; - - var req = {}; - var res = { - data: [{}] - }; - - search.middleware(req, res, function(){ - t.deepEquals(called_sanitizers, expected_sanitizers); - t.end(); - }); - - }); - - test('req.clean.text should be logged when isDNT=false', (t) => { - const infoLog = []; - - const search = proxyquire('../../../sanitizer/search_fallback', { - 'pelias-logger': { - get: () => { - return { - info: (msg) => { - infoLog.push(msg); - } - }; - } - }, - '../helper/logging': { - isDNT: () => { return false; } - } - }); - - const req = { - path: '/v1/search', - clean: { - text: 'this is the query text' - } - }; - - search.middleware(req, undefined, () => { - t.deepEquals(infoLog, [`fallback queryText: ${req.clean.text}`]); - t.end(); - }); - - }); - - test('req.clean.text should not be logged when isDNT=true', (t) => { - const infoLog = []; - - const search = proxyquire('../../../sanitizer/search_fallback', { - 'pelias-logger': { - get: () => { - return { - info: (msg) => { - infoLog.push(msg); - } - }; - } - }, - '../helper/logging': { - isDNT: () => { return true; } - } - }); - - const req = { - path: '/v1/search', - clean: { - text: 'this is the query text' - } - }; - - search.middleware(req, undefined, () => { - t.deepEquals(infoLog, ['fallback queryText: [text removed]']); - t.end(); - }); - - }); - -}; - -module.exports.all = function (tape, common) { - - function test(name, testFunction) { - return tape('SANITIZE /search_fallback ' + name, testFunction); - } - - for( var testCase in module.exports.tests ){ - module.exports.tests[testCase](test, common); - } -}; diff --git a/test/unit/sanitizer/structured_geocoding.js b/test/unit/sanitizer/structured_geocoding.js index 93cc8c21..a50ff3ef 100644 --- a/test/unit/sanitizer/structured_geocoding.js +++ b/test/unit/sanitizer/structured_geocoding.js @@ -26,6 +26,14 @@ module.exports.tests.sanitize = function(test, common) { } }; }, + '../sanitizer/_debug': () => { + return { + sanitize: () => { + called_sanitizers.push('_debug'); + return { errors: [], warnings: [] }; + } + }; + }, '../sanitizer/_synthesize_analysis': function () { return { sanitize: () => { @@ -134,6 +142,7 @@ module.exports.tests.sanitize = function(test, common) { var expected_sanitizers = [ '_single_scalar_parameters', + '_debug', '_deprecate_quattroshapes', '_synthesize_analysis', '_iso2_to_iso3', From a2848ff6f0010e64e7680e6e6d05a90bc054a5bc Mon Sep 17 00:00:00 2001 From: Lily He Date: Thu, 3 Aug 2017 17:40:39 -0400 Subject: [PATCH 2/2] debug messages for controller/search & predicates --- controller/predicates/is_admin_only_analysis.js | 7 ++++++- controller/predicates/is_coarse_reverse.js | 8 ++++++-- controller/search.js | 13 +++++++++++-- 3 files changed, 23 insertions(+), 5 deletions(-) diff --git a/controller/predicates/is_admin_only_analysis.js b/controller/predicates/is_admin_only_analysis.js index d170f3fc..7ecbd4bb 100644 --- a/controller/predicates/is_admin_only_analysis.js +++ b/controller/predicates/is_admin_only_analysis.js @@ -1,13 +1,18 @@ const _ = require('lodash'); +const Debug = require('../../helper/debug'); +const debugLog = new Debug('controller:predicates:is_admin_only_analysis'); module.exports = (request, response) => { if (!request.clean.hasOwnProperty('parsed_text')) { + debugLog.push(request, false + '(no parsed_text)'); return false; } // return true only if all non-admin properties of parsed_text are empty - return ['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); + return is_admin_only_analysis; }; diff --git a/controller/predicates/is_coarse_reverse.js b/controller/predicates/is_coarse_reverse.js index e02f90c5..55df78f5 100644 --- a/controller/predicates/is_coarse_reverse.js +++ b/controller/predicates/is_coarse_reverse.js @@ -1,9 +1,13 @@ const _ = require('lodash'); - +const Debug = require('../../helper/debug'); +const debugLog = new Debug('controller:predicates:is_coarse_reverse'); const non_coarse_layers = ['address', 'street', 'venue']; module.exports = (req, res) => { // returns true if layers is undefined, empty, or contains 'address', 'street', or 'venue' - return !_.isEmpty(req.clean.layers) && + const is_coarse_reverse = !_.isEmpty(req.clean.layers) && _.isEmpty(_.intersection(req.clean.layers, non_coarse_layers)); + + debugLog.push(req, is_coarse_reverse); + return is_coarse_reverse; }; diff --git a/controller/search.js b/controller/search.js index 989060a8..a8bee3e4 100644 --- a/controller/search.js +++ b/controller/search.js @@ -6,6 +6,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'); function isRequestTimeout(err) { return _.get(err, 'status') === 408; @@ -16,7 +18,7 @@ function setup( apiConfig, esclient, query, should_execute ){ if (!should_execute(req, res)) { return next(); } - + debugLog.beginTimer(req); let cleanOutput = _.cloneDeep(req.clean); if (logging.isDNT(req)) { cleanOutput = logging.removeFields(cleanOutput); @@ -28,6 +30,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'); return next(); } @@ -60,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, 'request timed out, retrying'); return; } @@ -97,11 +101,16 @@ 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)) + } + }}); } logger.debug('[ES response]', docs); next(); }); - + debugLog.stopTimer(req); }); }