--- jupytext: formats: md:myst text_representation: extension: .md format_name: myst kernelspec: display_name: Python 3.14 language: python name: python3 --- ```{code-cell} python :tags: [remove-cell] import os, sys os.environ["PATH"] = f"{os.path.dirname(sys.executable)}:{os.environ['PATH']}" os.environ.pop("VIRTUAL_ENV", None) for d in ("/tmp/stash_demo", "/tmp/conftest_demo", "/tmp/hooks_demo", "/tmp/hookimpl_demo", "/tmp/twohooks_demo/sub", "/tmp/pytest_loud_pkg", "/tmp/loud_test", "/tmp/marks_args_demo"): os.makedirs(d, exist_ok=True) ``` # Лекция 3. Тестирование и логирование ## План Сначала коротко — зачем тесты вообще и какими они бывают. Дальше четыре блока: 1. **pytest** — discovery, фикстуры и scope, `monkeypatch`, `parametrize`, `conftest.py`, marks, плагины. 2. **Coverage** — line vs branch, что мерить и что нет. 3. **logging** — уровни, иерархия, handlers/filters/formatters, `dictConfig`. 4. **structlog** — structured logs, context binding. В конце — раздел "Разбираем на семинаре": то, что нужно для задач, но для основной части не обязательно. ## Зачем тесты Работаем мы обычно командой, и договорённости о том, как ведёт себя код, надо где-то держать. Можно описать поведение текстом — в README, в комментарии, в голове автора. А можно зафиксировать его кодом, тестом. Кодом всегда лучше, и причина одна: настроенный CI гоняет тесты на каждый коммит, поэтому зафиксированное поведение остаётся актуальным — либо оно выполняется, либо прогон красный. Текст же устаревает молча: код поменяли, описание осталось прежним, и никто не заметил. ## Виды тестов Делят по тому, какой кусок системы тест трогает: **юнит** — одна функция или класс без внешнего мира; **интеграционные** — несколько компонентов вместе, часто с настоящими файлами или запущенным процессом; **приёмочные** — система целиком, глазами пользователя. Граница размытая, и спорить о ней бессмысленно. ## 1. pytest: за что мы его любим Три вещи, которые делают pytest де-факто стандартом: - **Синтаксис**: тест — просто функция и обычный `assert`, без обязательного класса-обёртки и без отдельного метода на каждый вид проверки (см. ниже). - **Фикстуры как DI**: аргументы функции подтягиваются из фикстур, время жизни задаётся явно. - **Гигантская экосистема**: `pytest-mock`, `pytest-xdist`, `pytest-cov`, `pytest-benchmark`, `pytest-timeout`, ... (тесты для async — `pytest-asyncio` — рассмотрим дальше в курсе, там, где сам asyncio).
Термин: DI (dependency injection) Зависимость не создаётся внутри функции, а передаётся ей снаружи. Тест объявляет, что ему нужно, параметром — def test_x(storage), — а кто и как создаст storage, решает pytest по имени параметра. Тест не знает ни про конструктор, ни про порядок инициализации, поэтому ту же зависимость легко подменить в другом окружении.
### Синтаксис unittest В `unittest` из stdlib тест обязан быть методом класса-наследника `TestCase`, а на каждый вид сравнения есть свой метод: `assertEqual`, `assertTrue`, `assertIn`, `assertRaises`, ... Их надо помнить и выбирать. ```{code-cell} python %%writefile /tmp/test_unittest_style.py import unittest def add(a: int, b: int) -> int: return a + b class TestAdd(unittest.TestCase): def test_add_positive(self) -> None: self.assertEqual(add(2, 3), 5) def test_in(self) -> None: self.assertIn("a", "abc") def test_oops(self) -> None: self.assertEqual(add(2, 3), 6) # ломаем специально — смотрим диагностику ``` ```{code-cell} python !PYTHONPATH=/tmp uv run python -m unittest -v test_unittest_style 2>&1 ``` То же самое на pytest — функция и обычный `assert`, без класса, без `self`, без словаря `assert*`-методов: ```{code-cell} python %%writefile /tmp/test_flat_style.py def add(a: int, b: int) -> int: return a + b def test_add_positive() -> None: assert add(2, 3) == 5 def test_in() -> None: assert "a" in "abc" def test_oops() -> None: assert add(2, 3) == 6 # ломаем так же ``` ```{code-cell} python !uv run pytest /tmp/test_flat_style.py -v || true ``` `unittest` сообщил только итог сравнения: `AssertionError: 5 != 6`. Какое подвыражение дало пятёрку, приходится достраивать глазами по строке кода. Pytest переписывает `assert` на этапе импорта и печатает разбор сам: `assert 5 == 6`, а следом `where 5 = add(2, 3)`. На `add(2, 3)` разница невелика, на условии в полстроки — уже нет. ### Проверка исключений — `pytest.raises` Обычного `assert` хватает не на всё: проверить, что код **бросил** исключение, им нельзя — упавший вызов не даст добраться до самого `assert`. Для этого есть менеджер контекста `pytest.raises`. ```{code-cell} python %%writefile /tmp/test_raises.py import pytest def parse_age(raw: str) -> int: age = int(raw) if age < 0: raise ValueError(f"возраст не может быть отрицательным: {age}") return age def test_raises_on_negative() -> None: with pytest.raises(ValueError): parse_age("-1") def test_message_matters() -> None: # match — регулярка по тексту исключения with pytest.raises(ValueError, match="отрицательным"): parse_age("-1") def test_inspect_the_exception() -> None: with pytest.raises(ValueError) as excinfo: parse_age("-5") assert "-5" in str(excinfo.value) ``` ```{code-cell} python !uv run pytest /tmp/test_raises.py -v ``` Три степени строгости. Голый `pytest.raises(ValueError)` проверяет только тип — и это чаще всего слишком слабо: `parse_age("abc")` тоже даёт `ValueError`, но совсем по другой причине, из `int()`. `match=` добавляет проверку текста, а `excinfo.value` отдаёт сам объект исключения, если надо посмотреть на поля.
Внутри with — только то, что должно упасть Лишние строки в блоке — и тест начнёт проходить не по той причине: исключение бросит соседний вызов, а ты будешь думать, что проверил нужный. Правило: один вызов внутри with, всё остальное до или после.
### Как pytest находит тесты
Термин: discovery (сбор тестов) Отдельная фаза до запуска: pytest обходит дерево каталогов, импортирует подходящие файлы и собирает из них тест-функции. Если тест "не бежит" — он чаще всего не запустился, а не упал: его просто не собрали. Смотреть, что собралось, — pytest --collect-only.
Правила discovery по умолчанию: - Файлы: `test_*.py` или `*_test.py` в текущем каталоге и всех подкаталогах. - Функции: `def test_*(...)` на верхнем уровне модуля. - Классы: `class Test*` **без** `__init__` — методы внутри `def test_*(self, ...)`. Класс с `__init__` не собирается вовсе: `PytestCollectionWarning`, и в отчёте его тестов нет — ни passed, ни skipped. Всё это конфигурируется в `pyproject.toml` (`[tool.pytest.ini_options]`): ```toml [tool.pytest.ini_options] testpaths = ["tests"] # где искать python_files = ["test_*.py", "check_*.py"] python_classes = ["Test*", "Check*"] python_functions = ["test_*", "check_*"] ``` Полезное: - `pytest --collect-only` — показать, что нашлось, без запуска. Быстрый способ понять "почему мой тест не бежит". - Один файл: `pytest tests/test_x.py`. Один тест: `pytest tests/test_x.py::test_foo`. Один параметр: `pytest tests/test_x.py::test_foo[case-name]`. ### Сравнение float — `pytest.approx` `0.1 + 0.2 == 0.3` в Python — **False**: float хранится двоичной дробью, а 0.1 в неё точно не ложится. Прямое сравнение float через `==` в тестах — почти всегда баг, ждущий своего часа. ```{code-cell} python %%writefile /tmp/test_float.py import pytest def scale(x: float, factor: float) -> float: return x * factor def test_scale_exact_fails() -> None: # Не "иногда не сходится": 0.1 * 3 == 0.30000000000000004 на любой # машине. Точное сравнение float ломается детерминированно. assert scale(0.1, 3) != 0.3 # sic! def test_scale_approx() -> None: assert scale(0.1, 3) == pytest.approx(0.3) # по умолчанию rel=1e-6 assert scale(0.1, 3) == pytest.approx(0.3, rel=1e-9) # допуск в долях assert scale(0.1, 3) == pytest.approx(0.3, abs=1e-12) # допуск в единицах # Работает и для контейнеров: assert [0.1 + 0.2, 1.0 / 3] == pytest.approx([0.3, 0.333333], rel=1e-4) assert {"a": 0.1 + 0.2} == pytest.approx({"a": 0.3}) def test_rel_vs_abs() -> None: # rel — доля от ожидаемого: 2% от 100 это 2, от 1 это 0.02. assert 101 == pytest.approx(100, rel=0.02) assert 103 != pytest.approx(100, rel=0.02) # abs — фиксированная величина, масштаб не важен. assert 3 == pytest.approx(1, abs=2) # Около нуля rel бесполезен: rel * 0 == 0, любой допуск схлопывается. assert 1e-9 != pytest.approx(0, rel=0.01) assert 1e-9 == pytest.approx(0, abs=1e-6) # Заданы оба — достаточно, чтобы сошёлся любой. assert 104 == pytest.approx(100, rel=0.001, abs=5) ``` ```{code-cell} python !uv run pytest /tmp/test_float.py -v ``` Разница между `rel` и `abs` — в том, от чего считается допуск. `rel` задаёт его **долей от ожидаемого значения**: `rel=0.02` это 2%, и для 100 допуск получится 2, а для 1 — всего 0.02. `abs` задаёт допуск **в самих единицах**, одинаковый при любом масштабе. Когда заданы оба, достаточно, чтобы сошёлся любой из них. Практическое следствие — около нуля `rel` не работает вовсе: допуск считается как `rel * |ожидаемое|`, а у нуля это ноль. Сравниваешь с нулём — бери `abs`. ### Фикстуры (fixtures) — DI-механизм Тесту почти всегда нужно подготовленное состояние: временный каталог, разобранный конфиг, набор тестовых данных, запущенный процесс. Готовить его прямо в теле теста плохо по двум причинам. Код подготовки расползается копипастой по всем тестам — поменялся формат данных, правишь в двадцати местах. И уборка рано или поздно забывается: тест упал на середине, за собой не прибрал, следующий падает на чужом мусоре. Фикстура закрывает это сразу с трёх сторон: подготовку пишем один раз и просим по имени; уборка выполняется гарантированно, даже если тест упал; время жизни задаётся явно — дорогое поднимаем один раз, дешёвое пересоздаём на каждый тест. Про уборку и время жизни — дальше в этом разделе. И то, ради чего это названо DI: тест не знает, кто и как создаёт зависимость. Он объявляет имя, а подставить под него можно что угодно — словарь в памяти в юнит-тесте и настоящие файлы на диске в интеграционном, не трогая сам тест. Фикстура — функция, помеченная `@pytest.fixture`. Тесты просят её через параметр — pytest подставляет. ```{code-cell} python %%writefile /tmp/test_fixtures.py import pytest @pytest.fixture def user() -> dict[str, str]: print(" [setup] creating user") return {"name": "Ivan", "role": "student"} def test_user_name(user: dict[str, str]) -> None: assert user["name"] == "Ivan" def test_user_role(user: dict[str, str]) -> None: assert user["role"] == "student" ``` ```{code-cell} python !uv run pytest /tmp/test_fixtures.py -v -s ``` Заметь: `[setup]` печатается **дважды**. Фикстура со `scope="function"` (это значение по умолчанию) создаётся заново на каждый тест.
Термин: scope (время жизни фикстуры) Не область видимости, а как долго живёт один экземпляр и сколько тестов его переиспользуют: function (по умолчанию) — свой на каждый тест, class — на класс, module — на файл, package — на пакет, session — один на весь прогон. Видны же фикстуры одинаково — по месту объявления (тот же файл или conftest.py выше по дереву).
### Scope: function / class / module / session ```{code-cell} python %%writefile /tmp/test_scope.py import pytest @pytest.fixture(scope="module") def storage() -> dict[str, list[str]]: print(" [setup module] готовлю хранилище") return {"users": []} def test_add_user(storage: dict[str, list[str]]) -> None: storage["users"].append("alice") assert "alice" in storage["users"] def test_users_count(storage: dict[str, list[str]]) -> None: # Тесты делят состояние — предыдущий тест уже добавил alice assert len(storage["users"]) == 1 ``` ```{code-cell} python !uv run pytest /tmp/test_scope.py -v -s ``` `[setup module]` печатается один раз — фикстура пережила между тестами одного модуля. Сколько раз срабатывает каждый scope и как это выглядит вживую — в разделе «Разбираем на семинаре». Выбор зависит от двух вещей: сколько стоит подготовка и меняют ли её тесты. **`function`** — значение по умолчанию и почти всегда правильный ответ. Каждый тест получает свой экземпляр, порядок тестов не важен, сломать друг другу ничего нельзя. Менять стоит только когда есть причина. **`class`** — когда тесты внутри класса проверяют один и тот же готовый результат, только с разных сторон. Считаем его один раз на класс, а не на каждый тест. ```python class TestReport: @pytest.fixture(scope="class") def report(self) -> Report: return build_report(SAMPLE) # один разбор на весь класс def test_title(self, report: Report) -> None: ... def test_rows(self, report: Report) -> None: ... ``` **`module`** — дорогая подготовка, общая для всего файла: разобрать большой вход, сгенерировать набор данных, скомпилировать грамматику. **`session`** — один раз на весь прогон, обычно объявляется в `conftest.py`: распаковать архив, собрать бинарник, поднять процесс. ```python # conftest.py @pytest.fixture(scope="session") def corpus() -> list[str]: # 200 МБ: на каждый тест — минуты вместо секунд return Path("tests/data/corpus.txt").read_text().splitlines() ``` **`package`** — на пакет целиком, между `module` и `session`. Нужен редко.
Осторожно с session/module scope Экземпляр один на много тестов: что в нём поменял один тест, увидят все следующие. В демо выше test_add_user положил alice в общее хранилище, а test_users_count рассчитывает, что она там есть. Отсюда правило: длинный scope берут для ресурса, который дорого создавать и который никто не меняет. Если тесты в ресурс пишут — оставляй function.
Проверим — запустим второй тест отдельно, без первого. ```{code-cell} python !uv run pytest "/tmp/test_scope.py::test_users_count" -v || true ``` Тот же тест, что был зелёным в прогоне всего файла. Сам по себе он не работает: alice в хранилище кладёт сосед, и без него проверять нечего. ### Фикстура с teardown (yield) ```{code-cell} python %%writefile /tmp/test_teardown.py from collections.abc import Iterator from pathlib import Path import pytest @pytest.fixture def temp_file(tmp_path: Path) -> Iterator[Path]: f = tmp_path / "data.txt" f.write_text("hello") yield f print(f" [teardown] прибираю за {f.name}") f.unlink() # tmp_path убрал бы и сам, но нам нужен видимый teardown def test_read(temp_file: Path) -> None: assert temp_file.read_text() == "hello" ``` ```{code-cell} python !uv run pytest /tmp/test_teardown.py -v -s ``` `yield` разделяет setup и teardown. `tmp_path` — встроенная фикстура pytest. Teardown отработает и если тест упал, а вот если исключение случилось **до** `yield` — теста не будет вовсе, он развалится на стадии setup (`ERROR`, не `FAILED`). Флаг `-s` в ячейках выше нужен, чтобы pytest не перехватывал stdout и чтобы `print` из фикстуры был виден. ### `request` — контекст, в котором позвали фикстуру Фикстура может попросить `request` — встроенную фикстуру, через которую видно обстоятельства вызова. Что оттуда берут: - `request.node` — сам тест: имя, метки (`get_closest_marker`), `stash`; - `request.config` — конфиг прогона и опции командной строки; - `request.getfixturevalue("name")` — попросить другую фикстуру по имени прямо во время работы, а не через параметр; - `request.param` — значение, с которым pytest позвал **параметризованную** фикстуру. Последнее стоит отдельного слова. Параметризовать можно не только тест, но и фикстуру: даёшь ей `params=[...]`, и каждый зависящий от неё тест прогоняется столько раз, сколько там значений. ```{code-cell} python %%writefile /tmp/test_request.py import pytest @pytest.fixture(params=["json", "yaml"]) def fmt(request: pytest.FixtureRequest) -> str: return request.param @pytest.fixture def whoami(request: pytest.FixtureRequest) -> str: return request.node.name def test_dump(fmt: str, whoami: str) -> None: print(f" тест {whoami} работает с форматом {fmt}") assert fmt in {"json", "yaml"} ``` ```{code-cell} python !uv run pytest /tmp/test_request.py -v -s ``` Один тест в коде — два в отчёте, и значение параметра попало в id. Получается второй способ размножить тесты: `parametrize` размножает по данным, `params=` у фикстуры — по способу подготовки. Сам тест при этом не меняется и про размножение не знает. ### `parametrize` — базовый инструмент Одну и ту же проверку на десятке входов хочется свернуть в цикл: складываем кейсы в список и проходим `for`. Так можно — и работает это ровно до первой ошибки. ```{code-cell} python %%writefile /tmp/test_loop.py CASES = [(2, True), (3, True), (4, False), (17, True), (0, False), (1, False)] def is_prime(n: int) -> bool: return all(n % i != 0 for i in range(2, int(n**0.5) + 1)) def test_is_prime_loop() -> None: for n, expected in CASES: assert is_prime(n) == expected ``` ```{code-cell} python !uv run pytest /tmp/test_loop.py -v || true ``` Первый же упавший `assert` завершает функцию, поэтому до `n=1` проверка не дошла — есть там баг или нет, мы так и не узнали. В отчёте при этом один тест: `1 failed` выглядит одинаково и когда сломан один кейс, и когда сломаны все шесть. Отдельный кейс тоже не запустить: pytest про них ничего не знает, он видит только `test_is_prime_loop`. `parametrize` разворачивает тот же список в отдельные тесты. Каждый кейс pytest считает и запускает сам по себе. ```{code-cell} python %%writefile /tmp/test_parametrize.py import pytest def is_prime(n: int) -> bool: return all(n % i != 0 for i in range(2, int(n**0.5) + 1)) @pytest.mark.parametrize("n,expected", [ (2, True), (3, True), (4, False), (17, True), (0, False), (1, False), ]) def test_is_prime(n: int, expected: bool) -> None: assert is_prime(n) == expected ``` ```{code-cell} python !uv run pytest /tmp/test_parametrize.py -v || true ``` Баг тот же, а картина другая: видно сразу оба плохих входа, а не только первый по порядку. В квадратных скобках — id кейса, и по нему можно перезапускать один тест, пока чинишь: ```{code-cell} python !uv run pytest "/tmp/test_parametrize.py::test_is_prime[1-False]" -v || true ``` Чинится одной строчкой в начале `is_prime`: `if n < 2: return False`. ### monkeypatch Код то и дело обращается к тому, что в тесте не воспроизвести: случайные числа, текущее время, переменные окружения, сеть. Встроенная фикстура `monkeypatch` подменяет это на время одного теста, а после теста **сама возвращает как было** — тот же `yield`-teardown, только писать его не надо. ```{code-cell} python %%writefile /tmp/test_monkeypatch.py import os import random import pytest GREETINGS = ["привет", "здорово", "салют"] def pick_greeting() -> str: return random.choice(GREETINGS) def api_url() -> str: return os.environ.get("COURSE_API_URL", "http://localhost:8000") def test_greeting_is_deterministic(monkeypatch: pytest.MonkeyPatch) -> None: monkeypatch.setattr(random, "choice", lambda seq: seq[-1]) assert pick_greeting() == "салют" def test_api_url_from_env(monkeypatch: pytest.MonkeyPatch) -> None: monkeypatch.setenv("COURSE_API_URL", "http://test.local") assert api_url() == "http://test.local" def test_nothing_leaked() -> None: # Обе подмены откатились сами, ни строчки teardown. assert pick_greeting() in GREETINGS assert api_url() == "http://localhost:8000" ``` ```{code-cell} python !uv run pytest /tmp/test_monkeypatch.py -v ```
Термин: переменные окружения Набор пар "имя -> строка", который процесс получает от того, кто его запустил, и передаёт дальше своим дочерним процессам. В Python это os.environ — обычный словарь строк. Туда кладут то, что меняется от машины к машине и не должно лежать в коде: адрес сервиса, режим работы (DEBUG=1), токены. Снаружи задаются перед командой — COURSE_API_URL=http://test.local python3 app.py, — а в тесте их подменяет monkeypatch.setenv.
Кроме `setattr` и `setenv` есть `delattr`, `delenv`, `setitem`/`delitem` для словарей, `syspath_prepend` и `chdir`. Откатываются они так же. **Главная ловушка — подменять не там.** `monkeypatch.setattr(random, "choice", ...)` меняет атрибут у модуля `random`. А строчка `from random import choice` ещё при импорте завела в модуле `service` собственное имя `choice`, указывающее на ту же функцию. Дальше `service` зовёт своё имя и на `random` уже не смотрит: ```{code-cell} python %%writefile /tmp/service.py from random import choice GREETINGS = ["привет", "здорово", "салют"] def greet() -> str: return choice(GREETINGS) ``` ```{code-cell} python %%writefile /tmp/test_patch_target.py import random import pytest import service def test_patching_random_does_not_help(monkeypatch: pytest.MonkeyPatch) -> None: monkeypatch.setattr(random, "choice", lambda seq: "ЗАПАТЧЕНО") assert service.greet() == "ЗАПАТЧЕНО" def test_patch_where_the_name_is_used(monkeypatch: pytest.MonkeyPatch) -> None: monkeypatch.setattr(service, "choice", lambda seq: "ЗАПАТЧЕНО") assert service.greet() == "ЗАПАТЧЕНО" ``` ```{code-cell} python !uv run pytest /tmp/test_patch_target.py -v || true ``` Первый упал: в `service` лежит своя ссылка на исходный `choice`, и правка `random.choice` до неё не достаёт. Правило: **патчить там, где имя ищут**, а не там, где оно объявлено. Если бы `service` писал `import random` и звал `random.choice(...)`, ловушки бы не было — но и "оба варианта" всё равно не сработали бы. Подменять надо было бы `random.choice`: имя ищут в модуле `random` уже в момент вызова. А `monkeypatch.setattr(service, "choice", ...)` тогда упал бы с `AttributeError` — такого атрибута у `service` просто нет.
Много подмен — плохой знак Чтобы что-то подменить, тест должен знать, как код устроен внутри: что нужная функция называется choice и лежит именно в service. Переименовали её или перенесли в соседний модуль — тест упал, хотя снаружи программа работает ровно как раньше. Выходит, тест следит не за тем, что код делает, а за тем, как он написан.
Часто подмена и не нужна. Пусть функция не лезет за случайностью сама, а принимает её аргументом: ```{code-cell} python %%writefile /tmp/di_demo.py import random from collections.abc import Callable GREETINGS = ["привет", "здорово", "салют"] def greet_hardcoded() -> str: return random.choice(GREETINGS) # откуда случайность — решено внутри def greet(pick: Callable[[list[str]], str] = random.choice) -> str: return pick(GREETINGS) # откуда брать — решает вызывающий ``` ```{code-cell} python %%writefile /tmp/test_di_demo.py from di_demo import GREETINGS, greet def test_greet_is_predictable() -> None: assert greet(lambda seq: seq[-1]) == "салют" def test_greet_default_is_still_random() -> None: assert greet() in GREETINGS ``` ```{code-cell} python !uv run pytest /tmp/test_di_demo.py -v ``` Тест передаёт свою функцию выбора и получает предсказуемый ответ, ничего не зная про внутренности `greet`. Ни `monkeypatch`, ни знания, из какого модуля пришёл `choice`. Так же убирается время (`now` аргументом вместо `datetime.now()` внутри) и всё остальное неуправляемое. Приём тот же, что в начале лекции: зависимость не берут внутри, а передают снаружи. ### `conftest.py` — общие фикстуры и хуки `conftest.py` — специальный файл, который pytest ищет и подгружает сам, **без импорта**. Живёт в директории с тестами и действует на неё и все вложенные подкаталоги. В дереве может быть несколько `conftest.py`. Для **фикстур** побеждает ближайший к тесту — одноимённая фикстура снизу перекрывает верхнюю. А вот с **хуками** так не выйдет: pytest зовёт одноимённый хук из **каждого** подходящего `conftest.py`, ближний не отменяет верхний. **Что в него кладут:** **1. Общие фикстуры** — без импорта видны во всех `test_*.py` под этой директорией: ```{code-cell} python %%writefile /tmp/conftest_demo/conftest.py import shutil import tempfile from collections.abc import Iterator from pathlib import Path import pytest @pytest.fixture def sample_user() -> dict[str, str]: return {"id": "u1", "name": "Alice"} @pytest.fixture(scope="session") def workdir() -> Iterator[Path]: path = Path(tempfile.mkdtemp()) yield path shutil.rmtree(path) ``` Тест лежит рядом и ничего не импортирует — просто просит фикстуры по именам: ```{code-cell} python %%writefile /tmp/conftest_demo/test_users.py from pathlib import Path def test_user_has_name(sample_user: dict[str, str]) -> None: assert sample_user["name"] == "Alice" def test_workdir_is_writable(workdir: Path) -> None: (workdir / "a.txt").write_text("ok") assert (workdir / "a.txt").read_text() == "ok" ``` ```{code-cell} python !uv run pytest /tmp/conftest_demo -v ``` **2. Хуки** — точки расширения pytest'а. В примерах ниже мелькают marks (метки тестов) — про них следующий раздел.
Термин: хук (hook) Функция с зарезервированным именем (pytest_configure, pytest_collection_modifyitems, ...), которую в нужный момент зовёт сам pytest. Регистрировать ничего не надо: достаточно положить функцию с таким именем в conftest.py или в плагин — pytest найдёт её по имени. А вот опечатка обходится дорого: pytest_runtest_setupp — и прогон падает целиком, PluginValidationError: unknown hook, ни один тест не запускается. Молча пропадёт только функция, у которой сломан сам префикс pytest_.
```{code-cell} python %%writefile /tmp/hooks_demo/conftest.py import pytest def pytest_configure(config: pytest.Config) -> None: """Вызывается один раз при старте — до collection.""" config.addinivalue_line("markers", "slow: медленные тесты") def pytest_collection_modifyitems(items: list[pytest.Item]) -> None: """Пробегает по всем собранным тестам: можно навесить mark по имени файла, отсортировать их или отфильтровать.""" for item in items: if "integration" in str(item.path): item.add_marker(pytest.mark.slow) def pytest_runtest_setup(item: pytest.Item) -> None: """Вызывается перед каждым тестом — тут его можно и пропустить.""" if item.get_closest_marker("slow"): pytest.skip("slow выключены в этом прогоне") def pytest_runtest_call(item: pytest.Item) -> None: """Фаза прогона тела теста. Мы тут не вместо него, а вместе с ним.""" print(f" [call] начинается {item.name}") ``` Два теста, и ни один про хуки не знает: ```{code-cell} python %%writefile /tmp/hooks_demo/test_unit.py def test_add() -> None: print(" [тест] тело test_add") assert 2 + 2 == 4 ``` ```{code-cell} python %%writefile /tmp/hooks_demo/test_integration_api.py def test_api_roundtrip() -> None: assert True ``` ```{code-cell} python !uv run pytest /tmp/hooks_demo -v -rs -s ``` Имя файла попало в условие — тест получил метку `slow` и был пропущен, хотя в самом файле ни метки, ни `skip` нет. Флаг `-rs` печатает причину пропуска, `-s` не даёт прятать `print`. Обрати внимание на `pytest_runtest_call`. Своей реализацией мы тело теста не заменили: `[call]` напечаталось, а сразу за ним отработал и сам тест. Хуки не переопределяют друг друга — pytest зовёт их все, в том числе свой собственный, который и запускает тест. Видно только одну сторону: что было **до**. Чем кончился тест, такой хук не узнает — для этого нужна обёртка. Одного имени хватает, чтобы хук вызвался. Но иногда нужно не просто добавить свою реализацию, а обернуть остальные — выполнить код до и после и увидеть исход. Для этого есть декоратор `@pytest.hookimpl`; разбираем на семинаре. Полный список хуков — в [документации](https://docs.pytest.org/en/stable/reference/reference.html#hooks). Штатного способа спросить "а какие реализации этого хука сейчас есть" у pytest нет; `pytest --trace-config` покажет только, какие плагины и `conftest.py` вообще подхватились. **Правила:** - `conftest.py` **не** запускается как тест и **не** импортируется руками — pytest сам его подхватит. - Одна и та же фикстура, объявленная в двух conftest'ах на разных уровнях, — резолвится по ближайшему к тесту. - Общую подготовку (фикстуры и хуки) держи именно здесь, не дублируй по тест-файлам. ### Marks — метки тестов Mark — это метка/атрибут, которую вешаешь на тест-функцию (или на конкретный параметр в `parametrize`). Pytest их использует для двух вещей: **модификация поведения** (skip, xfail, timeout, ...) и **отбор** (`pytest -m slow` — запустить только тесты с меткой `slow`).
Термин: skip vs xfail
**Встроенные, самые важные:** ```{code-cell} python %%writefile /tmp/test_marks.py import sys import pytest @pytest.mark.skip(reason="возможность временно выключена") def test_disabled() -> None: assert False # не побежит, тест skipped @pytest.mark.skipif(sys.platform == "win32", reason="Unix-only") def test_unix_only() -> None: assert "/" in "/tmp" @pytest.mark.xfail(reason="известный баг") def test_known_bug() -> None: assert 1 + 1 == 3 # ожидаемо падает -> XFAIL (жёлтый), не роняет прогон @pytest.mark.xfail(strict=True, reason="если вдруг заработает — сигналим") def test_should_still_be_broken() -> None: assert 1 + 1 == 3 # если пройдёт при strict=True — прогон упадёт (XPASS) @pytest.mark.slow def test_full_dataset() -> None: # долгий тест — можно исключить: pytest -m "not slow" assert sum(range(10_000)) == 49_995_000 ``` ```{code-cell} python !uv run pytest /tmp/test_marks.py -v ``` **Кастомные marks** (`slow`, `integration`, `network` и т.п.) надо объявить — иначе pytest выдаёт `PytestUnknownMarkWarning`. Два способа: **1. Декларативно, в `pyproject.toml`:** ```toml [tool.pytest.ini_options] markers = [ "slow: медленные тесты (исключаются в PR)", "integration: требуют внешний сервис", ] ``` **2. Императивно, в `conftest.py`** — тот самый `pytest_configure`, если нужна логика (условия, генерация): ```python def pytest_configure(config: pytest.Config) -> None: config.addinivalue_line("markers", "slow: медленные тесты (исключаются в PR)") config.addinivalue_line("markers", "integration: требуют внешний сервис") ``` Форматы эквивалентны. Первый — когда список статичный. Второй — когда marks добавляет плагин или их набор зависит от окружения. Тогда селекция работает: ```bash pytest -m slow # только slow pytest -m "not slow" # все кроме slow pytest -m "slow and not integration" ``` Посмотреть все зарегистрированные marks — `pytest --markers`. ### Marks с аргументами Метка — не только флаг: ей можно передать данные, а потом прочитать их из хука. На этом держатся плагины вроде `pytest-timeout` (`@pytest.mark.timeout(5)`) — и задача, которая ждёт тебя после лекции. ```{code-cell} python %%writefile /tmp/marks_args_demo/conftest.py import pytest def pytest_configure(config: pytest.Config) -> None: config.addinivalue_line("markers", "budget(ms, *, strict=False): бюджет теста") def pytest_runtest_call(item: pytest.Item) -> None: for marker in item.iter_markers("budget"): print(f" [{item.name}] args={marker.args} kwargs={marker.kwargs}") closest = item.get_closest_marker("budget") print(f" [{item.name}] ближайший: {closest.args if closest else None}") ``` ```{code-cell} python %%writefile /tmp/marks_args_demo/test_budget.py import pytest @pytest.mark.budget(100) def test_one() -> None: assert True @pytest.mark.budget(500, strict=True) @pytest.mark.budget(100) def test_two() -> None: assert True ``` ```{code-cell} python !uv run pytest /tmp/marks_args_demo -q -s ``` Что видно в выводе. Позиционные аргументы метки лежат в `marker.args`, именованные — в `marker.kwargs`. Меток с одним именем на тесте может быть несколько, и `item.iter_markers("budget")` отдаёт **все**. А `item.get_closest_marker("budget")` отдаёт только одну — ближайшую к функции, то есть **нижний** декоратор (в выводе это `(100,)`, хотя сверху написано `500`). Разница неочевидная и стоит дорого: возьмёшь `get_closest_marker` там, где нужны все метки, — часть проверок просто не выполнится, и тест будет зелёным зря. ### `parametrize` с ids и marks ```{code-cell} python %%writefile /tmp/test_parametrize_advanced.py import pytest def divide(a: int, b: int) -> float: return a / b @pytest.mark.parametrize("a,b,expected", [ pytest.param(10, 2, 5.0, id="int-int"), pytest.param(10, 3, 3.33, id="int-frac", marks=pytest.mark.xfail), pytest.param(-6, 2, -3.0, id="neg"), ]) def test_divide(a: int, b: int, expected: float) -> None: assert abs(divide(a, b) - expected) < 0.001 # То же самое, но имена кейсов заданы списком на весь набор @pytest.mark.parametrize( "a,b,expected", [(10, 2, 5.0), (9, 3, 3.0), (-6, 2, -3.0)], ids=["exact", "whole", "negative"], ) def test_divide_ids(a: int, b: int, expected: float) -> None: assert divide(a, b) == pytest.approx(expected) ``` ```{code-cell} python !uv run pytest /tmp/test_parametrize_advanced.py -v ``` Два способа назвать кейсы. `id=` у `pytest.param` — имя рядом с самими данными; `ids=[...]` у `parametrize` — список имён на весь набор, по порядку. В выводе они неразличимы: `test_divide[int-frac]` и `test_divide_ids[whole]`, и по любому из них запускается один кейс. `marks=` работает только в первом виде — метка вешается на конкретный `pytest.param`: `int-frac` ожидаемо не сходится с точностью 0.001 и даёт `XFAIL`, прогон остаётся зелёным. ### Плагины Ключевые: - **`pytest-mock`** — обёртка над `unittest.mock`, даёт фикстуру `mocker`. - **`pytest-xdist`** — параллельный запуск (`-n auto`). Он заметно меняет поведение фикстур с длинным scope — это на семинаре. - **`pytest-cov`** — coverage. - **`pytest-benchmark`** — микробенчмарки и отлов регрессий по скорости; разберём дальше в курсе, вместе с профилированием. - **`pytest-timeout`** — таймауты, чтобы зависший тест не блокировал CI. - **`pytest-asyncio`** — тесты для async-функций (`async def test_...`) — подробно дальше в курсе, там, где `asyncio`.
Термин: регрессия Поломка того, что раньше работало. Отсюда регрессионный тест — тест, который фиксирует уже починенный баг, чтобы тот не вернулся незамеченным. Регрессия по скорости — тот же случай, но про время: код остался правильным, а работать стал медленнее. Сама по себе она не видна — нужен сохранённый замер прошлого прогона, с которым сравнивают текущий.
Термин: профилирование Измерение того, куда программа тратит время (или память): какие функции вызывались, сколько раз, сколько заняли. Бенчмарк отвечает на вопрос "сколько всего" и даёт одно число; профилировщик отвечает "где именно" и даёт разбивку по коду. Первое говорит, что стало хуже, второе — из-за чего.
Пример `pytest-mock`: ```{code-cell} python %%writefile /tmp/test_mock.py from collections.abc import Callable from pytest_mock import MockerFixture def get_user_age(fetch_user: Callable[[int], dict[str, int]], user_id: int) -> int: data = fetch_user(user_id) return data["age"] def test_get_user_age(mocker: MockerFixture) -> None: fake_fetch = mocker.Mock(return_value={"age": 30}) age = get_user_age(fake_fetch, 42) assert age == 30 fake_fetch.assert_called_once_with(42) ``` ```{code-cell} python !uv run pytest /tmp/test_mock.py -v 2>&1 | head -20 ``` Обрати внимание: `pytest-mock` мы нигде не подключали — поставили пакет, и фикстура `mocker` просто оказалась в тесте. Установленный плагин pytest находит сам, по записи в метаданных пакета; как выглядит эта запись — на семинаре, когда будем паковать свой плагин. Объявлять приходится только то, что пакетом не поставлено: например модуль с общими фикстурами, который просто лежит в репозитории. Такой подключают из `conftest.py` списком `pytest_plugins`: ```python # conftest.py на верху репо pytest_plugins = ["my_project.fixtures.files"] ``` А сам `conftest.py` — тоже плагин, только локальный: грузится без объявления и действует лишь внутри своего каталога. Плагин не обязан жить в `conftest.py`. Его можно упаковать в wheel, и тогда pytest найдёт его сам, без единой строчки подключения, — по записи в метаданных пакета. Плюс к этому у фикстуры и хука есть штатный способ обменяться данными, `Stash`. И то и другое понадобится в задаче — разбираем на семинаре. ## 2. Coverage: что мерить, что не мерить **Что такое coverage.** Процент строк кода, покрытых тестами. Инструмент: `coverage.py` (или `pytest-cov` как обёртка). Три метрики: - **Line coverage** — сколько строк выполнилось. - **Branch coverage** — каждый `if` и `for` — обе ветки покрыты. - **Path coverage** — все комбинации веток. Branch coverage строже: считает не строки, а переходы между ними. Классическая дыра line coverage — `if` **без** `else`: тест заходит внутрь, все строки выполнены, line рисует 100%, а путь "условие ложно" не проверен ни разу — отдельной строки под него нет, пометить нечего. `--cov-branch` такой переход видит и пишет явно (`2->4` в колонке Missing). Включай всегда — стоит дёшево, ловит целый класс дыр. Пример: ```{code-cell} python %%writefile /tmp/mylib.py def clamp(x: int, lo: int, hi: int) -> int: if x < lo: return lo if x > hi: return hi return x ``` ```{code-cell} python %%writefile /tmp/test_mylib.py from mylib import clamp def test_clamp_low() -> None: assert clamp(-5, 0, 10) == 0 def test_clamp_mid() -> None: assert clamp(5, 0, 10) == 5 ``` ```{code-cell} python !uv run pytest /tmp/test_mylib.py --cov=mylib --cov-branch --cov-report=term-missing 2>&1 | tail -15 ``` В колонке `Missing` — номера строк, до которых тесты не добрались. Здесь это строка 5, то есть `return hi`: верхнюю границу мы не проверили ни разу. Соседние колонки: `Stmts` — сколько всего строк с кодом, `Miss` — сколько из них пропущено. `Branch` — сколько всего переходов по ветвлениям, `BrPart` — сколько ветвлений прошли только в одну сторону. Обрати внимание: ветвление внутри кода, который не выполнялся вовсе, в `BrPart` не попадёт — его строки уйдут в `Miss`. А вот случай, ради которого `--cov-branch` и включают: `if` без `else`, и тест заходит внутрь. ```{code-cell} python %%writefile /tmp/greeting.py def greeting(name: str) -> str: if not name: name = "аноним" return f"Привет, {name}!" ``` ```{code-cell} python %%writefile /tmp/test_greeting.py from greeting import greeting def test_empty_name() -> None: assert greeting("") == "Привет, аноним!" ``` ```{code-cell} python !uv run pytest /tmp/test_greeting.py --cov=greeting --cov-report=term-missing 2>&1 | tail -8 ``` `100%`, пропущенных строк нет — и это правда: все четыре строки выполнились. Только вариант "имя не пустое" не проверен ни разу. Добавим `--cov-branch`: ```{code-cell} python !uv run pytest /tmp/test_greeting.py --cov=greeting --cov-branch --cov-report=term-missing 2>&1 | tail -8 ``` `83%` и `2->4` в `Missing`: переход со строки 2 сразу на строку 4, минуя тело `if`, не случился ни разу. Отдельной строки под него нет, поэтому line coverage его и не заметил. Читать такие отчёты в консоли быстро надоедает: номера строк надо сопоставлять с кодом глазами. Для этого есть HTML-отчёт — `--cov-report=html`: ```{code-cell} python !uv run pytest /tmp/test_greeting.py --cov=greeting --cov-branch --cov-report=html:/tmp/htmlcov 2>&1 | tail -3 ``` ```{code-cell} python !ls /tmp/htmlcov ``` `index.html` открывается обычным браузером — там сводка по файлам и раскрашенный исходник. **Правила coverage:** - **100% != хорошие тесты.** Можно покрыть все строки бесполезными ассертами. - **branch > line** — включай `--cov-branch` всегда. - **Не гоняйся за 100%.** Иногда 85% с хорошими тестами лучше, чем 100% с шаблонными. - **Используй как сигнал**: резкое падение % при изменении кода — насторожись. ### Про TDD (и почему он тут) Отдельная культура — писать тест **до** реализации (Test-Driven Development). Идея: тест сначала краснеет, потом ты пишешь минимум кода, чтобы он зазеленел, потом рефакторишь. Роберт Мартин ("Uncle Bob") формализовал это как **три закона TDD** — см. его пост [The Cycles of TDD](http://blog.cleancoder.com/uncle-bob/2014/12/17/TheCyclesOfTDD.html) на Clean Coder Blog. Оригинальная книга — Kent Beck, *Test-Driven Development: By Example* (2002); практическая — Роберт Мартин, *Clean Code* (2008) и *Clean Coder* (2011). --- ## 3. logging ### Зачем логгер, а не print `print` пишет всегда, всем и в одно место. Этого хватает, пока код твой и запускается руками. Дальше выясняется, что вывод нужен разный: разработчику — подробный, в проде — только ошибки, тестам — никакой, а куда писать (консоль, файл) зависит от того, где код запустили. Логгер разделяет два решения, которые `print` склеивает в одно: **что записать** решает автор кода, **что из этого показать и куда** — тот, кто его запускает. Библиотека пишет `logger.info(...)` и ничего не знает про stdout и файлы; приложение один раз настраивает порог и назначение в точке входа, не трогая чужой код. ```{code-cell} python %%writefile /tmp/noisy_lib.py import logging logger = logging.getLogger(__name__) def fetch(url: str) -> str: print(f"[print] качаю {url}") logger.info("качаю %s", url) return "ok" ``` Приложение, которое просто зовёт библиотеку и ничего не настраивает: ```{code-cell} python %%writefile /tmp/app_plain.py import noisy_lib noisy_lib.fetch("https://example.com") ``` ```{code-cell} python !uv run python /tmp/app_plain.py 2>&1 ``` Тот же вызов, но теперь приложение включило логи: ```{code-cell} python %%writefile /tmp/app_logging.py import logging import noisy_lib logging.basicConfig(level=logging.INFO, format="[%(levelname)s] %(name)s: %(message)s") noisy_lib.fetch("https://example.com") ``` ```{code-cell} python !uv run python /tmp/app_logging.py 2>&1 ``` `print` вылез оба раза — отключить его снаружи нельзя никак, только править чужой исходник. `logger.info` в первом случае промолчал, во втором сказал то же самое, но с уровнем, именем модуля и в нужном формате. Автор библиотеки не выбирал ни то, ни другое — выбрал тот, кто запускает. Плюс к этому логгер бесплатно кладёт в запись время, уровень, модуль, строку и поток — с `print` это пишется руками в каждом вызове и всё равно разъезжается. ### Базовое использование ```{code-cell} python %%writefile /tmp/logging_basic.py import logging # Настраиваем минимальную конфигурацию logging.basicConfig( level=logging.DEBUG, format="%(asctime)s [%(levelname)s] %(name)s: %(message)s", ) logger = logging.getLogger(__name__) logger.debug("debug msg") logger.info("info msg") logger.warning("warning msg") logger.error("error msg") ``` ```{code-cell} python !uv run python /tmp/logging_basic.py 2>&1 ``` Отдельно про **корневой логгер** (root). Это логгер без имени — тот, что возвращает `logging.getLogger()` без аргумента. Он предок всех остальных, и модульные функции `logging.info(...)`, `logging.warning(...)` пишут именно в него. ```{code-cell} python %%writefile /tmp/root_demo.py import logging root = logging.getLogger() # без имени — это и есть корневой app = logging.getLogger("myapp") print("имя корневого :", repr(root.name), flush=True) print("родитель myapp :", app.parent is root, flush=True) print("getLogger() дважды :", logging.getLogger() is root, flush=True) logging.basicConfig(level=logging.INFO, format="[%(levelname)s] %(name)s: %(message)s") logging.info("модульная функция пишет прямо в корневой") app.info("а это myapp — но печатает его хендлер корневого") ``` ```{code-cell} python !uv run python /tmp/root_demo.py 2>&1 ``` Настраивают почти всегда именно корневой: хендлер, повешенный на него, ловит записи всех логгеров приложения и библиотек разом. А писать в него не надо — по имени `root` в логе не понять, кто это сказал. **Правила:** - **Всегда** `logger = getLogger(__name__)`, никогда не корневой. Настраивать корневой (через `basicConfig`/`dictConfig`) — можно и нужно, но только в точке входа приложения; писать в него — нет. - **Никогда** `print` в коде библиотеки. - Уровень — строго по семантике (см. ниже). ### Уровни: когда какой Уровней пять, а методов на них шесть: `logger.debug()`, `.info()`, `.warning()`, `.error()`, `.critical()` и `.exception()` (последний — особый, разберём ниже). Плюс есть `logger.log(level, ...)`, который принимает уровень аргументом, — он нужен, когда уровень вычисляется. Сами уровни, от низшего к высшему: | Уровень | Числовое | Когда используется | |---|---|---| | `DEBUG` | 10 | Подробности, интересные только при диагностике проблем. | | `INFO` | 20 | Для подтверждения того, что всё работает как запланировано. | | `WARNING` | 30 | Случилось неожиданное, или поломка возможна в ближайшем будущем — но программа всё ещё работает как задумано. | | `ERROR` | 40 | Для серьёзных ошибок, из-за которых программа теряет часть функциональности. | | `CRITICAL` | 50 | Серьёзная ошибка: возможно, программа не сможет продолжить работу. | Стандартный уровень (если ничего не настраивать) — **`WARNING`**, и порог этот стоит в двух местах: на самом логгере и на хендлере. Одного `logger.setLevel(DEBUG)` поэтому мало — без настроенных хендлеров запись уходит в `logging.lastResort`, а у него уровень тоже `WARNING`, и DEBUG молча пропадёт. Рабочий способ — `basicConfig(level=...)`, он ставит хендлер и поднимает уровень root разом. ```{code-cell} python %%writefile /tmp/logging_levels.py import logging logging.basicConfig(format="[%(levelname)s] %(message)s") logger = logging.getLogger(__name__) logger.debug("не увидим — уровень root по умолчанию WARNING") logger.warning("увидим") logger.log(logging.INFO, "через logger.log()") # Свои числовые уровни: между стандартными или ниже всех. TRACE = 5 logging.addLevelName(TRACE, "TRACE") logger.setLevel(TRACE) logger.log(TRACE, "ниже DEBUG") ``` ```{code-cell} python !uv run python /tmp/logging_levels.py 2>&1 ``` ### `logger.exception()` vs `logger.error(exc)` `logger.exception(msg)` — то же, что `logger.error(msg, exc_info=True)`. Добавляет traceback текущего активного исключения. Вызывать **только** внутри `except` — иначе `exc_info` пустой. ```{code-cell} python %%writefile /tmp/logging_exception.py import logging logging.basicConfig(format="[%(levelname)s] %(message)s") logger = logging.getLogger(__name__) def divide(a: int, b: int) -> float | None: try: return a / b except ZeroDivisionError: # ПЛОХО: только сообщение, traceback теряется, отладка мучительна. # logger.error(f"division failed: {exc}") # ХОРОШО: сообщение + полный traceback + тип исключения. logger.exception("division failed") return None divide(10, 0) ``` ```{code-cell} python !uv run python /tmp/logging_exception.py 2>&1 ``` `str(exc)` теряет контекст кадра: где именно упало и какие там были переменные. Разбирать поломку потом придётся по логу, воспроизвести её может и не получиться — а `logger.error(f"failed: {exc}")` даёт "failed: division by zero" без единой подсказки, где искать. `logger.exception` даёт полный traceback. ### Иерархия логгеров Логгеры образуют дерево через `.` в имени. `myapp` — родитель `myapp.api`, тот — родитель `myapp.api.client`. ```{code-cell} python %%writefile /tmp/logging_hierarchy.py import logging logging.basicConfig(level=logging.INFO, format="%(name)s: %(message)s") app = logging.getLogger("myapp") api = logging.getLogger("myapp.api") client = logging.getLogger("myapp.api.client") # Настраиваем вершину поддерева myapp (настоящий root logger — это # logging.getLogger() без имени, его тут трогает только basicConfig) app.setLevel(logging.WARNING) # Дочерние наследуют: своего уровня у них нет, берётся ближайший заданный выше app.info("app info") # < WARNING, пропускается api.warning("api warning") # OK client.error("client error") # OK ``` ```{code-cell} python !uv run python /tmp/logging_hierarchy.py 2>&1 ``` ### Handlers, Filters, Formatters
Термин: LogRecord Одна запись в логе как объект. Логгер не печатает строку сразу — он собирает LogRecord со всем контекстом (сообщение, уровень, имя логгера, файл, строка, время, поток) и передаёт дальше по конвейеру. Строкой запись становится только в самом конце, в Formatter.
Поймаем такую запись своим хендлером и посмотрим, что внутри: ```{code-cell} python import logging captured: list[logging.LogRecord] = [] class Capture(logging.Handler): def emit(self, record: logging.LogRecord) -> None: captured.append(record) logger = logging.getLogger("myapp.api") logger.setLevel(logging.INFO) logger.addHandler(Capture()) logger.warning("slow request: %s", "GET /users") rec = captured[0] print("msg :", repr(rec.msg), "| args:", rec.args) print("getMessage:", rec.getMessage()) print("поля :", sorted(vars(rec))) ``` Два вывода отсюда. Первый: подстановка аргументов отложена — в записи лежат отдельно шаблон `msg` и `args`, а склеиваются они только в `getMessage()`. Именно поэтому `logger.info("user %s", uid)` дешевле f-строки: если запись до хендлера не дойдёт, склейки не будет вовсе. Второй: имена в строке формата — это имена атрибутов записи. `%(levelname)s` и `%(name)s` берут `rec.levelname` и `rec.name` напрямую. Но не все: в списке полей выше нет ни `message`, ни `asctime` — их создаёт уже Formatter, из `msg`/`args` и из `created` соответственно. Свои поля тоже можно класть — через `logger.info(..., extra={"user_id": 42})`. Логика конвейера: ``` logger.info("...") 1. logger.isEnabledFor(INFO) -- уровень этого логгера (унаследованный, если свой не задан). Не прошло -> выходим, LogRecord даже не создаётся 2. создаётся LogRecord 3. фильтры самого логгера 4. идём по цепочке "логгер -> его предки" и для каждого его handlers: handler.level -- уровень предка НЕ проверяется, только хендлера фильтры хендлера Formatter -> строка handler.emit(record) -- пишет в stderr/файл/сеть подъём по предкам прекращается, если у логгера propagate = False ``` Handler — куда пишем (`StreamHandler`, `FileHandler`, `RotatingFileHandler`, `SysLogHandler`, ...). `StreamHandler` по умолчанию пишет в **stderr** — поэтому в ячейках этого раздела стоит `2>&1`. Filter — решает, пропускать ли запись дальше: вернул истину — идёт, ложь — запись выброшена. И заодно может её **править**, прямо по месту: дописать поле, замазать секрет в сообщении. Второе на практике встречается чаще первого. Formatter — как из LogRecord сделать текст.
Термин: propagate Флаг логгера (по умолчанию True): отдавать ли запись хендлерам предков. Именно из-за него myapp.api печатается через хендлер, настроенный на root, хотя своих хендлеров у него нет. Ставят False, когда у логгера есть собственный вывод и дублировать его в общий не надо, — как в dictConfig ниже.
### `dictConfig` — правильный способ Не собирать логгеры императивно в коде. Один раз на старте приложения: ```{code-cell} python %%writefile /tmp/logging_dictconfig.py import logging.config CONFIG = { # Версия схемы конфига. Всегда 1, других значений пока не бывает. "version": 1, # True (это значение по умолчанию!) выключил бы все созданные до вызова # логгеры, кроме перечисленных ниже и их потомков. Библиотеки заводят свои # на импорте, и в нашем конфиге их нет, — значит выключило бы. Поэтому False. "disable_existing_loggers": False, # Форматтеры — рецепты, как превратить запись в строку. Объявляем их # с именами, чтобы ниже сослаться по имени. "formatters": { "verbose": { # %-шаблон по атрибутам LogRecord "format": "%(asctime)s [%(levelname)s] %(name)s: %(message)s", }, "json": { "format": '{"time": "%(asctime)s", "level": "%(levelname)s", "logger": "%(name)s", "msg": "%(message)s"}', }, }, # Хендлеры — куда писать. Тоже именованные. "handlers": { "console": { "class": "logging.StreamHandler", # что импортировать и создать "level": "INFO", # свой порог, поверх порога логгера "formatter": "verbose", # имя из formatters выше }, "file": { "class": "logging.FileHandler", # всё лишнее уходит в конструктор хендлера как аргументы "filename": "/tmp/app.log", "mode": "w", # по умолчанию "a" — файл рос бы между прогонами "level": "DEBUG", "formatter": "json", }, }, # Настройки конкретных логгеров, по имени. Корневой настраивается # отдельным ключом "root" рядом с "loggers". "loggers": { "myapp": { "level": "DEBUG", # порог самого логгера "handlers": ["console", "file"], # имена из handlers выше "propagate": False, # запись не уходит наверх, к root }, }, } logging.config.dictConfig(CONFIG) log = logging.getLogger("myapp") log.debug("only in file") log.info("in console AND file") ``` ```{code-cell} python !uv run python /tmp/logging_dictconfig.py 2>&1 ``` В консоль ушло только то, что `INFO` и выше. А в файле — оба сообщения, и в другом формате: ```{code-cell} python !cat /tmp/app.log ```
Такой "json" — не JSON Формат собран %-подстановкой, которая ничего не экранирует. Сообщение с кавычкой или переводом строки (log.info('user said "hi"')) порвёт результат, и парсер на той стороне подавится. Для настоящего JSON нужен форматтер, который сериализует поля, — об этом следующий раздел.
--- ## 4. structlog — structured logs ### Проблема с текстовыми логами `logger.info("user 42 did login from 1.2.3.4")` — читаемо человеком, но: - Не парсится инструментами. - Не отфильтровать по полю: "покажи всё, что было с user 42". - Не агрегируется ("сколько раз user 42 логинился"). Решение — **структурированные** логи (JSON или key=value), где поля явные. ### structlog: простой пример ```{code-cell} python %%writefile /tmp/structlog_basic.py import structlog structlog.configure( processors=[ structlog.processors.add_log_level, structlog.processors.TimeStamper(fmt="iso"), structlog.processors.JSONRenderer(), ], ) log = structlog.get_logger() log.info("user_login", user_id=42, ip="1.2.3.4") log.warning("slow_request", path="/users", duration_ms=1200) ``` ```{code-cell} python !uv run python /tmp/structlog_basic.py 2>&1 ``` Каждая строка — валидный JSON: такие логи уже можно не читать глазами, а разбирать программой. ### Context binding ```{code-cell} python %%writefile /tmp/structlog_bind.py import structlog structlog.configure(processors=[ structlog.processors.add_log_level, structlog.processors.JSONRenderer(), ]) log = structlog.get_logger() # bind — привязывает контекст к логгеру, копия request_log = log.bind(request_id="req-abc", user_id=42) request_log.info("processing_start") request_log.info("cache_miss", key="user:42") request_log.info("processing_done", duration_ms=15) ``` ```{code-cell} python !uv run python /tmp/structlog_bind.py 2>&1 ``` Все три сообщения автоматически содержат `request_id` и `user_id`. Не нужно передавать их вручную в каждый `log.info`. Логгер с привязанным контекстом всё равно надо передавать дальше руками. От этого избавляет `structlog.contextvars` — значение кладётся один раз и само подхватывается во всех записях ниже по стеку. Разбираем на семинаре. ## Разбираем на семинаре Дальше — то, без чего основная нить обходится, но что стоит увидеть: обёртки вокруг хуков, scope во всех четырёх видах, параллельный прогон и его влияние на фикстуры, `Stash` и упаковка плагина в wheel, контекст логов через `contextvars`. Первое, `Stash` и wheel понадобятся в задаче. Читать можно и сейчас, и когда упрёшься. ### `@pytest.hookimpl` — обёртки вокруг хуков Один и тот же хук обычно объявлен не в одном месте: у тебя в `conftest.py`, в `conftest.py` выше по дереву, в каждом установленном плагине и в самом pytest. Все эти реализации выстраиваются в ряд, и pytest зовёт их по очереди. Декоратор `@pytest.hookimpl` нужен, когда важно, где в этом ряду стоишь ты. `tryfirst=True` и `trylast=True` просто двигают тебя в начало или в конец ряда. `wrapper=True` — другое. Твоя функция перестаёт быть одним из вызовов в ряду и становится обёрткой вокруг всех остальных. Пишут её генератором: - код до `yield` выполняется **перед** остальными реализациями хука; - на `yield` управление уходит к ним — для `pytest_runtest_call` это и есть запуск тела теста; - код после `yield` выполняется **после**, когда уже известно, чем дело кончилось. Исход приходит прямо в `yield`: тест прошёл — `yield` вернёт результат, тест упал — `yield` бросит то самое исключение, как будто оно случилось на этой строке. Имя `pytest_runtest_call` не выдумано: как у любого хука, оно зарезервировано и означает конкретный момент прогона — фазу, в которой выполняется тело теста. Рядом живут `pytest_runtest_setup` (тот самый, что выше пропускал тесты) и `pytest_runtest_teardown`, а `pytest_runtest_protocol` охватывает все три фазы разом. То есть выбираешь не имя, а момент — имя следует за ним. И `wrapper=True` работает с любым хуком, не только с `pytest_runtest_call`. Ниже обёрнуты сразу два: `pytest_runtest_setup` покажет изнутри, как отрабатывают фикстуры, а `pytest_runtest_call` — как выполняется тело теста. ```{code-cell} python %%writefile /tmp/hookimpl_demo/conftest.py import pytest @pytest.hookimpl(wrapper=True) def pytest_runtest_setup(item: pytest.Item): print(f"[setup] готовим {item.name}") result = yield # здесь отрабатывают фикстуры print(f"[setup] {item.name} готов") return result @pytest.hookimpl(wrapper=True) def pytest_runtest_call(item: pytest.Item): print(f"[call] до {item.name}") try: result = yield # здесь выполняется тело теста except Exception as exc: print(f"[call] {item.name} упал: {type(exc).__name__}") raise print(f"[call] {item.name} прошёл") return result ``` ```{code-cell} python %%writefile /tmp/hookimpl_demo/test_two.py import pytest @pytest.fixture def prepared() -> str: print(" [fixture] готовлю данные") return "ok" def test_ok(prepared: str) -> None: assert prepared == "ok" def test_broken() -> None: assert 2 + 2 == 5 ``` ```{code-cell} python !uv run pytest /tmp/hookimpl_demo -q -s || true ``` Видно, что обёртки охватывают именно свои фазы: `[fixture]` напечаталось внутри `[setup]`, а тело теста — между строчками `[call]`. И видно исход: `test_broken` пришёл в обёртку исключением — это и есть то, ради чего её берут. Два правила. Результат обязательно вернуть (`return result`), иначе pytest получит `None`. И если перехватил исключение — пробросить дальше (`raise`), иначе упавший тест молча станет зелёным. Две таких обёртки в одном файле не сделать: это обычная функция, и второе `def` с тем же именем просто затрёт первое. А в разных местах — сколько угодно: pytest зовёт все реализации, и обёртки вкладываются одна в другую, причём ближний к тесту `conftest.py` оказывается снаружи. Положим по обёртке в два `conftest.py`, вложенных один в другой: ```{code-cell} python %%writefile /tmp/twohooks_demo/conftest.py import pytest @pytest.hookimpl(wrapper=True) def pytest_runtest_call(item: pytest.Item): print(" [верхний] до") result = yield print(" [верхний] после") return result ``` ```{code-cell} python %%writefile /tmp/twohooks_demo/sub/conftest.py import pytest @pytest.hookimpl(wrapper=True) def pytest_runtest_call(item: pytest.Item): print(" [нижний] до") result = yield print(" [нижний] после") return result ``` ```{code-cell} python %%writefile /tmp/twohooks_demo/sub/test_x.py def test_one() -> None: print(" [тест] тело") assert True ``` ```{code-cell} python !uv run pytest /tmp/twohooks_demo -q -s ``` Обе сработали, и обёртки вложились друг в друга: ближний к тесту `conftest.py` оказался снаружи, верхний — внутри, тело теста в самой середине. Если две разных обёртки нужны именно в одном месте, выбор простой: либо одна функция, делающая оба дела, либо два отдельных модуля-плагина. ### Scope во всех четырёх видах Одна фикстура на каждый scope, все `autouse`, чтобы не загромождать сигнатуры тестов. `autouse=True` означает, что фикстура применяется ко всем тестам и просить её параметром не надо. ```{code-cell} python %%writefile /tmp/test_scopes.py import pytest @pytest.fixture(scope="session", autouse=True) def per_session() -> None: print("\n [session]") @pytest.fixture(scope="module", autouse=True) def per_module() -> None: print(" [module]") @pytest.fixture(scope="class", autouse=True) def per_class() -> None: print(" [class]") @pytest.fixture(autouse=True) def per_function() -> None: print(" [function]") class TestParse: def test_title(self) -> None: assert True def test_body(self) -> None: assert True class TestRender: def test_html(self) -> None: assert True def test_text(self) -> None: assert True ``` ```{code-cell} python !uv run pytest /tmp/test_scopes.py -v -s ``` Четыре теста в двух классах одного файла: `session` сработал один раз, `module` — один, `class` — два, `function` — четыре. ### Параллельный прогон и scope `pytest-xdist` раскидывает тесты по нескольким процессам: `pytest -n 2` — два воркера, `-n auto` — по числу ядер. Воркер — это отдельный процесс: свой импорт, своя память, своя сессия pytest. Объекты фикстур между процессами не ездят. Отсюда поправка к разделу про scope: он означает "не чаще одного раза", а не "ровно один раз за прогон". Единица переиспользования — воркер. ```{code-cell} python %%writefile /tmp/test_xdist_scope.py import os import uuid import pytest @pytest.fixture(scope="session") def token() -> str: value = uuid.uuid4().hex[:6] print(f"[session setup] token={value} pid={os.getpid()}") return value @pytest.mark.parametrize("i", range(4)) def test_uses_token(i: int, token: str, worker_id: str) -> None: print(f"test{i}: worker={worker_id} pid={os.getpid()} token={token}") ``` ```{code-cell} python !uv run pytest /tmp/test_xdist_scope.py -q -rP ``` Один setup, один pid, один и тот же `token` во всех четырёх тестах. `worker_id` — фикстура из xdist, без параллели она отдаёт `master`. Флаг `-rP` печатает вывод прошедших тестов, иначе pytest его прячет. Теперь то же самое в два процесса: ```{code-cell} python !uv run pytest /tmp/test_xdist_scope.py -q -n 2 -rP ``` Два setup'а, два pid, два разных `token` — при том же `scope="session"`. Столько же раз отработал бы и teardown. Пока это только цена: дорогую подготовку оплачиваем не один раз, а по разу на воркер. Хуже с тестами, которые передают состояние друг другу. Вернём тот файл из раздела про scope и запустим его в два процесса: ```{code-cell} python !uv run pytest /tmp/test_scope.py -n 2 -q || true ``` `test_add_user` и `test_users_count` уехали в разные процессы, и общего хранилища у них больше нет. Обрати внимание: xdist ничего не сломал — он вскрыл то, что и так было сломано. Тест, зависящий от соседа, падает и от запуска в одиночку, и от смены порядка; параллель просто делает это заметным. Что с этим делать: - **Не делить состояние между тестами.** `function`-scope под xdist работает ровно как обычно — самый надёжный ответ. - **`--dist loadfile`** — весь файл целиком уезжает на один воркер. Наша пара при нём зеленеет, и module-фикстура срабатывает один раз на файл. Платим параллелизмом: воркеров занято не больше, чем файлов. - **`--dist loadscope`** группирует мельче: по классу, а тесты вне классов — по файлу. Гарантии "весь модуль в одном воркере" не даёт, модуль с двумя классами он разрежет. - **Ресурс — на воркер, а не на прогон.** Если нужен внешний ресурс, его делают своим у каждого процесса: `worker_id` в имени каталога, свой порт, свой файл. Ровно один setup на весь параллельный прогон штатными средствами не получается; в [доках xdist](https://pytest-xdist.readthedocs.io/en/stable/how-to.html#making-session-scoped-fixtures-execute-only-once) для этого есть рецепт с файловой блокировкой. ### Stash — как фикстура и хук обмениваются данными Фикстура и хук смотрят на тест с разных сторон. Фикстура работает **внутри**: готовит окружение и может копить что-то, пока тест идёт, — записи лога, запросы, замеры. Хук работает **снаружи**: он видит исход, видит метки теста и может честно уронить его в фазе `call`. Заменить друг друга они не могут. Хук не умеет просить фикстуру: он не участвует в DI, у него нет параметров-фикстур. А фикстура не знает, чем кончился тест, и если уронить прогон из её teardown, получится `ERROR` отдельной строкой, а сам тест отчитается `passed`. Отсюда обычная для плагина связка: фикстура собирает, хук по итогу проверяет. Так же будет устроен плагин, который ты напишешь в задаче. Остаётся передать собранное из одной функции в другую. Общего у них только объект теста — `item`, и напрашивается прицепить к нему атрибут: ```python item._my_plugin_start = time.perf_counter() ``` Работает, но так делать не стоит: имя может занять другой плагин, `mypy` на чужой объект ругнётся `attr-defined`, и что там за значение — никто не знает. Для этого у pytest есть `Stash`: типизированный словарь на каждом узле (`item.stash`), а также на `Config` и `Session`. Ключ — **объект**, а не строка: ```{code-cell} python %%writefile /tmp/stash_demo/conftest.py import time import pytest # Ключ создаётся один раз на уровне модуля. STARTED_AT = pytest.StashKey[float]() @pytest.fixture(autouse=True) def _remember_start(request: pytest.FixtureRequest) -> None: request.node.stash[STARTED_AT] = time.perf_counter() @pytest.hookimpl(wrapper=True) def pytest_runtest_call(item: pytest.Item): result = yield started = item.stash.get(STARTED_AT, None) if started is not None: print(f"[stash] {item.name}: {time.perf_counter() - started:.3f}s") return result ``` ```{code-cell} python %%writefile /tmp/stash_demo/test_slow.py import time def test_fast() -> None: assert True def test_slow() -> None: time.sleep(0.2) assert True ``` ```{code-cell} python !uv run pytest /tmp/stash_demo -q -s ``` Фикстура положила, хук забрал. Два свойства, ради которых это не просто словарь: - **Ключи не сталкиваются.** Два плагина заведут `StashKey[float]()` под одним и тем же смыслом — и не пересекутся, потому что ключи сравниваются по идентичности, а не по имени. - **Тип привязан к ключу.** `StashKey[list[str]]()` означает, что `stash[key]` для тайпчекера именно `list[str]`, и `mypy --strict` поймает попытку положить туда не то. ### Как плагин попадает в wheel `conftest.py` работает, пока плагин нужен одному проекту. Чтобы им пользовались другие, его пакуют в wheel — и тогда `pytest_plugins` прописывать не нужно вовсе: pytest находит установленные плагины сам. Механизм — **entry point** группы `pytest11` (см. Лекцию 1 про `pyproject.toml`). Посмотрим, что в нашем окружении: ```{code-cell} python from importlib.metadata import entry_points for ep in sorted(entry_points(group="pytest11"), key=lambda e: e.name): print(f"{ep.name:18} -> {ep.value}") ``` Вот откуда берутся `mocker` и `--cov`: пакеты объявили точки входа, pytest на старте обошёл эту группу и импортировал модули. Соберём такой же плагин сами — он будет давать одну фикстуру `loud`. ```{code-cell} python %%writefile /tmp/pytest_loud_pkg/pytest_loud.py import pytest @pytest.fixture def loud() -> str: return "ГРОМКО" ``` ```{code-cell} python %%writefile /tmp/pytest_loud_pkg/pyproject.toml [project] name = "pytest-loud" version = "0.1.0" dependencies = ["pytest>=8"] [project.entry-points.pytest11] loud = "pytest_loud" [tool.setuptools] py-modules = ["pytest_loud"] [build-system] requires = ["setuptools>=68"] build-backend = "setuptools.build_meta" ``` Главная строчка — `loud = "pytest_loud"` в секции `[project.entry-points.pytest11]`. Слева от `=` — под каким именем плагин будет числиться у pytest; имя произвольное, оно нужно, чтобы плагин можно было назвать (например выключить через `-p no:loud`). Справа — что импортировать, когда плагин понадобится: модуль или пакет, откуда pytest заберёт хуки и фикстуры. Собираем wheel: ```{code-cell} python !cd /tmp/pytest_loud_pkg && uv build --wheel --no-build-isolation 2>&1 | tail -1 ``` Wheel — обычный zip. Объявление из `pyproject.toml` при сборке превратилось в файл `entry_points.txt` внутри метаданных пакета, и читает его уже не наш код, а pytest на старте: ```{code-cell} python !unzip -p /tmp/pytest_loud_pkg/dist/*.whl "*/entry_points.txt" ``` Ставим wheel в отдельный каталог и запускаем тест, рядом с которым нет ни `conftest.py`, ни импортов: ```{code-cell} python %%writefile /tmp/loud_test/test_loud.py def test_fixture_from_wheel(loud: str) -> None: assert loud == "ГРОМКО" ``` ```{code-cell} python !uv pip install --target /tmp/loud_site --no-deps /tmp/pytest_loud_pkg/dist/*.whl 2>&1 | tail -1 !PYTHONPATH=/tmp/loud_site uv run pytest /tmp/loud_test -v ``` Фикстура нашлась сама — ровно так же, как `mocker` из `pytest-mock`. Проверить, что подхватилось, — `pytest --trace-config`.
Имя пакета и имя модуля — разные вещи По конвенции пакет зовут pytest-<i>имя</i>, а модуль внутри — pytest_<i>имя</i>. Уникальными должны быть оба имени, и совпадение каждого проходит молча. Если имя entry point займёт чужой плагин, pluggy зарегистрирует того, кто пришёл первым, а твой пропустит — фикстур из него в тестах просто не окажется. Если совпадёт имя модуля, плагины столкнутся в sys.modules, и импортирован будет опять же один.
--- ### contextvars — контекст без явной передачи В прошлом разделе контекст жил в логгере: `log.bind(...)` возвращал новый логгер, и его надо было передавать дальше руками. `structlog.contextvars` убирает и это — кладёшь значение один раз, и его подхватывают все записи, сделанные дальше, даже из функций, которые про контекст ничего не знают. Держится это на модуле `contextvars` из stdlib ([PEP 567](https://peps.python.org/pep-0567/)). Думать о нём проще всего так: `ContextVar` выглядит как глобальная переменная, но глобальной не является. Программа нередко делает несколько дел сразу — скажем, обрабатывает несколько запросов. Обычную глобальную переменную такие дела затирают друг другу: второе записало свой `request_id`, и первое теперь пишет в лог чужой. У `ContextVar` значение своё у каждого дела: кто положил, тот и прочитает, соседи не мешают. Как именно устроена эта "одновременность" — потоки, корутины, — разберём дальше в курсе. Пока достаточно результата: в примере ниже два запроса обрабатываются вперемешку, и `request_id` у каждого свой. ```{code-cell} python %%writefile /tmp/structlog_ctxvars.py import asyncio import structlog from structlog.contextvars import bind_contextvars, clear_contextvars structlog.configure(processors=[ structlog.contextvars.merge_contextvars, structlog.processors.add_log_level, structlog.processors.JSONRenderer(), ]) log = structlog.get_logger() async def load_profile() -> None: await asyncio.sleep(0) # отдаём управление: пусть второй запрос вклинится log.info("profile_loaded") # про request_id ничего не знает async def handle_request(request_id: str, user_id: int) -> None: clear_contextvars() bind_contextvars(request_id=request_id, user_id=user_id) log.info("request_start") await load_profile() async def main() -> None: await asyncio.gather( handle_request("req-1", 42), handle_request("req-2", 7), ) asyncio.run(main()) ``` ```{code-cell} python !uv run python /tmp/structlog_ctxvars.py 2>&1 ``` Два запроса обрабатывались вперемешку, а `request_id` у каждого остался свой. И главное: `load_profile` про контекст ничего не знает и никаких аргументов не принимает — а в её записи `request_id` всё равно оказался. --- ## Материалы - [pytest docs](https://docs.pytest.org/) - [Python Logging HOWTO](https://docs.python.org/3/howto/logging.html) - [structlog docs](https://www.structlog.org/) - [pytest-xdist: параллельный прогон](https://pytest-xdist.readthedocs.io/en/stable/) - [coverage.py](https://coverage.readthedocs.io/)