Chapter 45 — The Test Harness

Green tests that never mention the clock

Chapter 42 wrote down what a servo was expected to do beside what it actually did. Chapter 43 put the seam cases behind one runner so a broken handoff between two working modules stopped hiding. Both answer the same question: did it work. Neither says how long it took. For an assistant that has to answer a spoken question before the person asking gets bored, the second question fails first, and it fails quietly.

Picture the version you will actually live through. Someone adds a lookup to the reply path, and a turn that used to spend 40 microseconds inside her own orchestration now spends 40 milliseconds. Every assertion still passes. Three weeks later she feels sluggish, twenty commits are candidates, and none is obviously guilty. The number that would have convicted the right one existed on the day it landed, and nothing wrote it down.

So this chapter's rule: a test result is data, with a name, a verdict, a duration in milliseconds and a message, and the suite writes those results to a file so this morning's run can be compared against last week's. Forty lines of standard library, no framework, no plugins, and it runs in the time it takes Python to start.

◆ Note — pytest is still the right tool for the big suite

None of this is an argument against pytest. When you want fixtures, parametrized cases and a plugin that collects a thousand tests across a package, install it and use it. This one exists for the other job: the fast pulse you run on every save and on a single-board computer over ssh, where "add a framework and two plugins to learn that a turn now takes 40 ms" is more moving parts than the question deserves. The two coexist happily, with one wrinkle: run pytest in the same project and it will decline to collect TestHarness and TestResult, because their names start with Test and their constructors take arguments. It says so in a warning, and it is the same rule chapter 43 worked around.

Time it, catch it, keep going

▣ Build · stage 1 — one test, timed and recorded

# labs/test_harness.py
import time
from dataclasses import dataclass


@dataclass
class TestResult:
    name: str
    passed: bool
    duration_ms: float
    error: str = ""


class TestHarness:
    def __init__(self, suite: str) -> None:
        self.suite = suite
        self.results: list[TestResult] = []

    def test(self, func) -> TestResult:
        start = time.perf_counter()
        try:
            func()
            result = TestResult(func.__name__, True, (time.perf_counter() - start) * 1000)
        except Exception as exc:
            result = TestResult(func.__name__, False, (time.perf_counter() - start) * 1000, str(exc))
        self.results.append(result)
        flag = "PASS" if result.passed else "FAIL"
        print(f"  [{flag}] {result.name} ({result.duration_ms:.3f} ms)")
        return result


def test_reply_is_never_blank() -> None:
    assert "Oh. It's you again.".strip()


if __name__ == "__main__":
    runner = TestHarness("voice loop")
    runner.test(test_reply_is_never_blank)

$ uv run python labs/test_harness.py
  [PASS] test_reply_is_never_blank (0.001 ms)

A test is a function that returns normally when things are fine and raises when they are not, so assert already does the whole job and TestHarness only has to catch what it throws. except Exception is deliberate: it covers AssertionError and anything else a test body can raise, while leaving KeyboardInterrupt and SystemExit alone, because those derive from BaseException and Ctrl+C should stop a run instead of becoming a logged result. func.__name__ supplies the label, which is why test takes a function object and not a name plus a lambda. Three decimal places, because a passing test measured in single microseconds rounds to zero at one place, and zeros cannot creep.

▣ Build · stage 2 — break one on purpose, then count

    def summary(self) -> dict:
        passed = sum(1 for r in self.results if r.passed)
        return {"suite": self.suite, "total": len(self.results),
                "passed": passed, "failed": len(self.results) - passed}


def test_history_pairs_up() -> None:
    history = []
    history.append({"role": "user", "content": "Hello GLaDOS"})
    assert len(history) == 4, f"expected 4 messages, got {len(history)}"


if __name__ == "__main__":
    runner = TestHarness("voice loop")
    runner.test(test_reply_is_never_blank)
    runner.test(test_history_pairs_up)
    print(runner.summary())

