Manage Your Ruby Logs Like a Pro

Logs are essential to any application's development. Most Ruby logs are verbose and chunky, so digging for exactly what you need can be difficult. Even though they contain useful information, you might not get as much value as you should from logs if you don't know how to use them effectively.

In this article, we'll explore:

• The importance of logging
• How to use Ruby's inbuilt logging utilities — puts and Logger
• Log levels and their differences
• Customizing your logs using JSON
• Integrating a logging library, using Lograge as an example

Let's get started.

Prerequisites

To follow along with this tutorial, you should have the following:

• A local installation of Ruby (we'll be using Ruby 3.2.0 for the tutorial).
• Some experience with Ruby.

Let's start by answering the question: "Why do we need to log, anyway?"

Why We Log

Before we dive in, it helps to know exactly why we log in the first place.

Logs provide us with information on what's happening inside our Ruby app. This is very useful for tasks like debugging errors and collecting critical app metrics. Log data depends on the type of app we have and the environment it is running on.

With that out of the way, let's introduce Ruby's inbuilt logging utilities.

Ruby’s Inbuilt Logging Utilities: puts and Logger

Ruby comes with two logging utilities. One is puts, a method provided by the IO class (other methods include print, printf, and write).

The other inbuilt logging utility is the Logger class.

Let's explore each in more detail, starting with puts.

Ruby's puts Method

Ruby's puts method — which is actually syntactic sugar for STDOUT.puts — is a way of writing Ruby program messages to the STDOUT output stream (usually a terminal output). puts will print out the given message string and add a new line to the end of the output.

The example below shows a simple use case where we use puts to output each line's length from a given text file:

# line_lengths.rb
ARGV.each do |f|
  File.open(f).each_line do |line|
    puts line.length
  end
end

# MyFile.txt
Ruby is an awesome language to learn.
It's very simple to get started.

Then we run the above Ruby script and pass in the text file as the argument:

ruby line_lengths.rb MyFile.txt

And once the script has run, each line's length is written out to the console:

# output
38
33

This simple example provides a glimpse into the world of the input/output (IO) streams at the heart of logging. Basically, anytime you run a Ruby program, you spawn the following IO streams:

• STDIN - This stream accepts commands into your Ruby program — for example, a key pressed on a user's keyboard.
• STDOUT writes to an output — for example, a terminal displayed on a user's screen.
• STDERR writes to an output just like the STDOUT one, but with a subtle difference that we'll cover in the next section.

Each of these is integral to logging and understanding how they work forms the basis of properly applying logs in Ruby apps.

The Limitations of puts in Ruby

Even though puts is a convenient and easy logging method for simple Ruby programs, you will very quickly need a proper logging library instead.

Here are a couple of its limitations:

• Automatic timestamps aren't included by default - Unless you manually customize puts, you will not get any timestamps in your log output.
• Output is not categorized into appropriate log levels - We'll cover this in more detail later, but the puts method has no way to categorize output messages according to standard log levels.

These features are basic requirements for any logging solution. The fact that they are missing from the puts method by default (coupled with the manual customization needed to have meaningful output messages) means that our ability to properly log using the method is limited.

So let's now consider a more robust solution, the Ruby Logger class.

Logging with Ruby Logger

The Logger class is a sophisticated logging utility that can create single or multiple event logs from a Ruby application. Logger comes bundled in Ruby, so no gem installation is needed to get it up and running. You only need a simple require statement somewhere at the top of your script:

require 'logger'

After that, instantiate a new Logger object as below:

require 'logger'

logger = Logger.new(STDOUT)
logger.info("This is an info level log message")

Note: The Logger class can accept a number of arguments, but the first one is almost always the log stream output, followed by other arguments like the retention policy (how long logs should be kept, how much the log files should grow in size before they are rotated, etc.)

You will get output similar to this:

# output
I, [2023-01-11T17:45:49.067481 #67559]  INFO -- : This is an info level log message

From the printed log message, we have:

• The log level's shortened format - Indicated by the leading "D". In this case, it shows that this is an info level log entry.
• A timestamp - A full timestamp of the log entry.
• A process ID - The ID of the server process running the program.
• The log level type in full.
• A program name - An optional argument that can be added to a Logger entry (we'll see how in a later code example).
• The log message - The message output that will be printed in the log entry (also optional).

Each of these log entry components is important, and together they give context to app events that lead to the creation of log entries.

That said, one aspect of log entry that deserves more coverage is the log level. Let's take a look at it next.

Understanding Log Levels

A log level setting tells the Logger a log message's severity. The severity level depends upon the event that resulted in that log output.

There are six levels of severity, ranging from the least to the most severe:

# example.rb
require 'logger'

logger = Logger.new(STDOUT)

logger.add(Logger::DEBUG, 'Least severe - debugging info')
logger.add(Logger::INFO, 'Next level - informational log')
logger.add(Logger::WARN, 'Warning level - warning log info')
logger.add(Logger::ERROR, 'Non-fatal error log info')
logger.add(Logger::FATAL, 'Fatal error log info')
logger.add(Logger::UNKNOWN, 'Most severe log level')

And here's the output:

# output
D, [2023-01-11T18:19:47.919567 #69315] DEBUG -- : Least severe - debugging info
I, [2023-01-11T18:19:47.919622 #69315]  INFO -- : Next level - informational log
W, [2023-01-11T18:19:47.919645 #69315]  WARN -- : Warning level - warning log info
E, [2023-01-11T18:19:47.919661 #69315] ERROR -- : Non-fatal error log info
F, [2023-01-11T18:19:47.919675 #69315] FATAL -- : Fatal error log info
A, [2023-01-11T18:19:47.919689 #69315]   ANY -- : Most severe log level

Log levels can help filter out app and server events that warrant your attention. To put this into context, consider these differences between log levels:

• debug - This is the default log level and the most information-rich. When this log level is enabled, your log entries will include pretty much every request happening in your app. This is particularly useful for a debugging session.
• info - A level above debug. Just like the previous log level, enabling this level will result in some very information-rich log entries of your app's events. info log entries will tell you what's going on with your app — for instance, running processes and method calls.
• warn - Any log entries at this level usually mean that your app encountered a problem, but nothing so severe that your app can't continue to function as expected (for example, you may have used an outdated method call for a gem or library.)
• error - At this level, your app has encountered an error that stops it from proceeding with the action that caused the error. However, this does not stop other parts of the app from working as expected. For example, if your app references a recently moved file, an error log entry will likely be generated.
• fatal - Your app has encountered an error that stops it from working any further. This could be caused by anything from running out of memory on the production server or a crashed background job.
• unknown - The actual cause of an error cannot be reliably traced.

Now that we have more information on log levels, let's see how to practically use them in a Ruby app.

Using Log Levels in a Ruby Application

In a development environment, the default log level is set to debug. As mentioned earlier, if your app's log level is set to debug (or even info), your output will include everything happening in the app. You will have very information-rich log entries that make for easier debugging in development.

However, in production, it isn't wise to use the debug or info log levels.

For starters, a production app will likely have too many processes, users, and method calls going on, so could very easily generate thousands (if not millions) of log entries. If these entries are being saved to log files on a production server, you can quickly run out of disk space.

Secondly, any attempt to sift for important error and fatal entries is extremely inefficient in production simply because you will have too much information to go through. So, you should only log entries when something "important" happens or when your app malfunctions in such a way that the user experience is affected.

It therefore makes more sense to set the log level at something more manageable like the error level, for example.

Although setting the log level can reduce the amount of information in the log entries, it doesn't help format the entries in any way. To do that, you need to customize the log output.

Customizing Log Output in Ruby

Customizing log output involves changing the format of how log entries look and the information they contain when printed out.

By default, log entries printed to the terminal will be in black and white text. But for some logs, a little color can go a long way. You can colorize default log output using ANSI color codes.

In Ruby, this is possible using a gem like Colorize or Rainbow.

You can format the printed output from your Ruby program using either of these gems. This example code uses Rainbow to colorize some sample log outputs:

# example.rb
require 'logger'
require 'rainbow'

logger = Logger.new(STDOUT)
logger.debug("This is a #{Rainbow('debug message!').blue}")
logger.info("This is a #{Rainbow('info message!').green}")
logger.warn("This is a #{Rainbow('warning message!').orange}")

And here's the colorized log output:

The other way to format log entries goes beyond just customizing the look and feel. First, consider the simple Logger entry below:

# output
D, [2023-01-23T15:29:35.924904 #11021] DEBUG -- my_prog: This is a debug level log entry

It's good to note that you are not limited to using the log entry as is. It is entirely possible to customize a log message by tweaking the log entry components. Let's see how.

The first step is to call Logger.new, and then add some log entries:

# example.rb
logger = Logger.new(STDOUT)

logger.info('This is an informational level log')
logger.error('This is just an error log')

Which gives us this output:

# output
I, [2023-01-23T16:24:34.315029 #12604]  INFO -- : This is an informational level log
E, [2023-01-23T16:24:34.315112 #12604] ERROR -- : This is just an error log

It's also possible to customize a program name in the log entry, like so:

# example.rb
logger = Logger.new(STDOUT)

logger.progname = 'sending emails'

logger.info('This is an informational level log')
logger.error('This is just an error log')

And here's the subsequent output:

# output
I, [2023-01-23T16:45:55.156600 #14183]  INFO -- sending emails: This is an informational level log
E, [2023-01-23T16:45:55.156660 #14183] ERROR -- sending emails: This is just an error log

By customizing the log entry's program name, you can add even more contextual information to your logs.

Now, let's look at how to customize all of the log entry's components all at once:

# example.rb
logger = Logger.new(STDOUT)

logger.formatter = proc do |severity, datetime, progname, msg|
  date_format = datetime.strftime("%Y-%m-%d")
  "date=[#{date_format}] severity=#{severity.ljust(5)} pid=##{Process.pid} message='#{msg}'\n"
end

logger.debug("This is a formatted log message!")

# output
date=[2023-01-12] severity=DEBUG pid=#75142 message='This is a formatted log message!'

Here, we use the logger entry formatter proc, which takes four arguments — severity, datetime, the program's name, and the message — to format the log entry and output a string formatted in the way specified.

Great — but we can still do better! So far, everything we've done has produced log outputs in an unstructured format. But log entries can build up quickly in a production app that has thousands of users and millions of processes. Parsing unstructured logs can take up significant time and is very inefficient.

What if there was a way to quickly and efficiently search through log files? Enter JSON.

Logging into JSON

The Javascript Object Notation format — or JSON — is a structured text format that uses key/value pairs.

It's not the only format that has structured text — there are others like YAML and even TOML. Both YAML and TOML function best as configuration files, though, while JSON's structure makes it really good for logging.

Here's some code that outputs a JSON-formatted log entry:

# example.rb
require 'logger'
logger = Logger.new(STDOUT)
logger.formatter = proc do |_severity, datetime, _progname, msg|
  %({timestamp: "#{datetime}", message: "#{msg}"}\n)
end
logger.info 'Hello, world!'

# output
{timestamp: "2023-02-13 17:47:13 +0300", message: "Hello, world!"}

At first glance, it's not easy to see why one would even want to do something like this. But with JSON formatted logs, it's possible to:

• Easily parse logs as they are now structured in a particular format (compared to the mass of unstructured entries characteristic of default logs). You can search for particular pieces of information using JSON keys tied to specific values.
• Forward these logs to a proper log processing tool that can process log outputs of almost any size.

So we've seen how useful Logger can be. But that does not mean the library is perfect.

Logger does have its imperfections, and we'll look at these next.

Limitations of Logger

If you use Logger to write output to log files frequently, one challenge you'll likely face is unreadable characters messing up your log files. These are caused by colorization ANSI codes not being parsed correctly in the log output files.

For example, consider this example code:

# example.rb
require 'logger'
require 'rainbow'

msg = Rainbow("this is red").red + " and " + Rainbow("this on yellow bg").bg(:yellow) + " and " + Rainbow("even bright underlined!").underline.bright

logger = Logger.new('colorized.log')

logger.debug(msg)

If you try to open the resulting log file, you'll notice it contains a bunch of unreadable characters in the log message section:

# output
# Logfile created on 2023-01-23 23:09:12 +0300 by logger.rb/v1.5.3
D, [2023-01-23T23:09:12.920635 #31599] DEBUG -- : ^[[31mthis is red^[[0m and ^[[43mthis on yellow bg^[[0m and ^[[4m^[[1meven bright underlined!^[[0m

One way to fix this problem is by using a string regex to escape these characters. For example, the Colorize gem contains a convenient uncolorize block:

# example.rb
...
def uncolorize
  self.scan(REGEXP_PATTERN).inject("") do |str, match|
    str << (match[3] || match[4])
  end
end
...

Another limitation of Logger, especially for busy production apps, is that default Logger entries can end up as information-rich multi-line entries (even when the log level has been set to something above the debug and info levels, like the error level).

If you're in charge of such an app, debugging can easily become a messy affair as you have to go through a mass of unstructured text to get what you want.

Considering these limitations, let's seek a better logging solution — one that has the features we've been lacking in most of the solutions we've outlined so far.

Integrating a Third-Party Logging Library

You can choose from a number of third-party logging libraries, including Logging — based on Java's log4j library — and Lograge. Lograge is a feature-rich logging library meant to simplify the often messy and verbose Rails logs characteristic of the default application logger.

Also worth mentioning is httplog, a specialized logging library for tracking third-party API calls that might not be captured in regular logs.

For this article, we'll look at Lograge.

Lograge for Logging in Rails

According to Lograge's GitHub page, Lograge is an attempt at bringing sanity to Rails' unusable and unparsable log output.

Lograge replaces the default Rails logger and simplifies output to single lines, with all the important information included. The resulting output is much easier to read through than the Rails logger.

Getting Started with Lograge

To get started with Lograge, open up your project's Gemfile and add the following line:

# Gemfile

gem "lograge"

Then run bundle install to finalize the installation.

Logging in Rails: Using Lograge with AppSignal

With Lograge installed, you're halfway through setting up a capable logging solution for your app. The next obvious question is what you'll use to read and parse the logs. SSHing into your server to read through log tails is highly inefficient, so what to do?

Well, AppSignal has a new logging feature that is perfect for this.

To get started, install the latest version of the AppSignal for Ruby gem by adding it to your Gemfile:

# Gemfile

gem 'appsignal'

Then run bundle install. If you already have the gem installed in your project, just run bundle update appsignal to get the latest version.

Next, add an initializer with the following information:

# config/initializers/lograge.rb

Rails.application.configure do
  config.lograge.enabled = true
  config.lograge.keep_original_rails_log = true
  config.lograge.logger = Appsignal::Logger.new(
    "rails",
    format: Appsignal::Logger::LOGFMT
  )
end

And that's it! You can now conveniently access your app's logs from AppSignal's logging dashboard:

Wrapping Up

In this article, we took a deep dive into the world of Ruby logs. We learned about puts, the Logger class, and how to customize log messages using JSON. We finally explored logging using Lograge and AppSignal.

Obviously, logging in Ruby goes much deeper. Use this post as a stepping stone to learn more. You might also find our Making the Most of Your Logs in Rails and Audit Logging in Ruby and Rails posts useful.

Thanks for reading!

P.S. If you'd like to read Ruby Magic posts as soon as they get off the press, subscribe to our Ruby Magic newsletter and never miss a single post!