diff --git a/test_integrations/phoenix_app/lib/phoenix_app_web/controllers/async_trace_controller.ex b/test_integrations/phoenix_app/lib/phoenix_app_web/controllers/async_trace_controller.ex new file mode 100644 index 00000000..aa6d9238 --- /dev/null +++ b/test_integrations/phoenix_app/lib/phoenix_app_web/controllers/async_trace_controller.ex @@ -0,0 +1,83 @@ +defmodule PhoenixAppWeb.AsyncTraceController do + @moduledoc """ + Scenarios where spans outlive the HTTP request that started them. + + Exercised by the tracing e2e suite, and useful for manually verifying + reported traces in the Sentry UI: run the server with a real `SENTRY_DSN` + and click through `/async-traces`. + """ + + use PhoenixAppWeb, :controller + + require OpenTelemetry.Tracer, as: Tracer + + alias PhoenixApp.Repo + + @task_work_ms 500 + + def index(conn, _params) do + html(conn, """ + + Async trace scenarios + +

Async trace scenarios

+ + + + """) + end + + def in_flight(conn, _params) do + caller = self() + ctx = :otel_ctx.get_current() + + {:ok, _pid} = + Task.start(fn -> + token = :otel_ctx.attach(ctx) + + try do + Tracer.with_span "deliver_report" do + send(caller, :report_started) + Process.sleep(@task_work_ms) + end + after + :otel_ctx.detach(token) + end + end) + + receive do + :report_started -> :ok + after + 1_000 -> :ok + end + + json(conn, %{status: "report delivery in progress"}) + end + + def nested(conn, _params) do + Tracer.with_span "process_batch" do + Repo.query!("SELECT 1") + ctx = :otel_ctx.get_current() + + {:ok, _pid} = + Task.start(fn -> + token = :otel_ctx.attach(ctx) + + try do + Process.sleep(@task_work_ms) + + Tracer.with_span "finalize_batch" do + Process.sleep(10) + end + after + :otel_ctx.detach(token) + end + end) + end + + json(conn, %{status: "batch scheduled"}) + end +end diff --git a/test_integrations/phoenix_app/lib/phoenix_app_web/controllers/distributed_trace_controller.ex b/test_integrations/phoenix_app/lib/phoenix_app_web/controllers/distributed_trace_controller.ex new file mode 100644 index 00000000..13c81743 --- /dev/null +++ b/test_integrations/phoenix_app/lib/phoenix_app_web/controllers/distributed_trace_controller.ex @@ -0,0 +1,104 @@ +defmodule PhoenixAppWeb.DistributedTraceController do + @moduledoc """ + Scenarios where this node continues a trace started by an upstream service. + + The handoff scenario mirrors work dispatched to a background worker or a + separate runner node: the upstream W3C context is carried along and the + spans are created after the request that delivered it has already finished, + so their parent belongs to another process entirely. + + Exercised by the tracing e2e suite, and useful for manually verifying + reported traces in the Sentry UI: run the server with a real `SENTRY_DSN` + and click through `/distributed-traces`. + """ + + use PhoenixAppWeb, :controller + + require OpenTelemetry.Tracer, as: Tracer + + alias PhoenixApp.Repo + + @handoff_delay_ms 400 + + def index(conn, _params) do + html(conn, """ + + Distributed trace scenarios + +

Distributed trace scenarios

+ +

+        
+      
+    
+    """)
+  end
+
+  def handoff(conn, _params) do
+    case upstream_traceparent(conn) do
+      nil ->
+        conn
+        |> put_status(:bad_request)
+        |> json(%{error: "no traceparent or sentry-trace header"})
+
+      traceparent ->
+        start_background_sync(traceparent)
+        json(conn, %{status: "sync scheduled", upstream: traceparent})
+    end
+  end
+
+  defp start_background_sync(traceparent) do
+    {:ok, _pid} =
+      Task.start(fn ->
+        Process.sleep(@handoff_delay_ms)
+
+        :otel_propagator_text_map.extract([{"traceparent", traceparent}])
+
+        Tracer.with_span "sync.run" do
+          Repo.query!("SELECT 1")
+        end
+      end)
+
+    :ok
+  end
+
+  defp upstream_traceparent(conn) do
+    case get_req_header(conn, "traceparent") do
+      [traceparent | _] -> traceparent
+      [] -> conn |> get_req_header("sentry-trace") |> from_sentry_trace()
+    end
+  end
+
+  defp from_sentry_trace([sentry_trace | _]) do
+    case String.split(sentry_trace, "-") do
+      [trace_id, span_id | rest] ->
+        flags = if rest == ["0"], do: "00", else: "01"
+        "00-#{trace_id}-#{span_id}-#{flags}"
+
+      _ ->
+        nil
+    end
+  end
+
+  defp from_sentry_trace(_), do: nil
+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 0c614e34..12bdfd46 100644
--- a/test_integrations/phoenix_app/lib/phoenix_app_web/router.ex
+++ b/test_integrations/phoenix_app/lib/phoenix_app_web/router.ex
@@ -40,6 +40,13 @@ defmodule PhoenixAppWeb.Router do
 
     live "/test-worker", TestWorkerLive
     live "/async-report", AsyncReportLive
