ReconTrace (WIP)

recon_trace.ex

require :recon_trace

defmodule ReconTrace do
  @moduledoc """
  `ReconTrace` provides functions for tracing events in a safe manner
  for single Erlang BEAM VM. It is a wrapper module of `recon_trace`
  in the Erlang Recon toolset: http://ferd.github.io/recon/

  ## Examples

  ```
  ReconTrace.calls({:queue, :in, fn(_) -> :return end}, 3, [scope: :local])
  ```

  TODO: More docs
  """

  @doc """
  TODO
  """
  def clear() do
    :recon_trace.clear
  end

  @doc """
  TODO
  """
  def calls({mod, fun, args}, max) when is_function(args) do
    :recon_trace.calls({mod, fun, fun_to_match_spec(args)}, max,
                       [{:formatter, &format/1}])
  end

  def calls({_mod, _fun, _args}=tspec, max) do
    :recon_trace.calls(tspec, max, [{:formatter, &format/1}])
  end

  def calls(tspecs, max) when is_list(tspecs) do
    Enum.map(tspecs,
             fn
               ({mod, fun, args}) when is_function(args) ->
                 {mod, fun, fun_to_match_spec(args)}
               ({_mod, _fun, _args}=tspec) ->
                 tspec
             end
    ) |> :recon_trace.calls(max, [{:formatter, &format/1}])
  end

  def calls({mod, fun, args}, max, opts) when is_function(args) do
    :recon_trace.calls({mod, fun, fun_to_match_spec(args)}, max,
                       add_formatter(opts))
  end

  def calls({_mod, _fun, _args}=tspec, max, opts) do
    :recon_trace.calls(tspec, max, add_formatter(opts))
  end

  def calls(tspecs, max, opts) when is_list(tspecs) do
    Enum.map(tspecs,
             fn
               ({mod, fun, args}) when is_function(args) ->
                 {mod, fun, fun_to_match_spec(args)}
               ({_mod, _fun, _args}=tspec) ->
                 tspec
             end
    ) |> :recon_trace.calls(max, add_formatter(opts))
  end

  defp add_formatter(opts) do
    case :proplists.get_value(:formatter, opts) do
      func when is_function(func, 1) ->
        opts
      _ ->
        [{:formatter, &format/1} | opts]
    end
  end

  def format(trace_msg) do
    {type, pid, {hour, min, sec}, trace_info} = extract_info(trace_msg)
    header = :io_lib.format('~n~2.2.0w:~2.2.0w:~9.6.0f ~p', [hour, min, sec, pid])
    body = format_body(type, trace_info) |> String.replace("~", "~~")
    '#{header} #{body}\n'
  end

  # {:trace, pid, :receive, msg}
  defp format_body(:receive, [msg]) do
    "< #{inspect msg, pretty: true}"
  end

  # {trace, pid, :send, msg, to}
  defp format_body(:send, [msg, to]) do
    " > #{inspect to, pretty: true}: #{inspect msg, pretty: true}"
  end

  # {:trace, pid, :send_to_non_existing_process, msg, to}
  defp format_body(:send_to_non_existing_process, [msg, to]) do
    " > (non_existent) #{inspect to, pretty: true}: #{inspect msg, pretty: true}"
  end

  # {:trace, pid, :call, {m, f, args}}
  defp format_body(:call, [{m, f, args}]) do
    "#{format_module m}.#{f}#{format_args args}"
  end

  # {:trace, pid, :return_to, {m, f, arity}}
  defp format_body(:return_to, [{m, f, arity}]) do
    "#{format_module m}.#{f}/#{arity}"
  end

  # {:trace, pid, :return_from, {m, f, arity}, return_value}
  defp format_body(:return_from, [{m, f, arity}, return]) do
    "#{format_module m}.#{f}/#{arity} --> #{inspect return, pretty: true}"
  end

  # {:trace, pid, :exception_from, {m, f, arity}, {class, value}}
  defp format_body(:exception_from, [{m, f, arity}, {class, val}]) do
    "#{format_module m}.#{f}/#{arity} #{class} #{inspect val, pretty: true}"
  end

  # {:trace, pid, :spawn, spawned, {m, f, args}}
  defp format_body(:spawn, [spawned, {m, f, args}]) do
    "spawned #{inspect spawned, pretty: true} as #{format_module m}.#{f}#{format_args args}"
  end

  # {:trace, pid, :exit, reason}
  defp format_body(:exit, [reason]) do
    "EXIT #{inspect reason, pretty: true}"
  end

  # {:trace, pid, :link, pid2}
  defp format_body(:link, [linked]) do
    "link(#{inspect linked, pretty: true})"
  end

  # {:trace, pid, :unlink, pid2}
  defp format_body(:unlink, [linked]) do
    "unlink(#{inspect linked, pretty: true})"
  end

  # {:trace, pid, :getting_linked, pid2}
  defp format_body(:getting_linked, [linker]) do
    "getting linked by #{inspect linker, pretty: true}"
  end

  # {:trace, pid, :getting_unlinked, pid2}
  defp format_body(:getting_unlinked, [unlinker]) do
    "getting unlinked by #{inspect unlinker, pretty: true}"
  end

  # {:trace, pid, :register, reg_name}
  defp format_body(:register, [name]) do
    "registered as #{inspect name, pretty: true}"
  end

  # {:trace, pid, :unregister, reg_name}
  defp format_body(:unregister, [name]) do
    "no longer registered as #{inspect name, pretty: true}"
  end

  # {:trace, pid, :in, {m, f, arity}}
  defp format_body(:in, [{m, f, arity}]) do
    "scheduled in for #{format_module m}.#{f}/#{arity}"
  end

  # {:trace, pid, :in, 0}
  defp format_body(:in, [0]) do
    "scheduled in"
  end

  # {:trace, pid, :out, {m, f, arity}}
  defp format_body(:out, [{m, f, arity}]) do
    "scheduled out from #{format_module m}.#{f}/#{arity}"
  end

  # {:trace, pid, :out, 0}
  defp format_body(:out, [0]) do
    "scheduled out"
  end

  # {:trace, pid, :gc_start, info}
  defp format_body(:gc_start, [info]) do
    heap_size = :proplists.get_value(:heap_size, info)
    old_heap_size = :proplists.get_value(:old_heap_size, info)
    mbuf_size = :proplists.get_value(:mbuf_size, info)
    total = heap_size + old_heap_size + mbuf_size
    "gc beginning -- heap #{total} bytes"
  end

  # {:trace, pid, :gc_end, Info}
  defp format_body(:gc_end, [info]) do
    heap_size = :proplists.get_value(:heap_size, info)
    old_heap_size = :proplists.get_value(:old_heap_size, info)
    mbuf_size = :proplists.get_value(:mbuf_size, info)
    total = heap_size + old_heap_size + mbuf_size
    "gc finished -- heap #{total} bytes"
  end

  defp format_body(type, trace_info) do
    "unknown trace type #{inspect type, pretty: true} -- #{inspect trace_info, pretty: true}"
  end

  defp extract_info(trace_msg) do
    case :erlang.tuple_to_list(trace_msg) do
      [:trace_ts, pid, type | info] ->
        {trace_info, [timestamp]} = :lists.split(:erlang.length(info) - 1, info)
        {type, pid, to_hms(timestamp), trace_info};
      [:trace, pid, type | trace_info] ->
        {type, pid, to_hms(:os.timestamp()), trace_info}
    end
  end

  defp to_hms(stamp = {_, _, micro}) do
    {_, {h, m, secs}} = :calendar.now_to_local_time(stamp)
    seconds = rem(secs, 60) + (micro / 1_000_000)
    {h, m, seconds}
  end

  defp to_hms(_) do
    {0, 0, 0}
  end

  defp format_module(module_atom) do
    module_str = to_string(module_atom)
    if String.starts_with?(module_str, "Elixir.") do
      String.slice(module_str, 7, String.length(module_str) - 7)
    else
      module_str
    end
  end

  defp format_args(arity) when is_integer(arity) do
    "/#{arity}"
  end

  defp format_args(args) when is_list(args) do
    arg_str = Enum.map(args, &(inspect &1, pretty: true)) |> Enum.join(", ")
    "(" <> arg_str <> ")"
  end

  defp fun_to_match_spec(shell_fun) do
    case :erl_eval.fun_data(shell_fun) do
      {:fun_data, import_list, clauses} ->
        case :ms_transform.transform_from_shell(:dbg, clauses, import_list) do
          {:error, [{_, [{_, _, code} | _]} |_], _} ->
            IO.puts "Error: #{:ms_transform.format_error(code)}"
            {:error, :transform_error}
          [{args, gurds, [:return]}] ->
            [{args, gurds, [{:return_trace}]}]
          match_spec ->
            match_spec
        end
      false ->
        exit(:shell_funs_only)
    end
  end

end