A case of weird behavior of keepalive connections with redirection

[1AdAstra1]

In our app that uses em-http-request we encountered a weird issue with one of our third-party API providers that uses 302 HTTP status to redirect users to the actual content file. The file took too long to download every time - 10 seconds, to be precise. But it was ligntning-fast in a browser or in cURL command line.

So I extracted some code to make a clean test case to see how EventMachine HTTP client (version 1.1.2 in our environment) handles such a request. The code was:

EventMachine.run {
    http = EventMachine::HttpRequest.new('http://some-url-with-redirection.com/').get :redirects => 2, keepalive: true
    http.callback { 
        p http.last_effective_url 
        p http.response_header
        p http.response
        EventMachine.stop
    }
}

The URL in question was my test machine with a one-line test script that redirects to another page. I ran this code a few times, with and without the 'keepalive' parameter. Then I took a look at the server logs, and here's what I found there:

(without keepalive parameter)

204.93.238.77 - - [29/Oct/2014:20:52:57 +0300] "GET /test.php HTTP/1.1" 302 209 "-" "EventMachine HttpClient" "-"
204.93.238.77 - - [29/Oct/2014:20:52:58 +0300] "GET /redirect_page.html HTTP/1.1" 200 1411 "-" "EventMachine HttpClient" "-"

(with keepalive parameter)

204.93.238.77 - - [29/Oct/2014:20:53:56 +0300] "GET /test.php HTTP/1.1" 302 238 "-" "EventMachine HttpClient" "-"
204.93.238.77 - - [29/Oct/2014:20:54:06 +0300] "GET /redirect_page.html HTTP/1.1" 200 1440 "-" "EventMachine HttpClient" "-"

So, the server is OK, but the EventMachine client is not releasing the connection for 10 seconds before following the next location URL that comes in a header. The inactivity_timeout option is not helping either, I tried to set it to 1 or 2 seconds, but the data was still being loaded in 10 seconds. I disabled keep-alive HTTP connections so far in our environment, but, anyway, this behavior is a bit unpredictable. Neither browsers nor cURL have such a problem with connections like that (and they assume the connections to be keep-alive by default, as they use HTTP 1.1). Can anything be done about it?

[igrigorik]

We need more data to diagnose this. As a start, can you capture the full HTTP request <> response cycle? What server are you using? It sounds like the server is not completing the request and hence the timeout.

[igrigorik]

Please reopen if you can get a more complete trace.

[soylent]

I had no problem reproducing this issue. Redirect request is triggered in EventMachine::HttpConnection#unbind only after comm_inactivity_timeout (10 seconds) when the original connection is being closed.

[igrigorik]

@soylent can you put together a test case?

[soylent]

@igrigorik sure, hopefully this week