Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Error handling and logging improvements via re-raising #400

Draft
wants to merge 5 commits into
base: main
Choose a base branch
from
Draft
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions lib/bandit/application.ex
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@ defmodule Bandit.Application do
{:ok, pid}
| {:error, {:already_started, pid} | {:shutdown, term} | term}
def start(_type, _args) do
Logger.add_translator({Bandit.LoggerTranslator, :translate})
children = [Bandit.Clock]
Supervisor.start_link(children, strategy: :one_for_one)
end
Expand Down
30 changes: 30 additions & 0 deletions lib/bandit/logger_translator.ex
Original file line number Diff line number Diff line change
@@ -0,0 +1,30 @@
defmodule Bandit.LoggerTranslator do
def translate(_min_level, :error, :report, {:logger, %{reason: {:bad_return_value, value}}}) do
stacktrace = []
{
:ok,
Exception.format(:throw, value, stacktrace),
crash_reason: {{:nocatch, value}, stacktrace}, domain: :bandit
}
end

def translate(_min_level, :error, :report, {:logger, %{reason: {exception, stacktrace}}}) when is_exception(exception) do
{
:ok,
Exception.format(:error, exception, stacktrace),
crash_reason: {exception, stacktrace}, domain: :bandit
}
end

def translate(_min_level, :error, :report, {:logger, %{reason: {reason, stacktrace}}}) do
{
:ok,
Exception.format(:exit, reason, stacktrace),
crash_reason: {reason, stacktrace}, domain: :bandit
}
end

def translate(_min_level, _level, _kind, _message) do
:none
end
end
47 changes: 29 additions & 18 deletions lib/bandit/pipeline.ex
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,12 @@ defmodule Bandit.Pipeline do
@type scheme :: String.t() | nil
@type path :: String.t() | :*

@protocol_errors [
Bandit.HTTPError,
Bandit.HTTP2.Errors.StreamError,
Bandit.HTTP2.Errors.ConnectionError
]

require Logger

@spec run(
Expand Down Expand Up @@ -45,13 +51,20 @@ defmodule Bandit.Pipeline do
Bandit.Telemetry.stop_span(span, adapter.metrics, %{conn: conn})
{:upgrade, adapter.transport, protocol, opts}
end
rescue
error -> handle_error(error, __STACKTRACE__, transport, span, opts)
catch
kind, reason ->
handle_error(kind, reason, __STACKTRACE__, transport, span, opts)
end
rescue
error ->
span = Bandit.Telemetry.start_span(:request, measurements, metadata)
handle_error(error, __STACKTRACE__, transport, span, opts)
error in @protocol_errors ->
handle_error(
:error,
error,
__STACKTRACE__,
transport,
Bandit.Telemetry.start_span(:request, measurements, metadata),
opts
)
end
end

Expand Down Expand Up @@ -194,18 +207,15 @@ defmodule Bandit.Pipeline do
end

@spec handle_error(
:error | :throw | :exit,
Exception.t(),
Exception.stacktrace(),
Bandit.HTTPTransport.t(),
Bandit.Telemetry.t(),
map()
) :: {:ok, Bandit.HTTPTransport.t()} | {:error, term()}
defp handle_error(%type{} = error, stacktrace, transport, span, opts)
when type in [
Bandit.HTTPError,
Bandit.HTTP2.Errors.StreamError,
Bandit.HTTP2.Errors.ConnectionError
] do
defp handle_error(:error, %type{} = error, stacktrace, transport, span, opts)
when type in @protocol_errors do
Bandit.Telemetry.stop_span(span, %{}, %{error: error.message})

maybe_log_error(error, stacktrace, opts.http)
Expand All @@ -216,16 +226,17 @@ defmodule Bandit.Pipeline do
{:error, error}
end

defp handle_error(error, stacktrace, transport, span, opts) do
Bandit.Telemetry.span_exception(span, :exit, error, stacktrace)
status = error |> Plug.Exception.status() |> Plug.Conn.Status.code()
defp handle_error(kind, reason, stacktrace, transport, span, opts) do
# TODO: Fix this telementry kind
Bandit.Telemetry.span_exception(span, :exit, reason, stacktrace)
status = reason |> Plug.Exception.status() |> Plug.Conn.Status.code()

if status in Keyword.get(opts.http, :log_exceptions_with_status_codes, 500..599) do
Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ideally this conditional would be inside the Bandit.LoggerTranslator. Need a way to access the opts.http from there.

Logger.error(Exception.format(:error, error, stacktrace), domain: [:bandit])
Bandit.HTTPTransport.send_on_error(transport, error)
{:error, error}
Bandit.HTTPTransport.send_on_error(transport, reason)

:erlang.raise(kind, reason, stacktrace)
else
Bandit.HTTPTransport.send_on_error(transport, error)
Bandit.HTTPTransport.send_on_error(transport, reason)
{:ok, transport}
end
end
Expand Down
33 changes: 32 additions & 1 deletion test/bandit/http1/request_test.exs
Original file line number Diff line number Diff line change
Expand Up @@ -140,19 +140,50 @@ defmodule HTTP1RequestTest do
describe "plug error logging" do
test "it should return 500 and log when unknown exceptions are raised", context do
output =
capture_log(fn ->
capture_log([metadata: [:domain]], fn ->
{:ok, response} = Req.get(context.req, url: "/unknown_crasher")
assert response.status == 500
Process.sleep(100)
end)

assert output =~ "(RuntimeError) boom"
assert output =~ "domain=bandit"
end

def unknown_crasher(_conn) do
raise "boom"
end

test "it should return 500 and log when throws", context do
output =
capture_log(fn ->
{:ok, response} = Req.get(context.req, url: "/uncaught_throw")
assert response.status == 500
Process.sleep(100)
end)

assert output =~ "(throw) \"something\""
end

def uncaught_throw(_conn) do
throw "something"
end

test "it should return 500 and log when abnormal exit", context do
output =
capture_log(fn ->
{:ok, response} = Req.get(context.req, url: "/abnormal_exit")
assert response.status == 500
Process.sleep(100)
end)

assert output =~ "(exit) :abnormal"
end

def abnormal_exit(_conn) do
exit(:abnormal)
end

test "it should return the code and not log when known exceptions are raised", context do
output =
capture_log(fn ->
Expand Down
Loading