I count myself lucky that I can earn a living programming with Ruby and in particular with the Ruby on Rails framework. But every tool, even the best, has a few surprises up its sleeve. Sometimes you get hung up on something quirky, but more often you’re having a problem with a feature—something that’s there by design. This is my story about one such problem I had with a Rails feature, how I diagnosed it, and what it means: metaprogramming is awesome, but it comes at a price, and in imperative languages, the price is side effects.
The Phenomenology of Nonsense
Debugging code is a singular experience. If you’re like me, you have to take a breath and remind yourself that the solution to your problem is going to be logical. Once you find it, it will make sense. It will almost certainly fit into your understanding of the framework, library, or language you’re using. It might expand your understanding a bit, but it won’t be alien. You have to trust that, because when a bug is obscure, and you can’t figure out where to look for it, it’s all to easy to become convinced that someone out there has it in for you. Possibly the computer. All too often the symptoms of the bug and the information you can obtain about it are just nonsense. Something that just can’t be happening is absolutely happening.
Here’s my specific case. I’m programming a web app in which online customers can register credit card information for later use in making purchases. The app’s data store doesn’t keep any sensitive information; instead, it sends it on to a payment gateway that exposes an API for storing and retrieving these credit cards’ information. Our data store just keeps a bare minimum of app-specific information about the cards, e.g. whether the card is the customer’s primary card or not.
Communication with the gateway is implemented in callbacks on the credit card model’s lifecycle. These two methods, save_profile and remove_profile, perform storage and removal operations on the gateway’s APIs:
before_destroy :remove_profile
before_save :save_profile
Great. Except as I tried out actual integration tests, I kept getting the most bizarre errors when deleting a credit card. They were telling me I wasn’t passing enough information to the gateway to save the card information. Save? I was trying to delete! Does Rails fire a before_save callback before a before_destroy callback? Nope. And yet that seemed to be what was happening.
As a way to blow off steam, I fired off a Tweet about my frustrations: why was before_save happening before before_destroy?
Paul’s comment shows the value of a consistent view of the world when debugging. In an imperative programming language, side effects, or changes in the state of data or objects, are lurking behind every line of code. If you remember this, you can tackle a bug by trying to find a side effect that is causing the nonsense. And Paul was 100% right in my case.
I got a handle on what was happening by including this code in my model, inside a rescue clause in the save_profile method I registered as a before_save callback:
rescue Exception => ex
...
logger.error("trace: #{ex.backtrace().join("\n")}")
end
When you insist that you can handle the truth, backtrace shows you every method that your code has passed through. It’s a lot of data to take in, but it’s a good way to find out what’s going on out of your sight. In my case, I found a mention of something called remove_from_list firing just after the code requesting a credit card record be destroyed. remove_from_list is part of the acts_as_list plugin, and it updates a record to set its position attribute to nil.
Remember I mentioned in passing that I was tracking whether a card was primary or not? I was using acts_as_list to do this. The first card in the list was the primary one. And all I had to do to get the ordering was to have this line in my credit card model file:
acts_as_list :scope => :customer
So powerful. In fact, a little too powerful for me, since this one line registers remove_from_list as a before_destroy callback. It does it magically, through meta-programming. That callback assignment doesn’t appear in your code, although you can imagine it “happens” right on the line with the acts_as_list declaration.
So that was my problem. I had code attempting to update the record before it was destroyed, and thus my before_save callbacks were firing.
The solution was twofold. First, I moved the line
before_destroy :remove_profile
above
acts_as_list :scope => :patient
in my code, to make sure remove_profile would be called before remove_from_list. In Ruby, the order of declarations often determines the precedence of similar operations. In Rails, callbacks occur in the order in which they’re registered, which in this case is the order of the lines of code in my model file.
Second, I made a little attribute called mode for my credit card class and had remove_profile set the mode to :destroy. Since remove_profile is the first callback that is called on destroy, the setting of mode happens before any other callbacks fire. Then I added a check in save_profile to just return true if mode were set to :destroy. So when remove_from_list triggers save_profile, save_profile doesn’t try to communicate with the gateway. And that solved the problem.
I wanted to post this for two reasons. First, when I was debugging, I did a bit of googling to see whether anyone had encountered a problem with callbacks happening out of order. I didn’t find anything. So a post with specifics might be useful to someone suffering the same affliction.
Second, I thought this was a great exercise in debugging a Ruby on Rails app. The Exception class’s backtrace method is a great tool, especially when combined with the built-in logger object. Also, I was helped out by keeping a development journal, just a text file that I type and copy interesting things into. When I’m debugging, trying to give shape in words to the problem I’m having often helps me find details and patterns that lead to a solution. I hope my experience might help you out of a similar jam.
Happy debugging.