Tracing and asserting function calls

ream88 · April 21, 2024, 9:33am

I recently encountered an issue where a partial or functional component was re-rendered multiple times, resulting in an inline function call being executed multiple times as well. This led to multiple database requests instead of just one. The problem was challenging to debug. I initially had some flaky tests and discovered that the issue was not related to render_async which was my first suspect. Instead, something else was happening with my live view. Using an IO.puts call, I found that my function was called six times instead of the expected single call.

I resolved the problem by assigning the specific assigns my function call depended on, rather than using {assigns} when rendering the partial.

My question for the Elixir community is: Is there a way to trace and debug such scenarios? I’m aware of :dbg and the possibility of mocking function calls using mox or similar tools. However, I’m wondering if there’s an existing library that allows setting expectations about function calls and asserting on them.

ream88 · April 21, 2024, 11:59am

I now ended up with the following helper for my ExUnit.Cases:

def setup_trace(%{trace: mfas}) when is_list(mfas) do
  :dbg.start()
  :dbg.tracer()
  :dbg.p(:all, :c)

  Enum.each(mfas, fn {mod, fun, arity} -> :dbg.tp(mod, fun, arity, []) end)

  on_exit(fn ->
    :dbg.stop()
  end)
end

def setup_trace(%{trace: mfa}), do: setup_trace(%{trace: [mfa]})

def setup_trace(_tags), do: :ok

This allows me to tag my tests:

@tag trace: {MyApp.Posts, :get_posts, 1}
test "renders list of posts", %{user: user, conn: conn} do
  # ...
end

This is better than nothing as it allows me to at least visually see multiple calls of my functions. I will maybe investigate a little bit more to check if I can come up with custom assertions.

LostKobrakai · April 21, 2024, 12:02pm

Take a look at Extrace. It’ll format traces with elixir syntax over erlang syntax.

ream88 · April 21, 2024, 12:47pm

Expanded my code now like this:

def setup_trace(%{trace: mfas}) when is_list(mfas) do
  {:ok, pid} = Agent.start_link(fn -> %{} end)

  :dbg.start()

  :dbg.tracer(
    :process,
    {fn {:trace, _pid, :call, {mod, fun, args}}, _state ->
      Agent.update(pid, fn calls ->
        Map.update(calls, {mod, fun, length(args)}, 1, &(&1 + 1))
      end)
    end, nil}
  )

  :dbg.p(:all, :c)

  Enum.each(mfas, fn {mod, fun, arity} -> :dbg.tp(mod, fun, arity, []) end)

  {:ok, pid: pid}
end

def setup_trace(%{trace: mfa}), do: setup_trace(%{trace: [mfa]})

def setup_trace(_tags), do: :ok

This allows me to assert on the calls like this:

@tag trace: {MyApp.Posts, :get_posts, 1}
test "renders list of posts", %{user: user, conn: conn, pid: pid} do
  # ...
  assert Agent.get(pid, & &1) == %{{MyApp.Posts, :get_posts, 1} => 1}
end

Will now try to wrap this in a custom macro, so it’s less boiler plate.

ream88 · April 21, 2024, 1:36pm

Opps Sunday afternoon programming escalation:

defmodule Tracer do
  @moduledoc false

  import ExUnit.Assertions, only: [assert: 1]

  def start_link do
    Agent.start_link(fn -> %{expectations: %{}, traces: %{}} end, name: __MODULE__)

    :dbg.start()

    :dbg.tracer(
      :process,
      {fn {:trace, _pid, :call, {module, function, args}}, _state ->
        Agent.update(__MODULE__, fn state ->
          update_in(state, [:traces, {module, function, length(args)}], fn
            nil -> 1
            count -> count + 1
          end)
        end)
      end, nil}
    )

    :dbg.p(:all, :c)

    :ok
  end

  def expect(module, function, arity, count \\ 1) do
    Agent.update(__MODULE__, fn state ->
      put_in(state, [:expectations, {module, function, arity}], count)
    end)

    :dbg.tp(module, function, arity, [])

    :ok
  end

  def verify do
    %{expectations: expectations, traces: traces} = Agent.get(__MODULE__, & &1)
    assert expectations == traces
  end

  def verify_on_exit! do
    ExUnit.Callbacks.on_exit(Tracer, fn -> Tracer.verify() end)
  end
end

This module can be used similar to Mox like this:

test "renders list of posts", %{user: user, conn: conn} do
  Tracer.expect(MyApp.Posts, :get_posts, 1, count)
  # ...
end

Now it properly asserts that this function is called count times:

 Assertion with == failed
 code:  assert expectations == traces
 left:  %{{MyApp.Posts, : get_posts, 1} => 2}
 right: %{{MyApp.Posts, : get_posts, 1} => 1}

Will probably clean it up a little bit more (for example replace the Agent with a proper GenServer and implement nicer error messages) and then publish it on hex Any suggestions for a nice name?