GET timeout after POST request

[jamhed]

Cowboy version 1.0.1

GET request terminates by timeout (15 seconds) if follows POST request.
As a work-around I just manually close HTTP connection right after POST request.

Please see HTTP messages log down here:

T 127.0.0.1:46915 -> 127.0.0.1:9080 [AP]
POST /store HTTP/1.1.
Host: localhost:9080.
Connection: keep-alive.
Content-Length: 28161.
Pragma: no-cache.
Cache-Control: no-cache.
Accept: /.
Origin: http://localhost:9080.
X-Requested-With: XMLHttpRequest.
User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.135 Safari/537.36.
Content-Type: multipart/form-data; boundary=----WebKitFormBoundarypxEP1lB353zVwsgJ.
Referer: http://localhost:9080/.
Accept-Encoding: gzip, deflate.
Accept-Language: ru-RU,ru;q=0.8,en-US;q=0.6,en;q=0.4.
.

T 127.0.0.1:9080 -> 127.0.0.1:46915 [AP]
HTTP/1.1 200 OK.
connection: keep-alive.
server: Cowboy.
date: Fri, 12 Jun 2015 20:46:04 GMT.
content-length: 0.
.

T 127.0.0.1:46915 -> 127.0.0.1:9080 [AP]
GET /store/avatar/3622058535?1434141965084 HTTP/1.1.
Host: localhost:9080.
Connection: keep-alive.
Pragma: no-cache.
Cache-Control: no-cache.
Accept: image/webp,/;q=0.8.
User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.135 Safari/537.36.
Referer: http://localhost:9080/.
Accept-Encoding: gzip, deflate, sdch.
Accept-Language: ru-RU,ru;q=0.8,en-US;q=0.6,en;q=0.4.

-------------------------- 15 seconds timeout -------------------------

-------------------- Request repeated by browser -------------------

T 127.0.0.1:46917 -> 127.0.0.1:9080 [AP]
GET /store/avatar/3622058535?1434141965084 HTTP/1.1.
Host: localhost:9080.
Connection: keep-alive.
Pragma: no-cache.
Cache-Control: no-cache.
Accept: image/webp,/;q=0.8.
User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.135 Safari/537.36.
Referer: http://localhost:9080/.
Accept-Encoding: gzip, deflate, sdch.
Accept-Language: ru-RU,ru;q=0.8,en-US;q=0.6,en;q=0.4.
.

T 127.0.0.1:9080 -> 127.0.0.1:46917 [AP]
HTTP/1.1 200 OK.
transfer-encoding: identity.
server: Cowboy.
date: Fri, 12 Jun 2015 20:46:19 GMT.
connection: close.
content-type: image/jpeg.

[essen]

Can you give the handler code for the POST and/or more info about what kind of handler and what it is doing?

[romangaleev]

Sure. It is a XHR file upload request, here is the handler:

https://gist.github.com/romangaleev/e22d5f4b24644dcea76e

[romangaleev]

And here is dispatcher:

dispatch_rules() ->
cowboy_router:compile(
[{'_', [
{"/store/[...]", web_store, ["store"]},
{"/image/[...]", web_image, ["store"]},
{"/", cowboy_static, {file, "web/index.html"}},
{"/main/ws/[...]", bullet_handler, [{handler, ws_main}]},
{"/[...]", cowboy_static, {dir, "web"}}
]}]).

[essen]

Thanks, I will try in a few days, I have quite a backlog right now. :-)

[romangaleev]

I can provide you a test server if you'd like to, with a running
application. It may simplify debugging.

On Tue, Jul 14, 2015 at 9:14 AM, Loïc Hoguin notifications@github.com
wrote:

Thanks, I will try in a few days, I have quite a backlog right now. :-)

—
Reply to this email directly or view it on GitHub
#833 (comment).

With best regards,
Roman Galeev,
+420 702 817 968

[essen]

If I fail to reproduce the issue then perhaps, thanks. Today I can't work though so I will get back to you.

