Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

never get callback in some request #2475

Closed
mike442144 opened this issue Nov 29, 2016 · 20 comments · May be fixed by request/tunnel-agent#22
Closed

never get callback in some request #2475

mike442144 opened this issue Nov 29, 2016 · 20 comments · May be fixed by request/tunnel-agent#22
Labels

Comments

@mike442144
Copy link

mike442144 commented Nov 29, 2016

I have about 10 million requests in a project, but I could never get response for some request.Here is my code:

let options = {timeout:15000,encoding:null,gzip:true,time:true,headers:{}};
options.uri = "xxxxx";
options.proxy="xxxxxx";
debug("Requesting: %s", options.uri);
request(options, (err,res) => {
    debug("Requested: %s", options.uri);
    if(err) 
	return reject(err);

    resolve();
});

I simplify the code for guys to better understand, let's call n("string") as "number of string" in log, then the problem is n("Requesting")>n("Requested")

What's your advice?

@mike442144
Copy link
Author

In case of misunderstanding, for instance, I have called request(), say 1k times, but got 9997 responses. Does anybody have same problem?

@derekseymour
Copy link

Same thing with us on the latest release.

@mike442144
Copy link
Author

@derekseymour Hi, do you use proxy in your code? I'm not sure if it is a proxy issue.

@kegsay
Copy link

kegsay commented Dec 22, 2016

I have also noticed this, I'm running 2.75.0

Server-side logs show that a 200 OK response is indeed being sent back, but nothing is logged in the client application. The first thing the client does is log the response, so I'm fairly confident this isn't an application fail on my end. These requests are typically quick (load balancer logs suggest it took 88ms to from recv req -> fully send response) so I don't think timeouts are being hit. The one noticeable point here is that I sent 2 requests at virtually the same time: so I'm wondering if request has a race condition which can cause the callback to never be invoked.

Sadly, this is a spectacular failure mode and has serious consequences for us, as we queue up requests and rely on requests either succeeding/failing/timing out in request. I can no longer trust request to do this now.

@mike442144
Copy link
Author

@kegsay I have this kind of problem only in the scenario of using proxy. There is no race condition for concurrent because in request all requests are sent and an Agent will handle the queue if maxSocket isn't infinite. In default http.Agent, maxSocket is infinite, so if you use the default one which means you do not specify the agent option or using proxy, all the requests will be sent.

What I wonder is the timeout feature so I read the source code about timeout and found nothing incorrect. Timeout event would have happened on socket regardless of HTTP error in theory. Do you have any idea? @mscdex @simov

@mscdex
Copy link
Contributor

mscdex commented Dec 23, 2016

@mike442144 I don't know anything about the proxy support.

@mike442144
Copy link
Author

mike442144 commented Dec 23, 2016

@mscdex @simov @koichik Okay, I check the test cases, and in test-timeout.js, there is no timeout case about proxy or tunnel-agent. Should we add cases to cover it?

@kegsay
Copy link

kegsay commented Dec 23, 2016

@mike442144 request won't fire timeouts if it thinks the request succeeded. I suspect that request got the response and then for some reason decided not to invoke the callback. I speculate it's a race condition due to the fact that I sent 2 and the responses according to load balancer logs were transmitted at the same millisecond.

@mike442144
Copy link
Author

@kegsay Maybe you are right, I'll continue checking.

@dish615
Copy link

dish615 commented Dec 28, 2016

any progress on this? I'm having the same issue with particular websites I'm making a get request to.

@mike442144
Copy link
Author

@dish615 Do you use proxy?

@mike442144
Copy link
Author

I've found the bug, it is in tunnel-agent. So if you are using proxy and your target website protocol is https, you would have the same problem. Below is the detail of the bug:

  1. TCP connection established from client, which is your process, to the proxy server. TCP status is ESTABLISHED and the socket fireup a 'connect' event.
  2. Client send a http request whose method is CONNECT to proxy server, but never got a response

According to the nodejs manual, a tcp socket connection will be timed out before established by the operating system, but a http request never.So when you call reuqest() in request.js with proxy, request.js got a socket only tunnel-agent have a http connection with proxy. See the code below:

// in tunnel-agent.js
connectReq.once('connect', onConnect)
//...
function onConnect(){
    pending.request.onSocket(socket) // pending.request is an instance of ClientRequest
}

// in _http_client.js
function onSocket(socket){
    req.emit('socket',socket); // request.js got the 'socket' event.
}

// in request.js
self.req.on('socket', function(socket) {
    var setReqTimeout = function() {
        self.req.setTimeout(timeout, function () {
        if (self.req) {
          self.abort()
          var e = new Error('ESOCKETTIMEDOUT')
          e.code = 'ESOCKETTIMEDOUT'
          e.connect = false
          self.emit('error', e)
        }
      })
    }
}

If tunnel-agent could not get a response for a 'connect' request, obviously request.js cannot get the socket event, which resulted in no timeout timer set to the underlying socket. That's the root cause, it is deep but solution is quite simple:

connectReq.setTimeout(options.timeout || 15000, function(){
    connectReq.abort();
});

That's all. I'll open a PR to the tunnel-agent.js.
@simov

@mike442144
Copy link
Author

@simov What are you going to do?

@lneveu
Copy link

lneveu commented Feb 6, 2017

Same issue here! Thanks @mike442144 for your PR 👍

@mike442144
Copy link
Author

@lneveu You're welcome.

mattlunn added a commit to mattlunn/build-screen that referenced this issue Jul 7, 2017
@yodeyer
Copy link

yodeyer commented Aug 13, 2018

Hello,

Any news concerning this issue?
We have the same issue in production (socket not being closed), and I would prefer not to use a fork.
Is there anything we can do to help ?

@mike442144
Copy link
Author

@yodeyer pls refer to #2440

@stale
Copy link

stale bot commented Aug 14, 2019

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

@stale stale bot added the stale label Aug 14, 2019
@mike442144
Copy link
Author

not resolved, let's keep it open. refer to #2440 for more details.

@stale stale bot removed the stale label Aug 20, 2019
@stale
Copy link

stale bot commented Aug 19, 2020

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

@stale stale bot added the stale label Aug 19, 2020
@stale stale bot closed this as completed Aug 29, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

8 participants
@mscdex @mike442144 @derekseymour @kegsay @yodeyer @lneveu @dish615 and others