Merge pull request #958 from appsignal/fix-ecto-transaction-in-parall…

…el-preload

Fix ecto transaction in parallel preload

.changesets/fix-ecto-transactions-in-parallel-preloads.md

@@ -0,0 +1,6 @@
+---
+bump: patch
+type: fix
+---
+
+Fix an issue where Ecto transactions in parallel preloads would not be instrumented correctly when using `Appsignal.Ecto.Repo`, causing the query in the Ecto transaction to not be instrumented and the sample to be incorrectly closed as an earlier time.

lib/appsignal/ecto.ex

@@ -73,7 +73,13 @@ defmodule Appsignal.Ecto do
   def handle_event(_event, _measurements, _metadata, _config), do: :ok
 
   defp current_span(metadata) do
-    metadata[:options][:_appsignal_current_span] || @tracer.current_span()
+    # If a current span is already set in this process, use that instead
+    # of the current span passed as part of the Ecto metadata.
+    # This fixes an issue where, when a transaction takes place in a
+    # parallel preload process, `handle_commit/3` and `handle_rollback/3`
+    # would not close the span created by `handle_begin/3`, but the span's
+    # parent.
+    @tracer.current_span() || metadata[:options][:_appsignal_current_span]
   end
 
   defp do_handle_event(nil, _total_time, _repo, _query), do: nil

test/appsignal/ecto_test.exs

@@ -68,7 +68,7 @@ defmodule Appsignal.EctoTest do
     end
   end
 
-  describe "handle_event/4 and handle_query/4, with a root span" do
+  describe "handle_event/4 and handle_query/4, with a root span from the tracer" do
     setup do
       start_supervised!(Test.Nif)
       start_supervised!(Test.Tracer)
@@ -100,7 +100,7 @@ defmodule Appsignal.EctoTest do
     end
 
     test "creates a span with a parent and a start time", %{parent: parent} do
-      {:ok, [{"http_request", parent, start_time: time}]} = Test.Tracer.get(:create_span)
+      {:ok, [{"http_request", ^parent, start_time: time}]} = Test.Tracer.get(:create_span)
       assert is_integer(time)
     end
 
@@ -165,7 +165,7 @@ defmodule Appsignal.EctoTest do
     end
 
     test "creates a span with a parent and a start time", %{parent: parent} do
-      {:ok, [{"http_request", parent, start_time: time}]} = Test.Tracer.get(:create_span)
+      {:ok, [{"http_request", ^parent, start_time: time}]} = Test.Tracer.get(:create_span)
       assert is_integer(time)
     end
 
@@ -192,6 +192,70 @@ defmodule Appsignal.EctoTest do
     end
   end
 
+  describe "handle_event/4 and handle_commit/4, with a root span from the tracer and a root span passed via telemetry options" do
+    setup do
+      start_supervised!(Test.Nif)
+      start_supervised!(Test.Tracer)
+      start_supervised!(Test.Span)
+      start_supervised!(Test.Monitor)
+
+      telemetry_span =
+        fn -> Appsignal.Tracer.create_span("http_request") end
+        |> Task.async()
+        |> Task.await()
+
+      tracer_span = Appsignal.Tracer.create_span("http_request")
+
+      :telemetry.execute(
+        [:appsignal, :test, :repo, :query],
+        %{
+          decode_time: 2_204_000,
+          query_time: 5_386_000,
+          queue_time: 1_239_000,
+          total_time: 8_829_000
+        },
+        %{
+          params: [],
+          query: "commit",
+          repo: Appsignal.Test.Repo,
+          result: :ok,
+          source: "users",
+          type: :ecto_sql_query
+        }
+      )
+
+      %{telemetry_span: telemetry_span, tracer_span: tracer_span}
+    end
+
+    test "creates a span with the tracer span as the parent and a start time", %{
+      tracer_span: parent
+    } do
+      {:ok, [{"http_request", ^parent, start_time: time}]} = Test.Tracer.get(:create_span)
+      assert is_integer(time)
+    end
+
+    test "sets the span's name" do
+      assert {:ok, [{%Span{}, "Commit Appsignal.Test.Repo"}]} = Test.Span.get(:set_name)
+    end
+
+    test "sets the span's category" do
+      assert attribute("appsignal:category", "commit.ecto")
+    end
+
+    test "does not set the span's body" do
+      assert Test.Span.get(:set_sql) == :error
+    end
+
+    test "closes the span and the parent tracer span with an end time", %{tracer_span: parent} do
+      {:ok, [{_, _, start_time: start_time}]} = Test.Tracer.get(:create_span)
+
+      {:ok, [{^parent, end_time: end_time}, {%Span{}, end_time: end_time}]} =
+        Test.Tracer.get(:close_span)
+
+      assert end_time - start_time == 8_829_000
+    end
+  end
+
   describe "handle_begin/4, with a root span" do
     setup do
       start_supervised!(Test.Nif)
@@ -223,7 +287,7 @@ defmodule Appsignal.EctoTest do
     end
 
     test "creates a span with a parent and a start time", %{parent: parent} do
-      {:ok, [{"http_request", %Span{}, start_time: time}]} = Test.Tracer.get(:create_span)
+      {:ok, [{"http_request", ^parent, start_time: time}]} = Test.Tracer.get(:create_span)
       assert is_integer(time)
     end
 
@@ -275,7 +339,7 @@ defmodule Appsignal.EctoTest do
     end
 
     test "creates a span with a parent and a start time", %{parent: parent} do
-      {:ok, [{"http_request", %Span{}, start_time: time}]} = Test.Tracer.get(:create_span)
+      {:ok, [{"http_request", ^parent, start_time: time}]} = Test.Tracer.get(:create_span)
       assert is_integer(time)
     end
 
@@ -294,7 +358,7 @@ defmodule Appsignal.EctoTest do
     test "closes the span and its parent with an end time", %{parent: parent} do
       {:ok, [{_, _, start_time: start_time}]} = Test.Tracer.get(:create_span)
 
-      {:ok, [{%Span{}, end_time: end_time}, {parent, end_time: end_time}]} =
+      {:ok, [{^parent, end_time: end_time}, {%Span{}, end_time: end_time}]} =
         Test.Tracer.get(:close_span)
 
       assert end_time - start_time == 8_829_000
@@ -332,7 +396,7 @@ defmodule Appsignal.EctoTest do
     end
 
     test "creates a span with a parent and a start time", %{parent: parent} do
-      {:ok, [{"http_request", parent, start_time: time}]} = Test.Tracer.get(:create_span)
+      {:ok, [{"http_request", ^parent, start_time: time}]} = Test.Tracer.get(:create_span)
       assert is_integer(time)
     end
 
@@ -351,7 +415,7 @@ defmodule Appsignal.EctoTest do
     test "closes the span and its parent with an end time", %{parent: parent} do
       {:ok, [{_, _, start_time: start_time}]} = Test.Tracer.get(:create_span)
 
-      {:ok, [{%Span{}, end_time: end_time}, {parent, end_time: end_time}]} =
+      {:ok, [{^parent, end_time: end_time}, {%Span{}, end_time: end_time}]} =
         Test.Tracer.get(:close_span)
 
       assert end_time - start_time == 8_829_000
@@ -393,7 +457,7 @@ defmodule Appsignal.EctoTest do
     end
 
     test "creates a span with a parent and a start time", %{parent: parent} do
-      {:ok, [{"http_request", parent, start_time: time}]} = Test.Tracer.get(:create_span)
+      {:ok, [{"http_request", ^parent, start_time: time}]} = Test.Tracer.get(:create_span)
       assert is_integer(time)
     end