$ uv run python labs/test_harness.py
  [PASS] test_reply_is_never_blank (0.001 ms)
  [FAIL] test_history_pairs_up (0.002 ms)
         expected 4 messages, got 1
{'suite': 'voice loop', 'total': 2, 'passed': 1, 'failed': 1}

The broken test proves the one important job: the AssertionError becomes a row, the run carries on, and summary() counts one of each. A runner that let the first failure escape would hide every test after it, and those are the ones you want on the day something breaks. Notice where the message came from. A bare assert len(history) == 4 raises AssertionError() with no arguments, and str() of that is the empty string, so the report would record a failure with nothing to say about it. The comma and the f-string put expected 4 messages, got 1 in the error field. Write the message every time; you are writing it for yourself at 11pm.

Point it at the loop she actually runs

▣ Build · stage 3 — test a real turn with fake collaborators

from glados.core import GladOSCore


def fake_stt(path: str) -> str:
    return "Hello GLaDOS"


def fake_llm(text: str, history: list[dict]) -> str:
    return f"Oh. It's you again. ({len(history)} messages remembered)"


def fake_tts(text: str) -> None:
    print(f"[SPEAKING] {text}")


def build_core() -> GladOSCore:
    return GladOSCore(stt=fake_stt, llm=fake_llm, tts=fake_tts)


def test_turn_reports_success() -> None:
    assert build_core().run_turn("glados/data/heard.wav") is True


def test_silence_ends_the_turn() -> None:
    core = GladOSCore(stt=lambda path: "   ", llm=fake_llm, tts=fake_tts)
    assert core.run_turn("glados/data/heard.wav") is False


def test_history_pairs_up() -> None:
    core = build_core()
    core.run_turn("glados/data/heard.wav")
    core.run_turn("glados/data/heard.wav")
    assert len(core.history) == 4, f"expected 4 messages, got {len(core.history)}"

$ uv run python labs/test_harness.py
You: Hello GLaDOS
GLaDOS: Oh. It's you again. (0 messages remembered)
[SPEAKING] Oh. It's you again. (0 messages remembered)
  [PASS] test_turn_reports_success (0.008 ms)
  [PASS] test_silence_ends_the_turn (0.003 ms)
You: Hello GLaDOS
GLaDOS: Oh. It's you again. (0 messages remembered)
[SPEAKING] Oh. It's you again. (0 messages remembered)
You: Hello GLaDOS
GLaDOS: Oh. It's you again. (2 messages remembered)
[SPEAKING] Oh. It's you again. (2 messages remembered)
  [PASS] test_history_pairs_up (0.007 ms)

Three real conversational turns ran through the real GladOSCore, and the whole suite finished in under a fiftieth of a millisecond. That is possible because of the constructor chapter 32 built: the core takes its listener, brain and voice as arguments, so fake_stt, fake_llm and fake_tts stand in for a transcription model, a language model and a speech synthesizer, each returning a fixed string in microseconds. What gets measured is her orchestration, the turn logic you keep editing, with none of the model load time that would drown it. Swap a real engine back in and the same test tells you what that engine costs. Two suites, one runner.

▣ Build · stage 4 — quiet the collaborators, then give the clock authority

import contextlib
import io

    def test(self, func, max_ms: float | None = None) -> TestResult:
        start = time.perf_counter()
        try:
            with contextlib.redirect_stdout(io.StringIO()):
                func()
            elapsed = (time.perf_counter() - start) * 1000
            if max_ms is not None and elapsed > max_ms:
                result = TestResult(func.__name__, False, elapsed,
                                    f"over budget: {elapsed:.1f} ms > {max_ms:.1f} ms")
            else:
                result = TestResult(func.__name__, True, elapsed)
        except Exception as exc:
            elapsed = (time.perf_counter() - start) * 1000
            result = TestResult(func.__name__, False, elapsed, str(exc))


