Seven Typical Problems With Logging Ruby (And How to Solve Them)

Last updated: August 2024

If your application uses Ruby, there are multiple ways to write log messages, each with various degrees of ease-of-use and control. Yet all these methods come with known issues that can derail your attempts to diagnose software issues and assist your Ruby troubleshooting.

Why Do We Need Logging in Ruby?

No matter how much logging you collect from other sources, some issues can only be diagnosed with application-level logging. As your application scales and you experience more crashing servers, network failures, and intermittent bugs, logs become even more important. Beyond application details, logs can even include business intelligence data to help you make improved business decisions.

Prerequisites:

Before we dive into solving typical Ruby logging problems, let’s make sure you have the basics covered. Ensure you have Ruby installed on your system. You can find installation instructions here.

Here are seven typical problems with logging in Ruby, and the solutions to help resolve them.

1. Using puts for Logging Is a Lot of Work

While Ruby’s puts method is an easy way to write Ruby logs, it lacks most of the basic features of a real logging system. For instance, puts doesn’t provide automated timestamps, log at different priority levels, or use a standard format. All of this means that you need to write extra code to emit usable log messages.

Many logging frameworks include all of the above features as standard, and many of them include much more. The quickest way to get started is to use Ruby’s built-in logging mechanism, logger, since it doesn’t require third-party gems.

The following Ruby code example instantiates a new logger object and configures it to log messages above the WARN level:

require ‘logger’
logger = Logger.new(STDOUT)
logger.level = Logger::WARN

You can then write log messages from within your application using the logger object:

logger.debug(“A debug message”)

This code produces the following message, complete with timestamp and log level prefix:

