Quick and Easy Logging with LogBuddy

Good logging is crucial for effective problem diagnosis in production. Plus, easy logging remains a terrific debugging technique during development. As helpful as "real debuggers" are, sometimes a debugging log statement is exactly what you need to find a problem quickly.

LogBuddy is a little gem that makes good logging easier. It helps even in Rails, which already has good logging support, and it's a bigger help when building gems and standalone Ruby apps, where you have to start from scratch with logging.

What does LogBuddy do for you that Rails doesn't already? There are numerous small features, but here are the big ones:

It ensures that logger is available everywhere, not just in classes that extend parts of the framework.
It makes it extremely easy to add informative debugging messages with annotated output and full exception info.

Installing and Adding LogBuddy to Your Project

To install the latest release of LogBuddy, just install the gem:

$ gem install relevance-log_buddy --source http://gems.github.com/

Then add a require 'log_buddy' statement to your app. If it's a Rails app, it's best to add this to environment.rb:

  config.gem 'relevance-log_buddy',
             :source => "http://gems.github.com/", 
             :lib => "log_buddy"

Finally, initialize LogBuddy. In Rails apps, we usually put this in config/initializers/logging.rb:

  LogBuddy.init

(You can pass some options to LogBuddy.init; we'll get back to that in a bit.)

LogBuddy creates and initializes a logger for the app to use. In Rails apps, it simply uses RAILS_DEFAULT_LOGGER unless you tell it differently.

Using LogBuddy

LogBuddy mixes a couple of methods into every object in the system: logger and d. Here's how they work.

The logger method is no surprise at all. It simply returns the Logger instance, and you can log by calling debug, info, warn, error, or log methods on it. LogBuddy's logger doesn't usually do anything special; the benefit is that, since it's mixed into Object, it's available everywhere, automatically. (In a typical Rails app, there are numerous contexts where logger doesn't work, and you have to explicitly use RAILS_DEFAULT_LOGGER.)

My personal favorite LogBuddy feature is the d method. Like logger, it's available everywhere. But the d method is designed just for debugging messages. You can call it with an explicit string, or with some object you want to see the value of:

  d "FINISHED PARSING"
  d some_exception
  d result

Strings are logged the same way logger.debug would do it. Exceptions are logged with all of the information you might want: the message, exception class name, and backtrace. Finally, if you pass any other object, d calls that object's inspect method and logs the resulting string.

Where d really shines is when you want to log several values at once, with annotations to distinguish them. Just pass a single-line block to d, like this:

  d { first; current; last}

That produces these three log lines:

  first = "foo"
  current = "bar"
  last = "baz"

The values you log can be any Ruby expression:

  d { 3; name; @model; RAILS_ENV; options[:limit] }

and you'll get just what you want out of that:

  3 = "3"
  name = "primary"
  @model = #<Contact id: 14, name: "Joe">
  RAILS_ENV = "development"
  options[:limit] = 5

There are some restrictions if you use this feature. The entire call to d must fit on one line, and you must use the curly-brace style of block, rather than the do/end style. Finally, if you want to log multiple values, separate them with semicolons, not commas.

(You may be wondering how LogBuddy accomplishes that trick. The answer is left as an exercise for the reader … especially since there are some hints in the restrictions just mentioned. Of course, you can always read the source.)

LogBuddy Initialization Options

The LogBuddy.init method takes an options hash. Here are the permissible options:

:logger – you can supply a logger instance for LogBuddy to use. If you don't supply one, LogBuddy uses RAILS_DEFAULT_LOGGER if it's defined; otherwise, it creates a new logger that writes to standard output.
:log_to_stdout – by default, messages from the d method are logged (using logger.debug) and also written to standard output. Set this option to false to only use the logger.
:disabled – set this option to true to turn off the output from the d method. It's common to set it this way:
LogBuddy.init :disabled => Rails.env.production?
:log_gems – if you set this option to true, LogBuddy watches gem activation and logs information about each gem. This can be useful for tracking down gem activation errors

Try It Out!

LogBuddy is really easy to set up, and then it's there when you need it most: when you're focused on a problem and just need to get the details quickly. Please try it and let us know what you think!