def slow_llm(text: str, history: list[dict]) -> str:
    time.sleep(0.05)                      # a stage that got slower overnight
    return fake_llm(text, history)


def test_turn_within_budget() -> None:
    build_core().run_turn("glados/data/heard.wav")


def test_turn_within_budget_slow() -> None:
    core = GladOSCore(stt=fake_stt, llm=slow_llm, tts=fake_tts)
    core.run_turn("glados/data/heard.wav")


if __name__ == "__main__":
    runner = TestHarness("voice loop")
    runner.test(test_turn_within_budget, max_ms=5.0)
    runner.test(test_turn_within_budget_slow, max_ms=5.0)

$ uv run python labs/test_harness.py
  [PASS] test_turn_within_budget (0.013 ms)
  [FAIL] test_turn_within_budget_slow (50.106 ms)
         over budget: 50.1 ms > 5.0 ms

Two changes, both small. redirect_stdout swaps the process's standard output for an in-memory buffer for the duration of the call, so everything the turn prints lands in a string no one reads and the output goes back to one line per test; test prints after the with block closes, so its own lines survive. Then max_ms: a test that raises fails, and now a test that returns correctly but takes longer than its budget fails too, on a number already in hand. That is the regression from the top of the chapter, caught the day it landed by a suite that ran in 50 milliseconds. Your figures will differ from these, and the 50 ms here is a sleep standing in for the change you did not mean to make.

▣ Build · stage 5 — the assembled module, and a report on disk

# labs/test_harness.py — full file
import contextlib
import io
import json
import time
from dataclasses import dataclass
from datetime import datetime
from pathlib import Path

from glados.core import GladOSCore

REPORT = Path("glados/data/test_harness.json")


@dataclass
class TestResult:
    name: str
    passed: bool
    duration_ms: float
    error: str = ""


class TestHarness:
    def __init__(self, suite: str) -> None:
        self.suite = suite
        self.results: list[TestResult] = []

    def test(self, func, max_ms: float | None = None) -> TestResult:
        start = time.perf_counter()
        try:
            with contextlib.redirect_stdout(io.StringIO()):
                func()
            elapsed = (time.perf_counter() - start) * 1000
            if max_ms is not None and elapsed > max_ms:
                result = TestResult(func.__name__, False, elapsed,
                                    f"over budget: {elapsed:.1f} ms > {max_ms:.1f} ms")
            else:
                result = TestResult(func.__name__, True, elapsed)
        except Exception as exc:
            elapsed = (time.perf_counter() - start) * 1000
            result = TestResult(func.__name__, False, elapsed, str(exc))
        self.results.append(result)
        flag = "PASS" if result.passed else "FAIL"
        print(f"  [{flag}] {result.name} ({result.duration_ms:.3f} ms)")
        if result.error:
            print(f"         {result.error}")
        return result

    def summary(self) -> dict:
        passed = sum(1 for r in self.results if r.passed)
        return {"suite": self.suite, "total": len(self.results),
                "passed": passed, "failed": len(self.results) - passed}

    def save(self, path: Path) -> None:
        path.parent.mkdir(parents=True, exist_ok=True)
        report = {
            "summary": self.summary(),
            "run_at": datetime.now().isoformat(timespec="seconds"),
            "results": [
                {"name": r.name, "passed": r.passed,
                 "duration_ms": round(r.duration_ms, 4), "error": r.error}
                for r in self.results
            ],
        }
        path.write_text(json.dumps(report, indent=2))


def fake_stt(path: str) -> str:
    return "Hello GLaDOS"


def fake_llm(text: str, history: list[dict]) -> str:
    return f"Oh. It's you again. ({len(history)} messages remembered)"


def fake_tts(text: str) -> None:
    print(f"[SPEAKING] {text}")


def build_core() -> GladOSCore:
    return GladOSCore(stt=fake_stt, llm=fake_llm, tts=fake_tts)


