Negative Test Suite Runtimes, or Don't Forget to Call Timecop.return

tl;dr When using Timecop,
always remember to turn it off at the end of the test.

I post this in the hopes that I’m not the only one to make this mistake
and someone else might actually benefit from my stupidity.

It’s a sad truth, but in my experience, when googling, googling again
and googling some more for a solution to a problem turns up nary a post
from someone having the same problem, it’s usually because
PEBKAC (I’m an
idiot). For several days I’ve been noticing in frustration that the
RSpec suite on one of my applications was periodically reporting
negative runtimes, e.g.,

Finished in -537150.87202 seconds
329 examples, 0 failures

This consistently happened when running the entire test suite, but
seemed sporadic when running a subset of the test suite. Adding to my
confusion, at just about the same time that this problem appeared I had
upgraded to RSpec 2.8 which fixed an
issue that popped up
when using Spork. I grudgingly
pushed the matter to the back of my mind since, with the test suite
running sufficiently fast, there were higher priority tasks. But today I
found myself specfically wanting to benchmark the test suite, and these
negative runtimes just wouldn’t do. So I poked around deeper.

I generated a fresh Rails application using the same
template I’d used to
generate the offending application. Running the new application’s nigh
empty test suite reported accurate (positive) runtimes, so I started
looking for additions/modifications made to
spec/spec_helper.rb to see where things diverged. Nothing
seemed significant. I then checked Gemfile to see what gems
had been added to the offending application.
Timecop! Of course, if something
was going to interfere with runtime calculations, freezing Time would
probably do it. I grepped for Timecop in my spec files and found it in
use in only one, but damningly, it was mentioned only once. I was
calling Timecop.freeze from a before block,
but I was not restoring Time by calling Timecop.return from
a corresponding after block.

face.send(:palm)

I added the missing after block. Runtime reports were
accurate once again. Unicorns! Rainbows! Chocolate milk!

As an aside, if you use RSpec and
Spork, and had found yourself adding
the following to your spec_helper.rb: