Unrecoverable error: closed

[andyleclair]

Hi!
We upgraded Bandit from 1.5.7 to 1.6.4 and started seeing a nonzero number of new Bandit.TransportError

It's a small percentage, but it seems like a regression. Happy to provide as much context as I can!

Stacktrace:

[andyleclair]

Downgrading to 1.5.7 makes this error go away

[mtrudel]

Are you able to deploy the branch at #453 and grab a trace based on the instructions therein?

[andyleclair]

Let me confer with my team. I'd prefer not to be handing errors to my clients in prod, but if it's load-related, I'm not sure I could reproduce on staging

[Tricote]

I'm on version 1.6.1 and I also get some of these:

lib/bandit/http1/socket.ex:437 Bandit.HTTPTransport.Bandit.HTTP1.Socket.socket_error!/1	
lib/bandit/http1/socket.ex:344 Bandit.HTTPTransport.Bandit.HTTP1.Socket.send_headers/4	
lib/bandit/http1/socket.ex:422 Bandit.HTTPTransport.Bandit.HTTP1.Socket.send_on_error/2	
lib/bandit/pipeline.ex:223 Bandit.Pipeline.handle_error/7	
lib/bandit/http1/handler.ex:12 Bandit.HTTP1.Handler.handle_data/3	
lib/bandit/delegating_handler.ex:18 Bandit.DelegatingHandler.handle_data/3	
/app/deps/thousand_island/lib/thousand_island/handler.ex:417 Bandit.DelegatingHandler.handle_continue/2	
gen_server.erl:2163 :gen_server.try_handle_continue/3

[andyleclair]

We noticed these errors originally on 1.6.3 and upgraded to 1.6.4 hoping it would fix it, but it did not.

[mtrudel]

If anyone is able to run the branch I linked to above and report back with dumps, that would greatly help with trying to resolve this (these?) issues

[andyleclair]

@mtrudel I'm going to try to run that on one server out of our prod fleet tomorrow. I'll do my best to report back findings

[mtrudel]

In any of these cases, could someone please provide a complete exception output, including the message text?

[c4710n]

@mtrudel

GenServer #PID<0.402810.0> terminating
** (Bandit.TransportError) Unrecoverable error: closed
    (bandit 1.6.1) lib/bandit/http1/socket.ex:437: Bandit.HTTPTransport.Bandit.HTTP1.Socket.socket_error!/1
    (bandit 1.6.1) lib/bandit/http1/socket.ex:344: Bandit.HTTPTransport.Bandit.HTTP1.Socket.send_headers/4
    (bandit 1.6.1) lib/bandit/http1/socket.ex:422: Bandit.HTTPTransport.Bandit.HTTP1.Socket.send_on_error/2
    (bandit 1.6.1) lib/bandit/pipeline.ex:223: Bandit.Pipeline.handle_error/7
    (bandit 1.6.1) lib/bandit/http1/handler.ex:12: Bandit.HTTP1.Handler.handle_data/3
    (bandit 1.6.1) lib/bandit/delegating_handler.ex:18: Bandit.DelegatingHandler.handle_data/3
    (bandit 1.6.1) /build/4z10g0y1h11jvc4pc33mz23alqwh0012-source/deps/thousand_island/lib/thousand_island/handler.ex:417: Bandit.DelegatingHandler.handle_continue/2
    (stdlib 5.2.3) gen_server.erl:1085: :gen_server.try_handle_continue/3
Last message: {:continue, :handle_connection}

[andykent]

We are also seeing a lot of these errors show up in Sentry. We are running bandit 1.6.7 alongside Phoenix / Absinthe. Very different stack trace to above though.

Bandit.TransportError: Unrecoverable error: closed
  File "lib/bandit/http1/socket.ex", line 440, in Bandit.HTTPTransport.Bandit.HTTP1.Socket.socket_error!/1
  File "lib/bandit/http1/socket.ex", line 230, in Bandit.HTTPTransport.Bandit.HTTP1.Socket.do_read_content_length_data!/4
  File "lib/bandit/http1/socket.ex", line 180, in Bandit.HTTPTransport.Bandit.HTTP1.Socket.read_data/2
  File "lib/bandit/adapter.ex", line 62, in Bandit.Adapter.read_req_body/2
  File "lib/plug/conn.ex", line 1151, in Plug.Conn.read_body/2
  File "lib/plug/parsers/json.ex", line 75, in Plug.Parsers.JSON.parse/5
  File "lib/plug/parsers.ex", line 340, in Plug.Parsers.reduce/8
  File "lib/app_web/endpoint.ex", line 1, in AppWeb.Endpoint.plug_builder_call/2

[mtrudel]

There are actually two distinct issues happening here.

The First Error

The first, as reported by @andyleclair & @andykent, is increased visibility of legitimate client terminations (ie: those are actual client-side shutdowns). Bandit changed how these errors are plumbed in 1.6.1: prior to this version they were passed around as Bandit.HTTPErrors whereas now they're passed as Bandit.TransportError. The thing is that these are generally intended to be opaque to the user (which is why this wasn't considered a breaking change). The intended execution path when they're raised is as follows:

1. Bandit calls your Plug.call/2 function from within Bandit.Pipeline here
2. Your plug goes and does its thing, and at some point the Plug.Conn functions you call will end up calling into Bandit.Adapter.read_req_body (or some other Bandit.Adapter function) to actually interact with the underlying connection.
3. When one of these calls encounters an error (as you're seeing above), Bandit will raise an error (almost always either a Bandit.HTTPError or Bandit.TransportError depending on whether the error can be signalled to the client or not).
4. This raise will normally bubble right up through your code and be rescued by Bandit.Pipeline here. Bandit will then handle the error as per configuration.

The reason we do things this way is to mimic the behaviour of Cowboy in this regard (the semantics of Plug derive more or less directly from Cowboy, so we're a little underspecified). Cowboy realizes this behaviour by virtue of having multiple processes per connection which allows the backing connection to immediately kill the plug process in this case. Bandit's single-process model needs to resort to bubble-based cleverness to realize the same outcome.

What I believe is happening here is that your Sentry setup is seeing those errors as they bubble up through your Plug code (between steps 3 and 4 above). To be clear, this flow is the expected way for Bandit to handle these error cases; the issue here is that your Sentry setup sees those errors and reports on them as they bubble past it.

Do you have your Sentry config set up to ignore Bandit.HTTPErrors (which is how these normal client disconnections where reported prior to 1.6.1) but not to ignore Bandit.TransportError messages? If so, adding the latter to your list of ignored error types should fix the issue.

The Second Error

This is the error seen by @Tricote and @c4710n. In this case, you have a (presumably legitimate) error (likely a client closure) that is bubbling out to Bandit.Pipeline as above, but the error handling logic then raises ANOTHER error trying to signal back to the client. This was fixed in 1.6.2 per the changelog.

[mtrudel]

Closing for hygiene; doesn't look like there's anything to do for this on Bandit itself.

Thanks for the great discussion! If any other (or even this) issue comes up again, please feel free to (re)open an issue!

[andyleclair]

@mtrudel thank you so much for the thorough investigation!