diff --git a/lib/tower.ex b/lib/tower.ex index 55990f7..99df902 100644 --- a/lib/tower.ex +++ b/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 diff --git a/lib/tower/bandit_exception_handler.ex b/lib/tower/bandit_exception_handler.ex new file mode 100644 index 0000000..2711665 --- /dev/null +++ b/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 diff --git a/mix.exs b/mix.exs index f207802..328320a 100644 --- a/mix.exs +++ b/mix.exs @@ -41,6 +41,7 @@ defmodule Tower.MixProject do defp deps do [ {:uniq, "~> 0.6.1"}, + {:telemetry, "~> 1.2"}, # Dev {:ex_doc, "~> 0.34.0", only: :dev, runtime: false}, @@ -48,7 +49,8 @@ defmodule Tower.MixProject do # 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 diff --git a/mix.lock b/mix.lock index c36f142..a0d3196 100644 --- a/mix.lock +++ b/mix.lock @@ -1,5 +1,6 @@ %{ "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"}, @@ -7,6 +8,7 @@ "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"}, } diff --git a/test/plug/tower_plug_test.exs b/test/plug/tower_plug_test.exs index 69e5841..954c090 100644 --- a/test/plug/tower_plug_test.exs +++ b/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,