From 87d06116f94530103eb5ed2fa2ea8aa0c5e76017 Mon Sep 17 00:00:00 2001 From: Yordis Prieto Date: Thu, 26 Feb 2026 00:25:06 -0500 Subject: [PATCH] fix: use Broadway/Oban pattern for OTel context propagation Signed-off-by: Yordis Prieto --- lib/commanded/opentelemetry/aggregate.ex | 7 +- lib/commanded/opentelemetry/application.ex | 5 - lib/commanded/opentelemetry/event_handler.ex | 35 +--- lib/commanded/opentelemetry/helpers.ex | 36 ++-- test/opentelemetry/application_e2e_test.exs | 199 +++++++++++++++++++ test/opentelemetry/application_test.exs | 75 +++++++ test/opentelemetry/helpers_test.exs | 183 +++++++++++++++++ 7 files changed, 490 insertions(+), 50 deletions(-) create mode 100644 test/opentelemetry/application_e2e_test.exs create mode 100644 test/opentelemetry/helpers_test.exs diff --git a/lib/commanded/opentelemetry/aggregate.ex b/lib/commanded/opentelemetry/aggregate.ex index cfcc4ba9..a630b86c 100644 --- a/lib/commanded/opentelemetry/aggregate.ex +++ b/lib/commanded/opentelemetry/aggregate.ex @@ -32,9 +32,10 @@ defmodule Commanded.OpenTelemetry.Aggregate do ) do context = meta.execution_context - # Propagate trace context from command metadata (aggregates run in separate processes) - # Uses W3C traceparent/tracestate headers injected by TraceContextPropagator middleware - Helpers.attach_ctx(context.metadata) + case Helpers.extract_propagated_ctx(context.metadata) do + {_links, :undefined} -> Helpers.clear_ctx() + {_links, ctx} -> :otel_ctx.attach(ctx) + end handler_module_name = Helpers.module_name(context.handler) diff --git a/lib/commanded/opentelemetry/application.ex b/lib/commanded/opentelemetry/application.ex index b90facdc..ff41a3a6 100644 --- a/lib/commanded/opentelemetry/application.ex +++ b/lib/commanded/opentelemetry/application.ex @@ -32,11 +32,6 @@ defmodule Commanded.OpenTelemetry.Application do ) do context = meta.execution_context - # Attach trace context from command metadata if present. - # The TraceContextPropagator middleware injects W3C traceparent/tracestate headers - # into metadata, allowing explicit context propagation when needed. - Helpers.attach_ctx(context.metadata) - handler_module_name = Helpers.module_name(context.handler) attributes = [ diff --git a/lib/commanded/opentelemetry/event_handler.ex b/lib/commanded/opentelemetry/event_handler.ex index ec169e59..bd8ee307 100644 --- a/lib/commanded/opentelemetry/event_handler.ex +++ b/lib/commanded/opentelemetry/event_handler.ex @@ -50,22 +50,23 @@ defmodule Commanded.OpenTelemetry.EventHandler do recorded_event = meta.recorded_event span_relationship = config.span_relationship - # Clear any stale context and set up links based on span_relationship mode. - # All modes must explicitly handle context to avoid inheriting unintended parents - # from pre-existing OTel context in the process dictionary. links = case span_relationship do :link -> - link_ctx = extract_span_context_for_link(recorded_event.metadata) - Helpers.attach_ctx(nil) - if link_ctx, do: [OpenTelemetry.link(link_ctx)], else: [] + {links, _ctx} = Helpers.extract_propagated_ctx(recorded_event.metadata) + Helpers.clear_ctx() + links :child -> - Helpers.attach_ctx(recorded_event.metadata) + case Helpers.extract_propagated_ctx(recorded_event.metadata) do + {_links, :undefined} -> Helpers.clear_ctx() + {_links, ctx} -> :otel_ctx.attach(ctx) + end + [] :none -> - Helpers.attach_ctx(nil) + Helpers.clear_ctx() [] end @@ -170,7 +171,7 @@ defmodule Commanded.OpenTelemetry.EventHandler do # Since batch metadata doesn't include traceparent, we always clear context # to start fresh traces. This ensures batch spans don't accidentally inherit # stale context from the process dictionary (from other OTel instrumentation). - Helpers.attach_ctx(nil) + Helpers.clear_ctx() handler_module_name = Helpers.module_name(meta.handler_module) @@ -253,22 +254,6 @@ defmodule Commanded.OpenTelemetry.EventHandler do OpentelemetryTelemetry.end_telemetry_span(@tracer_id, meta) end - # Extract span context from W3C headers for :link span relationship. - # Returns context without setting as current (unlike attach_ctx/1). - defp extract_span_context_for_link(nil), do: nil - - defp extract_span_context_for_link(metadata) when is_map(metadata) do - headers = Helpers.build_headers_from_metadata(metadata) - - if headers != [] do - fresh_ctx = :otel_ctx.new() - extracted_ctx = :otel_propagator_text_map.extract_to(fresh_ctx, headers) - :otel_tracer.current_span_ctx(extracted_ctx) - else - nil - end - end - defp put_links(span_opts, []), do: span_opts defp put_links(span_opts, links), do: Map.put(span_opts, :links, links) end diff --git a/lib/commanded/opentelemetry/helpers.ex b/lib/commanded/opentelemetry/helpers.ex index 525b4421..b73244da 100644 --- a/lib/commanded/opentelemetry/helpers.ex +++ b/lib/commanded/opentelemetry/helpers.ex @@ -1,29 +1,31 @@ defmodule Commanded.OpenTelemetry.Helpers do @moduledoc false - # Propagates trace context across process boundaries. Commanded runs aggregates - # and event handlers in separate processes, so we extract W3C trace headers - # from metadata to maintain parent-child span relationships. - # - # When nil or no headers, we clear context to prevent inheriting stale context - # from the process dictionary (which could link unrelated traces). - def attach_ctx(nil) do - :otel_ctx.attach(:otel_ctx.new()) - end + def extract_propagated_ctx(nil), do: {[], :undefined} - def attach_ctx(metadata) when is_map(metadata) do + def extract_propagated_ctx(metadata) when is_map(metadata) do headers = build_headers_from_metadata(metadata) + if headers == [], do: {[], :undefined}, else: extract_to_ctx(headers) + end + + defp extract_to_ctx(headers) do + ctx = + :otel_ctx.new() + |> :otel_propagator_text_map.extract_to(headers) - if headers != [] do - fresh_ctx = :otel_ctx.new() - extracted_ctx = :otel_propagator_text_map.extract_to(fresh_ctx, headers) - :otel_ctx.attach(extracted_ctx) - else - :otel_ctx.attach(:otel_ctx.new()) + span_ctx = :otel_tracer.current_span_ctx(ctx) + + case span_ctx do + :undefined -> {[], :undefined} + span_ctx -> {[OpenTelemetry.link(span_ctx)], ctx} end end - def build_headers_from_metadata(metadata) do + def clear_ctx do + :otel_ctx.attach(:otel_ctx.new()) + end + + defp build_headers_from_metadata(metadata) do [] |> maybe_add_header(metadata, "traceparent") |> maybe_add_header(metadata, "tracestate") diff --git a/test/opentelemetry/application_e2e_test.exs b/test/opentelemetry/application_e2e_test.exs new file mode 100644 index 00000000..9dd94dac --- /dev/null +++ b/test/opentelemetry/application_e2e_test.exs @@ -0,0 +1,199 @@ +defmodule Commanded.OpenTelemetry.ApplicationE2ETest do + use Commanded.OpenTelemetryCase, async: false + + @moduletag :eventstore_adapter + + alias Commanded.Middleware.Commands.IncrementCount + alias Commanded.OpenTelemetry.Aggregate, as: OTelAggregate + alias Commanded.OpenTelemetry.Application, as: OTelApplication + alias Commanded.OpenTelemetry.EventHandler, as: OTelEventHandler + alias Commanded.UUID + + require OpenTelemetry.Tracer, as: Tracer + + defmodule E2ERouter do + use Commanded.Commands.Router + + alias Commanded.Middleware.Commands.CommandHandler + alias Commanded.Middleware.Commands.CounterAggregateRoot + + middleware Commanded.Middleware.TraceContextPropagator + + dispatch IncrementCount, + to: CommandHandler, + aggregate: CounterAggregateRoot, + identity: :aggregate_uuid + end + + defmodule App do + use Commanded.Application, + otp_app: :commanded, + event_store: [ + adapter: Commanded.EventStore.Adapters.EventStore, + event_store: TestEventStore + ], + pubsub: :local, + registry: :local + + router(E2ERouter) + end + + defmodule E2EEventHandler do + use Commanded.Event.Handler, + application: Commanded.OpenTelemetry.ApplicationE2ETest.App, + name: __MODULE__ + + def handle(_event, _metadata), do: :ok + end + + setup do + start_event_store() + start_supervised!(App) + detach_all_handlers() + OTelApplication.setup() + OTelAggregate.setup() + OTelEventHandler.setup(span_relationship: :link) + start_supervised!(E2EEventHandler) + :ok + end + + test "dispatch and aggregate are children, event handler is linked" do + aggregate_uuid = UUID.uuid4() + + {http_trace_id, http_span_id} = + Tracer.with_span "http.server.request" do + ctx = Tracer.current_span_ctx() + trace_id = :otel_span.trace_id(ctx) + span_id = :otel_span.span_id(ctx) + + :ok = App.dispatch(%IncrementCount{aggregate_uuid: aggregate_uuid}) + + {trace_id, span_id} + end + + spans = collect_spans_until(["dispatch", "execute", "handle"]) + + dispatch_span = find_span_prefix(spans, "dispatch") + execute_span = find_span_prefix(spans, "execute") + handle_span = find_span_prefix(spans, "handle") + + assert span(dispatch_span, :trace_id) == http_trace_id + assert span(dispatch_span, :parent_span_id) == http_span_id + + dispatch_span_id = span(dispatch_span, :span_id) + assert span(execute_span, :trace_id) == http_trace_id + assert span(execute_span, :parent_span_id) == dispatch_span_id + + assert span(handle_span, :trace_id) != http_trace_id, + "Event handler should start a new trace, not join the original" + + assert span(handle_span, :parent_span_id) == :undefined, + "Event handler should have no parent (root of its own trace)" + + [first_link | _] = :otel_links.list(span(handle_span, :links)) + + assert link(first_link, :trace_id) == http_trace_id, + "Event handler link should reference the original trace" + + assert link(first_link, :span_id) == dispatch_span_id, + "Event handler link should point to the dispatch span" + end + + test "dispatch telemetry metadata has no traceparent (middleware runs after)" do + aggregate_uuid = UUID.uuid4() + test_pid = self() + + :telemetry.attach( + "metadata-spy-dispatch", + [:commanded, :application, :dispatch, :start], + fn _event, _measurements, meta, _config -> + send(test_pid, {:dispatch_metadata, meta.execution_context.metadata}) + end, + nil + ) + + :telemetry.attach( + "metadata-spy-aggregate", + [:commanded, :aggregate, :execute, :start], + fn _event, _measurements, meta, _config -> + send(test_pid, {:aggregate_metadata, meta.execution_context.metadata}) + end, + nil + ) + + Tracer.with_span "http.server.request" do + :ok = App.dispatch(%IncrementCount{aggregate_uuid: aggregate_uuid}) + end + + assert_receive {:dispatch_metadata, dispatch_meta}, 1000 + assert_receive {:aggregate_metadata, aggregate_meta}, 1000 + + refute Map.has_key?(dispatch_meta, "traceparent"), + "dispatch :start should NOT have traceparent (middleware hasn't run yet)" + + assert Map.has_key?(aggregate_meta, "traceparent"), + "aggregate :start should have traceparent (middleware already ran)" + + :telemetry.detach("metadata-spy-dispatch") + :telemetry.detach("metadata-spy-aggregate") + end + + defp start_event_store do + alias Commanded.EventStore.Adapters.EventStore.Storage + + config = Storage.config() + + on_exit(fn -> + {:ok, conn} = Storage.connect(config) + Storage.reset!(conn, config) + end) + end + + defp find_span_prefix(spans, prefix) do + Enum.find(spans, fn s -> String.starts_with?(span(s, :name), prefix) end) + end + + defp collect_spans_until(expected_prefixes, timeout \\ 5000) do + deadline = System.monotonic_time(:millisecond) + timeout + collect_spans_until([], expected_prefixes, deadline) + end + + defp collect_spans_until(acc, expected_prefixes, deadline) do + remaining = max(deadline - System.monotonic_time(:millisecond), 0) + + if has_all_prefixes?(acc, expected_prefixes) do + Enum.reverse(acc) + else + receive do + {:span, s} -> collect_spans_until([s | acc], expected_prefixes, deadline) + after + remaining -> Enum.reverse(acc) + end + end + end + + defp has_all_prefixes?(spans, prefixes) do + Enum.all?(prefixes, fn prefix -> + Enum.any?(spans, fn s -> String.starts_with?(span(s, :name), prefix) end) + end) + end + + defp detach_all_handlers do + commanded_events = [ + [:commanded, :application, :dispatch, :start], + [:commanded, :application, :dispatch, :stop], + [:commanded, :application, :dispatch, :exception], + [:commanded, :aggregate, :execute, :start], + [:commanded, :aggregate, :execute, :stop], + [:commanded, :aggregate, :execute, :exception], + [:commanded, :event, :handle, :start], + [:commanded, :event, :handle, :stop], + [:commanded, :event, :handle, :exception] + ] + + for event <- commanded_events, + handler <- :telemetry.list_handlers(event) do + :telemetry.detach(handler.id) + end + end +end diff --git a/test/opentelemetry/application_test.exs b/test/opentelemetry/application_test.exs index 6959f908..8194c662 100644 --- a/test/opentelemetry/application_test.exs +++ b/test/opentelemetry/application_test.exs @@ -7,6 +7,8 @@ defmodule Commanded.OpenTelemetry.ApplicationTest do alias Commanded.TestSupport.Factory alias Commanded.UUID + require OpenTelemetry.Tracer, as: Tracer + setup do start_supervised!(DefaultApp) @@ -104,6 +106,79 @@ defmodule Commanded.OpenTelemetry.ApplicationTest do end end + describe "context propagation — dispatch within an active span" do + @describetag :context_propagation + + test "dispatch span becomes a child of the active parent span (same trace_id, correct parent_span_id)" do + causation_id = UUID.uuid4() + correlation_id = UUID.uuid4() + + # Simulate a gRPC/HTTP handler that creates a parent span, then dispatches a command. + # The dispatch span MUST be a child of this parent span. + {parent_trace_id, parent_span_id} = + Tracer.with_span "grpc.server.request" do + ctx = Tracer.current_span_ctx() + parent_trace_id = :otel_span.trace_id(ctx) + parent_span_id = :otel_span.span_id(ctx) + + meta = + Factory.build_application_dispatch_metadata( + causation_id: causation_id, + correlation_id: correlation_id + ) + + :telemetry.execute([:commanded, :application, :dispatch, :start], %{}, meta) + + :telemetry.execute( + [:commanded, :application, :dispatch, :stop], + %{duration: 1000}, + meta + ) + + {parent_trace_id, parent_span_id} + end + + assert_receive {:span, + span( + name: "dispatch Commanded.TestSupport.TestDomain.Account", + trace_id: dispatch_trace_id, + parent_span_id: dispatch_parent_span_id + )}, + 1000 + + assert dispatch_trace_id == parent_trace_id, + "Dispatch span should share the same trace_id as the parent span. " <> + "Expected: #{parent_trace_id}, got: #{dispatch_trace_id}. " <> + "This means the dispatch span started a new trace instead of joining the parent." + + assert dispatch_parent_span_id == parent_span_id, + "Dispatch span's parent_span_id should be the gRPC server span. " <> + "Expected: #{parent_span_id}, got: #{inspect(dispatch_parent_span_id)}. " <> + "This means context propagation is broken — the dispatch span is disconnected." + end + + test "dispatch span without active parent and no metadata starts a new trace" do + causation_id = UUID.uuid4() + correlation_id = UUID.uuid4() + + meta = + Factory.build_application_dispatch_metadata( + causation_id: causation_id, + correlation_id: correlation_id + ) + + :telemetry.execute([:commanded, :application, :dispatch, :start], %{}, meta) + :telemetry.execute([:commanded, :application, :dispatch, :stop], %{duration: 1000}, meta) + + assert_receive {:span, + span( + name: "dispatch Commanded.TestSupport.TestDomain.Account", + parent_span_id: :undefined + )}, + 1000 + end + end + describe "error handling" do setup do detach_handlers() diff --git a/test/opentelemetry/helpers_test.exs b/test/opentelemetry/helpers_test.exs new file mode 100644 index 00000000..f9a717b8 --- /dev/null +++ b/test/opentelemetry/helpers_test.exs @@ -0,0 +1,183 @@ +defmodule Commanded.OpenTelemetry.HelpersTest do + use Commanded.OpenTelemetryCase, async: false + + alias Commanded.OpenTelemetry.Helpers + + require OpenTelemetry.Tracer, as: Tracer + + describe "extract_propagated_ctx/1" do + test "returns {[], :undefined} for nil metadata" do + assert {[], :undefined} = Helpers.extract_propagated_ctx(nil) + end + + test "returns {[], :undefined} for empty metadata map" do + assert {[], :undefined} = Helpers.extract_propagated_ctx(%{}) + end + + test "returns {[], :undefined} for metadata without traceparent" do + assert {[], :undefined} = Helpers.extract_propagated_ctx(%{"foo" => "bar"}) + end + + test "returns {[], :undefined} for invalid traceparent" do + assert {[], :undefined} = Helpers.extract_propagated_ctx(%{"traceparent" => "not-valid"}) + end + + test "returns {links, ctx} for valid traceparent" do + {expected_trace_id, expected_span_id, traceparent} = make_traceparent() + + {links, ctx} = Helpers.extract_propagated_ctx(%{"traceparent" => traceparent}) + + refute ctx == :undefined + + assert [%{trace_id: ^expected_trace_id, span_id: ^expected_span_id}] = links + end + + test "returned ctx contains the extracted span context" do + {expected_trace_id, expected_span_id, traceparent} = make_traceparent() + + {_links, ctx} = Helpers.extract_propagated_ctx(%{"traceparent" => traceparent}) + + span_ctx = :otel_tracer.current_span_ctx(ctx) + assert :otel_span.trace_id(span_ctx) == expected_trace_id + assert :otel_span.span_id(span_ctx) == expected_span_id + end + + test "handles traceparent with tracestate" do + {expected_trace_id, _span_id, traceparent} = make_traceparent() + + metadata = %{ + "traceparent" => traceparent, + "tracestate" => "vendor=opaque" + } + + {links, ctx} = Helpers.extract_propagated_ctx(metadata) + + refute ctx == :undefined + assert [%{trace_id: ^expected_trace_id}] = links + end + + test "does not attach the extracted context to the process dictionary" do + before_ctx = :otel_ctx.get_current() + + {_links, _ctx} = make_traceparent() |> make_metadata() |> Helpers.extract_propagated_ctx() + + after_ctx = :otel_ctx.get_current() + assert before_ctx == after_ctx + end + end + + describe "clear_ctx/0" do + test "replaces current context with an empty one" do + {_links, ctx} = make_traceparent() |> make_metadata() |> Helpers.extract_propagated_ctx() + :otel_ctx.attach(ctx) + + span_before = :otel_tracer.current_span_ctx() + refute span_before == :undefined + + Helpers.clear_ctx() + + span_after = :otel_tracer.current_span_ctx() + refute :otel_span.is_valid(span_after) + end + + test "clears stale context from a previous attach" do + stale_traceparent = + Tracer.with_span "stale.span" do + encode_traceparent(Tracer.current_span_ctx()) + end + + stale_headers = [{"traceparent", stale_traceparent}] + stale_ctx = :otel_propagator_text_map.extract_to(:otel_ctx.new(), stale_headers) + :otel_ctx.attach(stale_ctx) + + assert :otel_span.is_valid(:otel_tracer.current_span_ctx()) + + Helpers.clear_ctx() + + refute :otel_span.is_valid(:otel_tracer.current_span_ctx()) + end + end + + describe "extract_propagated_ctx + clear_ctx integration" do + test ":link pattern — extract links then clear context" do + {expected_trace_id, expected_span_id, traceparent} = make_traceparent() + + {links, _ctx} = Helpers.extract_propagated_ctx(%{"traceparent" => traceparent}) + Helpers.clear_ctx() + + assert [%{trace_id: ^expected_trace_id, span_id: ^expected_span_id}] = links + + refute :otel_span.is_valid(:otel_tracer.current_span_ctx()) + end + + test ":child pattern — extract and attach valid context" do + {expected_trace_id, _span_id, traceparent} = make_traceparent() + + case Helpers.extract_propagated_ctx(%{"traceparent" => traceparent}) do + {_links, :undefined} -> Helpers.clear_ctx() + {_links, ctx} -> :otel_ctx.attach(ctx) + end + + span_ctx = :otel_tracer.current_span_ctx() + assert :otel_span.is_valid(span_ctx) + assert :otel_span.trace_id(span_ctx) == expected_trace_id + end + + test ":child pattern — clear context when no valid traceparent" do + stale_headers = [{"traceparent", make_traceparent() |> elem(2)}] + stale_ctx = :otel_propagator_text_map.extract_to(:otel_ctx.new(), stale_headers) + :otel_ctx.attach(stale_ctx) + + case Helpers.extract_propagated_ctx(%{}) do + {_links, :undefined} -> Helpers.clear_ctx() + {_links, ctx} -> :otel_ctx.attach(ctx) + end + + refute :otel_span.is_valid(:otel_tracer.current_span_ctx()) + end + + test ":none pattern — always clear regardless of metadata" do + {_trace_id, _span_id, traceparent} = make_traceparent() + + Helpers.clear_ctx() + + refute :otel_span.is_valid(:otel_tracer.current_span_ctx()) + + stale_headers = [{"traceparent", traceparent}] + stale_ctx = :otel_propagator_text_map.extract_to(:otel_ctx.new(), stale_headers) + :otel_ctx.attach(stale_ctx) + + Helpers.clear_ctx() + + refute :otel_span.is_valid(:otel_tracer.current_span_ctx()) + end + end + + defp make_traceparent do + Tracer.with_span "test.parent.span" do + ctx = Tracer.current_span_ctx() + + { + :otel_span.trace_id(ctx), + :otel_span.span_id(ctx), + encode_traceparent(ctx) + } + end + end + + defp make_metadata({_trace_id, _span_id, traceparent}) do + %{"traceparent" => traceparent} + end + + defp encode_traceparent(span_ctx) do + trace_id = :otel_span.trace_id(span_ctx) + span_id = :otel_span.span_id(span_ctx) + trace_flags = span_ctx(span_ctx, :trace_flags) + + hex_trace_id = :io_lib.format("~32.16.0b", [trace_id]) |> IO.iodata_to_binary() + hex_span_id = :io_lib.format("~16.16.0b", [span_id]) |> IO.iodata_to_binary() + hex_flags = :io_lib.format("~2.16.0b", [trace_flags]) |> IO.iodata_to_binary() + + "00-#{hex_trace_id}-#{hex_span_id}-#{hex_flags}" + end +end