Prefer the tracer span to the telemetry span

When processing an Ecto event, if both a tracer span and a telemetry
span are present, use the tracer span as the parent.

This should fix an issue where, when an Ecto transaction takes place
inside an Ecto parallel preload, when the transaction's commit or
rollback event attempts to close both its own span and the
overarching transaction span (which would be the tracer parent, within
the parallel preload's sub-process) it instead closes the transaction
span's parent (which would be the telemetry parent, from the process
that spawned the parallel preload) leaving the transaction span
unclosed and potentially cutting the transaction short.

.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)
@@ -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)