Don't let the last word to the Logger
You know those days, right? Either you’re jumping from one zoom call to another with barely time to breathe, or you’re in the zone, fingers flying over the keyboard, crushing a tricky bug. And bam! That’s exactly when you might accidentally leave a Logger statement hanging there as your function’s last word. Oops!
Been there, done that - it’s a simple mistake that can lead to subtle bugs. Let’s see how to catch them using a custom Credo check.
Returning a Logger statement is a valid return after all
In Elixir a logger statement returns :ok always, whatever level you use, even with Logger.error and it makes total sense, that’s a deliberately choice inherited from Erlang.
And this implicit return value can trick you. Let’s see a silly example just to clarify what I mean:
defmodule HelloWorld do
require Logger
def post_request(payload) do
case HttpClient.post(payload) do
:ok ->
Logger.info("yay! created")
{:error, reason} ->
Logger.error("Oh no! Error: #{inspect(reason)}")
end
end
end
As you can read from the little snippet above, when the HttpClient.request/1 call succeeds, it returns :ok, otherwise an error tuple {:error, reason}.
While the Logger.info is theoretically not harmful here since it returns :ok like the HTTP call, the Logger.error is probably not what you want as the handler of the {:error, reason} case.
While waiting for types: custom Credo check
I don’t think I’ll ever use this Credo check in any projects I’m working on, even more now that types are coming, but I stumble upon this issue recently and I thought, why not, let’s do that just for fun™️.
With the help of Claude I assembled this custom check in less than 30 minutes including tests and I wrapped it in a elixir script no_logger_as_last_statement.exs for convenience.
# no_logger_as_last_statement.exs
Mix.install([:credo])
defmodule Credo.Check.NoLoggerAsLastStatement do
use Credo.Check,
base_priority: :high,
category: :warning,
explanations: [
check: """
Logger calls should not be the last statement in a function.
Logger calls are asynchronous and return :ok, which might not be the intended
return value for the function.
"""
]
# https://hexdocs.pm/logger/1.18.1/Logger.html#t:level/0
@logger_levels [
:emergency,
:alert,
:critical,
:error,
:warning,
:warn,
:notice,
:info,
:debug
]
@impl true
def run(%SourceFile{} = source_file, params \\ []) do
issue_meta = IssueMeta.for(source_file, params)
Credo.Code.prewalk(source_file, &traverse(&1, &2, issue_meta))
end
# Match function definitions
defp traverse({def_type, _meta, [_head, [do: body]]} = ast, issues, issue_meta)
when def_type in [:def, :defp] do
case analyze_last_statement(body) do
[] -> {ast, issues}
lines -> {ast, issues ++ Enum.map(lines, &issue_for(issue_meta, &1))}
end
end
# Default case - continue traversing
defp traverse(ast, issues, _issue_meta) do
{ast, issues}
end
# Handle blocks - only check the last statement
defp analyze_last_statement({:__block__, _meta, statements}) do
statements
|> List.last()
|> analyze_last_statement()
end
# Handle if expressions
defp analyze_last_statement({:if, _meta, [_condition, [do: do_block, else: else_block]]}) do
analyze_last_statement(do_block) ++ analyze_last_statement(else_block)
end
# Handle case expressions
defp analyze_last_statement({:case, _meta, [_expr, [do: clauses]]}) do
Enum.flat_map(clauses, fn {:->, _, [_pattern, body]} ->
analyze_last_statement(body)
end)
end
# Handle cond expressions
defp analyze_last_statement({:cond, _meta, [[do: clauses]]}) do
Enum.flat_map(clauses, fn {:->, _, [_, body]} ->
analyze_last_statement(body)
end)
end
# Handle with statements
defp analyze_last_statement({:with, _meta, args}) do
# Extract the last item from args which is the [do: do_block, else: clauses] keyword list
blocks = List.last(args)
case blocks do
[do: do_block] ->
analyze_last_statement(do_block)
[do: do_block, else: clauses] ->
analyze_last_statement(do_block) ++
Enum.flat_map(clauses, fn {:->, _, [_pattern, body]} ->
analyze_last_statement(body)
end)
end
end
# Handle direct Logger.<level>/2 calls
defp analyze_last_statement(
{{:., _meta1, [{:__aliases__, _meta2, [:Logger]}, level]}, meta3, _args}
)
when level in @logger_levels do
[meta3[:line]]
end
# Handle direct Logger.log/3 calls
defp analyze_last_statement(
{{:., _meta1, [{:__aliases__, _meta2, [:Logger]}, :log]}, meta3, _args}
) do
[meta3[:line]]
end
# Everything else is not a Logger call
defp analyze_last_statement(_ast) do
[]
end
defp issue_for(issue_meta, line_no) do
format_issue(
issue_meta,
message: "Logger call should not be the last statement in a function",
line_no: line_no
)
end
end
ExUnit.start()
defmodule MyProject.Checks.RejectModuleAttributesTest do
use Credo.Test.Case
alias Credo.Check.NoLoggerAsLastStatement
test "returns NO warnings" do
"""
defmodule Foo do
require Logger
def bar do
Logger.info("42")
42
end
end
"""
|> to_source_file()
|> run_check(NoLoggerAsLastStatement)
|> refute_issues()
end
test "returns a single warning" do
"""
defmodule Foo do
require Logger
def bar do
Logger.info("42")
end
end
"""
|> to_source_file()
|> run_check(NoLoggerAsLastStatement)
|> assert_issue()
end
test "flags Logger.log/3 too" do
"""
defmodule Foo do
require Logger
def bar do
Logger.log(:info, "42")
end
end
"""
|> to_source_file()
|> run_check(NoLoggerAsLastStatement)
|> assert_issue()
end
test "returns a warning for each if/else block" do
"""
defmodule Foo do
require Logger
def bar(arg) do
if arg == true do
Logger.info("42")
else
Logger.error("24")
end
end
end
"""
|> to_source_file()
|> run_check(NoLoggerAsLastStatement)
|> assert_issues(&(length(&1) == 2))
end
test "returns a warning for only one branch" do
"""
defmodule Foo do
require Logger
def bar(arg) do
if arg == true do
Logger.info("42")
42
else
Logger.error("24")
end
end
end
"""
|> to_source_file()
|> run_check(NoLoggerAsLastStatement)
|> assert_issue()
end
test "handles nested clauses" do
"""
defmodule Foo do
require Logger
def bar(arg) do
if arg == true do
Logger.info("42")
else
if arg == 42 do
Logger.info("42")
42
else
Logger.error("24")
end
end
end
end
"""
|> to_source_file()
|> run_check(NoLoggerAsLastStatement)
|> assert_issues(&(length(&1) == 2))
end
test "handles case statements" do
"""
defmodule Foo do
require Logger
def bar(arg) do
case arg do
true ->
Logger.info("TRUE")
42 ->
Logger.info(42)
42
false ->
Logger.error("FALSE")
string when is_string(string) ->
Logger.info(string)
string
end
end
end
"""
|> to_source_file()
|> run_check(NoLoggerAsLastStatement)
|> assert_issues(&(length(&1) == 2))
end
test "handles cond statements" do
"""
defmodule Foo do
require Logger
def bar(arg) do
cond do
arg == true ->
Logger.info("TRUE")
arg == 42 ->
Logger.info(42)
42
false ->
Logger.error("FALSE")
string when is_string(string) ->
Logger.info(string)
string
_else ->
Logg.error("ELSE")
end
end
end
"""
|> to_source_file()
|> run_check(NoLoggerAsLastStatement)
|> assert_issues(&(length(&1) == 3))
end
test "handles with statements" do
"""
defmodule Foo do
require Logger
def bar(arg) do
with {:ok, _} <- arg do
Logger.info("OK")
else
{:error, _} ->
Logger.error("ERROR")
end
end
end
"""
|> to_source_file()
|> run_check(NoLoggerAsLastStatement)
|> assert_issues(&(length(&1) == 2))
end
end
You can run with elixir no_logger_as_last_statement.exs (adjust the filename). And voila, we have our own custom check ready to be used.
A closer look
The check recursevly traverses the AST and identifies if the last statement in a block (:__block__) is a Logger call:
- either
Logger.info/2(or other levels) - or
Logger.log/3
In that case, it appends a new Credo warning for the flagged line to accumulated ones.
The check handles if/else, case, cond and with statements, and the recursive approach works out of the box with nesting too 🚀 (ahhh… the beauty of the language!).
Final notes
Again, I don’t think I’ll never use this check, but I found it an interesting exercise.
I’m sure it does not cover all the possibilities (e.g. apply/3 or logger calls using the erlang :logger module), but hey 🤷♂️.
See you around ✌️.