How to manage exception after connexion timeout ?
jschaeff opened this issue · 6 comments
My application sends data using Plug.send_chunked/2
Somtimes, the client disconnects (how rude) and then Bandit spits a lot of errors (I guess one per chunks) like this:
2024-02-13T08:26:26.66053416Z stdout F 08:26:26.652 request_id=e02b53330f86e32c489b9984b628c91d application=wsdataselect [error] Error sending chunk to client: :timeout
2024-02-13T08:26:26.740291959Z stdout F 08:26:26.662 request_id=e02b53330f86e32c489b9984b628c91d [error] Bandit.HTTP1.Handler #PID<0.224281.0> received unexpected message in handle_info/2: {#Port<0.146814>,
Can you give me a hint on how to manage this situation to avoid all these ?
So, client connection closes mid-response are a bit of an odd case in the Plug lifecycle.
On the one hand, the various Plug.Conn.send_* calls generally return error tuples to indicate that there was an error sending whatever they were trying to send, and so the app should probably do something about it (most likely, give up on the response).
On the other hand, the only thing a Plug is supposed to do is to handle a request, so it has no business living any longer than necessary to do that one job. Once we've seen a client close, there's no possible way to bring the response to completion, so raising an error is arguably the correct thing to do.
Partly to try and square this circle, I've recently done some pretty substantial refactors of both the HTTP/1 and HTTP/2 stacks (the HTTP/2 is merged into main but unreleased, the HTTP/1 work is in #297). Once merged, Bandit's behaviour in this case will be to raise a relevant exception, and terminate the response handling for you. You'll still have these errors in your logs though (because, hey, we're just telling you your clients are closing early). Why your clients are doing this is up to you; by the time this happens there's no way for the server to mitigate the issue. Note that Cowboy, in its typical fashion, is silent about these error and just doesn't log anything. Presumably they're still happening there, just silently.
(Aside: I'd be interested in seeing the rest of that second 'received unexpected message' line!)
Thank you for this detailed reply.
To answer your curiosity, this is the full log line. The :data part is probably the binary chunk passed to the client.
2024-02-13T13:34:56.481017973Z stdout F 13:34:56.445 request_id=d57eab7afcac53b9d9dd6fd309b66214 [error] Bandit.HTTP1.Handler #PID<0.250641.0> received unexpected message in handle_info/2: {#Port<0.186415>, {:data,
<<48, 48, 48, 53, 49, 51, 81, 32, 66, 79, 82, 32, 32, 48, 48, 69, 72, 78, 80, 70, 7, 223, 0, 23, 7, 8, 46, 0, 11, 15, 20, 102, 0, 100, 0, 1, 0, 32, 0, 2, 0, 0, 0, 0, 0, 64, ...>>}}
In my code, when this case happens, I just close the relevant things but let the Plug.Conn live it's life until the end of the request.
case Plug.Conn.chunk(conn, datachunk) do
{:ok, conn} ->
IO.binwrite(device, datachunk)
stream_dataselect_output(conn, p, device)
true
{:error, e} ->
Logger.error("Error sending chunk to client: #{inspect(e)}")
# TODO Should we close connection here ?
# Like this ?
# Plug.Conn.halt(conn)
false
endThat {:data, ....} tuple - is that something you're sending to your own processes (or maybe that a library is?)
Great! I was worried that that was something internal to Bandit; given that it's coming from something external of yours, then that messages is expected.