If you have bug or you app is not working as expected, your log files may be critical to fixing the issue. We’ve covered the basics of debugging and now we’ll discuss what you need know about logging in your Elixir Phoenix application with Logger.
Logging keeps a record of data inputs, processes, data outputs, and final results in a program. You can traverse through logs and find out exactly where the application is having problems. Poor logs will leave you searching for answers, while a helpful log can assist you in resolving the bug right away.
Overview
We’ll cover the basics of Elixir Logger and use an example application to learn about different configuration and use cases.
- Logging in Elixir with Logger
- Phoenix Logging Example
- Demo Phoenix App
- Logging Levels
- Logging Metadata
Prerequisites
To follow this guide, make sure you have at least the following applications installed on your machine. In the brackets are the versions with which this guide was written.
- Elixir (1.12.3-otp-24)
- Erlang (OTP 24.1)
- Phoenix (1.6.2)
- Node.js with npm (15.14.0)
Logging in Elixir with Logger
Elixir programmers will often use IO.inspect/2 (guilty!) in their code as a quick and convenient debugging tool. Elixir provides Logger for logging in Elixir applications.
Using Elixir Logger is only a little more effort than that, but it’s much more elegant and flexible. As well as being useful for debugging, logging can also provide you with more – and better structured – information about the state and health of your application.
Logger provides debug, info, warn, and error levels. It supports multiple backends which are automatically supervised when plugged into Logger . Furthermore, it formats and truncates messages on the client to avoid clogging Logger backends. It also alternates between sync and async modes to remain performant when required but also apply backpressure when under stress. Finally, it integrates with Erlang’s :logger to convert terms to Elixir syntax.
We’ll use a sample project to learn more about Logger’s features.
Phoenix Logging Example
Before we get to the sample project, we’re going to look at how logging in implemented in Phoenix. When you start your server, the output in your console comes from Logger. Let’s check out the Phoenix.Logger module on GitHub.
Check out the code starting on line 205.
def phoenix_endpoint_start(_, _, %{conn: conn} = metadata, _) do
case log_level(metadata[:options][:log], conn) do
false ->
:ok
level ->
Logger.log(level, fn ->
%{method: method, request_path: request_path} = conn
[method, ?\s, request_path]
end)
end
end
You can see if takes information from the conn to include in the log message when the endpoint starts. You may not understand how the entire module works, but hopefully this helps you make the connection between output in your console and code in libraries you are using.
Demo Phoenix App
Now let’s create a simple application, so we can implement logging for ourselves. Use the command line to update your Phoenix version and create a new Phoenix application.
$ mix archive.install hex phx_new 1.6.2
$ mix phx.new hello_logging
Change into the project directory, create your database and start your server.
$ cd hello_logging
$ mix ecto.create
$ mix phx.server
Now visit http://localhost:4000 and you should see the Welcome to Phoenix! page.
Check your console and you should see something like:
[info] GET /
[debug] Processing with HelloLoggingWeb.PageController.index/2
Parameters: %{}
Pipelines: [:browser]
[info] Sent 200 in 30ms
You should have an idea now about where that logging info comes from in the Phoenix project code.
Logger Levels
Let’s play around with Logger levels. The supported levels are ordered by importance. You can update the config in your project to limit output to only certain levels.
The supported levels, ordered by importance, are:
:emergency– when system is unusable, panics:alert– for alerts, actions that must be taken immediately, ex. corrupted database:critical– for critical conditions:error– error message:warning– warning message:notice– for normal, but significant, messages:info– for information of any kind:debug– debug message
For example, :info log level takes precedence over :debug log level. If your log level is set to :info, then all :info, :notice and above will be passed to backends. If your log level is set to :alert, only :alert and :emergency will be printed.
Add a logging message for the following logging levels in you HelloLoggingWeb.PageController so they will be called when you visit the Phoenix homepage. We’ve also included a call to IO.inspect. Finally, you will need to require Logger.
defmodule HelloLoggingWeb.PageController do
use HelloLoggingWeb, :controller
# Add this to make Logger available
require Logger
def index(conn, _params) do
# Add these different logging messages
IO.inspect("This is IO.inspect")
Logger.debug("This is a debug log")
Logger.info("This is an info log")
Logger.warn("This is a warn log")
Logger.error("This is an error log")
render(conn, "index.html")
end
end
Next visit your homepage again. You should see the following in your console and the different levels may be different colors if your console supports it.
Logger displays all log statements with default settings, but you can adjust the level of log messages Logger sends in your app’s logger configuration. For example, a new Phoenix project is configured to :info log level in production.
# config/prod.exs
# Do not print debug messages in production
config :logger, level: :info
Let’s update our dev config to :warn level to see how it affects our log output.
# config/dev.exs
# Temporarily update dev to :warn level
config :logger, level: :warn
Restart your server and visit the homepage. You should only see the following in your console:
"This is IO.inspect"
[warn] This is a warn log
[error] This is an error log
Now that you’ve seen how we can adjust the log levels in config, remove our updates from config/dev.exs to return to default settings.
Let’s also remove all of the log messages except for the :info level.
defmodule HelloLoggingWeb.PageController do
use HelloLoggingWeb, :controller
# Add this to make Logger available
require Logger
def index(conn, _params) do
Logger.info("This is an info log")
render(conn, "index.html")
end
end
You should have the default :logger config and a Logger.info message when we visit the homepage.
Logging Metadata
Whenever a message is logged, additional information can be given via metadata. Each log operation, such as Logger.info/2, allows metadata to be given as an argument.
The default config/dev.exs setting removes metadata, so let’s comment that line out to get timestamps and metadata in development.
# config/dev.exs
# Do not include metadata nor timestamps in development logs
# config :logger, :console, format: "[$level] $message\n"
Restart your server and visit the homepage. You should see both timestamps and a request id added to you log output.
20:50:20.907 request_id=FsDUax3mYJj1FHgAAAAm [info] This is an info log
``
To understand our new timestamp and metadata details that have been added to the logs, check out `config/config.exs`.
```elixir
# Configures Elixir's Logger
config :logger, :console,
format: "$time $metadata[$level] $message\n",
metadata: [:request_id]
You can see the :format and :metadata settings for a new Phoenix project. You’ll also notice the default settings use the console backend.
We can add our own metadata to the logs. While we haven’t added users, we can simulate adding a user_id to the log metadata. For example, let’s look at the fetch_current_user/2 function added when you run mix phx.gen.auth. See docs on Forbidding access.
# Function from MyProjectWeb.UserAuth when generating auth using mix phx.gen.auth
def fetch_current_user(conn, _opts) do
{user_token, conn} = ensure_user_token(conn)
user = user_token && Accounts.get_user_by_session_token(user_token)
# Add user_id
Logger.metadata(user_id: user.id)
assign(conn, :current_user, user)
end
You can add the user_id as metadata to help you keep track of users as they visit pages in your app. We haven’t added authentication, so let’s just hard code this is a simple Plug of our own. Let’s add a function plug called fetch_current_user in our HelloLoggingWeb.Endpoint. Then add it before the plug HelloLoggingWeb.Router.
defmodule HelloLoggingWeb.Endpoint do
...
plug :fetch_current_user
plug HelloLoggingWeb.Router
def fetch_current_user(conn, _opts) do
Logger.metadata(user_id: 1)
conn
end
end
Now we need to update our config/config.exs file to add the user_id to our metadata.
# Configures Elixir's Logger
config :logger, :console,
format: "$time $metadata[$level] $message\n",
metadata: [:request_id, :user_id]
Restart your server and visit the homepage. Remember, we’ve added a Logger.info message to the homepage. We’ve also commented out the config/dev.exs line that removed metadata from the logging format.
You should see something similar to the following line in your console. All the log messages should contain both the request_id and user_id.
21:08:49.282 request_id=FsEkAb-qx_i7r1UAAABC user_id=1 [info] This is an info log
You can add other metadata to help make your logs easier to search and analyze. Adding a lot of metadata may grow the size of your logs substantially, so you only want to add new metadata that will provide value.
Additional Configuration
Logger supports a wide range of configurations. This configuration is split in three categories:
- Application configuration, including the option to set your logger backend. The default is the console backend, but you have the option to add an Elixir custom backend.
- Runtime configuration, including the ability to set the level, log format template, and truncate log messages.
- Erlang configuration – options that handle integration with Erlang’s logging facilities
Check out the docs for all the configuration options.
Conclusion
Congratulations! You’ve learned how to add logging into your own application. You can set the level and understand how to configure the levels in development and production. You also learned how to add your own metadata to the logs to make it easier for your to analyze logs.
If you liked learning about logging, we have an entire book about managing your app in production. See below for how to get the Quick Reference Guide from the Phoenix Deployment Handbook for free.