All Rubyists Love Logging

If you’re an old hand at Rails, you likely take logging for granted. However, if you’re one of the unicorns that write apps in Ruby and don’t use Rails, you’ve probably done little-to-no logging. Apps that don’t use a database on the backend or local command line style apps with no datastore may actually have no logging at all. Is this a problem? Should you be worried? What even is logging?

What is Logging?

Logging generally refers to an application writing various kinds of activity to a file (or database, or the console) as it happens in the application. So, right away, we have a rather fuzzy definition.

• What exactly should you be logging? Errors? Transactions? Status?
• What will your logs be used for? Audit trail? Error tracking? Debugging?
• Who will be looking at these logs? Developers? Managers? Support?

If I haven’t made it clear by now, logging is a very business process heavy construct. While I can’t tell you what to log, I can show you an easy way to add logging to your application, whether it’s a script, command line app, Sinatra web app, or whatever!

Class: Logger

As Ruby developers, we’re lucky to have the Ruby Standard Library, which once again has us covered. The Logger class has everything we need for most of our logging needs. You can have one logger object for each type of log, or one for each class, or any other combination you can imagine. For a beginner, and for most simple-to-moderate needs, I’ve found that one log to rule them all works well.

One Log to Rule Them All

How do you add this to your app?

require 'logger'

class MyLog
  def self.log
    if @logger.nil?
      @logger = Logger.new STDOUT
      @logger.level = Logger::DEBUG
      @logger.datetime_format = '%Y-%m-%d %H:%M:%S '
    end
    @logger
  end
end

That’s it. Your entire application can now write to the log with a line like this:

MyLog.log.info "Look, ma! I'm loggin'!"

Since it’s writing to STDOUT, you’d see this in your terminal:

I, [2014-08-13 15:18:50-0600 #65630]  INFO -- : Look, ma! I'm loggin'!

How It Works

Let’s break down what our code is actually doing. First, there’s something we’re not doing.

We’re not instantiating a logger object directly into our application and passing that object around, all OOP style. Instead, we create a small class called MyLog with a single class method called log. This single method checks to see if a logger object exists, creates it if it doesn’t, and returns it. Ruby developers generally don’t write a lot of class methods, but this is a clever way to create a globally accessible object.

You could just, you know, create a global variable:

$log = Logger.new STDOUT
$log.level = Logger::DEBUG
$log.datetime_format = '%Y-%m-%d %H:%M:%S%z '

But, since globals are mutable, it’s less stable than a class with class method.

In the faux-initialize block, we instantiate the Logger object, set where the output goes, set the log level, and set the datetime format.

if @logger.nil?
  @logger = Logger.new STDOUT
  @logger.level = Logger::DEBUG
  @logger.datetime_format = '%Y-%m-%d %H:%M:%S%z '
end

The log entries are set to go to STDOUT, but you can just as easily direct them into a file with something like:

@logger = Logger.new 'path/to/log/files/log.txt'

The level of the log is a little tricky to understand at first, but it basically controls what information is written to the log. When telling the logger to write, the “level” of the message can be specified. This is useful because you can set the level to Logger::WARN for production, meaning WARN, FATAL, ERROR, and UNKNOWN are written. That way, the debug lines in your code won’t clutter up the production logs. When you’re writing new features or fixing bugs in development, turn the level up to Logger::Debug and all the debug and info logs start showing up too. The available levels are (in “most serious” to “least serious” order):

• UNKNOWN – I can’t even. Always written to log.
• FATAL – Fatal errors and other serious unhappiness.
• ERROR – An error occurred. Someone should fix this.
• WARN – A possible error occurred. Someone maybe should fix this.
• INFO – In case you were wondering…
• DEBUG – The more sophisticated version of puts style debugging.

There is a corresponding method for each of the levels. For example, @logger.fatal("App is dying!!") will write the message at the FATAL level. The Logger class also has query methods for each level (i.e. fatal?), allowing you to ask the @logger if it currently supports that level of logging.

It’ll be up to you to decide what level each log entry should be, but it’s pretty obvious once you start adding logs to your app the difference between a fatal error, general info, and debug data.

The datetime that will be shown in the log is being set to the ISO 8601 standard and I don’t see any reason to do it any other way. These datetimes are universally readable, searchable, and parseable. Change it if you must, but do so with caution and for a good reason.

Go Forth and Log

Since I’ve started playing with the Logger I’ve been using DEBUG and INFO the most.

DEBUG is great for checking the contents of a variable, seeing if a certain method is ever called, watching the progress of a loop, or anything else you want to keep an eye on in your application. Unlike puts style debugging, you can just leave these log calls in place, turn down the level on your logger, and no longer see this data in your logs or in the console. Want to check if an array is the size you expect? Drop in a call to your logger and see this in your log:

D [2014-08-13 15:23:42-0600 #65631]  DEBUG -- : Array length: 42

42 items in my Life, The Universe, and Everything array…that seems right!

INFO is nice for simple transaction logging. Databases usually give you this kind of thing for free, but scripts, command line apps, or web apps with no datastore can benefit from keeping a general audit trail. For example, you might log the completion of a certain task:

I, [2014-08-13 15:25:21-0600 #65632]  INFO -- : David published an article.

Later, if you want to know when David published an article, BAM! it’s in your logs.

MyLog.log.info “Wrapping up”

Do you use the Ruby Logger? Maybe you have a favorite gem to handle all your logging needs? If you’ve been around the logging block a few times, what practices and designs have worked for you? Log your info in the comments!

Frequently Asked Questions (FAQs) about Ruby Logging