OpenTelemetry improvements (#6007)

* include trace_id in log comments

* site team_id to OpenTelemetry attributes

* Move tracing to QueryRunner so that all queries profit from additional attributes in their spans

* Add trace_id assertion to debug metadata test

* Fix warning

* add trace_id

* remove integer check

* log trace_id to correlate logs and traces

* Update lib/plausible/clickhouse_repo.ex

Co-authored-by: Adrian Gruntkowski <adrian.gruntkowski@gmail.com>

* Update lib/plausible/open_telemetry/logger.ex

Co-authored-by: Adrian Gruntkowski <adrian.gruntkowski@gmail.com>

* mix format

* Refactor trace_id retrieval

---------

Co-authored-by: Adrian Gruntkowski <adrian.gruntkowski@gmail.com>

Author: cnkk

config/runtime.exs

@@ -27,7 +27,7 @@ log_level =
   |> String.to_existing_atom()
 
 config :logger, level: log_level
-config :logger, :default_formatter, metadata: [:request_id]
+config :logger, :default_formatter, metadata: [:request_id, :trace_id]
 
 config :logger, Sentry.LoggerBackend,
   capture_log_messages: true,

lib/plausible/application.ex

@@ -371,6 +371,7 @@ defmodule Plausible.Application do
     OpentelemetryEcto.setup([:plausible, :repo])
     OpentelemetryEcto.setup([:plausible, :clickhouse_repo])
     OpentelemetryOban.setup()
+    Plausible.OpenTelemetry.Logger.setup()
   end
 
   defp setup_geolocation do

lib/plausible/clickhouse_repo.ex

@@ -46,7 +46,17 @@ defmodule Plausible.ClickhouseRepo do
   @impl true
   def prepare_query(_operation, query, opts) do
     {plausible_query, opts} = Keyword.pop(opts, :query)
-    log_comment = if(plausible_query, do: Jason.encode!(plausible_query.debug_metadata), else: "")
+
+    trace_id = Plausible.OpenTelemetry.current_trace_id()
+
+    log_comment_data =
+      if plausible_query do
+        Map.put(plausible_query.debug_metadata, :trace_id, trace_id)
+      else
+        %{trace_id: trace_id}
+      end
+
+    log_comment = Jason.encode!(log_comment_data)
 
     opts =
       Keyword.update(opts, :settings, [log_comment: log_comment], fn settings ->

lib/plausible/open_telemetry.ex

@@ -3,12 +3,26 @@ defmodule Plausible.OpenTelemetry do
 
   require OpenTelemetry.Tracer, as: Tracer
 
+  def current_trace_id do
+    case OpenTelemetry.Tracer.current_span_ctx() do
+      :undefined ->
+        nil
+
+      span_ctx ->
+        span_ctx
+        |> OpenTelemetry.Span.trace_id()
+        |> Integer.to_string(16)
+        |> String.downcase()
+    end
+  end
+
   def add_site_attributes(site) do
     case site do
       %Plausible.Site{} = site ->
         Tracer.set_attributes([
           {"plausible.site.id", site.id},
-          {"plausible.site.domain", site.domain}
+          {"plausible.site.domain", site.domain},
+          {"plausible.site.team_id", site.team_id}
         ])
 
       id when is_integer(id) ->

lib/plausible/open_telemetry/logger.ex

@@ -0,0 +1,36 @@
+defmodule Plausible.OpenTelemetry.Logger do
+  @moduledoc """
+  Telemetry handler that adds the OpenTelemetry trace_id to Logger metadata.
+
+  This enables correlation between log lines and distributed traces.
+  The trace_id is extracted from the current OTel span context and added
+  to the Logger metadata when Phoenix router dispatch starts.
+  """
+
+  require Logger
+
+  @doc """
+  Attaches telemetry handlers to set trace_id in Logger metadata.
+
+  Should be called during application startup, after OpentelemetryPhoenix.setup().
+  """
+  def setup do
+    :telemetry.attach(
+      "plausible-otel-logger-metadata",
+      [:phoenix, :router_dispatch, :start],
+      &__MODULE__.handle_router_dispatch_start/4,
+      %{}
+    )
+  end
+
+  @doc false
+  def handle_router_dispatch_start(_event, _measurements, _metadata, _config) do
+    case Plausible.OpenTelemetry.current_trace_id() do
+      nil ->
+        :ok
+
+      trace_id_hex ->
+        Logger.metadata(trace_id: trace_id_hex)
+    end
+  end
+end

lib/plausible/stats/aggregate.ex

@@ -9,8 +9,6 @@ defmodule Plausible.Stats.Aggregate do
   alias Plausible.Stats.{Query, QueryRunner, QueryResult, QueryOptimizer}
 
   def aggregate(site, query, metrics) do
-    Query.trace(query, metrics)
-
     query =
       query
       |> Query.set(metrics: metrics, remove_unavailable_revenue_metrics: true)

lib/plausible/stats/query_runner.ex

@@ -15,6 +15,7 @@ defmodule Plausible.Stats.QueryRunner do
   alias Plausible.Stats.{
     Comparisons,
     Compare,
+    Query,
     QueryOptimizer,
     QueryResult,
     Metrics,
@@ -36,6 +37,8 @@ defmodule Plausible.Stats.QueryRunner do
   def run(site, query) do
     optimized_query = QueryOptimizer.optimize(query)
 
+    Query.trace(optimized_query, optimized_query.metrics)
+
     %__MODULE__{main_query: optimized_query, site: site}
     |> execute_main_query()
     |> add_comparison_query()

test/plausible_web/controllers/api/external_stats_controller/debug_metadata_test.exs

@@ -16,7 +16,7 @@ defmodule PlausibleWeb.Api.ExternalController.DebugMetadataTest do
       }
 
       conn =
-        post(conn, "api/v2/query", query)
+        post(conn, "/api/v2/query", query)
 
       assert json_response(conn, 200)
 
@@ -38,10 +38,11 @@ defmodule PlausibleWeb.Api.ExternalController.DebugMetadataTest do
                          "phoenix_controller" =>
                            "Elixir.PlausibleWeb.Api.ExternalQueryApiController",
                          "request_method" => "POST",
-                         "request_path" => "api/v2/query",
+                         "request_path" => "/api/v2/query",
                          "site_domain" => ^site.domain,
                          "site_id" => ^site.id,
                          "team_id" => ^team_of(user).id,
+                         "trace_id" => _,
                          "user_id" => ^user.id
                        }) = decoded
 

test/plausible_web/controllers/api/stats_controller/debug_metadata_test.exs

@@ -32,6 +32,7 @@ defmodule PlausibleWeb.Api.StatsController.DebugMetadataTest do
                          "site_domain" => ^site.domain,
                          "site_id" => ^site.id,
                          "team_id" => ^team_of(user).id,
+                         "trace_id" => _,
                          "user_id" => ^user.id
                        }) = decoded
       end
@@ -90,6 +91,7 @@ defmodule PlausibleWeb.Api.StatsController.DebugMetadataTest do
                            "site_id" => ^site.id,
                            # nil team_id because viewing a public/shared dashboard
                            "team_id" => nil,
+                           "trace_id" => _,
                            # the logged in user ID is included even when viewing a random public dashboard
                            "user_id" => ^user.id
                          }) = decoded