invalid_request, CaseClauseError

[woylie]

I configured Bandit in a Phoenix 1.7-rc.0 / LiveView application. Ever since making the change, I'm getting invalid_request errors. In one application, this occurs periodically during deployments, in another one, it happens throughout the day, about 60 times per hour, which makes me think that it has something to do with health checks.

In any case, Cowboy does not log or raise errors under the same circumstances.

Before Bandit 0.6.4, this is what gets logged:

message
  GenServer #PID<0.7891.0> terminating
** (stop) :invalid_request
Last message: {:continue, :handle_connection}
metadata.domain
  otp
metadata.erl_level
  error
metadata.error.initial_call
  
 - 
metadata.error.reason
  {:invalid_request, []}
metadata.error_logger.report_cb
  &:gen_server.format_log/1
metadata.error_logger.tag
  error
severity
  error

After upgrading to Bandit 0.6.4, we're getting a CaseClauseError instead:

CaseClauseError: no case clause matching: {:error, :invalid_request}
  File "lib/thousand_island/handler.ex", line 387, in Bandit.DelegatingHandler.handle_continuation/2
  File "gen_server.erl", line 1123, in :gen_server.try_dispatch/4
  File "gen_server.erl", line 865, in :gen_server.loop/7
  File "proc_lib.erl", line 240, in :proc_lib.init_p_do_apply/3

I guess the :invalid_request error comes from here:

bandit/lib/bandit/http1/adapter.ex

Line 76 in 422651d

{:ok, {:http_error, _reason}, _rest} ->

This means that :erlang.decode_packet/3 returns an HTTP error, but unfortunately, Bandit discards the reason.

While we haven't figured out what exactly causes the invalid requests, this should probably be handled gracefully?

[dmorneau]

Could this be HTTPS health checks sent to an HTTP listener?

[woylie]

Could this be HTTPS health checks sent to an HTTP listener?

No, that's not it.

[mtrudel]

Thanks for the report!

The discrepancy between 0.6.4 and earlier versions is due to a return argument I'd missed in refactoring; it's fixed on the linked PR.

In terms of the overall issue of verbose logging, I suspect that Cowboy is also erroring on these same connections, but is doing so silently as is its general policy (Bandit logs loudly on error cases by design). What you're seeing on the earlier versions is intended, though we should be passing through the underlying error (I've got this fix on the PR as well).

Is it possible for you to test against a Bandit branch and report back as to the error you're seeing? The :http_error tuple is an untested code path, and I'm honestly not sure how to poke decode_packet in the right way to issue it. I'd love to add a test case for it if you can let me know what type of bogus request induces it.

See #76 for the branch to test against.

[mtrudel]

Do you have any idea about what client is making this request, or anything else that can characterize things from the client side?

[mtrudel]

It looks like the response you sent me via DM is a verbatim copy of (part of) the client request. They don't parse as either HTTP/2 or WebSocket payloads, so I'm not really sure what to suggest here other than that it may be an SSL request. I don't know how much further we can go on covering this with tests unless we can glean more info out of any client info you can provide.

In the meantime I'm going to merge #76.

[mtrudel]

GitHub automation mistakenly closed this issue. I'll re-open it in anticipation of more client info.

[woylie]

It seems like it is an HTTPS request after all. In the messages that are logged, the first bytes are always <<22, 3, 1>>, which means content type handshake(22) and protocol version 3.1. Looks like something is misconfigured somewhere. I'd say this issue can be closed as soon as the log message is improved?

[mtrudel]

Good sleuthing! The error message has been updated in #76 to log these cases more simply (and to prevent the GenServer terminating logging loudness on the part of the OTP runtime). I think that covers us from a verbosity perspective, though it may be helpful for future folks if we special-case <<22, 3>> and suggest to the user that this connection may be HTTPS? I can work that up in a separate PR. For now we can close this issue.

Thanks for the issue!

[woylie]

I updated to the latest version from main, but I'm still seeing these error messages:

GenServer #PID<0.4535.0> terminating
** (stop) <<22, 3, 1, ...>>
Last message: {:continue, :handle_connection}

I'd appreciate better error messages. Sentry isn't able to recognize these errors as the same, so it's mayhem over there...

[mtrudel]

Drag. I'll dig a bit deeper tomorrow and hopefully get to the bottom of it. Now that we have a known repro case it should be straightforward.

[mtrudel]

0.6.6 just dropped with a fix for this. Connections made to an HTTP server that look like HTTPS (ie: that start with <<22, 3, I>> when i in [1,3]) are logged as such.

[woylie]

There is one observable difference between Cowboy and Bandit, easily reproducible by just running any plain HTTP server and running curl https://localhost:4000 instead of using http://.

With Bandit, curl returns curl: (35) Recv failure: Connection reset by peer. Wget returns Unable to establish SSL connection. without any further details.

With Cowboy, I'm getting an error from the used SSL library, e.g. curl: (35) LibreSSL/3.3.6: error:1404B42E:SSL routines:ST_CONNECT:tlsv1 alert protocol version or OpenSSL: error:0A00010B:SSL routines::wrong version number.

I don't know whether one of the implementations is more correct than the other.

[mtrudel]

Bandit special cases the tls preamble specifically to log on this server side. From there it'll forcibly close the connection which is why you're seeing a difference in behaviour. They're both to spec, since that corner of tls is undefined

[mtrudel]

See https://github.com/mtrudel/bandit/blob/main/lib/bandit/initial_handler.ex#L25