Timeout issue in dev mode with phoenix

[mfeckie]

I'm not sure if this is the correct place to report this issue.

When working with a phoenix live view app in development I get this error reported.

[error] GenServer #PID<0.1040.0> terminating
** (stop) time out
Last message: :timeout
State: {%ThousandIsland.Socket{socket:

I think this is related to development mode because it references the SyncCodeReloadPlug

plug: {Phoenix.Endpoint.SyncCodeReloadPlug, {WodWeb.Endpoint, []}}}, handler_module: Bandit.HTTP2.Handler, plug: {Phoenix.Endpoint.SyncCodeReloadPlug, {WodWeb.Endpoint, []}}}}

It may be something bespoke to my setup because I'm running HTTPS in dev.

Happy to provide more information or move to a different place if it's the wrong place to report

[michealp-coder]

Have you tried the patch found in this ticket #74 ?

[mfeckie]

Thanks, have just tried and same issue

[mtrudel]

That timeout indicates the server timing out waiting to read data from the client. This could be the client being closed midway through an HTTP request, a network blip, or (99% of the time) related to a WebSocket client that's otherwise delayed client-side.

It's also possible that you've got timeouts configured abnormally. In normal operation, Phoenix's JS client will send a WebSocket heartbeat every 30s, which will normally arrive well before the default server timeout of 60s. If you've tinkered with your timeout settings (in your endpoint.ex file) that may be the cause here.

The SyncCodeReloadPlug is a red herring - that's a normal and expected part of the Plug stack in development (or any other environment where you have enabled automatic code reloading).

[mfeckie]

Interesting. I've gone through and had a look, there's nothing changed with timeouts or heartbeat.

As far as I can tell, it's all basically vanilla. Only thing I think I have is that I run HTTPS in dev.

I can consistently reproduce the error be simply visiting any liveview page and waiting around 60 seconds.

[moogle19]

I tried to reproduce this and have the same error, but only when using Firefox.
Did you also use Firefox? Did you test it with other browsers?

[mfeckie]

I do use Firefox. Just tried in Brave, Safari and Chrome, can reproduce there too

[moogle19]

Hmm, strange. In Safari I don't get the timeouts.
But I noticed a lot of "Could not determine protocol" errors from Safari "prefetching" the site:

My.Movie.mp4

@mtrudel
Maybe we should not error on this events and just ignore them? Or make it configurable? Otherwise the log get confusing fast.

Not sure how Cowboy handles these cases, but I did not notice these errors there before.

[ryanwinchester]

Is it only happening with https in dev mode?
I'm using bandit in a phoenix-based project under development (without https) and haven't had any issues yet.

[mfeckie]

I'm not sure about the others,I'm running https dev though

…

On Mon, 9 Jan 2023 at 21:48, Ryan Winchester ***@***.***> wrote: Is it only happening with https in dev mode? — Reply to this email directly, view it on GitHub <#79 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAMCUOPFTSJZ5LMVE2WSXW3WRQJK5ANCNFSM6AAAAAATTTK5OI> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[moogle19]

The timeout errors seems to be the "normal" http2 timeout after 60s.

