Support Phoenix 1.7's template telemetry (#54)

* Support Phoenix 1.7's template telemetry

Instead of using Appsignal.View, Appsignal.EventHandler subscribes to
Phoenix 1.7's new template telemetry to gain template rendering
insights.

* Add warning for using Phoenix.View on Phoenix 1.7

Phoenix 1.7 apps don't have a :view in their web modules. The closest
thing is :html, which is similar, but doesn't have Phoenix.View anymore,
which is what Appsignal.Phoenix.View depended on.

To make sure users don't move their use Appsignal.Phoenix.View line to
the html function in their Phoenix 1.7 web module, this patch makes sure
that whatever Appsignal.Phoenix.View is used in has a __templates__/0
and a render/2 function before doing anything. If not, it'll print a
warning:

> 10:20:44.354 [warning] AppSignal.Phoenix.View NOT attached to Elixir.AppsignalPhoenixExampleWeb.Layouts
>
> Template rendering instrumentation is now set up automatically, so using
> Appsignal.Phoenix.View in your app's web module is no longer needed.

This warning is noisy, as it prints for every view module in the app.

Also, it's printed using Elixir's regular Logger instead of
Appsignal.IntegrationLogger for two reasons. Firstly, since it's run in
a __before_compile__/1, the configuration isn't loaded yet, so
Appsignal.IntegrationLogger can't function. Also, it's not needed since
it's using the warn level, which would be printed anyway.

* Add changeset for new template instrumentation

> Add template instrumentation for Phoenix 1.7. Phoenix's upcoming
> release adds telemetry to templates, so using Appsignal.Phoenix.View
> is no longer needed.

* Update lib/appsignal_phoenix/event_handler.ex

Co-authored-by: Noemi <45180344+unflxw@users.noreply.github.com>

* Update event handler tests to match new event keys

The merged version of the Phoenix patch uses
`[:phoenix, :controller, :render, :start]` instead of the proposed
`[:phoenix_template, :render, :start]`.

Co-authored-by: Noemi <45180344+unflxw@users.noreply.github.com>

.changesets/add-template-instrumentation-for-phoenix-1-7.md

@@ -0,0 +1,6 @@
+---
+bump: "minor"
+type: "add"
+---
+
+Add automatic template instrumentation for Phoenix 1.7. Phoenix's upcoming release adds telemetry to templates, so using Appsignal.Phoenix.View is no longer needed.

lib/appsignal_phoenix/event_handler.ex

@@ -9,7 +9,10 @@ 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, :endpoint, :stop] => &__MODULE__.phoenix_endpoint_stop/4,
+      [:phoenix, :controller, :render, :start] => &__MODULE__.phoenix_template_render_start/4,
+      [:phoenix, :controller, :render, :stop] => &__MODULE__.phoenix_template_render_stop/4,
+      [:phoenix, :controller, :render, :exception] => &__MODULE__.phoenix_template_render_stop/4
     }
 
     for {event, fun} <- handlers do
@@ -50,6 +53,21 @@ defmodule Appsignal.Phoenix.EventHandler do
     @tracer.close_span(@tracer.current_span())
   end
 
+  def phoenix_template_render_start(_event, _measurements, metadata, _config) do
+    parent = @tracer.current_span()
+
+    "http_request"
+    |> @tracer.create_span(parent)
+    |> @span.set_name(
+      "Render #{inspect(metadata.template)} (#{metadata.type}) template from #{module_name(metadata.view)}"
+    )
+    |> @span.set_attribute("appsignal:category", "render.phoenix_template")
+  end
+
+  def phoenix_template_render_stop(_event, _measurements, _metadata, _config) do
+    @tracer.close_span(@tracer.current_span())
+  end
+
   defp module_name("Elixir." <> module), do: module
   defp module_name(module) when is_binary(module), do: module
   defp module_name(module), do: module |> to_string() |> module_name()

lib/appsignal_phoenix/view.ex

@@ -40,38 +40,50 @@ defmodule Appsignal.Phoenix.View do
 
   defmacro __before_compile__(_env) do
     quote do
