2021-09-12 19:49:24 +00:00
|
|
|
defmodule OpentelemetryPhoenixTest do
|
|
|
|
use ExUnit.Case, async: false
|
|
|
|
doctest OpentelemetryPhoenix
|
|
|
|
|
|
|
|
require OpenTelemetry.Tracer
|
|
|
|
require OpenTelemetry.Span
|
|
|
|
require Record
|
|
|
|
|
|
|
|
alias PhoenixMeta, as: Meta
|
|
|
|
|
|
|
|
for {name, spec} <- Record.extract_all(from_lib: "opentelemetry/include/otel_span.hrl") do
|
|
|
|
Record.defrecord(name, spec)
|
|
|
|
end
|
|
|
|
|
|
|
|
for {name, spec} <- Record.extract_all(from_lib: "opentelemetry_api/include/opentelemetry.hrl") do
|
|
|
|
Record.defrecord(name, spec)
|
|
|
|
end
|
|
|
|
|
|
|
|
setup do
|
2022-03-24 17:48:59 +00:00
|
|
|
:otel_simple_processor.set_exporter(:otel_exporter_pid, self())
|
2021-09-12 19:49:24 +00:00
|
|
|
|
|
|
|
:ok
|
|
|
|
end
|
|
|
|
|
|
|
|
test "records spans for Phoenix web requests" do
|
|
|
|
OpentelemetryPhoenix.setup()
|
|
|
|
|
|
|
|
:telemetry.execute(
|
|
|
|
[:phoenix, :endpoint, :start],
|
|
|
|
%{system_time: System.system_time()},
|
|
|
|
Meta.endpoint_start()
|
|
|
|
)
|
|
|
|
|
|
|
|
:telemetry.execute(
|
|
|
|
[:phoenix, :router_dispatch, :start],
|
|
|
|
%{system_time: System.system_time()},
|
|
|
|
Meta.router_dispatch_start()
|
|
|
|
)
|
|
|
|
|
|
|
|
:telemetry.execute(
|
|
|
|
[:phoenix, :endpoint, :stop],
|
|
|
|
%{duration: 444},
|
|
|
|
Meta.endpoint_stop()
|
|
|
|
)
|
|
|
|
|
|
|
|
assert_receive {:span,
|
|
|
|
span(
|
|
|
|
name: "/users/:user_id",
|
2021-12-28 23:39:06 +00:00
|
|
|
attributes: attributes,
|
2021-09-12 19:49:24 +00:00
|
|
|
parent_span_id: 13_235_353_014_750_950_193
|
|
|
|
)}
|
|
|
|
|
2021-12-28 23:39:06 +00:00
|
|
|
assert %{
|
2021-09-12 19:49:24 +00:00
|
|
|
"http.client_ip": "10.211.55.2",
|
|
|
|
"http.flavor": :"1.1",
|
2022-12-12 20:51:54 +00:00
|
|
|
"net.host.name": "localhost",
|
2021-09-12 19:49:24 +00:00
|
|
|
"http.method": "GET",
|
|
|
|
"http.route": "/users/:user_id",
|
|
|
|
"http.scheme": "http",
|
2021-11-19 14:15:43 +00:00
|
|
|
"http.status_code": 200,
|
2021-09-12 19:49:24 +00:00
|
|
|
"http.target": "/users/123",
|
|
|
|
"http.user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:81.0) Gecko/20100101 Firefox/81.0",
|
2022-12-12 20:51:54 +00:00
|
|
|
"net.sock.host.addr": "10.211.55.2",
|
2021-09-12 19:49:24 +00:00
|
|
|
"net.host.port": 4000,
|
2022-12-12 20:51:54 +00:00
|
|
|
"net.sock.peer.addr": "10.211.55.2",
|
2021-09-12 19:49:24 +00:00
|
|
|
"net.peer.port": 64291,
|
|
|
|
"net.transport": :"IP.TCP",
|
|
|
|
"phoenix.action": :user,
|
|
|
|
"phoenix.plug": Elixir.MyStoreWeb.PageController
|
2021-12-28 23:39:06 +00:00
|
|
|
} == :otel_attributes.map(attributes)
|
2021-09-12 19:49:24 +00:00
|
|
|
end
|
|
|
|
|
|
|
|
test "parses x-forwarded-for with single value" do
|
|
|
|
OpentelemetryPhoenix.setup()
|
|
|
|
|
|
|
|
x_forwarded_for_request("203.0.113.195")
|
|
|
|
|
2021-12-28 23:39:06 +00:00
|
|
|
assert_receive {:span, span(attributes: attributes)}
|
2021-09-12 19:49:24 +00:00
|
|
|
|
2021-12-28 23:39:06 +00:00
|
|
|
assert Map.fetch!(:otel_attributes.map(attributes), :"http.client_ip") == "203.0.113.195"
|
2021-09-12 19:49:24 +00:00
|
|
|
end
|
|
|
|
|
|
|
|
test "parses x-forwarded-for with multiple values" do
|
|
|
|
OpentelemetryPhoenix.setup()
|
|
|
|
|
|
|
|
x_forwarded_for_request("203.0.113.195, 70.41.3.18, 150.172.238.178")
|
|
|
|
|
2021-12-28 23:39:06 +00:00
|
|
|
assert_receive {:span, span(attributes: attributes)}
|
2021-09-12 19:49:24 +00:00
|
|
|
|
2021-12-28 23:39:06 +00:00
|
|
|
assert Map.fetch!(:otel_attributes.map(attributes), :"http.client_ip") == "203.0.113.195"
|
2021-09-12 19:49:24 +00:00
|
|
|
end
|
|
|
|
|
|
|
|
test "records exceptions for Phoenix web requests" 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)
|
|
|
|
)
|
|
|
|
|
|
|
|
expected_status = OpenTelemetry.status(:error, "")
|
|
|
|
|
|
|
|
assert_receive {:span,
|
|
|
|
span(
|
|
|
|
name: "/users/:user_id/exception",
|
2021-12-28 23:39:06 +00:00
|
|
|
attributes: attributes,
|
2021-09-12 19:49:24 +00:00
|
|
|
kind: :server,
|
2021-12-28 23:39:06 +00:00
|
|
|
events: events,
|
2021-09-12 19:49:24 +00:00
|
|
|
parent_span_id: 13_235_353_014_750_950_193,
|
|
|
|
status: ^expected_status
|
|
|
|
)}
|
|
|
|
|
2021-12-28 23:39:06 +00:00
|
|
|
assert %{
|
2021-09-12 19:49:24 +00:00
|
|
|
"http.client_ip": "10.211.55.2",
|
|
|
|
"http.flavor": :"1.1",
|
2022-12-12 20:51:54 +00:00
|
|
|
"net.host.name": "localhost",
|
2021-09-12 19:49:24 +00:00
|
|
|
"http.method": "GET",
|
|
|
|
"http.route": "/users/:user_id/exception",
|
|
|
|
"http.scheme": "http",
|
2021-11-19 14:15:43 +00:00
|
|
|
"http.status_code": 500,
|
2021-09-12 19:49:24 +00:00
|
|
|
"http.target": "/users/123/exception",
|
|
|
|
"http.user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:81.0) Gecko/20100101 Firefox/81.0",
|
2022-12-12 20:51:54 +00:00
|
|
|
"net.sock.host.addr": "10.211.55.2",
|
2021-09-12 19:49:24 +00:00
|
|
|
"net.host.port": 4000,
|
2022-12-12 20:51:54 +00:00
|
|
|
"net.sock.peer.addr": "10.211.55.2",
|
2021-09-12 19:49:24 +00:00
|
|
|
"net.peer.port": 64291,
|
|
|
|
"net.transport": :"IP.TCP",
|
|
|
|
"phoenix.action": :code_exception,
|
|
|
|
"phoenix.plug": MyStoreWeb.PageController
|
2021-12-28 23:39:06 +00:00
|
|
|
} == :otel_attributes.map(attributes)
|
|
|
|
|
|
|
|
[
|
|
|
|
event(
|
|
|
|
name: "exception",
|
|
|
|
attributes: event_attributes
|
|
|
|
)
|
|
|
|
] = :otel_events.list(events)
|
|
|
|
|
|
|
|
assert [:key, :map, "exception.message", "exception.stacktrace", "exception.type"] ==
|
|
|
|
Map.keys(:otel_attributes.map(event_attributes))
|
2021-09-12 19:49:24 +00:00
|
|
|
end
|
|
|
|
|
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
2022-03-18 11:21:26 +00:00
|
|
|
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
|
|
|
|
|
2021-09-12 19:49:24 +00:00
|
|
|
test "records exceptions for Phoenix web requests with plug wrappers" 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(:plug_wrapper)
|
|
|
|
)
|
|
|
|
|
|
|
|
:telemetry.execute(
|
|
|
|
[:phoenix, :endpoint, :stop],
|
|
|
|
%{duration: 444},
|
|
|
|
Meta.endpoint_stop(:exception)
|
|
|
|
)
|
|
|
|
|
|
|
|
expected_status = OpenTelemetry.status(:error, "")
|
|
|
|
|
|
|
|
assert_receive {:span,
|
|
|
|
span(
|
|
|
|
name: "/users/:user_id/exception",
|
2021-12-28 23:39:06 +00:00
|
|
|
attributes: attributes,
|
2021-09-12 19:49:24 +00:00
|
|
|
kind: :server,
|
2021-12-28 23:39:06 +00:00
|
|
|
events: events,
|
2021-09-12 19:49:24 +00:00
|
|
|
parent_span_id: 13_235_353_014_750_950_193,
|
|
|
|
status: ^expected_status
|
|
|
|
)}
|
|
|
|
|
2021-12-28 23:39:06 +00:00
|
|
|
assert %{
|
2021-09-12 19:49:24 +00:00
|
|
|
"http.client_ip": "10.211.55.2",
|
|
|
|
"http.flavor": :"1.1",
|
2022-12-12 20:51:54 +00:00
|
|
|
"net.host.name": "localhost",
|
2021-09-12 19:49:24 +00:00
|
|
|
"http.method": "GET",
|
|
|
|
"http.route": "/users/:user_id/exception",
|
|
|
|
"http.scheme": "http",
|
2021-11-19 14:15:43 +00:00
|
|
|
"http.status_code": 500,
|
2021-09-12 19:49:24 +00:00
|
|
|
"http.target": "/users/123/exception",
|
|
|
|
"http.user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:81.0) Gecko/20100101 Firefox/81.0",
|
2022-12-12 20:51:54 +00:00
|
|
|
"net.sock.host.addr": "10.211.55.2",
|
2021-09-12 19:49:24 +00:00
|
|
|
"net.host.port": 4000,
|
2022-12-12 20:51:54 +00:00
|
|
|
"net.sock.peer.addr": "10.211.55.2",
|
2021-09-12 19:49:24 +00:00
|
|
|
"net.peer.port": 64291,
|
|
|
|
"net.transport": :"IP.TCP",
|
|
|
|
"phoenix.action": :code_exception,
|
|
|
|
"phoenix.plug": MyStoreWeb.PageController
|
2021-12-28 23:39:06 +00:00
|
|
|
} == :otel_attributes.map(attributes)
|
|
|
|
|
|
|
|
[
|
|
|
|
event(
|
|
|
|
name: "exception",
|
|
|
|
attributes: event_attributes
|
|
|
|
)
|
|
|
|
] = :otel_events.list(events)
|
|
|
|
|
|
|
|
assert ["exception.message", "exception.stacktrace", "exception.type"] ==
|
|
|
|
Map.keys(:otel_attributes.map(event_attributes))
|
2021-09-12 19:49:24 +00:00
|
|
|
end
|
|
|
|
|
|
|
|
defp x_forwarded_for_request(x_forwarded_for) do
|
|
|
|
meta = Meta.endpoint_start()
|
|
|
|
|
|
|
|
meta = %{
|
|
|
|
meta
|
|
|
|
| conn: %{
|
|
|
|
meta.conn
|
|
|
|
| req_headers: [{"x-forwarded-for", x_forwarded_for} | meta.conn.req_headers]
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
:telemetry.execute(
|
|
|
|
[:phoenix, :endpoint, :start],
|
|
|
|
%{system_time: System.system_time()},
|
|
|
|
meta
|
|
|
|
)
|
|
|
|
|
|
|
|
:telemetry.execute(
|
|
|
|
[:phoenix, :endpoint, :stop],
|
|
|
|
%{duration: 444},
|
|
|
|
Meta.endpoint_stop()
|
|
|
|
)
|
|
|
|
end
|
|
|
|
end
|