Instrument an HTTP Chunked Response

[cschneid]

A user in slack asked about their controller, which does chunked responses, and isn't instrumented well currently. The actual data is fed via an Ecto.Stream.

We need to investigate and document how this should work.

defmodule MaestroApiWeb.ExportController do
 use MaestroApiWeb, :controller
 alias MaestroApi.ExportToCSV
​
 def deals(conn, _params) do
  conn =
   conn
   |> put_resp_header("content-disposition", "attachment; filename=deals.csv")
   |> put_resp_content_type("text/csv")
   |> send_chunked(200)
​
  export(:deal_summary, conn)
 end
​
 defp export(resource, conn) do
  {:ok, conn} =
   Repo.transaction(fn ->
    ExportToCSV.build_export_query(resource, current_company(conn), current_user(conn))
    |> Enum.reduce_while(conn, fn data, conn ->
     case chunk(conn, data) do
      {:ok, conn} ->
       {:cont, conn}
​
      {:error, :closed} ->
       {:halt, conn}
     end
    end)
   end)
​
  conn
 end
end

[cschneid]

As of right now, this won't be instrumented by our normal controller plug, so the strategy is to instrument it manually, and tell the normal instruments to not run at all:

  def chunked(conn, _params) do
    ScoutApm.TrackedRequest.start_layer("Controller", ScoutApm.Plugs.ControllerTimer.action_name(conn))

    conn =
      conn
      |> put_resp_content_type("text/plain")
      |> send_chunked(200)

    Enum.map(1..20000, fn(x) -> "#{x}" end)
    |> Enum.reduce_while(conn, fn (chunk, conn) ->
      case Plug.Conn.chunk(conn, chunk) do
        {:ok, conn} ->
          {:cont, conn}
        {:error, :closed} ->
          {:halt, conn}
      end
    end)
    |> ScoutApm.Plugs.ControllerTimer.before_send()
  end

# config.exs
config :scout_apm,
  name: "Scout Test Ecto 3.0",
  key: "",
  ignore: ["/chunked"]

[lypborges]

I'll test it soon. Thanks.

[lypborges]

I'm getting this warning warning: function ScoutApm.Plugs.ControllerTimer.action_name/1 is undefined or private and it's true ;)

  def deals_chunked(conn, _params) do
    ScoutApm.TrackedRequest.start_layer("Controller", "deals_chunked")

    conn =
      conn
      |> put_resp_header("content-disposition", "attachment; filename=deals.csv")
      |> put_resp_content_type("text/csv")
      |> send_chunked(200)

    export(:vw_deals_by_revenue, conn)
  end

  defp export(resource, conn) do
    {:ok, conn} =
      Repo.transaction(fn ->
        ExportToCSV.build_export_query(resource, current_company(conn), current_user(conn))
        |> Enum.reduce_while(conn, fn data, conn ->
          case chunk(conn, data) do
            {:ok, conn} ->
              {:cont, conn}

            {:error, :closed} ->
              {:halt, conn}
          end
        end)
      end)
      |> ScoutApm.Plugs.ControllerTimer.before_send()

    conn
  end

Can I just change for ScoutApm.TrackedRequest.start_layer("Controller", "deals_chunked") ?

[mitchellhenke]

@lypborges hey, I've pushed a new branch here that should fix that 🙂

Could you install it and let us know if things show up in Scout as expected? If the route is configured in ignore, it should skip normal instrumentation and only use the instrumentation added manually.

# mix.exs
-     {:scout_apm, "~> 0.0"},
+     {:scout_apm, git: "https://github.com/scoutapp/scout_apm_elixir.git",
+       branch: "chunked-responses"},

[lypborges]

Hi! @mitchellhenke tks for the reply.

I tried, but the request is not being tracked. How can I help with more info or any tip to debug?

[lypborges]

I think that it's something wrong in the action_name method. It's calling private but it's not getting a conn but a :ok atom.

  def call(conn, _default) do
    if !ignore_uri?(conn.request_path) do
      ScoutApm.TrackedRequest.start_layer("Controller", action_name(conn))

      conn
      |> Plug.Conn.register_before_send(&before_send/1)
    else
      conn
    end
  end

  # Takes a connection, extracts the phoenix controller & action, then manipulates & cleans it up.
  # Returns a string like "PageController#index"
  def action_name(conn) do
    controller_name = conn.private[:phoenix_controller]
    action_name = conn.private[:phoenix_action]

    "#{controller_name}##{action_name}" # a string like "Elixir.TestappPhoenix.PageController#index"
      |>  String.split(".") # Split into a list
      |>  Enum.drop(2) # drop "Elixir.TestappPhoenix", leaving just ["PageController#index"]
      |>  Enum.join(".") # Probably just "joining" a 1 elem array, but recombine this way anyway in case of periods
  end

2018-11-21T00:42:25.579219+00:00 app[web.1]: ** (exit) an exception was raised:
2018-11-21T00:42:25.579220+00:00 app[web.1]:     ** (UndefinedFunctionError) function :ok.private/1 is undefined (module :ok is not available)
2018-11-21T00:42:25.579262+00:00 app[web.1]:         :ok.private({:ok, %Plug.Conn{adapter: {Plug.Cowboy.Conn, :...}, assigns: %{}, before_send: [#Function<1.70744679/1 in ScoutApm.Plugs.ControllerTimer.call/2>,

[mitchellhenke]

It looks like part of the issue is what is being piped into ScoutApm.Plugs.ControllerTimer.before_send/1:

  {:ok, conn} =
    Repo.transaction(fn ->
      ExportToCSV.build_export_query(resource, current_company(conn), current_user(conn))
      |> Enum.reduce_while(conn, fn data, conn ->
        case chunk(conn, data) do
          {:ok, conn} ->
            {:cont, conn}

          {:error, :closed} ->
            {:halt, conn}
        end
      end)
    end)
    |> ScoutApm.Plugs.ControllerTimer.before_send()

If the transaction is successful, Repo.transaction returns the tuple of {:ok, conn}, which means you're ultimately calling:

ScoutApm.Plugs.ControllerTimer.before_send({:ok, conn})

To fix that, I would slightly shuffle things around to do something like this:

  defp export(resource, conn) do
    {:ok, conn} =
      Repo.transaction(fn ->
        ExportToCSV.build_export_query(resource, current_company(conn), current_user(conn))
        |> Enum.reduce_while(conn, fn data, conn ->
          case chunk(conn, data) do
            {:ok, conn} ->
              {:cont, conn}

            {:error, :closed} ->
              {:halt, conn}
          end
        end)
      end)

    ScoutApm.Plugs.ControllerTimer.before_send(conn)
    conn
  end

It also appears that the route isn't configured to be ignored with :ignore. The plug should be skipped, but the stacktrace shows your conn having before_send set.

I would double check config/config.exs to make sure configuration has that set up:

config :scout_apm,
  name: "My Scout App Name",
  key: "My Scout Key",
  ignore: ["/my_chunked_route_prefix"]

[lypborges]

It works. Thanks a lot.

[mitchellhenke]

Closed in #70 and released in 0.4.9