Lost parent context when Phoenix LiveView assign_async is used

[arathunku]

Describe the bug

When Phoenix.LiveView assign_async/3 is used, any spans from async task will not have parent context, even when OpentelemetryProcessPropagator is used. This means that any Ecto query is detached span.

Expected behavior

I'd expect parent context to be propagated.

Additional context

Repro script:

#!/usr/bin/env elixir
Application.put_env(:sample, Example.Endpoint,
  http: [ip: {127, 0, 0, 1}, port: 5001],
  server: true,
  live_view: [signing_salt: "you-are-the-best"],
  secret_key_base: String.duplicate("a", 64)
)

Application.put_env(:opentelemetry, :traces_exporter, {:otel_exporter_stdout, []})

Mix.install([
  {:plug_cowboy, "~> 2.5"},
  {:jason, "~> 1.0"},
  {:phoenix, "~> 1.7"},
  {:phoenix_live_view, "~> 0.20.1"},
  {:opentelemetry, "~> 1.3"},
  {:opentelemetry_api, "~> 1.2"},
  {:opentelemetry_exporter, "~> 1.6"},
  {:opentelemetry_process_propagator, "~> 0.3.0"},
  {:opentelemetry_phoenix, "~> 1.1"}
])

defmodule Example.ErrorView do
  def render(template, _), do: Phoenix.Controller.status_message_from_template(template)
end

defmodule Example.HomeLive do
  use Phoenix.LiveView, layout: {__MODULE__, :live}
  require OpenTelemetry.Tracer, as: Tracer

  def mount(_params, _session, socket) do
    IO.inspect({Tracer.current_span_ctx(), connected?(socket)})

    span_ctx = Tracer.current_span_ctx()

    {:ok,
     socket
     |> assign_async(:items, fn ->
       # detached spans are expected here I guess
       Tracer.with_span "span-without-propagation" do
         {:ok, %{items: []}}
       end
     end)
     |> assign_async(:special_items, fn ->
       with_telemetry_ctx(fn ->
         # BUG! this is also detached span?
         Tracer.with_span "span-with-propagation" do
           {:ok, %{special_items: []}}
         end
       end)
     end)
     |> assign_async(:special_items_ctx, fn ->
       Tracer.set_current_span(span_ctx)

       Tracer.with_span "span-with-set-context" do
         {:ok, %{special_items_ctx: []}}
       end
     end)}
  end

  def render("live.html", assigns) do
    ~H"""
    <script src="/assets/phoenix/phoenix.js"></script>
    <script src="/assets/phoenix_live_view/phoenix_live_view.js"></script>
    <script>
      let liveSocket = new window.LiveView.LiveSocket("/live", window.Phoenix.Socket)
      liveSocket.connect()
    </script>
    <style>
      * { font-size: 1.1em; }
    </style>
    <%= @inner_content %>
    """
  end

  def render(assigns) do
    ~H"""
    Hello world
    """
  end

  # Basically what Ecto is doing:
  # https://github.com/open-telemetry/opentelemetry-erlang-contrib/blob/3f13bc8b2042071b723d0ea8c7b118fd10f42d26/instrumentation/opentelemetry_ecto/lib/opentelemetry_ecto.ex#L116
  defp with_telemetry_ctx(fun) do
    parent_context =
      case OpentelemetryProcessPropagator.fetch_ctx(self()) do
        :undefined ->
          OpentelemetryProcessPropagator.fetch_parent_ctx(1, :"$callers")

        ctx ->
          ctx
      end

    parent_token =
      if parent_context != :undefined do
        OpenTelemetry.Ctx.attach(parent_context)
      else
        :undefined
      end

    result = fun.()

    if parent_token != :undefined do
      OpenTelemetry.Ctx.detach(parent_token)
    end

    result
  end
end

defmodule Example.Router do
  use Phoenix.Router
  import Phoenix.LiveView.Router

  pipeline :browser do
    plug(:accepts, ["html"])
  end

  scope "/", Example do
    pipe_through(:browser)

    live("/", HomeLive, :index)
  end
end

defmodule Example.Endpoint do
  use Phoenix.Endpoint, otp_app: :sample
  socket("/live", Phoenix.LiveView.Socket)

  plug(Plug.Static, from: {:phoenix, "priv/static"}, at: "/assets/phoenix")
  plug(Plug.Static, from: {:phoenix_live_view, "priv/static"}, at: "/assets/phoenix_live_view")

  plug(Example.Router)
end

{:ok, _} = Supervisor.start_link([Example.Endpoint], strategy: :one_for_one)
:ok = OpentelemetryPhoenix.setup(adapter: :cowboy2)
Process.sleep(:infinity)

This gives the following debug log:

