use router dispatch start events to update name of span (#4)

* use router dispatch start events to update name of span * remove event_prefix from setup args * remove event_prefix from handler identifiers * upgrade to plug 1.10.1 for the router events * mix format * don't crash handler if :start skipped If one of our user's tests don't call through a `Plug.Conn.Adapter` that calls `:telemetry.execute/4` with a `[:plug_adapter, :call, :start]` event as expected, our handler will crash out loudly when their router calls `:telemetry.execute/4` with `[:plug, :router_dispatch, :start]` or `[:phoenix, :router_dispatch, :start]` if we don't take care to avoid calling `OpenTelemetry.Span.set_attribute/2` when the span context is `:undefined`. * repair test Make requests through `Plug.Cowboy` to ensure the necessary `[:plug_adapter, :call, :start]` event, taking necessary dependencies on `hackney`, `plug`, and `plug_cowboy`. Smells more of an integration test, but gets the job done. * use safe means to get peer data closes #6 Co-authored-by: Tristan Sloughter <[email protected]>
opentelemetry-beam · Jun 8, 2020 · c22a40e · c22a40e
1 parent ddbf6e1
commit c22a40e
Show file tree

Hide file tree

Showing 6 changed files with 138 additions and 57 deletions.
diff --git a/.formatter.exs b/.formatter.exs
@@ -1,4 +1,5 @@
 # Used by "mix format"
 [
+  import_deps: [:plug],
   inputs: ["{mix,.formatter}.exs", "{config,lib,test}/**/*.{ex,exs}"]
 ]
diff --git a/lib/opentelemetry_plug.ex b/lib/opentelemetry_plug.ex
@@ -12,7 +12,7 @@ defmodule OpentelemetryPlug do
 
   Example:
 
-      OpentelemetryPlug.setup([:my, :plug])
+      OpentelemetryPlug.setup([])
 
   You may also supply the following options in the second argument:
 
@@ -23,78 +23,112 @@ defmodule OpentelemetryPlug do
       defaults to the concatenation of the event name with periods, e.g.
       `"my.plug.start"`.
   """
-  def setup(event_prefix, config \\ []) do
+  def setup(config \\ []) do
     # register the tracer. just re-registers if called for multiple repos
     _ = OpenTelemetry.register_application_tracer(:opentelemetry_plug)
 
-    :telemetry.attach({__MODULE__, {event_prefix, :opentelemetry_plug_tracer_start}},
-      event_prefix ++ [:start],
+    :telemetry.attach(
+      {__MODULE__, :phoenix_tracer_router_start},
+      [:phoenix, :router_dispatch, :start],
+      &__MODULE__.handle_route/4,
+      config
+    )
+
+    :telemetry.attach(
+      {__MODULE__, :plug_tracer_router_start},
+      [:plug, :router_dispatch, :start],
+      &__MODULE__.handle_route/4,
+      config
+    )
+
+    :telemetry.attach(
+      {__MODULE__, :plug_tracer_start},
+      [:plug_adapter, :call, :start],
       &__MODULE__.handle_start/4,
-      config)
+      config
+    )
 
-    :telemetry.attach({__MODULE__, {event_prefix, :opentelemetry_plug_tracer_stop}},
-      event_prefix ++ [:stop],
+    :telemetry.attach(
+      {__MODULE__, :plug_tracer_stop},
+      [:plug_adapter, :call, :stop],
       &__MODULE__.handle_stop/4,
-      config)
+      config
+    )
 
-    :telemetry.attach({__MODULE__, {event_prefix, :opentelemetry_plug_tracer_exception}},
-      event_prefix ++ [:exception],
+    :telemetry.attach(
+      {__MODULE__, :plug_tracer_exception},
+      [:plug_adapter, :call, :exception],
       &__MODULE__.handle_exception/4,
-      config)
+      config
+    )
   end
 
   @doc false
   def handle_start(_, _measurements, %{conn: conn}, _config) do
+    # TODO: add config for what paths are traced
+
     # setup OpenTelemetry context based on request headers
     :ot_propagation.http_extract(conn.req_headers)
 
-    # TODO: add config option to allow `conn.request_path` as span name
-    span_name = case Map.get(conn.private, :plug_route) do
-                  nil ->
-                    "HTTP " <> conn.method
-                  {route, _fun} ->
-                    route
-                end
-
-    {_, adapter} = conn.adapter
+    span_name = "HTTP " <> conn.method
+
+    peer_data = Plug.Conn.get_peer_data(conn)
+
     user_agent = header_or_empty(conn, "User-Agent")
     host = header_or_empty(conn, "Host")
-    peer_ip = Map.get(Map.get(adapter, :peer_data), :address)
-
-    attributes = [{"http.target", conn.request_path},
-                  {"http.host",  conn.host},
-                  {"http.scheme",  conn.scheme},
-                  {"http.user_agent", user_agent},
-                  {"http.method", conn.method},
-                  {"net.peer.ip", to_string(:inet_parse.ntoa(peer_ip))},
-                  {"net.peer.port", adapter.peer_data.port},
-                  {"net.peer.name", host},
-                  {"net.transport", "IP.TCP"},
-                  {"net.host.ip", to_string(:inet_parse.ntoa(conn.remote_ip))},
-                  {"net.host.port", conn.port} | optional_attributes(conn)
-                  # {"net.host.name", HostName}
-                 ]
+    peer_ip = Map.get(peer_data, :address)
+
+    attributes = [
+      {"http.target", conn.request_path},
+      {"http.host", conn.host},
+      {"http.scheme", conn.scheme},
+      {"http.user_agent", user_agent},
+      {"http.method", conn.method},
+      {"net.peer.ip", to_string(:inet_parse.ntoa(peer_ip))},
+      {"net.peer.port", peer_data.port},
+      {"net.peer.name", host},
+      {"net.transport", "IP.TCP"},
+      {"net.host.ip", to_string(:inet_parse.ntoa(conn.remote_ip))},
+      {"net.host.port", conn.port} | optional_attributes(conn)
+      # {"net.host.name", HostName}
+    ]
+
     # TODO: Plug should provide a monotonic native time in measurements to use here
     # for the `start_time` option
     OpenTelemetry.Tracer.start_span(span_name, %{attributes: attributes})
   end
 
+  @doc false
+  def handle_route(_, _measurements, %{route: route}, _config) do
+    # TODO: add config option to allow `conn.request_path` as span name
+    if in_span?() do
+      OpenTelemetry.Span.update_name(route)
+    end
+  end
+
   @doc false
   def handle_stop(_, _measurements, %{conn: conn}, _config) do
-    OpenTelemetry.Span.set_attribute("http.status", conn.status)
-    OpenTelemetry.Tracer.end_span()
+    if in_span?() do
+      OpenTelemetry.Span.set_attribute("http.status", conn.status)
+      OpenTelemetry.Tracer.end_span()
+    end
   end
 
   @doc false
   def handle_exception(_, _measurements, %{conn: _conn}, _config) do
-    OpenTelemetry.Span.set_status(OpenTelemetry.status('UnknownError', "unknown error"))
-    OpenTelemetry.Tracer.end_span()
+    if in_span?() do
+      OpenTelemetry.Span.set_status(OpenTelemetry.status('UnknownError', "unknown error"))
+      OpenTelemetry.Tracer.end_span()
+    end
   end
 
+  defp in_span?, do: OpenTelemetry.Tracer.current_ctx() != :undefined
+
   defp header_or_empty(conn, header) do
     case Plug.Conn.get_req_header(conn, header) do
       [] ->
         ""
+
       [host | _] ->
         host
     end
@@ -103,21 +137,25 @@ defmodule OpentelemetryPlug do
   defp optional_attributes(conn) do
     # for some reason Elixir removed Enum.filter_map in 1.5
     # so just using Erlang's list module
-    :lists.filtermap(fn({attr, fun}) ->
-      case fun.(conn) do
-        nil ->
-          false;
-        value ->
-          {true, {attr, value}}
-      end
-    end, [{"http.client_ip", &client_ip/1},
-          {"http.server_name", &server_name/1}])
+    :lists.filtermap(
+      fn {attr, fun} ->
+        case fun.(conn) do
+          nil ->
+            false
+
+          value ->
+            {true, {attr, value}}
+        end
+      end,
+      [{"http.client_ip", &client_ip/1}, {"http.server_name", &server_name/1}]
+    )
   end
 
   defp client_ip(conn) do
     case Plug.Conn.get_req_header(conn, "X-Forwarded-For") do
       [] ->
         nil
+
       [host | _] ->
         host
     end

diff --git a/mix.exs b/mix.exs
@@ -21,9 +21,11 @@ defmodule OpentelemetryPlug.MixProject do
   # Run "mix help deps" to learn about dependencies.
   defp deps do
     [
-      {:plug, "~> 1.10"},
+      {:hackney, "~> 1.0", only: :test, runtime: false},
       {:opentelemetry_api, "~> 0.3"},
       {:opentelemetry, "~> 0.3"},
+      {:plug, "~> 1.10.1"},
+      {:plug_cowboy, "~> 2.2", only: :test, runtime: false},
       {:telemetry, "~> 0.4"}
     ]
   end

diff --git a/mix.lock b/mix.lock
@@ -1,8 +1,20 @@
 %{
+  "certifi": {:hex, :certifi, "2.5.1", "867ce347f7c7d78563450a18a6a28a8090331e77fa02380b4a21962a65d36ee5", [:rebar3], [{:parse_trans, "~>3.3", [hex: :parse_trans, repo: "hexpm", optional: false]}], "hexpm", "805abd97539caf89ec6d4732c91e62ba9da0cda51ac462380bbd28ee697a8c42"},
+  "cowboy": {:hex, :cowboy, "2.7.0", "91ed100138a764355f43316b1d23d7ff6bdb0de4ea618cb5d8677c93a7a2f115", [:rebar3], [{:cowlib, "~> 2.8.0", [hex: :cowlib, repo: "hexpm", optional: false]}, {:ranch, "~> 1.7.1", [hex: :ranch, repo: "hexpm", optional: false]}], "hexpm", "04fd8c6a39edc6aaa9c26123009200fc61f92a3a94f3178c527b70b767c6e605"},
+  "cowlib": {:hex, :cowlib, "2.8.0", "fd0ff1787db84ac415b8211573e9a30a3ebe71b5cbff7f720089972b2319c8a4", [:rebar3], [], "hexpm", "79f954a7021b302186a950a32869dbc185523d99d3e44ce430cd1f3289f41ed4"},
+  "hackney": {:hex, :hackney, "1.15.2", "07e33c794f8f8964ee86cebec1a8ed88db5070e52e904b8f12209773c1036085", [:rebar3], [{:certifi, "2.5.1", [hex: :certifi, repo: "hexpm", optional: false]}, {:idna, "6.0.0", [hex: :idna, repo: "hexpm", optional: false]}, {:metrics, "1.0.1", [hex: :metrics, repo: "hexpm", optional: false]}, {:mimerl, "~>1.1", [hex: :mimerl, repo: "hexpm", optional: false]}, {:ssl_verify_fun, "1.1.5", [hex: :ssl_verify_fun, repo: "hexpm", optional: false]}], "hexpm", "e0100f8ef7d1124222c11ad362c857d3df7cb5f4204054f9f0f4a728666591fc"},
+  "idna": {:hex, :idna, "6.0.0", "689c46cbcdf3524c44d5f3dde8001f364cd7608a99556d8fbd8239a5798d4c10", [:rebar3], [{:unicode_util_compat, "0.4.1", [hex: :unicode_util_compat, repo: "hexpm", optional: false]}], "hexpm", "4bdd305eb64e18b0273864920695cb18d7a2021f31a11b9c5fbcd9a253f936e2"},
+  "metrics": {:hex, :metrics, "1.0.1", "25f094dea2cda98213cecc3aeff09e940299d950904393b2a29d191c346a8486", [:rebar3], [], "hexpm", "69b09adddc4f74a40716ae54d140f93beb0fb8978d8636eaded0c31b6f099f16"},
   "mime": {:hex, :mime, "1.3.1", "30ce04ab3175b6ad0bdce0035cba77bba68b813d523d1aac73d9781b4d193cf8", [:mix], [], "hexpm", "6cbe761d6a0ca5a31a0931bf4c63204bceb64538e664a8ecf784a9a6f3b875f1"},
+  "mimerl": {:hex, :mimerl, "1.2.0", "67e2d3f571088d5cfd3e550c383094b47159f3eee8ffa08e64106cdf5e981be3", [:rebar3], [], "hexpm", "f278585650aa581986264638ebf698f8bb19df297f66ad91b18910dfc6e19323"},
   "opentelemetry": {:hex, :opentelemetry, "0.4.0", "293729f014009b03a1a2c47e6367db6f280b41412faa5639f06dcce9733d18a6", [:rebar3], [{:opentelemetry_api, "~> 0.3.1", [hex: :opentelemetry_api, repo: "hexpm", optional: false]}], "hexpm", "f0eb4281f26879147322b0a6f1c457c57f3f1c4121cbff1f6056e4c98b1647a7"},
   "opentelemetry_api": {:hex, :opentelemetry_api, "0.3.1", "aa042f9ff0b774c3e9827e215fcf972d5cfccd9a79ed55194b58c329a945b486", [:mix, :rebar3], [], "hexpm", "91fc78c521b9fc7f72f47144bb9f0838d57584b1be5bbd3098d8aaf2f2d42686"},
-  "plug": {:hex, :plug, "1.10.0", "6508295cbeb4c654860845fb95260737e4a8838d34d115ad76cd487584e2fc4d", [:mix], [{:mime, "~> 1.0", [hex: :mime, repo: "hexpm", optional: false]}, {:plug_crypto, "~> 1.1.1 or ~> 1.2", [hex: :plug_crypto, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4", [hex: :telemetry, repo: "hexpm", optional: true]}], "hexpm", "422a9727e667be1bf5ab1de03be6fa0ad67b775b2d84ed908f3264415ef29d4a"},
+  "parse_trans": {:hex, :parse_trans, "3.3.0", "09765507a3c7590a784615cfd421d101aec25098d50b89d7aa1d66646bc571c1", [:rebar3], [], "hexpm", "17ef63abde837ad30680ea7f857dd9e7ced9476cdd7b0394432af4bfc241b960"},
+  "plug": {:hex, :plug, "1.10.1", "c56a6d9da7042d581159bcbaef873ba9d87f15dce85420b0d287bca19f40f9bd", [:mix], [{:mime, "~> 1.0", [hex: :mime, repo: "hexpm", optional: false]}, {:plug_crypto, "~> 1.1.1 or ~> 1.2", [hex: :plug_crypto, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4", [hex: :telemetry, repo: "hexpm", optional: true]}], "hexpm", "b5cd52259817eb8a31f2454912ba1cff4990bca7811918878091cb2ab9e52cb8"},
+  "plug_cowboy": {:hex, :plug_cowboy, "2.2.1", "fcf58aa33227a4322a050e4783ee99c63c031a2e7f9a2eb7340d55505e17f30f", [:mix], [{:cowboy, "~> 2.7", [hex: :cowboy, repo: "hexpm", optional: false]}, {:plug, "~> 1.7", [hex: :plug, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "3b43de24460d87c0971887286e7a20d40462e48eb7235954681a20cee25ddeb6"},
   "plug_crypto": {:hex, :plug_crypto, "1.1.2", "bdd187572cc26dbd95b87136290425f2b580a116d3fb1f564216918c9730d227", [:mix], [], "hexpm", "6b8b608f895b6ffcfad49c37c7883e8df98ae19c6a28113b02aa1e9c5b22d6b5"},
+  "ranch": {:hex, :ranch, "1.7.1", "6b1fab51b49196860b733a49c07604465a47bdb78aa10c1c16a3d199f7f8c881", [:rebar3], [], "hexpm", "451d8527787df716d99dc36162fca05934915db0b6141bbdac2ea8d3c7afc7d7"},
+  "ssl_verify_fun": {:hex, :ssl_verify_fun, "1.1.5", "6eaf7ad16cb568bb01753dbbd7a95ff8b91c7979482b95f38443fe2c8852a79b", [:make, :mix, :rebar3], [], "hexpm", "13104d7897e38ed7f044c4de953a6c28597d1c952075eb2e328bc6d6f2bfc496"},
   "telemetry": {:hex, :telemetry, "0.4.1", "ae2718484892448a24470e6aa341bc847c3277bfb8d4e9289f7474d752c09c7f", [:rebar3], [], "hexpm", "4738382e36a0a9a2b6e25d67c960e40e1a2c95560b9f936d8e29de8cd858480f"},
+  "unicode_util_compat": {:hex, :unicode_util_compat, "0.4.1", "d869e4c68901dd9531385bb0c8c40444ebf624e60b6962d95952775cac5e90cd", [:rebar3], [], "hexpm", "1d1848c40487cdb0b30e8ed975e34e025860c02e419cb615d255849f3427439d"},
 }
diff --git a/test/opentelemetry_plug_test.exs b/test/opentelemetry_plug_test.exs
@@ -1,15 +1,42 @@
 defmodule OpentelemetryPlugTest do
   use ExUnit.Case
-  use Plug.Test
+
+  setup_all do
+    OpentelemetryPlug.setup([])
+
+    {:ok, _} = Plug.Cowboy.http(MyPlug, [], ip: {127, 0, 0, 1}, port: 0)
+
+    on_exit(fn ->
+      :ok = Plug.Cowboy.shutdown(MyPlug.HTTP)
+    end)
+  end
 
   test "creates span" do
-    conn = conn(:get, "/hello/world")
+    assert {200, _, "Hello world"} = request(:get, "/hello/world")
+  end
 
-    OpentelemetryPlug.setup([:my, :plug], [])
-    conn = MyRouter.call(conn, [])
+  defp base_url do
+    info = :ranch.info(MyPlug.HTTP)
+    port = Keyword.fetch!(info, :port)
+    ip = Keyword.fetch!(info, :ip)
+    "http://#{:inet.ntoa(ip)}:#{port}"
+  end
 
-    assert conn.state == :sent
-    assert conn.status == 200
+  defp request(:head = verb, path) do
+    {:ok, status, headers} = :hackney.request(verb, base_url() <> path, [], "", [])
+    {status, headers, nil}
+  end
+
+  defp request(verb, path, headers \\ [], body \\ "") do
+    case :hackney.request(verb, base_url() <> path, headers, body, []) do
+      {:ok, status, headers, client} ->
+        {:ok, body} = :hackney.body(client)
+        :hackney.close(client)
+        {status, headers, body}
+
+      {:error, _} = error ->
+        error
+    end
   end
 end
 
@@ -27,6 +54,7 @@ defmodule MyPlug do
         conn
         |> put_resp_content_type("text/plain")
         |> send_resp(400, "no span context")
+
       _ ->
         conn
         |> put_resp_content_type("text/plain")
@@ -39,7 +67,6 @@ defmodule MyRouter do
   use Plug.Router
 
   plug :match
-  plug Plug.Telemetry, event_prefix: [:my, :plug]
   plug :dispatch
 
   forward "/hello/:foo", to: MyPlug

diff --git a/test/test_helper.exs b/test/test_helper.exs
@@ -1,4 +1,5 @@
 ExUnit.start()
 
+Application.ensure_all_started(:hackney)
 Application.ensure_all_started(:opentelemetry_api)
 Application.ensure_all_started(:opentelemetry)