callback called twice on error. #304

Closed
manu844 opened this Issue Aug 22, 2012 · 12 comments

Projects

None yet

7 participants

@manu844

on making get request, if the request fails due to timeout callback is getting called twice.

@mpfilbin

Can you provide a test case (preferred) or code snippet that demonstrates the behavior you are observing. Also, can you reference a version number?

@diversario

I just ran into the same issue. Here's the gist that demonstrates it. I'm using request v2.27.0

@diversario diversario added a commit to diversario/request that referenced this issue Sep 11, 2013
@diversario diversario Test case for #304. abcbadd
@j20

I'm experiencing this too.

When a response times out, the callback is called twice--first with an err.code of ETIMEDOUT and then a second time with an err.code of ECONNRESET.

This makes handling the errors really hard since the response processing logic gets run twice.

I wrote a functional test to try to show this. It seems that the basic syntax for a request works fine and returns just ETIMEDOUT (test 1 below). But when using the syntax of req.on('response'), req.on('error'), etc for more custom handling, then the issue appears--i.e. the callback is called twice, first with ETIMEDOUT and then again with ECONNREST (test 2 below).

To run the test below:
npm install mocha -g
npm install chai
mocha path/to/test.js

var chai   = require('chai');
var expect = chai.expect;

var http    = require('http');
var express = require('express');
var app     = express();
var port    = 6767;
var host    = 'http://localhost:' + port;
var Request = require('request');


app.get('/timeout', function (req, res) {
  // Intentionally trigger a timeout
  setTimeout(function () {
    res.send('hello world (timeout)');
  }, 50);
});


describe('Timeout', function () {

  before(function () {
    this.server = http.createServer(app).listen(port);
  });

  after(function() {
    this.server.close();
  });

  context('requests that fail to connect within the allowed timeout', function () {
     var options = {
      uri: host + '/timeout',
      timeout: 20 // ms
    };

    it('should return an err.code of `ETIMEDOUT` (v1)', function (done) {
      Request(options, function (err, res, body) {
        expect(err.code).to.equal('ETIMEDOUT');
        done();
      });

      /**
       * Result: This style of request works:
       * 1.) An err.code of ETIMEDOUT is given
       * 2.) It does not appear to invoke the callback twice because
       * if it did, Mocha would throw its own error that done() was called twice.
       */
    });

    it('should return an err.code of `ETIMEDOUT` (v2)', function (done) {
      customRequest(options, function (err, res, body) {
        expect(err.code).to.equal('ETIMEDOUT');

        // it...should invoke the request`s callback only once.
        // (If mocha's done() is called more than once, Mocha will throw an error.
        // I'm not sure how to directly write a test for this or I'd add that too.)
        done();
      });
    });

    // it('should invoke the request`s callback only once');
  });
});



customRequest = function (options, callback) {
  var req = Request(options);

  req.on('response', function (res) {
    var chunks = [];

    res.on('data', function (chunk) {
      chunks.push(chunk);
    });

    res.on('end', function () {
      var buffer = Buffer.concat(chunks);
      callback(null, res, buffer.toString());
    });
  });

  req.on('error', function(err) {
    // Uncomment this to see that the errors are being given twice
    // (ETIMEDOUT, ECONNRESET).
    console.log('******' + err.code + '******');
    callback(err);
  });
}

I think it has something to do with req.on('error') being called multiple times, but I'm not sure...

req.on('error', function(err) {
      // To show that this is called twice
    console.log('******' + err.code + '******');
  callback(err);
});

node v0.10.15
request 2.27.0

@j20

I found a solution (workaround?) so that the callback is only called once when an err of ETIMEDOUT occurs. Within req.on('error'), I added req.abort();.

Now when I receive an ETIMEDOUT error, it's the only error received and the callback is only invoked once. I still have more testing of other request errors to do to determine if this causes others problems that I'm not aware of at the moment. But for now it gets me past the issue of ETIMEDOUT invoking the callback twice.

req.on('error', function(err) {
  callback(err);

  // Abort request so the callback is only ever
  // invoked once following an err message.
  req.abort();
});
@mikeal
request member

i think this is fixed.

@mikeal mikeal closed this Aug 27, 2014
@ghprod

@mikeal

i still have it, do you mean fixed it with put req.abort() on error handling?

@diversario

I still get this on request 2.42.

@mikeal mikeal reopened this Sep 13, 2014
@seanstrom

Hey guys, I think I tracked this down to the right place.

File: request.js
Lines: 803 - 810
Version: 2.42.x

So based on @j20 work around I found that we are aborting the http/https request we make internally when a timeout happens. However we do not abort the actual Request instance like @j20 does.
Sounds like we need an additionally statement to abort the Request instance as well.

Any thoughts?

@seanstrom

Also whats the ideal way to fix this?
Based on looking at the tests, we assert that the first error event should be the ETIMEDOUT error,
but all others should be ECONNRESET error.

Is there a use case for users to rely on the ECONNRESET error event?
Like we're giving them these raw errors, so users could be totally doing something when they get back a ETIMEDOUT error or ECONNRESET error.
If that is the case then we can just tell users to check for the error code they want to respond to or just use @j20 work around.

@seanstrom

Okay to shed even more light on the subject,
Seems like @mikeal and @diversario at different points in time have both tried and succeeded to fix this issue. But at certain commit, the tests were changed to allow for the another error event to happen.

Disclaimer: Not pointing fingers - Just Time Traveling

This is when the tests were changed to accommodate another change.
e8dbcc8

That other change is.
f87cbf6

And it all gets tied together by some logic that looks like this.

self.req.on('error', self.clientErrorHandler)

Now that line above goes back probably to nearly to the beginning, i stopped checking after 0.3.6.
It doesn't look exactly the same, but other variations exist.

@seanstrom

All in all, given the history, this is a bug and I believe I fixed it.
#1076

@seanstrom

#1076 has been merged, closing.

@seanstrom seanstrom closed this Sep 19, 2014
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment