Attempt to improve plug call exception handling and logging

lib/bandit/pipeline.ex

@@ -46,12 +46,15 @@ defmodule Bandit.Pipeline do
  {:upgrade, adapter.transport, protocol, opts}
  end
  rescue
- error -> handle_error(error, __STACKTRACE__, transport, span, opts)
+ error -> handle_error(:error, error, __STACKTRACE__, transport, span, opts)
+ catch
+ kind, reason ->
+ handle_error(kind, reason, __STACKTRACE__, transport, span, opts)
  end
  rescue
  error ->
  span = Bandit.Telemetry.start_span(:request, measurements, metadata)
- handle_error(error, __STACKTRACE__, transport, span, opts)
+ handle_error(:error, error, __STACKTRACE__, transport, span, opts)
  end
  end
 
@@ -194,13 +197,14 @@ defmodule Bandit.Pipeline do
  end
 
  @spec handle_error(
- Exception.t(),
+ :error | :throw | :exit,
+ Exception.t() | term(),
  Exception.stacktrace(),
  Bandit.HTTPTransport.t(),
  Bandit.Telemetry.t(),
  map()
  ) :: {:ok, Bandit.HTTPTransport.t()} | {:error, term()}
- defp handle_error(%type{} = error, stacktrace, transport, span, opts)
+ defp handle_error(:error, %type{} = error, stacktrace, transport, span, opts)
  when type in [
  Bandit.HTTPError,
  Bandit.HTTP2.Errors.StreamError,
@@ -216,16 +220,21 @@ defmodule Bandit.Pipeline do
  {:error, error}
  end
 
- defp handle_error(error, stacktrace, transport, span, opts) do
- Bandit.Telemetry.span_exception(span, :exit, error, stacktrace)
- status = error |> Plug.Exception.status() |> Plug.Conn.Status.code()
+ defp handle_error(kind, reason, stacktrace, transport, span, opts) 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(:error, error, stacktrace), domain: [:bandit])
- Bandit.HTTPTransport.send_on_error(transport, error)
- {:error, error}
+ Logger.error(
+ Exception.format(kind, reason, stacktrace),
+ domain: [:bandit],
+ crash_reason: crash_reason(kind, reason, stacktrace)
+ )
+
+ Bandit.HTTPTransport.send_on_error(transport, reason)
+ {:error, reason}
  else
- Bandit.HTTPTransport.send_on_error(transport, error)
+ Bandit.HTTPTransport.send_on_error(transport, reason)
  {:ok, transport}
  end
  end
@@ -247,4 +256,9 @@ defmodule Bandit.Pipeline do
  end
 
  defp do_maybe_log_error(_error, _stacktrace, false), do: :ok
+
+ # Builds a crash reason used in Logger reporting.
+ def crash_reason(:throw, reason, stack), do: {{:nocatch, reason}, stack}
+ def crash_reason(:error, reason, stack), do: {Exception.normalize(:error, reason, stack), stack}
+ def crash_reason(:exit, reason, stack), do: {reason, stack}
 end

lib/bandit/telemetry.ex

@@ -76,8 +76,8 @@ defmodule Bandit.Telemetry do
  * `conn`: The `Plug.Conn` representing this connection. Not present in cases where `error`
  is also set and the nature of error is such that Bandit was unable to successfully build
  the conn
- * `kind`: The kind of unexpected condition, typically `:exit`
- * `exception`: The exception which caused this unexpected termination
+ * `kind`: The kind of unexpected condition, typically `:error`, `:throw` or `:exit`
+ * `reason`: The exception, throw value or exit reason which caused this unexpected termination
  * `stacktrace`: The stacktrace of the location which caused this unexpected termination
 
  ## `[:bandit, :websocket, *]`
@@ -188,15 +188,28 @@ defmodule Bandit.Telemetry do
  untimed_span_event(span, :stop, measurements, metadata)
  end
 
- @spec span_exception(t(), Exception.kind(), Exception.t(), Exception.stacktrace()) :: :ok
- def span_exception(span, kind, exception, stacktrace) do
+ @spec span_exception(
+ t(),
+ :error | :throw | :exit,
+ Exception.t() | term(),
+ Exception.stacktrace()
+ ) :: :ok
+ def span_exception(span, kind, reason, stacktrace) do
  metadata =
  Map.merge(span.start_metadata, %{
  kind: kind,
- exception: exception,
+ reason: reason,
  stacktrace: stacktrace
  })
 
+ # Keep exception field for backwards compatibility
+ metadata =
+ if kind == :error and is_exception(reason) do
+ Map.put(metadata, :exception, reason)
+ else
+ metadata
+ end
+
  span_event(span, :exception, %{}, metadata)
  end
 

test/bandit/http1/request_test.exs

@@ -2149,7 +2149,7 @@ defmodule HTTP1RequestTest do
  assert output =~ "(Bandit.HTTPError) Header read timeout"
  end
 
