Only attempt to record an exception if there is an active span. (#37)

There is an edge case, if you use `forward/4` and use Plug.ErrorHandler,
then when an exception reaches the outer router, then Plug.send_resp
will be called, triggering `[:phoenix, :endpoint, :stop]`, and the span
will be gone by the time the outer router gets the exception. This
causes this telemetry handler to crash and be detached.

Sequence of events:
- [:phoenix, :endpoint, :start]
- [:phoenix, :router_dispatch, :exception] (inner router)
- [:phoenix, :endpoint, :stop]
- [:phoenix, :router_dispatch, :exception] (outer router) ** here there is no span, crashes
This commit is contained in:
Derek Kraan 2022-03-18 12:21:26 +01:00 committed by GitHub
parent 563901d516
commit ddb2d3b963
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
2 changed files with 51 additions and 11 deletions

View File

@ -164,21 +164,23 @@ defmodule OpentelemetryPhoenix do
%{kind: kind, reason: reason, stacktrace: stacktrace} = meta, %{kind: kind, reason: reason, stacktrace: stacktrace} = meta,
_config _config
) do ) do
ctx = OpentelemetryTelemetry.set_current_telemetry_span(@tracer_id, meta) if OpenTelemetry.Span.is_recording(OpenTelemetry.Tracer.current_span_ctx()) do
ctx = OpentelemetryTelemetry.set_current_telemetry_span(@tracer_id, meta)
{[reason: reason], attrs} = {[reason: reason], attrs} =
Reason.normalize(reason) Reason.normalize(reason)
|> Keyword.split([:reason]) |> Keyword.split([:reason])
# try to normalize all errors to Elixir exceptions # try to normalize all errors to Elixir exceptions
exception = Exception.normalize(kind, reason, stacktrace) exception = Exception.normalize(kind, reason, stacktrace)
# record exception and mark the span as errored # record exception and mark the span as errored
Span.record_exception(ctx, exception, stacktrace, attrs) Span.record_exception(ctx, exception, stacktrace, attrs)
Span.set_status(ctx, OpenTelemetry.status(:error, "")) Span.set_status(ctx, OpenTelemetry.status(:error, ""))
# do not close the span as endpoint stop will still be called with # do not close the span as endpoint stop will still be called with
# more info, including the status code, which is nil at this stage # more info, including the status code, which is nil at this stage
end
end end
defp http_flavor({_adapter_name, meta}) do defp http_flavor({_adapter_name, meta}) do

View File

@ -167,6 +167,44 @@ defmodule OpentelemetryPhoenixTest do
Map.keys(:otel_attributes.map(event_attributes)) Map.keys(:otel_attributes.map(event_attributes))
end end
test "records exceptions for nested Phoenix routers" do
OpentelemetryPhoenix.setup()
:telemetry.execute(
[:phoenix, :endpoint, :start],
%{system_time: System.system_time()},
Meta.endpoint_start(:exception)
)
:telemetry.execute(
[:phoenix, :router_dispatch, :start],
%{system_time: System.system_time()},
Meta.router_dispatch_start(:exception)
)
:telemetry.execute(
[:phoenix, :router_dispatch, :exception],
%{duration: 222},
Meta.router_dispatch_exception(:normal)
)
:telemetry.execute(
[:phoenix, :endpoint, :stop],
%{duration: 444},
Meta.endpoint_stop(:exception)
)
:telemetry.execute(
[:phoenix, :router_dispatch, :exception],
%{duration: 222},
Meta.router_dispatch_exception(:normal)
)
assert_receive {:span, _}
assert [_ | _] = :telemetry.list_handlers([:phoenix, :router_dispatch, :exception])
end
test "records exceptions for Phoenix web requests with plug wrappers" do test "records exceptions for Phoenix web requests with plug wrappers" do
OpentelemetryPhoenix.setup() OpentelemetryPhoenix.setup()