From a1add3656eb2d34c64927f0b0b25070e6c1e2947 Mon Sep 17 00:00:00 2001
From: Julian Simioni <julian@simioni.org>
Date: Fri, 26 Oct 2018 19:42:30 -0400
Subject: [PATCH] feat(log): Use structured logs for place endpoint

---
 controller/place.js            | 19 +++++++++++--------
 service/mget.js                |  7 ++++++-
 test/unit/controller/place.js  | 11 ++++++-----
 test/unit/controller/search.js |  5 ++---
 4 files changed, 25 insertions(+), 17 deletions(-)

diff --git a/controller/place.js b/controller/place.js
index ac851359..eabcda8e 100644
--- a/controller/place.js
+++ b/controller/place.js
@@ -47,12 +47,21 @@ function setup( apiConfig, esclient ){
     operation.attempt((currentAttempt) => {
       const initialTime = debugLog.beginTimer(req);
 
-      mgetService( esclient, cmd, function( err, docs ) {
+      mgetService( esclient, cmd, function( err, docs, data) {
+        const message = {
+          controller: 'place',
+          queryType: 'place',
+          result_count: _.get(data, 'docs.length'),
+          response_time: _.get(data, 'response_time', undefined),
+          params: req.clean,
+          retries: currentAttempt - 1
+        };
+        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 on attempt ${currentAttempt}, retrying`);
           return;
         }
@@ -73,12 +82,6 @@ function setup( apiConfig, esclient ){
         }
         // 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;
         }
         logger.debug('[ES response]', docs);
diff --git a/service/mget.js b/service/mget.js
index 306ed565..65c91c56 100644
--- a/service/mget.js
+++ b/service/mget.js
@@ -22,7 +22,12 @@ function service( esclient, query, cb ){
   };
 
   // query elasticsearch
+  const startTime = new Date();
   esclient.mget( cmd, function( err, data ){
+    if (data) {
+      data.response_time = new Date() - startTime;
+    }
+
     // handle elasticsearch errors
     if( err ){
       logger.error( `elasticsearch error ${err}`);
@@ -50,7 +55,7 @@ function service( esclient, query, cb ){
     }
 
     // fire callback
-    return cb( null, docs );
+    return cb( null, docs, data );
   });
 
 }
diff --git a/test/unit/controller/place.js b/test/unit/controller/place.js
index 533db310..869a5f41 100644
--- a/test/unit/controller/place.js
+++ b/test/unit/controller/place.js
@@ -1,3 +1,4 @@
+const _ = require('lodash');
 const setup = require('../../../controller/place');
 const proxyquire =  require('proxyquire').noCallThru();
 
@@ -177,8 +178,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: () => {}
           };
@@ -203,9 +204,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', 2);
+      }));
 
       t.deepEqual(req.errors, [timeoutError.message]);
       t.deepEqual(res, {});
diff --git a/test/unit/controller/search.js b/test/unit/controller/search.js
index 531a5b9e..faee2f70 100644
--- a/test/unit/controller/search.js
+++ b/test/unit/controller/search.js
@@ -268,8 +268,7 @@ 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) => {
-        console.log(msg);
-        return _.get(msg, 'json.retries') === 3;
+        return _.get(msg, 'json.retries') === 2;
       }));
 
       t.end();
@@ -337,7 +336,7 @@ module.exports.tests.timeout = function(test, common) {
       t.equal(searchServiceCallCount, 3+1);
 
       t.ok(infoMesssages.find(function(msg) {
-        return _.get(msg, 'json.retries') === 3;
+        return _.get(msg, 'json.retries') === 2;
       }));
 
       t.deepEqual(req, {