lib/liberator/trace.ex

defmodule Liberator.Trace do
  import Plug.Conn
  require Logger

  @moduledoc """
  Decision tracing functions.
  """

  @doc """
  Get the log of all decisions made on the given conn.

  The trace is a list of maps, each map corresponding to one call to a decision function.
  Each map has the following keys:

  - `:step`: the name of the function that was executed, or the atoms `:start` or `:stop`
  - `:result`: the value the function returned
  - `:timestamp`: the time the function was called
  - `:duration`: how long the call took, in native time units

  """
  @doc since: "1.1"
  def get_trace(conn) do
    Map.get(conn.private, :liberator_trace, [])
  end

  @doc false
  def start(conn, start_time) do
    first_trace = [
      %{
        step: :start,
        timestamp: start_time
      }
    ]

    put_private(conn, :liberator_trace, first_trace)
  end

  @doc false
  def update_trace(conn, next_step, result, called_at, duration) do
    current_trace = get_trace(conn)

    updated_trace =
      current_trace ++
        [
          %{
            step: next_step,
            result: result,
            timestamp: called_at,
            duration: duration
          }
        ]

    put_private(conn, :liberator_trace, updated_trace)
  end

  @doc false
  def stop(conn, end_time) do
    current_trace = get_trace(conn)

    updated_trace =
      current_trace ++
        [
          %{
            step: :stop,
            timestamp: end_time
          }
        ]

    put_private(conn, :liberator_trace, updated_trace)
  end

  @doc """
  Get a list of tuples for the `x-liberator-trace` header,
  based on the given trace.
  """
  @doc since: "1.3"
  def headers(trace) do
    trace
    # remove :start and :stop traces
    |> Enum.slice(1, Enum.count(trace) - 2)
    |> Enum.map(fn %{step: key, result: val, duration: duration_native} ->
      duration_us = System.convert_time_unit(duration_native, :native, :microsecond)

      {"x-liberator-trace", "#{Atom.to_string(key)}: #{inspect(val)} (took #{duration_us} µs)"}
    end)
  end

  @doc """
  Log a message containing the given trace,
  along with its request path and optional request ID.
  """
  @doc since: "1.3"
  def log(trace, request_path, request_id \\ nil) do
    trace =
      trace
      # remove :start and :stop traces
      |> Enum.slice(1, Enum.count(trace) - 2)
      |> Enum.with_index()
      |> Enum.map(fn {%{step: key, duration: duration_native} = trace, index} ->
        val = Map.get(trace, :result, nil)
        duration_us = System.convert_time_unit(duration_native, :native, :microsecond)
        "    #{index + 1}. #{Atom.to_string(key)}: #{inspect(val)} (took #{duration_us} µs)"
      end)
      |> Enum.join("\n")

    header =
      if request_id do
        "Liberator trace for request #{inspect(request_id)} to #{request_path}:\n\n"
      else
        "Liberator trace for request to #{request_path}:\n\n"
      end

    Logger.debug(header <> trace)
  end
end