feat: handles errors in bandit plug dispatch

lib/tower.ex

@@ -10,11 +10,13 @@ defmodule Tower do
   @spec attach() :: :ok
   def attach do
     :ok = Tower.LoggerHandler.attach()
+    :ok = Tower.BanditExceptionHandler.attach()
   end
 
   @spec detach() :: :ok
   def detach do
     :ok = Tower.LoggerHandler.detach()
+    :ok = Tower.BanditExceptionHandler.detach()
   end
 
   @spec handle_caught(Exception.kind(), Event.reason(), Exception.stacktrace()) :: :ok

lib/tower/bandit_exception_handler.ex

@@ -0,0 +1,50 @@
+defmodule Tower.BanditExceptionHandler do
+  require Logger
+
+  @handler_id __MODULE__
+
+  def attach do
+    :telemetry.attach(
+      @handler_id,
+      [:bandit, :request, :exception],
+      &__MODULE__.handle_event/4,
+      _handler_config = []
+    )
+  end
+
+  def detach do
+    :telemetry.detach(@handler_id)
+  end
+
+  def handle_event(
+        [:bandit, :request, :exception],
+        _event_measurements,
+        event_metadata,
+        _handler_config
+      ) do
+    handle_event_metadata(event_metadata)
+  end
+
+  defp handle_event_metadata(%{
+         kind: _kind,
+         exception: %{
+           __struct__: Plug.Conn.WrapperError,
+           kind: :error,
+           reason: reason,
+           stack: stacktrace,
+           conn: conn
+         },
+         stacktrace: stacktrace
+       }) do
+    Exception.normalize(:error, reason, stacktrace)
+    |> Tower.handle_exception(stacktrace, plug_conn: conn)
+  end
+
+  defp handle_event_metadata(event_metadata) do
+    Logger.warning(
+      "UNHANDLED BANDIT REQUEST EXCEPTION with event_metadata=#{inspect(event_metadata, pretty: true)}"
+    )
+
+    :ignored
+  end
+end

mix.exs

@@ -41,14 +41,16 @@ defmodule Tower.MixProject do
   defp deps do
     [
       {:uniq, "~> 0.6.1"},
+      {:telemetry, "~> 1.2"},
 
       # Dev
       {:ex_doc, "~> 0.34.0", only: :dev, runtime: false},
       {:dialyxir, "~> 1.4", only: :dev, runtime: false},
 
       # Test
       {:assert_eventually, "~> 1.0", only: :test},
-      {:plug_cowboy, "~> 2.7", only: :test}
+      {:plug_cowboy, "~> 2.7", only: :test},
+      {:bandit, "~> 1.5", only: :test}
     ]
   end
 

mix.lock

