I shipped a release yesterday. Four CI rounds, most of a day, and the part worth writing down isn't the release — it's that three checks in my own test suite had been passing for reasons that had nothing to do with what they claimed to test, and I only found out because a platform I don't own ran them.
They're three separate mechanisms. That's what makes them worth reading about: I didn't make one mistake three times, I made three different mistakes that all produce the same symptom, which is a green check that means nothing.
One: the trigger that never fired
The feature is small. A rule file in the workspace can declare Applies to: lib/redact.py, and when the files it names are the ones being edited, that rule gets more room in the context block than one that declares nothing. The check compares the two and asserts the scoped one wins.
It passed on macOS. It failed on Windows. I spent a while assuming that meant something about Windows.
It didn't. The check builds a temp repository and commits into it — five commits. The ranking it depends on returns nothing below fifty commits, so the trigger under test had never fired, on any platform, since the check was written. What it was actually comparing was the raw length of two strings, and the scoped rule's body is longer than the unscoped one for a reason you can probably guess: it carries the Applies to: line. Forty-one characters. That was the entire margin it had been passing by.
Windows didn't find a Windows bug. Windows got unlucky with string lengths in the other direction and exposed a check that had never worked.
Fixed by making the fixture commit past the constant it depends on, derived from the constant rather than hardcoded:
for i in range(_rollup.MIN_COMMITS_TO_RANK + 2):
With the trigger actually firing: scoped 541 characters, unscoped 306, elsewhere 300. Against 411 / 370 / 371 before. The feature works. Nothing had ever shown that, and it was named in the release notes.
Two: the check that was never the platform under test
This one is almost funny. A detector warns when a repository contains a file named like a program the tool is about to run, because Windows searches the current directory before PATH. The check forces sys.platform = "win32", exercises the detector, restores the platform, and then asserts the detector stays quiet — "it stays silent on a platform that does not search the current directory."
On a Mac that's true. On Windows the real platform is the platform under test, the detector correctly fires, and the check fails.
I'd written a check whose final assertion was only correct on machines that are not the thing it tests.
Three: a floor finer than the clock
CI reported this:
FAIL late failure on 'identifiers' grows no worse than linearly:
0.0 ms at 4 KiB, 31.2 ms at 16 KiB (x625.0)
Four times the input, 625 times the CPU. That reads like a catastrophic regression in a redaction routine.
The line doing the dividing:
ratio = big / max(small, 0.05)
process_time() on Windows advances on the scheduler tick, roughly every 15.6 ms. The 4 KiB case is faster than that, so it reads 0.0. The floor supplies 0.05. And 31.2 / 0.05 is 624.
The tell was in the log the whole time and I didn't see it for a while: 31.2 is exactly 15.6 x 2. Both numbers were quantised to ticks. Also, the same input passed on Python 3.8 in the same run — a real quadratic blowup doesn't care which interpreter you use.
The fix is autoranging, the way timeit does it: repeat the small case until the total is genuinely measurable, then measure both sizes at that same repeat count and divide the totals.
And then I got it wrong a second time, which is the part I actually want to write down.
The second mistake inside the fix
My first version keyed the target off time.get_clock_info("process_time").resolution.
That's a documented API returning a real number, and on Windows it is 1e-07. One hundred nanoseconds — the unit GetProcessTimes returns its values in. It is not the rate at which those values change, which is the 15.6 ms tick. So the target would have been 0.002 ms, the autorange would have stopped immediately, and the fix would have been a no-op on the only platform it exists for.
It would also have passed every local test, because this Mac's clock really does resolve to a microsecond and the repeat count stays at 1 here no matter what.
Measure the tick instead of asking for it:
t0 = time.process_time()
while True:
t1 = time.process_time()
if t1 != t0:
return (t1 - t0) * 1000.0
Take the larger of that and the reported resolution. On macOS nothing changes. On Windows the target becomes ~312 ms and the autorange does its job.
How I checked it this time
The thing that had bitten me three times in one day was believing a green result from a mechanism that had never engaged. So before trusting the fix I forced the resolution to 15.6 ms in a scratch copy and watched what the autorange did:
'identifiers': resolution 15.600 ms, repeated x64 to reach a 512.493 ms baseline
'digits': resolution 15.600 ms, repeated x32 to reach a 319.907 ms baseline
'spaces': resolution 15.600 ms, repeated x8 to reach a 312.779 ms baseline
Ten lines of Python, no VM, no second machine. The mechanism engaged, the baselines became real numbers, and the check still passed. That is evidence. The earlier run where everything was green and repeat was 1 everywhere was not.
What I'd take from it
Three mechanisms, one symptom:
- a population that was never gathered (five commits against a threshold of fifty)
- an environment that was never entered (the check ran on the platform it wasn't about)
- a mechanism that never engaged (repeat stuck at 1 on a fast clock)
None of them announces itself. All three look exactly like a passing test, and a passing test is the thing you least want to go and re-examine.
The habit I'm trying to build from it is narrow enough to actually follow: before believing a check, make it fail on purpose. Not "does it pass" — "have I watched this go red for the reason it exists?" It cost me ten minutes per check. It would have saved most of a day.
And the part I keep turning over: none of these were bugs in the shipped code. Every one was in the apparatus I use to decide whether the shipped code is correct. The tools were fine. The instruments were lying.
Top comments (0)