HTTP/1.1 client persistent connections issues

[sdebnath]

Hi there,

I have a small easy test case that repros consistently. I have a small API server built using Webmachine that is responding to REST clients. Since webmachine is built upon mochiweb, filing the issue here. The test clients are written in erlang using eunit and the source can be found at the link below. I have already vetted the fact that its not an inets/httpc issue (see link to erlang-questions below).

The issue:
httpc by default uses HTTP/1.1 to open connections with the server. Within the same connection I do 2 sequential GET requests and in another connection 2 sequential POST requests. The connection with the POST requests fails 99.99% of the time while the GET requests always succeed. After trying different options, turns out using HTTP/1.0 instead of HTTP/1.1 for the POST connections makes it work. Based on the erlang-questions thread, the client is trying to re-use the same connection while the server has closed it which results in **error:{badmatch,{error,socket_closed_remotely}}. Adding debug printfs produced a big enough delay in the client to catch the server's closing of the connection.

Expected:
Since its HTTP/1.1, mochiweb should not be closing the connection after each request. Passing in "Connection: keep-alive" header didn't help either.

Link to erlang-questions

• discussion thread: http://erlang.org/pipermail/erlang-questions/2015-January/082654.html
• most important message with the workaround: http://erlang.org/pipermail/erlang-questions/2015-January/082656.html

Link to test source & output: http://pastebin.com/9DFzxLps

[etrepum]

The repro doesn't appear to include the server-side code. Can you include that?

[sdebnath]

Okay give me a few, and I will create a new test server, I am currently running it with our internal app.

[etrepum]

Also, what release of Erlang are you testing with?

[etrepum]

With Erlang R17 and the latest mochiweb, using a server that doesn't have any handlers at all for POST (_ -> Req:not_found()), I am unable to reproduce.

[httpc:request(post, {"http://localhost:8080/" ++ Path, [], "application/json", "{}"}, [], []) || _ <- lists:seq(1, 10), Path <- ["begin_url", "end_url"]].
[{ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type","text/plain"}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length","10"},
       {"content-type",[...]}],
      "Not found."}},
 {ok,{{"HTTP/1.1",404,"Object Not Found"},
      [{"date","Thu, 15 Jan 2015 23:05:41 GMT"},
       {"server","MochiWeb/1.0 (Any of you quaids got a smint?)"},
       {"content-length",[...]},
       {[...],...}],
      "Not found."}}]

It is not using a persistent socket for this though, if you send a response before reading the body of a request it'll close the socket after the response is complete. You can see here that the socket gets closed before the body gets sent.

$ telnet localhost 8080
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
POST /begin HTTP/1.1
Host: localhost:8080
Content-Length: 4
Content-Type: application/json

HTTP/1.1 404 Object Not Found
Server: MochiWeb/1.0 (Any of you quaids got a smint?)
Date: Thu, 15 Jan 2015 23:08:24 GMT
Content-Type: text/plain
Content-Length: 10

Not found.Connection closed by foreign host.

[sdebnath]

Narrowed the repro down and turns out its a webmachine issue. Enabling tracing results and doing 2 sequential POST calls that results in failure ends up dropping the connection.

[etrepum]

I'm going to commit a patch for this, but it won't change webmachine's behavior at all as it doesn't use the mochiweb_request module. There's also no guarantee that it will be a workaround for this bug in httpc either, but it seems like it may be the right thing to do.

[sdebnath]

@etrepum I am getting set up to look at httpc right now. Should be a fun experience in hunting this down and fixing this.

[etrepum]

You could always configure httpc to never re-use connections, if you really want to continue using httpc.

[sdebnath]

Building and tearing down connections are expensive unless absolutely necessary. It seems like patching httpc to handle this corner case is also the right thing to do. And for continuing to use httpc - why not fix it if we can and make the erlang distribution better :)