Debugging with Rails Logger

This post originally appeared on the Scout blog.

If you’re a Rails developer, then you’ve probably used Rails Logger on at least one occasion or another. Or maybe you have used it without even realizing, like when you run ‘rails server’ and it prints information to the terminal window, for example. Rails Logger provides us with a powerful way of debugging our applications and gives us an insight into understanding errors when they occur. But are you using all of the Rails Logger features? There’s a good chance you are not! So let’s take a more in-depth look at the logging system in Rails, look at some of its more unknown features, and establish some best practices for our log creation in the future.

What is the Rails Logger?

The Rails Logger is part of the the ActiveSupport library, which is a utility library and set of extensions to the core Ruby language. It builds on top of Ruby’s Logger class and provides us with a simple mechanism for logging events that occur throughout our application’s lifetime. Logging enables us to record information about our application during runtime, and store it persistently for later analysis and debugging.

Rails is configured to create separate log files for each of the three default environments: development, test and production. By default it puts these log files in the log/ directory of your project. So if you open up that folder you’ll see a development.log and test.log file, and perhaps a production.log file too, depending on how your project is set up.

Using the Rails Logger is as simple as adding a line of code like the one shown below to one of your Controllers, Models or Mailers:

logger.debug "User created: #{@user.inspect}"

Here we use the debug method of the globally accessible logger to write a message with an object’s details to the log. In our development environment, this prints our log message to the terminal as well as to the development.log file:

The debug level which we specified is just one of six possible levels that we can use, and there is a corresponding method to call for each of these levels. By having a level system for our logs, it allows us to group logs together and then selectively choose which levels get reported and which do not. For example we might not pay much attention to low-level debugging information in our production environment, instead we would want to hear about errors and warnings that are occurring. Let’s take a look at each of these levels and see what they can be used for:

Customizing our logs

Perhaps that’s as far as most Rails developers go with Rails Logger; just logging the occasional debug messages while they develop. But there is much more that we can do with this powerful tool. Let’s take a look at how we would customize the logging system to work differently from it’s default settings.

We can customize our logger settings either collectively in the main application.rb file, or individually for each environment in each of the config/development.rb, config/test.rb and config/production.rb files. Here we can do things like change the logging level that gets reported, define different locations for our logs, or even write to our logs in different formats that we can define ourselves.

Changing the log level

If we wanted to prevent developer-specific log messages from filling up our logs in our production environment, we could instead set the logging level to :error. This would show only log messages from the error level down. In other words just error and fatal messages would be reported.

# config/environments/production.rb
config.log_level = :error

Outside of these environment initializer files, you can also just temporarily change the log level dynamically, anywhere in your code, like this:

# From anywhere, you can specify a value from 0 to 5
Rails.logger.level = 3

This might be useful if you want to turn on a verbose-level of logging around a certain task, and then quickly turn it off again.

Changing the log location

To change the location of where our log file gets saved to somewhere other than log/, we can define a new logger and specify our own path like this:

# config/environments/development.rb
config.logger = Logger.new("/path/to/file.log")

Changing the log format

For even more flexibility, we can take this a step further by overriding the Rails’ formatter class with our own custom class. This allows us to fully define how our logs look, and if we wanted to, we could also add our own complex logic to determine what gets logged and how it gets logged.

class CustomFormatter < ActiveSupport::Logger::SimpleFormatter                  
  def call(severity, time, progname, msg)                                       
    "[Level] #{severity} \n" +                                                  
    "[Time] #{time} \n" +                                                       
    "[Message] #{msg} \n\n\n"                                                   
  end                                                                           
end

After putting that file in our lib/ folder, we can tell Rails Logger to use like this:

# config/environments/development.rb
config.log_formatter = CustomFormatter.new

As you can see, even this small, simple change makes the log much more readable:

Another good use case for writing your own formatting class might be if you wanted to output the logs in JSON format so that you can integrate your logs with other systems.

Tagged Logging

Another powerful feature of Rails Logger is the ability to tag our log entries. This could really useful if your application runs across multiple subdomains for example. In this scenario, by adding a subdomain tag you would be able to clearly separate log entries for the different subdomains you are using. Another example is that you could add a request ID tag, this would be very useful when debugging so that you could isolate all log entries for a given request.

To enable tagged logging, you need to create a new logger of type TaggedLogging and assign it to config.logger in your config file:

# config/environments/development.rb
config.logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT))

Once you’ve done this you can put your logs in blocks of code following a call to the tagged method:

# This will log: [my-subdomain] User created: ...
logger.tagged("my-subdomain") { logger.debug "User created: #{@user.inspect} }"

What’s next?

Rails Logger is a very flexible tool that should be a part of every Rails developers development process, and as we’ve seen, by making just a couple of small tweaks we can be even more productive and efficient in our debugging process. Hopefully we’ve given you some good ideas about how you can start to do that.