Tags: Mercurial, hg, Debugging, Testing

So at work we're switching over to Mercurial (hg), and I'm trying out some of the more advanced features. One which I've been looking forward to for a while is 'bisect' (which git and others have also).

The idea is straightforward. I have a unit test that fails. I know that it worked like a month ago or something. Someone committed something between then and now that made it fail. But what was it? Bisect will systematically help find it -- start in the middle, and if it was good there go back half of the remaining time. If bad, go forward. In just a few chops like this it will narrow down to the exact commit that caused an issue.

This works well in Mercurial (and Git) because it is really really fast to revert to a previous version of your code. By far the longest part of the process in the process was executing the unit test itself!

Here are the steps I went through. I'm using Mercurial 4.3, by the way.

bwilcox@wickedwitch:~/dev-rel172$ hg bisect -r

First I "reset" the bisect. That just means, let's begin!

bwilcox@wickedwitch:~/dev-rel172$ hg bisect -b

Now I marked the current revision as "bad", since my test fails.

bwilcox@wickedwitch:~/dev-rel172$ hg bisect -g 51303
Testing changeset 51497:3f631045f30d (196 changesets remaining, ~7 tests)
124 files updated, 0 files merged, 26 files removed, 0 files unresolved

I looked back at history before I started this and decided that this test definitely passed at revision 51303 -- that was just before our last release and all the tests passed. So here I'm saying that I know for sure that it was "good" at revision 51303.

Now comes the fun part.

bwilcox@wickedwitch:~/dev-rel172$ hg bisect -c 'bin/test_suite.pl bin/t/default/pnr_phase1/14-task_acquisition_approval.t | grep PASS'
Changeset 51497:3f631045f30d: bad
Result: PASS
Changeset 51404:8b0f3381e3f5: good
Changeset 51449:f3b668e05928: bad
Changeset 51415:ebc770d284d3: bad
Result: PASS
Changeset 51409:dfd5706dc765: good
Result: PASS
Changeset 51412:e33660e38ea0: good
Result: PASS
Changeset 51413:d1390b75856f: good
Changeset 51414:d39f58b490ab: bad
The first bad revision is:
changeset:   51414:d39f58b490ab
user:        chiggins
date:        Tue May 18 21:34:51 2010 +0000
summary:     RT: https://rt.liquidation.com/Ticket/Display.html?id=733702

In case it isn't clear, the command that I ran is:

hg bisect -c 'bin/test_suite.pl bin/t/default/pnr_phase1/14-task_acquisition_approval.t | grep PASS'

This instructs Mercurial to keep going, and use my test_suite.pl command to decide whether a particular revision is "good" or "bad". The "-c" parameter runs what you give it and looks at the exit status to decide if it is good or bad. It just so happens that the "grep" command returns exit status depending on whether it found something :) . So I'm grepping for the "PASS" that comes at the end of a standard perl test suite to indicate that the current revision is good.

And then off it runs! Test... bad. Test... good. Test... bad. And so on, narrowing it down to the exact revision which was the first to fail the test!

From there I took a look at that revision, and immediately saw what the problem was. Easily fixed, and now my test suite passes with a clean bill of health.

Aw hells yes.