I have a confession to make: I really like hospital based tv series: House, ER, Scrubs, Green Wing. It’s all good. Of the lot, House is the one I’ve been watching most recently and in many ways a typical episode is basically a medical murder mystery. Understanding a bug or working out some unexplained behaviour is basically the same thing, it’s just that this time you’re the hardened police officer on the case!

This episode opens up with a strange scene:

1
2
3
4
5
6
7
8
9

>> s = Shift.find :first
=> #<Shift id: 1, start: "2008-04-30 22:19:31", created_at: "2008-04-30 22:19:32", 
updated_at: "2008-04-30 22:19:32">
>> s.start
=> true
>> s.created_at
=> Wed Apr 30 22:19:32 BST 2008
>> s.start
=> Wed Apr 30 22:19:31 BST 2008

Something is clearly wrong, and as the title sequence starts up the viewer knows there’s funny business afoot. In the grand tradition of TV series the next scene doesn’t seem hugely related.

You can’t be serious

A controller with a ‘start’ action was claiming that there was no such action, systematically. This controller had always had such an action and had not been changed in months, I was merely passing it while working on another issue. It was getting late so I called it a day. The next morning, with no code changes, it was fine so I moved on to other things, pushing that niggling feeling you get when you don’t understand a bug to the back of my mind. Then at lunch it stopped working, again without apparent reason.

Time to tackle the problem head on. I fired up my trusty debugger and went stepping through ActionController. When a request comes in and the controller and action have been identified, ActionController (broadly speaking) will try to find a method of that name, a template of the same name or hit method missing. Now there’s a bunch of methods that shouldn’t be exposed as actions so what AC does is subtract from your controller’s public methods all those public methods defined in ActionController::Base (which by definition pretty much can’t be actions). For some reason ActionController::Base seemed to have a method called start and so ‘start’ was on the list of method names that could not be actions. Searching through the source revealed no definition of a start method, but interrogation of Kernel reveals that it defined a start method. I fired up script/console to do some more poking, and interestingly enough, no start method in Kernel. It should be running the same code as the app on the same machine, same everything and yet there’s a difference.

There’s definitely some methodicalness to tracking down a problem. At some point though you’ve go to switch off the guidance computer and just use the Force. If you’re short on Jedi powers (as I am) then you’ve got to settle for second best which is to have an idea. It suddenly occurred to me that the difference was the debugger. When I’d been stepping through the ActionController code it was obviously on but when I’d been pissing about in script/console it hadn’t. So I had a look at the source for ruby debug and sure enough it defines Kernel#start. So the seemingly random factor that was causing the action to fade in and out of existance was whether or not I was debugging something else!

Dénoument

At this point the problem I started with is sort of solved, a quick experiment shows that under the debugger it exhibits the anomalous behaviour and without the debugger it’s fine. But why does the second call to start work?

When you get an ActiveRecord class it doesn’t have your attribute accessors defined. They come into existance the first time you try and use them (via method_missing). So the first time we call start, we’re calling the start method from Kernel.start that ruby-debug created. When we call created_at, method_missing gets hit which goes and generates all the accessors, overwriting the start method from Kernel.start with one that reads the start attribute. Then we call start again and this time we get the freshly generated one method

So there, mystery solved. The credits start rolling. I think this was a pretty good episode, who would have thought it was your trusted lieutenant who’d been stirring up trouble all along!

Epilogue: I now stick

1

Kernel.send :undef_method, :start if Kernel.respond_to? :start

In a file in config/initializers and order is restored to the galaxy.

Post-Epilogue: ruby-debug has since been updated to not define a start method. Still an interesting story if you ask me!