timeout events emitted during/after request object receives data #3234

Closed
s3u opened this Issue May 7, 2012 · 13 comments

Projects

None yet

3 participants

@s3u
s3u commented May 7, 2012

I'm seeing that the timeout event gets emitted when not expected (such as after while receiving data events or after the end event.

var clientReq = http.request(options, function (clientRes) {
    // happy path

});
clientReq.setTimeout(someval, function () {
    // handle timeout
});
clientReq.end();

I don't have an isolated test case, but under load with slow resources, on occasion I see this behavior.

A work-around is to skip processing the timeout handler if the event occurs after response starts to trickle in.

@bnoordhuis
Member

Can you post the stack trace(s) you get?

@s3u
s3u commented May 7, 2012

You mean call trace for timeout and end events?

There are no stack traces as it is right now up to the app to handle this. In my case (ql.io - gateway style use case), the app ended up writing two responses with the second one causing Error: Can't set headers after they are sent.

@bnoordhuis
Member

@s3u Does it still happen with v0.6.18?

@s3u
s3u commented May 16, 2012

@bnoordhuis yes. My HTTP client looks like the one in https://gist.github.com/2712347

@bnoordhuis bnoordhuis added a commit that referenced this issue May 20, 2012
@bnoordhuis bnoordhuis test: add http 'data after timeout' test
See #3234. TDB if this is or is not the desired behavior.
ca642b0
@bnoordhuis
Member

Okay, I think I see what you mean. Can you confirm that the test in ca642b0 is similar to the behavior you're seeing?

Assuming it is, we'll have to decide if the current behavior should be changed. It's not quite principle of least surprise so that's an argument in favor of changing it. On the other hand, it's not unlikely that existing code relies on the current behavior so that's an argument against.

@s3u
s3u commented May 20, 2012

My test is similar to the one in https://gist.github.com/2759844.

The surprise here that after the timeout, the app received valid response and continued to process the response. In my case, it lead to two different responses to the application level - one indicating a socket timeout triggered by the timeout event, followed by one that indicated success.

@bnoordhuis
Member

@isaacs, @koichik: Do you guys have strong opinions? It seems reasonable (least surprising) to reset the timer when new data comes in.

@isaacs
isaacs commented May 21, 2012

@bnoordhuis I think you're right. The expected behavior would be for the timer to be cleared and re-set on each chunk of data that comes in, and removed entirely on end.

That is, if the server does this:

setTimeout(function () {
  res.write("*")
  setTimeout(function () {
    res.end("*")
  }, 100)
}, 10)

and the client has done req.setTimeout(30), then I would expect it to time out after 40ms. That is, at 10ms, it gets the chunk, which restarts the countdown.

@s3u
s3u commented May 21, 2012

@isaacs +1

@s3u
s3u commented Jun 14, 2012

Any chance this will make it in the 0.6.x lime? These are frequent under load.

@bnoordhuis
Member

Any chance this will make it in the 0.6.x lime?

I'm afraid the answer has to be 'no'. It's not a downright bug and we don't change behavior in stable releases (i.e. 0.6.x).

@s3u
s3u commented Jun 14, 2012

Looking at some of our recent logs under load, it seems that the sockets are getting destroyed between 'data' events as the timer is kicking to emit the timeout event and immediately calling self.destroy. The application can do nothing to prevent this even though it knows that the socket is not idle. Increasing timeout is an option but it has other consequences at the application level.

@bnoordhuis
Member

Closing, fixed in 451ff15.

@bnoordhuis bnoordhuis closed this Jan 7, 2013
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment