Add plug to logging metadata (#448)

lib/bandit.ex

@@ -317,12 +317,15 @@ defmodule Bandit do
     |> ThousandIsland.start_link()
     |> case do
       {:ok, pid} ->
-        startup_log && Logger.log(startup_log, info(scheme, display_plug, pid), domain: [:bandit])
+        startup_log &&
+          Logger.log(startup_log, info(scheme, display_plug, pid), domain: [:bandit], plug: plug)
+
         {:ok, pid}
 
       {:error, {:shutdown, {:failed_to_start_child, :listener, :eaddrinuse}}} = error ->
         Logger.error([info(scheme, display_plug, nil), " failed, port #{port} already in use"],
-          domain: [:bandit]
+          domain: [:bandit],
+          plug: plug
         )
 
         error

lib/bandit/http2/connection.ex

@@ -203,7 +203,11 @@ defmodule Bandit.HTTP2.Connection do
   # Catch-all handler for unknown frame types
 
   def handle_frame(%Bandit.HTTP2.Frame.Unknown{} = frame, _socket, connection) do
-    Logger.warning("Unknown frame (#{inspect(Map.from_struct(frame))})", domain: [:bandit])
+    Logger.warning("Unknown frame (#{inspect(Map.from_struct(frame))})",
+      domain: [:bandit],
+      plug: connection.plug
+    )
+
     connection
   end
 

lib/bandit/http2/handler.ex

@@ -14,10 +14,7 @@ defmodule Bandit.HTTP2.Handler do
     connection = Bandit.HTTP2.Connection.init(socket, state.plug, state.opts)
     {:continue, Map.merge(state, %{buffer: <<>>, connection: connection})}
   rescue
-    error ->
-      # Reuse Pipeline's error configuration logic
-      Bandit.Pipeline.maybe_log_error(error, __STACKTRACE__, state.opts.http)
-      {:close, state}
+    error -> rescue_error(error, __STACKTRACE__, socket, state)
   end
 
   @impl ThousandIsland.Handler
@@ -40,6 +37,8 @@ defmodule Bandit.HTTP2.Handler do
         raise Bandit.HTTP2.Errors.ConnectionError, message: message, error_code: error_code
     end)
     |> then(&{:continue, &1})
+  rescue
+    error -> rescue_error(error, __STACKTRACE__, socket, state)
   end
 
   @impl ThousandIsland.Handler
@@ -62,18 +61,6 @@ defmodule Bandit.HTTP2.Handler do
     )
   end
 
-  @impl ThousandIsland.Handler
-  def handle_error({%Bandit.HTTP2.Errors.ConnectionError{} = error, _stacktrace}, socket, state) do
-    Bandit.HTTP2.Connection.close_connection(
-      error.error_code,
-      error.message,
-      socket,
-      state.connection
-    )
-  end
-
-  def handle_error(_error, _socket, _state), do: :ok
-
   def handle_call({{:send_data, data, end_stream}, stream_id}, from, {socket, state}) do
     # In 'normal' cases where there is sufficient space in the send windows for this message to be
     # sent, Connection will call `unblock` synchronously in the `Connection.send_data` call below.
@@ -100,6 +87,8 @@ defmodule Bandit.HTTP2.Handler do
       )
 
     {:noreply, {socket, %{state | connection: connection}}, socket.read_timeout}
+  rescue
+    error -> rescue_error_handle_info(error, __STACKTRACE__, socket, state)
   end
 
   def handle_info({{:send_headers, headers, end_stream}, stream_id}, {socket, state}) do
@@ -113,6 +102,8 @@ defmodule Bandit.HTTP2.Handler do
       )
 
     {:noreply, {socket, %{state | connection: connection}}, socket.read_timeout}
+  rescue
+    error -> rescue_error_handle_info(error, __STACKTRACE__, socket, state)
   end
 
   def handle_info({{:send_recv_window_update, size_increment}, stream_id}, {socket, state}) do
@@ -124,22 +115,48 @@ defmodule Bandit.HTTP2.Handler do
     )
 
     {:noreply, {socket, state}, socket.read_timeout}