*SPANS FOR DEBUG*
{span,258017312708833371964411571289189239406,8451101793218774242,
      {tracestate,[]},
      undefined,<<"Example.HomeLive.mount">>,server,-576460749570026539,
      -576460749554976171,
      {attributes,128,infinity,0,#{}},
      {events,128,128,infinity,0,[]},
      {links,128,128,infinity,0,[]},
      undefined,1,false,
      {instrumentation_scope,<<"opentelemetry_phoenix">>,<<"1.2.0">>,
                             undefined}}
{span,114061670040808529142589516162197117224,3262951029120267145,
      {tracestate,[]},
# THIS LOOKS OK
      undefined,<<"span-without-propagation">>,internal,-576460749554952607,
      -576460749554903105,
      {attributes,128,infinity,0,#{}},
      {events,128,128,infinity,0,[]},
      {links,128,128,infinity,0,[]},
      undefined,1,false,undefined}
{span,258017312708833371964411571289189239406,7524343052582475866,
      {tracestate,[]},
# THIS LOOKS OK, CONTEXT MANUALLY SET
      8451101793218774242,<<"span-with-set-context">>,internal,
      -576460749554866196,-576460749554842512,
      {attributes,128,infinity,0,#{}},
      {events,128,128,infinity,0,[]},
      {links,128,128,infinity,0,[]},
      undefined,1,false,undefined}
{span,156269372488035503806460351374740489154,16606203842975826459,
      {tracestate,[]},
# THIS LOOKS BROKEN! 
      undefined,<<"span-with-propagation">>,internal,-576460749544575511,
      -576460749544498287,
      {attributes,128,infinity,0,#{}},
      {events,128,128,infinity,0,[]},
      {links,128,128,infinity,0,[]},
      undefined,1,false,undefined}

I'd expect to have parent id in span-with-propagation.

I'm unsure if it's an issue with OpentelemetryProcessPropagator or the way async assign in LiveView works.

[bryannaegele]

I took a peak at the source code and yeah, it's not going to be possible to have it be automatic. The tasks aren't the only problem, there's also this message passing which nothing can propagate through. Maybe somebody could get incredibly clever but, in the meantime, you'll need to manually propagate as you have in the 3rd example.

The main issue is to make it automatic we'd have to extend those LiveView modules to do that for you. See Task for reference on what would have to be done.

[arathunku]

That sounds bad given how easy to use current assign_async is... it's very nice DX. Thank you @bryannaegele for looking into it, and for linking what needs to be done. I'll close the issue here then and start a discussion on LiveView repo.

[tsloughter]

What is assign_async and can we provide our own for users to use like we do in Task?

[tsloughter]

I meant to better extend on what @bryannaegele said and not just repeat it, hehe. Should we not provide these functions as part of the Phoenix instrumentation library I mean? Instead of the user doing it.

I'm sure someone would be interested in contributing that if we asked.

[arathunku]

What is assign_async and can we provide our own for users to use like we do in Task?

Please see assign_async/4 and module async operations but if you're not using LiveView it might not be clear. Under the hood it's spawning Task, with some additional logic to nicely handle failures and results.

Before I open any issue on LiveView, I'll explore exactly that - how easy it would be to provide alternative assign_async, without going into conflicts with assign_async/4 in LiveView and maintaining the same API.

[tsloughter]

Right, I was wondering how it is used. So LiveView has keys that get assigned values and then replaced, with the option to have that replacement done at some future time when a Task completes?

So probably used pretty often?

I don't think there is anything LiveView can/should do differently that wouldn't involve integrating OpenTelemetry. Instead I think we should provide replacements (@bryannaegele can correct me there if its not something we'd be good to try to provide a drop-in for, like maybe it is one of those things since its a pre-1.0 project that may likely change too much/often internally).

That and better document that implicit context is per-process and will not automatically propagate, requiring the user manually set it, like https://opentelemetry.io/docs/languages/erlang/instrumentation/#spans-in-separate-processes

[arathunku]

So LiveView has keys that get assigned values and then replaced, with the option to have that replacement done at some future time when a Task completes?
So probably used pretty often?

Absolutely yes, it's a recent LiveView-specific "primitive" but I expect it to be used by almost every LiveView app at some point.

I'll test a drop-in in a separate repo and see how much needs to be copied over vs reused from LiveView.

better document that implicit context is per-process and will not automatically propagate

I think the documentation is pretty clear about that and this wasn't a surprise to me, I was mostly surprised that even though Ecto telemetry uses Process Propagator here, any Ecto spans were detached from parent span when assign_async is used.

[danschultzer]

I had helper macros in my private repo, but I think based on OpentelemetryProcessPropagator.Task and OpentelemetryOban we should have the helper macros in OpentelemetryPhoenix: #439