Timeout issue in dev mode with phoenix about bandit HOT 15 CLOSED

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

from bandit.

Thanks, have just tried and same issue

from bandit.

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).

from bandit.

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.

from bandit.

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?

from bandit.

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

from bandit.

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:

@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.

from bandit.

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.

from bandit.

from bandit.

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.

from bandit.

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!

from bandit.

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.

from bandit.

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.

from bandit.

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

from bandit.

Thanks folks!

from bandit.