+  rescue
+    error -> rescue_error_handle_info(error, __STACKTRACE__, socket, state)
   end
 
   def handle_info({{:send_rst_stream, error_code}, stream_id}, {socket, state}) do
     Bandit.HTTP2.Connection.send_rst_stream(stream_id, error_code, socket, state.connection)
     {:noreply, {socket, state}, socket.read_timeout}
+  rescue
+    error -> rescue_error_handle_info(error, __STACKTRACE__, socket, state)
   end
 
   def handle_info({{:close_connection, error_code, msg}, _stream_id}, {socket, state}) do
-    {:error, reason, connection} =
-      Bandit.HTTP2.Connection.close_connection(error_code, msg, socket, state.connection)
-
-    {:stop, reason, {socket, %{state | connection: connection}}}
+    Bandit.HTTP2.Connection.close_connection(error_code, msg, socket, state.connection)
+    {:stop, :normal, {socket, state}}
   end
 
   def handle_info({:EXIT, pid, _reason}, {socket, state}) do
     connection = Bandit.HTTP2.Connection.stream_terminated(pid, state.connection)
     {:noreply, {socket, %{state | connection: connection}}, socket.read_timeout}
   end
+
+  defp rescue_error(error, stacktrace, socket, state) do
+    do_rescue_error(error, stacktrace, socket, state)
+    {:close, state}
+  end
+
+  defp rescue_error_handle_info(error, stacktrace, socket, state) do
+    do_rescue_error(error, stacktrace, socket, state)
+    {:stop, :normal}
+  end
+
+  defp do_rescue_error(error, stacktrace, socket, state) do
+    _ =
+      if state.connection do
+        Bandit.HTTP2.Connection.close_connection(
+          error.error_code,
+          error.message,
+          socket,
+          state.connection
+        )
+      end
+
+    Bandit.Logger.maybe_log_protocol_error(error, stacktrace, state.opts, plug: state.plug)
+  end
 end

lib/bandit/initial_handler.ex

@@ -23,7 +23,8 @@ defmodule Bandit.InitialHandler do
     case {state.http_1_enabled, state.http_2_enabled, alpn_protocol(socket), sniff_wire(socket)} do
       {_, _, _, :likely_tls} ->
         Logger.warning("Connection that looks like TLS received on a clear channel",
-          domain: [:bandit]
+          domain: [:bandit],
+          plug: state.plug
         )
 
         {:close, state}

lib/bandit/logger.ex

@@ -87,4 +87,36 @@ defmodule Bandit.Logger do
       domain: [:bandit]
     )
   end
+
+  def maybe_log_protocol_error(error, stacktrace, opts, metadata) do
+    logging_verbosity =
+      case error do
+        %Bandit.TransportError{error: :closed} ->
+          Keyword.get(opts.http, :log_client_closures, false)
+
+        _error ->
+          Keyword.get(opts.http, :log_protocol_errors, :short)
+      end
+
+    case logging_verbosity do
+      :short ->
+        logger_metadata = logger_metadata_for(:error, error, stacktrace, metadata)
+        Logger.error(Exception.format_banner(:error, error, stacktrace), logger_metadata)
+
+      :verbose ->
+        logger_metadata = logger_metadata_for(:error, error, stacktrace, metadata)
+        Logger.error(Exception.format(:error, error, stacktrace), logger_metadata)
+
+      false ->
+        :ok
+    end
+  end
+
+  def logger_metadata_for(kind, reason, stacktrace, metadata) do
+    [domain: [:bandit], crash_reason: crash_reason(kind, reason, stacktrace)]
+    |> Keyword.merge(metadata)
+  end
+
+  defp crash_reason(:throw, reason, stacktrace), do: {{:nocatch, reason}, stacktrace}
+  defp crash_reason(_, reason, stacktrace), do: {reason, stacktrace}
 end

lib/bandit/pipeline.ex

@@ -49,20 +49,14 @@ defmodule Bandit.Pipeline do
             Bandit.Telemetry.stop_span(span, adapter.metrics, %{conn: conn})
             {:upgrade, adapter.transport, protocol, opts}
         end
