Step 4: Add Some Logging

Imagine a large Elixir application—dozens of processes potentially running across a number of nodes. You’d really 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.

project/5/issues/mix.exs
 def​ application ​do
  [
 extra_applications:​ [​:logger​]
  ]
 end

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

First, you can determine at compile time the minimum level of logging to include. Logging below this level is not even compiled into your code. The compile-time level is set in the config/config.exs file:

project/5/issues/config/config.exs
 use​ Mix.Config
 
 config ​:issues​,
 github_url:​ ​"​​https://api.github.com"
 
»config ​:logger​,
»compile_time_purge_level:​ ​:info

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

After all this configuration, it’s time to add some 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.

Anyway, here’s a version of our fetch function with some logging:

project/5/issues/lib/issues/github_issues.ex
 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 you forget this (and I do every time), you’ll get an error when you 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.