correct timer timings for controller debug logs

controller/place.js

@@ -22,7 +22,7 @@ function setup( apiConfig, esclient ){
     if (requestHasErrors(req)){
       return next();
     }
-    const initialTime = debugLog.beginTimer(req);
+
     // options for retry
     // maxRetries is from the API config with default of 3
     // factor of 1 means that each retry attempt will esclient requestTimeout
@@ -47,13 +47,15 @@ function setup( apiConfig, esclient ){
     debugLog.push(req, {ES_req: cmd});
 
     operation.attempt((currentAttempt) => {
+      const initialTime = debugLog.beginTimer(req);
+
       mgetService( esclient, cmd, function( err, docs ) {
         // 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');
+          debugLog.stopTimer(req, initialTime, `request timed out on attempt ${currentAttempt}, retrying`);
           return;
         }
 

controller/search.js

@@ -18,8 +18,7 @@ function setup( apiConfig, esclient, query, should_execute ){
       return next();
     }
 
-    const debugLog = new Debug(req, 'controller:search');
-    const initialTime = debugLog.beginTimer(req);
+    const debugLog = new Debug('controller:search');
 
     let cleanOutput = _.cloneDeep(req.clean);
     if (logging.isDNT(req)) {
@@ -32,7 +31,7 @@ function setup( apiConfig, esclient, query, should_execute ){
 
     // if there's no query to call ES with, skip the service
     if (_.isUndefined(renderedQuery)) {
-      debugLog.stopTimer(req, initialTime, 'No query to call ES with. Skipping');
+      debugLog.push(req, 'No query to call ES with. Skipping');
       return next();
     }
 
@@ -59,6 +58,7 @@ function setup( apiConfig, esclient, query, should_execute ){
     debugLog.push(req, {ES_req: cmd});
 
     operation.attempt((currentAttempt) => {
+      const initialTime = debugLog.beginTimer(req, `Attempt ${currentAttempt}`);
       // query elasticsearch
       searchService( esclient, cmd, function( err, docs, meta ){
         // returns true if the operation should be attempted again

controller/search_with_ids.js

@@ -17,7 +17,6 @@ function setup( apiConfig, esclient, query, should_execute ){
       return next();
     }
 
-    const initialTime = debugLog.beginTimer(req);
     const cleanOutput = _.cloneDeep(req.clean);
     if (logging.isDNT(req)) {
       logging.removeFields(cleanOutput);
@@ -29,7 +28,7 @@ function setup( apiConfig, esclient, query, should_execute ){
 
     // if there's no query to call ES with, skip the service
     if (_.isUndefined(renderedQuery)) {
-      debugLog.stopTimer(req, initialTime, 'No query to call ES with. Skipping');
+      debugLog.push(req, `No query to call ES with. Skipping`);
       return next();
     }
 
@@ -56,6 +55,7 @@ function setup( apiConfig, esclient, query, should_execute ){
     debugLog.push(req, {ES_req: cmd});
 
     operation.attempt((currentAttempt) => {
+      const initialTime = debugLog.beginTimer(req, `Attempt ${currentAttempt}`);
       // query elasticsearch
       searchService( esclient, cmd, function( err, docs, meta ){
         // returns true if the operation should be attempted again
@@ -63,7 +63,7 @@ function setup( apiConfig, esclient, query, should_execute ){
         // 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');
+          debugLog.stopTimer(req, initialTime, `request timed out on attempt ${currentAttempt}, retrying`);
           return;
         }