+
+    get "/async-traces", AsyncTraceController, :index
+    get "/async-traces/in-flight", AsyncTraceController, :in_flight
+    get "/async-traces/nested", AsyncTraceController, :nested
+
+    get "/distributed-traces", DistributedTraceController, :index
+    get "/distributed-traces/handoff", DistributedTraceController, :handoff
     live "/tracing-test", TracingTestLive
 
     live "/users", UserLive.Index, :index
diff --git a/test_integrations/tracing/tests/async_traces.spec.ts b/test_integrations/tracing/tests/async_traces.spec.ts
new file mode 100644
index 00000000..bf34efaa
--- /dev/null
+++ b/test_integrations/tracing/tests/async_traces.spec.ts
@@ -0,0 +1,126 @@
+import { test, expect } from "@playwright/test";
+import {
+  clearLoggedEvents,
+  waitForEvents,
+  type SentryEvent,
+  type TransactionWithSpans,
+} from "./helpers";
+
+const PHOENIX_URL = process.env.SENTRY_E2E_PHOENIX_APP_URL;
+if (!PHOENIX_URL) {
+  throw new Error(
+    "Required environment variable SENTRY_E2E_PHOENIX_APP_URL is not set."
+  );
+}
+
+function transactions(events: SentryEvent[]): TransactionWithSpans[] {
+  return events.filter(
+    (e) => e.type === "transaction"
+  ) as TransactionWithSpans[];
+}
+
+function findByRoute(
+  events: SentryEvent[],
+  route: string
+): TransactionWithSpans | undefined {
+  return transactions(events).find(
+    (t) => t.contexts?.trace?.data?.["http.route"] === route
+  );
+}
+
+function findByName(
+  events: SentryEvent[],
+  name: string
+): TransactionWithSpans | undefined {
+  return transactions(events).find((t) => t.transaction === name);
+}
+
+test.describe("Async trace continuation", () => {
+  test.beforeEach(() => {
+    clearLoggedEvents();
+  });
+
+  test("work outliving the request is reported as a linked follow-up transaction", async ({
+    page,
+  }) => {
+    await page.goto(`${PHOENIX_URL}/async-traces/in-flight`);
+
+    const logged = await waitForEvents((l) =>
+      Boolean(
+        findByRoute(l.events, "/async-traces/in-flight") &&
+          findByName(l.events, "deliver_report")
+      )
+    );
+
+    const requestTx = findByRoute(logged.events, "/async-traces/in-flight");
+    const followUpTx = findByName(logged.events, "deliver_report");
+
+    expect(requestTx).toBeDefined();
+    expect(followUpTx).toBeDefined();
+
+    const requestTrace = requestTx!.contexts?.trace;
+    expect(requestTrace?.op).toBe("http.server");
+
+    const requestSpans = requestTx!.spans ?? [];
+    for (const span of requestSpans) {
+      expect(span.timestamp, `span ${span.description} has no end timestamp`)
+        .toBeTruthy();
+    }
+    expect(requestSpans.map((s) => s.description)).not.toContain(
+      "deliver_report"
+    );
+
+    const followUpTrace = followUpTx!.contexts?.trace;
+    expect(followUpTrace?.trace_id).toBe(requestTrace?.trace_id);
+    expect(followUpTrace?.parent_span_id).toBe(requestTrace?.span_id);
+    expect(followUpTrace?.data?.["sentry.parent_span_already_sent"]).toBe(
+      true
+    );
+  });
+
+  test("late work from a nested span is reported as a linked follow-up transaction", async ({
+    page,
+  }) => {
+    await page.goto(`${PHOENIX_URL}/async-traces/nested`);
+
+    const logged = await waitForEvents((l) =>
+      Boolean(
+        findByRoute(l.events, "/async-traces/nested") &&
+          findByName(l.events, "finalize_batch")
+      )
+    );
+
+    const requestTx = findByRoute(logged.events, "/async-traces/nested");
+    const followUpTx = findByName(logged.events, "finalize_batch");
+
+    expect(requestTx).toBeDefined();
+    expect(followUpTx).toBeDefined();
+
+    const requestSpans = requestTx!.spans ?? [];
+    const batchSpan = requestSpans.find(
+      (s) => s.description === "process_batch"
+    );
+    const dbSpan = requestSpans.find((s) => s.op === "db");
+
+    expect(batchSpan).toBeDefined();
+    expect(dbSpan).toBeDefined();
+    expect(dbSpan!.parent_span_id).toBe(batchSpan!.span_id);
+
+    const followUpTrace = followUpTx!.contexts?.trace;
+    expect(followUpTrace?.trace_id).toBe(
+      requestTx!.contexts?.trace?.trace_id
+    );
+    expect(followUpTrace?.parent_span_id).toBe(batchSpan!.span_id);
+    expect(followUpTrace?.data?.["sentry.parent_span_already_sent"]).toBe(
+      true
+    );
+  });
+
+  test("scenario index page links to both scenarios", async ({ page }) => {
+    await page.goto(`${PHOENIX_URL}/async-traces`);
+
+    await expect(page.locator("h1")).toContainText("Async trace scenarios");
+    await expect(page.locator("a#in-flight")).toBeVisible();
+    await expect(page.locator("a#nested")).toBeVisible();
+  });
+});
diff --git a/test_integrations/tracing/tests/distributed_traces.spec.ts b/test_integrations/tracing/tests/distributed_traces.spec.ts
new file mode 100644
index 00000000..e464bc3a
--- /dev/null
+++ b/test_integrations/tracing/tests/distributed_traces.spec.ts
@@ -0,0 +1,135 @@
+import { test, expect } from "@playwright/test";
+import {
+  clearLoggedEvents,
+  waitForEvents,
+  type SentryEvent,
+  type TransactionWithSpans,
+} from "./helpers";
+
+const PHOENIX_URL = process.env.SENTRY_E2E_PHOENIX_APP_URL;
+if (!PHOENIX_URL) {
+  throw new Error(
+    "Required environment variable SENTRY_E2E_PHOENIX_APP_URL is not set."
+  );
+}
+
+const UPSTREAM_TRACE_ID = "1f2e3d4c5b6a79881f2e3d4c5b6a7988";
+const UPSTREAM_SPAN_ID = "a1b2c3d4e5f60718";
+
+function transactions(events: SentryEvent[]): TransactionWithSpans[] {
+  return events.filter(
+    (e) => e.type === "transaction"
+  ) as TransactionWithSpans[];
+}
+
+function findByName(
+  events: SentryEvent[],
+  name: string
+): TransactionWithSpans | undefined {
+  return transactions(events).find((t) => t.transaction === name);
+}
+
+function findByRoute(
+  events: SentryEvent[],
+  route: string
+): TransactionWithSpans | undefined {
+  return transactions(events).find(
+    (t) => t.contexts?.trace?.data?.["http.route"] === route
+  );
+}
+
+test.describe("Trace continued from an upstream service", () => {
+  test.beforeEach(() => {
+    clearLoggedEvents();
+  });
+
+  test("background work is reported as a segment of the upstream trace", async ({
+    page,
+  }) => {
+    await page.setExtraHTTPHeaders({
+      traceparent: `00-${UPSTREAM_TRACE_ID}-${UPSTREAM_SPAN_ID}-01`,
+    });
+
+    await page.goto(`${PHOENIX_URL}/distributed-traces/handoff`);
+
+    const logged = await waitForEvents((l) =>
+      Boolean(
+        findByRoute(l.events, "/distributed-traces/handoff") &&
+          findByName(l.events, "sync.run")
+      )
+    );
+
+    const requestTx = findByRoute(
+      logged.events,
+      "/distributed-traces/handoff"
+    );
+    const syncTx = findByName(logged.events, "sync.run");
+
+    expect(requestTx).toBeDefined();
+    expect(
+      syncTx,
+      "background sync continuing the upstream trace was not reported"
+    ).toBeDefined();
+
+    // The request span already worked before the fix: it is kind: :server with
+    // an http.request.method attribute, so the old heuristic promoted it.
+    expect(requestTx!.contexts?.trace?.trace_id).toBe(UPSTREAM_TRACE_ID);
+    expect(requestTx!.contexts?.trace?.parent_span_id).toBe(UPSTREAM_SPAN_ID);
+
+    // The background sync is a plain internal span whose parent belongs to the
+    // upstream service, which is what used to be dropped.
+    const syncTrace = syncTx!.contexts?.trace;
+    expect(syncTrace?.trace_id).toBe(UPSTREAM_TRACE_ID);
+    expect(syncTrace?.parent_span_id).toBe(UPSTREAM_SPAN_ID);
+    expect(syncTrace?.op).toBe("sync.run");
+
+    const dbSpan = (syncTx!.spans ?? []).find((s) => s.op === "db");
+    expect(dbSpan, "instrumented db span missing from the sync").toBeDefined();
+    expect(dbSpan!.parent_span_id).toBe(syncTrace?.span_id);
+    expect(dbSpan!.trace_id).toBe(UPSTREAM_TRACE_ID);
+
+    // The upstream context is inherited by every span of the local subtree, so
+    // a promotion rule that keyed off it alone would report each span as its
+    // own transaction instead of nesting them under the sync.
+    const dbTransactions = transactions(logged.events).filter(
+      (t) => t.contexts?.trace?.op === "db"
+    );
+
+    expect(
+      dbTransactions,
+      "instrumented child spans were promoted to their own transactions"
+    ).toHaveLength(0);
+  });
+
+  test("the scenario page triggers the handoff on its own", async ({ page }) => {
+    await page.goto(`${PHOENIX_URL}/distributed-traces`);
+
+    await expect(page.locator("h1")).toContainText(
+      "Distributed trace scenarios"
+    );
+
+    await page.click("a#handoff");
+    await expect(page.locator("#result")).toContainText("upstream: 00-");
+
+    const result = await page.locator("#result").textContent();
+    const traceId = result!.match(/upstream: 00-([0-9a-f]{32})-/)![1];
+
+    const logged = await waitForEvents((l) =>
+      transactions(l.events).some(
+        (t) =>
+          t.transaction === "sync.run" &&
+          t.contexts?.trace?.trace_id === traceId
+      )
+    );
+
+    const syncTx = transactions(logged.events).find(
+      (t) => t.transaction === "sync.run"
+    );
+
+    expect(
+      syncTx,
+      "clicking the scenario link did not produce a reported sync"
+    ).toBeDefined();
+    expect(syncTx!.contexts?.trace?.trace_id).toBe(traceId);
+  });
+});
diff --git a/test_integrations/tracing/tests/helpers.ts b/test_integrations/tracing/tests/helpers.ts
index c1c264fc..28c3c244 100644
--- a/test_integrations/tracing/tests/helpers.ts
+++ b/test_integrations/tracing/tests/helpers.ts
@@ -147,6 +147,8 @@ export interface Span {
   parent_span_id?: string;
   op?: string;
   description?: string;
+  start_timestamp?: string | null;
+  timestamp?: string | null;
   data?: Record;
 }