Add cases for Plug exceptions

.tool-versions

@@ -1 +1 @@
-elixir main-otp-27
+elixir 1.19.0-rc.0-otp-27

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.

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.
+
+  <!-- tabs-open -->
+
+  ### 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
+  }
+  ```
+
+  <!-- tabs-close -->
+  """
+  @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

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

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

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