[jamhed]

Any luck meanwhile? :)

[essen]

Sorry, haven't had much time to work on Cowboy yet.

[essen]

Don't see the issue, but one thing though: the only place in Cowboy with 15000 is the default socket read timeout when reading the body. Since GET has no body, guessing it's POST that has issues?

[endeepak]

I'm facing similar issue and the stack trace shows

2015-11-10T16:56:06.680425+00:00 app[web.1]: 16:56:06.680 request_id=19c1ba3f-cfaf-476f-a145-12d234b61c55 [info] POST /stub_urls
2015-11-10T16:56:21.684018+00:00 heroku[router]: at=info method=POST path="/stub_urls" host=stubonweb.herokuapp.com request_id=19c1ba3f-cfaf-476f-a145-12d234b61c55 fwd="43.247.159.40" dyno=web.1 connect=1ms service=15004ms status=500 bytes=243
2015-11-10T16:56:21.683882+00:00 app[web.1]: 16:56:21.683 [error] #PID<0.429.0> running StubOnWeb.Endpoint terminated
2015-11-10T16:56:21.683887+00:00 app[web.1]: Server: stubonweb.herokuapp.com:80 (http)
2015-11-10T16:56:21.683888+00:00 app[web.1]: Request: POST /stub_urls
2015-11-10T16:56:21.683889+00:00 app[web.1]: ** (exit) an exception was raised:
2015-11-10T16:56:21.683890+00:00 app[web.1]:     ** (CaseClauseError) no case clause matching: {:error, :timeout}
2015-11-10T16:56:21.683891+00:00 app[web.1]:         (plug) lib/plug/parsers/urlencoded.ex:10: Plug.Parsers.URLENCODED.parse/5
2015-11-10T16:56:21.683892+00:00 app[web.1]:         (plug) lib/plug/parsers.ex:186: Plug.Parsers.reduce/6
2015-11-10T16:56:21.683893+00:00 app[web.1]:         (stub_on_web) lib/stub_on_web/endpoint.ex:1: StubOnWeb.Endpoint.phoenix_pipeline/1
2015-11-10T16:56:21.683894+00:00 app[web.1]:         (stub_on_web) lib/phoenix/endpoint/render_errors.ex:34: StubOnWeb.Endpoint.call/2
2015-11-10T16:56:21.683894+00:00 app[web.1]:         (plug) lib/plug/adapters/cowboy/handler.ex:15: Plug.Adapters.Cowboy.Handler.upgrade/4
2015-11-10T16:56:21.683895+00:00 app[web.1]:         (cowboy) src/cowboy_protocol.erl:442: :cowboy_protocol.execute/4

@essen 's last comment seems to make more sense with this stack trace and corresponding line(plug/parsers/urlencoded.ex:10) in code

Also in my case this issue started after I followed the phoenixframework/phoenix#459 (comment) to read request body and added the below code in endpoint.ex

defp copy_req_body(conn, _) do
    {:ok, body, _} = Plug.Conn.read_body(conn, length: 1_000_000_000)
    Plug.Conn.put_private(conn, :raw_request_body, body)
end

plug :copy_req_body

plug Plug.Parsers,
    parsers: [:urlencoded, :multipart, :json],
    pass: ["*/*"],
    json_decoder: Poison

More context on the problem is posted on http://stackoverflow.com/questions/33637418/elixir-phoenix-on-heroku-timeout-error-after-15-seconds

Is there a way to fix this? Would increasing socket timeout solve this issue? If so, how to increase the time out?

[essen]

Basically no idea what you just said, but to answer the question, yes, the timeout can be increased on a per call basis. See the manual for the body functions.

[jamhed]

Since GET has no body, guessing it's POST that has issues?

The issue arises if a GET request followed by POST request. So probably this is the case: POST somehow tries to read till timeout, and therefore following GET request is not handled.

[essen]

I haven't been able to retry this, and am not sure this still applies to master (body reading has changed) so I will be closing this. Thanks!