Sunday, June 12, 2011

Metaprogramming Danger Box

In my last post, I showed how one can use the "execute around" pattern in Ruby to log any calls to a method, without cluttering the methods themselves with logging calls.

That gave us code like this:

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

Our with_log method took care of printing out some logging info before and after executing the block given to it.

But as Adam pointed out in the comments, this is still kind of ugly. We don't have all the actual logging code inside of the "defuse_bomb" method, but have had to modify it to use with_log. What if we could add logging more transparently?

We can! With some metaprogramming magic added to the Logging module, here's the way the DangerBox class looks now:

class DangerBox
    extend Logging

    add_logging_to(:defuse_bomb, :throw_error)

    def defuse_bomb
      puts "Snip the red wire..."
    end

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

    # This method's output won't be logged
    def eat_poison
      puts "Mmmmm, poison!! Nom Nom Nom Nom!!!!"
    end

  end

It still works the same way as it did before:

d = DangerBox.new
  d.defuse_bomb
  # ==== Sun Jun 12 16:55:49 -0400 2011 ====
  # About to execute 'defuse_bomb'...
  # Snip the red wire...
  # Executed 'defuse_bomb' successfully.

  d.throw_error
  # ==== Sun Jun 12 16:55:49 -0400 2011 ====
  # About to execute 'throw_error'...
  # I feel an error coming on...
  # Error while executing 'throw_error': 'Success: an error!'!

  d.eat_poison
  # Mmmmm, poison!! Nom Nom Nom Nom!!!!

Adam, I see your "hmmmm" and raise you a "BOOYAH!" (Although I didn't write tests for my version of this, so you still win on that front.)

But how the heck did we get all this logging output? Obviously, it's something to do with the line that says:

add_logging_to(:defuse_bomb, :throw_error)

Well, yes: that and a spiffy new Logging module that redefines our methods on the fly to use logging. Here's the code:

module Logging
    # Keeps track of the methods we want to log
    def add_logging_to(*args)
      @logged_methods ||= []
      @logged_methods.concat(args)
    end

    # Anytime a method gets added to our class (like with "def"),
    # this will execute
    def method_added(method_name)
      if @logged_methods.include?(method_name)
        # A lock to prevent infinite recursion; since we're
        # going to add a method below, we don't want that
        # to make method_added fire again, which would
        # make it fire again, etc...
        unless @adding_with_metaprogramming
          @adding_with_metaprogramming = true
          stashed_method = "stashed_#{method_name}".to_sym
          # Creates a new method named, for example,
          # "stashed_defuse_bomb", which does the same
          # thing as "defuse_bomb"
          alias_method stashed_method, method_name
          # Now we redefine "defuse_bomb" to do this:
          define_method method_name do
            begin
              puts "==== #{Time.now} ===="
              puts "About to execute '#{method_name}'..."
              # Calls "stashed_defuse_bomb" to get the original version
              send(stashed_method)
              puts "Executed '#{method_name}' successfully."
            rescue Exception => e
              puts "Error while executing '#{method_name}': '#{e.message}'!"
            ensure
              puts "\n\n"
            end
          end
        end
        # Remove the lock
        @adding_with_metaprogramming = false
      end
    end
  end

Metaprogramming! It sounds terrifying, doesn't it? Like, if programs can write programs, next thing you know, the Terminator is going to be ripping through your door! But it's actually slightly less terrifying than that.

Anyway, I got the idea for the last post from reading one chapter in "Eloquent Ruby," and I got the idea for this post while lying in bed after reading another chapter. So: thumbs up, Eloquent Ruby! I hereby recommend you.

Friday, June 10, 2011

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.

Thursday, June 9, 2011

Understanding Rack applications

I'm starting to understand Ruby's Rack application architecture, and it's really cool. It's a simple concept, but very powerful, because of the ways it lets you stack up different components with different responsibilities.

First, the basics. According to the spec:

A Rack application is an Ruby object (not a class) that responds to call. It
takes exactly one argument, the environment and returns an Array of exactly
three values: the status, the headers, and the body.

So each component in a rack stack is like a rung in a ladder. An incoming request is stashed inside a hash called the environment, which includes info about the request itself and othert things (see the spec). That environment is passed down the ladder from one component to the next until it gets to the app at the end. The app receives the environment, generates a response, and returns it. Since the app was called by the final rack component, it hands it response back to that component. That component then returns the response to the component which called it, etc, effectively passing it back up the ladder, until it's returned to the user.

Got that? Requests go down the ladder, responses come back up.

Of course, in that description, each component is just passing the environment down and then passing the response back up. If that's all a component did, it would be useless. To be useful, it will have to actually something. Specifically, a given component will do (at least) one of three things:

  1. Screen the requests. For example, if the component is for authorization, it verifies that the user has entered a valid login. If it's an invalid login, it will return a "failed login" response and never call the next component. If it's a valid login, it will pass the request to the next component - maybe a Rails app.
  2. Modify the environment before passing it on to the next component. Our authorization component might do this in addition to screening: if there's a valid login, it might set a user object in the environment before passing that to the next component. With this setup, the next component can assume that the user object will always be set whenever it gets a request.
  3. Modify the response after getting it back from the next component. A silly example would be to translate the response into Japanese.

Notice that each component needs to know what the next component in the chain is, so that it knows who to call. That's why whatever you give to Rack::Builder#use needs to have an initialize method that accepts the next component, in addition to a call method that accepts the env.

The application at the end, however, doesn't need to call anybody else; it just needs to take the env as it then stands and generate a response. So whatever you pass to Rack::Builder::run doesn't need an initialize method; it just needs to respond to call(env). Even a lambda can do that.

Some pseudocode examples of call methods:

# A component with this call method would be useless.
# Still, it's worth remembering that this:
def call(env)
  @next_component.call(env)
end

# ... is Ruby shorthand for this:
def call(env)
  result = @next_component.call(env)
  return result
end

# Instead, we can do something useful on the way in:
def call(env)
  valid_user = contains_valid_login?(env)

  if valid_user
    add_current_user_object_to(env)
    # Next component can rely on having a current_user object
    @next_component.call(env)

  else
    redirect_to_login_page_with_error
  end
end

# Or we can do something useful on the way out:
def call(env)
  result = @next_component.call(env)
  result.translate_to_russian!
end

Friday, June 3, 2011

Ruby's Set class

Yesterday at work, we ran into an interesting problem. We're creating the new version of an application and discarding the old, ugly code. But we need to migrate some data: the old system has (let's say) widgets, and the new system has widgets, too. The old system uses 5 different databases (see how ugly?) with weird row schemas, but it does reliably have widget color, size, and shapes. The new system uses one database and has a nice row schema, but it also has widget color, size, and shapes.