-      require Appsignal.Utils
-      @span Appsignal.Utils.compile_env(:appsignal, :appsignal_span, Appsignal.Span)
-      @tracer Appsignal.Utils.compile_env(:appsignal, :appsignal_tracer, Appsignal.Tracer)
+      if Module.defines?(__MODULE__, {:__templates__, 0}) &&
+           Module.defines?(__MODULE__, {:render, 2}) do
+        require Appsignal.Utils
+        @span Appsignal.Utils.compile_env(:appsignal, :appsignal_span, Appsignal.Span)
+        @tracer Appsignal.Utils.compile_env(:appsignal, :appsignal_tracer, Appsignal.Tracer)
 
-      defoverridable render: 2
+        defoverridable render: 2
 
-      def render(template, assigns) when is_binary(template) do
-        {root, _pattern, _names} = __templates__()
-        path = Path.join(root, template)
+        def render(template, assigns) when is_binary(template) do
+          {root, _pattern, _names} = __templates__()
+          path = Path.join(root, template)
 
-        do_render(@tracer.current_span, path, fn ->
+          do_render(@tracer.current_span, path, fn ->
+            super(template, assigns)
+          end)
+        end
+
+        def render(template, assigns) do
           super(template, assigns)
-        end)
-      end
+        end
 
-      def render(template, assigns) do
-        super(template, assigns)
-      end
+        defp do_render(%Appsignal.Span{} = span, path, fun) do
+          Appsignal.instrument("Render #{path}", fn span ->
+            _ =
+              span
+              |> @span.set_attribute("title", path)
+              |> @span.set_attribute("appsignal:category", "render.phoenix_template")
 
-      defp do_render(%Appsignal.Span{} = span, path, fun) do
-        Appsignal.instrument("Render #{path}", fn span ->
-          _ =
-            span
-            |> @span.set_attribute("title", path)
-            |> @span.set_attribute("appsignal:category", "render.phoenix_template")
+            fun.()
+          end)
+        end
 
+        defp do_render(_span, _path, fun) do
           fun.()
-        end)
-      end
+        end
+      else
+        require Logger
+
+        Logger.warn("""
+        AppSignal.Phoenix.View NOT attached to #{__MODULE__}
 
-      defp do_render(_span, _path, fun) do
-        fun.()
+        Template rendering instrumentation is now set up automatically, so using
+        Appsignal.Phoenix.View in your app's web module is no longer needed.
+        """)
       end
     end
   end

test/appsignal_phoenix/event_handler_test.exs

@@ -34,6 +34,40 @@ defmodule Appsignal.Phoenix.EventHandlerTest do
     end
   end
 
+  describe "after receiving an render-start event" do
+    setup [:create_root_span, :render_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 name" do
+      assert {:ok, [{%Span{}, "Render \"template\" (html) template from PhoenixWeb.View"}]} =
+               Test.Span.get(:set_name)
+    end
+
+    test "sets the span's category" do
+      assert {:ok, [{%Span{}, "appsignal:category", "render.phoenix_template"}]} =
+               Test.Span.get(:set_attribute)
+    end
+  end
+
+  describe "after receiving an render-start and an render-stop event" do
+    setup [:create_root_span, :render_start_event, :render_finish_event]
+
+    test "finishes an event" do
+      assert {:ok, [{%Span{}}]} = Test.Tracer.get(:close_span)
+    end
+  end
+
+  describe "after receiving an render-start and an render-exception event" do
+    setup [:create_root_span, :render_start_event, :render_exception_event]
+
+    test "finishes an event" do
+      assert {:ok, [{%Span{}}]} = Test.Tracer.get(:close_span)
+    end
+  end
+
   defp create_root_span(_context) do
     [span: Tracer.create_span("http_request")]
   end
@@ -59,4 +93,28 @@ defmodule Appsignal.Phoenix.EventHandlerTest do
       }
     )
   end
+
+  def render_start_event(_context) do
+    :telemetry.execute(
+      [:phoenix, :controller, :render, :start],
+      %{time: -576_460_736_044_040_000},
+      %{view: PhoenixWeb.View, template: "template", type: "html"}
+    )
+  end
+
+  def render_finish_event(_context) do
+    :telemetry.execute(
+      [:phoenix, :controller, :render, :stop],
+      %{duration: 49_474_000},
+      %{}
+    )
+  end
+
+  def render_exception_event(_context) do
+    :telemetry.execute(
+      [:phoenix, :controller, :render, :exception],
+      %{duration: 49_474_000},
+      %{}
+    )
+  end
 end