D, [2019-03-18T14:12:44.116332 #28944] DEBUG -- : A debug message

The logger object has 6 methods for writing messages, each with a corresponding log level — :debug, :info, :warn, :error, :fatal, and :unknown.

2. Raw ANSI Color Codes Can Appear in Logs

By default, the Ruby on Rails logger uses ANSI color codes in log messages, which can cause problems if you send logs to a destination, such as a text file, that cannot parse those codes. Instead of colorful log messages, those log files will contain raw control characters. Here’s an example showing what a logger.debug message using colors looks like in a plain-text file:

D, [2019-03-18T14:12:44.116332 #28944] DEBUG -- : [1m[36mA debug message[0m

To fix this semi-unreadable log, you can disable colorized messages with the following configuration options.

For Rails >= 3.x:

config.colorized_logging = false

For Rails 2.x:

config.active_record.colorize_logging = false

3. The Default Logger Is Too Verbose for Production

Ruby’s built-in Logger class allows you to write messages with an individual log level and set an application-wide log level below which messages will not be logged. However, many developers run into a big issue when using the default logger in production: it’s way too noisy, with messages often split across multiple lines, making them difficult to read.

Log Levels in Ruby

Logging systems commonly use different log levels to categorize log messages according to their severity. Here are the standard log levels used in Ruby:

• DEBUG: Detailed information, typically useful only for diagnosing problems.
• INFO: Confirmation that things are working as expected.
• WARN: An indication that something unexpected happened, which might indicate a growing problem  (e.g., ‘disk space low’). The software is still working as expected.
• ERROR: Due to a more serious problem, the software has not been able to perform some function.
• FATAL: A severe error that causes the program to terminate immediately.
• UNKNOWN: An unknown message type.

Lograge was created to address this problem with the default logging instrumentation in Rails. Instead of writing messages across multiple lines, Lograge writes a much shorter string on a single line and includes only actionable information.

To use Lograge, you need to include the gem:

gem ‘lograge’

Once the gem is added, enable it in an initializer or your environment config:

# config/initializers/lograge.rb
# OR
# config/environments/production.rb
Rails.application.configure do
  config.lograge.enabled = true
end

If you’re using Rails 5’s API-only mode and inherit from ActionController::API, you must define it as the controller base class which Lograge will patch:

# config/initializers/lograge.rb
Rails.application.configure do
  config.lograge.base_controller_class = 'ActionController::API'
end

Because Lograge patches existing logging classes, log messages are automatically improved without you needing to modify any code. For example, while the default Rails request log contains multi-line messages like this:

Started GET "/" for 127.0.0.1 at 2012-03-10 14:28:14 +0100
Processing by HomeController#index as HTML
  Rendered text template within layouts/application (0.0ms)
  Rendered layouts/_assets.html.erb (2.0ms)
  Rendered layouts/_top.html.erb (2.6ms)
  Rendered layouts/_about.html.erb (0.3ms)
  Rendered layouts/_google_analytics.html.erb (0.4ms)
Completed 200 OK in 79ms (Views: 78.8ms | ActiveRecord: 0.0ms)

Lograge instead writes much more succinct messages:

method=GET path=/jobs/833552.json format=json controller=JobsController  action=show status=200 duration=58.33 view=40.43 db=15.26

4. Lograge Uses the Info Log Level by Default

Even though Lograge is a marked improvement over the standard logging mechanism in Rails, it’s not without its own foibles. One major caveat is that the log level of each message is info by default, which makes it far too easy to incorrectly categorize critical log messages as unimportant.

You can force Lograge to use an appropriate level by customizing the log levels and storing them in a level variable by adding the following to application/controller.rb:

# controllers/application_controller.rb
def append_info_to_payload(payload)
      super
     case 
        when payload[:status] == 200
          payload[:level] = "INFO"
        when payload[:status] == 302
          payload[:level] = "WARN"
        else
          payload[:level] = "ERROR"
        end
end

Then, you need to use the new level variable in the custom_options hook from an initializer file like this:

#config/initializers/lograge.rb
[...]
    config.lograge.custom_options = lambda do |event|
      { :params => event.payload[:params],
        :level => event.payload[:level],
      }
  end

This code uses the HTTP status of the request to infer the correct log level to use.

5. Unstructured Logs Are Difficult to Filter

To truly benefit from a centralized log management tool such as Loggly^®, Fluentd^®, or Papertrail^™, you need to generate structured logs. Using structured logs allows these log management tools to easily search through and run filters on logs, making it possible to analyze logs at scale.

Lograge supports JSON-formated output which is turned on by using the Lograge::Formatters::Json.new formatter:

# config/environments/production.rb
Rails.application.configure do
  config.lograge.formatter = Lograge::Formatters::Json.new
end

Doing so turns the following message:

I, [2018-08-31T14:37:44.588288 #27948]  INFO -- : method=GET path=/ format=html controller=Rails::WelcomeController action=index status=200 duration=105.06 view=51.52 db=0.00 params={'controller'=>'rails/welcome', 'action'=>'index'} headers=#<ActionDispatch::Http::Headers:0x046ab950> view_runtime=51.52 db_runtime=0

into trivially machine-readable JSON text:

I, [2018-08-31T14:51:54.603784 #17752]  INFO -- : {'method':'GET','path':'/','format':'html','controller':'Rails::WelcomeController','action':'index','status':200,'duration':104.06,'view':51.99,'db':0.0,'params':{'controller':'rails/welcome','action':'index'},'headers':'#<ActionDispatch::Http::Headers:0x03b75520>','view_runtime':51.98726899106987,'db_runtime':0}

6. Logging Can Degrade Application Performance

Because Ruby makes it easy to write log messages, it’s all too easy to write too much data to your log files. Excessive writing to log files on disk can negatively impact the performance of your application, especially if you’re running a large program with lots of processes.

You can solve this problem by judiciously using log levels and by ensuring that only important messages are written to the log file, for example by ignoring all messages at the debug level. Unfortunately, even if the log level is ignored, the Ruby code itself is still evaluated. Code that includes lots of logger calls can also degrade performance, even if those calls aren’t executed.

One way to mitigate this problem is to use Ruby’s blocks construct, otherwise known as lazy loading. Using blocks allows Ruby to defer evaluation until the message’s String object is definitely needed.

So, instead of writing a debug message in the normal way:

logger.debug “A debug message”

You can use blocks to defer evaluation:

logger.debug { “A debug message “}

7. Logs Missing Vital Information

Clearly, there are many ways to write log messages in Ruby, but none of them will help you if crucial information isn’t included in the logs when you need it—logs are often the only way to debug issues after they’ve occurred. To aid in debugging, at a bare minimum you should consider including the following context from your web application in each log message:

• User ID
• Timestamp
• HTTP method and response code
• URL requests and parameters
• Query latency

Typing out these details for every message is fairly cumbersome, so thankfully there is a simpler way: Ruby on Rails has a built-in mechanism to include extra information with its Active Support Tagged Logging feature.

Here’s an example of tagged logging:

logger.tagged(current_user_id ? "user-#{current_user_id}" : "user-anonymous") do
  logger.debug "Searching for posts..."
  @post = Post.all
  logger.debug "Found #{@post.length} posts!"
end

The resulting log message includes a user ID as a prefix, :

[user-123] Searching for posts...

[user-123]

Post Load (0.3ms) SELECT “post”.* FROM “post” [user-123] Found 511 posts!

Conclusion

Though Ruby and the popular Ruby on Rails framework provide logging capabilities out of the box, there are a number of tricky issues you need to watch out for when using logging in production. The seven problems listed in this article are common hurdles for Ruby developers, but if you use the techniques in this article your logs will contain the right information in an easily readable format to help you when you need them most—when things break.