August 31, 2011

Posted by John

Tagged gems and logging

Older: Counters Everywhere, Part 2

Newer: Creating an API

Stupid Simple Debugging

There are all kinds of fancy debugging tools out there, but personally, I get the most mileage out of good old puts statements.

When I started with Ruby, several years ago, I used puts like this to debug:

puts account.inspect

The problem with this is two fold. First, if you have a few puts statements, you don’t know which one is actually which object. This always led me to doing something like this:

puts "account: #{account.inspect}"

Second, depending on whether you are just in Ruby or running an app through a web server, puts is sometimes swallowed. This led me to often times do something like this when using Rails:

Rails.logger.debug "account: #{account.inspect}"

Now, not only do I have to think about which method to use to debug something, I also have to think about where the output will be sent so I can watch for it.

Enter Log Buddy

Then, one fateful afternoon, I stumbled across log buddy (gem install log_buddy). In every project, whether it be a library, Rails app, or Sinatra app, one of the first gems I throw in my Gemfile is log_buddy.

Once you have the gem installed, you can tell log buddy where your log file is and whether or not to actually log like so:

LogBuddy.init({
  :logger   => Gauges.logger,
  :disabled => Gauges.production?,
})

Simply provide log buddy with a logger and tell it if you want it to be silenced in a given situation or environment and you get some nice bang for your buck.

One Method, One Character

First, log buddy adds a nice and short method named d. d is 4X shorter than puts, so right off the bat you get some productivity gains. The d method takes any argument and calls inspect on it. Short and sweet.

d account # will puts account.inspect
d 'Some message' # will puts "Some message"

The cool part is that on top of printing the inspected object to stdout, it also logs it to the logger provided in in LogBuddy.init. No more thinking about which method to use or where output will be. One method, output is sent to multiple places.

This is nice, but it won’t win you any new friends. Where log buddy gets really cool, is when you pass it a block.

d { account } # puts and logs account = <Account ...>

Again, one method, output to stdout and your log file, but when you use a block, it does magic to print out the variable name and that inspected value. You can also pass in several objects, separating them with semi-colons.

d { account; account.creator; current_user }

This gives you each variable on its own line with the name and inspected value. Nothing fancy, but log buddy has saved me a lot of time over the past year. I figured it was time I send it some love.

13 Comments

  1. Log_buddy automagically getting its own line with the name and inspected value is going to be a huge time saver. Beautiful. Thank you John!

  2. No link to the code on github ?!? That’s the most important part!

  3. LogBuddy is great. It does have limitations, though. If memory serves, it finds the name of what it’s displaying by opening the source file and parsing its own call. Pretty cool. However, that means you can’t put two calls on one line, or one call on multiple lines. Not a big deal, I imagine.

    d is not a good method name – just try grepping for it. My own tool started off as l, then became ll, then (when Rails started using that), lll. And that’s where it stands today (gem install lll).

    lll doesn’t require any initialization. It just automatically logs to the Rails log (if there is one), it does its puts’ing in reverse video, and has a couple of other small benefits. You call it with lll {’account’} (which is a good candidate for an editor macro).

  4. what about `p account` ?

  5. James sadler James sadler

    Sep 02, 2011

    You should be able to avoid the source file parsing by looking at the bindings of the current scope (Kernel#binding).

  6. Is it possible to make log_buddy use awesome_print style output? #inspect is grim once you get used to awesome_print and its indentation and unravelling of complex data structures :-)

  7. @Peter – I’m sure it is. Probably would just need to add an option for what method to be called instead of doing inspect. Please do investigate… :D

  8. @mark:

    Please use grep properly: grep -nr ‘\bd\b’ lib

  9. @ryan: I think it’s easier to grep for a unique term. I also label lll’s output with ‘lll’ so it’s easy to find in log files or in the terminal window. But point taken.

  10. @james: I don’t see how Kernel.binding would help you determine the text of the expression.

    @john, @peter: Another alternative is to use pretty_inspect instead of inspect. pretty_inspect is in the standard library.

  11. Awesome John, had been thinking about building this exact functionality today. Thanks for saving the time.

  12. Thanks for the writeup, John. Although LogBuddy hasn’t been touched in quite awhile, we still use it in all our recent Rails / Ruby apps at Relevance. Patches and pull requests are welcome…

  13. Thanks for sharing this.
    @john: please tell us which one do you prefer log_buddy or awesome_print?..your suggestion would be helpful.

Sorry, comments are closed for this article to ease the burden of pruning spam.

About

Authored by John Nunemaker (Noo-neh-maker), a programmer who has fallen deeply in love with Ruby. Learn More.

Projects

Flipper
Release your software more often with fewer problems.
Flip your features.