added request retries for ES request timeouts

controller/place.js

@@ -1,16 +1,39 @@
-var service = { mget: require('../service/mget') };
+'use strict';
-var logger = require('pelias-logger').get('api');
+
+const _ = require('lodash');
+const retry = require('retry');
+
+const mgetService = require('../service/mget');
+const logger = require('pelias-logger').get('api');
 
 function setup( apiConfig, esclient ){
-  function controller( req, res, next ){
+  function requestHasErrors(request) {
+    return _.get(request, 'errors', []).length > 0;
+  }
 
-    // do not run controller when a request
+  function isRequestTimeout(err) {
-    // validation error has occurred.
+    return _.get(err, 'status') === 408;
-    if( req.errors && req.errors.length ){
+  }
+
+  function controller( req, res, next ){
+    // do not run controller when a request validation error has occurred.
+    if (requestHasErrors(req)){
       return next();
     }
 
-    var query = req.clean.ids.map( function(id) {
+    // options for retry
+    // maxRetries is from the API config with default of 3
+    // factor of 1 means that each retry attempt will esclient requestTimeout
+    const operationOptions = {
+      retries: _.get(apiConfig, 'requestRetries', 3),
+      factor: 1,
+      minTimeout: _.get(esclient, 'transport.requestTimeout')
+    };
+
+    // setup a new operation
+    const operation = retry.operation(operationOptions);
+
+    const query = req.clean.ids.map( function(id) {
       return {
         _index: apiConfig.indexName,
         _type: id.layers,
@@ -20,19 +43,36 @@ function setup( apiConfig, esclient ){
 
     logger.debug( '[ES req]', query );
 
-    service.mget( esclient, query, function( err, docs ) {
+    operation.attempt((currentAttempt) => {
+      mgetService( esclient, query, 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`);
+          return;
+        }
+
         // error handler
         if( err ){
           req.errors.push( err );
         }
         // 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);
 
         next();
       });
+    });
+
   }
 
   return controller;

test/unit/controller/place.js

@@ -1,129 +1,372 @@
-var setup = require('../../../controller/place'),
+'use strict';
-    mockBackend = require('../mock/backend');
+
+const setup = require('../../../controller/search');
+const proxyquire =  require('proxyquire').noCallThru();
 
 module.exports.tests = {};
 
-module.exports.tests.interface = function(test, common) {
+module.exports.tests.interface = (test, common) => {
-  test('valid interface', function(t) {
+  test('valid interface', (t) => {
     t.equal(typeof setup, 'function', 'setup is a function');
     t.equal(typeof setup(), 'function', 'setup returns a controller');
     t.end();
   });
 };
 
-// reminder: this is only the api subsection of the full config
+module.exports.tests.success = (test, common) => {
-var fakeDefaultConfig = {
+  test('successful request to search service should set data and meta', (t) => {
-  indexName: 'pelias'
+    const config = {
+      indexName: 'indexName value'
     };
+    const esclient = 'this is the esclient';
 
-// functionally test controller (backend success)
+    // request timeout messages willl be written here
-module.exports.tests.functional_success = function(test, common) {
+    const infoMesssages = [];
 
-  // expected geojson features for 'client/place/ok/1' fixture
+    // a controller that validates the esclient and cmd that was passed to the search service
-  var expected = [{
+    const controller = proxyquire('../../../controller/place', {
-    type: 'Feature',
+      '../service/mget': (esclient, query, callback) => {
-    geometry: {
+        t.equal(esclient, 'this is the esclient');
-      type: 'Point',
+        t.deepEqual(query, [
-      coordinates: [ -50.5, 100.1 ]
+          {
-    },
+            _index: 'indexName value',
-    properties: {
+            _type: 'layer1',
-      id: 'myid1',
+            _id: 'id1'
-      layer: 'mytype1',
-      text: 'test name1, city1, state1'
-    }
-  }, {
-    type: 'Feature',
-    geometry: {
-      type: 'Point',
-      coordinates: [ -51.5, 100.2 ]
           },
-    properties: {
+          {
-      id: 'myid2',
+            _index: 'indexName value',
-      layer: 'mytype2',
+            _type: 'layer2',
-      text: 'test name2, city2, state2'
+            _id: 'id2'
           }
-  }];
+        ]);
 
-  test('functional success', function(t) {
+        const docs = [{}, {}];
-    var backend = mockBackend( 'client/mget/ok/1', function( cmd ){
+
-      t.deepEqual(cmd, { body: { docs: [ { _id: 123, _index: 'pelias', _type: [ 'a' ] } ] } }, 'correct backend command');
+        callback(undefined, docs);
-    });
+      }
-    var controller = setup( fakeDefaultConfig, backend );
+    })(config, esclient);
-    var res = {
+
-      status: function( code ){
+    const req = {
-        t.equal(code, 200, 'status set');
+      clean: {
-        return res;
+        ids: [
+          {
+            id: 'id1',
+            layers: 'layer1'
           },
-      json: function( json ){
+          {
-        t.equal(typeof json, 'object', 'returns json');
+            id: 'id2',
-        t.equal(typeof json.date, 'number', 'date set');
+            layers: 'layer2'
-        t.equal(json.type, 'FeatureCollection', 'valid geojson');
-        t.true(Array.isArray(json.features), 'features is array');
-        t.deepEqual(json.features, expected, 'values correctly mapped');
           }
+        ]
+      },
+      errors: [],
+      warnings: []
     };
-    var req = { clean: { ids: [ {'id' : 123, layers: [ 'a' ] } ] }, errors: [], warnings: [] };
+    const res = {};
-    var next = function next() {
+
-      t.equal(req.errors.length, 0, 'next was called without error');
+    const next = () => {
+      t.deepEqual(req.errors, []);
+      t.deepEqual(req.warnings, []);
+      t.deepEquals(res.data, [{}, {}]);
       t.end();
     };
+
     controller(req, res, next);
+
   });
 
-  test('functional success with custom index name', function(t) {
-    var fakeCustomizedConfig = {
-      indexName: 'alternateindexname'
 };
 
-    var backend = mockBackend( 'client/mget/ok/1', function( cmd ){
+module.exports.tests.error_conditions = (test, common) => {
-      t.deepEqual(cmd, { body: { docs: [ { _id: 123, _index: 'alternateindexname', _type: [ 'a' ] } ] } }, 'correct backend command');
+  test('non-empty req.errors should ', (t) => {
+    const esclient = () => {
+      throw new Error('esclient should not have been called');
+    };
+    const controller = setup( {}, esclient );
+
+    // the existence of `errors` means that a sanitizer detected an error,
+    //  so don't call the esclient
+    const req = {
+      errors: ['error']
+    };
+    const res = { };
+
+    t.doesNotThrow(() => {
+      controller(req, res, () => {});
+    });
+    t.end();
+
+  });
+
+  test('mgetService returning error should add to req.errors and ignore docs', (t) => {
+    const config = {
+      indexName: 'indexName value'
+    };
+    const esclient = 'this is the esclient';
+
+    // request timeout messages willl be written here
+    const infoMesssages = [];
+
+    const nonTimeoutError = {
+      status: 500,
+      displayName: 'InternalServerError',
+      message: 'an internal server error occurred'
+    };
+
+    // a controller that validates the esclient and cmd that was passed to the search service
+    const controller = proxyquire('../../../controller/place', {
+      '../service/mget': (esclient, query, callback) => {
+        const docs = [{}, {}];
+
+        callback(nonTimeoutError, docs);
+      }
+    })(config, esclient);
+
+    const req = {
+      clean: {
+        ids: [
+          {
+            id: 'id1',
+            layers: 'layer1'
+          }
+        ]
+      },
+      errors: [],
+      warnings: []
+    };
+    const res = {};
+
+    const next = () => {
+      t.deepEqual(req.errors, [nonTimeoutError]);
+      t.deepEqual(req.warnings, []);
+      t.deepEquals(res.data, undefined);
+      t.end();
+    };
+
+    controller(req, res, next);
+
   });
-    var controller = setup( fakeCustomizedConfig, backend );
+
-    var res = {
+};
-      status: function( code ){
+
-        t.equal(code, 200, 'status set');
+module.exports.tests.timeout = function(test, common) {
-        return res;
+  test('default # of request timeout retries should be 3', (t) => {
+    const config = {
+      indexName: 'indexName value'
+    };
+    const esclient = 'this is the esclient';
+
+    let searchServiceCallCount = 0;
+
+    const timeoutError = {
+      status: 408,
+      displayName: 'RequestTimeout',
+      message: 'Request Timeout after 17ms'
+    };
+
+    // request timeout messages willl be written here
+    const infoMesssages = [];
+
+    // a controller that validates the esclient and cmd that was passed to the search service
+    const controller = proxyquire('../../../controller/place', {
+      '../service/mget': (esclient, cmd, callback) => {
+        // not that the searchService got called
+        searchServiceCallCount++;
+
+        callback(timeoutError);
+      },
+      'pelias-logger': {
+        get: (service) => {
+          t.equal(service, 'api');
+          return {
+            info: (msg) => {
+              infoMesssages.push(msg);
             },
-      json: function( json ){
+            debug: () => {}
-        t.equal(typeof json, 'object', 'returns json');
+          };
-        t.equal(typeof json.date, 'number', 'date set');
+        }
-        t.equal(json.type, 'FeatureCollection', 'valid geojson');
+      }
-        t.true(Array.isArray(json.features), 'features is array');
+    })(config, esclient);
-        t.deepEqual(json.features, expected, 'values correctly mapped');
+
+    const req = {
+      clean: {
+        ids: [
+          {
+            id: 'id1',
+            layers: 'layer1'
+          }
+        ]
+      },
+      errors: [],
+      warnings: []
+    };
+    const res = {};
+
+    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.errors, [timeoutError]);
+      t.deepEqual(res, {});
+      t.end();
+    };
+
+    controller(req, res, next);
+
+  });
+
+  test('explicit apiConfig.requestRetries should retry that many times', (t) => {
+    const config = {
+      indexName: 'indexName value',
+      requestRetries: 17
+    };
+    const esclient = 'this is the esclient';
+
+    let searchServiceCallCount = 0;
+
+    const timeoutError = {
+      status: 408,
+      displayName: 'RequestTimeout',
+      message: 'Request Timeout after 17ms'
+    };
+
+    // a controller that validates the esclient and cmd that was passed to the search service
+    const controller = proxyquire('../../../controller/place', {
+      '../service/mget': (esclient, cmd, callback) => {
+        // not that the searchService got called
+        searchServiceCallCount++;
+
+        callback(timeoutError);
+      }
+    })(config, esclient);
+
+    const req = {
+      clean: {
+        ids: [
+          {
+            id: 'id1',
+            layers: 'layer1'
           }
+        ]
+      },
+      errors: [],
+      warnings: []
     };
-    var req = { clean: { ids: [ {'id' : 123, layers: [ 'a' ] } ] }, errors: [], warnings: [] };
+    const res = {};
-    var next = function next() {
+
-      t.equal(req.errors.length, 0, 'next was called without error');
+    const next = () => {
+      t.equal(searchServiceCallCount, 17+1);
       t.end();
     };
+
     controller(req, res, next);
+
   });
+
+  test('only status code 408 should be considered a retryable request', (t) => {
+    const config = {
+      indexName: 'indexName value'
+    };
+    const esclient = 'this is the esclient';
+
+    let searchServiceCallCount = 0;
+
+    const nonTimeoutError = {
+      status: 500,
+      displayName: 'InternalServerError',
+      message: 'an internal server error occurred'
+    };
+
+    // a controller that validates the esclient and cmd that was passed to the search service
+    const controller = proxyquire('../../../controller/place', {
+      '../service/mget': (esclient, cmd, callback) => {
+        // not that the searchService got called
+        searchServiceCallCount++;
+
+        callback(nonTimeoutError);
+      }
+    })(config, esclient);
+
+    const req = {
+      clean: {
+        ids: [
+          {
+            id: 'id1',
+            layers: 'layer1'
+          }
+        ]
+      },
+      errors: [],
+      warnings: []
+    };
+    const res = {};
+
+    const next = () => {
+      t.equal(searchServiceCallCount, 1);
+      t.deepEqual(req.errors, [nonTimeoutError]);
+      t.end();
     };
 
-// functionally test controller (backend failure)
+    controller(req, res, next);
-module.exports.tests.functional_failure = function(test, common) {
+
-  test('functional failure', function(t) {
-    var backend = mockBackend( 'client/mget/fail/1', function( cmd ){
-      t.deepEqual(cmd, { body: { docs: [ { _id: 123, _index: 'pelias', _type: ['b'] } ] } }, 'correct backend command');
   });
-    var controller = setup( fakeDefaultConfig, backend );
+
-    var req = { clean: { ids: [ {'id' : 123, layers: [ 'b' ] } ] }, errors: [], warnings: [] };
+  test('string error should not retry and be logged as-is', (t) => {
-    var next = function( message ){
+    const config = {
-      t.equal(req.errors[0],'an elasticsearch error occurred','error passed to errorHandler');
+      indexName: 'indexName value'
+    };
+    const esclient = 'this is the esclient';
+
+    let searchServiceCallCount = 0;
+
+    const stringTypeError = 'this is an error string';
+
+    // a controller that validates the esclient and cmd that was passed to the search service
+    const controller = proxyquire('../../../controller/place', {
+      '../service/mget': (esclient, cmd, callback) => {
+        // not that the searchService got called
+        searchServiceCallCount++;
+
+        callback(stringTypeError);
+      }
+    })(config, esclient);
+
+    const req = {
+      clean: {
+        ids: [
+          {
+            id: 'id1',
+            layers: 'layer1'
+          }
+        ]
+      },
+      errors: [],
+      warnings: []
+    };
+    const res = {};
+
+    const next = () => {
+      t.equal(searchServiceCallCount, 1);
+      t.deepEqual(req.errors, [stringTypeError]);
       t.end();
     };
-    controller(req, undefined, next );
+
+    controller(req, res, next);
+
   });
+
 };
 
-module.exports.all = function (tape, common) {
+module.exports.all = (tape, common) => {
 
   function test(name, testFunction) {
     return tape('GET /place ' + name, testFunction);
   }
 
-  for( var testCase in module.exports.tests ){
+  for( const testCase in module.exports.tests ){
     module.exports.tests[testCase](test, common);
   }
 };