The test passed with the bug in place

0.9.2 fixes an old annoyance. Once the tool has finished crawling your site, it still has to check the status of the links leaving it, and that runs at the speed of the slowest server belonging to someone else, with a single request in flight per foreign host, out of courtesy. During that wait, the progress line said something like this:

5,865 crawled · 1,204 queued · 65 URL/s · 2,834 findings

Twelve hundred queued URLs that were not yours: they were probes to other people’s sites, added into the same counter with no label. And since nothing of your own site was left to crawl, the number stopped moving for minutes. A live process, idle CPU, and not a word about what it was waiting for. Anyone would kill it, and killing it at the wrong moment is how you lose the SQLite write-ahead log flush.

Probes now travel in their own counter, and the line says so:

5,865 crawled · checking external links · 1,204 left · 2,834 findings

While the site is still being crawled, probes stay as a note at the margin. The fix is small and so is the version, 0.9.2: not one piece of crawl data changes, and no rule behaves differently.

Two things came out of writing it anyway.

The counter that would have got stuck

Splitting the two figures means knowing how many in-flight requests are probes, and the pool does not know that: both kinds live in it together. It is tracked by hand, adding one when a probe is dispatched and subtracting one when its answer comes back.

I put the decrement where it looked natural, in the arm that handles a probe’s answer. Rereading it, I saw there are two arms that handle it: the general one, and an earlier one for the case where the name resolved to an address the perimeter refuses. That second case also consumes an in-flight probe, and with the decrement only in the first, the counter would have stayed high forever as soon as a link to a refused address turned up. The bar would have said “3 probes left” until the end of the crawl.

The fix is to move it before the arms, where it holds for all of them. No test found this; rereading what I had just written, asking “is there another path this goes through?”, did.

The test that protected nothing

Here is the part actually worth the post. I wrote a test for the progress emitter: hand it some numbers, check that the snapshot it produces carries the site queue on one side and the probes on the other. Green first time.

This project has a house rule: a test you have not watched fail protects nothing. So I reverted the engine fix — adding the probes back into the site counter, which was the original bug — and ran the test expecting red.

It stayed green.

The reason, once seen, is obvious. The emitter was never broken: it does what it is told with the numbers it is given. What was wrong was who hands it those numbers, in the crawl loop, which was adding two different things together before passing them on. My test handed it the numbers already split and checked that it passed them on split. It was checking that two plus two is four.

The good test had to look at a whole crawl: a test server standing in for a foreign host answering in 300 milliseconds, two external links, and a progress observer recording the peak of each counter. With that, reverting the wiring does go red, and the message says why: “some snapshot should have shown pending probes”.

The 300 milliseconds are not arbitrary either, and that was the third lesson of the afternoon. At a 120 ms delay the test failed, and not because of the bug: the emitter samples every 150 milliseconds, the whole crawl finished in less than that, and only the initial snapshot was ever emitted, with the counters at zero. A timing test that ignores the timings of the system under test is measuring something else.

Why this happens more than it looks

It is the third time this month that a test in this project passes with its bug in place, and all three followed the same shape: the test aims at the piece that is fine, not at the seam between two pieces. It is easy to see why — the piece is what you just wrote and it is fresh in your head — and the seam is exactly where things break.

Which is why the check is not “does the test pass?” but “have I watched it fail for the bug I claim it covers?”. It takes thirty seconds, and it is the difference between a test and an ornament. In yesterday’s entry that same habit uncovered a scheduler bug that had been sitting there for weeks.

The rest of the 0.9.2 balance: 1,036 tests green, the linter quiet, and the performance regression compiled with optimisations at 107,702 items per second with 30.1 MB peak memory. Both new tests stay, the emitter one included: it checks little, but what it checks is true and it costs microseconds.