(this is a little gem that I'm resurrecting from a prior blogroll... hence the 2010 dates)
The story so far...
I had been working my way through the excellent text Agile Web Development with Rails (4th edition) by Sam Ruby.
I let myself be led by the nose through a couple of working sessions without running all of the functional tests. Suddenly, there I was on Iteration F4 and my test complained:
$ rake test
.
.
.
Started
.F....................
Finished in 0.538259 seconds.
1) Failure:
test_should_destroy_cart(CartsControllerTest) [test/functional/carts_controller_test.rb:43]:
"Cart.count" didn't change by -1.
<1> expected but was
<2>.
However, this particular test failure wasn't described in the text (oh noes!). I was on my own to troubleshoot the underlying issue. I tried a number of typical first-line troubleshooting techniques: sprinkling a few pretty-prints here and there to get a sense for why the destroy wasn't actually destroying. But to no avail. And since I hadn't run my functional tests in some time, I didn't know when I introduced the defect. :-/
git bisect to the rescue!
Luckily, I had been diligent at least about committing my work to a local git repo. I was committing each "iteration" (unit of work from the text), so I had a reasonably high-fidelity history.
With git bisect, I was able to quickly hunt down the offending commit.
First I went back in time a bunch of commits (about 8 commits back) and ran the rake test. They succeeded! So, at least I know the tests were running back then and branched there as "last_known_good":
(master) $ git branch -f last_known_good 4586dadff6cf838262c48149ca265e5226cb80b1
(master) $ git co last_known_good
(master) $ rake test
Started
...............
Finished in 0.399094 seconds.
15 tests, 24 assertions, 0 failures, 0 errors, 0 skips
I then initialized a bisect session:
(master) $ git bisect start
(master) $ git bisect bad
(master) $ git bisect good last_known_good
Bisecting: 3 revisions left to test after this (roughly 2 steps)
[8aab0db8f45e8a0c2f5ffc10e6f2382d90c249e8] (E1,E2) Added 'quantity' to Line Items
This first step is the halfway point between the "last_known_good" branch and my master branch (hence the name: git is bisecting the history, doing a binary search until the actual last known good commit (or even better, the first known bad commit) is identified.
Now, it's just a matter of running my test and letting bisect know whether they succeeded or not. bisect took care of doing the binary search through the history to find the actual last known good:
jonamac:work ((no branch))$ rake test
Started
......................
Finished in 0.541449 seconds.
22 tests, 34 assertions, 0 failures, 0 errors, 0 skips
that one was good. So, I just tell git bisect that. It then finds the midpoint commit between this commit (about the 4th from the top)
$ git bisect good
Bisecting: 1 revision left to test after this (roughly 1 step)
[a17b740253ceb4e4df5f055808aa638bee269a7f] (F1) Added partials for Line Item and Cart.
git tells me that he's moved to that midpoint. I just run my rake test again and tell git about the results.
$ rake test
Started
.F.E...F.EEEE...EEEE..
Finished in 0.557046 seconds.
1) Failure:
test_should_destroy_cart(CartsControllerTest) [test/functional/carts_controller_test.rb:43]:
"Cart.count" didn't change by -1.
<1> expected but was
<2>.
...
22 tests, 22 assertions, 2 failures, 9 errors, 0 skips
oiy! this one is bad! Again, I just tell git that fact and it continues to hunt down the source...
$ git bisect bad
Bisecting: 0 revisions left to test after this (roughly 0 steps)
[bc5470e9380a80448fd61e780d24fe8e1927dec3] (E3) Improved cart display.
...run my test again...
$ rake test
Started
.F....................
Finished in 0.538259 seconds.
1) Failure:
test_should_destroy_cart(CartsControllerTest) [test/functional/carts_controller_test.rb:43]:
"Cart.count" didn't change by -1.
<1> expected but was
<2>.
22 tests, 33 assertions, 1 failures, 0 errors, 0 skips
and as I tell git about this last one (that I see the failure), it reports that it has found the first bad commit:
$ git bisect bad
bc5470e9380a80448fd61e780d24fe8e1927dec3 is the first bad commit
commit bc5470e9380a80448fd61e780d24fe8e1927dec3
Author: John S. Ryan
Date: Sun Dec 12 18:00:54 2010 -0800
(E3) Improved cart display.
+ Added ability to empty cart.
There we go! Something in this commit is the root cause of my issue. gitk can be helpful to visualize what happened:
 |
| gitk visualization of a bisection; it's a hunt for when a particular condition first occurs. |
It was bisect, not I who applied those tags that start with "bisect/good" and "bisect/bad". This is handy to get a sense for what just happened.
Now I've got my smoking gun.
What's left is to simply check out at the actual last known good and apply the diff from the next commit, one logical chunk at a time. Turns out, the bug was a typo (I wrote "card" instead of "cart").
Post Mortem
There was a deep cause to my problem: I had not run my test suite before I committed (repeatedly) and thus injected a defect that was there for some time. Had I stuck to my guns and continued to run my tests, I would have found this bug much faster.
That said, it's nice to have a safety net. Lucky for me, I was diligent about my use of my DVCS. With git's bisect, I was able to track down the source of the defect pretty quick in a rather reliable process.
No comments:
Post a Comment