Handle :phoenix, :endpoint events in EventHandler (#90)

* Handle :phoenix, :endpoint events in EventHandler

Previously, the EventHandler ignored endpoint events, mostly because
of difficulty determining the root span, as the endpoint and
router_dispatch spans close in reverse order. Because of the addition
of the root_span functions, this can now be solved, as span data can
be set on the root span directly.

This patch moves the span data to the phoenix_endpoint_stop function,
which also causes spans to start earlier in the request. That, in
turn, means that plugs can be instrumented without changes once again.

Closes #83.

* Update .changesets/add-endpoint-events-to-phoenix-request-traces.md

Co-authored-by: Tom de Bruijn <tom@tomdebruijn.com>

---------

Co-authored-by: Tom de Bruijn <tom@tomdebruijn.com>

.changesets/add-endpoint-events-to-phoenix-request-traces.md

@@ -0,0 +1,6 @@
+---
+bump: "minor"
+type: "add"
+---
+
+Add endpoint events to Phoenix request traces to instrument more events of the request lifetime.

lib/appsignal_phoenix/event_handler.ex

@@ -6,6 +6,8 @@ defmodule Appsignal.Phoenix.EventHandler do
 
   def attach do
     handlers = %{
+      [:phoenix, :endpoint, :start] => &__MODULE__.phoenix_endpoint_start/4,
+      [:phoenix, :endpoint, :stop] => &__MODULE__.phoenix_endpoint_stop/4,
       [:phoenix, :router_dispatch, :start] => &__MODULE__.phoenix_router_dispatch_start/4,
       [:phoenix, :router_dispatch, :stop] => &__MODULE__.phoenix_router_dispatch_stop/4,
       [:phoenix, :router_dispatch, :exception] => &__MODULE__.phoenix_router_dispatch_exception/4,
@@ -34,17 +36,31 @@ defmodule Appsignal.Phoenix.EventHandler do
     end
   end
 
-  def phoenix_router_dispatch_start(_event, _measurements, _metadata, _config) do
+  def phoenix_endpoint_start(_event, _measurements, _metadata, _config) do
     parent = @tracer.current_span()
 
     "http_request"
     |> @tracer.create_span(parent)
     |> @span.set_attribute("appsignal:category", "call.phoenix_endpoint")
   end
 
+  def phoenix_endpoint_stop(_event, _measurements, metadata, _config) do
+    set_span_data(@tracer.root_span(), metadata)
+
+    @tracer.current_span()
+    |> @tracer.close_span()
+  end
+
+  def phoenix_router_dispatch_start(_event, _measurements, _metadata, _config) do
+    parent = @tracer.current_span()
+
+    "http_request"
+    |> @tracer.create_span(parent)
+    |> @span.set_attribute("appsignal:category", "call.phoenix_router_dispatch")
+  end
+
   def phoenix_router_dispatch_stop(_event, _measurements, metadata, _config) do
     @tracer.current_span()
-    |> set_span_data(metadata)
     |> @tracer.close_span()
   end
 

test/appsignal_phoenix/event_handler_test.exs

@@ -9,8 +9,8 @@ defmodule Appsignal.Phoenix.EventHandlerTest do
     :ok
   end
 
-  describe "after receiving an router_dispatch-start event" do
-    setup [:create_root_span, :router_dispatch_start_event]
+  describe "after receiving an endpoint-start event" do
+    setup [:create_root_span, :endpoint_start_event]
 
     test "starts a child span", %{span: parent} do
       assert {:ok, [{"http_request", ^parent}]} = Test.Tracer.get(:create_span)
@@ -22,8 +22,8 @@ defmodule Appsignal.Phoenix.EventHandlerTest do
     end
   end
 
-  describe "after receiving an router_dispatch-start and an router_dispatch-stop event" do
-    setup [:create_root_span, :router_dispatch_start_event, :router_dispatch_finish_event]
+  describe "after receiving an endpoint-start and an endpoint-stop event" do
+    setup [:create_root_span, :endpoint_start_event, :endpoint_finish_event]
 
     test "sets the span's name" do
       assert {:ok, [{%Span{}, "AppsignalPhoenixExampleWeb.PageController#index"}]} =
@@ -65,12 +65,12 @@ defmodule Appsignal.Phoenix.EventHandlerTest do
     end
   end
 
-  describe "after receiving an router_dispatch-start and an router_dispatch-stop event without an event name in the conn" do
-    setup [:create_root_span, :router_dispatch_start_event]
+  describe "after receiving an endpoint-start and an endpoint-stop event without an event name in the conn" do
+    setup [:create_root_span, :endpoint_start_event]
 
     setup do
       :telemetry.execute(
-        [:phoenix, :router_dispatch, :stop],
+        [:phoenix, :endpoint, :stop],
         %{duration: 49_474_000},
         %{conn: %Plug.Conn{}, route: "/foo/:bar", options: []}
       )
@@ -81,6 +81,32 @@ defmodule Appsignal.Phoenix.EventHandlerTest do
     end
   end
 
+  describe "after receiving an router_dispatch-start event" do
+    setup [:create_root_span, :router_dispatch_start_event]
+
+    test "starts a child span", %{span: parent} do
+      assert {:ok, [{"http_request", ^parent}]} = Test.Tracer.get(:create_span)
+    end
+
+    test "sets the span's category" do
+      assert {:ok, [{%Span{}, "appsignal:category", "call.phoenix_router_dispatch"}]} =
+               Test.Span.get(:set_attribute)
+    end
+  end
+
+  describe "after receiving an router_dispatch-start and an router_dispatch-stop event" do
+    setup [:create_root_span, :router_dispatch_start_event, :router_dispatch_finish_event]
+
+    test "sets the root span's category" do
+      assert {:ok, [{%Span{}, "appsignal:category", "call.phoenix_router_dispatch"}]} =
+               Test.Span.get(:set_attribute)
+    end
+
+    test "finishes an event" do
+      assert {:ok, [{%Span{}}]} = Test.Tracer.get(:close_span)
+    end
+  end
+
   describe "after receiving an router_dispatch-start and an router_dispatch-exception event" do
     setup [:create_root_span, :router_dispatch_start_event]
 
@@ -236,6 +262,25 @@ defmodule Appsignal.Phoenix.EventHandlerTest do
     [span: Tracer.create_span("http_request")]
   end
 
+  def endpoint_start_event(_context) do
+    :telemetry.execute(
+      [:phoenix, :endpoint, :start],
+      %{time: -576_460_736_044_040_000},
+      %{
+        conn: %Plug.Conn{private: %{phoenix_endpoint: PhoenixWeb.Endpoint}},
+        options: []
+      }
+    )
+  end
+
+  def endpoint_finish_event(_context) do
+    :telemetry.execute(
+      [:phoenix, :endpoint, :stop],
+      %{duration: 49_474_000},
+      %{conn: conn(), route: "/foo/:bar", options: []}
+    )
+  end
+
   def router_dispatch_start_event(_context) do
     :telemetry.execute(
       [:phoenix, :router_dispatch, :start],