From 33181a7d84d405801c000b4cd7f3736c8a36d02e Mon Sep 17 00:00:00 2001 From: Julian Simioni Date: Tue, 13 Mar 2018 13:22:40 -0400 Subject: [PATCH] Remove possibly intensive logging statements These all execute on every single request, which matters as we serve more requests. --- controller/coarse_reverse.js | 3 --- controller/search.js | 8 ------- controller/search_with_ids.js | 2 -- middleware/requestLanguage.js | 3 --- query/reverse.js | 12 ----------- test/unit/controller/search.js | 21 ------------------- test/unit/controller/search_with_ids.js | 28 ++++++------------------- 7 files changed, 6 insertions(+), 71 deletions(-) diff --git a/controller/coarse_reverse.js b/controller/coarse_reverse.js index 3f8129a3..e2cb834d 100644 --- a/controller/coarse_reverse.js +++ b/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 diff --git a/controller/search.js b/controller/search.js index 721c0dde..c64fbb79 100644 --- a/controller/search.js +++ b/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); diff --git a/controller/search_with_ids.js b/controller/search_with_ids.js index 75c14aea..b108107a 100644 --- a/controller/search_with_ids.js +++ b/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); diff --git a/middleware/requestLanguage.js b/middleware/requestLanguage.js index c7532fc9..9eed4032 100644 --- a/middleware/requestLanguage.js +++ b/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(); }; diff --git a/query/reverse.js b/query/reverse.js index a9c1d25c..7d11316d 100644 --- a/query/reverse.js +++ b/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) diff --git a/test/unit/controller/search.js b/test/unit/controller/search.js index 3f80f7d1..c79f560a 100644 --- a/test/unit/controller/search.js +++ b/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], diff --git a/test/unit/controller/search_with_ids.js b/test/unit/controller/search_with_ids.js index ff884be9..4968a0ab 100644 --- a/test/unit/controller/search_with_ids.js +++ b/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],