From 7a5081360014081fca4ea92b5fc15ed544bd8e1e Mon Sep 17 00:00:00 2001 From: martosaur Date: Tue, 17 Jun 2025 15:12:58 -0700 Subject: [PATCH] Add cases for Plug exceptions --- .tool-versions | 2 +- guides/plug-integration.md | 46 ++++++ lib/logger_handler_kit/act.ex | 224 ++++++++++++++++++++++++++++++ lib/logger_handler_kit/arrange.ex | 26 +++- lib/logger_handler_kit/plug.ex | 21 +++ mix.exs | 7 +- mix.lock | 14 ++ test/default_logger_test.exs | 59 +++++++- 8 files changed, 393 insertions(+), 6 deletions(-) create mode 100644 guides/plug-integration.md create mode 100644 lib/logger_handler_kit/plug.ex diff --git a/.tool-versions b/.tool-versions index fa0b42d..92bd06b 100644 --- a/.tool-versions +++ b/.tool-versions @@ -1 +1 @@ -elixir main-otp-27 +elixir 1.19.0-rc.0-otp-27 diff --git a/guides/plug-integration.md b/guides/plug-integration.md new file mode 100644 index 0000000..4c81560 --- /dev/null +++ b/guides/plug-integration.md @@ -0,0 +1,46 @@ +# Plug Integration + +`Plug` integration is the most common "addon" for +[logging](https://hexdocs.pm/sentry/setup-with-plug-and-phoenix.html) +[libraries](https://hexdocs.pm/honeybadger/Honeybadger.Plug.html) +[by](https://github.com/appsignal/appsignal-elixir-plug) +[far](https://hexdocs.pm/error_tracker/ErrorTracker.Integrations.Plug.html). +There are two reasons for this. + +## 1. Metadata + +`Plug.Conn` is a treasure trove of useful metadata that makes understanding +errors much easier. Even basic information like request path and user-agent can +make a huge difference in debugging. To take advantage of this rich context and +save developers effort, logging libraries typically provide a plug module that +you can drop into your router. This plug automatically extracts relevant +connection data and adds it to logger metadata. Any errors logged later in the +same process will inherit this context. + +## 2. Error Handling + +Setting metadata from `conn` is straightforward, why do a lot of Plug +integration modules consist largely of macros? + +For a long time, `Cowboy` was _the_ web server for Elixir applications, and it +has one significant quirk: Cowboy logs errors from a different process than the +one that actually handled the request. Remember our earlier point? + +> Any errors logged later in the same process will inherit this context. + +Well, for Cowboy errors, all the lovely metadata will be gone. That's why Plug +integration modules use macros: they wrap plug execution in a way that allows +them to log the error themselves while in the process with access to metadata. +And this is also the reason why virtually every library excludes logs coming +from the `:cowboy` domain - that is, to avoid duplicates. + +These days, custom error handling is hardly necessary. `Bandit` web server is +the new default and it executes requests and logs errors in the same process. +But the Cowboy situation is better too. `Plug.Cowboy` adapter comes with a +translator that ensures the `conn` struct is available in the log metadata, so a +logger handler can extract all the metadata from it again. + +## Testing + +LoggerHandlerKit comes with a `LoggerHandlerKit.Act.plug_error/3` test case to +help you check how plug errors will look when logged by your handler. \ No newline at end of file diff --git a/lib/logger_handler_kit/act.ex b/lib/logger_handler_kit/act.ex index 5403f52..0ae816c 100644 --- a/lib/logger_handler_kit/act.ex +++ b/lib/logger_handler_kit/act.ex @@ -1743,4 +1743,228 @@ defmodule LoggerHandlerKit.Act do end def metadata_serialization(case), do: Logger.metadata(extra: Map.fetch!(@metadata_types, case)) + + @doc """ + Starts a web server powered by Cowboy or Bandit and sends a request that triggers an error during the Plug pipeline. + + See [Plug integration guide](guides/plug-integration.md) for more details. + + + + ### Example Test + + ```elixir + # You only need to create your own router if you want to test custom plugs that somehow affect logging + defmodule MyPlug do + use Plug.Router + + plug MyCustomPlug + plug :match + plug :dispatch + + forward "/", to: LoggerHandlerKit.Plug + end + + test "Bandit: plug exception", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.plug_error(:exception, Bandit, MyPlug) + LoggerHandlerKit.Assert.assert_logged(ref) + + # handler-specific assertions + end + ``` + + ### Example Log Event (Bandit) + + ```elixir + %{ + meta: %{ + line: 242, + pid: #PID<0.556.0>, + time: 1750196815012775, + file: ~c"lib/bandit/pipeline.ex", + gl: #PID<0.69.0>, + domain: [:elixir, :bandit], + application: :bandit, + mfa: {Bandit.Pipeline, :handle_error, 7}, + plug: {LoggerHandlerKit.Plug, %{test_pid: #PID<0.240.0>}}, + conn: %Plug.Conn{...}, + crash_reason: {%RuntimeError{message: "oops"}, + [ + {LoggerHandlerKit.Plug, :"-do_match/4-fun-1-", 2, + [ + file: ~c"lib/logger_handler_kit/plug.ex", + line: 8, + error_info: %{module: Exception} + ]}, + {LoggerHandlerKit.Plug, :"-dispatch/2-fun-0-", 4, + [file: ~c"deps/plug/lib/plug/router.ex", line: 246]}, + {:telemetry, :span, 3, + [ + file: ~c"/Users/user/projects/logger_handler_kit/deps/telemetry/src/telemetry.erl", + line: 324 + ]}, + {LoggerHandlerKit.Plug, :dispatch, 2, + [file: ~c"deps/plug/lib/plug/router.ex", line: 242]}, + {LoggerHandlerKit.Plug, :plug_builder_call, 2, + [file: ~c"lib/logger_handler_kit/plug.ex", line: 1]}, + {Bandit.Pipeline, :call_plug!, 2, + [file: ~c"lib/bandit/pipeline.ex", line: 131]}, + {Bandit.Pipeline, :run, 5, [file: ~c"lib/bandit/pipeline.ex", line: 42]}, + {Bandit.HTTP1.Handler, :handle_data, 3, + [file: ~c"lib/bandit/http1/handler.ex", line: 13]}, + {Bandit.DelegatingHandler, :handle_data, 3, + [file: ~c"lib/bandit/delegating_handler.ex", line: 18]}, + {Bandit.DelegatingHandler, :handle_continue, 2, + [file: ~c"lib/bandit/delegating_handler.ex", line: 8]}, + {:gen_server, :try_handle_continue, 3, + [file: ~c"gen_server.erl", line: 2335]}, + {:gen_server, :loop, 7, [file: ~c"gen_server.erl", line: 2244]}, + {:proc_lib, :init_p_do_apply, 3, [file: ~c"proc_lib.erl", line: 329]} + ]} + }, + msg: {:string, + "** (RuntimeError) oops\n (logger_handler_kit 0.2.0) lib/logger_handler_kit/plug.ex:8: anonymous fn/2 in LoggerHandlerKit.Plug.do_match/4\n (logger_handler_kit 0.2.0) deps/plug/lib/plug/router.ex:246: anonymous fn/4 in LoggerHandlerKit.Plug.dispatch/2\n (telemetry 1.3.0) /Users/user/projects/logger_handler_kit/deps/telemetry/src/telemetry.erl:324: :telemetry.span/3\n (logger_handler_kit 0.2.0) deps/plug/lib/plug/router.ex:242: LoggerHandlerKit.Plug.dispatch/2\n (logger_handler_kit 0.2.0) lib/logger_handler_kit/plug.ex:1: LoggerHandlerKit.Plug.plug_builder_call/2\n (bandit 1.7.0) lib/bandit/pipeline.ex:131: Bandit.Pipeline.call_plug!/2\n (bandit 1.7.0) lib/bandit/pipeline.ex:42: Bandit.Pipeline.run/5\n (bandit 1.7.0) lib/bandit/http1/handler.ex:13: Bandit.HTTP1.Handler.handle_data/3\n (bandit 1.7.0) lib/bandit/delegating_handler.ex:18: Bandit.DelegatingHandler.handle_data/3\n (bandit 1.7.0) lib/bandit/delegating_handler.ex:8: Bandit.DelegatingHandler.handle_continue/2\n (stdlib 6.2.2) gen_server.erl:2335: :gen_server.try_handle_continue/3\n (stdlib 6.2.2) gen_server.erl:2244: :gen_server.loop/7\n (stdlib 6.2.2) proc_lib.erl:329: :proc_lib.init_p_do_apply/3\n"}, + level: :error + } + ``` + + ### Example Log Event (Cowboy) (Elixir 1.19+) + + ```elixir + %{ + meta: %{ + error_logger: %{tag: :error}, + pid: #PID<0.454.0>, + time: 1750197653870258, + gl: #PID<0.69.0>, + domain: [:cowboy], + report_cb: &Logger.Utils.translated_cb/1, + conn: %Plug.Conn{...}, + crash_reason: {%RuntimeError{message: "oops"}, + [ + {LoggerHandlerKit.Plug, :"-do_match/4-fun-1-", 2, + [ + file: ~c"lib/logger_handler_kit/plug.ex", + line: 8, + error_info: %{module: Exception} + ]}, + {LoggerHandlerKit.Plug, :"-dispatch/2-fun-0-", 4, + [file: ~c"deps/plug/lib/plug/router.ex", line: 246]}, + {:telemetry, :span, 3, + [ + file: ~c"/Users/user/projects/logger_handler_kit/deps/telemetry/src/telemetry.erl", + line: 324 + ]}, + {LoggerHandlerKit.Plug, :dispatch, 2, + [file: ~c"deps/plug/lib/plug/router.ex", line: 242]}, + {LoggerHandlerKit.Plug, :plug_builder_call, 2, + [file: ~c"lib/logger_handler_kit/plug.ex", line: 1]}, + {Plug.Cowboy.Handler, :init, 2, + [file: ~c"lib/plug/cowboy/handler.ex", line: 11]}, + {:cowboy_handler, :execute, 2, + [ + file: ~c"/Users/user/projects/logger_handler_kit/deps/cowboy/src/cowboy_handler.erl", + line: 37 + ]}, + {:cowboy_stream_h, :execute, 3, + [ + file: ~c"/Users/user/projects/logger_handler_kit/deps/cowboy/src/cowboy_stream_h.erl", + line: 310 + ]}, + {:cowboy_stream_h, :request_process, 3, + [ + file: ~c"/Users/user/projects/logger_handler_kit/deps/cowboy/src/cowboy_stream_h.erl", + line: 299 + ]}, + {:proc_lib, :init_p_do_apply, 3, [file: ~c"proc_lib.erl", line: 329]} + ]} + }, + msg: {:report, + %{ + args: [ + LoggerHandlerKit.Plug.HTTP, + #PID<0.454.0>, + 1, + #PID<0.455.0>, + {{{%RuntimeError{message: "oops"}, + [ + {LoggerHandlerKit.Plug, :"-do_match/4-fun-1-", 2, + [ + file: ~c"lib/logger_handler_kit/plug.ex", + line: 8, + error_info: %{module: Exception} + ]}, + {LoggerHandlerKit.Plug, :"-dispatch/2-fun-0-", 4, + [file: ~c"deps/plug/lib/plug/router.ex", line: 246]}, + {:telemetry, :span, 3, + [ + file: ~c"/Users/user/projects/logger_handler_kit/deps/telemetry/src/telemetry.erl", + line: 324 + ]}, + {LoggerHandlerKit.Plug, :dispatch, 2, + [file: ~c"deps/plug/lib/plug/router.ex", line: 242]}, + {LoggerHandlerKit.Plug, :plug_builder_call, 2, + [file: ~c"lib/logger_handler_kit/plug.ex", line: 1]}, + {Plug.Cowboy.Handler, :init, 2, + [file: ~c"lib/plug/cowboy/handler.ex", line: 11]}, + {:cowboy_handler, :execute, 2, + [ + file: ~c"/Users/user/projects/logger_handler_kit/deps/cowboy/src/cowboy_handler.erl", + line: 37 + ]}, + {:cowboy_stream_h, :execute, 3, + [ + file: ~c"/Users/user/projects/logger_handler_kit/deps/cowboy/src/cowboy_stream_h.erl", + line: 310 + ]}, + {:cowboy_stream_h, :request_process, 3, + [ + file: ~c"/Users/user/projects/logger_handler_kit/deps/cowboy/src/cowboy_stream_h.erl", + line: 299 + ]}, + {:proc_lib, :init_p_do_apply, 3, + [file: ~c"proc_lib.erl", line: 329]} + ]}, + {LoggerHandlerKit.Plug, :call, + [ + %Plug.Conn{}, + %{test_pid: #PID<0.238.0>} + ]}}, []} + ], + label: {:error_logger, :error_msg}, + format: ~c"Ranch listener ~p, connection process ~p, stream ~p had its request process ~p exit with reason ~0p~n", + elixir_translation: [ + "#PID<0.455.0>", + " running ", + "LoggerHandlerKit.Plug", + [" (connection ", "#PID<0.454.0>", ", stream id ", "1", 41], + " terminated\n", + [ + ["Server: ", "localhost", ":", "8001", 32, 40, "http", 41, 10], + ["Request: ", "GET", 32, "/exception", 10] + ] | + "** (exit) an exception was raised:\n ** (RuntimeError) oops\n (logger_handler_kit 0.2.0) lib/logger_handler_kit/plug.ex:8: anonymous fn/2 in LoggerHandlerKit.Plug.do_match/4\n (logger_handler_kit 0.2.0) deps/plug/lib/plug/router.ex:246: anonymous fn/4 in LoggerHandlerKit.Plug.dispatch/2\n (telemetry 1.3.0) /Users/user/projects/logger_handler_kit/deps/telemetry/src/telemetry.erl:324: :telemetry.span/3\n (logger_handler_kit 0.2.0) deps/plug/lib/plug/router.ex:242: LoggerHandlerKit.Plug.dispatch/2\n (logger_handler_kit 0.2.0) lib/logger_handler_kit/plug.ex:1: LoggerHandlerKit.Plug.plug_builder_call/2\n (plug_cowboy 2.7.3) lib/plug/cowboy/handler.ex:11: Plug.Cowboy.Handler.init/2\n (cowboy 2.13.0) /Users/user/projects/logger_handler_kit/deps/cowboy/src/cowboy_handler.erl:37: :cowboy_handler.execute/2\n (cowboy 2.13.0) /Users/user/projects/logger_handler_kit/deps/cowboy/src/cowboy_stream_h.erl:310: :cowboy_stream_h.execute/3\n (cowboy 2.13.0) /Users/user/projects/logger_handler_kit/deps/cowboy/src/cowboy_stream_h.erl:299: :cowboy_stream_h.request_process/3\n (stdlib 6.2.2) proc_lib.erl:329: :proc_lib.init_p_do_apply/3" + ] + }}, + level: :error + } + ``` + + + """ + @doc group: "Plug" + @spec plug_error(:exception | :throw | :exit, Bandit | Plug.Cowboy, module()) :: :ok + def plug_error( + flavour \\ :exception, + web_server \\ Bandit, + router_plug \\ LoggerHandlerKit.Plug + ) do + ExUnit.Callbacks.start_supervised!( + {web_server, [plug: {router_plug, %{test_pid: self()}}, scheme: :http, port: 8001]} + ) + + {:ok, conn} = Mint.HTTP.connect(:http, "localhost", 8001) + {:ok, _conn, _request_ref} = Mint.HTTP.request(conn, "GET", "/#{flavour}", [], nil) + :ok + end end diff --git a/lib/logger_handler_kit/arrange.ex b/lib/logger_handler_kit/arrange.ex index 1230540..46a31dd 100644 --- a/lib/logger_handler_kit/arrange.ex +++ b/lib/logger_handler_kit/arrange.ex @@ -134,7 +134,10 @@ defmodule LoggerHandlerKit.Arrange do %{ otp: Map.get(big_config_override, :handle_otp_reports, true), sasl: Map.get(big_config_override, :handle_sasl_reports, false), - translators: [{Logger.Translator, :translate}] + translators: [ + {Plug.Cowboy.Translator, :translate}, + {Logger.Translator, :translate} + ] }} ] } @@ -170,7 +173,16 @@ defmodule LoggerHandlerKit.Arrange do """ def ownership_filter(log_event, %{handler_id: handler_id}) do callers = Process.get(:"$callers") || [] - meta_pid = get_in(log_event, [:meta, :pid]) + + meta_pids = + [ + # A lot of OTP reports have original pid under this key + get_in(log_event, [:meta, :pid]), + # In Bandit Plug error, we can fetch thoughtfully put test pid from the `conn` metadata + get_in(log_event, [:meta, :plug, Access.elem(1), :test_pid]), + # In Cowboy/Ranch reports, `conn` is also available albeit deeply, painfully nested + maybe_test_pid_from_ranch_report(log_event) + ] @ownership_server |> NimbleOwnership.fetch_owner([self() | callers], handler_id) @@ -179,7 +191,7 @@ defmodule LoggerHandlerKit.Arrange do log_event _ -> - case NimbleOwnership.fetch_owner(@ownership_server, [meta_pid], handler_id) do + case NimbleOwnership.fetch_owner(@ownership_server, meta_pids, handler_id) do {:ok, owner_pid} -> with server when not is_nil(server) <- GenServer.whereis({:global, Mox.Server}) do for {key, _} <- NimbleOwnership.get_owned({:global, Mox.Server}, owner_pid, %{}) do @@ -207,4 +219,12 @@ defmodule LoggerHandlerKit.Arrange do def allow(owner_pid, pid, handler_id) do NimbleOwnership.allow(@ownership_server, owner_pid, pid, handler_id) end + + defp maybe_test_pid_from_ranch_report(%{ + msg: {:report, %{args: [_, _, _, _, {{_, {_, _, [_, %{test_pid: pid} | _]}}, _} | _]}} + }) do + pid + end + + defp maybe_test_pid_from_ranch_report(_), do: nil end diff --git a/lib/logger_handler_kit/plug.ex b/lib/logger_handler_kit/plug.ex new file mode 100644 index 0000000..5f06582 --- /dev/null +++ b/lib/logger_handler_kit/plug.ex @@ -0,0 +1,21 @@ +defmodule LoggerHandlerKit.Plug do + use Plug.Router + + plug(:match) + plug(:dispatch) + + get "/exception" do + raise "oops" + conn + end + + get "/throw" do + throw("catch!") + conn + end + + get "/exit" do + exit("i quit") + conn + end +end diff --git a/mix.exs b/mix.exs index ebd5fa8..6e7fde4 100644 --- a/mix.exs +++ b/mix.exs @@ -47,7 +47,8 @@ defmodule LoggerHandlerKit.MixProject do "README.md", "guides/translation.md", "guides/unhandled.md", - "guides/metadata.md" + "guides/metadata.md", + "guides/plug-integration.md" ], groups_for_modules: [ Helpers: [ @@ -68,6 +69,10 @@ defmodule LoggerHandlerKit.MixProject do defp deps do [ {:nimble_ownership, "~> 1.0"}, + {:plug, "~> 1.18"}, + {:bandit, "~> 1.7"}, + {:plug_cowboy, "~> 2.7"}, + {:mint, "~> 1.7"}, {:ex_doc, "~> 0.37", only: :dev} ] end diff --git a/mix.lock b/mix.lock index 488d85b..ee20a8c 100644 --- a/mix.lock +++ b/mix.lock @@ -1,9 +1,23 @@ %{ + "bandit": {:hex, :bandit, "1.7.0", "d1564f30553c97d3e25f9623144bb8df11f3787a26733f00b21699a128105c0c", [:mix], [{:hpax, "~> 1.0", [hex: :hpax, repo: "hexpm", optional: false]}, {:plug, "~> 1.18", [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", "3e2f7a98c7a11f48d9d8c037f7177cd39778e74d55c7af06fe6227c742a8168a"}, + "cowboy": {:hex, :cowboy, "2.13.0", "09d770dd5f6a22cc60c071f432cd7cb87776164527f205c5a6b0f24ff6b38990", [:make, :rebar3], [{:cowlib, ">= 2.14.0 and < 3.0.0", [hex: :cowlib, repo: "hexpm", optional: false]}, {:ranch, ">= 1.8.0 and < 3.0.0", [hex: :ranch, repo: "hexpm", optional: false]}], "hexpm", "e724d3a70995025d654c1992c7b11dbfea95205c047d86ff9bf1cda92ddc5614"}, + "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.15.0", "3c97a318a933962d1c12b96ab7c1d728267d2c523c25a5b57b0f93392b6e9e25", [:make, :rebar3], [], "hexpm", "4f00c879a64b4fe7c8fcb42a4281925e9ffdb928820b03c3ad325a617e857532"}, "earmark_parser": {:hex, :earmark_parser, "1.4.44", "f20830dd6b5c77afe2b063777ddbbff09f9759396500cdbe7523efd58d7a339c", [:mix], [], "hexpm", "4778ac752b4701a5599215f7030989c989ffdc4f6df457c5f36938cc2d2a2750"}, "ex_doc": {:hex, :ex_doc, "0.37.3", "f7816881a443cd77872b7d6118e8a55f547f49903aef8747dbcb345a75b462f9", [:mix], [{:earmark_parser, "~> 1.4.42", [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", "e6aebca7156e7c29b5da4daa17f6361205b2ae5f26e5c7d8ca0d3f7e18972233"}, + "hpax": {:hex, :hpax, "1.0.3", "ed67ef51ad4df91e75cc6a1494f851850c0bd98ebc0be6e81b026e765ee535aa", [:mix], [], "hexpm", "8eab6e1cfa8d5918c2ce4ba43588e894af35dbd8e91e6e55c817bca5847df34a"}, "makeup": {:hex, :makeup, "1.2.1", "e90ac1c65589ef354378def3ba19d401e739ee7ee06fb47f94c687016e3713d1", [:mix], [{:nimble_parsec, "~> 1.4", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "d36484867b0bae0fea568d10131197a4c2e47056a6fbe84922bf6ba71c8d17ce"}, "makeup_elixir": {:hex, :makeup_elixir, "1.0.1", "e928a4f984e795e41e3abd27bfc09f51db16ab8ba1aebdba2b3a575437efafc2", [: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", "7284900d412a3e5cfd97fdaed4f5ed389b8f2b4cb49efc0eb3bd10e2febf9507"}, "makeup_erlang": {:hex, :makeup_erlang, "1.0.2", "03e1804074b3aa64d5fad7aa64601ed0fb395337b982d9bcf04029d68d51b6a7", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}], "hexpm", "af33ff7ef368d5893e4a267933e7744e46ce3cf1f61e2dccf53a111ed3aa3727"}, + "mime": {:hex, :mime, "2.0.7", "b8d739037be7cd402aee1ba0306edfdef982687ee7e9859bee6198c1e7e2f128", [:mix], [], "hexpm", "6171188e399ee16023ffc5b76ce445eb6d9672e2e241d2df6050f3c771e80ccd"}, + "mint": {:hex, :mint, "1.7.1", "113fdb2b2f3b59e47c7955971854641c61f378549d73e829e1768de90fc1abf1", [:mix], [{:castore, "~> 0.1.0 or ~> 1.0", [hex: :castore, repo: "hexpm", optional: true]}, {:hpax, "~> 0.1.1 or ~> 0.2.0 or ~> 1.0", [hex: :hpax, repo: "hexpm", optional: false]}], "hexpm", "fceba0a4d0f24301ddee3024ae116df1c3f4bb7a563a731f45fdfeb9d39a231b"}, "nimble_ownership": {:hex, :nimble_ownership, "1.0.1", "f69fae0cdd451b1614364013544e66e4f5d25f36a2056a9698b793305c5aa3a6", [:mix], [], "hexpm", "3825e461025464f519f3f3e4a1f9b68c47dc151369611629ad08b636b73bb22d"}, "nimble_parsec": {:hex, :nimble_parsec, "1.4.2", "8efba0122db06df95bfaa78f791344a89352ba04baedd3849593bfce4d0dc1c6", [:mix], [], "hexpm", "4b21398942dda052b403bbe1da991ccd03a053668d147d53fb8c4e0efe09c973"}, + "plug": {:hex, :plug, "1.18.0", "d78df36c41f7e798f2edf1f33e1727eae438e9dd5d809a9997c463a108244042", [:mix], [{:mime, "~> 1.0 or ~> 2.0", [hex: :mime, repo: "hexpm", optional: false]}, {:plug_crypto, "~> 1.1.1 or ~> 1.2 or ~> 2.0", [hex: :plug_crypto, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4.3 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "819f9e176d51e44dc38132e132fe0accaf6767eab7f0303431e404da8476cfa2"}, + "plug_cowboy": {:hex, :plug_cowboy, "2.7.3", "1304d36752e8bdde213cea59ef424ca932910a91a07ef9f3874be709c4ddb94b", [:mix], [{:cowboy, "~> 2.7", [hex: :cowboy, repo: "hexpm", optional: false]}, {:cowboy_telemetry, "~> 0.3", [hex: :cowboy_telemetry, repo: "hexpm", optional: false]}, {:plug, "~> 1.14", [hex: :plug, repo: "hexpm", optional: false]}], "hexpm", "77c95524b2aa5364b247fa17089029e73b951ebc1adeef429361eab0bb55819d"}, + "plug_crypto": {:hex, :plug_crypto, "2.1.1", "19bda8184399cb24afa10be734f84a16ea0a2bc65054e23a62bb10f06bc89491", [:mix], [], "hexpm", "6470bce6ffe41c8bd497612ffde1a7e4af67f36a15eea5f921af71cf3e11247c"}, + "ranch": {:hex, :ranch, "2.2.0", "25528f82bc8d7c6152c57666ca99ec716510fe0925cb188172f41ce93117b1b0", [:make, :rebar3], [], "hexpm", "fa0b99a1780c80218a4197a59ea8d3bdae32fbff7e88527d7d8a4787eff4f8e7"}, + "telemetry": {:hex, :telemetry, "1.3.0", "fedebbae410d715cf8e7062c96a1ef32ec22e764197f70cda73d82778d61e7a2", [:rebar3], [], "hexpm", "7015fc8919dbe63764f4b4b87a95b7c0996bd539e0d499be6ec9d7f3875b79e6"}, + "thousand_island": {:hex, :thousand_island, "1.3.14", "ad45ebed2577b5437582bcc79c5eccd1e2a8c326abf6a3464ab6c06e2055a34a", [:mix], [{:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "d0d24a929d31cdd1d7903a4fe7f2409afeedff092d277be604966cd6aa4307ef"}, + "websock": {:hex, :websock, "0.5.3", "2f69a6ebe810328555b6fe5c831a851f485e303a7c8ce6c5f675abeb20ebdadc", [:mix], [], "hexpm", "6105453d7fac22c712ad66fab1d45abdf049868f253cf719b625151460b8b453"}, } diff --git a/test/default_logger_test.exs b/test/default_logger_test.exs index d6024b2..6e152cc 100644 --- a/test/default_logger_test.exs +++ b/test/default_logger_test.exs @@ -1,7 +1,7 @@ defmodule LoggerHandlerKit.DefaultLoggerTest do use ExUnit.Case, async: true - setup_all {LoggerHandlerKit.Arrange, :ensure_per_handler_translation} + setup {LoggerHandlerKit.Arrange, :ensure_per_handler_translation} setup do ref = make_ref() @@ -559,4 +559,61 @@ defmodule LoggerHandlerKit.DefaultLoggerTest do refute msg =~ "extra" end end + + describe "Plug" do + @describetag level: :error + + test "Bandit: plug exception", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.plug_error(:exception, Bandit) + LoggerHandlerKit.Assert.assert_logged(ref) + assert_receive {^io_ref, msg} + assert msg =~ "[error] ** (RuntimeError) oops" + end + + test "Bandit: plug throw", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.plug_error(:throw, Bandit) + LoggerHandlerKit.Assert.assert_logged(ref) + assert_receive {^io_ref, msg} + assert msg =~ "[error] ** (throw) \"catch!\"" + end + + test "Bandit: plug exit", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.plug_error(:exit, Bandit) + LoggerHandlerKit.Assert.assert_logged(ref) + assert_receive {^io_ref, msg} + assert msg =~ "[error] ** (exit) \"i quit\"" + end + + test "Cowboy: plug exception", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.plug_error(:exception, Plug.Cowboy) + LoggerHandlerKit.Assert.assert_logged(ref) + assert_receive {^io_ref, msg} + assert msg =~ "running LoggerHandlerKit.Plug" + assert msg =~ "Server: localhost:8001" + assert msg =~ "Request: GET /exception" + assert msg =~ "(exit) an exception was raised:" + assert msg =~ "** (RuntimeError) oops" + end + + test "Cowboy: plug throw", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.plug_error(:throw, Plug.Cowboy) + LoggerHandlerKit.Assert.assert_logged(ref) + assert_receive {^io_ref, msg} + assert msg =~ "running LoggerHandlerKit.Plug" + assert msg =~ "Server: localhost:8001" + assert msg =~ "Request: GET /throw" + assert msg =~ "(exit) an exception was raised:" + assert msg =~ "** (ErlangError) Erlang error: {:nocatch, \"catch!\"}" + end + + test "Cowboy: plug exit", %{handler_ref: ref, io_ref: io_ref} do + LoggerHandlerKit.Act.plug_error(:exit, Plug.Cowboy) + LoggerHandlerKit.Assert.assert_logged(ref) + assert_receive {^io_ref, msg} + assert msg =~ "running LoggerHandlerKit.Plug" + assert msg =~ "Server: localhost:8001" + assert msg =~ "Request: GET /exit" + assert msg =~ "** (exit) \"i quit\"" + end + end end