diff --git a/.sampo/changesets/ambient-exception-trace-context.md b/.sampo/changesets/ambient-exception-trace-context.md new file mode 100644 index 0000000..89d02fd --- /dev/null +++ b/.sampo/changesets/ambient-exception-trace-context.md @@ -0,0 +1,5 @@ +--- +hex/posthog: minor +--- + +Add the active OpenTelemetry trace and span IDs to exception events when the application provides OpenTelemetry. diff --git a/lib/posthog/handler.ex b/lib/posthog/handler.ex index 43d1779..f192d12 100644 --- a/lib/posthog/handler.ex +++ b/lib/posthog/handler.ex @@ -1,6 +1,14 @@ defmodule PostHog.Handler do @moduledoc """ A [`logger handler`](https://www.erlang.org/doc/apps/kernel/logger_chapter.html#handlers). + + When the application provides OpenTelemetry, exception events include the active + span's `$trace_id` and `$span_id`. The handler reads the span in the process that + logs the exception, including spans that are not sampled. Event context, log + metadata, and global properties take precedence over these derived IDs. + + OpenTelemetry is not required. Missing or unreadable trace context does not + prevent exception capture. """ if System.otp_release() |> String.to_integer() >= 27 do @behaviour :logger_handler @@ -9,6 +17,8 @@ defmodule PostHog.Handler do alias PostHog.Context alias PostHog.ErrorTracking.Sources + @compile {:no_warn_undefined, [:otel_tracer, :otel_span]} + # credo:disable-for-next-line Credo.Check.Design.TagTODO # TODO: add @impl :logger_handler once we drop support for OTP < 27 @doc false @@ -42,6 +52,26 @@ defmodule PostHog.Handler do :ok end + defp trace_properties do + with true <- Code.ensure_loaded?(:otel_tracer), + span <- :otel_tracer.current_span_ctx(), + true <- :otel_span.is_valid(span), + trace_id when trace_id in 1..0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF <- + :otel_span.trace_id(span), + span_id when span_id in 1..0xFFFFFFFFFFFFFFFF <- :otel_span.span_id(span) do + %{ + "$trace_id": Base.encode16(<>, case: :lower), + "$span_id": Base.encode16(<>, case: :lower) + } + else + _ -> %{} + end + rescue + _ -> %{} + catch + _, _ -> %{} + end + defp properties(log_event, config) do exceptions = exceptions(log_event, config) @@ -69,6 +99,18 @@ defmodule PostHog.Handler do |> enrich_context(log_event) |> Map.put(:"$exception_list", exceptions) |> Map.merge(metadata) + |> add_trace_properties(config.global_properties) + end + + defp add_trace_properties(properties, global_properties) do + supplied = Map.merge(properties, global_properties) + + trace_properties() + |> Enum.reject(fn {key, _} -> + Map.has_key?(supplied, key) or Map.has_key?(supplied, Atom.to_string(key)) + end) + |> Map.new() + |> Map.merge(properties) end if Version.match?(System.version(), ">= 1.19.0") and diff --git a/mix.exs b/mix.exs index b152b43..b17c105 100644 --- a/mix.exs +++ b/mix.exs @@ -74,7 +74,8 @@ defmodule PostHog.MixProject do {:ex_doc, "~> 0.37", only: :dev, runtime: false}, {:logger_handler_kit, "~> 0.4", only: :test}, {:credo, "~> 1.7", only: [:dev, :test], runtime: false}, - {:mox, "~> 1.1", only: :test} + {:mox, "~> 1.1", only: :test}, + {:opentelemetry_api, "~> 1.5", only: :test, runtime: false} ] end diff --git a/mix.lock b/mix.lock index 5c53b87..5dbb015 100644 --- a/mix.lock +++ b/mix.lock @@ -24,6 +24,7 @@ "nimble_parsec": {:hex, :nimble_parsec, "1.4.2", "8efba0122db06df95bfaa78f791344a89352ba04baedd3849593bfce4d0dc1c6", [:mix], [], "hexpm", "4b21398942dda052b403bbe1da991ccd03a053668d147d53fb8c4e0efe09c973"}, "nimble_pool": {:hex, :nimble_pool, "1.1.0", "bf9c29fbdcba3564a8b800d1eeb5a3c58f36e1e11d7b7fb2e084a643f645f06b", [:mix], [], "hexpm", "af2e4e6b34197db81f7aad230c1118eac993acc0dae6bc83bac0126d4ae0813a"}, "open_feature": {:hex, :open_feature, "0.1.3", "b03ea38818010dd04c3e690059a8baf14a797c9322af06eb40ac3f81c733474e", [:mix], [], "hexpm", "2dafd79e94384328469c655ef2ddc66647c2531a53b57634e012f952b6afcaf9"}, + "opentelemetry_api": {:hex, :opentelemetry_api, "1.5.0", "1a676f3e3340cab81c763e939a42e11a70c22863f645aa06aafefc689b5550cf", [:mix, :rebar3], [], "hexpm", "f53ec8a1337ae4a487d43ac89da4bd3a3c99ddf576655d071deed8b56a2d5dda"}, "plug": {:hex, :plug, "1.20.3", "56c480c633ec2ce10140e236e15233bf576e1d323887d7c96711bd02ab5160db", [:mix], [{:mime, "~> 1.0 or ~> 2.0", [hex: :mime, repo: "hexpm", optional: false]}, {:plug_crypto, "~> 1.1.1 or ~> 1.2 or ~> 2.0", [hex: :plug_crypto, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4.3 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "be266aee1b8536ef6409d58cf39a3121319f0ec47cfa1b24024485aa0e76ad76"}, "plug_cowboy": {:hex, :plug_cowboy, "2.9.0", "87e21e0d9054ced99c36d128f49e3ea2cd8b745fffb97de50bff99706087af4f", [:mix], [{:cowboy, "~> 2.7", [hex: :cowboy, repo: "hexpm", optional: false]}, {:cowboy_telemetry, "~> 0.3", [hex: :cowboy_telemetry, repo: "hexpm", optional: false]}, {:plug, "~> 1.18", [hex: :plug, repo: "hexpm", optional: false]}], "hexpm", "2002bafba4f3a45b55a58e68d70211b153a7ed18d37edb1ceb6e96e7a92c422e"}, "plug_crypto": {:hex, :plug_crypto, "2.2.0", "144014737daaf485407f5ed77daeaad74d651b216a28c87543f8cc7043f8efc8", [:mix], [], "hexpm", "83a95744ab1c75876542b6fab135fcc176280e0f301a111c1f757fddcec95d2c"}, diff --git a/test/posthog/handler_test.exs b/test/posthog/handler_test.exs index 86b2ef3..cb81311 100644 --- a/test/posthog/handler_test.exs +++ b/test/posthog/handler_test.exs @@ -11,6 +11,127 @@ defmodule PostHog.HandlerTest do setup :setup_supervisor setup :setup_logger_handler + for {name, trace_id, span_id, flags, properties} <- [ + {"sampled", 0x123456789ABCDEF0123456789ABCDEF0, 0x123456789ABCDEF0, 1, %{}}, + {"unsampled", 0x123456789ABCDEF0123456789ABCDEF0, 0x123456789ABCDEF0, 0, %{}}, + {"leading zeros", 3, 4, 0, %{}}, + {"caller trace ID", 3, 4, 1, %{"$trace_id": "caller-trace"}}, + {"caller span ID", 3, 4, 1, %{"$span_id": "caller-span"}} + ] do + @trace_id trace_id + @span_id span_id + @trace_flags flags + @trace_properties properties + + test "adds active trace context to exceptions: #{name}", %{ + handler_ref: ref, + config: %{supervisor_name: supervisor_name} + } do + span = :otel_tracer.non_recording_span(@trace_id, @span_id, @trace_flags) + context = :otel_tracer.set_current_span(:otel_ctx.new(), span) + token = :otel_ctx.attach(context) + PostHog.set_event_context(supervisor_name, "$exception", @trace_properties) + + try do + Logger.error("Example failure", distinct_id: "example-user") + LoggerHandlerKit.Assert.assert_logged(ref) + after + :otel_ctx.detach(token) + end + + assert [%{event: "$exception", properties: properties}] = all_captured(supervisor_name) + + expected = + Map.merge( + %{ + "$trace_id": Base.encode16(<<@trace_id::128>>, case: :lower), + "$span_id": Base.encode16(<<@span_id::64>>, case: :lower) + }, + @trace_properties + ) + + assert Map.take(properties, [:"$trace_id", :"$span_id"]) == expected + + Logger.error("Outside the span", distinct_id: "example-user") + LoggerHandlerKit.Assert.assert_logged(ref) + + assert [%{properties: outside_properties}, _] = all_captured(supervisor_name) + assert Map.take(outside_properties, [:"$trace_id", :"$span_id"]) == @trace_properties + end + end + + for {name, source, properties} <- [ + {"atom event context", :context, + %{"$trace_id": "caller-trace", "$span_id": "caller-span"}}, + {"string event context", :context, + %{"$trace_id" => "caller-trace", "$span_id" => "caller-span"}}, + {"atom log metadata", :metadata, + %{"$trace_id": "caller-trace", "$span_id": "caller-span"}}, + {"string log metadata", :metadata, + %{"$trace_id" => "caller-trace", "$span_id" => "caller-span"}}, + {"atom global properties", :global, + %{"$trace_id": "caller-trace", "$span_id": "caller-span"}} + ] do + @source source + @properties properties + @tag config: [ + metadata: :all, + global_properties: if(source == :global, do: properties, else: %{}) + ] + + test "preserves trace IDs from #{name}", %{ + handler_ref: ref, + config: %{supervisor_name: supervisor_name} + } do + span = :otel_tracer.non_recording_span(3, 4, 1) + token = :otel_ctx.attach(:otel_tracer.set_current_span(:otel_ctx.new(), span)) + + if @source == :context do + PostHog.set_event_context(supervisor_name, "$exception", @properties) + end + + metadata = if @source == :metadata, do: @properties, else: %{} + + try do + :logger.log(:error, "Example failure", metadata) + LoggerHandlerKit.Assert.assert_logged(ref) + after + :otel_ctx.detach(token) + end + + assert [%{properties: captured}] = all_captured(supervisor_name) + trace_keys = [:"$trace_id", :"$span_id", "$trace_id", "$span_id"] + assert Map.take(captured, trace_keys) == @properties + end + end + + for {name, span} <- [ + {"no active span", :undefined}, + {"zero trace ID", :otel_tracer.non_recording_span(0, 4, 1)}, + {"zero span ID", :otel_tracer.non_recording_span(3, 0, 1)} + ] do + @span span + + test "omits invalid ambient trace context: #{name}", %{ + handler_ref: ref, + config: %{supervisor_name: supervisor_name} + } do + context = :otel_tracer.set_current_span(:otel_ctx.new(), @span) + token = :otel_ctx.attach(context) + + try do + Logger.error("Example failure", distinct_id: "example-user") + LoggerHandlerKit.Assert.assert_logged(ref) + after + :otel_ctx.detach(token) + end + + assert [%{event: "$exception", properties: properties}] = all_captured(supervisor_name) + refute Map.has_key?(properties, :"$trace_id") + refute Map.has_key?(properties, :"$span_id") + end + end + test "takes distinct_id from metadata", %{ handler_ref: ref, config: %{supervisor_name: supervisor_name} diff --git a/test/posthog/handler_trace_context_isolation_test.exs b/test/posthog/handler_trace_context_isolation_test.exs new file mode 100644 index 0000000..276593a --- /dev/null +++ b/test/posthog/handler_trace_context_isolation_test.exs @@ -0,0 +1,57 @@ +defmodule PostHog.HandlerTraceContextIsolationTest do + use ExUnit.Case, async: true + + for failure <- [:absent, :raise, :throw, :exit] do + @failure failure + + test "captures exceptions when the OpenTelemetry API is #{@failure}" do + script = """ + false = Code.ensure_loaded?(:otel_tracer) + if #{@failure != :absent} do + defmodule :otel_tracer do + def current_span_ctx, do: #{@failure}("Example lookup failure") + end + end + + Application.load(:posthog) + Application.put_env(:posthog, :enable, false) + {:ok, _} = Application.ensure_all_started(:posthog) + + config = PostHog.Config.validate!( + api_key: "example-key", + api_host: "https://example.com", + before_send: fn event -> send(self(), {:captured, event}); nil end + ) + {:ok, _} = PostHog.Supervisor.start_link(config) + :ok = :logger.add_handler(:trace_test, PostHog.Handler, %{config: config}) + + require Logger + Logger.error("Example failure", distinct_id: "example-user") + + receive do + {:captured, %{event: "$exception", properties: properties}} -> + if Map.has_key?(properties, :"$trace_id") or Map.has_key?(properties, :"$span_id"), + do: raise("Unexpected derived trace IDs") + IO.puts("exception captured") + after + 0 -> raise "Exception was not captured" + end + """ + + paths = + :code.get_path() + |> Enum.map(&List.to_string/1) + |> Enum.reject(&(Path.basename(Path.dirname(&1)) == "opentelemetry_api")) + |> Enum.flat_map(&["-pa", &1]) + + {output, status} = + System.cmd(System.find_executable("elixir"), paths ++ ["-e", script], + stderr_to_stdout: true, + env: [{"ERL_FLAGS", "+S 2:2"}] + ) + + assert status == 0, output + assert output =~ "exception captured" + end + end +end