Treat abortive-close posix reasons as client closures in logging (#663)

Bandit.Logger.maybe_log_protocol_error/4 only suppressed logging for
%Bandit.TransportError{error: :closed}, so a client that aborts a
connection (RST) during HTTP/2 init - before conn_data/peer_data can
be obtained - gets logged at ERROR level even with the default
log_client_closures: false, because peername/1 surfaces a different
posix reason (e.g. :enotconn, :einval, :econnaborted, :econnreset)
for an abortive close rather than :closed.

A peer that is already gone is a client closure regardless of which
of these reasons the socket happens to report, so treat all of them
the same way :closed is treated.

Adds an HTTP2ProtocolTest case that opens a TLS connection with
linger: {true, 0} (forcing an abortive RST close) and closes it
immediately, before any HTTP/2 bytes are exchanged, then asserts
nothing is logged at the default settings - the same connection-init
code path as the reported issue. Transport.tls_client/2 gains an
optional third `opts` argument so the test can pass linger through
to the underlying :ssl.connect call.

Also loosens two pre-existing HTTP/1 logging assertions that
hardcoded "closed" as the only expected posix reason in the log
message text; on this platform an abortive close of an in-flight
request can legitimately surface as :econnreset or similar, which is
exactly the class of reason this fix now handles consistently.

Fixes #647

Author: mtrudel

lib/bandit/logger.ex

@@ -3,10 +3,17 @@ defmodule Bandit.Logger do
 
   require Logger
 
+  # Posix reasons that a peer socket can surface as once the client has gone away.
+  # `:closed` is the common case, but an abortive close (RST) can also surface as
+  # `:enotconn` / `:einval` / `:econnaborted` / `:econnreset` depending on platform
+  # and on how far along the connection was when the peer disappeared.
+  @client_closure_errors [:closed, :enotconn, :einval, :econnaborted, :econnreset]
+
   def maybe_log_protocol_error(error, stacktrace, opts, metadata) do
     logging_verbosity =
       case error do
-        %Bandit.TransportError{error: :closed} ->
+        %Bandit.TransportError{error: transport_error}
+        when transport_error in @client_closure_errors ->
           Keyword.get(opts.http, :log_client_closures, false)
 
         _error ->

test/bandit/http1/logging_test.exs

@@ -76,7 +76,12 @@ defmodule HTTP1LoggingTest do
       Transport.close(client)
 
       assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500
-      assert msg == "** (Bandit.TransportError) Unrecoverable error: closed"
+
+      # An abortive close (which is what we force via linger: {true, 0} in
+      # SimpleHTTP1Client.tcp_client/1) can surface as any of a handful of posix reasons
+      # depending on platform and timing, not just :closed (see #647)
+      assert msg =~
+               ~r/^\*\* \(Bandit\.TransportError\) Unrecoverable error: (closed|enotconn|einval|econnaborted|econnreset)$/
     end
 
     @tag :capture_log
@@ -92,7 +97,10 @@ defmodule HTTP1LoggingTest do
       Transport.close(client)
 
       assert_receive {:log, %{level: :error, msg: {:string, msg}}}, 500
-      assert msg =~ "** (Bandit.TransportError) Unrecoverable error: closed"
+
+      assert msg =~
+               ~r/^\*\* \(Bandit\.TransportError\) Unrecoverable error: (closed|enotconn|einval|econnaborted|econnreset)/
+
       assert msg =~ "lib/bandit/pipeline.ex:"
     end
 

test/bandit/http2/protocol_test.exs

@@ -50,6 +50,20 @@ defmodule HTTP2ProtocolTest do
       Process.sleep(100)
     end
 
+    test "it should not log an error if the client aborts the connection during init " <>
+           "(https://github.com/mtrudel/bandit/issues/647)",
+         context do
+      # Force an abortive close (RST) rather than a graceful one, since it's an abortive close
+      # that can surface conn_data/peer_data errors as a posix reason other than :closed. Race
+      # this against connection init by closing as soon as the TLS handshake completes, before
+      # sending any HTTP/2 bytes.
+      socket = Transport.tls_client(context, ["h2"], linger: {true, 0})
+      Transport.close(socket)
+      Process.sleep(100)
+
+      refute_receive {:log, %{level: :error}}
+    end
+
     @tag :capture_log
     test "it should ignore unknown frame types", context do
       socket = SimpleH2Client.setup_connection(context)

test/support/transport.ex

@@ -13,15 +13,19 @@ defmodule Transport do
     {:client, %{socket: socket, transport: :gen_tcp}}
   end
 
-  def tls_client(context, protocols) do
+  def tls_client(context, protocols, opts \\ []) do
     {:ok, socket} =
-      :ssl.connect(~c"localhost", context[:port],
-        active: false,
-        mode: :binary,
-        nodelay: true,
-        verify: :verify_peer,
-        cacertfile: Path.join(__DIR__, "../support/ca.pem"),
-        alpn_advertised_protocols: protocols
+      :ssl.connect(
+        ~c"localhost",
+        context[:port],
+        [
+          active: false,
+          mode: :binary,
+          nodelay: true,
+          verify: :verify_peer,
+          cacertfile: Path.join(__DIR__, "../support/ca.pem"),
+          alpn_advertised_protocols: protocols
+        ] ++ opts
       )
 
     {:client, %{socket: socket, transport: :ssl}}