feat(error-tracking): add ambient trace IDs to exceptions

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

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(<<trace_id::128>>, case: :lower),
+        "$span_id": Base.encode16(<<span_id::64>>, 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

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
 

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"},

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}

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