Add log_client_closures http option (#397)

* Add log_client_closures http option * Update documentation * Refactor & consolidate conditional error logic --------- Co-authored-by: Mat Trudel <[email protected]>
mtrudel · Sep 17, 2024 · 55ac87a · 55ac87a
1 parent 8dc344f
commit 55ac87a
Show file tree

Hide file tree

Showing 4 changed files with 88 additions and 30 deletions.
diff --git a/lib/bandit.ex b/lib/bandit.ex
@@ -109,12 +109,16 @@ defmodule Bandit do
   * `log_protocol_errors`: How to log protocol errors such as malformed requests. `:short` will
     log a single-line summary, while `:verbose` will log full stack traces. The value of `false`
     will disable protocol error logging entirely. Defaults to `:short`
+  * `log_client_closures`: How to log cases where the client closes the connection. These happen
+    routinely in the real world and so the handling of them is configured separately since they
+    can be quite noisy. Takes the same options as `log_protocol_errors`, but defaults to `false`
   """
   @type http_options :: [
           {:compress, boolean()}
           | {:deflate_opions, deflate_options()}
           | {:log_exceptions_with_status_codes, list() | Range.t()}
           | {:log_protocol_errors, :short | :verbose | false}
+          | {:log_client_closures, :short | :verbose | false}
         ]
 
   @typedoc """
@@ -215,7 +219,7 @@ defmodule Bandit do
   end
 
   @top_level_keys ~w(plug scheme port ip keyfile certfile otp_app cipher_suite display_plug startup_log thousand_island_options http_options http_1_options http_2_options websocket_options)a
-  @http_keys ~w(compress deflate_options log_exceptions_with_status_codes log_protocol_errors)a
+  @http_keys ~w(compress deflate_options log_exceptions_with_status_codes log_protocol_errors log_client_closures)a
   @http_1_keys ~w(enabled max_request_line_length max_header_length max_header_count max_requests clear_process_dict gc_every_n_keepalive_requests log_unknown_messages)a
   @http_2_keys ~w(enabled max_header_block_size max_requests default_local_settings)a
   @websocket_keys ~w(enabled max_frame_size validate_text_frames compress)a

diff --git a/lib/bandit/http2/handler.ex b/lib/bandit/http2/handler.ex
@@ -9,27 +9,14 @@ defmodule Bandit.HTTP2.Handler do
 
   use ThousandIsland.Handler
 
-  require Logger
-
   @impl ThousandIsland.Handler
   def handle_connection(socket, state) do
     connection = Bandit.HTTP2.Connection.init(socket, state.plug, state.opts)
     {:continue, Map.merge(state, %{buffer: <<>>, connection: connection})}
   rescue
     error ->
-      case Keyword.get(state.opts.http, :log_protocol_errors, :short) do
-        :short ->
-          Logger.error(Exception.format_banner(:error, error, __STACKTRACE__),
-            domain: [:bandit]
-          )
-
-        :verbose ->
-          Logger.error(Exception.format(:error, error, __STACKTRACE__), domain: [:bandit])
-
-        false ->
-          :ok
-      end
-
+      # Reuse Pipeline's error configuration logic
+      Bandit.Pipeline.maybe_log_error(error, __STACKTRACE__, state.opts.http)
       {:close, state}
   end
 

diff --git a/lib/bandit/pipeline.ex b/lib/bandit/pipeline.ex
@@ -208,16 +208,7 @@ defmodule Bandit.Pipeline do
             ] do
     Bandit.Telemetry.stop_span(span, %{}, %{error: error.message})
 
-    case Keyword.get(opts.http, :log_protocol_errors, :short) do
-      :short ->
-        Logger.error(Exception.format_banner(:error, error, stacktrace), domain: [:bandit])
-
-      :verbose ->
-        Logger.error(Exception.format(:error, error, stacktrace), domain: [:bandit])
-
-      false ->
-        :ok
-    end
+    maybe_log_error(error, stacktrace, opts.http)
 
     # We want to do this at the end of the function, since the HTTP2 stack may kill this process
     # in the course of handling a ConnectionError
@@ -238,4 +229,22 @@ defmodule Bandit.Pipeline do
       {:ok, transport}
     end
   end
+
+  def maybe_log_error(%Bandit.HTTPError{message: "closed"} = error, stacktrace, http_opts) do
+    do_maybe_log_error(error, stacktrace, Keyword.get(http_opts, :log_client_closures, false))
+  end
+
+  def maybe_log_error(error, stacktrace, http_opts) do
+    do_maybe_log_error(error, stacktrace, Keyword.get(http_opts, :log_protocol_errors, :short))
+  end
+
+  defp do_maybe_log_error(error, stacktrace, :short) do
+    Logger.error(Exception.format_banner(:error, error, stacktrace), domain: [:bandit])
+  end
+
+  defp do_maybe_log_error(error, stacktrace, :verbose) do
+    Logger.error(Exception.format(:error, error, stacktrace), domain: [:bandit])
+  end
+
+  defp do_maybe_log_error(_error, _stacktrace, false), do: :ok
 end
diff --git a/test/bandit/http1/request_test.exs b/test/bandit/http1/request_test.exs
@@ -81,6 +81,60 @@ defmodule HTTP1RequestTest do
 
       assert output == ""
     end
