When Inheritance Doesn't Pay - Problems Testing Rails

The smallest things have the capacity to cause the most pain. Today's pain is caused by 5 characters, or to be more acurate, the absence of 5 characters.

super

Say it with me, super. Yep, super. Guess what Rails doesn't include in the setup of functional tests by default. You betcha, super. And the funny thing is, most of the time, it really doesn't matter. But sometimes, oh boy, yeah, sometimes it makes all the difference.

Given two test classes:

a_test.rb
require File.dirname(__FILE__) + '/../test_helper'

class ATest < Test::Unit::TestCase
fixtures :empties

def setup
end

def test_fixture
empties(:first)
end
end

b_test.rb
require File.dirname(__FILE__) + '/a_test'
class BTest < ATest; end

Would it surprise you that run seperately, both of these pass with flying colors, but run together, they result in abominable crashes? It sure surprised me.

[~/projects/test]$ /usr/bin/ruby -Ilib:test "/usr/lib/ruby/gems/1.8/gems/rake-0.7.1/lib/rake/rake_test_loader.rb" "test/unit/a_test.rb" Loaded suite /usr/lib/ruby/gems/1.8/gems/rake-0.7.1/lib/rake/rake_test_loader
Started
.
Finished in 0.115591 seconds.

1 tests, 0 assertions, 0 failures, 0 errors
[~/projects/test]$ /usr/bin/ruby -Ilib:test "/usr/lib/ruby/gems/1.8/gems/rake-0.7.1/lib/rake/rake_test_loader.rb" "test/unit/b_test.rb" Loaded suite /usr/lib/ruby/gems/1.8/gems/rake-0.7.1/lib/rake/rake_test_loader
Started
..
Finished in 0.157902 seconds.

2 tests, 0 assertions, 0 failures, 0 errors
[~/projects/test]$ /usr/bin/ruby -Ilib:test "/usr/lib/ruby/gems/1.8/gems/rake-0.7.1/lib/rake/rake_test_loader.rb" "test/unit/a_test.rb" "test/unit/b_test.rb"
Loaded suite /usr/lib/ruby/gems/1.8/gems/rake-0.7.1/lib/rake/rake_test_loader
Started
EEEE
Finished in 0.088633 seconds.

1) Error:
test_fixture(ATest):
NoMethodError: You have a nil object when you didn't expect it!
You might have expected an instance of Array.
The error occured while evaluating nil.[]
/usr/lib/ruby/gems/1.8/gems/activerecord-1.14.2/lib/active_record/fixtures.rb:475:in `empties'
./test/unit/a_test.rb:10:in `test_fixture'

2) Error:
test_fixture(ATest):
NoMethodError: You have a nil object when you didn't expect it!
You might have expected an instance of Array.
The error occured while evaluating nil.-
/usr/lib/ruby/gems/1.8/gems/activerecord-1.14.2/lib/active_record/transactions.rb:112:in `unlock_mutex'
/usr/lib/ruby/gems/1.8/gems/activerecord-1.14.2/lib/active_record/fixtures.rb:534:in `teardown'

3) Error:
test_fixture(BTest):
NoMethodError: You have a nil object when you didn't expect it!
You might have expected an instance of Array.
The error occured while evaluating nil.[]
/usr/lib/ruby/gems/1.8/gems/activerecord-1.14.2/lib/active_record/fixtures.rb:475:in `empties'
./test/unit/a_test.rb:10:in `test_fixture'

4) Error:
test_fixture(BTest):
NoMethodError: You have a nil object when you didn't expect it!
You might have expected an instance of Array.
The error occured while evaluating nil.-
/usr/lib/ruby/gems/1.8/gems/activerecord-1.14.2/lib/active_record/transactions.rb:112:in `unlock_mutex'
/usr/lib/ruby/gems/1.8/gems/activerecord-1.14.2/lib/active_record/fixtures.rb:534:in `teardown'

2 tests, 0 assertions, 0 failures, 4 errors
[~/projects/test]$

The key to this dilemma should be pretty easy to find now that I have bloodied myself on the problem for you. Exactly, super. Add super to the setup and all our woes are cured. I haven't got the slightest idea what magic TestCase.setup is doing but without it, we bomb every time. Actually, I suspect inheritance isn't even the culprit here. Running a with itself twice exhibits the same behavior, with the same solution.

I suspect the error condition is related to the edge case of a test class completing then being loaded again but I'm not sure how to prove it. I'm guessing the 2nd time through, an action isn't take because Rails is convinced it already happened. But the moral is clear, super is your friend.

Compounding Errors - Another Rails Testing Adventure

The Moral:
Always include test_helper in Rails tests.
Be specific when handling exceptions.
Use diff. Trust diff.
Pair often. Pair always.

The Story:
Every test class generated by Rails includes require File.dirname(__FILE__) + '/../test_helper'. If you remove it, or you write your own test and forget it, bad things can happen, things like this....

First things first, how are the tests? rake test_functional. Failure. Hmm. I expected that. This project was written before we fully committed to test first. It shouldn't be too hard to get the existing tests to run. Let's see what we need.

The failure is in the functional tests. A require is failing and I don't know why. I wonder where that file is supposed to come from? Maybe it is really missing. There is something similar in another one of our projects. For now, I will just include the mock we used to make that test pass. (Copy the test/mock directory from one rails app to the other.)

