Elixir + Phoenix on Heroku : Timeout error after 15 seconds

Question

Context: I'm running a elixir+phoenix app https://github.com/endeepak/stub_on_web on Heroku. I've followed steps mentioned in http://www.phoenixframework.org/docs/heroku for deploying the app.

Problem: When a POST request takes longer than 15 seconds, the web server returns 500 Internal server error with logs showing error as no case clause matching: {:error, :timeout}. Error stack is pasted below

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

My observations

It is not the Heroku router's "H12 error" which happens if request takes longer that 30s. Ref: https://devcenter.heroku.com/articles/request-timeout . I couldn't get much help from heroku support as it seems like web server issue and they don't know erlang/elixir.
I've tried running on local with production config, simulated a delay of 60s. The request returns 200 OK response after 60s without any timeout error as above.

Is there any configuration I'm missing here? Any other thoughts?

This github issue might be related: github.com/ninenines/cowboy/issues/833 — Patrick Oscity
Thanks @PatrickOscity. That issue led me to another thread in phoenix issues and a temporary fix for the problem. If anyone else is facing similar issue, please refer github.com/phoenixframework/phoenix/issues/… for explanation and a workaround — Deepak N

Deepak N Deepak N · Accepted Answer · 2015-11-11T07:09:16

The issue happened since I had added a plug to read request body and save it as private assigns in conn for future access. The code used earlier was

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

There seems to an issue with plug which causes :timeout when the Plug.Parsers try to read the body again.

The temp work around for now is to use code as suggested in https://github.com/phoenixframework/phoenix/issues/459#issuecomment-155671415

Reference commit: https://github.com/endeepak/stub_on_web/commit/47192558f501652edd8cd237a5a2430f38177ca4

Elixir + Phoenix on Heroku : Timeout error after 15 seconds

1 Answers