-      rescue
-        exception ->
-          handle_error(:error, exception, __STACKTRACE__, transport, span, opts, conn)
       catch
-        :throw, value ->
-          handle_error(:throw, value, __STACKTRACE__, transport, span, opts, conn)
-
-        :exit, value ->
-          handle_error(:exit, value, __STACKTRACE__, transport, span, opts, conn)
+        kind, value ->
+          handle_error(kind, value, __STACKTRACE__, transport, span, opts, plug: plug, conn: conn)
       end
     rescue
       exception ->
         span = Bandit.Telemetry.start_span(:request, measurements, metadata)
-        handle_error(:error, exception, __STACKTRACE__, transport, span, opts)
+        handle_error(:error, exception, __STACKTRACE__, transport, span, opts, plug: plug)
     end
   end
 
@@ -211,51 +205,37 @@ defmodule Bandit.Pipeline do
           Bandit.HTTPTransport.t(),
           Bandit.Telemetry.t(),
           map(),
-          Plug.Conn.t() | nil
+          keyword()
         ) :: {:ok, Bandit.HTTPTransport.t()} | {:error, term()}
-  defp handle_error(kind, error, stacktrace, transport, span, opts, conn \\ nil)
-
-  defp handle_error(
-         :error,
-         %Plug.Conn.WrapperError{} = error,
-         _stacktrace,
-         transport,
-         span,
-         opts,
-         conn
-       ) do
+  defp handle_error(:error, %Plug.Conn.WrapperError{} = error, _, transport, span, opts, metadata) do
     # Unwrap the inner error and handle it
-    handle_error(error.kind, error.reason, error.stack, transport, span, opts, conn)
+    handle_error(error.kind, error.reason, error.stack, transport, span, opts, metadata)
   end
 
-  defp handle_error(:error, %type{} = error, stacktrace, transport, span, opts, _conn)
+  defp handle_error(:error, %type{} = error, stacktrace, transport, span, opts, metadata)
        when type in [
               Bandit.HTTPError,
               Bandit.TransportError,
               Bandit.HTTP2.Errors.StreamError,
               Bandit.HTTP2.Errors.ConnectionError
             ] do
-    Bandit.Telemetry.stop_span(span, %{}, %{error: error.message})
+    Bandit.Telemetry.stop_span(span, %{}, Enum.into(metadata, %{error: error.message}))
 
-    maybe_log_error(error, stacktrace, opts.http)
+    Bandit.Logger.maybe_log_protocol_error(error, stacktrace, opts, metadata)
 
     # 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
     Bandit.HTTPTransport.send_on_error(transport, error)
     {:error, error}
   end
 
-  defp handle_error(kind, reason, stacktrace, transport, span, opts, conn) do
+  defp handle_error(kind, reason, stacktrace, transport, span, opts, metadata) do
     Bandit.Telemetry.span_exception(span, kind, reason, stacktrace)
     status = reason |> Plug.Exception.status() |> Plug.Conn.Status.code()
 
     if status in Keyword.get(opts.http, :log_exceptions_with_status_codes, 500..599) do
-      Logger.error(
-        Exception.format(kind, reason, stacktrace),
-        domain: [:bandit],
-        crash_reason: crash_reason(kind, reason, stacktrace),
-        conn: conn
-      )
+      logger_metadata = Bandit.Logger.logger_metadata_for(kind, reason, stacktrace, metadata)
+      Logger.error(Exception.format(kind, reason, stacktrace), logger_metadata)
 
       Bandit.HTTPTransport.send_on_error(transport, reason)
       {:error, reason}
@@ -264,25 +244,4 @@ defmodule Bandit.Pipeline do
       {:ok, transport}
     end
   end
-
-  def maybe_log_error(%Bandit.TransportError{error: :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
-
-  defp crash_reason(:throw, reason, stacktrace), do: {{:nocatch, reason}, stacktrace}
-  defp crash_reason(_, reason, stacktrace), do: {reason, stacktrace}
 end