Step 4: Add Some Logging

Imagine a large Elixir application with dozens of processes potentially running across a number of nodes. We’d want a standard way to keep track of significant events as it runs. Enter the Elixir logger. The default mix.exs starts the logger for your application.

def application do 
 [
  extra_applications: [:logger] 
 ]
end

Logger

The logger supports four levels of message. In increasing order of severity, they are debug, info, warn, and error. We select the level of logging in two ways.

First, we can determine at compile time the minimum level of logging include. Logging below this level isn’t even compiled into the code. The compile-time level is set in the config/config.exs file:

use Mix.Config

config :issues,
       github_url: "https://api.github.com"

config :logger,
       compile_time_purge_level: :info

Next, we can choose to change the minimum log level at runtime by calling Logger.configure. (Clearly, this can’t enable log levels that we excluded at compile time.)

After all this configuration, it’s time to add some logging.

Add logging

The basic logging functions are Logger.debug, .info, .warn, and .error. Each function takes either a string or a zero-arity function:

Logger.debug "Order total #{total(order)}" 
Logger.debug fn -> "Order total #{total(order)}" end

Why have the function version? Perhaps the calculation of the order total is expensive. In the first version, we’ll always call it to interpolate the value into our string, even if the runtime log level is set to ignore debug-level messages. In the function variant, though, the total function will be invoked only if the log message is needed.

Here’s a version of our fetch function with some logging:

defmodule Issues.GithubIssues do

  require Logger

  @user_agent  [ {"User-agent", "Elixir dave@pragprog.com"} ]

  # use a module attribute to fetch the value at compile time
  @github_url Application.get_env(:issues, :github_url)


  def fetch(user, project) do
    Logger.info("Fetching #{user}'s project #{project}")

    issues_url(user, project)
    |> HTTPoison.get(@user_agent)
    |> handle_response
  end

  def issues_url(user, project) do
    "#{@github_url}/repos/#{user}/#{project}/issues"
  end

  def handle_response({ _, %{status_code: status_code, body: body}}) do
    Logger.info("Got response: status code=#{status_code}")
    Logger.debug(fn -> inspect(body) end)
    {
      status_code |> check_for_error(),
      body        |> Poison.Parser.parse!()
    }
  end

  defp check_for_error(200), do: :ok
  defp check_for_error(_),   do: :error

end

Note the use of require Logger at the top of the module. If we forget this, which is common, we’ll get an error when we make the first call to Logger.

We can play with the new code in IEx:

iex> Issues.CLI.process {"pragdave", "earmark", 1} 
19:53:44.207 [info] Fetching pragdave's project earmark 
19:53:44.804 [info] Got response: status code=200
num |  created_at          | title 
----+----------------------+--------------
171 | 2017-12-03T11:08:40Z | Fix typespecs
:ok

Notice that the debug-level message is not displayed.

Note the use of require Logger at the top of the module. If we forget this, which is common, we’ll get an error when we make the first call to Logger.