That should fix it. rake test_functional. Blamo. Still failing. Hmm. Naming problems? File names seem to match. Hack. Hack. Hack. This sucks, I've burned an afternoon and there's nothing to show for it.

Interlude. A night of little sleep and a nagging weight on my mind. Not fun. The tension wakes me up at 3:00 AM and I start hacking from home. It isn't like I was getting any useful rest anyway.

So, the test isn't finding my mock either. I don't get it. Well, I guess I can check my load path before the require.

puts $:.inspect
 ["lib", "test", "/usr/lib/site_ruby/1.8", "/usr/lib/site_ruby/1.8/i386-linux",
 "/usr/lib/site_ruby", "/usr/lib/ruby/1.8", "/usr/lib/ruby/1.8/i386-linux",
 "."]

That doesn't look right. None of my rails includes are there. Hack. Hack. Hack.
Burned several morning hours and I still have to face Steve and tell him I have nothing to show for it. Having that hanging over my head sure does make for a long morning commute.

OK. Before I talk to Steve about this, lets at least check his machine. rake test_functional Passed. Everything passed. Wait. WTF do you mean everything passed?! OK. Maybe I'm just an idiot (I mean past experience suggest this must frequently be the case.) so lets make sure I have the current code. svn status. Nothing modified. svn udpate. Nothing missing. Well, maybe Steve made changes on his machine. svn status. Nothing modified. svn udpate. Nothing missing.

I've been here before. Code works on one machine but not on the other. The problem is, this time, it is well tested code and I can't find anything that is different. Discussing it with Steve didn't help either. He spent a chunk of time getting all these tests to pass just recently so they should still work.

Well, my machine is different. We are planning a system upgrade and I'm the guinea pig. But most of our software is the same. Sure, the OS is different right now but.... Well, I can at least standardize my software install. I'll just get our environment setup script to work.

Great. That script blows up on my machine too. It can't get the file from subversion. Well, of course it can't. That doesn't look like the repository location to me. Hack, hack. Oh. Idiot. That was right. The subversion repository is being served up by http and I was looking for the svn+ssh location.

Well, it still blows up. Compare the file path. Still missing. Load the directory in a browser. There the file is. But, umm, well. OK. Maybe it is something in the version. That looks different in the script. Nope. That looks right.

Eventually, I notice the file name the script is looking for is .tar.bz2 but the file name in the directory is .tar.gz. Don't ask how long it took. Too long.

It's looking for the wrong file name. Why. Where does that come from. There it is. But, wait, it should be looking for the name that is there first. If it doesn't find that then it catches the exception and tries the other name.

The light bulb finally goes on.

Ah. I'm getting an exception other than the expected exception and that is incorrectly being understood as a missing file. And hey, while I'm at it, guess what, I should be running this as root and I'm not. The real error is a permissions error but I can't see that because we handled every exception instead of just the missing file exception we expected. And surprise, surprise, everything works great when I run it as root. I leave the script to run over night since it is taking too long.

Interlude. Another bad night. Another early morning. This time I was so burned out that instead of going to hacking night, I crashed for 3 hours when I got home. Of course that meant I couldn't get back to sleep until the wee hours. And of course that didn't stop me from waking up way too early.

Back at the office again. Everything is good on Steve's machine, and not good on my machine. Well, lets diff the output. I should have done this days ago but hindsight is 20/20 and foresight is blind as a bat. Well, the commands for the tests aren't in the same order but I don't really see anything else. Lets follow the rake trace.

The trace is different but I don't really understand why. Hack. Hack. Oh, by the way, things work in autotest but not rake. Now that is just creepy.

Finally, I corner Steve to help me out. I'm not solving this alone, so lets try some of that pairing juju.

Hack here. Hack there. Trace this. Trace that. Eventually Steve notices what I already knew but this time, Steve gets it when I just blanked. It is order dependent. The tests are being run in a different order. Hack, hack. Well, we can't really control the order, it seems to be an artifact of the different OS. Still, we should be able to figure out what causes the order dependency. Hack. Hack.

Bingo, there it is. This test (which was copied from another, non-rails project) doesn't include test_helper. And guess what. test_helper is where environment.rb is loaded. And environment.rb is where the additional include paths are added, not to mention that test_helper is where the mock paths are added. No wonder it couldn't find those mocks that I added.

Finally, we get to here and now. Two and a half days of developer time wasted over several small errors, compounded together. Cory Foy recently wrote "And that's the trick with being Agile. If you slip, even for a second, it *will* bite you. You have to stay on guard constantly". This is true of Agile but really, it is true of all development. How many times have you been bitten by small problems that take days to figure out and would have been avoided with just that little bit more effort?

Of course, the mark of a great developer isn't the lack of mistakes. The mark of a great developer is learning from mistakes and preventing them in the future. Soon, we will either have something that tests to make sure our tests include test_helper, or even better a way to avoid that step in every single bloody test file. We will also be more careful to trap only what we expect and leave the unexpected unhandled or at least properly handled. And I will definitely learn to trust my diffs earlier.

Don't make my mistakes, but more importantly, don't make your mistakes twice.