Testing Logger in Phoenix

Say you have a controller function that logs messages on successful or failed login attempts:

def create(conn, %{"user" => user_params}) do
  %{"email" => email, "password" => password} = user_params

  if user = Accounts.get_user_by_email_and_password(email, password) do
    Logger.info("LOGIN: #{email} from #{get_ip(conn)}")
    UserAuth.log_in_user(conn, user, user_params)
  else
    Logger.warn("LOGIN ERROR: Attempted login to #{email} from #{get_ip(conn)}")
    render(conn, "new.html", error_message: "Invalid email or password")
  end
end

How would you go about testing testing the Logger.info and Logger.warn calls in this code?

As it turns out, the answer is really simple. The ExUnit.CaptureLog module has a capture_log function that takes an anonymous function as an argument and returns a string with the log messages produced by calling that function. We can then make an assertion on the returned string:

import ExUnit.CaptureLog
...

test "logs a warning message with invalid credentials", %{conn: conn, user: user} do
  assert capture_log(fn ->
    post(conn, Routes.user_session_path(conn, :create), %{
        "user" => %{"email" => user.email, "password" => "invalid_password"}
      })
  end) =~ "[warn] LOGIN ERROR: Attempted login to #{user.email} from 127.0.0.1"
end

This test will pass as long as the string we are asserting on is somewhere inside the output from capture_log.

But this test will fail:

test "logs an info message on successful login", %{conn: conn, user: user} do
  assert capture_log(fn ->
    post(conn, Routes.user_session_path(conn, :create), %{
      "user" => %{"email" => user.email, "password" => valid_user_password()}
    })
  end) =~ "[info] LOGIN: #{user.email} from 127.0.0.1"
end

There is nothing wrong with the test itself. The problem is that login success is being logged at the info level, but Phoenix by default only enables logging at the warn level or above when running tests. You can change that in the config/test.exs file:

config :logger, level: :info

Now our test will pass. But unfortunately, we are also getting a lot of other messages logged to the console, which makes it hard to read the test output. You can fix that by adding a line in config/test.exs:

config :logger, :console, level: :warn

This will get rid of the [info] messages logged to the test console.

The sample controller function and tests used above are based on code generated by phx.gen.auth. The generator injects another test that calls the create controller function, and with our current settings this test will still print a log message to the console. You can silence it by inserting @tag :capture_log on the line immediately before the test. Alternatively, you can silence all Logger output in a test module using @moduletag :capture_log.