From 8356d9e12721d6130a9ea6ac9a09eb871861fbba Mon Sep 17 00:00:00 2001 From: Mat Trudel Date: Thu, 2 Jan 2025 19:58:44 -0500 Subject: [PATCH] Add plug to logging metadata (#448) --- lib/bandit.ex | 7 ++-- lib/bandit/http2/connection.ex | 6 +++- lib/bandit/http2/handler.ex | 57 ++++++++++++++++++----------- lib/bandit/initial_handler.ex | 3 +- lib/bandit/logger.ex | 32 +++++++++++++++++ lib/bandit/pipeline.ex | 65 +++++++--------------------------- 6 files changed, 93 insertions(+), 77 deletions(-) diff --git a/lib/bandit.ex b/lib/bandit.ex index ea864dcd..4dc06e0d 100644 --- a/lib/bandit.ex +++ b/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 diff --git a/lib/bandit/http2/connection.ex b/lib/bandit/http2/connection.ex index 4edab3dc..9699a1b0 100644 --- a/lib/bandit/http2/connection.ex +++ b/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 diff --git a/lib/bandit/http2/handler.ex b/lib/bandit/http2/handler.ex index ccd89d86..81ba720f 100644 --- a/lib/bandit/http2/handler.ex +++ b/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 diff --git a/lib/bandit/initial_handler.ex b/lib/bandit/initial_handler.ex index 27a0a0d4..3bbff2f4 100644 --- a/lib/bandit/initial_handler.ex +++ b/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} diff --git a/lib/bandit/logger.ex b/lib/bandit/logger.ex index 46ce4edd..1c0d79f5 100644 --- a/lib/bandit/logger.ex +++ b/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 diff --git a/lib/bandit/pipeline.ex b/lib/bandit/pipeline.ex index 139f02f3..4d765685 100644 --- a/lib/bandit/pipeline.ex +++ b/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,33 +205,23 @@ 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 @@ -245,17 +229,13 @@ defmodule Bandit.Pipeline do {: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