Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
@@ -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, """
<html>
<head><title>Async trace scenarios</title></head>
<body>
<h1>Async trace scenarios</h1>
<ul>
<li><a id="in-flight" href="/async-traces/in-flight">In-flight report delivery</a></li>
<li><a id="nested" href="/async-traces/nested">Nested batch finalization</a></li>
</ul>
</body>
</html>
""")
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
Original file line number Diff line number Diff line change
@@ -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, """
<html>
<head><title>Distributed trace scenarios</title></head>
<body>
<h1>Distributed trace scenarios</h1>
<ul>
<li><a id="handoff" href="#">Upstream handoff to a background sync</a></li>
</ul>
<pre id="result"></pre>
<script>
function hex(length) {
const bytes = new Uint8Array(length / 2);
crypto.getRandomValues(bytes);
return Array.from(bytes, (b) => b.toString(16).padStart(2, "0")).join("");
}

document.getElementById("handoff").addEventListener("click", async (event) => {
event.preventDefault();

const traceparent = "00-" + hex(32) + "-" + hex(16) + "-01";
const response = await fetch("/distributed-traces/handoff", {
headers: { traceparent: traceparent },
});

document.getElementById("result").textContent =
"upstream: " + traceparent + "\\n" + JSON.stringify(await response.json());
});
</script>
</body>
</html>
""")
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
7 changes: 7 additions & 0 deletions test_integrations/phoenix_app/lib/phoenix_app_web/router.ex
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
126 changes: 126 additions & 0 deletions test_integrations/tracing/tests/async_traces.spec.ts
Original file line number Diff line number Diff line change
@@ -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();
});
});
Loading
Loading