Skip to content

Commit 0496256

Browse files
martosaurmartosaur
committed
Add cases for Plug exceptions
1 parent 61e92a8 commit 0496256

8 files changed

Lines changed: 393 additions & 6 deletions

File tree

‎.tool-versions‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1 +1 @@
1-
elixir main-otp-27
1+
elixir 1.19.0-rc.0-otp-27

‎guides/plug-integration.md‎

Lines changed: 46 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,46 @@
1+
# Plug Integration
2+
3+
`Plug` integration is the most common "addon" for
4+
[logging](https://hexdocs.pm/sentry/setup-with-plug-and-phoenix.html)
5+
[libraries](https://hexdocs.pm/honeybadger/Honeybadger.Plug.html)
6+
[by](https://github.com/appsignal/appsignal-elixir-plug)
7+
[far](https://hexdocs.pm/error_tracker/ErrorTracker.Integrations.Plug.html).
8+
There are two reasons for this.
9+
10+
## 1. Metadata
11+
12+
`Plug.Conn` is a treasure trove of useful metadata that makes understanding
13+
errors much easier. Even basic information like request path and user-agent can
14+
make a huge difference in debugging. To take advantage of this rich context and
15+
save developers effort, logging libraries typically provide a plug module that
16+
you can drop into your router. This plug automatically extracts relevant
17+
connection data and adds it to logger metadata. Any errors logged later in the
18+
same process will inherit this context.
19+
20+
## 2. Error Handling
21+
22+
Setting metadata from `conn` is straightforward, why do a lot of Plug
23+
integration modules consist largely of macros?
24+
25+
For a long time, `Cowboy` was _the_ web server for Elixir applications, and it
26+
has one significant quirk: Cowboy logs errors from a different process than the
27+
one that actually handled the request. Remember our earlier point?
28+
29+
> Any errors logged later in the same process will inherit this context.
30+
31+
Well, for Cowboy errors, all the lovely metadata will be gone. That's why Plug
32+
integration modules use macros: they wrap plug execution in a way that allows
33+
them to log the error themselves while in the process with access to metadata.
34+
And this is also the reason why virtually every library excludes logs coming
35+
from the `:cowboy` domain - that is, to avoid duplicates.
36+
37+
These days, custom error handling is hardly necessary. `Bandit` web server is
38+
the new default and it executes requests and logs errors in the same process.
39+
But the Cowboy situation is better too. `Plug.Cowboy` adapter comes with a
40+
translator that ensures the `conn` struct is available in the log metadata, so a
41+
logger handler can extract all the metadata from it again.
42+
43+
## Testing
44+
45+
LoggerHandlerKit comes with a `LoggerHandlerKit.Act.plug_error/3` test case to
46+
help you check how plug errors will look when logged by your handler.

‎lib/logger_handler_kit/act.ex‎

Lines changed: 224 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1743,4 +1743,228 @@ defmodule LoggerHandlerKit.Act do
17431743
end
17441744

17451745
def metadata_serialization(case), do: Logger.metadata(extra: Map.fetch!(@metadata_types, case))
1746+
1747+
@doc """
1748+
Starts a web server powered by Cowboy or Bandit and sends a request that triggers an error during the Plug pipeline.
1749+
1750+
See [Plug integration guide](guides/plug-integration.md) for more details.
1751+
1752+
<!-- tabs-open -->
1753+
1754+
### Example Test
1755+
1756+
```elixir
1757+
# You only need to create your own router if you want to test custom plugs that somehow affect logging
1758+
defmodule MyPlug do
1759+
use Plug.Router
1760+
1761+
plug MyCustomPlug
1762+
plug :match
1763+
plug :dispatch
1764+
1765+
forward "/", to: LoggerHandlerKit.Plug
1766+
end
1767+
1768+
test "Bandit: plug exception", %{handler_ref: ref, io_ref: io_ref} do
1769+
LoggerHandlerKit.Act.plug_error(:exception, Bandit, MyPlug)
1770+
LoggerHandlerKit.Assert.assert_logged(ref)
1771+
1772+
# handler-specific assertions
1773+
end
1774+
```
1775+
1776+
### Example Log Event (Bandit)
1777+
1778+
```elixir
1779+
%{
1780+
meta: %{
1781+
line: 242,
1782+
pid: #PID<0.556.0>,
1783+
time: 1750196815012775,
1784+
file: ~c"lib/bandit/pipeline.ex",
1785+
gl: #PID<0.69.0>,
1786+
domain: [:elixir, :bandit],
1787+
application: :bandit,
1788+
mfa: {Bandit.Pipeline, :handle_error, 7},
1789+
plug: {LoggerHandlerKit.Plug, %{test_pid: #PID<0.240.0>}},
1790+
conn: %Plug.Conn{...},
1791+
crash_reason: {%RuntimeError{message: "oops"},
1792+
[
1793+
{LoggerHandlerKit.Plug, :"-do_match/4-fun-1-", 2,
1794+
[
1795+
file: ~c"lib/logger_handler_kit/plug.ex",
1796+
line: 8,
1797+
error_info: %{module: Exception}
1798+
]},
1799+
{LoggerHandlerKit.Plug, :"-dispatch/2-fun-0-", 4,
1800+
[file: ~c"deps/plug/lib/plug/router.ex", line: 246]},
1801+
{:telemetry, :span, 3,
1802+
[
1803+
file: ~c"/Users/user/projects/logger_handler_kit/deps/telemetry/src/telemetry.erl",
1804+
line: 324
1805+
]},
1806+
{LoggerHandlerKit.Plug, :dispatch, 2,
1807+
[file: ~c"deps/plug/lib/plug/router.ex", line: 242]},
1808+
{LoggerHandlerKit.Plug, :plug_builder_call, 2,
1809+
[file: ~c"lib/logger_handler_kit/plug.ex", line: 1]},
1810+
{Bandit.Pipeline, :call_plug!, 2,
1811+
[file: ~c"lib/bandit/pipeline.ex", line: 131]},
1812+
{Bandit.Pipeline, :run, 5, [file: ~c"lib/bandit/pipeline.ex", line: 42]},
1813+
{Bandit.HTTP1.Handler, :handle_data, 3,
1814+
[file: ~c"lib/bandit/http1/handler.ex", line: 13]},
1815+
{Bandit.DelegatingHandler, :handle_data, 3,
1816+
[file: ~c"lib/bandit/delegating_handler.ex", line: 18]},
1817+
{Bandit.DelegatingHandler, :handle_continue, 2,
1818+
[file: ~c"lib/bandit/delegating_handler.ex", line: 8]},
1819+
{:gen_server, :try_handle_continue, 3,
1820+
[file: ~c"gen_server.erl", line: 2335]},
1821+
{:gen_server, :loop, 7, [file: ~c"gen_server.erl", line: 2244]},
1822+
{:proc_lib, :init_p_do_apply, 3, [file: ~c"proc_lib.erl", line: 329]}
1823+
]}
1824+
},
1825+
msg: {:string,
1826+
"** (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"},
1827+
level: :error
1828+
}
1829+
```
1830+
1831+
### Example Log Event (Cowboy) (Elixir 1.19+)
1832+
1833+
```elixir
1834+
%{
1835+
meta: %{
1836+
error_logger: %{tag: :error},
1837+
pid: #PID<0.454.0>,
1838+
time: 1750197653870258,
1839+
gl: #PID<0.69.0>,
1840+
domain: [:cowboy],
1841+
report_cb: &Logger.Utils.translated_cb/1,
1842+
conn: %Plug.Conn{...},
1843+
crash_reason: {%RuntimeError{message: "oops"},
1844+
[
1845+
{LoggerHandlerKit.Plug, :"-do_match/4-fun-1-", 2,
1846+
[
1847+
file: ~c"lib/logger_handler_kit/plug.ex",
1848+
line: 8,
1849+
error_info: %{module: Exception}
1850+
]},
1851+
{LoggerHandlerKit.Plug, :"-dispatch/2-fun-0-", 4,
1852+
[file: ~c"deps/plug/lib/plug/router.ex", line: 246]},
1853+
{:telemetry, :span, 3,
1854+
[
1855+
file: ~c"/Users/user/projects/logger_handler_kit/deps/telemetry/src/telemetry.erl",
1856+
line: 324
1857+
]},
1858+
{LoggerHandlerKit.Plug, :dispatch, 2,
1859+
[file: ~c"deps/plug/lib/plug/router.ex", line: 242]},
1860+
{LoggerHandlerKit.Plug, :plug_builder_call, 2,
1861+
[file: ~c"lib/logger_handler_kit/plug.ex", line: 1]},
1862+
{Plug.Cowboy.Handler, :init, 2,
1863+
[file: ~c"lib/plug/cowboy/handler.ex", line: 11]},
1864+
{:cowboy_handler, :execute, 2,
1865+
[
1866+
file: ~c"/Users/user/projects/logger_handler_kit/deps/cowboy/src/cowboy_handler.erl",
1867+
line: 37
1868+
]},
1869+
{:cowboy_stream_h, :execute, 3,
1870+
[
1871+
file: ~c"/Users/user/projects/logger_handler_kit/deps/cowboy/src/cowboy_stream_h.erl",
1872+
line: 310
1873+
]},
1874+
{:cowboy_stream_h, :request_process, 3,
1875+
[
1876+
file: ~c"/Users/user/projects/logger_handler_kit/deps/cowboy/src/cowboy_stream_h.erl",
1877+
line: 299
1878+
]},
1879+
{:proc_lib, :init_p_do_apply, 3, [file: ~c"proc_lib.erl", line: 329]}
1880+
]}
1881+
},
1882+
msg: {:report,
1883+
%{
1884+
args: [
1885+
LoggerHandlerKit.Plug.HTTP,
1886+
#PID<0.454.0>,
1887+
1,
1888+
#PID<0.455.0>,
1889+
{{{%RuntimeError{message: "oops"},
1890+
[
1891+
{LoggerHandlerKit.Plug, :"-do_match/4-fun-1-", 2,
1892+
[
1893+
file: ~c"lib/logger_handler_kit/plug.ex",
1894+
line: 8,
1895+
error_info: %{module: Exception}
1896+
]},
1897+
{LoggerHandlerKit.Plug, :"-dispatch/2-fun-0-", 4,
1898+
[file: ~c"deps/plug/lib/plug/router.ex", line: 246]},
1899+
{:telemetry, :span, 3,
1900+
[
1901+
file: ~c"/Users/user/projects/logger_handler_kit/deps/telemetry/src/telemetry.erl",
1902+
line: 324
1903+
]},
1904+
{LoggerHandlerKit.Plug, :dispatch, 2,
1905+
[file: ~c"deps/plug/lib/plug/router.ex", line: 242]},
1906+
{LoggerHandlerKit.Plug, :plug_builder_call, 2,
1907+
[file: ~c"lib/logger_handler_kit/plug.ex", line: 1]},
1908+
{Plug.Cowboy.Handler, :init, 2,
1909+
[file: ~c"lib/plug/cowboy/handler.ex", line: 11]},
1910+
{:cowboy_handler, :execute, 2,
1911+
[
1912+
file: ~c"/Users/user/projects/logger_handler_kit/deps/cowboy/src/cowboy_handler.erl",
1913+
line: 37
1914+
]},
1915+
{:cowboy_stream_h, :execute, 3,
1916+
[
1917+
file: ~c"/Users/user/projects/logger_handler_kit/deps/cowboy/src/cowboy_stream_h.erl",
1918+
line: 310
1919+
]},
1920+
{:cowboy_stream_h, :request_process, 3,
1921+
[
1922+
file: ~c"/Users/user/projects/logger_handler_kit/deps/cowboy/src/cowboy_stream_h.erl",
1923+
line: 299
1924+
]},
1925+
{:proc_lib, :init_p_do_apply, 3,
1926+
[file: ~c"proc_lib.erl", line: 329]}
1927+
]},
1928+
{LoggerHandlerKit.Plug, :call,
1929+
[
1930+
%Plug.Conn{},
1931+
%{test_pid: #PID<0.238.0>}
1932+
]}}, []}
1933+
],
1934+
label: {:error_logger, :error_msg},
1935+
format: ~c"Ranch listener ~p, connection process ~p, stream ~p had its request process ~p exit with reason ~0p~n",
1936+
elixir_translation: [
1937+
"#PID<0.455.0>",
1938+
" running ",
1939+
"LoggerHandlerKit.Plug",
1940+
[" (connection ", "#PID<0.454.0>", ", stream id ", "1", 41],
1941+
" terminated\n",
1942+
[
1943+
["Server: ", "localhost", ":", "8001", 32, 40, "http", 41, 10],
1944+
["Request: ", "GET", 32, "/exception", 10]
1945+
] |
1946+
"** (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"
1947+
]
1948+
}},
1949+
level: :error
1950+
}
1951+
```
1952+
1953+
<!-- tabs-close -->
1954+
"""
1955+
@doc group: "Plug"
1956+
@spec plug_error(:exception | :throw | :exit, Bandit | Plug.Cowboy, module()) :: :ok
1957+
def plug_error(
1958+
flavour \\ :exception,
1959+
web_server \\ Bandit,
1960+
router_plug \\ LoggerHandlerKit.Plug
1961+
) do
1962+
ExUnit.Callbacks.start_supervised!(
1963+
{web_server, [plug: {router_plug, %{test_pid: self()}}, scheme: :http, port: 8001]}
1964+
)
1965+
1966+
{:ok, conn} = Mint.HTTP.connect(:http, "localhost", 8001)
1967+
{:ok, _conn, _request_ref} = Mint.HTTP.request(conn, "GET", "/#{flavour}", [], nil)
1968+
:ok
1969+
end
17461970
end

‎lib/logger_handler_kit/arrange.ex‎

Lines changed: 23 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -134,7 +134,10 @@ defmodule LoggerHandlerKit.Arrange do
134134
%{
135135
otp: Map.get(big_config_override, :handle_otp_reports, true),
136136
sasl: Map.get(big_config_override, :handle_sasl_reports, false),
137-
translators: [{Logger.Translator, :translate}]
137+
translators: [
138+
{Plug.Cowboy.Translator, :translate},
139+
{Logger.Translator, :translate}
140+
]
138141
}}
139142
]
140143
}
@@ -170,7 +173,16 @@ defmodule LoggerHandlerKit.Arrange do
170173
"""
171174
def ownership_filter(log_event, %{handler_id: handler_id}) do
172175
callers = Process.get(:"$callers") || []
173-
meta_pid = get_in(log_event, [:meta, :pid])
176+
177+
meta_pids =
178+
[
179+
# A lot of OTP reports have original pid under this key
180+
get_in(log_event, [:meta, :pid]),
181+
# In Bandit Plug error, we can fetch thoughtfully put test pid from the `conn` metadata
182+
get_in(log_event, [:meta, :plug, Access.elem(1), :test_pid]),
183+
# In Cowboy/Ranch reports, `conn` is also available albeit deeply, painfully nested
184+
maybe_test_pid_from_ranch_report(log_event)
185+
]
174186

175187
@ownership_server
176188
|> NimbleOwnership.fetch_owner([self() | callers], handler_id)
@@ -179,7 +191,7 @@ defmodule LoggerHandlerKit.Arrange do
179191
log_event
180192

181193
_ ->
182-
case NimbleOwnership.fetch_owner(@ownership_server, [meta_pid], handler_id) do
194+
case NimbleOwnership.fetch_owner(@ownership_server, meta_pids, handler_id) do
183195
{:ok, owner_pid} ->
184196
with server when not is_nil(server) <- GenServer.whereis({:global, Mox.Server}) do
185197
for {key, _} <- NimbleOwnership.get_owned({:global, Mox.Server}, owner_pid, %{}) do
@@ -207,4 +219,12 @@ defmodule LoggerHandlerKit.Arrange do
207219
def allow(owner_pid, pid, handler_id) do
208220
NimbleOwnership.allow(@ownership_server, owner_pid, pid, handler_id)
209221
end
222+
223+
defp maybe_test_pid_from_ranch_report(%{
224+
msg: {:report, %{args: [_, _, _, _, {{_, {_, _, [_, %{test_pid: pid} | _]}}, _} | _]}}
225+
}) do
226+
pid
227+
end
228+
229+
defp maybe_test_pid_from_ranch_report(_), do: nil
210230
end

‎lib/logger_handler_kit/plug.ex‎

Lines changed: 21 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,21 @@
1+
defmodule LoggerHandlerKit.Plug do
2+
use Plug.Router
3+
4+
plug(:match)
5+
plug(:dispatch)
6+
7+
get "/exception" do
8+
raise "oops"
9+
conn
10+
end
11+
12+
get "/throw" do
13+
throw("catch!")
14+
conn
15+
end
16+
17+
get "/exit" do
18+
exit("i quit")
19+
conn
20+
end
21+
end

‎mix.exs‎

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -47,7 +47,8 @@ defmodule LoggerHandlerKit.MixProject do
4747
"README.md",
4848
"guides/translation.md",
4949
"guides/unhandled.md",
50-
"guides/metadata.md"
50+
"guides/metadata.md",
51+
"guides/plug-integration.md"
5152
],
5253
groups_for_modules: [
5354
Helpers: [
@@ -68,6 +69,10 @@ defmodule LoggerHandlerKit.MixProject do
6869
defp deps do
6970
[
7071
{:nimble_ownership, "~> 1.0"},
72+
{:plug, "~> 1.18"},
73+
{:bandit, "~> 1.7"},
74+
{:plug_cowboy, "~> 2.7"},
75+
{:mint, "~> 1.7"},
7176
{:ex_doc, "~> 0.37", only: :dev}
7277
]
7378
end

0 commit comments

Comments
 (0)