def test_turn_reports_success() -> None:
    assert build_core().run_turn("glados/data/heard.wav") is True


def test_silence_ends_the_turn() -> None:
    core = GladOSCore(stt=lambda path: "   ", llm=fake_llm, tts=fake_tts)
    assert core.run_turn("glados/data/heard.wav") is False


def test_history_pairs_up() -> None:
    core = build_core()
    core.run_turn("glados/data/heard.wav")
    core.run_turn("glados/data/heard.wav")
    assert len(core.history) == 4, f"expected 4 messages, got {len(core.history)}"


def test_turn_within_budget() -> None:
    build_core().run_turn("glados/data/heard.wav")


def main() -> None:
    runner = TestHarness("voice loop")
    runner.test(test_turn_reports_success)
    runner.test(test_silence_ends_the_turn)
    runner.test(test_history_pairs_up)
    runner.test(test_turn_within_budget, max_ms=5.0)
    runner.save(REPORT)
    print(runner.summary())


if __name__ == "__main__":
    main()

$ uv run python labs/test_harness.py
  [PASS] test_turn_reports_success (0.013 ms)
  [PASS] test_silence_ends_the_turn (0.005 ms)
  [PASS] test_history_pairs_up (0.009 ms)
  [PASS] test_turn_within_budget (0.013 ms)
{'suite': 'voice loop', 'total': 4, 'passed': 4, 'failed': 0}

