diff --git a/.changesets/fix-ecto-transactions-in-parallel-preloads.md b/.changesets/fix-ecto-transactions-in-parallel-preloads.md new file mode 100644 index 000000000..81b7d9d4e --- /dev/null +++ b/.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. diff --git a/lib/appsignal/ecto.ex b/lib/appsignal/ecto.ex index d655f22fa..8e76b211e 100644 --- a/lib/appsignal/ecto.ex +++ b/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 diff --git a/test/appsignal/ecto_test.exs b/test/appsignal/ecto_test.exs index 796f2a3ce..ca763159e 100644 --- a/test/appsignal/ecto_test.exs +++ b/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