Using the Execute Around pattern in Ruby

At my last job, I wrote a script that was run by a cron job overnight. The script was supposed to go through a MySQL table of scheduled database queries and, if they met some sanity checks, run them. This was so we could run slow queries like ALTER TABLE during the wee hours of the morning, when customers weren't hitting our database. It may sound odd to execute MySQL queries that had been stored in MySQL, but it worked. (Just don't drop the stored queries table!)

The first time my script ran, it failed, and I didn't know why. My boss wisely suggested that I add some logging: print messages to standard output. We were a PHP shop, so that meant echo statements; all this output was captured in a log file by the cron job, which ran my script like this:

query_runner.php > some_log_file.txt

I went crazy with the logging, announcing up front how many queries I had to run, my progress ("Running query 4 of 7..."), how long each query took, whether it had errors, etc. At the end I printed a nice summary.

All this made the log files very useful when something went wrong: I could tell which queries had and hadn't run, and generally why. I learned the value of logging, and that day, I became a man.

No wait, I'm confusing my stories. I just learned the value of logging, that's all.

Execute Around

Anywho, these days I'm coding Ruby, and I'm currently reading "Eloquent Ruby" by Russ Olsen. In one section, he shows a nice way of adding logging to any method you like, without cluttering up the internals of the method itself.

The secret is the "execute around" pattern: you pass your method, as a block, to another method, which can do things before and after executing it. In this case, the logging method will log a message, execute the block, log another message, and even catch and log any exceptions.

Here's an example:

module Logging
    def with_log(description, &block)
      begin
        puts "==== #{Time.now} ===="
        puts "About to execute '#{description}'..."
        block.call
        puts "Executed '#{description}' successfully."
      rescue Exception => e
        puts "Error while executing '#{description}': '#{e.message}'!"
      ensure
        puts "\n\n"
      end
    end
  end

  class DangerBox
    include Logging

    def defuse_bomb
      with_log('defuse_bomb') {puts "Snip the red wire..."}
    end

    def throw_error
      with_log('throw_error') do 
        puts 'I feel an error coming on...'
        raise 'Success: an error!'
      end
    end

  end

Here's what it looks like in action:

d = DangerBox.new
  d.defuse_bomb
  # ==== Fri Jun 10 16:41:54 -0400 2011 ====
  # About to execute 'defuse_bomb'...
  # Snip the red wire...
  # Executed 'defuse_bomb' successfully.

  d.throw_error
  # ==== Fri Jun 10 16:41:54 -0400 2011 ====
  # About to execute 'throw_error'...
  # I feel an error coming on...
  # Error while executing 'throw_error': 'Success: an error!'!

Lovely! All the logging and error handling is done in one place, and the methods that use it can be much cleaner.