- test "it should send `exception` events for erroring requests", context do
+ test "it should send `error` events for erroring requests", context do
  output =
  capture_log(fn ->
  {:ok, collector_pid} =
@@ -2166,7 +2166,8 @@ defmodule HTTP1RequestTest do
  connection_telemetry_span_context: reference(),
  telemetry_span_context: reference(),
  conn: struct_like(Plug.Conn, []),
- kind: :exit,
+ kind: :error,
+ reason: %RuntimeError{message: "boom"},
  exception: %RuntimeError{message: "boom"},
  stacktrace: list()
  }}
@@ -2175,6 +2176,68 @@ defmodule HTTP1RequestTest do
 
  assert output =~ "(RuntimeError) boom"
  end
+
+ def uncaught_throw(_conn) do
+ throw("thrown")
+ end
+
+ test "it should send `error` events for uncaught throw requests", context do
+ output =
+ capture_log(fn ->
+ {:ok, collector_pid} =
+ start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :exception]]})
+
+ Req.get!(context.req, url: "/uncaught_throw")
+
+ Process.sleep(100)
+
+ assert Bandit.TelemetryCollector.get_events(collector_pid)
+ ~> [
+ {[:bandit, :request, :exception], %{monotonic_time: integer()},
+ %{
+ connection_telemetry_span_context: reference(),
+ telemetry_span_context: reference(),
+ conn: struct_like(Plug.Conn, []),
+ kind: :throw,
+ reason: "thrown",
+ stacktrace: list()
+ }}
+ ]
+ end)
+
+ assert output =~ "(throw) \"thrown\""
+ end
+
+ def abnormal_exit(_conn) do
+ exit(:abnormal)
+ end
+
+ test "it should send `error` events for abnormal exit requests", context do
+ output =
+ capture_log(fn ->
+ {:ok, collector_pid} =
+ start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :exception]]})
+
+ Req.get!(context.req, url: "/abnormal_exit")
+
+ Process.sleep(100)
+
+ assert Bandit.TelemetryCollector.get_events(collector_pid)
+ ~> [
+ {[:bandit, :request, :exception], %{monotonic_time: integer()},
+ %{
+ connection_telemetry_span_context: reference(),
+ telemetry_span_context: reference(),
+ conn: struct_like(Plug.Conn, []),
+ kind: :exit,
+ reason: :abnormal,
+ stacktrace: list()
+ }}
+ ]
+ end)
+
+ assert output =~ "(exit) :abnormal"
+ end
  end
 
  describe "connection closure / error handling" do

test/bandit/http2/plug_test.exs

@@ -996,7 +996,7 @@ defmodule HTTP2PlugTest do
  assert output =~ "(Bandit.HTTP2.Errors.StreamError) Received uppercase header"
  end
 
- test "it should send `exception` events for erroring requests", context do
+ test "it should send `error` eventr for erroring requests", context do
  output =
  capture_log(fn ->
  {:ok, collector_pid} =
@@ -1013,7 +1013,8 @@ defmodule HTTP2PlugTest do
  connection_telemetry_span_context: reference(),
  telemetry_span_context: reference(),
  conn: struct_like(Plug.Conn, []),
- kind: :exit,
+ kind: :error,
+ reason: %RuntimeError{message: "boom"},
  exception: %RuntimeError{message: "boom"},
  stacktrace: list()
  }}
@@ -1026,5 +1027,67 @@ defmodule HTTP2PlugTest do
  def raise_error(_conn) do
  raise "boom"
  end
+
+ test "it should send `error` events for uncaught throw requests", context do
+ output =
+ capture_log(fn ->
+ {:ok, collector_pid} =
+ start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :exception]]})
+
+ Req.get!(context.req, url: "/uncaught_throw")
+
+ Process.sleep(100)
+
+ assert Bandit.TelemetryCollector.get_events(collector_pid)
+ ~> [
+ {[:bandit, :request, :exception], %{monotonic_time: integer()},
+ %{
+ connection_telemetry_span_context: reference(),
+ telemetry_span_context: reference(),
+ conn: struct_like(Plug.Conn, []),
+ kind: :throw,
+ reason: "thrown",
+ stacktrace: list()
+ }}
+ ]
+ end)
+
+ assert output =~ "(throw) \"thrown\""
+ end
+
+ def uncaught_throw(_conn) do
+ throw("thrown")
+ end
+
+ test "it should send `error` events for abnormal exit requests", context do
+ output =
+ capture_log(fn ->
+ {:ok, collector_pid} =
+ start_supervised({Bandit.TelemetryCollector, [[:bandit, :request, :exception]]})
+
+ Req.get!(context.req, url: "/abnormal_exit")
+
+ Process.sleep(100)
+
+ assert Bandit.TelemetryCollector.get_events(collector_pid)
+ ~> [
+ {[:bandit, :request, :exception], %{monotonic_time: integer()},
+ %{
+ connection_telemetry_span_context: reference(),
+ telemetry_span_context: reference(),
+ conn: struct_like(Plug.Conn, []),
+ kind: :exit,
+ reason: :abnormal,
+ stacktrace: list()
+ }}
+ ]
+ end)
+
+ assert output =~ "(exit) :abnormal"
+ end
+
+ def abnormal_exit(_conn) do
+ exit(:abnormal)
+ end
  end
 end