+
+    test "client closure protocol errors are not logged by default", context do
+      context = http_server(context, http_options: [log_protocol_errors: :verbose])
+      client = SimpleHTTP1Client.tcp_client(context)
+
+      SimpleHTTP1Client.send(client, "GET", "/sleep_and_send", ["host: localhost"])
+      Process.sleep(100)
+
+      output =
+        capture_log(fn ->
+          Transport.close(client)
+          Process.sleep(500)
+        end)
+
+      assert output == ""
+    end
+
+    test "client closure protocol errors are short logged if so configured", context do
+      context = http_server(context, http_options: [log_client_closures: :short])
+      client = SimpleHTTP1Client.tcp_client(context)
+
+      SimpleHTTP1Client.send(client, "GET", "/sleep_and_send", ["host: localhost"])
+      Process.sleep(100)
+
+      output =
+        capture_log(fn ->
+          Transport.close(client)
+          Process.sleep(500)
+        end)
+
+      assert output =~ "[error] ** (Bandit.HTTPError) closed"
+
+      # Make sure we don't log a stacktrace
+      refute output =~ "lib/bandit/pipeline.ex:"
+    end
+
+    test "client closure protocol errors are verbosely logged if so configured", context do
+      context = http_server(context, http_options: [log_client_closures: :verbose])
+      client = SimpleHTTP1Client.tcp_client(context)
+
+      SimpleHTTP1Client.send(client, "GET", "/sleep_and_send", ["host: localhost"])
+      Process.sleep(100)
+
+      output =
+        capture_log(fn ->
+          Transport.close(client)
+          Process.sleep(500)
+        end)
+
+      assert output =~ "[error] ** (Bandit.HTTPError) closed"
+
+      # Make sure we log a stacktrace
+      assert output =~ "lib/bandit/pipeline.ex:"
+    end
   end
 
   describe "plug error logging" do
@@ -2133,6 +2187,7 @@ defmodule HTTP1RequestTest do
     end
 
     test "raises an error if client closes while body is being read", context do
+      context = http_server(context, http_options: [log_client_closures: :verbose])
       client = SimpleHTTP1Client.tcp_client(context)
 
       SimpleHTTP1Client.send(client, "POST", "/expect_incomplete_body", [
@@ -2150,7 +2205,7 @@ defmodule HTTP1RequestTest do
 
       assert output =~ "(Bandit.HTTPError) closed"
       refute output =~ "IMPOSSIBLE"
-      assert ThousandIsland.connection_pids(context.server_pid) == {:ok, []}
+      assert ThousandIsland.connection_pids(context[:server_pid]) == {:ok, []}
     end
 
     def expect_incomplete_body(conn) do
@@ -2159,6 +2214,7 @@ defmodule HTTP1RequestTest do
     end
 
     test "raises an error if client closes while body is being written", context do
+      context = http_server(context, http_options: [log_client_closures: :verbose])
       client = SimpleHTTP1Client.tcp_client(context)
 
       SimpleHTTP1Client.send(client, "GET", "/sleep_and_send", ["host: localhost"])
@@ -2168,7 +2224,7 @@ defmodule HTTP1RequestTest do
       output = capture_log(fn -> Process.sleep(500) end)
       assert output =~ "(Bandit.HTTPError) closed"
       refute output =~ "IMPOSSIBLE"
-      assert ThousandIsland.connection_pids(context.server_pid) == {:ok, []}
+      assert ThousandIsland.connection_pids(context[:server_pid]) == {:ok, []}
     end
 
     def sleep_and_send(conn) do
@@ -2181,6 +2237,7 @@ defmodule HTTP1RequestTest do
     end
 
     test "returns an error if client closes while chunked body is being written", context do
+      context = http_server(context, http_options: [log_client_closures: :verbose])
       client = SimpleHTTP1Client.tcp_client(context)
 
       SimpleHTTP1Client.send(client, "GET", "/sleep_and_send_chunked", ["host: localhost"])
@@ -2189,7 +2246,7 @@ defmodule HTTP1RequestTest do
 
       output = capture_log(fn -> Process.sleep(500) end)
       assert output == ""
-      assert ThousandIsland.connection_pids(context.server_pid) == {:ok, []}
+      assert ThousandIsland.connection_pids(context[:server_pid]) == {:ok, []}
     end
 
     def sleep_and_send_chunked(conn) do
@@ -2202,6 +2259,7 @@ defmodule HTTP1RequestTest do
     end
 
     test "raises an error if client closes before sendfile body is being written", context do
+      context = http_server(context, http_options: [log_client_closures: :verbose])
       client = SimpleHTTP1Client.tcp_client(context)
 
       SimpleHTTP1Client.send(client, "GET", "/sleep_and_sendfile", ["host: localhost"])
@@ -2211,7 +2269,7 @@ defmodule HTTP1RequestTest do
       output = capture_log(fn -> Process.sleep(500) end)
       assert output =~ "(Bandit.HTTPError) closed"
       refute output =~ "IMPOSSIBLE"
-      assert ThousandIsland.connection_pids(context.server_pid) == {:ok, []}
+      assert ThousandIsland.connection_pids(context[:server_pid]) == {:ok, []}
     end
 
     def sleep_and_sendfile(conn) do