created new debug helper class and debug sanitizer

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;

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

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
+});

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),

sanitizer/defer_to_addressit.js

@@ -1,5 +1,6 @@
 const sanitizeAll = require('../sanitizer/sanitizeAll'),
     sanitizers = {
+      debug: require('../sanitizer/_debug')(),
       text: require('../sanitizer/_text_addressit')()
     };
 

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),

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)
     };

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),

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*/),

sanitizer/search_fallback.js

@@ -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();
-
-};

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')(),

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);
+  }
+};

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'),

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);
+  }
+};

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',

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);
 

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',

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'
     ];

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',

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',

test/unit/sanitizer/search_fallback.js

@@ -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);
-  }
-};

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',