diff --git a/CHANGELOG.md b/CHANGELOG.md index 83c45e9a..fa28f384 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,9 @@ +## Unreleased + +### Bug fixes + +- Deeply nested spans are handled now when building up traces in `SpanProcessor` ([#924](https://github.com/getsentry/sentry-elixir/pull/924)) + ## 11.0.1 #### Various improvements diff --git a/lib/sentry/opentelemetry/span_storage.ex b/lib/sentry/opentelemetry/span_storage.ex index 30095a5d..d2c8ca2a 100644 --- a/lib/sentry/opentelemetry/span_storage.ex +++ b/lib/sentry/opentelemetry/span_storage.ex @@ -64,8 +64,20 @@ defmodule Sentry.OpenTelemetry.SpanStorage do def get_child_spans(parent_span_id, opts \\ []) do table_name = Keyword.get(opts, :table_name, default_table_name()) - :ets.match_object(table_name, {{:child_span, parent_span_id, :_}, :_, :_}) - |> Enum.map(fn {_key, span_data, _stored_at} -> span_data end) + get_all_descendants(parent_span_id, table_name) + end + + defp get_all_descendants(parent_span_id, table_name) do + direct_children = + :ets.match_object(table_name, {{:child_span, parent_span_id, :_}, :_, :_}) + |> Enum.map(fn {_key, span_data, _stored_at} -> span_data end) + + nested_descendants = + Enum.flat_map(direct_children, fn child -> + get_all_descendants(child.span_id, table_name) + end) + + (direct_children ++ nested_descendants) |> Enum.sort_by(& &1.start_time) end diff --git a/test/sentry/opentelemetry/span_processor_test.exs b/test/sentry/opentelemetry/span_processor_test.exs index 331acd08..eaa76f39 100644 --- a/test/sentry/opentelemetry/span_processor_test.exs +++ b/test/sentry/opentelemetry/span_processor_test.exs @@ -183,7 +183,7 @@ defmodule Sentry.Opentelemetry.SpanProcessorTest do end @tag span_storage: true - test "nested child spans maintain sampling consistency" do + test "nested child spans maintain hierarchy" do put_test_config(environment_name: "test", traces_sample_rate: 1.0) Sentry.Test.start_collecting_sentry_reports() @@ -193,22 +193,22 @@ defmodule Sentry.Opentelemetry.SpanProcessorTest do Tracer.with_span "root_span" do Tracer.with_span "level_1_child" do Tracer.with_span "level_2_child" do - Process.sleep(10) + Process.sleep(1) end Tracer.with_span "level_2_sibling" do - Process.sleep(10) + Process.sleep(1) end end Tracer.with_span "level_1_sibling" do - Process.sleep(10) + Process.sleep(1) end end assert [%Sentry.Transaction{} = transaction] = Sentry.Test.pop_sentry_transactions() - assert length(transaction.spans) == 2 + assert length(transaction.spans) == 4 trace_id = transaction.contexts.trace.trace_id @@ -217,7 +217,7 @@ defmodule Sentry.Opentelemetry.SpanProcessorTest do end) span_names = Enum.map(transaction.spans, & &1.op) |> Enum.sort() - expected_names = ["level_1_child", "level_1_sibling"] + expected_names = ["level_1_child", "level_1_sibling", "level_2_child", "level_2_sibling"] assert span_names == expected_names end diff --git a/test/sentry/opentelemetry/span_storage_test.exs b/test/sentry/opentelemetry/span_storage_test.exs index 5a5548b2..20bb63c0 100644 --- a/test/sentry/opentelemetry/span_storage_test.exs +++ b/test/sentry/opentelemetry/span_storage_test.exs @@ -434,6 +434,206 @@ defmodule Sentry.OpenTelemetry.SpanStorageTest do end end + describe "nested span hierarchies" do + @tag span_storage: true + test "retrieves grand-children spans correctly", %{table_name: table_name} do + root_span = %SpanRecord{ + span_id: "root123", + parent_span_id: nil, + trace_id: "trace123", + name: "root_span", + start_time: 1000, + end_time: 2000 + } + + child1_span = %SpanRecord{ + span_id: "child1", + parent_span_id: "root123", + trace_id: "trace123", + name: "child_span_1", + start_time: 1100, + end_time: 1900 + } + + child2_span = %SpanRecord{ + span_id: "child2", + parent_span_id: "root123", + trace_id: "trace123", + name: "child_span_2", + start_time: 1200, + end_time: 1800 + } + + grandchild1_span = %SpanRecord{ + span_id: "grandchild1", + parent_span_id: "child1", + trace_id: "trace123", + name: "grandchild_span_1", + start_time: 1150, + end_time: 1250 + } + + grandchild2_span = %SpanRecord{ + span_id: "grandchild2", + parent_span_id: "child1", + trace_id: "trace123", + name: "grandchild_span_2", + start_time: 1300, + end_time: 1400 + } + + grandchild3_span = %SpanRecord{ + span_id: "grandchild3", + parent_span_id: "child2", + trace_id: "trace123", + name: "grandchild_span_3", + start_time: 1250, + end_time: 1350 + } + + SpanStorage.store_span(root_span, table_name: table_name) + SpanStorage.store_span(child1_span, table_name: table_name) + SpanStorage.store_span(child2_span, table_name: table_name) + SpanStorage.store_span(grandchild1_span, table_name: table_name) + SpanStorage.store_span(grandchild2_span, table_name: table_name) + SpanStorage.store_span(grandchild3_span, table_name: table_name) + + all_descendants = SpanStorage.get_child_spans("root123", table_name: table_name) + + assert length(all_descendants) == 5 + + span_ids = Enum.map(all_descendants, & &1.span_id) + assert "child1" in span_ids + assert "child2" in span_ids + assert "grandchild1" in span_ids + assert "grandchild2" in span_ids + assert "grandchild3" in span_ids + + start_times = Enum.map(all_descendants, & &1.start_time) + assert start_times == Enum.sort(start_times) + end + + @tag span_storage: true + test "retrieves deep nested hierarchies correctly", %{table_name: table_name} do + spans = [ + %SpanRecord{ + span_id: "root", + parent_span_id: nil, + trace_id: "trace123", + name: "root_span", + start_time: 1000, + end_time: 2000 + }, + %SpanRecord{ + span_id: "child", + parent_span_id: "root", + trace_id: "trace123", + name: "child_span", + start_time: 1100, + end_time: 1900 + }, + %SpanRecord{ + span_id: "grandchild", + parent_span_id: "child", + trace_id: "trace123", + name: "grandchild_span", + start_time: 1200, + end_time: 1800 + }, + %SpanRecord{ + span_id: "great_grandchild", + parent_span_id: "grandchild", + trace_id: "trace123", + name: "great_grandchild_span", + start_time: 1300, + end_time: 1700 + } + ] + + Enum.each(spans, &SpanStorage.store_span(&1, table_name: table_name)) + + all_descendants = SpanStorage.get_child_spans("root", table_name: table_name) + assert length(all_descendants) == 3 + + span_ids = Enum.map(all_descendants, & &1.span_id) + assert "child" in span_ids + assert "grandchild" in span_ids + assert "great_grandchild" in span_ids + + child_descendants = SpanStorage.get_child_spans("child", table_name: table_name) + assert length(child_descendants) == 2 + + child_span_ids = Enum.map(child_descendants, & &1.span_id) + assert "grandchild" in child_span_ids + assert "great_grandchild" in child_span_ids + + grandchild_descendants = SpanStorage.get_child_spans("grandchild", table_name: table_name) + assert length(grandchild_descendants) == 1 + assert hd(grandchild_descendants).span_id == "great_grandchild" + end + + @tag span_storage: true + test "handles multiple disconnected subtrees correctly", %{table_name: table_name} do + spans = [ + %SpanRecord{ + span_id: "branch1", + parent_span_id: "root", + trace_id: "trace123", + name: "branch1_span", + start_time: 1100, + end_time: 1500 + }, + %SpanRecord{ + span_id: "leaf1", + parent_span_id: "branch1", + trace_id: "trace123", + name: "leaf1_span", + start_time: 1150, + end_time: 1250 + }, + %SpanRecord{ + span_id: "leaf2", + parent_span_id: "branch1", + trace_id: "trace123", + name: "leaf2_span", + start_time: 1300, + end_time: 1400 + }, + %SpanRecord{ + span_id: "branch2", + parent_span_id: "root", + trace_id: "trace123", + name: "branch2_span", + start_time: 1600, + end_time: 1900 + }, + %SpanRecord{ + span_id: "leaf3", + parent_span_id: "branch2", + trace_id: "trace123", + name: "leaf3_span", + start_time: 1650, + end_time: 1750 + } + ] + + Enum.each(spans, &SpanStorage.store_span(&1, table_name: table_name)) + + all_descendants = SpanStorage.get_child_spans("root", table_name: table_name) + assert length(all_descendants) == 5 + + span_ids = Enum.map(all_descendants, & &1.span_id) + assert "branch1" in span_ids + assert "branch2" in span_ids + assert "leaf1" in span_ids + assert "leaf2" in span_ids + assert "leaf3" in span_ids + + start_times = Enum.map(all_descendants, & &1.start_time) + assert start_times == [1100, 1150, 1300, 1600, 1650] + end + end + describe "cleanup" do @tag span_storage: [cleanup_interval: 100] test "cleanup respects span TTL precisely", %{table_name: table_name} do diff --git a/test_integrations/phoenix_app/lib/phoenix_app_web/controllers/page_controller.ex b/test_integrations/phoenix_app/lib/phoenix_app_web/controllers/page_controller.ex index dbc7812b..8b31383c 100644 --- a/test_integrations/phoenix_app/lib/phoenix_app_web/controllers/page_controller.ex +++ b/test_integrations/phoenix_app/lib/phoenix_app_web/controllers/page_controller.ex @@ -3,7 +3,7 @@ defmodule PhoenixAppWeb.PageController do require OpenTelemetry.Tracer, as: Tracer - alias PhoenixApp.{Repo, User} + alias PhoenixApp.{Repo, Accounts.User} def home(conn, _params) do render(conn, :home, layout: false) @@ -26,4 +26,26 @@ defmodule PhoenixAppWeb.PageController do render(conn, :home, layout: false) end + + def nested_spans(conn, _params) do + Tracer.with_span "root_span" do + Tracer.with_span "child_span_1" do + Tracer.with_span "grandchild_span_1" do + :timer.sleep(50) + end + + Tracer.with_span "grandchild_span_2" do + Repo.all(User) |> Enum.count() + end + end + + Tracer.with_span "child_span_2" do + Tracer.with_span "grandchild_span_3" do + :timer.sleep(30) + end + end + end + + render(conn, :home, layout: false) + end end diff --git a/test_integrations/phoenix_app/lib/phoenix_app_web/router.ex b/test_integrations/phoenix_app/lib/phoenix_app_web/router.ex index ddf33edf..597506b1 100644 --- a/test_integrations/phoenix_app/lib/phoenix_app_web/router.ex +++ b/test_integrations/phoenix_app/lib/phoenix_app_web/router.ex @@ -20,6 +20,7 @@ defmodule PhoenixAppWeb.Router do get "/", PageController, :home get "/exception", PageController, :exception get "/transaction", PageController, :transaction + get "/nested-spans", PageController, :nested_spans live "/test-worker", TestWorkerLive diff --git a/test_integrations/phoenix_app/test/phoenix_app_web/controllers/transaction_test.exs b/test_integrations/phoenix_app/test/phoenix_app_web/controllers/transaction_test.exs index 2a821d4e..49d4faa3 100644 --- a/test_integrations/phoenix_app/test/phoenix_app_web/controllers/transaction_test.exs +++ b/test_integrations/phoenix_app/test/phoenix_app_web/controllers/transaction_test.exs @@ -61,4 +61,72 @@ defmodule Sentry.Integrations.Phoenix.TransactionTest do assert trace.op == "PhoenixAppWeb.UserLive.Index.handle_params" assert trace.data == %{} end + + test "GET /nested-spans includes grand-child spans", %{conn: conn} do + get(conn, ~p"/nested-spans") + + transactions = Sentry.Test.pop_sentry_transactions() + + assert length(transactions) == 1 + assert [transaction] = transactions + + assert transaction.transaction == "root_span" + assert transaction.transaction_info == %{source: :custom} + + trace = transaction.contexts.trace + assert trace.origin == "phoenix_app" + assert trace.op == "root_span" + + assert length(transaction.spans) == 6 + + span_names = Enum.map(transaction.spans, & &1.description) + + # Verify all expected spans are present + assert "child_span_1" in span_names + assert "child_span_2" in span_names + assert "grandchild_span_1" in span_names + assert "grandchild_span_2" in span_names + assert "grandchild_span_3" in span_names + + # Find the database span + db_spans = Enum.filter(transaction.spans, &(&1.op == "db")) + assert length(db_spans) == 1 + + [db_span] = db_spans + assert String.starts_with?(db_span.description, "SELECT") + assert db_span.data["db.system"] == :sqlite + + child_spans = Enum.filter(transaction.spans, &(&1.parent_span_id == transaction.span_id)) + assert length(child_spans) == 2 + + child_span_ids = MapSet.new(child_spans, & &1.span_id) + + grandchild_spans = Enum.filter(transaction.spans, fn span -> + span.parent_span_id != transaction.span_id and span.parent_span_id in child_span_ids + end) + + assert length(grandchild_spans) == 3 + end + + test "LiveView mount and handle_params create disconnected transactions with child spans", %{conn: conn} do + get(conn, ~p"/users") + + transactions = Sentry.Test.pop_sentry_transactions() + + assert length(transactions) == 2 + assert [mount_transaction, handle_params_transaction] = transactions + + assert mount_transaction.transaction == "PhoenixAppWeb.UserLive.Index.mount" + assert length(mount_transaction.spans) == 1 + + [mount_db_span] = mount_transaction.spans + assert mount_db_span.op == "db" + assert mount_db_span.parent_span_id == mount_transaction.span_id + + assert handle_params_transaction.transaction == "PhoenixAppWeb.UserLive.Index.handle_params" + assert handle_params_transaction.span_id != mount_transaction.span_id + assert handle_params_transaction.contexts.trace.trace_id != mount_transaction.contexts.trace.trace_id + + refute mount_transaction.contexts.trace.trace_id == handle_params_transaction.contexts.trace.trace_id + end end