The Goal

Write a macro def_with_log for defining method with the same syntax as def. That method should define described method and call logger with received arguments and calculated result of method’s body.

Implementation

Lets define a simple wrapper.

defmodule PlugLogger do
  # define macro method for defining wrapping method
  defmacro def_with_log(head, do: body) do
    # fetch params, env method name from head
    {method_name, env, params} = method_name_and_params(head)
    quote do
      # pass head unchanged
      def unquote(head) do
        # unquote body and set return to result variable
        result = unquote(body)
        
        # call log method with module and method name, received params and result
        ControllerLogger.log({__MODULE__, unquote(env), unquote(method_name)}, unquote(params), result)
        
        # return calculated result
        result
      end
    end
  end
  
  # get method name, env and params from head
  defp method_name_and_params(head) do
    case(head) do
      # method with guard, skip guard and get params
      {:when, env, [{name, _env2, params}, _condititions]} ->
        {name, env, params}
      {name, env, params} ->
        {name, env, params}
    end
  end
  
  # simplified example of log method
  def log({caller_module, env, method_name}, params, result) do
    [
      caller_module: caller_module,
      env: env,
      method_name: method_name,
      params: params,
      result: result
    ] |> IO.inspect(label: "Log")
  end
end

defmodule UserController do
  require PlugLogger
  
  def_with_log index(conn, params) do
    users = Accounts.list_users()
    render(conn, "index.html", users: users) 
  end
  # `Macro.to_string` show what was really in definition
  # def(index(conn, params)) do
  #    result = (
  #      users = Accounts.list_users()
  #      render(conn, "index.html", users: users)
  #    )
  #   ControllerLogger.log({__MODULE__, [line: 7], :index}, [conn, params], result)
  #   result
  # end
end

Problem 1

Everything works correct until we start defining methods with underscored variables.

  def_with_log index(conn, _params) do
    users = Accounts.list_users()
    render(conn, "index.html", users: users)
  end

On compile we receive unexpected warnings. warning: the underscored variable "_params" is used after being set. A leading underscore indicates that the value of the variable should be ignored. If this is intended please rename the variable to remove the underscore

That’s happened because we passed _param in log method

  def(index(conn, list_users)) do
    result = (
      user = Accounts.find_me(conn)
      render(conn, "index.html", user: user)
    )
    PlugLogger.log({__MODULE__, [line: 28], :index}, [conn, _params], result)
    result
  end

Problem 2

When we use pattern matching in arguments

  def_with_log show(conn, %{"id" => "me", "token" => "token_" <> token} = params) do
    user = Accounts.find_me(conn, token)
    render(conn, "show.html", user: user, token: token)
  end
  def_with_log show(conn, %{"id" => id, "token" => "token_" <> token} = params) do
    user = Accounts.get_user!(id)
    render(conn, "show.html", user: user, token: token)
  end

We received compilation warnings:

  • warning: variable "token" is unused
  • warning: variable "id" is unused But they are used in method body.

Solution

For fixing these warnings we have to add additional variables to each argument and pass them to the logger.

For example, for definition

  def_with_log show(conn, %{"id" => "me"}) do
    user = Accounts.find_me(conn)
    render(conn, "show.html", user: user)
  end

we should define a method with additional variables arg1 and arg2 and pass them to the logger.

	# should define method with additional vars `arg 
	def(show(conn = arg1, %{"id" => "me"} = arg2)) do
    result = (
      user = Accounts.find_me(conn)
      render(conn, "show.html", user: user)
    )
  PlugLogger.log({__MODULE__, [line: 28], :show}, [arg1, arg2], result)
  result
end

Final version

defmodule PlugLogger do
  defmacro def_with_log(head, do: body) do
    # receive updated method head (with arg1, arg2, … to each param), method name and list of additional params (arg1, arg2, …)
    {wrapped_method, {method_name, env, params}} = wrap_method(head)
    defined_method = quote do
      # define wrapped method
      def unquote(wrapped_method) do
        # set body of method to result variable
        result = unquote(body)
        
        # call log method with all received arguments and method's result
        PlugLogger.log({__MODULE__, unquote(env), unquote(method_name)}, unquote(params), result)
        result
      end
    end
    
    # print method definition
    IO.puts "result: #{Macro.to_string defined_method}"
  end
  
  # wrap method with guard
  defp wrap_method({:when, env, [{name, env2, params}, conditions]}) do
    {wrapped_params, additional_params} = wrap_params(params)
    result = {:when, env, [{name, env2, wrapped_params}, conditions]}
    additional = {name, env, additional_params}
    {result, additional}
  end
  defp wrap_method({name, env, params}) do
    {wrapped_params, additional_params} = wrap_params(params)
    result = {name, env, wrapped_params}
    additional = {name, env, additional_params}
    {result, additional}
  end

  # add variable arg#{number} to each method's argument
  defp wrap_params(params) do
    {wrapped_params, {_index, additional_params}} =
      Enum.map_reduce(params, {1, []}, fn(param, {index, args}) ->
        additional_param = {:"arg#{index}", [], Elixir}
        {
          {:=, [], [param, additional_param]},
          {index + 1, [additional_param | args]}
        }
      end)
    {wrapped_params, Enum.reverse(additional_params)}
  end

Check our wrapped methods now.

  def_with_log index(conn, _params) do
    users = Accounts.list_users()
    render(conn, "index.html", users: users)
  end

  def_with_log show(conn, %{"id" => "me", "token" => "token_" <> token}) do
    user = Accounts.find_me(conn, token)
    render(conn, "show.html", user: user)
  end
  
  def_with_log show(conn, %{"id" => id, "token" => "token_" <> token}) when token == "sometoken" do
    user = Accounts.get_user!(id)
    render(conn, "show.html", user: user, token: token)
  end

Our defined methods.

def(index(conn = arg1, _params = arg2)) do
  result = (
    users = Accounts.list_users()
    render(conn, "index.html", users: users)
  )
  PlugLogger.log({__MODULE__, [line: 7], :index}, [arg1, arg2], result)
  result
end

def(show(conn = arg1, %{"id" => "me", "token" => "token_" <> token} = arg2)) do
  result = (
    user = Accounts.find_me(conn, token)
    render(conn, "show.html", user: user)
  )
  PlugLogger.log({__MODULE__, [line: 28], :show}, [arg1, arg2], result)
  result
end

def(show(conn = arg1, %{"id" => id, "token" => "token_" <> token} = arg2) when token == "sometoken")) do
  result = (
    user = Accounts.get_user!(id)
    render(conn, "show.html", user: user, token: token)
  )
  PlugLogger.log({__MODULE__, [line: 33], :show}, [arg1, arg2], result)
  result
end

Great! We’ve implemented simple method wrapper for logging plug requests arguments and result.

Further we could call different logger modules for controllers and channels.

Thank you for your time. :)