Elixir compile-time code injection / AOP

Question

I've previously used AOP-style code to separate Logic from Logging, and been very pleased with the results. I recognize that opinions on AOP vary, but I'd like to figure out a solution in Elixir, even if I don't end up using it in prod.

The closest example I've seen is the setup callback inside of ExUnit, which allows execution of code before each test runs; I'd like to do something similar, but haven't been able to muddle through the ExUnit source to grasp the intuitions there.

In code form:

defmodule Project.Logic do
    LoggingInjection.inject Project.Logging

    def work_do_stuff(arg) do
        #...
        #returns some_result
    end
end

in a separate code file:

defmodule Project.Logging do
    #called just before Project.Logic.work_do_stuff with the same args
    def before_work_do_stuff(arg) do
        Log.write("about to work_do_stuff with #{inspect arg}")
    end
    # def after_work_do_stuff(some_result) implicitly defined as no-op,
    # but could be overridden.
end

and finally, the real question: What is the code to enable this magic?

defmodule LoggingInjection do
    defmacro inject(logging_module) do
        #What goes here?
    end
end

Answer 1

It's not AOP, but if you're interested in observing function calls at runtime, you can consider looking into Erlang trace.

For example, you can use :dbg to setup dynamic traces of function calls. Here's how to trace all calls to IO:

iex> :dbg.tracer
iex> :dbg.p(:all, [:call])
iex> :dbg.tp(IO, [{:_, [], [{:return_trace}]}])

(<0.53.0>) call 'Elixir.IO':puts(stdio,<<"\e[33m{:ok, [{:matched, :nonode@nohost, 28}, {:saved, 1}]}\e[0m">>)
(<0.53.0>) returned from 'Elixir.IO':puts/2 -> ok
(<0.59.0>) call 'Elixir.IO':gets(stdio,<<"iex(4)> ">>)

I occasionally use this feature to connect to a running BEAM node, and analyze the running system. Be sure to stop traces with :dbg.stop_clear once you're done.

If you want to manually handle trace messages and do something specific about them (e.g. log them to a file), you can use :erlang.trace. Here's a simple gen_server that traces calls to various modules:

defmodule Tracer do
  use GenServer

  def start(modules), do: GenServer.start(__MODULE__, modules)

  def init(modules) do
    :erlang.trace(:all, true, [:call])

    for module <- modules do
      :erlang.trace_pattern({module, :_, :_}, [{:_, [], [{:return_trace}]}])
    end

    {:ok, nil}
  end

  def handle_info({:trace, _, :call, {mod, fun, args}}, state) do
    IO.puts "called #{mod}.#{fun}(#{Enum.join(Enum.map(args, &inspect/1), ",")})"
    {:noreply, state}
  end

  def handle_info({:trace, _, :return_from, {mod, fun, arity}, res}, state) do
    IO.puts "#{mod}.#{fun}/#{arity} returned #{res}"
    {:noreply, state}
  end

  def handle_info(_, state), do: {:noreply, state}
end

To use it, just start it and provide the list of modules you want to trace:

iex(2)> Tracer.start([IO])
{:ok, #PID<0.84.0>}

called Elixir.IO.puts(:stdio,"\e[33m{:ok, #PID<0.84.0>}\e[0m")
Elixir.IO.puts/2 returned ok
call Elixir.IO.gets(:stdio,"iex(3)> ")

Tracing is very powerful and you can do all sorts of thing with it. I didn't use it for a logging system myself, so I can't say how much of a problem it will be, so if you take this road, I advise you to be careful and observe performance, because too much of tracing might overload your system.