We need to know: which widgets are only in the old system? Which widgets are only in the new? Which are in both?

Enter Sets


Asking these questions tripped a switch in my mind. "I know about this!", I thought. "This is a job for sets! And Ruby has a Set class."

I'd never used them yet, but sets are made for this kind of thing. Sets are often illustrated with Venn diagrams: overlapping circles, where you ask "which things are only in the left circle? What's in the overlap?", etc.

For instance:



A set is a list of items where no item is repeated. If you have more than one set, you can compare them and answer the kinds of questions we've been asking. Here's a demo I just threw together:

require 'set'

  def sets_demo

    # Sets ignore duplicate values
    game_words = Set.new(['duck','duck','duck','goose'])
    puts "Unique game words                 : #{game_words}\n\n"
    #=>   Unique game words                 : goose, duck
     

    # Here are two sets with one thing in common
    fast  = Set.new(['bullet', 'cheetah'])
    round = Set.new(['bullet', 'beach ball'])

    # All the ways we can compare them
    puts "Round                             : #{round}"
    #=>   Round                             : bullet, beach ball
    
    puts "Fast                              : #{fast}"
    #=>   Fast                              : cheetah, bullet
    puts ''


    puts "Round and Fast (&)                : #{(fast & round)}"
    #=>   Round and Fast (&)                : bullet
    #
    puts "Round but not Fast (-)            : #{(round - fast)}"
    #=>   Round but not Fast (-)            : beach ball
    
    puts "Fast but not Round (-)            : #{(fast - round)}"
    #=>   Fast but not Round (-)            : cheetah

    puts "Round OR Fast (|)                 : #{(round | fast)}"
    #=>   Round OR Fast (|)                 : cheetah, bullet, beach ball

    puts "Round OR Fast, but NOT both (XOR) : #{((round | fast) - (fast & round))}"
    #=>   Round OR Fast, but NOT both (XOR) : cheetah, beach ball

  end

  # Formatting the way the sets print
  class Set
    def to_s
      to_a.join(', ')
    end
  end

  sets_demo
  

Got it?

In my examples, the items in the sets were strings, but they could be anything. In our case at work, we used hashes: a widget was represented by a hash containing its color, shape and size. So, we just had to:

  1. Connect to each of the databases in the old system, getting all the widgets, creating a hash for each one, and dropping each into an old_system_widgets set (which automatically ignores duplicates)
  2. Connect to the new system's database and make a similar set of its widgets
  3. Do the kinds of set operations illustrated above

Voila! Now we knew which widgets were new and which ones still needed to be migrated to the new system.

In conclusion: sets are swell!

Hmmm. That's a pretty weak ending.