diff --git a/docs/logging.md b/docs/logging.md index 4b4410196..1ad326b83 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -92,6 +92,12 @@ logging.getLogger("pact.ffi").setLevel(TRACE) ## Correlating Logs with Tests +/// note | Set Automatically +Most test suites never call `set_test_run_id` themselves. The +[pytest plugin](#pytest) and the [`unittest` mixin](#unittest) described below +set the run ID for every test. +/// + Plugins serve every test in the process, so their records do not identify the test which triggered them on their own. [`set_test_run_id`][pact.logging.set_test_run_id] sets an identifier for the @@ -107,6 +113,41 @@ Records from the library's own threads do not carry this ID. Group them by `log_id` instead: the records of one mock server share its ID, and the records of one provider verification share `verify:`. +### Pytest + +The pytest plugin in [`pact.testing.pytest`][pact.testing.pytest] is enabled +automatically. Its autouse fixture +[`pact_test_run_id`][pact.testing.pytest.pact_test_run_id] sets each test's +node ID as the run ID. Pytest's own log capture then shows Pact records in the +"Captured log call" section of a failing test. By default, pytest only captures +warnings and errors; set its `log_level` to `INFO` to capture the other +records too. Disable the plugin with `-p no:pact`. + +The plugin does not load the Pact FFI. A session which never uses Pact Python +does not load the library, and a test which first imports `pact` while it runs +still has its run ID applied. + +### Unittest + +Use [`PactTestMixin`][pact.testing.unittest.PactTestMixin] on test cases which +use Pact. It sets the test ID as the run ID and, when a test fails or errors, +writes the Pact records collected during the test to stderr. While the test +runs, the `pact` logger is lowered to the forwarding level +([`forwarding_level`][pact.logging.forwarding_level]) if it has no explicit +level of its own, so records below the root logger's level are collected too. +Handlers on the root logger still receive only the records at or above its +level: + +```python +import unittest + +from pact.testing.unittest import PactTestMixin + + +class ConsumerTest(PactTestMixin, unittest.TestCase): + def test_something(self) -> None: ... +``` + ## Migrating from `pact_ffi.log_to_stderr` Earlier releases left the library's logging unconfigured, and test suites @@ -115,13 +156,14 @@ session-scoped fixture in `conftest.py`, to see the library's output. Pact Python now applies the library's logger itself and forwards every event to `logging`, so remove the call. -Once `pact` is imported, `log_to_stderr`, `log_to_stdout`, `log_to_file`, -`init` and `init_with_log_level` on `pact_ffi` emit a `UserWarning` and do -nothing else. A call to `log_to_stderr`, `init` or `init_with_log_level` made -before `pact` is imported still applies the library's own sink, and Pact Python -keeps it: events are still forwarded to -`logging`, at the more restrictive of the sink's level and the level described -under [Verbosity](#verbosity), and a warning is logged on the `pact` logger. +Once [`pact.logging`][pact.logging] is imported, which importing `Pact` or +`Verifier` does, `log_to_stderr`, `log_to_stdout`, `log_to_file`, `init` and +`init_with_log_level` on `pact_ffi` emit a `UserWarning` and do nothing else. +A call to `log_to_stderr`, `init` or `init_with_log_level` made before then +still applies the library's own sink, and Pact Python keeps it: events are +still forwarded to `logging`, at the more restrictive of the sink's level and +the level described under [Verbosity](#verbosity), and a warning is logged on +the `pact` logger. To keep seeing the library's output on stderr, attach a handler through `logging`: @@ -137,4 +179,6 @@ Under pytest, `--log-cli-level=INFO` shows the records as each test runs. ## Further Information - [`pact.logging`][pact.logging] +- [`pact.testing.pytest`][pact.testing.pytest] +- [`pact.testing.unittest`][pact.testing.unittest] - [`pact_ffi.LevelFilter`][pact_ffi.LevelFilter] diff --git a/pyproject.toml b/pyproject.toml index 24f072bc6..839697b48 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -53,6 +53,9 @@ dependencies = [ issues = "https://github.com/pact-foundation/pact-python/issues" source = "https://github.com/pact-foundation/pact-python" + [project.entry-points.pytest11] + pact = "pact.testing.pytest" + [dependency-groups] # Linting and formatting tools use a more narrow specification to ensure # developper consistency. All other dependencies are as above. diff --git a/src/pact/__init__.py b/src/pact/__init__.py index fa044154b..286a5be39 100644 --- a/src/pact/__init__.py +++ b/src/pact/__init__.py @@ -111,17 +111,23 @@ from __future__ import annotations +import importlib +from typing import TYPE_CHECKING + # The `__version__` submodule shares its name with the attribute. Under PEP 810 # lazy imports, a submodule loaded after its attribute is bound replaces that # attribute. Assigning from an aliased module binds the attribute after the # submodule has loaded. import pact.__version__ as _version_module from pact import generate as generate -from pact import logging as logging from pact import match as match from pact import xml as xml -from pact.pact import Pact -from pact.verifier import Verifier + +if TYPE_CHECKING: + from pact import logging as logging + from pact import testing as testing + from pact.pact import Pact + from pact.verifier import Verifier __version__ = _version_module.__version__ __version_tuple__ = _version_module.__version_tuple__ @@ -135,6 +141,51 @@ "Verifier", "__version__", "__version_tuple__", - "logging", "xml", ] + +# Attributes imported on first access. `Pact`, `Verifier` and `logging` load the +# Pact FFI shared library, and the pytest plugin imports `pact.testing.pytest`, +# which runs this module in every pytest session. +_LAZY_ATTRIBUTES: dict[str, tuple[str, str | None]] = { + "Pact": ("pact.pact", "Pact"), + "Verifier": ("pact.verifier", "Verifier"), + "logging": ("pact.logging", None), + "testing": ("pact.testing", None), +} + + +def __getattr__(name: str) -> object: + """ + Import an attribute listed in `_LAZY_ATTRIBUTES` on first access. + + Args: + name: + The attribute name. + + Returns: + The attribute's value. + + Raises: + AttributeError: + If `name` is not a lazily imported attribute. + """ + try: + module_name, attribute = _LAZY_ATTRIBUTES[name] + except KeyError: + msg = f"module {__name__!r} has no attribute {name!r}" + raise AttributeError(msg) from None + module = importlib.import_module(module_name) + value = module if attribute is None else getattr(module, attribute) + globals()[name] = value + return value + + +def __dir__() -> list[str]: + """ + List the module's attributes, including those not yet imported. + + Returns: + The sorted attribute names. + """ + return sorted({*globals(), *_LAZY_ATTRIBUTES}) diff --git a/src/pact/logging.py b/src/pact/logging.py index 30e35a116..10141570d 100644 --- a/src/pact/logging.py +++ b/src/pact/logging.py @@ -34,15 +34,18 @@ library's `TRACE` level is exposed as [`TRACE`][TRACE], below `logging.DEBUG`. Log records can be attributed to the test which caused them by setting a test -run ID with [`set_test_run_id`][set_test_run_id]. - -Importing `pact` replaces `pact_ffi.init`, `pact_ffi.init_with_log_level`, -`pact_ffi.log_to_stderr`, `pact_ffi.log_to_stdout` and `pact_ffi.log_to_file` -with functions which emit a `UserWarning` and do nothing else. A logger -applied through `pact_ffi.init`, `pact_ffi.init_with_log_level` or -`pact_ffi.log_to_stderr` before `pact` was imported is kept: events are -still forwarded to `logging`, at the more restrictive of that sink's level and -the forwarding level, and a warning is emitted on the `pact` logger. +run ID with [`set_test_run_id`][set_test_run_id]. The pytest plugin in +[`pact.testing.pytest`][testing.pytest] and the `unittest` mixin in +[`pact.testing.unittest`][testing.unittest] do this automatically. + +Importing this module, which importing `Pact` or `Verifier` does, replaces +`pact_ffi.init`, `pact_ffi.init_with_log_level`, `pact_ffi.log_to_stderr`, +`pact_ffi.log_to_stdout` and `pact_ffi.log_to_file` with functions which emit +a `UserWarning` and do nothing else. A logger applied through `pact_ffi.init`, +`pact_ffi.init_with_log_level` or `pact_ffi.log_to_stderr` before this module +was imported is kept: events are still forwarded to `logging`, at the more +restrictive of that sink's level and the forwarding level, and a warning is +emitted on the `pact` logger. """ from __future__ import annotations @@ -50,6 +53,7 @@ import atexit import contextlib import logging +import sys import threading import warnings from typing import TYPE_CHECKING @@ -243,7 +247,7 @@ def ensure_initialised() -> None: warning on the `pact` logger, once. If a logger was already applied, through one of the `pact_ffi.log_to_*` - functions called before `pact` was imported, a warning is logged on the + functions called before this module was imported, a warning is logged on the `pact` logger and the callbacks are registered against that logger instead. """ @@ -314,7 +318,7 @@ def _stand_in(name: str) -> Callable[..., None]: Pact Python applies the FFI logger itself, and the logger can be applied once per process. A suite which still calls one of these functions after - `pact` is imported gets a warning in place of the FFI's "Logger already + this module is imported gets a warning in place of the FFI's "Logger already initialized" error. Args: @@ -369,3 +373,9 @@ def set_test_run_id(test_run_id: str | None) -> None: or `None` to clear a previously set ID. """ pact_ffi.set_test_run_id(test_run_id) + + +# A test which imports `pact` while it runs loads this module after the pytest +# plugin has set the test's run ID. +if (_pytest_plugin := sys.modules.get("pact.testing.pytest")) is not None: + set_test_run_id(_pytest_plugin.current_test_run_id()) diff --git a/src/pact/testing/__init__.py b/src/pact/testing/__init__.py new file mode 100644 index 000000000..92148767c --- /dev/null +++ b/src/pact/testing/__init__.py @@ -0,0 +1,8 @@ +""" +Test runner integrations. + +- [`pact.testing.pytest`][testing.pytest] is a pytest plugin, enabled + automatically when `pact-python` is installed. +- [`pact.testing.unittest`][testing.unittest] provides a mixin for + `unittest.TestCase` subclasses. +""" diff --git a/src/pact/testing/pytest.py b/src/pact/testing/pytest.py new file mode 100644 index 000000000..c48d9f305 --- /dev/null +++ b/src/pact/testing/pytest.py @@ -0,0 +1,66 @@ +""" +Pytest plugin scoping the Pact test run ID to each test. + +The plugin is registered through the `pytest11` entry point and is active +whenever `pact-python` is installed. It provides one autouse fixture, +[`pact_test_run_id`][testing.pytest.pact_test_run_id], which sets the +test's node ID as the Pact test run ID for the test's duration. The Pact +library's records from the test's thread, and the log entries a plugin sends +back for the test's requests, then carry the test which caused them. + +The plugin does not load the Pact FFI. While no module has imported Pact +Python's logging integration, the run ID is held in Python, and applied once +the integration is imported. + +Disable the plugin with `-p no:pact`. +""" + +from __future__ import annotations + +import sys +import threading +from typing import TYPE_CHECKING + +import pytest + +if TYPE_CHECKING: + from collections.abc import Generator + +_state = threading.local() + + +def current_test_run_id() -> str | None: + """ + Run ID of the test running on the current thread. + + Returns: + The node ID set by [`pact_test_run_id`][testing.pytest.pact_test_run_id], + or `None` outside a test. + """ + return getattr(_state, "test_run_id", None) + + +def _set_test_run_id(test_run_id: str | None) -> None: + _state.test_run_id = test_run_id + # Looked up, never imported: importing it would load the FFI in sessions + # which never use Pact. + pact_logging = sys.modules.get("pact.logging") + if pact_logging is not None: + pact_logging.set_test_run_id(test_run_id) + + +@pytest.fixture(autouse=True) +def pact_test_run_id(request: pytest.FixtureRequest) -> Generator[str, None, None]: + """ + Set the test's node ID as the Pact test run ID. + + Args: + request: + The pytest request for the running test. + + Yields: + The node ID set as the run ID. It is cleared on teardown. + """ + _set_test_run_id(request.node.nodeid) + yield request.node.nodeid + _set_test_run_id(None) diff --git a/src/pact/testing/unittest.py b/src/pact/testing/unittest.py new file mode 100644 index 000000000..384880cf4 --- /dev/null +++ b/src/pact/testing/unittest.py @@ -0,0 +1,171 @@ +""" +`unittest` integration for Pact logs. + +[`PactTestMixin`][testing.unittest.PactTestMixin] scopes the Pact test run +ID to each test and prints the Pact log records collected during a test to +stderr when the test fails or errors: + +```python +import unittest + +from pact.testing.unittest import PactTestMixin + + +class ConsumerTest(PactTestMixin, unittest.TestCase): + def test_something(self) -> None: ... +``` + +List the mixin before `unittest.TestCase` so that its `run` wraps the test. +""" + +from __future__ import annotations + +import logging +import sys +from typing import TYPE_CHECKING, Any + +from pact import logging as pact_logging + +if TYPE_CHECKING: + import unittest + +__all__ = ["PactTestMixin"] + + +class _BufferHandler(logging.Handler): + """ + Handler buffering every record, and forwarding some to a parent logger. + + While [`PactTestMixin`][testing.unittest.PactTestMixin] lowers the `pact` + logger, it stops the logger propagating. This handler stands in for + propagation, handing the parent's handlers only the records which would + have reached them at the logger's previous level. + """ + + def __init__(self, parent: logging.Logger | None, threshold: int) -> None: + super().__init__(logging.NOTSET) + self.records: list[logging.LogRecord] = [] + self._parent = parent + self._threshold = threshold + + def emit(self, record: logging.LogRecord) -> None: + self.records.append(record) + if self._parent is not None and record.levelno >= self._threshold: + self._parent.callHandlers(record) + + +class _ResultProxy: + """ + Wrapper around a test result noting whether the test failed or errored. + + Every attribute is looked up on the wrapped result. Pytest passes its own + result object to `run`, which lacks the `failures` and `errors` lists of + `unittest.TestResult`. + """ + + _FAILING = frozenset({"addError", "addFailure", "addSubTest"}) + + def __init__(self, result: object) -> None: + self._result = result + self.failed = False + + def __getattr__(self, name: str) -> Any: # noqa: ANN401 + attribute = getattr(self._result, name) + if name not in self._FAILING: + return attribute + + def record(*args: Any) -> Any: # noqa: ANN401 + # `addSubTest` is called with `err=None` for a passing subtest. + if name != "addSubTest" or args[-1] is not None: + self.failed = True + return attribute(*args) + + return record + + +def _enclosing_test_run_id() -> str | None: + # Looked up, never imported: `unittest` suites need not have pytest + # installed. + pytest_plugin = sys.modules.get("pact.testing.pytest") + if pytest_plugin is None: + return None + return pytest_plugin.current_test_run_id() + + +class PactTestMixin: + """ + Mixin for `unittest.TestCase` subclasses using Pact. + + While a test runs, its `id()` is set as the Pact test run ID and every + record on the `pact` logger is buffered. If the test fails or errors, the + buffered records are written to stderr under a banner naming the test. + Afterwards, the run ID is cleared or, when pytest runs the test case, set + back to the test's node ID. + + A logger only hands records at or above its effective level to its + handlers, so when the `pact` logger has no explicit level it is lowered to + [`forwarding_level`][pact_logging.forwarding_level] for the duration of the + test and restored afterwards. Handlers above the `pact` logger still + receive only the records at or above its previous effective level. + Handlers attached to the `pact` logger or below it receive every buffered + record. + """ + + def run( + self, + result: unittest.TestResult | None = None, + ) -> unittest.TestResult | None: + """ + Run the test with the Pact run ID set and Pact logs buffered. + + Args: + result: + The result to record into. When omitted, the test's + `defaultTestResult()` is used, and its `startTestRun()` and + `stopTestRun()` are called around the test, as + `unittest.TestCase.run` does. + + Returns: + The result the test was recorded into. + """ + owns_result = result is None + if result is None: + result = self.defaultTestResult() # type: ignore[attr-defined] + result.startTestRun() + test_id: str = self.id() # type: ignore[attr-defined] + proxy = _ResultProxy(result) + + pact_logger = logging.getLogger("pact") + lowered = pact_logger.level == logging.NOTSET + propagate = pact_logger.propagate + handler = _BufferHandler( + pact_logger.parent if lowered and propagate else None, + pact_logger.getEffectiveLevel(), + ) + + pact_logging.set_test_run_id(test_id) + pact_logger.addHandler(handler) + if lowered: + pact_logger.setLevel(pact_logging.forwarding_level()) + pact_logger.propagate = False + try: + super().run(proxy) # type: ignore[misc] + if proxy.failed: + self._dump(test_id, handler.records) + return result + finally: + if lowered: + pact_logger.setLevel(logging.NOTSET) + pact_logger.propagate = propagate + pact_logger.removeHandler(handler) + pact_logging.set_test_run_id(_enclosing_test_run_id()) + if owns_result: + result.stopTestRun() + + @staticmethod + def _dump(test_id: str, records: list[logging.LogRecord]) -> None: + formatter = logging.Formatter("%(levelname)s %(name)s: %(message)s") + lines = [f"--- Pact logs for {test_id} ---"] + lines.extend(formatter.format(record) for record in records) + lines.append("--- end of Pact logs ---") + sys.stderr.write("\n".join(lines) + "\n") diff --git a/tests/conftest.py b/tests/conftest.py index 6807fae55..34d6cc223 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -25,6 +25,8 @@ import pytest +pytest_plugins = ["pytester"] + @pytest.fixture def temp_assets(tmp_path: Path) -> Path: diff --git a/tests/test_import.py b/tests/test_import.py index 2a67b1321..c9ef8f754 100644 --- a/tests/test_import.py +++ b/tests/test_import.py @@ -4,17 +4,21 @@ from __future__ import annotations +import importlib import subprocess import sys import pytest +import pact + @pytest.mark.parametrize( "module", [ pytest.param("http.server", id="http.server"), pytest.param("pact._server", id="pact._server"), + pytest.param("pact_ffi", id="pact_ffi"), pytest.param("yarl", id="yarl"), ], ) @@ -35,6 +39,39 @@ def test_import_does_not_load(module: str) -> None: assert result.stdout.strip() == "False", f"`import pact` loaded {module}" +@pytest.mark.parametrize( + ("name", "module", "attribute"), + [ + pytest.param("Pact", "pact.pact", "Pact", id="Pact"), + pytest.param("Verifier", "pact.verifier", "Verifier", id="Verifier"), + pytest.param("logging", "pact.logging", None, id="logging"), + pytest.param("testing", "pact.testing", None, id="testing"), + ], +) +def test_lazy_attribute(name: str, module: str, attribute: str | None) -> None: + imported = importlib.import_module(module) + expected = imported if attribute is None else getattr(imported, attribute) + assert getattr(pact, name) is expected + assert vars(pact)[name] is expected + + +def test_unknown_attribute() -> None: + with pytest.raises(AttributeError, match="has no attribute 'missing'"): + _ = pact.missing + + +def test_dir_lists_lazy_attributes() -> None: + # A fresh interpreter, so that no lazy attribute has been imported yet. + code = "import pact; print(' '.join(dir(pact)))" + result = subprocess.run( # noqa: S603 + [sys.executable, "-c", code], + capture_output=True, + text=True, + check=True, + ) + assert {"Pact", "Verifier", "logging", "testing"} <= set(result.stdout.split()) + + def test_state_handler_url_alias() -> None: from pact.types import StateHandlerUrl # noqa: PLC0415 diff --git a/tests/test_logging.py b/tests/test_logging.py index 1ad2e4c83..cae5b6087 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -379,7 +379,7 @@ def test_does_not_apply_a_logger(self) -> None: import warnings import pact_ffi - import pact + import pact.logging warnings.simplefilter("ignore") pact_ffi.log_to_stderr("INFO") diff --git a/tests/testing/__init__.py b/tests/testing/__init__.py new file mode 100644 index 000000000..e69de29bb diff --git a/tests/testing/test_pytest.py b/tests/testing/test_pytest.py new file mode 100644 index 000000000..83fbcce75 --- /dev/null +++ b/tests/testing/test_pytest.py @@ -0,0 +1,100 @@ +""" +Tests for the pytest plugin in [`pact.testing.pytest`][pact.testing.pytest]. +""" + +from __future__ import annotations + +from typing import TYPE_CHECKING + +if TYPE_CHECKING: + import pytest + +CONFTEST = """ +import pytest + +import pact.logging + +calls = [] + + +# Session scope so the recorder is in place before the plugin's function-scoped +# autouse fixture runs. +@pytest.fixture(autouse=True, scope="session") +def _record(): + original = pact.logging.set_test_run_id + pact.logging.set_test_run_id = calls.append + yield + pact.logging.set_test_run_id = original + + +def pytest_sessionfinish(session): + session.config.rootpath.joinpath("calls.txt").write_text( + "\\n".join(str(c) for c in calls) + ) +""" + +TEST_FILE = """ +def test_one(pact_test_run_id, request): + assert pact_test_run_id == request.node.nodeid +""" + + +def test_fixture_scopes_the_run_id(pytester: pytest.Pytester) -> None: + pytester.makeconftest(CONFTEST) + pytester.makepyfile(test_example=TEST_FILE) + + result = pytester.runpytest("-p", "no:cacheprovider") + + result.assert_outcomes(passed=1) + calls = pytester.path.joinpath("calls.txt").read_text().splitlines() + assert calls == ["test_example.py::test_one", "None"] + + +def test_plugin_can_be_disabled(pytester: pytest.Pytester) -> None: + pytester.makepyfile(test_example=TEST_FILE) + + result = pytester.runpytest("-p", "no:pact", "-p", "no:cacheprovider") + + result.assert_outcomes(errors=1) + result.stdout.fnmatch_lines(["*fixture 'pact_test_run_id' not found*"]) + + +def test_session_without_pact_does_not_load_the_ffi(pytester: pytest.Pytester) -> None: + pytester.makepyfile( + test_example=""" + import sys + + def test_ffi_not_loaded(pact_test_run_id): + assert "pact_ffi" not in sys.modules + """ + ) + + result = pytester.runpytest_subprocess("-p", "no:cacheprovider") + + result.assert_outcomes(passed=1) + + +def test_run_id_applied_when_pact_is_imported_during_a_test( + pytester: pytest.Pytester, +) -> None: + # The plugin holds the ID in Python until the logging integration loads, + # which then applies it to the FFI. + pytester.makepyfile( + test_example=""" + import sys + + def test_import_during_test(request): + import pact_ffi + + calls = [] + pact_ffi.set_test_run_id = calls.append + assert "pact.logging" not in sys.modules + import pact.logging + + assert calls == [request.node.nodeid] + """ + ) + + result = pytester.runpytest_subprocess("-p", "no:cacheprovider") + + result.assert_outcomes(passed=1) diff --git a/tests/testing/test_unittest.py b/tests/testing/test_unittest.py new file mode 100644 index 000000000..a3310e4b8 --- /dev/null +++ b/tests/testing/test_unittest.py @@ -0,0 +1,216 @@ +""" +Tests for [`PactTestMixin`][pact.testing.unittest.PactTestMixin]. +""" + +from __future__ import annotations + +import contextlib +import logging +import sys +import unittest +from typing import TYPE_CHECKING + +import pytest + +import pact.logging +from pact.testing.unittest import PactTestMixin + +if TYPE_CHECKING: + from collections.abc import Generator + + +@pytest.fixture +def run_ids(monkeypatch: pytest.MonkeyPatch) -> list[str | None]: + calls: list[str | None] = [] + monkeypatch.setattr(pact.logging, "set_test_run_id", calls.append) + return calls + + +class Example(PactTestMixin, unittest.TestCase): + """`unittest.TestCase` exercising `PactTestMixin` for the tests below.""" + + # Keep pytest from collecting the deliberately failing cases. + __test__ = False + + def test_passes(self) -> None: + logging.getLogger("pact.ffi.x").info("quiet") + + def test_fails(self) -> None: + logging.getLogger("pact.ffi.x").info("noisy") + self.fail("boom") + + def test_errors(self) -> None: + logging.getLogger("pact.plugins").warning("plugin noise") + raise RuntimeError + + def test_subtest_fails(self) -> None: + logging.getLogger("pact.ffi.x").info("subtest noise") + with self.subTest(case=1): + self.fail("boom") + + +def run(name: str) -> unittest.TestResult: + result = unittest.TestResult() + Example(name).run(result) + return result + + +def test_sets_and_clears_run_id( + run_ids: list[str | None], monkeypatch: pytest.MonkeyPatch +) -> None: + monkeypatch.delitem(sys.modules, "pact.testing.pytest") + run("test_passes") + assert run_ids == [f"{Example.__module__}.Example.test_passes", None] + + +def test_restores_pytest_run_id( + run_ids: list[str | None], request: pytest.FixtureRequest +) -> None: + run("test_passes") + assert run_ids == [ + f"{Example.__module__}.Example.test_passes", + request.node.nodeid, + ] + + +def test_silent_on_success(capsys: pytest.CaptureFixture[str]) -> None: + result = run("test_passes") + assert result.wasSuccessful() + assert capsys.readouterr().err == "" + + +def test_dumps_logs_on_failure(capsys: pytest.CaptureFixture[str]) -> None: + result = run("test_fails") + assert len(result.failures) == 1 + output = capsys.readouterr().err + assert "--- Pact logs for" in output + assert "test_fails" in output + assert "noisy" in output + + +def test_dumps_logs_on_error(capsys: pytest.CaptureFixture[str]) -> None: + result = run("test_errors") + assert len(result.errors) == 1 + assert "plugin noise" in capsys.readouterr().err + + +def test_dumps_logs_on_subtest_failure(capsys: pytest.CaptureFixture[str]) -> None: + result = run("test_subtest_fails") + assert len(result.failures) == 1 + assert "subtest noise" in capsys.readouterr().err + + +def test_runs_under_pytest(pytester: pytest.Pytester) -> None: + # Pytest passes its own result object to `run`, which has no `failures` + # or `errors` lists. + pytester.makepyfile( + test_example=""" + import logging + import unittest + + from pact.testing.unittest import PactTestMixin + + + class Example(PactTestMixin, unittest.TestCase): + def test_passes(self): + pass + + def test_fails(self): + logging.getLogger("pact.ffi.x").info("noisy") + self.fail("boom") + """ + ) + + result = pytester.runpytest("-p", "no:cacheprovider") + + result.assert_outcomes(passed=1, failed=1) + result.stdout.fnmatch_lines(["--- Pact logs for *test_fails ---", "*noisy"]) + + +@contextlib.contextmanager +def quiet_root() -> Generator[None, None, None]: + """ + Root logger at `WARNING` and the `pact` logger unset, as outside pytest. + + Pytest's `log_level = "NOTSET"` setting lowers the root logger at the + start of each test phase, so this is entered inside the test body. + """ + root = logging.getLogger() + pact_logger = logging.getLogger("pact") + root_level, pact_level = root.level, pact_logger.level + root.setLevel(logging.WARNING) + pact_logger.setLevel(logging.NOTSET) + try: + yield + finally: + root.setLevel(root_level) + pact_logger.setLevel(pact_level) + + +def test_dumps_logs_below_root_level(capsys: pytest.CaptureFixture[str]) -> None: + with quiet_root(): + assert not logging.getLogger("pact.ffi.x").isEnabledFor(logging.INFO) + result = run("test_fails") + assert logging.getLogger("pact").level == logging.NOTSET + assert len(result.failures) == 1 + assert "noisy" in capsys.readouterr().err + + +class _ListHandler(logging.Handler): + def __init__(self) -> None: + super().__init__() + self.records: list[logging.LogRecord] = [] + + def emit(self, record: logging.LogRecord) -> None: + self.records.append(record) + + +def test_root_handlers_keep_their_level() -> None: + # A handler on the root logger, as `logging.basicConfig()` installs, sees + # only the records which reach it without the mixin. + root_handler = _ListHandler() + logging.getLogger().addHandler(root_handler) + try: + with quiet_root(): + run("test_passes") + run("test_errors") + assert logging.getLogger("pact").propagate + finally: + logging.getLogger().removeHandler(root_handler) + assert [r.getMessage() for r in root_handler.records] == ["plugin noise"] + + +def test_keeps_explicit_pact_level() -> None: + pact_logger = logging.getLogger("pact") + pact_logger.setLevel(logging.ERROR) + try: + run("test_fails") + assert pact_logger.level == logging.ERROR + finally: + pact_logger.setLevel(logging.NOTSET) + + +def test_handler_is_removed() -> None: + before = list(logging.getLogger("pact").handlers) + run("test_fails") + assert logging.getLogger("pact").handlers == before + + +def test_run_without_result( + capsys: pytest.CaptureFixture[str], monkeypatch: pytest.MonkeyPatch +) -> None: + calls: list[str] = [] + + class Recording(unittest.TestResult): + def startTestRun(self) -> None: # noqa: N802 + calls.append("start") + + def stopTestRun(self) -> None: # noqa: N802 + calls.append("stop") + + monkeypatch.setattr(Example, "defaultTestResult", lambda _self: Recording()) + result = Example("test_fails").run() + assert isinstance(result, Recording) + assert len(result.failures) == 1 + assert calls == ["start", "stop"] + assert "noisy" in capsys.readouterr().err