Since thousand_island returns {:stop, :timeout, reason} on handle_info(:timeout, {socket, state}) (instead of {:stop, {:shutdown, :timeout}, reason} an error is logged here.

[mtrudel]

HTTP2 timeouts should be handled 'in-protocol' (see lib/bandit/http2/handler.ex:56), and generally should be silent in the logs (as @moogle19 's attached PR fixes).

Assuming that @moogle19 's hunch is correct (I'm sure it is), the attached PR should solve this. With what's at hand currently here, I don't quite get the logic jump to HTTP2 and would like to connect those dots to make sure we're solving the right thing. @mfeckie can you provide a more complete copy of the error that you get in the terminal when this happens? Also, a screenshot of the network tab in your browser inspector would be super helpful if possible.

Thanks all!

[moogle19]

Here is the complete output for an error:

[error] GenServer #PID<0.6420.0> terminating
** (stop) time out
Last message: :timeout
State: {%ThousandIsland.Socket{socket: {:sslsocket, {:gen_tcp, #Port<0.24>, :tls_connection, [option_tracker: #PID<0.6365.0>, session_tickets_tracker: :disabled, session_id_tracker: #PI
D<0.6366.0>]}, [#PID<0.6419.0>, #PID<0.6418.0>]}, transport_module: ThousandIsland.Transports.SSL, read_timeout: 15000}, %{buffer: "", connection: %Bandit.HTTP2.Connection{local_setting
s: %Bandit.HTTP2.Settings{header_table_size: 4096, max_concurrent_streams: :infinity, initial_window_size: 65535, max_frame_size: 16384, max_header_list_size: :infinity}, remote_setting
s: %Bandit.HTTP2.Settings{header_table_size: 65536, max_concurrent_streams: :infinity, initial_window_size: 131072, max_frame_size: 16384, max_header_list_size: :infinity}, fragment_fra
me: nil, send_hpack_state: %HPAX.Table{max_table_size: 4096, entries: [{"content-type", "text/javascript"}, {"etag", "\"7D65CB3\""}, {"accept-ranges", "bytes"}, {"content-type", "text/c
ss"}, {"etag", "\"7C1BC2\""}, {"cache-control", "public"}, {"x-permitted-cross-domain-policies", "none"}, {"x-frame-options", "SAMEORIGIN"}, {"x-download-options", "noopen"}, {"x-conten
t-type-options", "nosniff"}, {"referrer-policy", "strict-origin-when-cross-origin"}, {"x-request-id", "Fzjyda1rAHWPVpkAAQwj"}, {"cache-control", "max-age=0, private, must-revalidate"}, 
{"content-type", "text/html; charset=utf-8"}, {"date", "Tue, 10 Jan 2023 12:30:48 GMT"}], size: 899, length: 15}, recv_hpack_state: %HPAX.Table{max_table_size: 4096, entries: [{"sec-fet
ch-dest", "image"}, {"accept", "image/avif,image/webp,*/*"}, {"sec-fetch-dest", "iframe"}, {"if-none-match", "\"3123B9E\""}, {"sec-fetch-dest", "script"}, {"accept", "*/*"}, {"sec-fetch
-site", "same-origin"}, {"sec-fetch-mode", "no-cors"}, {"sec-fetch-dest", "style"}, {"referer", "https://localhost:4001/users/"}, {"accept", "text/css,*/*;q=0.1"}, {"te", "trailers"}, {
"sec-fetch-site", "cross-site"}, {"sec-fetch-mode", "navigate"}, {"sec-fetch-dest", "document"}, {"upgrade-insecure-requests", "1"}, {"cookie", "_phx_server_key=SFMyNTY.g3QAAAABbQAAAAtf
Y3NyZl90b2tlbm0AAAAYTDgtX2wweW0yc2c5dU5nblQ5ZWRqelJt.JBjmWzd6xp8hQexhqwyhkMbX4itwKWVndTdj8wh0yDk"}, {"cookie", "user_data=eyJoZXhfY29sb3IiOiIjRkE4MDcyIiwibmFtZSI6bnVsbH0="}, {"accept-en
coding", "gzip, deflate, br"}, {"accept-language", "en-US,en;q=0.7,de;q=0.3"}, {"accept", "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"}, {"use
r-agent", "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:108.0) Gecko/20100101 Firefox/108.0"}, {":authority", "localhost:4001"}], size: 1571, length: 23}, send_window_size: 11844157
, recv_window_size: 65535, streams: %Bandit.HTTP2.StreamCollection{initial_recv_window_size: 65535, initial_send_window_size: 131072, max_concurrent_streams: :infinity, last_local_strea
m_id: 0, last_remote_stream_id: 23, streams: %{}}, pending_sends: [], plug: {Phoenix.Endpoint.SyncCodeReloadPlug, {PhxServerWeb.Endpoint, []}}}, handler_module: Bandit.HTTP2.Handler, pl
ug: {Phoenix.Endpoint.SyncCodeReloadPlug, {PhxServerWeb.Endpoint, []}}}}

It only occurs for https requests since we currently don't support upgrading from http1.1 to h2 (nor does Firefox try to upgrade for http requests). So only the https requests use h2.

The h2 connection is kept alive until either the client or the server close it (both is okay from what I read in the specs).
In this case the server closes the connection after the 60s timeout (since the Firefox timeout is at 170s by default).
When chaning the Firefox timeout to a value <60s no error is logged.

Hope that clarifies the issue.

[mtrudel]

Yep, that lines it up for me too. Good sleuthing!

I'll close this once mtrudel/thousand_island#36 merges and we update dependencies to pull that version of Thousand Island in.

[mtrudel]

Fixed in Thousand Island 0.5.15 / Bandit 0.6.5, both just released!

[mfeckie]

Thanks folks!