2021-09-12 13:49:24 -06:00
|
|
|
defmodule OpentelemetryPhoenix do
|
2023-01-06 13:46:06 -07:00
|
|
|
@options_schema NimbleOptions.new!(
|
|
|
|
endpoint_prefix: [
|
|
|
|
type: {:list, :atom},
|
|
|
|
default: [:phoenix, :endpoint],
|
|
|
|
doc: "The endpoint prefix in your endpoint."
|
|
|
|
],
|
|
|
|
adapter: [
|
|
|
|
type: {:in, [:cowboy2, nil]},
|
|
|
|
default: nil,
|
|
|
|
doc: "The phoenix server adapter being used.",
|
|
|
|
type_doc: ":atom"
|
|
|
|
]
|
|
|
|
)
|
|
|
|
|
2021-09-12 13:49:24 -06:00
|
|
|
@moduledoc """
|
|
|
|
OpentelemetryPhoenix uses [telemetry](https://hexdocs.pm/telemetry/) handlers to create `OpenTelemetry` spans.
|
|
|
|
|
|
|
|
Current events which are supported include endpoint start/stop, router start/stop,
|
|
|
|
and router exceptions.
|
|
|
|
|
2023-01-06 13:46:06 -07:00
|
|
|
### Supported options
|
|
|
|
#{NimbleOptions.docs(@options_schema)}
|
|
|
|
|
|
|
|
If you are using PlugCowboy as your adapter you can add `:opentelemetry_cowboy` to your project
|
|
|
|
and pass the `:adapter` option when calling setup. Setting this option will prevent a new
|
|
|
|
span from being started and the existing cowboy span to be continued. This is the recommended
|
|
|
|
setup for measuring accurate latencies.
|
|
|
|
|
|
|
|
`Bandit.PhoenixAdapter` is not currently supported.
|
|
|
|
|
2021-09-12 13:49:24 -06:00
|
|
|
## Usage
|
|
|
|
|
|
|
|
In your application start:
|
|
|
|
|
|
|
|
def start(_type, _args) do
|
2023-01-06 13:46:06 -07:00
|
|
|
:opentelemetry_cowboy.setup()
|
|
|
|
OpentelemetryPhoenix.setup(adapter: :cowboy2)
|
2021-09-12 13:49:24 -06:00
|
|
|
|
|
|
|
children = [
|
|
|
|
{Phoenix.PubSub, name: MyApp.PubSub},
|
|
|
|
MyAppWeb.Endpoint
|
|
|
|
]
|
|
|
|
|
|
|
|
opts = [strategy: :one_for_one, name: MyStore.Supervisor]
|
|
|
|
Supervisor.start_link(children, opts)
|
|
|
|
end
|
|
|
|
|
|
|
|
"""
|
2023-01-06 13:46:06 -07:00
|
|
|
require OpenTelemetry.Tracer
|
2022-12-12 15:51:54 -05:00
|
|
|
alias OpenTelemetry.SemanticConventions
|
2023-01-06 13:46:06 -07:00
|
|
|
alias OpenTelemetry.Tracer
|
2021-09-12 13:49:24 -06:00
|
|
|
alias OpentelemetryPhoenix.Reason
|
|
|
|
|
2022-12-12 15:51:54 -05:00
|
|
|
require SemanticConventions.Trace
|
|
|
|
require OpenTelemetry.Tracer
|
|
|
|
|
2021-12-28 16:39:06 -07:00
|
|
|
@tracer_id __MODULE__
|
2021-09-12 13:49:24 -06:00
|
|
|
|
|
|
|
@typedoc "Setup options"
|
2023-01-06 13:46:06 -07:00
|
|
|
@type opts :: [endpoint_prefix() | adapter()]
|
2021-09-12 13:49:24 -06:00
|
|
|
|
|
|
|
@typedoc "The endpoint prefix in your endpoint. Defaults to `[:phoenix, :endpoint]`"
|
|
|
|
@type endpoint_prefix :: {:endpoint_prefix, [atom()]}
|
|
|
|
|
2023-01-06 13:46:06 -07:00
|
|
|
@typedoc "The phoenix server adapter being used. Optional"
|
|
|
|
@type adapter :: {:adapter, :cowboy2 | term()}
|
|
|
|
|
2021-09-12 13:49:24 -06:00
|
|
|
@doc """
|
|
|
|
Initializes and configures the telemetry handlers.
|
|
|
|
"""
|
|
|
|
@spec setup(opts()) :: :ok
|
|
|
|
def setup(opts \\ []) do
|
2023-01-06 13:46:06 -07:00
|
|
|
opts = NimbleOptions.validate!(opts, @options_schema)
|
2021-09-12 13:49:24 -06:00
|
|
|
|
|
|
|
attach_endpoint_start_handler(opts)
|
|
|
|
attach_endpoint_stop_handler(opts)
|
|
|
|
attach_router_start_handler()
|
|
|
|
attach_router_dispatch_exception_handler()
|
|
|
|
|
|
|
|
:ok
|
|
|
|
end
|
|
|
|
|
|
|
|
@doc false
|
|
|
|
def attach_endpoint_start_handler(opts) do
|
|
|
|
:telemetry.attach(
|
|
|
|
{__MODULE__, :endpoint_start},
|
|
|
|
opts[:endpoint_prefix] ++ [:start],
|
|
|
|
&__MODULE__.handle_endpoint_start/4,
|
2023-01-06 13:46:06 -07:00
|
|
|
%{adapter: opts[:adapter]}
|
2021-09-12 13:49:24 -06:00
|
|
|
)
|
|
|
|
end
|
|
|
|
|
|
|
|
@doc false
|
|
|
|
def attach_endpoint_stop_handler(opts) do
|
|
|
|
:telemetry.attach(
|
|
|
|
{__MODULE__, :endpoint_stop},
|
|
|
|
opts[:endpoint_prefix] ++ [:stop],
|
|
|
|
&__MODULE__.handle_endpoint_stop/4,
|
2023-01-06 13:46:06 -07:00
|
|
|
%{adapter: opts[:adapter]}
|
2021-09-12 13:49:24 -06:00
|
|
|
)
|
|
|
|
end
|
|
|
|
|
|
|
|
@doc false
|
|
|
|
def attach_router_start_handler do
|
|
|
|
:telemetry.attach(
|
|
|
|
{__MODULE__, :router_dispatch_start},
|
|
|
|
[:phoenix, :router_dispatch, :start],
|
|
|
|
&__MODULE__.handle_router_dispatch_start/4,
|
|
|
|
%{}
|
|
|
|
)
|
|
|
|
end
|
|
|
|
|
|
|
|
@doc false
|
|
|
|
def attach_router_dispatch_exception_handler do
|
|
|
|
:telemetry.attach(
|
|
|
|
{__MODULE__, :router_dispatch_exception},
|
|
|
|
[:phoenix, :router_dispatch, :exception],
|
|
|
|
&__MODULE__.handle_router_dispatch_exception/4,
|
|
|
|
%{}
|
|
|
|
)
|
|
|
|
end
|
|
|
|
|
|
|
|
@doc false
|
2023-01-06 13:46:06 -07:00
|
|
|
def handle_endpoint_start(_event, _measurements, meta, config) do
|
|
|
|
Process.put({:otel_phoenix, :adapter}, config.adapter)
|
|
|
|
|
|
|
|
case adapter() do
|
|
|
|
:cowboy2 ->
|
|
|
|
cowboy2_start()
|
|
|
|
|
|
|
|
_ ->
|
|
|
|
default_start(meta)
|
|
|
|
end
|
|
|
|
end
|
|
|
|
|
|
|
|
defp cowboy2_start do
|
|
|
|
OpentelemetryProcessPropagator.fetch_parent_ctx()
|
|
|
|
|> OpenTelemetry.Ctx.attach()
|
|
|
|
end
|
|
|
|
|
|
|
|
defp default_start(meta) do
|
|
|
|
%{conn: conn} = meta
|
2021-10-13 21:11:26 -06:00
|
|
|
:otel_propagator_text_map.extract(conn.req_headers)
|
2021-09-12 13:49:24 -06:00
|
|
|
|
|
|
|
peer_data = Plug.Conn.get_peer_data(conn)
|
|
|
|
|
|
|
|
user_agent = header_value(conn, "user-agent")
|
|
|
|
peer_ip = Map.get(peer_data, :address)
|
|
|
|
|
2021-12-28 16:39:06 -07:00
|
|
|
attributes = %{
|
2022-12-12 15:51:54 -05:00
|
|
|
SemanticConventions.Trace.http_client_ip() => client_ip(conn),
|
2023-01-06 13:46:06 -07:00
|
|
|
SemanticConventions.Trace.http_flavor() => http_flavor(conn.adapter),
|
2022-12-12 15:51:54 -05:00
|
|
|
SemanticConventions.Trace.http_method() => conn.method,
|
|
|
|
SemanticConventions.Trace.http_scheme() => "#{conn.scheme}",
|
|
|
|
SemanticConventions.Trace.http_target() => conn.request_path,
|
|
|
|
SemanticConventions.Trace.http_user_agent() => user_agent,
|
|
|
|
SemanticConventions.Trace.net_host_name() => conn.host,
|
|
|
|
SemanticConventions.Trace.net_sock_host_addr() => to_string(:inet_parse.ntoa(conn.remote_ip)),
|
|
|
|
SemanticConventions.Trace.net_host_port() => conn.port,
|
|
|
|
SemanticConventions.Trace.net_sock_peer_addr() => to_string(:inet_parse.ntoa(peer_ip)),
|
|
|
|
SemanticConventions.Trace.net_peer_port() => peer_data.port,
|
|
|
|
SemanticConventions.Trace.net_transport() => :"IP.TCP"
|
2021-12-28 16:39:06 -07:00
|
|
|
}
|
2021-09-12 13:49:24 -06:00
|
|
|
|
|
|
|
# start the span with a default name. Route name isn't known until router dispatch
|
2021-12-17 17:16:26 +01:00
|
|
|
OpentelemetryTelemetry.start_telemetry_span(@tracer_id, "HTTP #{conn.method}", meta, %{
|
|
|
|
kind: :server,
|
|
|
|
attributes: attributes
|
|
|
|
})
|
2021-09-12 13:49:24 -06:00
|
|
|
end
|
|
|
|
|
|
|
|
@doc false
|
2023-01-06 13:46:06 -07:00
|
|
|
def handle_endpoint_stop(_event, _measurements, meta, _config) do
|
|
|
|
case adapter() do
|
|
|
|
:cowboy2 ->
|
|
|
|
:ok
|
|
|
|
|
|
|
|
_ ->
|
|
|
|
default_stop(meta)
|
|
|
|
end
|
|
|
|
end
|
|
|
|
|
|
|
|
defp default_stop(meta) do
|
|
|
|
%{conn: conn} = meta
|
|
|
|
|
2021-09-12 13:49:24 -06:00
|
|
|
# ensure the correct span is current and update the status
|
2023-01-06 13:46:06 -07:00
|
|
|
OpentelemetryTelemetry.set_current_telemetry_span(@tracer_id, meta)
|
2021-09-12 13:49:24 -06:00
|
|
|
|
2023-01-06 13:46:06 -07:00
|
|
|
Tracer.set_attribute(SemanticConventions.Trace.http_status_code(), conn.status)
|
2021-09-12 13:49:24 -06:00
|
|
|
|
2022-06-03 10:54:37 -06:00
|
|
|
if conn.status >= 500 do
|
2023-01-06 13:46:06 -07:00
|
|
|
Tracer.set_status(OpenTelemetry.status(:error, ""))
|
2021-09-12 13:49:24 -06:00
|
|
|
end
|
|
|
|
|
|
|
|
# end the Phoenix span
|
|
|
|
OpentelemetryTelemetry.end_telemetry_span(@tracer_id, meta)
|
|
|
|
end
|
|
|
|
|
|
|
|
@doc false
|
|
|
|
def handle_router_dispatch_start(_event, _measurements, meta, _config) do
|
2021-12-28 16:39:06 -07:00
|
|
|
attributes = %{
|
2022-12-12 15:51:54 -05:00
|
|
|
:"phoenix.plug" => meta.plug,
|
|
|
|
:"phoenix.action" => meta.plug_opts,
|
|
|
|
SemanticConventions.Trace.http_route() => meta.route
|
2021-12-28 16:39:06 -07:00
|
|
|
}
|
2021-09-12 13:49:24 -06:00
|
|
|
|
2023-01-06 13:46:06 -07:00
|
|
|
Tracer.update_name("#{meta.route}")
|
|
|
|
Tracer.set_attributes(attributes)
|
2021-09-12 13:49:24 -06:00
|
|
|
end
|
|
|
|
|
|
|
|
@doc false
|
|
|
|
def handle_router_dispatch_exception(
|
|
|
|
_event,
|
|
|
|
_measurements,
|
2023-01-06 13:46:06 -07:00
|
|
|
%{kind: kind, reason: reason, stacktrace: stacktrace},
|
2021-09-12 13:49:24 -06:00
|
|
|
_config
|
|
|
|
) do
|
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 12:21:26 +01:00
|
|
|
if OpenTelemetry.Span.is_recording(OpenTelemetry.Tracer.current_span_ctx()) do
|
|
|
|
{[reason: reason], attrs} =
|
|
|
|
Reason.normalize(reason)
|
|
|
|
|> Keyword.split([:reason])
|
2021-09-12 13:49:24 -06:00
|
|
|
|
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 12:21:26 +01:00
|
|
|
# try to normalize all errors to Elixir exceptions
|
|
|
|
exception = Exception.normalize(kind, reason, stacktrace)
|
2021-09-12 13:49:24 -06:00
|
|
|
|
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 12:21:26 +01:00
|
|
|
# record exception and mark the span as errored
|
2023-01-06 13:46:06 -07:00
|
|
|
Tracer.record_exception(exception, stacktrace, attrs)
|
|
|
|
Tracer.set_status(OpenTelemetry.status(:error, ""))
|
2021-09-12 13:49:24 -06:00
|
|
|
|
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 12:21:26 +01:00
|
|
|
# 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
|
|
|
|
end
|
2021-09-12 13:49:24 -06:00
|
|
|
end
|
|
|
|
|
|
|
|
defp http_flavor({_adapter_name, meta}) do
|
|
|
|
case Map.get(meta, :version) do
|
|
|
|
:"HTTP/1.0" -> :"1.0"
|
|
|
|
:"HTTP/1.1" -> :"1.1"
|
|
|
|
:"HTTP/2.0" -> :"2.0"
|
|
|
|
:"HTTP/2" -> :"2.0"
|
|
|
|
:SPDY -> :SPDY
|
|
|
|
:QUIC -> :QUIC
|
|
|
|
nil -> ""
|
|
|
|
end
|
|
|
|
end
|
|
|
|
|
|
|
|
defp client_ip(%{remote_ip: remote_ip} = conn) do
|
|
|
|
case header_value(conn, "x-forwarded-for") do
|
|
|
|
"" ->
|
|
|
|
remote_ip
|
|
|
|
|> :inet_parse.ntoa()
|
|
|
|
|> to_string()
|
|
|
|
|
|
|
|
ip_address ->
|
|
|
|
ip_address
|
|
|
|
|> String.split(",", parts: 2)
|
|
|
|
|> List.first()
|
|
|
|
end
|
|
|
|
end
|
|
|
|
|
|
|
|
defp header_value(conn, header) do
|
|
|
|
case Plug.Conn.get_req_header(conn, header) do
|
|
|
|
[] ->
|
|
|
|
""
|
|
|
|
|
|
|
|
[value | _] ->
|
|
|
|
value
|
|
|
|
end
|
|
|
|
end
|
2023-01-06 13:46:06 -07:00
|
|
|
|
|
|
|
defp adapter do
|
|
|
|
Process.get({:otel_phoenix, :adapter})
|
|
|
|
end
|
2021-09-12 13:49:24 -06:00
|
|
|
end
|