Merge pull request #457 from cloudant/456-retry-timeout-hang

456 retry timeout hang

Author: ricellis

CHANGES.md

@@ -1,4 +1,6 @@
 # UNRELEASED
+- [FIXED] Hang caused by plugins (i.e. retry plugin) preventing callback execution
+  by attempting to retry on errors received after starting to return the response body.
 - [DEPRECATED] This library is now deprecated and will be EOL on Dec 31 2021.
 
 # 4.4.0 (2021-06-18)

README.md

@@ -511,7 +511,10 @@ var cloudant = Cloudant({ url: myurl, maxAttempt: 5, plugins: [ { iamauth: { iam
     - `retryErrors`
 
       Automatically retry a request on error (e.g. connection reset errors)
-      _(default: true)_.
+      _(default: true)_. Note that this will only retry errors encountered
+      _before_ the library starts to read response body data. After that point
+      any errors (e.g. socket timeout reading from the server) will be returned
+      to the caller (via callback or emitted `error` depending on the usage). 
 
     - `retryInitialDelayMsecs`
 

lib/clientutils.js

@@ -120,6 +120,7 @@ var processState = function(r, callback) {
   }
 
   // [5] => Return response to awaiting client.
+  r.state.final = true; // flags that we are terminating the loop
   setImmediate(callback, new Error('No retry requested')); // no retry
 };
 
@@ -157,7 +158,7 @@ var wrapCallback = function(r, done) {
       if (error) {
         runHooks('onError', r, error, function() {
           processState(r, function(stop) {
-            if (stop && !stop.skipClientCallback) {
+            if ((stop && !stop.skipClientCallback) || r.state.final) {
               r.clientCallback(error, response, body);
             }
             done(stop);

plugins/retry.js

@@ -14,7 +14,7 @@
 'use strict';
 
 const BasePlugin = require('./base.js');
-
+const debug = require('debug')('cloudant:plugins:retry');
 /**
  * Retry plugin.
  */
@@ -38,24 +38,28 @@ class RetryPlugin extends BasePlugin {
 
   onResponse(state, response, callback) {
     if (this._cfg.retryStatusCodes.indexOf(response.statusCode) !== -1) {
+      debug(`Received status code ${response.statusCode}; setting retry state.`);
       state.retry = true;
       if (state.attempt === 1) {
         state.retryDelayMsecs = this._cfg.retryInitialDelayMsecs;
       } else {
         state.retryDelayMsecs *= this._cfg.retryDelayMultiplier;
       }
+      debug(`Asking for retry after ${state.retryDelayMsecs}`);
     }
     callback(state);
   }
 
   onError(state, error, callback) {
     if (this._cfg.retryErrors) {
+      debug(`Received error ${error.code} ${error.message}; setting retry state.`);
       state.retry = true;
       if (state.attempt === 1) {
         state.retryDelayMsecs = this._cfg.retryInitialDelayMsecs;
       } else {
         state.retryDelayMsecs *= this._cfg.retryDelayMultiplier;
       }
+      debug(`Asking for retry after ${state.retryDelayMsecs}`);
     }
     callback(state);
   }

test/plugins/retry.js

@@ -860,6 +860,38 @@ describe('Retry Plugin', function() {
   });
 
   describe('retries on error', function() {
+    function dataPhaseErrorMockServer(port, timesToError, successBody, lifetime, done) {
+      // nock is unable to mock the timeout in the response phase so create a mock http server
+      const http = require('http');
+      var counter = 0;
+      const mockServer = http.createServer({}, function(req, res) {
+        counter++;
+        console.log(`DPE MOCK SERVER: received request ${counter} for URL: ${req.url}`);
+        if (counter <= timesToError) {
+          res.writeHead(200, { 'Content-Type': 'application/json' });
+          res.write(successBody);
+          // We intentionally fail to end the request so that the client side will timeout in the data phase
+          // res.end();
+        } else {
+          // respond successfully promptly
+          res.end(successBody);
+        }
+      }).listen(port, '127.0.0.1');
+      // set a timeout so we don't hang the test (mocha's timeout won't kill the http server)
+      const serverTimeout = setTimeout(() => {
+        console.log('DPE MOCK SERVER: timeout');
+        if (mockServer.listening) {
+          console.log('DPE MOCK SERVER: close requested from timeout');
+          mockServer.close(() => done(new Error('Test server timeout; client hang!')));
+        }
+      }, lifetime);
+      return {server: mockServer,
+        close: () => {
+          clearTimeout(serverTimeout);
+          mockServer.close(done);
+        }};
+    }
+
     describe('with callback only', function() {
       it('performs request and returns response', function(done) {
         // NOTE: Use NOCK_OFF=true to test using a real CouchDB instance.
@@ -945,6 +977,31 @@ describe('Retry Plugin', function() {
           done();
         });
       });
+
+      it('does not retry in response data phase', function(done) {
+        // mock server on 6984 that errors for 1 request then returns the DB info block for other reqs
+        // and finally stops listening after 1s if it wasn't already closed
+        const mock = dataPhaseErrorMockServer(6984, 1, '{"doc_count":0}', 1000, done);
+        // A client that will timeout after 100 ms and make only 2 attempts with a retry 10 ms after receiving an error
+        var cloudantClient = new Client({
+          https: false,
+          maxAttempt: 2,
+          requestDefaults: {timeout: 100},
+          plugins: { retry: { retryInitialDelayMsecs: 10, retryStatusCodes: [] } }
+        });
+
+        var req = {
+          url: 'http://127.0.0.1:6984/foo',
+          auth: { username: ME, password: PASSWORD },
+          method: 'GET'
+        };
+
+        cloudantClient.request(req, function(err, resp, data) {
+          assert.ok(err, 'Should get called back with an error.');
+          assert.equal('ESOCKETTIMEDOUT', err.code);
+          mock.close();
+        });
+      });
     });
 
     describe('with listener only', function() {
@@ -1084,6 +1141,54 @@ describe('Retry Plugin', function() {
             assert.fail('Unexpected data from server');
           });
       });
+
+      it('does not retry in response data phase', function(done) {
+        // mock server on 6985 that errors for 1 request then returns the DB info block for other reqs
+        // and finally stops listening after 1s if it wasn't already closed
+        const mock = dataPhaseErrorMockServer(6985, 1, '{"doc_count":0}', 1000, done);
+
+        // A client that will timeout after 100 ms and make only 2 attempts with a retry 10 ms after receiving an error
+        var cloudantClient = new Client({
+          https: false,
+          maxAttempt: 2,
+          requestDefaults: {timeout: 100},
+          plugins: { retry: { retryInitialDelayMsecs: 10, retryStatusCodes: [] } }
+        });
+
+        var req = {
+          url: 'http://127.0.0.1:6985/foo',
+          auth: { username: ME, password: PASSWORD },
+          method: 'GET'
+        };
+
+        var responseCount = 0;
+        var errors = [];
+        var responseData = '';
+
+        cloudantClient.request(req)
+          .on('error', (err) => {
+            errors.push(err);
+          })
+          .on('response', function(resp) {
+            responseCount++;
+            assert.equal(resp.statusCode, 200);
+          })
+          .on('data', function(data) {
+            responseData += data;
+          })
+          .on('end', function() {
+            let expectedErrors = 1;
+            if (process.version.startsWith('v16.')) {
+              // Node 16 has an additional `aborted` error
+              // https://github.com/nodejs/node/issues/28172
+              expectedErrors++;
+            }
+            assert.ok(responseData.toString('utf8').indexOf('"doc_count":0') > -1);
+            assert.equal(responseCount, 1);
+            assert.equal(errors.length, expectedErrors);
+            mock.close(done);
+          });
+      });
     });
 
     describe('with callback and listener', function() {
@@ -1235,6 +1340,55 @@ describe('Retry Plugin', function() {
             assert.fail('Unexpected data from server');
           });
       });
+
+      it('does not retry in response data phase', function(done) {
+        // mock server on 6986 that errors for 1 request then returns the DB info block for other reqs
+        // and finally stops listening after 1s if it wasn't already closed
+        const mock = dataPhaseErrorMockServer(6986, 1, '{"doc_count":0}', 1000, done);
+        // A client that will timeout after 100 ms and make only 2 attempts with a retry 10 ms after receiving an error
+        var cloudantClient = new Client({
+          https: false,
+          maxAttempt: 2,
+          requestDefaults: {timeout: 100},
+          plugins: { retry: { retryInitialDelayMsecs: 10, retryStatusCodes: [] } }
+        });
+
+        var req = {
+          url: 'http://127.0.0.1:6986/foo',
+          auth: { username: ME, password: PASSWORD },
+          method: 'GET'
+        };
+
+        var responseCount = 0;
+        var errors = [];
+        var responseData = '';
+        cloudantClient.request(req, function(err, resp, data) {
+          assert.ok(err, 'Should get called back with an error.');
+          assert.equal('ESOCKETTIMEDOUT', err.code);
+          mock.close();
+        })
+          .on('error', (err) => {
+            errors.push(err);
+          })
+          .on('response', function(resp) {
+            responseCount++;
+            assert.equal(resp.statusCode, 200);
+          })
+          .on('data', function(data) {
+            responseData += data;
+          })
+          .on('end', function() {
+            let expectedErrors = 1;
+            if (process.version.startsWith('v16.')) {
+              // Node 16 has an additional `aborted` error
+              // https://github.com/nodejs/node/issues/28172
+              expectedErrors++;
+            }
+            assert.ok(responseData.toString('utf8').indexOf('"doc_count":0') > -1);
+            assert.equal(responseCount, 1);
+            assert.equal(errors.length, expectedErrors);
+          });
+      });
     });
   });
 });