Testing, Debugging, and Logging

Three tools answer three questions

A program working once is nice, but it is not much evidence. Tests, debuggers, and logs help in different ways.

A debugger session does not leave a repeatable test. A pile of logs does not prove correctness. Use the smallest tool that answers the current question.

Make tests boring and repeatable

A deterministic test controls its inputs and checks public behavior. It should not secretly depend on the clock, network, random state, current folder, test order, or another test’s leftovers.

unittest discovers methods beginning with test. Boundary cases with the same shape fit neatly in subTest():

import unittest


def pace(minutes):
    if minutes < 0:
        raise ValueError("minutes must not be negative")
    return "short" if minutes <= 20 else "long"


class PaceTests(unittest.TestCase):
    def test_boundaries(self):
        for minutes, expected in [(0, "short"), (20, "short"), (21, "long")]:
            with self.subTest(minutes=minutes):
                self.assertEqual(pace(minutes), expected)

    def test_negative_value_fails(self):
        with self.assertRaisesRegex(ValueError, "negative"):
            pace(-1)


suite = unittest.defaultTestLoader.loadTestsFromTestCase(PaceTests)
result = unittest.TestResult()
suite.run(result)
print(result.testsRun, len(result.failures), len(result.errors))

Output:

2 0 0

Test empty input, the last accepted value, the first rejected value, and expected failures. Use assertAlmostEqual() only when floating-point rounding is part of the contract; prefer exact assertions for strings, integers, and collections. A failing test should point to one broken behavior, not duplicate every implementation detail.

Mock only the narrow doorway

A mock is a pretend collaborator that remembers calls. Use one at an external doorway such as a publisher, clock, or client—not for every pure helper.

from unittest.mock import Mock


def publish(summary, sender):
    sender(summary)
    return "sent"


sender = Mock()
print(publish({"minutes": 45}, sender))
print(sender.call_args)

Output:

sent
call({'minutes': 45})

Dependency injection keeps the doorway visible; a test can use sender.assert_called_once_with(...). If you need patch(), patch the name where the code under test looks it up. If report.py imported send directly, patch report.send, not the module that originally defined send. Prefer spec= or autospec=True for real interfaces, and keep most real code connected.

Read clues before changing code

For an exception, read the traceback’s final line first: type and message. Then move upward through the nearest frames and find the first place where actual state stopped matching your expectation. Preserve low-level evidence with raise NewError(...) from cause when adding domain wording.

def safe_ratio(part, whole, *, debug=False):
    if debug:
        breakpoint()
    if whole == 0:
        raise ValueError("whole must not be zero")
    return part / whole


print(safe_ratio(6, 3))

Normal output is 2.0. With debug=True, the usual pdb prompt lets you use p expression, n for next line, s to step in, where for the stack, c to continue, and q to quit. Do not inspect with expressions that change state. Remove unconditional breakpoints before automation; one can wait forever for a person who is not there.

Build an observable study report

Logging is data flow: a logger accepts records, a handler chooses a destination and level, and a formatter chooses stable text. Configure an application-owned logger at the entry point, not the root logger inside a reusable library.

Save this complete standard-library project as observable_report.py:

import logging
import sys
import unittest
from dataclasses import dataclass
from io import StringIO
from unittest.mock import Mock


@dataclass(frozen=True)
class Record:
    topic: str
    minutes: int


def parse_record(line):
    topic, separator, minutes_text = line.partition("|")
    if not separator or not topic.strip():
        raise ValueError("expected topic|minutes")
    try:
        minutes = int(minutes_text)
    except ValueError as cause:
        raise ValueError("minutes must be an integer") from cause
    if minutes <= 0:
        raise ValueError("minutes must be positive")
    return Record(topic.strip(), minutes)


def load_records(lines, logger):
    records = []
    for number, line in enumerate(lines, start=1):
        try:
            record = parse_record(line)
        except ValueError as error:
            logger.warning(
                "skipped line %d: %s",
                number,
                error,
                extra={"event": "invalid_record"},
            )
        else:
            records.append(record)
    logger.info(
        "loaded %d records",
        len(records),
        extra={"event": "import_complete"},
    )
    return records


def summarize(records):
    return {"count": len(records), "minutes": sum(r.minutes for r in records)}


def publish_summary(records, publisher):
    summary = summarize(records)
    publisher(summary)
    return summary


def configure_logger(stream):
    logger = logging.getLogger("observable_report")
    logger.handlers.clear()
    logger.propagate = False
    logger.setLevel(logging.INFO)
    handler = logging.StreamHandler(stream)
    handler.setLevel(logging.INFO)
    handler.setFormatter(logging.Formatter("%(levelname)s %(event)s %(message)s"))
    logger.addHandler(handler)
    return logger


class ReportTests(unittest.TestCase):
    def test_boundaries(self):
        cases = [("Testing | 1", Record("Testing", 1)), (" Logging | 45 ", Record("Logging", 45))]
        for text, expected in cases:
            with self.subTest(text=text):
                self.assertEqual(parse_record(text), expected)

    def test_invalid_minutes_fail(self):
        with self.assertRaisesRegex(ValueError, "integer"):
            parse_record("Testing | many")

    def test_logs_are_stable(self):
        stream = StringIO()
        records = load_records(["Testing | 20", "Bad | zero"], configure_logger(stream))
        self.assertEqual(records, [Record("Testing", 20)])
        self.assertEqual(
            stream.getvalue().splitlines(),
            [
                "WARNING invalid_record skipped line 2: minutes must be an integer",
                "INFO import_complete loaded 1 records",
            ],
        )

    def test_publisher_doorway(self):
        publisher = Mock()
        summary = publish_summary([Record("Testing", 20)], publisher)
        self.assertEqual(summary, {"count": 1, "minutes": 20})
        publisher.assert_called_once_with(summary)


suite = unittest.defaultTestLoader.loadTestsFromTestCase(ReportTests)
test_result = unittest.TestResult()
suite.run(test_result)
if not test_result.wasSuccessful():
    raise AssertionError(test_result.failures + test_result.errors)
print(f"Tests: {test_result.testsRun}, failures: 0, errors: 0")

logger = configure_logger(sys.stdout)
records = load_records(["Testing | 30", "Broken | many", "Logging | 25"], logger)
summary = summarize(records)
print(f"Total: {summary['count']} records, {summary['minutes']} min")

Run python3 observable_report.py:

Tests: 4, failures: 0, errors: 0
WARNING invalid_record skipped line 2: minutes must be an integer
INFO import_complete loaded 2 records
Total: 2 records, 55 min

The test owns its StringIO, and propagate = False prevents duplicate output from ancestor loggers. No timestamp, machine path, global configuration, or network makes the checks wobble. Stable event fields add searchable context; never put secrets or reserved LogRecord names in extra.

Three tiny missions

1. Add subtests for zero minutes, a blank topic, and the smallest valid minute.
2. Make an injected mock publisher raise RuntimeError and test that the failure remains visible.
3. Add a stable source field to every log record and update the formatter and exact log test.

Ready for Chapter 20?

• I can write deterministic unittest cases for success, boundaries, and failure.
• I can label repeated cases with subTest().
• I mock one collaborator doorway, not every internal helper.
• I read a traceback before editing and use breakpoint() intentionally.
• I configure a named logger, handler, level, formatter, and stable context.
• I ran the report and tested behavior, logs, and the publisher.

Next, you will use these skills to polish, package, and ship a complete command-line application.