$ head -20 glados/data/test_harness.json
{
  "summary": {
    "suite": "voice loop",
    "total": 4,
    "passed": 4,
    "failed": 0
  },
  "run_at": "2026-08-22T09:28:16",
  "results": [
    {
      "name": "test_turn_reports_success",
      "passed": true,
      "duration_ms": 0.013,
      "error": ""
    },
    {
      "name": "test_silence_ends_the_turn",
      "passed": true,
      "duration_ms": 0.0054,
      "error": ""
    },

The file is the point of the exercise. A terminal scrolls; this does not. round(r.duration_ms, 4) trims seventeen digits of floating-point noise to something a human compares at a glance while keeping microsecond resolution, so a test drifting from 0.0054 to 0.0090 shows up. timespec="seconds" stops the timestamp carrying microseconds no one will read. And mkdir(parents=True, exist_ok=True) is the habit from chapter 31: create the folder if it is missing, say nothing if it is there, so the script works the first time and the fiftieth.

Why this works: two exits and one honest clock

All of it rests on one fact about Python: a raised exception unwinds the stack until something catches it. The try block is that catcher, so the two ways any function can end map onto two branches. Return normally and you get TestResult(passed=True). Raise anything at all and the except branch records the failure, keeps the message, and lets the run continue. The budget check adds a third verdict with no third exit, because the duration is already in a local variable by then. The pattern generalizes past testing: turn "it blew up" into a value and the caller decides what happens next, instead of the stack deciding for it.

The clock matters as much as the catch. time.perf_counter() is monotonic and high-resolution: it counts from an arbitrary starting point that never moves backwards, so an NTP correction landing mid-test cannot produce a negative duration the way time.time() can. Sampling it in both branches means even a failed test reports how long it ran before it broke, which tells you whether it died instantly or timed out waiting on something.

Chapter 28 timed things too, with a @timed decorator that wrapped a stage and logged its duration. Same clock, different owner of the number. The decorator lives inside the production path permanently and reports to the log, for you watching a live session. TestHarness stays outside the code it measures and hands the duration back as a value the caller can assert on, store and compare. Instrumentation watches; a harness judges.

⚠ Worked failure — the parentheses that killed the run

The harness wants a function, not a function's result. Two characters separate those:

    runner.test(test_turn_reports_success())   # called it: passes None, not the function

$ uv run python labs/test_harness.py
You: Hello GLaDOS
GLaDOS: Oh. It's you again. (0 messages remembered)
[SPEAKING] Oh. It's you again. (0 messages remembered)
Traceback (most recent call last):
  File "/home/you/GladOS/labs/test_harness.py", line 32, in test
    func()
    ~~~~^^
TypeError: 'NoneType' object is not callable

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/you/GladOS/labs/test_harness.py", line 106, in main
    runner.test(test_turn_reports_success())
    ~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/you/GladOS/labs/test_harness.py", line 41, in test
    result = TestResult(func.__name__, False, elapsed, str(exc))
                        ^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute '__name__'

Read it from the top and the sequence comes apart cleanly. The turn's own output appears first, before any PASS or FAIL line, because the test ran at the call site while Python was still evaluating the argument; the redirect never got a chance. The function returned None, so func is None and func() raised TypeError, which was caught exactly as designed. Then the except branch reached for func.__name__ to label the result, None has no such attribute, and a second exception escaped from inside the handler and took the run down. "During handling of the above exception, another exception occurred" means the crash you are reading is a bug in the error path: read the first traceback for the cause, the second for where the recovery went wrong. Delete the parentheses and it works. The lesson underneath is that error paths run at the worst possible moment and are the least tested lines in any codebase.

Checkpoint, and reactions that need a net under them

✓ Checkpoint — what you can now do

I can explain why except Exception and not a bare except in test, and what still gets through it on purpose.
I can say what str() of a bare AssertionError gives, and what putting a comma and a message after an assertion changes in the report.
I can name two properties of perf_counter that time.time lacks, and what goes wrong in a duration when a clock is corrected mid-run.
I can point at the constructor argument that lets a test drive a full turn with no model on the machine, and say what the resulting duration is measuring.
Handed a suite that dies with two stacked tracebacks, I can tell which one names the original fault and which one names the broken handler.

⚡ Exercises — try first, then reveal

Exercise 1 — a test per case. Add test_many(func, cases) that runs func once per case and records each as its own result, labelled with the case, so one bad input does not hide behind five good ones.

Pull the timing body out into a private _record(name, func) so test and test_many share it, then loop: self._record(f"{func.__name__}[{case!r}]", lambda c=case: func(c)). The c=case default argument is the part that matters. A plain lambda: func(case) captures the variable, not its value, so every queued call would run with whatever case held last, and all three results would report the same input. Run it over ["hello", "glados", ""] against a check that the transcript is non-empty and you should see two PASS rows and one FAIL row naming the empty string.

Exercise 2 — make the exit code mean something. Have main() exit non-zero when anything failed, then run the suite from a shell and print $?.

Two lines: import sys at the top, then sys.exit(1 if runner.summary()["failed"] else 0) at the end of main. With every test passing echo $? prints 0; break one and it prints 1. That number is the whole interface between your suite and anything that automates it: a git hook, a Makefile target, a job on a build machine. A suite that always exits zero can be run automatically and ignored automatically.

Exercise 3 — compare two runs. Save each report under a timestamped filename, then write compare.py that loads two of them and prints the per-test change in milliseconds.

Name the files with datetime.now().strftime("%Y%m%dT%H%M%S") so they sort chronologically, build a dict from name to duration_ms for each report, and walk the keys they share. Print f"{name:32} {old:8.4f} -> {new:8.4f} {new - old:+.4f}" for a column of signed deltas. Now insert time.sleep(0.002) into fake_llm and rerun: the turn tests jump by about two milliseconds and the silence test, which never reaches the brain, does not move. The deltas point at the stage, not just at the suite.

There is a net under her now: change the turn logic, run four tests in a blink, and see both correctness and cost before you commit. The next thing to change is how she decides what to do at all. Her reactions still live in an if/elif chain that grows a branch every time she learns a trick, and that chain cannot say which reaction wins when two of them fire on the same event. Chapter 46 moves those reactions into data with a priority on each, and the tests you just built are what make that rewrite safe.