feat(log): move retry info to structured logs

controller/search.js

@@ -57,11 +57,23 @@ function setup( apiConfig, esclient, query, should_execute ){
       const initialTime = debugLog.beginTimer(req, `Attempt ${currentAttempt}`);
       // query elasticsearch
       searchService( esclient, cmd, function( err, docs, meta, data ){
+        const message = {
+          controller: 'search',
+          queryType: renderedQuery.type,
+          es_hits: _.get(data, 'hits.total'),
+          result_count: _.get(res, 'data', []).length,
+          es_took: _.get(data, 'took', undefined),
+          response_time: _.get(data, 'response_time', undefined),
+          params: req.clean,
+          retries: currentAttempt - 1,
+          text_length: _.get(req, 'clean.text.length', 0)
+        };
+        logger.info('elasticsearch', message);
+
         // 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');
           return;
         }
@@ -82,12 +94,6 @@ function setup( apiConfig, esclient, query, should_execute ){
         }
         // set response data
         else {
-          // log that a retry was successful
-          // most requests succeed on first attempt so this declutters log files
-          if (currentAttempt > 1) {
-            logger.info(`succeeded on retry ${currentAttempt-1}`);
-          }
-
           res.data = docs;
           res.meta = meta || {};
           // store the query_type for subsequent middleware
@@ -98,19 +104,6 @@ function setup( apiConfig, esclient, query, should_execute ){
             `[queryType:${renderedQuery.type}]`,
             `[es_result_count:${_.get(res, 'data', []).length}]`
           ];
-
-          const message = {
-            controller: 'search',
-            queryType: renderedQuery.type,
-            es_hits: _.get(data, 'hits.total'),
-            result_count: _.get(res, 'data', []).length,
-            es_took: _.get(data, 'took', undefined),
-            response_time: _.get(data, 'response_time', undefined),
-            params: req.clean,
-            text_length: _.get(req, 'clean.text.length', 0)
-          };
-          logger.info('elasticsearch', message);
-
           debugLog.push(req, {queryType: {
             [renderedQuery.type] : {
               es_result_count: _.get(res, 'data', []).length

controller/search_with_ids.js

@@ -64,6 +64,7 @@ function setup( apiConfig, esclient, query, should_execute ){
           es_took: _.get(data, 'took', undefined),
           response_time: _.get(data, 'response_time', undefined),
           params: req.clean,
+          retries: currentAttempt - 1,
           text_length: _.get(req, 'clean.text.length', 0)
         };
         logger.info('elasticsearch', message);
@@ -72,7 +73,6 @@ function setup( apiConfig, esclient, query, should_execute ){
         // (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 on attempt ${currentAttempt}, retrying`);
           return;
         }
@@ -89,12 +89,6 @@ function setup( apiConfig, esclient, query, should_execute ){
           req.errors.push( _.get(err, 'message', err));
         }
         else {
-          // log that a retry was successful
-          // most requests succeed on first attempt so this declutters log files
-          if (currentAttempt > 1) {
-            logger.info(`succeeded on retry ${currentAttempt-1}`);
-          }
-
           // because this is used in response to placeholder, there may already
           // be results.  if there are no results from this ES call, don't overwrite
           // what's already there from placeholder.

test/unit/controller/search.js

@@ -1,3 +1,4 @@
+const _ = require('lodash');
 const setup = require('../../../controller/search');
 const proxyquire =  require('proxyquire').noCallThru();
 
@@ -245,8 +246,8 @@ module.exports.tests.success = function(test, common) {
         get: (service) => {
           t.equal(service, 'api');
           return {
-            info: (msg) => {
-              infoMesssages.push(msg);
+            info: (msg, json) => {
+              infoMesssages.push({ msg: msg, json: json});
             },
             debug: () => {}
           };
@@ -267,7 +268,8 @@ module.exports.tests.success = function(test, common) {
       t.deepEquals(res.meta, { key: 'value', query_type: 'this is the query type' });
 
       t.ok(infoMesssages.find((msg) => {
-        return msg === 'succeeded on retry 2';
+        console.log(msg);
+        return _.get(msg, 'json.retries') === 3;
       }));
 
       t.end();
@@ -319,8 +321,8 @@ module.exports.tests.timeout = function(test, common) {
         get: (service) => {
           t.equal(service, 'api');
           return {
-            info: (msg) => {
-              infoMesssages.push(msg);
+            info: (msg, json) => {
+              infoMesssages.push({msg: msg, json: json});
             },
             debug: () => {}
           };
@@ -334,9 +336,9 @@ 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.ok(infoMesssages.find(function(msg) {
+        return _.get(msg, 'json.retries') === 3;
+      }));
 
       t.deepEqual(req, {
         clean: {},

test/unit/controller/search_with_ids.js

@@ -259,7 +259,7 @@ module.exports.tests.success = (test, common) => {
   });
 
   test('successful request on retry to search service should log info message', (t) => {
-    t.plan(3+1+2); // 3 search service calls, 1 log messages, 1 req, 1 res
+    t.plan(3+2); // 3 search service calls, 1 req, 1 res
 
     const logger = mocklogger();
 
@@ -331,8 +331,6 @@ module.exports.tests.success = (test, common) => {
         }
       });
 
-      t.ok(logger.isInfoMessage('succeeded on retry 2'));
-
       t.end();
     };