Remove possibly intensive logging statements

These all execute on every single request, which matters as we serve
more requests.

controller/coarse_reverse.js

@@ -142,9 +142,6 @@ function setup(service, should_execute) {
         return next();
       }
 
-      // log how many results there were
-      logger.info(`[controller:coarse_reverse][queryType:pip][result_count:${_.size(results)}]`);
-
       // now keep everything from the response that is equal to or less granular
       // than the most granular layer requested.  that is, if effective_layers=['county'],
       // remove neighbourhoods, boroughs, localities, localadmins

controller/search.js

@@ -21,11 +21,6 @@ function setup( apiConfig, esclient, query, should_execute ){
     const debugLog = new Debug('controller:search');
 
     let cleanOutput = _.cloneDeep(req.clean);
-    if (logging.isDNT(req)) {
-      cleanOutput = logging.removeFields(cleanOutput);
-    }
-    // log clean parameters for stats
-    logger.info('[req]', 'endpoint=' + req.path, cleanOutput);
 
     const renderedQuery = query(req.clean);
 
@@ -54,7 +49,6 @@ function setup( apiConfig, esclient, query, should_execute ){
       body: renderedQuery.body
     };
 
-    logger.debug( '[ES req]', cmd );
     debugLog.push(req, {ES_req: cmd});
 
     operation.attempt((currentAttempt) => {
@@ -103,14 +97,12 @@ function setup( apiConfig, esclient, query, should_execute ){
             `[es_result_count:${_.get(res, 'data', []).length}]`
           ];
 
-          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, initialTime);

controller/search_with_ids.js

@@ -21,8 +21,6 @@ function setup( apiConfig, esclient, query, should_execute ){
     if (logging.isDNT(req)) {
       logging.removeFields(cleanOutput);
     }
-    // log clean parameters for stats
-    logger.info('[req]', `endpoint=${req.path}`, cleanOutput);
 
     const renderedQuery = query(req.clean, res);
 

middleware/requestLanguage.js

@@ -102,8 +102,5 @@ module.exports = function middleware( req, res, next ){
     defaulted: req.language.defaulted
   };
 
-  // logging
-  logger.info( '[lang] \'%s\' via \'%s\'', lang.iso6391, via );
-
   next();
 };

query/reverse.js

@@ -4,7 +4,6 @@ const peliasQuery = require('pelias-query');
 const defaults = require('./reverse_defaults');
 const check = require('check-types');
 const _ = require('lodash');
-const logger = require('pelias-logger').get('api');
 
 //------------------------------
 // reverse geocode query
@@ -29,25 +28,20 @@ function generateQuery( clean ){
 
   const vs = new peliasQuery.Vars( defaults );
 
-  let logStr = '[query:reverse] ';
-
   // set size
   if( clean.querySize ){
     vs.var( 'size', clean.querySize);
-    logStr += '[param:querySize] ';
   }
 
   // sources
   if( check.array(clean.sources) && clean.sources.length ) {
     vs.var('sources', clean.sources);
-    logStr += '[param:sources] ';
   }
 
   // layers
   if( check.array(clean.layers) && clean.layers.length ) {
     // only include non-coarse layers
     vs.var( 'layers', _.intersection(clean.layers, ['address', 'street', 'venue']));
-    logStr += '[param:layers] ';
   }
 
   // focus point to score by distance
@@ -57,7 +51,6 @@ function generateQuery( clean ){
       'focus:point:lat': clean['point.lat'],
       'focus:point:lon': clean['point.lon']
     });
-    logStr += '[param:focus_point] ';
   }
 
   // bounding circle
@@ -83,7 +76,6 @@ function generateQuery( clean ){
             'boundary:circle:radius': clean['boundary.circle.radius'] + 'km'
           });
         }
-    logStr += '[param:boundary_circle] ';
   }
 
   // boundary country
@@ -91,17 +83,13 @@ function generateQuery( clean ){
     vs.set({
       'boundary:country': clean['boundary.country']
     });
-    logStr += '[param:boundary_country] ';
   }
 
   // categories
   if (clean.categories) {
     vs.var('input:categories', clean.categories);
-    logStr += '[param:categories] ';
   }
 