@@ -1,12 +1,14 @@
 %{
   "assert_eventually": {:hex, :assert_eventually, "1.0.0", "f1539f28ba3ffa99a712433c77723c7103986932aa341d05eee94c333a920d15", [:mix], [{:ex_doc, ">= 0.0.0", [hex: :ex_doc, repo: "hexpm", optional: true]}], "hexpm", "c658ac4103c8bd82d0cf72a2fdb77477ba3fbc6b15228c5c801003d239625c69"},
+  "bandit": {:hex, :bandit, "1.5.7", "6856b1e1df4f2b0cb3df1377eab7891bec2da6a7fd69dc78594ad3e152363a50", [:mix], [{:hpax, "~> 1.0.0", [hex: :hpax, repo: "hexpm", optional: false]}, {:plug, "~> 1.14", [hex: :plug, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}, {:thousand_island, "~> 1.0", [hex: :thousand_island, repo: "hexpm", optional: false]}, {:websock, "~> 0.5", [hex: :websock, repo: "hexpm", optional: false]}], "hexpm", "f2dd92ae87d2cbea2fa9aa1652db157b6cba6c405cb44d4f6dd87abba41371cd"},
   "cowboy": {:hex, :cowboy, "2.12.0", "f276d521a1ff88b2b9b4c54d0e753da6c66dd7be6c9fca3d9418b561828a3731", [:make, :rebar3], [{:cowlib, "2.13.0", [hex: :cowlib, repo: "hexpm", optional: false]}, {:ranch, "1.8.0", [hex: :ranch, repo: "hexpm", optional: false]}], "hexpm", "8a7abe6d183372ceb21caa2709bec928ab2b72e18a3911aa1771639bef82651e"},
   "cowboy_telemetry": {:hex, :cowboy_telemetry, "0.4.0", "f239f68b588efa7707abce16a84d0d2acf3a0f50571f8bb7f56a15865aae820c", [:rebar3], [{:cowboy, "~> 2.7", [hex: :cowboy, repo: "hexpm", optional: false]}, {:telemetry, "~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "7d98bac1ee4565d31b62d59f8823dfd8356a169e7fcbb83831b8a5397404c9de"},
   "cowlib": {:hex, :cowlib, "2.13.0", "db8f7505d8332d98ef50a3ef34b34c1afddec7506e4ee4dd4a3a266285d282ca", [:make, :rebar3], [], "hexpm", "e1e1284dc3fc030a64b1ad0d8382ae7e99da46c3246b815318a4b848873800a4"},
   "dialyxir": {:hex, :dialyxir, "1.4.3", "edd0124f358f0b9e95bfe53a9fcf806d615d8f838e2202a9f430d59566b6b53b", [:mix], [{:erlex, ">= 0.2.6", [hex: :erlex, repo: "hexpm", optional: false]}], "hexpm", "bf2cfb75cd5c5006bec30141b131663299c661a864ec7fbbc72dfa557487a986"},
   "earmark_parser": {:hex, :earmark_parser, "1.4.40", "f3534689f6b58f48aa3a9ac850d4f05832654fe257bf0549c08cc290035f70d5", [:mix], [], "hexpm", "cdb34f35892a45325bad21735fadb88033bcb7c4c296a999bde769783f53e46a"},
   "erlex": {:hex, :erlex, "0.2.7", "810e8725f96ab74d17aac676e748627a07bc87eb950d2b83acd29dc047a30595", [:mix], [], "hexpm", "3ed95f79d1a844c3f6bf0cea61e0d5612a42ce56da9c03f01df538685365efb0"},
   "ex_doc": {:hex, :ex_doc, "0.34.2", "13eedf3844ccdce25cfd837b99bea9ad92c4e511233199440488d217c92571e8", [:mix], [{:earmark_parser, "~> 1.4.39", [hex: :earmark_parser, repo: "hexpm", optional: false]}, {:makeup_c, ">= 0.1.0", [hex: :makeup_c, repo: "hexpm", optional: true]}, {:makeup_elixir, "~> 0.14 or ~> 1.0", [hex: :makeup_elixir, repo: "hexpm", optional: false]}, {:makeup_erlang, "~> 0.1 or ~> 1.0", [hex: :makeup_erlang, repo: "hexpm", optional: false]}, {:makeup_html, ">= 0.1.0", [hex: :makeup_html, repo: "hexpm", optional: true]}], "hexpm", "5ce5f16b41208a50106afed3de6a2ed34f4acfd65715b82a0b84b49d995f95c1"},
+  "hpax": {:hex, :hpax, "1.0.0", "28dcf54509fe2152a3d040e4e3df5b265dcb6cb532029ecbacf4ce52caea3fd2", [:mix], [], "hexpm", "7f1314731d711e2ca5fdc7fd361296593fc2542570b3105595bb0bc6d0fad601"},
   "makeup": {:hex, :makeup, "1.1.2", "9ba8837913bdf757787e71c1581c21f9d2455f4dd04cfca785c70bbfff1a76a3", [:mix], [{:nimble_parsec, "~> 1.2.2 or ~> 1.3", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "cce1566b81fbcbd21eca8ffe808f33b221f9eee2cbc7a1706fc3da9ff18e6cac"},
   "makeup_elixir": {:hex, :makeup_elixir, "0.16.2", "627e84b8e8bf22e60a2579dad15067c755531fea049ae26ef1020cad58fe9578", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}, {:nimble_parsec, "~> 1.2.3 or ~> 1.3", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "41193978704763f6bbe6cc2758b84909e62984c7752b3784bd3c218bb341706b"},
   "makeup_erlang": {:hex, :makeup_erlang, "1.0.0", "6f0eff9c9c489f26b69b61440bf1b238d95badae49adac77973cbacae87e3c2e", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}], "hexpm", "ea7a9307de9d1548d2a72d299058d1fd2339e3d398560a0e46c27dab4891e4d2"},
@@ -17,5 +19,7 @@
   "plug_crypto": {:hex, :plug_crypto, "2.1.0", "f44309c2b06d249c27c8d3f65cfe08158ade08418cf540fd4f72d4d6863abb7b", [:mix], [], "hexpm", "131216a4b030b8f8ce0f26038bc4421ae60e4bb95c5cf5395e1421437824c4fa"},
   "ranch": {:hex, :ranch, "1.8.0", "8c7a100a139fd57f17327b6413e4167ac559fbc04ca7448e9be9057311597a1d", [:make, :rebar3], [], "hexpm", "49fbcfd3682fab1f5d109351b61257676da1a2fdbe295904176d5e521a2ddfe5"},
   "telemetry": {:hex, :telemetry, "1.2.1", "68fdfe8d8f05a8428483a97d7aab2f268aaff24b49e0f599faa091f1d4e7f61c", [:rebar3], [], "hexpm", "dad9ce9d8effc621708f99eac538ef1cbe05d6a874dd741de2e689c47feafed5"},
+  "thousand_island": {:hex, :thousand_island, "1.3.5", "6022b6338f1635b3d32406ff98d68b843ba73b3aa95cfc27154223244f3a6ca5", [:mix], [{:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "2be6954916fdfe4756af3239fb6b6d75d0b8063b5df03ba76fd8a4c87849e180"},
   "uniq": {:hex, :uniq, "0.6.1", "369660ecbc19051be526df3aa85dc393af5f61f45209bce2fa6d7adb051ae03c", [:mix], [{:ecto, "~> 3.0", [hex: :ecto, repo: "hexpm", optional: true]}], "hexpm", "6426c34d677054b3056947125b22e0daafd10367b85f349e24ac60f44effb916"},
+  "websock": {:hex, :websock, "0.5.3", "2f69a6ebe810328555b6fe5c831a851f485e303a7c8ce6c5f675abeb20ebdadc", [:mix], [], "hexpm", "6105453d7fac22c712ad66fab1d45abdf049868f253cf719b625151460b8b453"},
 }

test/plug/tower_plug_test.exs

@@ -13,7 +13,7 @@ defmodule TowerPlugTest do
   end
 
   @tag capture_log: true
-  test "reports arithmetic error during plug dispatch" do
+  test "reports arithmetic error during plug dispatch with Plug.Cowboy" do
     # An ephemeral port hopefully not being in the host running this code
     plug_port = 51111
     url = "http://127.0.0.1:#{plug_port}/arithmetic-error"
@@ -43,7 +43,7 @@ defmodule TowerPlugTest do
   end
 
   @tag capture_log: true
-  test "reports uncaught throw during plug dispatch" do
+  test "reports uncaught throw during plug dispatch with Plug.Cowboy" do
     # An ephemeral port hopefully not being in the host running this code
     plug_port = 51111
     url = "http://127.0.0.1:#{plug_port}/uncaught-throw"
@@ -73,7 +73,7 @@ defmodule TowerPlugTest do
   end
 
   @tag capture_log: true
-  test "reports abnormal exit during plug dispatch" do
+  test "reports abnormal exit during plug dispatch with Plug.Cowboy" do
     # An ephemeral port hopefully not being in the host running this code
     plug_port = 51111
     url = "http://127.0.0.1:#{plug_port}/abnormal-exit"
@@ -102,6 +102,98 @@ defmodule TowerPlugTest do
     assert Plug.Conn.request_url(plug_conn) == url
   end
 
+  @tag capture_log: true
+  test "reports arithmetic error during plug dispatch with Bandit" do
+    # An ephemeral port hopefully not being in the host running this code
+    plug_port = 51111
+    url = "http://127.0.0.1:#{plug_port}/arithmetic-error"
+
+    start_link_supervised!({Bandit, plug: Tower.TestPlug, scheme: :http, port: plug_port})
+
+    {:ok, _response} = :httpc.request(url)
+
+    assert_eventually(
+      [
+        %{
+          id: id,
+          datetime: datetime,
+          level: :error,
+          kind: :error,
+          reason: %ArithmeticError{message: "bad argument in arithmetic expression"},
+          stacktrace: stacktrace,
+          plug_conn: %Plug.Conn{} = plug_conn
+        }
+      ] = Tower.EphemeralReporter.events()
+    )
+
+    assert String.length(id) == 36
+    assert recent_datetime?(datetime)
+    assert is_list(stacktrace)
+    assert Plug.Conn.request_url(plug_conn) == url
+  end
+
+  @tag capture_log: true
+  test "reports uncaught throw during plug dispatch with Bandit" do
+    # An ephemeral port hopefully not being in the host running this code
+    plug_port = 51111
+    url = "http://127.0.0.1:#{plug_port}/uncaught-throw"
+
+    start_link_supervised!({Bandit, plug: Tower.TestPlug, scheme: :http, port: plug_port})
+
+    {:error, :socket_closed_remotely} = :httpc.request(url)
+
+    assert_eventually(
+      [
+        %{
+          id: id,
+          datetime: datetime,
+          level: :error,
+          # Bandit doesn't handle uncaught throws inside plug call so it becomes a gen server exit.
+          # We have no control over this kind.
+          kind: :exit,
+          reason: {:bad_return_value, "something"},
+          stacktrace: stacktrace,
+          # Bandit doesn't handle uncaught throws so it doesn't provide the conn in the metadata
+          plug_conn: nil
+        }
+      ] = Tower.EphemeralReporter.events()
+    )
+
+    assert String.length(id) == 36
+    assert recent_datetime?(datetime)
+    assert is_list(stacktrace)
+  end
+
+  @tag capture_log: true
+  test "reports abnormal exit during plug dispatch with Bandit" do
+    # An ephemeral port hopefully not being in the host running this code
+    plug_port = 51111
+    url = "http://127.0.0.1:#{plug_port}/abnormal-exit"
+
+    start_link_supervised!({Bandit, plug: Tower.TestPlug, scheme: :http, port: plug_port})
+
+    {:error, :socket_closed_remotely} = :httpc.request(url)
+
+    assert_eventually(
+      [
+        %{
+          id: id,
+          datetime: datetime,
+          level: :error,
+          kind: :exit,
+          reason: :abnormal,
+          stacktrace: stacktrace,
+          # Bandit doesn't handle exits so it doesn't provide the conn in the metadata
+          plug_conn: nil
+        }
+      ] = Tower.EphemeralReporter.events()
+    )
+
+    assert String.length(id) == 36
+    assert recent_datetime?(datetime)
+    assert is_list(stacktrace)
+  end
+
   test "reports message plug_conn manually" do
     Tower.handle_message(
       :info,