-  logger.info(logStr);
-
   return {
     type: 'reverse',
     body: query.render(vs)

test/unit/controller/search.js

@@ -69,9 +69,6 @@ module.exports.tests.success = function(test, common) {
       t.deepEquals(res.data, [{}, {}]);
       t.deepEquals(res.meta, { key: 'value', query_type: 'this is the query type' });
 
-      t.ok(infoMesssages.find((msg) => {
-        return msg === '[controller:search] [queryType:this is the query type] [es_result_count:2]';
-      }));
       t.end();
     };
 
@@ -133,9 +130,6 @@ module.exports.tests.success = function(test, common) {
       t.deepEquals(res.data, [{}, {}]);
       t.deepEquals(res.meta, { query_type: 'this is the query type' });
 
-      t.ok(infoMesssages.find((msg) => {
-        return msg === '[controller:search] [queryType:this is the query type] [es_result_count:2]';
-      }));
       t.end();
     };
 
@@ -197,9 +191,6 @@ module.exports.tests.success = function(test, common) {
       t.equals(res.data, undefined);
       t.deepEquals(res.meta, { key: 'value', query_type: 'this is the query type' });
 
-      t.ok(infoMesssages.find((msg) => {
-        return msg === '[controller:search] [queryType:this is the query type] [es_result_count:0]';
-      }));
       t.end();
     };
 
@@ -277,14 +268,6 @@ module.exports.tests.success = function(test, common) {
       t.deepEquals(res.data, [{}, {}]);
       t.deepEquals(res.meta, { key: 'value', query_type: 'this is the query type' });
 
-      t.ok(infoMesssages.find((msg) => {
-        return msg === '[controller:search] [queryType:this is the query type] [es_result_count:2]';
-      }));
-
-      t.ok(infoMesssages.find((msg) => {
-        return msg === 'succeeded on retry 2';
-      }));
-
       t.end();
     };
 
@@ -349,10 +332,6 @@ module.exports.tests.timeout = function(test, common) {
     const next = () => {
       t.equal(searchServiceCallCount, 3+1);
 
-      t.ok(infoMesssages.indexOf('request timed out on attempt 1, retrying') !== -1);
-      t.ok(infoMesssages.indexOf('request timed out on attempt 2, retrying') !== -1);
-      t.ok(infoMesssages.indexOf('request timed out on attempt 3, retrying') !== -1);
-
       t.deepEqual(req, {
         clean: {},
         errors: [timeoutError.message],

test/unit/controller/search_with_ids.js

@@ -17,7 +17,7 @@ module.exports.tests.interface = (test, common) => {
 
 module.exports.tests.success = (test, common) => {
   test('successful request to search service should replace data and meta', (t) => {
-    t.plan(5);
+    t.plan(4);
 
     const logger = mocklogger();
 
@@ -79,8 +79,6 @@ module.exports.tests.success = (test, common) => {
         }
       });
 
-      t.ok(logger.isInfoMessage('[controller:search] [queryType:this is the query type] [es_result_count:2]'));
-
       t.end();
     };
 
@@ -148,7 +146,7 @@ module.exports.tests.success = (test, common) => {
   });
 
   test('undefined docs in response should not overwrite existing results', (t) => {
-    t.plan(1+3); // ensures that search service was called, then req+res+logger tests
+    t.plan(1+2); // ensures that search service was called, then req+res tests
 
     const logger = mocklogger();
 
@@ -198,8 +196,6 @@ module.exports.tests.success = (test, common) => {
         meta: { key: 'value' }
       });
 
-      t.notOk(logger.isInfoMessage(/[controller:search] [queryType:this is the query type] [es_result_count:0]/));
-
       t.end();
     };
 
@@ -208,7 +204,7 @@ module.exports.tests.success = (test, common) => {
   });
 
   test('empty docs in response should not overwrite existing results', (t) => {
-    t.plan(4);
+    t.plan(3);
 
     const logger = mocklogger();
 
@@ -257,8 +253,6 @@ module.exports.tests.success = (test, common) => {
         meta: { key: 'value' }
       });
 
-      t.notOk(logger.isInfoMessage(/[controller:search] [queryType:this is the query type] [es_result_count:0]/));
-
       t.end();
     };
 
@@ -267,7 +261,7 @@ module.exports.tests.success = (test, common) => {
   });
 
   test('successful request on retry to search service should log info message', (t) => {
-    t.plan(3+2+2); // 3 search service calls, 2 log messages, 1 req, 1 res
+    t.plan(3+2); // 3 search service calls, 1 req, 1 res
 
     const logger = mocklogger();
 
@@ -339,9 +333,6 @@ module.exports.tests.success = (test, common) => {
         }
       });
 
-      t.ok(logger.isInfoMessage('[controller:search] [queryType:this is the query type] [es_result_count:2]'));
-      t.ok(logger.isInfoMessage('succeeded on retry 2'));
-
       t.end();
     };
 
@@ -353,8 +344,8 @@ module.exports.tests.success = (test, common) => {
 
 module.exports.tests.service_errors = (test, common) => {
   test('default # of request timeout retries should be 3', (t) => {
-    // test for 1 initial search service, 3 retries, 1 log messages, 1 req, and 1 res
-    t.plan(1 + 3 + 1 + 2);
+    // test for 1 initial search service, 3 retries, 1 req, and 1 res
+    t.plan(1 + 3 + 2);
 
     const logger = mocklogger();
 
@@ -387,13 +378,6 @@ module.exports.tests.service_errors = (test, common) => {
     const res = {};
 
     const next = () => {
-      t.deepEqual(logger.getInfoMessages(), [
-        '[req] endpoint=undefined {}',
-        'request timed out on attempt 1, retrying',
-        'request timed out on attempt 2, retrying',
-        'request timed out on attempt 3, retrying'
-      ]);
-
       t.deepEqual(req, {
         clean: {},
         errors: [timeoutError.message],