From 21268cf80dbd51b952e1b8f066ce44372032a8ec Mon Sep 17 00:00:00 2001 From: JP-Ellis Date: Thu, 17 Sep 2026 22:14:30 +1000 Subject: [PATCH 01/12] feat: route Pact library and plugin logs through logging Add pact.logging, which initialises the Pact FFI once with a silent sink and registers the library and plugin log callbacks, re-emitting every event on the pact.ffi. and pact.plugins loggers with the test run ID and mock server or plugin instance ID as record attributes. The forwarding level follows any explicit level on those loggers, and otherwise defaults to DEBUG. Initialisation is implicit because the FFI logger can be applied once per process and users should not have to know that. Pact and Verifier will call ensure_initialised() on construction, so the first use of the library wires everything up. A logger applied earlier through one of the pact_ffi.log_to_* functions is kept, with a warning on the pact logger, and the callbacks attach to it instead. ensure_initialised() also registers an atexit hook which sets the callback level to OFF and deregisters both callbacks. A callback fired from a library thread during interpreter finalisation cannot acquire the GIL and aborts the process, so the hook cuts the callbacks off before finalisation starts. The test suite no longer initialises FFI logging to stderr itself, as initialisation is now the library's responsibility. tests/interaction/test_http_interaction.py::test_pact_server_verbose counted every record caplog captured, expecting only the `pact.pact` mismatch record. The mock server's own events now reach caplog's root handler through the `pact.ffi.*` loggers, so the assertion filters to records from `pact.pact`. Signed-off-by: JP-Ellis Assisted-by: Claude Code:claude-opus-5-5 --- src/pact/__init__.py | 2 + src/pact/logging.py | 304 ++++++++++++++++++ tests/conftest.py | 10 - tests/interaction/test_http_interaction.py | 7 +- tests/test_logging.py | 355 +++++++++++++++++++++ 5 files changed, 666 insertions(+), 12 deletions(-) create mode 100644 src/pact/logging.py create mode 100644 tests/test_logging.py diff --git a/src/pact/__init__.py b/src/pact/__init__.py index 447952fd3..fa044154b 100644 --- a/src/pact/__init__.py +++ b/src/pact/__init__.py @@ -117,6 +117,7 @@ # 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 @@ -134,5 +135,6 @@ "Verifier", "__version__", "__version_tuple__", + "logging", "xml", ] diff --git a/src/pact/logging.py b/src/pact/logging.py new file mode 100644 index 000000000..380e107ce --- /dev/null +++ b/src/pact/logging.py @@ -0,0 +1,304 @@ +""" +Logging integration between the Pact library and the standard `logging` module. + +The Pact FFI and Pact plugins run outside the Python interpreter, so their log +output does not reach `logging` on its own. This module initialises the FFI +once, on the first use of [`Pact`][pact.Pact] or [`Verifier`][pact.Verifier], +and re-emits every event through `logging`: + +- Events from the Pact library are emitted on the `pact.ffi` logger, with + the Rust module path appended (for example + `pact.ffi.pact_matching::matchers`). Each record carries `test_run_id` + (for events emitted from the calling thread) and `log_id` (the mock + server ID, for events emitted while handling a request) as extra + attributes. +- Events from plugins are emitted on the `pact.plugins` logger, with + `plugin_instance_id`, `test_run_id` and `plugin_target` as extra + attributes. + +Nothing needs to be configured. Verbosity is controlled with `logging`: + +```python +import logging + +logging.getLogger("pact.ffi").setLevel(logging.DEBUG) +``` + +The FFI forwards events at the most verbose level set explicitly on the +`pact.ffi` and `pact.plugins` loggers, or at +[`DEFAULT_LEVEL`][logging.DEFAULT_LEVEL] when neither is set. That level is +fixed when the FFI is initialised, so set logger levels before creating the +first `Pact` or `Verifier`. The Pact library's `TRACE` level is exposed as +[`TRACE`][logging.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`][logging.set_test_run_id]. + +Calling one of the `pact_ffi.log_to_*` functions before the first `Pact` or +`Verifier` configures the FFI's own sink instead. Events are still forwarded +to `logging`, at the more restrictive of that sink's level and the level +above, and a warning is emitted on the `pact` logger. +""" + +from __future__ import annotations + +import atexit +import contextlib +import logging +import threading + +import pact_ffi + +__all__ = [ + "DEFAULT_LEVEL", + "TRACE", + "ensure_initialised", + "forwarding_level", + "from_ffi_level", + "set_test_run_id", + "to_ffi_level", +] + +logger = logging.getLogger("pact") + +# MARK: Level mapping + +TRACE = 5 +""" +Level of the Pact library's `TRACE` events, below `logging.DEBUG`. + +The level is registered with the name `TRACE`, unless another library has +already named level 5 or registered `TRACE` as another level. `verboselogs`, +for example, names level 5 `SPAM`, and records at this level then show that +name. +""" + +if ( + logging.getLevelName(TRACE) == f"Level {TRACE}" + and logging.getLevelName("TRACE") == "Level TRACE" +): + logging.addLevelName(TRACE, "TRACE") + +DEFAULT_LEVEL = logging.DEBUG +""" +Level at which the Pact library forwards events when neither the `pact.ffi` nor +the `pact.plugins` logger has an explicit level. +""" + +_TO_FFI: list[tuple[int, pact_ffi.LevelFilter]] = [ + (logging.ERROR, pact_ffi.LevelFilter.ERROR), + (logging.WARNING, pact_ffi.LevelFilter.WARN), + (logging.INFO, pact_ffi.LevelFilter.INFO), + (logging.DEBUG, pact_ffi.LevelFilter.DEBUG), + (TRACE, pact_ffi.LevelFilter.TRACE), +] + +_FROM_FFI: dict[str, int] = { + "TRACE": TRACE, + "DEBUG": logging.DEBUG, + "INFO": logging.INFO, + "WARN": logging.WARNING, + "ERROR": logging.ERROR, +} + + +def to_ffi_level(level: int) -> pact_ffi.LevelFilter: + """ + Convert a `logging` level to the FFI level filter admitting it. + + Args: + level: + A `logging` level. Levels between two standard levels map to the + more verbose one, so that every record at `level` is admitted. + + Returns: + The [`LevelFilter`][pact_ffi.LevelFilter] which forwards records at + `level`. + """ + for threshold, ffi_level in _TO_FFI: + if level >= threshold: + return ffi_level + return pact_ffi.LevelFilter.TRACE + + +def from_ffi_level(level: str) -> int: + """ + Convert a Pact library level name to a `logging` level. + + Args: + level: + One of `TRACE`, `DEBUG`, `INFO`, `WARN` or `ERROR`, in any case. + + Returns: + The matching `logging` level. Unknown names map to `logging.INFO`. + """ + return _FROM_FFI.get(level.upper(), logging.INFO) + + +def forwarding_level() -> int: + """ + `logging` level at which the Pact library forwards events. + + Returns: + The most verbose level set explicitly on the `pact.ffi` and + `pact.plugins` loggers, or [`DEFAULT_LEVEL`][DEFAULT_LEVEL] when + neither has one. + """ + explicit = [ + lg.level + for lg in (logging.getLogger("pact.ffi"), logging.getLogger("pact.plugins")) + if lg.level != logging.NOTSET + ] + return min(explicit) if explicit else DEFAULT_LEVEL + + +def _ffi_level() -> pact_ffi.LevelFilter: + """ + Level filter to forward events at. + + Returns: + The [`LevelFilter`][pact_ffi.LevelFilter] admitting every record at + [`forwarding_level`][forwarding_level]. + """ + return to_ffi_level(forwarding_level()) + + +# MARK: FFI callbacks + + +def _core_callback( + log_id: str, + test_run_id: str, + level: str, + target: str, + message: str, +) -> None: + # Runs on a thread owned by the Pact library; an exception here has nowhere + # to go, so it is discarded. + with contextlib.suppress(Exception): + logging.getLogger(f"pact.ffi.{target}" if target else "pact.ffi").log( + from_ffi_level(level), + "%s", + message, + extra={ + "test_run_id": test_run_id or None, + "log_id": log_id or None, + }, + ) + + +def _plugin_callback( + plugin_instance_id: str, + test_run_id: str, + level: str, + target: str, + message: str, +) -> None: + with contextlib.suppress(Exception): + logging.getLogger("pact.plugins").log( + from_ffi_level(level), + "%s", + message, + extra={ + "plugin_instance_id": plugin_instance_id, + "test_run_id": test_run_id or None, + "plugin_target": target or None, + }, + ) + + +# MARK: One-time initialisation + +_initialised = False +_applied_level = logging.CRITICAL +_level_warned = False +_lock = threading.Lock() + + +def ensure_initialised() -> None: + """ + Initialise the Pact library's logging once. + + Applies a logger with no visible sink at the level returned by + `_ffi_level`, registers the callbacks which re-emit library and plugin + events through `logging`, and registers an `atexit` hook which + deregisters them again. + + The forwarding level cannot be raised once the logger is applied. A later + call which finds a more verbose level set on the `pact.ffi` or + `pact.plugins` logger logs a warning on the `pact` logger, once. + + If a logger was already applied, through one of the `pact_ffi.log_to_*` + functions, a warning is logged on the `pact` logger and the callbacks are + registered against that logger instead. + """ + global _initialised, _applied_level, _level_warned # noqa: PLW0603 + + with _lock: + if _initialised: + requested = forwarding_level() + applied = to_ffi_level(_applied_level) + if ( + not _level_warned + and requested < _applied_level + and to_ffi_level(requested) != applied + ): + _level_warned = True + logger.warning( + "Pact library events are forwarded at %s, fixed when the " + "first Pact or Verifier was created. Set the levels of the " + "'pact.ffi' and 'pact.plugins' loggers before then.", + applied.name, + ) + return + _applied_level = forwarding_level() + pact_ffi.set_log_callback_level(to_ffi_level(_applied_level)) + try: + pact_ffi.log_to_buffer(pact_ffi.LevelFilter.OFF) + except RuntimeError: + logger.warning( + "Pact FFI logging was configured externally; " + "events more verbose than that sink are not forwarded to logging." + ) + pact_ffi.register_log_callback(_core_callback) + pact_ffi.register_plugin_log_callback(_plugin_callback) + atexit.register(_shutdown) + _initialised = True + + +def _shutdown() -> None: + """ + Stop forwarding events and deregister the callbacks. + + Registered with `atexit` by [`ensure_initialised`][ensure_initialised]. + """ + # A callback fired from a library thread during interpreter finalisation + # cannot acquire the GIL and aborts the process. + with contextlib.suppress(Exception): + pact_ffi.set_log_callback_level("OFF") + with contextlib.suppress(Exception): + pact_ffi.register_log_callback(None) + with contextlib.suppress(Exception): + pact_ffi.register_plugin_log_callback(None) + + +# MARK: Test Run ID + + +def set_test_run_id(test_run_id: str | None) -> None: + """ + Set the test run ID for the current thread. + + The ID is reported as the `test_run_id` attribute on the records the Pact + library emits from the current thread. It is also attached to every + request sent to a plugin from the current thread, so every plugin record + carries it. Records emitted while the mock server handles a request come + from the server's own threads; they carry the mock server ID as `log_id` + and no `test_run_id`. + + Args: + test_run_id: + The identifier to attach, such as pytest's `request.node.nodeid`, + or `None` to clear a previously set ID. + """ + pact_ffi.set_test_run_id(test_run_id) diff --git a/tests/conftest.py b/tests/conftest.py index 9fe7c2f15..6807fae55 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -25,16 +25,6 @@ import pytest -import pact_ffi - - -@pytest.fixture(scope="session", autouse=True) -def _setup_pact_logging() -> None: - """ - Set up logging for the pact package. - """ - pact_ffi.log_to_stderr("INFO") - @pytest.fixture def temp_assets(tmp_path: Path) -> Path: diff --git a/tests/interaction/test_http_interaction.py b/tests/interaction/test_http_interaction.py index 50e6fe686..87da8973c 100644 --- a/tests/interaction/test_http_interaction.py +++ b/tests/interaction/test_http_interaction.py @@ -701,7 +701,10 @@ async def test_pact_server_verbose( ): assert resp.status == 500 - assert len(caplog.records) == 1 - for record in caplog.records: + # Pact FFI events also propagate to the root logger, on their own + # `pact.ffi.*` loggers, so caplog captures those too. + records = [record for record in caplog.records if record.name == "pact.pact"] + assert len(records) == 1 + for record in records: assert record.levelname == "ERROR" assert record.message.startswith("Mismatches:\n") diff --git a/tests/test_logging.py b/tests/test_logging.py new file mode 100644 index 000000000..e28feeb82 --- /dev/null +++ b/tests/test_logging.py @@ -0,0 +1,355 @@ +""" +Unit tests for [`pact.logging`][pact.logging]. +""" + +from __future__ import annotations + +import atexit +import logging +from typing import TYPE_CHECKING + +import pytest + +import pact_ffi +from pact import logging as pact_logging + +if TYPE_CHECKING: + from collections.abc import Generator + + +def emit_core( + log_id: str = "", + test_run_id: str = "", + level: str = "INFO", + target: str = "pact_matching", + message: str = "hello", +) -> None: + """Invoke the core log callback registered with the FFI as the library would.""" + callback = pact_ffi._log_callback # noqa: SLF001 + assert callback is not None + callback( + *(s.encode("utf-8") for s in (log_id, test_run_id, level, target, message)) + ) + + +def emit_plugin( + plugin_instance_id: str = "instance", + test_run_id: str = "", + level: str = "INFO", + target: str = "", + message: str = "hello", +) -> None: + """Invoke the plugin log callback registered with the FFI as the library would.""" + callback = pact_ffi._plugin_log_callback # noqa: SLF001 + assert callback is not None + callback( + *( + s.encode("utf-8") + for s in (plugin_instance_id, test_run_id, level, target, message) + ) + ) + + +@pytest.fixture +def uninitialised(monkeypatch: pytest.MonkeyPatch) -> list[str]: + """ + Reset the initialisation flag and stub the FFI calls, recording their names. + + The FFI logger can be applied once per process, so the initialisation path + is exercised against stubs. + """ + calls: list[str] = [] + monkeypatch.setattr(pact_logging, "_initialised", False) + monkeypatch.setattr(pact_logging, "_level_warned", False) + monkeypatch.setattr(pact_logging, "_applied_level", logging.CRITICAL) + monkeypatch.setattr(atexit, "register", lambda *_a, **_k: None) + for name in ( + "set_log_callback_level", + "log_to_buffer", + "register_log_callback", + "register_plugin_log_callback", + ): + monkeypatch.setattr(pact_ffi, name, lambda *_a, _n=name, **_k: calls.append(_n)) + return calls + + +class TestLevels: + """Tests for the level mappings.""" + + def test_trace_is_registered(self) -> None: + assert logging.getLevelName(pact_logging.TRACE) == "TRACE" + + @pytest.mark.parametrize( + ("level", "expected"), + [ + pytest.param(pact_logging.TRACE, pact_ffi.LevelFilter.TRACE, id="trace"), + pytest.param(logging.DEBUG, pact_ffi.LevelFilter.DEBUG, id="debug"), + pytest.param(logging.INFO, pact_ffi.LevelFilter.INFO, id="info"), + pytest.param(logging.WARNING, pact_ffi.LevelFilter.WARN, id="warning"), + pytest.param(logging.ERROR, pact_ffi.LevelFilter.ERROR, id="error"), + pytest.param(logging.CRITICAL, pact_ffi.LevelFilter.ERROR, id="critical"), + pytest.param(15, pact_ffi.LevelFilter.DEBUG, id="between-debug-and-info"), + ], + ) + def test_to_ffi_level(self, level: int, expected: pact_ffi.LevelFilter) -> None: + assert pact_logging.to_ffi_level(level) == expected + + @pytest.mark.parametrize( + ("level", "expected"), + [ + pytest.param("TRACE", pact_logging.TRACE, id="trace"), + pytest.param("DEBUG", logging.DEBUG, id="debug"), + pytest.param("INFO", logging.INFO, id="info"), + pytest.param("WARN", logging.WARNING, id="warn"), + pytest.param("ERROR", logging.ERROR, id="error"), + pytest.param("warn", logging.WARNING, id="lowercase"), + pytest.param("BOGUS", logging.INFO, id="unknown"), + ], + ) + def test_from_ffi_level(self, level: str, expected: int) -> None: + assert pact_logging.from_ffi_level(level) == expected + + +class TestFfiLevel: + """Tests for [`_ffi_level`][pact.logging._ffi_level].""" + + @pytest.fixture(autouse=True) + def _reset_loggers(self) -> Generator[None, None, None]: + yield + logging.getLogger("pact.ffi").setLevel(logging.NOTSET) + logging.getLogger("pact.plugins").setLevel(logging.NOTSET) + + def test_default_when_unset(self) -> None: + assert pact_logging._ffi_level() == pact_logging.to_ffi_level( # noqa: SLF001 + pact_logging.DEFAULT_LEVEL + ) + + def test_most_verbose_explicit_level_wins(self) -> None: + logging.getLogger("pact.ffi").setLevel(logging.ERROR) + logging.getLogger("pact.plugins").setLevel(pact_logging.TRACE) + assert pact_logging._ffi_level() == pact_ffi.LevelFilter.TRACE # noqa: SLF001 + + def test_single_explicit_level(self) -> None: + logging.getLogger("pact.ffi").setLevel(logging.ERROR) + assert pact_logging._ffi_level() == pact_ffi.LevelFilter.ERROR # noqa: SLF001 + + +class TestEnsureInitialised: + """Tests for [`ensure_initialised`][pact.logging.ensure_initialised].""" + + def test_applies_logger_and_registers_callbacks( + self, uninitialised: list[str] + ) -> None: + pact_logging.ensure_initialised() + assert uninitialised == [ + "set_log_callback_level", + "log_to_buffer", + "register_log_callback", + "register_plugin_log_callback", + ] + + @pytest.mark.parametrize( + ("level", "expected"), + [ + pytest.param( + logging.NOTSET, + pact_logging.to_ffi_level(pact_logging.DEFAULT_LEVEL), + id="default", + ), + pytest.param(logging.DEBUG, pact_ffi.LevelFilter.DEBUG, id="debug"), + pytest.param(pact_logging.TRACE, pact_ffi.LevelFilter.TRACE, id="trace"), + ], + ) + def test_applies_forwarding_level( + self, + uninitialised: list[str], + monkeypatch: pytest.MonkeyPatch, + level: int, + expected: pact_ffi.LevelFilter, + ) -> None: + applied: list[object] = [] + monkeypatch.setattr(pact_ffi, "set_log_callback_level", applied.append) + ffi_logger = logging.getLogger("pact.ffi") + ffi_logger.setLevel(level) + try: + pact_logging.ensure_initialised() + finally: + ffi_logger.setLevel(logging.NOTSET) + assert applied == [expected] + assert "log_to_buffer" in uninitialised + + def test_registers_shutdown_hook( + self, uninitialised: list[str], monkeypatch: pytest.MonkeyPatch + ) -> None: + registered: list[object] = [] + monkeypatch.setattr(atexit, "register", registered.append) + + pact_logging.ensure_initialised() + assert registered == [pact_logging._shutdown] # noqa: SLF001 + + del uninitialised[:] + pact_logging._shutdown() # noqa: SLF001 + assert uninitialised == [ + "set_log_callback_level", + "register_log_callback", + "register_plugin_log_callback", + ] + + def test_shutdown_swallows_errors( + self, uninitialised: list[str], monkeypatch: pytest.MonkeyPatch + ) -> None: + def fail(*_a: object, **_k: object) -> None: + raise RuntimeError + + monkeypatch.setattr(pact_ffi, "set_log_callback_level", fail) + pact_logging._shutdown() # noqa: SLF001 + assert uninitialised == [ + "register_log_callback", + "register_plugin_log_callback", + ] + + def test_is_idempotent(self, uninitialised: list[str]) -> None: + pact_logging.ensure_initialised() + pact_logging.ensure_initialised() + assert len(uninitialised) == 4 + + def test_warns_once_when_level_raised_later( + self, + uninitialised: list[str], + caplog: pytest.LogCaptureFixture, + ) -> None: + pact_logging.ensure_initialised() + with caplog.at_level(pact_logging.TRACE, logger="pact.ffi"): + pact_logging.ensure_initialised() + pact_logging.ensure_initialised() + + applied = pact_logging.to_ffi_level(pact_logging.DEFAULT_LEVEL) + warnings = [r for r in caplog.records if r.name == "pact"] + assert len(warnings) == 1 + assert f"forwarded at {applied.name}" in warnings[0].getMessage() + assert len(uninitialised) == 4 + + def test_silent_when_level_unchanged( + self, + uninitialised: list[str], + caplog: pytest.LogCaptureFixture, + ) -> None: + pact_logging.ensure_initialised() + with caplog.at_level(logging.WARNING, logger="pact.ffi"): + pact_logging.ensure_initialised() + assert not [r for r in caplog.records if r.name == "pact"] + assert uninitialised + + def test_warns_when_logger_already_applied( + self, + uninitialised: list[str], + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, + ) -> None: + def fail(*_a: object, **_k: object) -> None: + msg = "There was an unknown error setting the logger." + raise RuntimeError(msg) + + monkeypatch.setattr(pact_ffi, "log_to_buffer", fail) + with caplog.at_level(logging.WARNING, logger="pact"): + pact_logging.ensure_initialised() + + assert [r.levelno for r in caplog.records] == [logging.WARNING] + assert "configured externally" in caplog.records[0].getMessage() + assert uninitialised[-2:] == [ + "register_log_callback", + "register_plugin_log_callback", + ] + + +class TestCallbacks: + """Tests for the records emitted by the FFI callbacks.""" + + @pytest.fixture(autouse=True) + def _initialised(self) -> None: + pact_logging.ensure_initialised() + + def test_core_record(self, caplog: pytest.LogCaptureFixture) -> None: + with caplog.at_level(pact_logging.TRACE, logger="pact.ffi"): + emit_core( + log_id="server-1", + test_run_id="run-1", + level="WARN", + target="pact_matching::matchers", + message="careful", + ) + + assert len(caplog.records) == 1 + record = caplog.records[0] + assert record.name == "pact.ffi.pact_matching::matchers" + assert record.levelno == logging.WARNING + assert record.getMessage() == "careful" + assert record.__dict__["test_run_id"] == "run-1" + assert record.__dict__["log_id"] == "server-1" + + def test_core_empty_strings_become_none( + self, caplog: pytest.LogCaptureFixture + ) -> None: + with caplog.at_level(pact_logging.TRACE, logger="pact.ffi"): + emit_core(level="TRACE") + + record = caplog.records[0] + assert record.levelno == pact_logging.TRACE + assert record.__dict__["test_run_id"] is None + assert record.__dict__["log_id"] is None + + def test_plugin_record(self, caplog: pytest.LogCaptureFixture) -> None: + with caplog.at_level(logging.DEBUG, logger="pact.plugins"): + emit_plugin("inst", "run-1", "ERROR", "plugin::mod", "boom") + + assert len(caplog.records) == 1 + record = caplog.records[0] + assert record.name == "pact.plugins" + assert record.levelno == logging.ERROR + assert record.getMessage() == "boom" + assert record.__dict__["plugin_instance_id"] == "inst" + assert record.__dict__["test_run_id"] == "run-1" + assert record.__dict__["plugin_target"] == "plugin::mod" + + def test_plugin_empty_strings_become_none( + self, caplog: pytest.LogCaptureFixture + ) -> None: + with caplog.at_level(logging.DEBUG, logger="pact.plugins"): + emit_plugin(test_run_id="", target="") + + record = caplog.records[0] + assert record.__dict__["test_run_id"] is None + assert record.__dict__["plugin_target"] is None + + def test_handler_exceptions_do_not_propagate( + self, + monkeypatch: pytest.MonkeyPatch, + capsys: pytest.CaptureFixture[str], + ) -> None: + """ + The Python callbacks swallow handler errors. + + The callbacks are invoked directly: the CFFI handle already discards + exceptions (printing a traceback to stderr), so driving it would not + exercise the guard inside the callbacks. + """ + + def boom(*_a: object, **_k: object) -> None: + raise RuntimeError + + monkeypatch.setattr(logging.getLogger("pact.ffi.x"), "log", boom) + monkeypatch.setattr(logging.getLogger("pact.plugins"), "log", boom) + pact_logging._core_callback("", "", "INFO", "x", "hello") # noqa: SLF001 + pact_logging._plugin_callback("instance", "", "INFO", "", "hello") # noqa: SLF001 + assert capsys.readouterr().err == "" + + +class TestSetTestRunId: + """Tests for [`set_test_run_id`][pact.logging.set_test_run_id].""" + + def test_set_and_clear(self, monkeypatch: pytest.MonkeyPatch) -> None: + calls: list[str | None] = [] + monkeypatch.setattr(pact_ffi, "set_test_run_id", calls.append) + pact_logging.set_test_run_id("tests/test_x.py::test_y") + pact_logging.set_test_run_id(None) + assert calls == ["tests/test_x.py::test_y", None] From 7b4a222c8b044868304801702e974017ce53428c Mon Sep 17 00:00:00 2001 From: JP-Ellis Date: Fri, 16 Oct 2026 10:56:36 +1100 Subject: [PATCH 02/12] feat: initialise Pact logging from Pact and Verifier Pact and Verifier call pact.logging.ensure_initialised on construction, so a test suite gets library and plugin logs through logging with no set-up of its own. ensure_initialised is a no-op past the first call in the process, while the FFI callbacks are process-wide. A test elsewhere in the suite that registers and deregisters its own callback leaves pact.logging's callbacks unregistered. TestCallbacks re-registers them after ensure_initialised so it does not depend on suite order. Signed-off-by: JP-Ellis Assisted-by: Claude Code:claude-opus-5-5 --- src/pact/pact.py | 13 +++++++++++-- src/pact/verifier.py | 3 +++ tests/test_logging.py | 6 ++++++ 3 files changed, 20 insertions(+), 2 deletions(-) diff --git a/src/pact/pact.py b/src/pact/pact.py index 8aba8db11..8703623fb 100644 --- a/src/pact/pact.py +++ b/src/pact/pact.py @@ -84,6 +84,7 @@ from pact.interaction._async_message_interaction import AsyncMessageInteraction from pact.interaction._http_interaction import HttpInteraction from pact.interaction._sync_message_interaction import SyncMessageInteraction +from pact.logging import ensure_initialised if TYPE_CHECKING: from collections.abc import Callable, Generator @@ -140,6 +141,8 @@ def __init__( msg = "Provider name cannot be empty." raise ValueError(msg) + ensure_initialised() + self._consumer = consumer self._provider = provider self._interactions: set[Interaction] = set() @@ -756,8 +759,14 @@ def logs(self) -> str | None: Logs from the server. This is a string containing the logs from the server. If there are no - logs, then this is `None`. For this to be populated, the logging must - be configured to make use of the internal buffer. + logs, then this is `None`. + + Pact Python forwards the server's logs to the `logging` module, where + the records of one server share a `log_id` attribute. It applies the + library's in-memory buffer at `OFF`, so this is normally `None`. The + buffer is only populated when + [`pact_ffi.log_to_buffer`][pact_ffi.log_to_buffer] is called before + the first `Pact` is created. Raises: RuntimeError: diff --git a/src/pact/verifier.py b/src/pact/verifier.py index f793c34db..e744e9a16 100644 --- a/src/pact/verifier.py +++ b/src/pact/verifier.py @@ -86,6 +86,7 @@ import pact_ffi from pact._util import apply_args, strip_url_credentials +from pact.logging import ensure_initialised from pact.types import ( UNSET, Message, @@ -237,6 +238,8 @@ def __init__(self, name: str, host: str | None = None) -> None: communicate with the provider. If not specified, the default value is `localhost`. """ + ensure_initialised() + self._name = name self._host = host or "localhost" self._handle = pact_ffi.verifier_new_for_application() diff --git a/tests/test_logging.py b/tests/test_logging.py index e28feeb82..4a779e75f 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -268,6 +268,12 @@ class TestCallbacks: @pytest.fixture(autouse=True) def _initialised(self) -> None: pact_logging.ensure_initialised() + # ensure_initialised() is a no-op past the first call in the process, + # so another test module may have since replaced the FFI callbacks + # with its own (e.g. to assert on deregistration). Re-register the + # module's own callbacks so these tests do not depend on suite order. + pact_ffi.register_log_callback(pact_logging._core_callback) # noqa: SLF001 + pact_ffi.register_plugin_log_callback(pact_logging._plugin_callback) # noqa: SLF001 def test_core_record(self, caplog: pytest.LogCaptureFixture) -> None: with caplog.at_level(pact_logging.TRACE, logger="pact.ffi"): From 0a8c84278b9572cef2e9489abe48ef804ce91a0c Mon Sep 17 00:00:00 2001 From: JP-Ellis Date: Fri, 16 Oct 2026 10:57:09 +1100 Subject: [PATCH 03/12] docs: describe logging through the standard logging module Rewrite the logging page around the automatic forwarding: the loggers and record attributes, controlling verbosity through logger levels, correlating records with a test run ID, and configuring the FFI's own sinks as the escape hatch. The examples no longer initialise FFI logging to stderr, as the library now does its own initialisation. Fix cross-reference syntax in src/pact/logging.py: `mkdocs build --strict` reported them unresolved. mkdocstrings' scoped_crossrefs resolves an unqualified reference relative to the referencing module, but a `pact.`-prefixed target from a module below the package root gets that prefix prepended again (e.g. `pact.Verifier` from `pact.logging` resolves to `pact.pact.Verifier`), so cross-module references need the path relative to the `pact` package instead of the full `pact.`-prefixed path. Within `pact/logging.py` itself, the module's own `import logging` shadows a relative `logging.x` self-reference, so those use the bare member name instead. Signed-off-by: JP-Ellis Assisted-by: Claude Code:claude-opus-5-5 --- docs/logging.md | 176 ++++++++---------- examples/conftest.py | 10 - examples/http/aiohttp_and_flask/conftest.py | 13 -- .../http/requests_and_fastapi/conftest.py | 13 -- .../service_consumer_provider/conftest.py | 15 -- examples/http/xml_example/conftest.py | 13 -- src/pact/logging.py | 13 +- 7 files changed, 80 insertions(+), 173 deletions(-) diff --git a/docs/logging.md b/docs/logging.md index 6fb46f28b..90b01eddb 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -1,124 +1,96 @@ -# Logging Configuration - -Pact Python uses the Rust FFI (Foreign Function Interface) library for its core functionality. While the Python code uses the standard library `logging` module, the underlying FFI cannot interface with that directly. This page explains how to configure FFI logging for debugging and troubleshooting. - -## Basic Configuration - -The simplest way to configure FFI logging is to use the [`log_to_stderr`][pact_ffi.log_to_stderr] function from the `pact_ffi` module. This directs all FFI log output to standard error. +# Logging + +Pact Python is built on the Pact FFI, a Rust library, and Pact plugins run as +separate processes. Neither writes to Python's `logging` module on its own, so +Pact Python forwards their log events for them. Nothing needs to be +configured: the first [`Pact`][pact.Pact] or [`Verifier`][pact.Verifier] +created in a process initialises the FFI and registers the forwarding. + +## Loggers + +| Logger | Source | +| --------------------- | --------------------------------------------------------------- | +| `pact.ffi.` | The Pact library, where `` is the Rust module path | +| `pact.plugins` | Plugins, whether written to their stderr or sent over the RPC | +| `pact.` | Pact Python itself, for example `pact.pact` or `pact.verifier` | +| `pact` | Pact Python's warnings about the logging set-up | + +Each record from the library carries `test_run_id` and `log_id` as +attributes. `test_run_id` is set on records emitted from the thread which +called into the library; `log_id` is the mock server ID, set on records +emitted while the server handles a request on one of its own threads, where +`test_run_id` is `None`. Each plugin record carries `plugin_instance_id`, +`test_run_id` and `plugin_target`. They can be included in a formatter. +Records from other loggers do not have them, so give the formatter a default: ```python -import pact_ffi - -pact_ffi.log_to_stderr("INFO") +handler = logging.StreamHandler() +handler.setFormatter( + logging.Formatter( + "%(levelname)s %(name)s [%(test_run_id)s] %(message)s", + defaults={"test_run_id": "-"}, + ) +) +logging.basicConfig(handlers=[handler]) ``` -### Log Levels - -The following log levels are available (from least to most verbose): +## Verbosity -- `"OFF"` - Disable all logging -- `"ERROR"` - Only error messages -- `"WARN"` - Warnings and errors -- `"INFO"` - Informational messages, warnings, and errors -- `"DEBUG"` - Debug messages and above -- `"TRACE"` - All messages including trace-level details - -## Recommended Setup with Pytest - -/// warning | One-time Initialization -The FFI logging can only be initialized **once** per process. Attempting to configure it multiple times will result in an error. For this reason, it's recommended to set up logging in a session-scoped fixture. -/// - -The recommended way to configure FFI logging in your test suite is to use a pytest fixture with `autouse=True` and `scope="session"` in your `conftest.py` file: +The library forwards events at the most verbose level set explicitly on the +`pact.ffi` and `pact.plugins` loggers, or at +[`DEFAULT_LEVEL`][pact.logging.DEFAULT_LEVEL] when neither is set: ```python -import pytest -import pact_ffi - +import logging -@pytest.fixture(autouse=True, scope="session") -def pact_logging(): - """Configure Pact FFI logging for the test session.""" - pact_ffi.log_to_stderr("INFO") +logging.getLogger("pact.ffi").setLevel(logging.INFO) ``` -This ensures that: +That level is fixed when the FFI is initialised, so set it before creating the +first `Pact` or `Verifier`, for example at the top of `conftest.py`. Standard +`logging` configuration then decides what is shown; under pytest, `log_level` +and `log_cli_level` apply as usual. -1. Logging is configured automatically for all tests -2. It's only initialized once at the start of the test session -3. All test output includes relevant Pact FFI logs - -## Advanced Configuration - -For more advanced use cases, the `pact_ffi` module provides additional logging functions: - -### Logging to a File - -/// note | Not Yet Implemented -The `log_to_file` function is currently not implemented in the Python bindings. If you need this feature, please open an issue on the [Pact Python GitHub repository](https://github.com/pact-foundation/pact-python/issues). -/// - -To direct logs to a file instead of stderr, you would use: +The library's `TRACE` level sits below `logging.DEBUG` and is exposed as +[`pact.logging.TRACE`][pact.logging.TRACE]: ```python -import pact_ffi +from pact.logging import TRACE -# This will be available in a future release -pact_ffi.log_to_file("/path/to/logfile.log", pact_ffi.LevelFilter.DEBUG) +logging.getLogger("pact.ffi").setLevel(TRACE) ``` -### Logging to a Buffer +## Correlating Logs with Tests + +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 +current thread which is reported as `test_run_id` on the library's records +from that thread and, because it is attached to every plugin request the +thread makes, on every plugin record. This keeps records apart when tests run +in parallel, or when a plugin's clean-up overlaps the start of the next test. +Mock server records carry `log_id` instead. + +## Configuring the FFI Directly + +The `pact_ffi` module exposes the library's own sinks. Calling +[`log_to_stderr`][pact_ffi.log_to_stderr] or +[`log_to_buffer`][pact_ffi.log_to_buffer] before the first `Pact` or +`Verifier` applies that sink instead of the silent one Pact Python uses. +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. The library's logger can be applied +once per process, so calling these after a `Pact` or `Verifier` exists fails +with "Logger already initialized". -For applications that need to capture and process logs programmatically, you can use [`log_to_buffer`][pact_ffi.log_to_buffer]: - -```python -import pact_ffi - -# Configure logging to an internal buffer -pact_ffi.log_to_buffer("DEBUG") -``` - -This is particularly useful for: - -- Capturing logs in CI/CD environments -- Including logs in test failure reports -- Processing or filtering log messages programmatically - -/// note | Retrieving Buffer Contents -The `fetch_log_buffer` function for retrieving buffered logs is currently not implemented in the Python bindings. If you need this feature, please open an issue on the [Pact Python GitHub repository](https://github.com/pact-foundation/pact-python/issues). -/// - -### Multiple Sinks - -/// note | Advanced Usage -The functions `logger_init`, `logger_attach_sink`, and `logger_apply` are currently not implemented in the Python bindings. If you need these features, please open an issue on the [Pact Python GitHub repository](https://github.com/pact-foundation/pact-python/issues). +/// note | Not Yet Implemented +`log_to_file`, `fetch_log_buffer`, `logger_init`, `logger_attach_sink` and +`logger_apply` are not implemented in the Python bindings. If you need one, +open an issue on the [Pact Python GitHub +repository](https://github.com/pact-foundation/pact-python/issues). /// -For the most advanced scenarios, the FFI supports configuring multiple log sinks simultaneously (e.g., logging to both stderr and a file). This requires using the lower-level `logger_init`, `logger_attach_sink`, and `logger_apply` functions, which are planned for future implementation. - -## Troubleshooting - -### "Logger already initialized" Error - -If you see an error about the logger already being initialized, it means you're trying to configure FFI logging more than once. Ensure that: - -1. You're using a session-scoped fixture as shown above -2. You're not calling any of the `log_to_*` functions multiple times in your code -3. If running tests multiple times in the same process (e.g., with pytest-xdist), the fixture scope is set correctly - -### No Log Output - -If you're not seeing any log output: - -1. Check that the log level is appropriate - `"ERROR"` will only show errors, while `"INFO"` or `"DEBUG"` will show more information -2. Verify that the logging is configured before any Pact operations are performed -3. For `log_to_file`, ensure the file path is writable and the directory exists - ## Further Information -For complete API documentation, see: - -- [`pact_ffi.log_to_stderr`][pact_ffi.log_to_stderr] -- [`pact_ffi.log_to_file`][pact_ffi.log_to_file] -- [`pact_ffi.log_to_buffer`][pact_ffi.log_to_buffer] +- [`pact.logging`][pact.logging] - [`pact_ffi.LevelFilter`][pact_ffi.LevelFilter] diff --git a/examples/conftest.py b/examples/conftest.py index 3ced5de4d..b304175c7 100644 --- a/examples/conftest.py +++ b/examples/conftest.py @@ -16,8 +16,6 @@ import pytest -import pact_ffi - EXAMPLE_DIR = Path(__file__).parent.resolve() @@ -25,11 +23,3 @@ def pacts_path() -> Path: """Fixture for the Pact directory.""" return EXAMPLE_DIR / "pacts" - - -@pytest.fixture(scope="session", autouse=True) -def _setup_pact_logging() -> None: - """ - Set up logging for the pact package. - """ - pact_ffi.log_to_stderr("INFO") diff --git a/examples/http/aiohttp_and_flask/conftest.py b/examples/http/aiohttp_and_flask/conftest.py index d8c4a164c..b304175c7 100644 --- a/examples/http/aiohttp_and_flask/conftest.py +++ b/examples/http/aiohttp_and_flask/conftest.py @@ -12,13 +12,10 @@ from __future__ import annotations -import contextlib from pathlib import Path import pytest -import pact_ffi - EXAMPLE_DIR = Path(__file__).parent.resolve() @@ -26,13 +23,3 @@ def pacts_path() -> Path: """Fixture for the Pact directory.""" return EXAMPLE_DIR / "pacts" - - -@pytest.fixture(scope="session", autouse=True) -def _setup_pact_logging() -> None: - """ - Set up logging for the pact package. - """ - # If the logger is already configured, this will raise a RuntimeError. - with contextlib.suppress(RuntimeError): - pact_ffi.log_to_stderr("INFO") diff --git a/examples/http/requests_and_fastapi/conftest.py b/examples/http/requests_and_fastapi/conftest.py index d8c4a164c..b304175c7 100644 --- a/examples/http/requests_and_fastapi/conftest.py +++ b/examples/http/requests_and_fastapi/conftest.py @@ -12,13 +12,10 @@ from __future__ import annotations -import contextlib from pathlib import Path import pytest -import pact_ffi - EXAMPLE_DIR = Path(__file__).parent.resolve() @@ -26,13 +23,3 @@ def pacts_path() -> Path: """Fixture for the Pact directory.""" return EXAMPLE_DIR / "pacts" - - -@pytest.fixture(scope="session", autouse=True) -def _setup_pact_logging() -> None: - """ - Set up logging for the pact package. - """ - # If the logger is already configured, this will raise a RuntimeError. - with contextlib.suppress(RuntimeError): - pact_ffi.log_to_stderr("INFO") diff --git a/examples/http/service_consumer_provider/conftest.py b/examples/http/service_consumer_provider/conftest.py index 0182939b6..eaf917e87 100644 --- a/examples/http/service_consumer_provider/conftest.py +++ b/examples/http/service_consumer_provider/conftest.py @@ -4,13 +4,10 @@ from __future__ import annotations -import contextlib from pathlib import Path import pytest -import pact_ffi - EXAMPLE_DIR = Path(__file__).parent.resolve() @@ -23,15 +20,3 @@ def pacts_path() -> Path: Path to the directory where Pact contract files are written. """ return EXAMPLE_DIR / "pacts" - - -@pytest.fixture(scope="session", autouse=True) -def _setup_pact_logging() -> None: - """ - Set up logging for the pact package. - """ - # If the logger is already configured (e.g., when running alongside other - # examples), log_to_stderr raises RuntimeError. We suppress it here so - # that the first configuration wins. - with contextlib.suppress(RuntimeError): - pact_ffi.log_to_stderr("INFO") diff --git a/examples/http/xml_example/conftest.py b/examples/http/xml_example/conftest.py index acb15b98f..3ea0a8b6c 100644 --- a/examples/http/xml_example/conftest.py +++ b/examples/http/xml_example/conftest.py @@ -7,13 +7,10 @@ from __future__ import annotations -import contextlib from pathlib import Path import pytest -import pact_ffi - EXAMPLE_DIR = Path(__file__).parent.resolve() @@ -21,13 +18,3 @@ def pacts_path() -> Path: """Fixture providing the path to the generated Pact contract files.""" return EXAMPLE_DIR / "pacts" - - -@pytest.fixture(scope="session", autouse=True) -def _setup_pact_logging() -> None: - """ - Set up logging for the pact package. - """ - # If the logger is already configured, this will raise a RuntimeError. - with contextlib.suppress(RuntimeError): - pact_ffi.log_to_stderr("INFO") diff --git a/src/pact/logging.py b/src/pact/logging.py index 380e107ce..8c7c8945c 100644 --- a/src/pact/logging.py +++ b/src/pact/logging.py @@ -3,7 +3,7 @@ The Pact FFI and Pact plugins run outside the Python interpreter, so their log output does not reach `logging` on its own. This module initialises the FFI -once, on the first use of [`Pact`][pact.Pact] or [`Verifier`][pact.Verifier], +once, on the first use of [`Pact`][pact.Pact] or [`Verifier`][verifier.Verifier], and re-emits every event through `logging`: - Events from the Pact library are emitted on the `pact.ffi` logger, with @@ -25,14 +25,13 @@ ``` The FFI forwards events at the most verbose level set explicitly on the -`pact.ffi` and `pact.plugins` loggers, or at -[`DEFAULT_LEVEL`][logging.DEFAULT_LEVEL] when neither is set. That level is -fixed when the FFI is initialised, so set logger levels before creating the -first `Pact` or `Verifier`. The Pact library's `TRACE` level is exposed as -[`TRACE`][logging.TRACE], below `logging.DEBUG`. +`pact.ffi` and `pact.plugins` loggers, or at [`DEFAULT_LEVEL`][DEFAULT_LEVEL] +when neither is set. That level is fixed when the FFI is initialised, so set +logger levels before creating the first `Pact` or `Verifier`. The Pact +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`][logging.set_test_run_id]. +run ID with [`set_test_run_id`][set_test_run_id]. Calling one of the `pact_ffi.log_to_*` functions before the first `Pact` or `Verifier` configures the FFI's own sink instead. Events are still forwarded From a6242f481b818997d1c27a287834994696a77501 Mon Sep 17 00:00:00 2001 From: JP-Ellis Date: Thu, 17 Sep 2026 23:42:10 +1000 Subject: [PATCH 04/12] feat: set the default Pact log forwarding level Observed DEBUG output from the consumer suite (tests/test_pact.py), provider verification (tests/test_verifier.py) and an HTTP example (examples/http/requests_and_fastapi) with --log-cli-level=DEBUG. In all three, DEBUG volume was dominated by "FFI function invoked" tracing on every call and per-request matching dumps (headers, body, matching rules) that add nothing once a test passes; running the fake plugin driver additionally showed a burst of hyper/rustls/reqwest transport chatter from the plugin driver's metrics beacon. INFO keeps the messages that matter (catalogue updates, plugin lifecycle, warnings and errors) without that noise, so DEFAULT_LEVEL is now logging.INFO. Signed-off-by: JP-Ellis Assisted-by: Claude Code:claude-opus-5 --- docs/logging.md | 33 +++++++++++++++++++++++++-------- src/pact/logging.py | 7 ++++++- 2 files changed, 31 insertions(+), 9 deletions(-) diff --git a/docs/logging.md b/docs/logging.md index 90b01eddb..d80be94e8 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -36,20 +36,37 @@ logging.basicConfig(handlers=[handler]) ## Verbosity -The library forwards events at the most verbose level set explicitly on the -`pact.ffi` and `pact.plugins` loggers, or at -[`DEFAULT_LEVEL`][pact.logging.DEFAULT_LEVEL] when neither is set: +By default, the library forwards events at `INFO` and above +([`DEFAULT_LEVEL`][pact.logging.DEFAULT_LEVEL]). Its `DEBUG` output is much +noisier: it traces every FFI call, dumps each request as it is matched and, +once a plugin is loaded, includes the transport logs of `hyper`, `rustls` and +`reqwest`. To see it when debugging a failure, set the level of the `pact.ffi` +logger: ```python import logging -logging.getLogger("pact.ffi").setLevel(logging.INFO) +logging.getLogger("pact.ffi").setLevel(logging.DEBUG) ``` -That level is fixed when the FFI is initialised, so set it before creating the -first `Pact` or `Verifier`, for example at the top of `conftest.py`. Standard -`logging` configuration then decides what is shown; under pytest, `log_level` -and `log_cli_level` apply as usual. +/// warning | Set the Level Before the First `Pact` +The forwarding level is fixed when the first `Pact` or `Verifier` is created, +and cannot be changed afterwards. Set it before then, for example at the top of +`conftest.py`. A more verbose level set later only logs a warning on the `pact` +logger, once. In particular, `caplog.set_level` within a test cannot show +records which were never forwarded. +/// + +Forwarded records are handled like any others, so the `logging` configuration +decides which are shown. Under pytest, `log_level` and `log_cli_level` apply as +usual. With no logging configured at all, Python's last-resort handler writes +warnings and errors to stderr. To silence them, add a handler such as +`logging.NullHandler()` to the `pact` logger. + +The `pact.ffi` and `pact.plugins` loggers share a single forwarding level: the +more verbose of the levels set on them. Setting only `pact.plugins` to `DEBUG` +therefore forwards the library's `DEBUG` events as well. Python discards them, +but only after each one has been passed from the library to the interpreter. The library's `TRACE` level sits below `logging.DEBUG` and is exposed as [`pact.logging.TRACE`][pact.logging.TRACE]: diff --git a/src/pact/logging.py b/src/pact/logging.py index 8c7c8945c..47650024a 100644 --- a/src/pact/logging.py +++ b/src/pact/logging.py @@ -78,10 +78,15 @@ ): logging.addLevelName(TRACE, "TRACE") -DEFAULT_LEVEL = logging.DEBUG +DEFAULT_LEVEL = logging.INFO """ Level at which the Pact library forwards events when neither the `pact.ffi` nor the `pact.plugins` logger has an explicit level. + +`INFO` is the default because the library's `DEBUG` output is dominated by +per-FFI-call tracing, per-request matching dumps and, when a plugin is +loaded, transport chatter from `hyper`, `rustls` and `reqwest`, none of +which helps once a test has already passed. """ _TO_FFI: list[tuple[int, pact_ffi.LevelFilter]] = [ From fe6ea81c063a9585528b99869c971e8525cf0bf2 Mon Sep 17 00:00:00 2001 From: JP-Ellis Date: Fri, 18 Sep 2026 00:00:57 +1000 Subject: [PATCH 05/12] test: cover Pact library log forwarding end to end The unit tests in tests/test_logging.py drive the CFFI callback objects directly, so none of them proves that the Pact library reaches the Python callback from its own threads. Add a consumer test which starts a mock server, makes one request through it and asserts that records arrived on a pact.ffi.* logger with a mock server ID as log_id. The assertions stop at "some records, at least one with a log_id"; the count and wording of the library's events vary between Pact FFI releases and would make the test brittle. Signed-off-by: JP-Ellis Assisted-by: Claude Code:claude-opus-5 --- tests/test_logging.py | 27 +++++++++++++++++++++++++++ 1 file changed, 27 insertions(+) diff --git a/tests/test_logging.py b/tests/test_logging.py index 4a779e75f..e1eea67b0 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -8,9 +8,11 @@ import logging from typing import TYPE_CHECKING +import aiohttp import pytest import pact_ffi +from pact import Pact from pact import logging as pact_logging if TYPE_CHECKING: @@ -350,6 +352,31 @@ def boom(*_a: object, **_k: object) -> None: assert capsys.readouterr().err == "" +class TestEndToEnd: + """Records forwarded from the Pact library during a consumer test.""" + + @pytest.mark.asyncio + async def test_mock_server_records(self, caplog: pytest.LogCaptureFixture) -> None: + caplog.set_level(logging.INFO, logger="pact.ffi") + pact = Pact("consumer", "provider") + ( + pact + .upon_receiving("a request") + .with_request("GET", "/") + .will_respond_with(200) + ) + with pact.serve() as srv: + async with ( + aiohttp.ClientSession(srv.url) as session, + session.get("/") as resp, + ): + assert resp.status == 200 + + records = [r for r in caplog.records if r.name.startswith("pact.ffi.")] + assert records + assert any(r.__dict__.get("log_id") is not None for r in records) + + class TestSetTestRunId: """Tests for [`set_test_run_id`][pact.logging.set_test_run_id].""" From 1143671c84701534f10c87fe368525a18a1a4279 Mon Sep 17 00:00:00 2001 From: JP-Ellis Date: Fri, 16 Oct 2026 10:58:03 +1100 Subject: [PATCH 06/12] chore: require pact-python-ffi 0.5.12 pact.logging needs `register_log_callback` and `set_log_callback_level`, added in Pact FFI 0.5.9. Under the previous `~=0.5.0` specifier, an older pact-python-ffi raised AttributeError on the first `Pact` or `Verifier`. 0.5.12 makes deregistering a log callback safe while another thread is still running it. pact.logging deregisters both callbacks at interpreter exit, when a mock server or plugin thread may still be emitting. Signed-off-by: JP-Ellis Assisted-by: Claude Code:claude-opus-5-5 --- pyproject.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pyproject.toml b/pyproject.toml index 742535444..24f072bc6 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -41,7 +41,7 @@ requires-python = ">=3.11" # - A minor version address vulnerability which directly impacts Pact Python dependencies = [ # Pact dependencies - "pact-python-ffi~=0.5.0", + "pact-python-ffi~=0.5.12", "typing-extensions~=4.0 ; python_version < '3.13'", # External dependencies ] From 1e16d75a9b3f5b12e9c00c91ab79713db4f7d91a Mon Sep 17 00:00:00 2001 From: JP-Ellis Date: Fri, 16 Oct 2026 10:59:54 +1100 Subject: [PATCH 07/12] feat: replace pact_ffi logger set-up with a warning Test suites used to call `pact_ffi.log_to_stderr`, usually from a session-scoped conftest fixture, to see the Pact library's output. Pact Python now applies the library's logger on the first `Pact` or `Verifier`, and that logger can be applied once per process. An existing call made after that point failed with "Logger already initialized". Importing `pact` now replaces `init`, `init_with_log_level`, `log_to_stderr`, `log_to_stdout` and `log_to_file` on `pact_ffi` with functions which emit a `UserWarning` and return without applying anything. A suite which still calls one of them keeps running, and the warning asks for the call to be removed in favour of `logging` configuration. A call made before `pact` is imported still applies the library's own sink, which Pact Python keeps and warns about on the `pact` logger, as before. `log_to_buffer` is left in place, since pact.logging applies its silent sink through it. The consumer and provider guides no longer recommend `log_to_stderr`, and the logging page explains the change and how to get the library's output on stderr through `logging`. Signed-off-by: JP-Ellis Assisted-by: Claude Code:claude-opus-5-5 --- docs/consumer.md | 19 ++++++------ docs/logging.md | 44 ++++++++++++++++------------ docs/provider.md | 19 ++++++------ src/pact/logging.py | 67 +++++++++++++++++++++++++++++++++++++++---- tests/test_logging.py | 40 ++++++++++++++++++++++++++ 5 files changed, 145 insertions(+), 44 deletions(-) diff --git a/docs/consumer.md b/docs/consumer.md index d23629556..7a4f8da2f 100644 --- a/docs/consumer.md +++ b/docs/consumer.md @@ -194,22 +194,21 @@ When the mock service is started with `pact.serve()`, it will handle requests fo ## Logging -To enable logging for debugging and troubleshooting, configure the FFI (Foreign Function Interface) logging using [`pact_ffi.log_to_stderr`][pact_ffi.log_to_stderr]. This is particularly useful when you need to understand what's happening inside the mock service or diagnose issues with your tests. +Pact Python logs through Python's standard `logging` module, so no set-up is needed. Records are emitted on three groups of loggers: -The recommended approach is to set up logging in a pytest fixture within your `conftest.py`: +- `pact` and `pact.`, such as `pact.pact`, for Pact Python itself. +- `pact.ffi`, for the mock server and the rest of the Pact library. +- `pact.plugins`, for plugins. -```python -import pytest -import pact_ffi +Under pytest, warnings and errors appear in the captured log of a failing test. Set pytest's `log_level` to `INFO` to capture the other records too. To see more detail when diagnosing a failure, lower the level before creating the first `Pact`: +```python +import logging -@pytest.fixture(autouse=True, scope="session") -def pact_logging(): - """Configure Pact FFI logging for the test session.""" - pact_ffi.log_to_stderr("INFO") +logging.getLogger("pact.ffi").setLevel(logging.DEBUG) ``` -For more information on logging configuration, including advanced options and troubleshooting, see the [Logging Configuration](logging.md) page. +See [Logging](logging.md) for the full list of loggers, the attributes on each record, and how to migrate from `pact_ffi.log_to_stderr`. ## Mock Service diff --git a/docs/logging.md b/docs/logging.md index d80be94e8..8f467051b 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -88,24 +88,32 @@ thread makes, on every plugin record. This keeps records apart when tests run in parallel, or when a plugin's clean-up overlaps the start of the next test. Mock server records carry `log_id` instead. -## Configuring the FFI Directly - -The `pact_ffi` module exposes the library's own sinks. Calling -[`log_to_stderr`][pact_ffi.log_to_stderr] or -[`log_to_buffer`][pact_ffi.log_to_buffer] before the first `Pact` or -`Verifier` applies that sink instead of the silent one Pact Python uses. -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. The library's logger can be applied -once per process, so calling these after a `Pact` or `Verifier` exists fails -with "Logger already initialized". - -/// note | Not Yet Implemented -`log_to_file`, `fetch_log_buffer`, `logger_init`, `logger_attach_sink` and -`logger_apply` are not implemented in the Python bindings. If you need one, -open an issue on the [Pact Python GitHub -repository](https://github.com/pact-foundation/pact-python/issues). -/// +## Migrating from `pact_ffi.log_to_stderr` + +Earlier releases left the library's logging unconfigured, and test suites +called [`pact_ffi.log_to_stderr`][pact_ffi.log_to_stderr], typically from a +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. + +To keep seeing the library's output on stderr, attach a handler through +`logging`: + +```python +import logging + +logging.basicConfig(level=logging.INFO) +``` + +Under pytest, `--log-cli-level=INFO` shows the records as each test runs. ## Further Information diff --git a/docs/provider.md b/docs/provider.md index 5b01087d1..af3be614c 100644 --- a/docs/provider.md +++ b/docs/provider.md @@ -135,22 +135,21 @@ More information on the selector options is available in the [API reference][pac ## Logging -To enable logging for debugging and troubleshooting, configure the FFI (Foreign Function Interface) logging using [`pact_ffi.log_to_stderr`][pact_ffi.log_to_stderr]. This is particularly useful when you need to understand what's happening during provider verification or diagnose issues with provider state handlers. +Pact Python logs through Python's standard `logging` module, so no set-up is needed. Records are emitted on three groups of loggers: -The recommended approach is to set up logging in a pytest fixture within your `conftest.py`: +- `pact` and `pact.`, such as `pact.verifier`, for Pact Python itself. +- `pact.ffi`, for the verifier and the rest of the Pact library. +- `pact.plugins`, for plugins. -```python -import pytest -import pact_ffi +Under pytest, warnings and errors appear in the captured log of a failing test. Set pytest's `log_level` to `INFO` to capture the other records too. To see more detail when diagnosing a failure, lower the level before creating the first `Verifier`: +```python +import logging -@pytest.fixture(autouse=True, scope="session") -def pact_logging(): - """Configure Pact FFI logging for the test session.""" - pact_ffi.log_to_stderr("INFO") +logging.getLogger("pact.ffi").setLevel(logging.DEBUG) ``` -For more information on logging configuration, including advanced options and troubleshooting, see the [Logging Configuration](logging.md) page. +See [Logging](logging.md) for the full list of loggers, the attributes on each record, and how to migrate from `pact_ffi.log_to_stderr`. ### Publishing Results diff --git a/src/pact/logging.py b/src/pact/logging.py index 47650024a..a6c85b259 100644 --- a/src/pact/logging.py +++ b/src/pact/logging.py @@ -33,10 +33,13 @@ 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]. -Calling one of the `pact_ffi.log_to_*` functions before the first `Pact` or -`Verifier` configures the FFI's own sink instead. Events are still forwarded -to `logging`, at the more restrictive of that sink's level and the level -above, and a warning is emitted on the `pact` logger. +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. """ from __future__ import annotations @@ -45,9 +48,14 @@ import contextlib import logging import threading +import warnings +from typing import TYPE_CHECKING import pact_ffi +if TYPE_CHECKING: + from collections.abc import Callable + __all__ = [ "DEFAULT_LEVEL", "TRACE", @@ -233,8 +241,9 @@ def ensure_initialised() -> None: `pact.plugins` logger logs a warning on the `pact` logger, once. If a logger was already applied, through one of the `pact_ffi.log_to_*` - functions, a warning is logged on the `pact` logger and the callbacks are - registered against that logger instead. + functions called before `pact` was imported, a warning is logged on the + `pact` logger and the callbacks are registered against that logger + instead. """ global _initialised, _applied_level, _level_warned # noqa: PLW0603 @@ -286,6 +295,52 @@ def _shutdown() -> None: pact_ffi.register_plugin_log_callback(None) +# MARK: FFI logger stand-ins + +_REPLACED_FFI_FUNCTIONS = ( + "init", + "init_with_log_level", + "log_to_stderr", + "log_to_stdout", + "log_to_file", +) + + +def _stand_in(name: str) -> Callable[..., None]: + """ + Create a replacement for a `pact_ffi` function which applies a logger. + + 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 + initialized" error. + + Args: + name: + Name of the `pact_ffi` function being replaced. + + Returns: + A function accepting any arguments, which emits a `UserWarning` and + returns `None`. + """ + + def stand_in(*_args: object, **_kwargs: object) -> None: + warnings.warn( + f"pact_ffi.{name} has no effect: Pact Python forwards the Pact " + "library's logs to the logging module. Remove the call and set the " + "levels of the 'pact.ffi' and 'pact.plugins' loggers instead.", + UserWarning, + stacklevel=2, + ) + + stand_in.__name__ = stand_in.__qualname__ = name + return stand_in + + +for _name in _REPLACED_FFI_FUNCTIONS: + setattr(pact_ffi, _name, _stand_in(_name)) + + # MARK: Test Run ID diff --git a/tests/test_logging.py b/tests/test_logging.py index e1eea67b0..cc88bcfaf 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -6,6 +6,9 @@ import atexit import logging +import subprocess +import sys +import textwrap from typing import TYPE_CHECKING import aiohttp @@ -352,6 +355,43 @@ def boom(*_a: object, **_k: object) -> None: assert capsys.readouterr().err == "" +class TestFfiStandIns: + """The `pact_ffi` functions which apply a logger, once `pact` is imported.""" + + @pytest.mark.parametrize("name", pact_logging._REPLACED_FFI_FUNCTIONS) # noqa: SLF001 + def test_warns_at_caller(self, name: str) -> None: + with pytest.warns(UserWarning, match=rf"pact_ffi\.{name} has no effect") as w: + result = getattr(pact_ffi, name)("INFO") + + assert result is None + assert w[0].filename == __file__ + + def test_does_not_apply_a_logger(self) -> None: + # Applying a logger is permanent for the process, so the test runs in a + # separate interpreter. The logger can be applied once, so the final + # `log_to_buffer` only succeeds if the stand-ins applied nothing. + script = textwrap.dedent( + """ + import warnings + + import pact_ffi + import pact + + warnings.simplefilter("ignore") + pact_ffi.log_to_stderr("INFO") + pact_ffi.init_with_log_level("INFO") + pact_ffi.init("LOG_LEVEL") + pact_ffi.log_to_buffer("OFF") + """ + ) + subprocess.run( # noqa: S603 + [sys.executable, "-c", script], + check=True, + capture_output=True, + text=True, + ) + + class TestEndToEnd: """Records forwarded from the Pact library during a consumer test.""" From adc719574b2d1b8a6c0da2fb7485d9698c55adc4 Mon Sep 17 00:00:00 2001 From: JP-Ellis Date: Fri, 16 Oct 2026 11:01:29 +1100 Subject: [PATCH 08/12] docs: describe log_id during provider verification Pact FFI reports `verify:` as the log ID of events emitted while verifying a provider, alongside the mock server ID while a mock server handles a request. The verifier also generates its own test run ID for the verification, which most of its records carry in place of the ID set with `set_test_run_id`. Describe both on the logging page, in the pact.logging module docstring and in `set_test_run_id`. Records from the library's own threads are grouped by `log_id`, not `test_run_id`. Cover the verification path end to end, asserting that a record arrives with `log_id == "verify:provider"`. Signed-off-by: JP-Ellis Assisted-by: Claude Code:claude-opus-5-5 --- docs/logging.md | 27 +++++++++++++++++++-------- src/pact/logging.py | 21 ++++++++++++++------- tests/test_logging.py | 34 +++++++++++++++++++++++++++++++++- 3 files changed, 66 insertions(+), 16 deletions(-) diff --git a/docs/logging.md b/docs/logging.md index 8f467051b..85afb37bc 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -15,13 +15,21 @@ created in a process initialises the FFI and registers the forwarding. | `pact.` | Pact Python itself, for example `pact.pact` or `pact.verifier` | | `pact` | Pact Python's warnings about the logging set-up | -Each record from the library carries `test_run_id` and `log_id` as -attributes. `test_run_id` is set on records emitted from the thread which -called into the library; `log_id` is the mock server ID, set on records -emitted while the server handles a request on one of its own threads, where -`test_run_id` is `None`. Each plugin record carries `plugin_instance_id`, -`test_run_id` and `plugin_target`. They can be included in a formatter. -Records from other loggers do not have them, so give the formatter a default: +Each record from the library carries `log_id` and `test_run_id` as +attributes: + +- `log_id` identifies the operation which emitted the event: the mock + server ID while the server handles a request, or `verify:` + while verifying a provider. It is `None` otherwise. +- `test_run_id` is the ID set with + [`set_test_run_id`][pact.logging.set_test_run_id] on the thread which + emitted the event. Records from the mock server's threads have none. + While a provider is verified, most records carry an ID which the + verifier generates for the run. + +Each plugin record carries `plugin_instance_id`, `test_run_id` and +`plugin_target`. These attributes can be included in a formatter. Records from +other loggers do not have them, so give the formatter a default: ```python handler = logging.StreamHandler() @@ -86,7 +94,10 @@ current thread which is reported as `test_run_id` on the library's records from that thread and, because it is attached to every plugin request the thread makes, on every plugin record. This keeps records apart when tests run in parallel, or when a plugin's clean-up overlaps the start of the next test. -Mock server records carry `log_id` instead. + +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:`. ## Migrating from `pact_ffi.log_to_stderr` diff --git a/src/pact/logging.py b/src/pact/logging.py index a6c85b259..e7580a3d2 100644 --- a/src/pact/logging.py +++ b/src/pact/logging.py @@ -8,10 +8,12 @@ - Events from the Pact library are emitted on the `pact.ffi` logger, with the Rust module path appended (for example - `pact.ffi.pact_matching::matchers`). Each record carries `test_run_id` - (for events emitted from the calling thread) and `log_id` (the mock - server ID, for events emitted while handling a request) as extra - attributes. + `pact.ffi.pact_matching::matchers`). Each record carries + `log_id` and `test_run_id` as extra attributes. `log_id` identifies the + operation which emitted the event: the mock server ID while the server + handles a request, or `verify:` while verifying a + provider. `test_run_id` is the ID set on the emitting thread with + [`set_test_run_id`][set_test_run_id]. - Events from plugins are emitted on the `pact.plugins` logger, with `plugin_instance_id`, `test_run_id` and `plugin_target` as extra attributes. @@ -351,9 +353,14 @@ def set_test_run_id(test_run_id: str | None) -> None: The ID is reported as the `test_run_id` attribute on the records the Pact library emits from the current thread. It is also attached to every request sent to a plugin from the current thread, so every plugin record - carries it. Records emitted while the mock server handles a request come - from the server's own threads; they carry the mock server ID as `log_id` - and no `test_run_id`. + carries it. + + Records from the library's own threads do not carry this ID, and are + identified by their `log_id` instead. While the mock server handles a + request, `log_id` is the mock server ID and `test_run_id` is `None`. + While a provider is verified, `log_id` is `verify:` and + most records carry an ID which the verifier generates for the run as + `test_run_id`. Args: test_run_id: diff --git a/tests/test_logging.py b/tests/test_logging.py index cc88bcfaf..62516be8d 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -15,11 +15,12 @@ import pytest import pact_ffi -from pact import Pact +from pact import Pact, Verifier from pact import logging as pact_logging if TYPE_CHECKING: from collections.abc import Generator + from pathlib import Path def emit_core( @@ -416,6 +417,37 @@ async def test_mock_server_records(self, caplog: pytest.LogCaptureFixture) -> No assert records assert any(r.__dict__.get("log_id") is not None for r in records) + def test_verifier_records( + self, + caplog: pytest.LogCaptureFixture, + tmp_path: Path, + ) -> None: + caplog.set_level(logging.INFO, logger="pact.ffi") + pact = Pact("consumer", "provider") + ( + pact + .upon_receiving("a request") + .with_request("GET", "/") + .will_respond_with(200) + ) + pact.write_file(tmp_path) + + # The mock server stands in for the provider, so it satisfies the + # interaction it was built from. + with pact.serve() as srv: + ( + Verifier("provider") + .add_transport(url=srv.url) + .add_source(tmp_path / "consumer-provider.json") + .verify() + ) + + assert any( + r.name.startswith("pact.ffi.") + and r.__dict__.get("log_id") == "verify:provider" + for r in caplog.records + ) + class TestSetTestRunId: """Tests for [`set_test_run_id`][pact.logging.set_test_run_id].""" From e32cb9aa74c703db57a062bd1169920fb21c19b9 Mon Sep 17 00:00:00 2001 From: JP-Ellis Date: Fri, 16 Oct 2026 11:01:52 +1100 Subject: [PATCH 09/12] feat: name Pact library loggers with dotted module paths Events from the Pact library were emitted on `pact.ffi.` with the Rust module path as given, such as `pact.ffi.pact_matching::matchers`. The `logging` hierarchy only splits names on `.`, so that logger's parent was `pact.ffi` and a level set on `pact.ffi.pact_matching` did not reach it. Replace `::` with `.` in the target, so records from `pact_matching::matchers` go to `pact.ffi.pact_matching.matchers`, and one crate or module can be filtered on its own. Signed-off-by: JP-Ellis Assisted-by: Claude Code:claude-opus-5-5 --- docs/logging.md | 6 ++++++ src/pact/logging.py | 7 ++++--- tests/test_logging.py | 2 +- 3 files changed, 11 insertions(+), 4 deletions(-) diff --git a/docs/logging.md b/docs/logging.md index 85afb37bc..37165dbaf 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -15,6 +15,12 @@ created in a process initialises the FFI and registers the forwarding. | `pact.` | Pact Python itself, for example `pact.pact` or `pact.verifier` | | `pact` | Pact Python's warnings about the logging set-up | +The Rust module path's `::` separators become `.`, so the records from +`pact_matching::matchers` are emitted on `pact.ffi.pact_matching.matchers`, +and a level set on `pact.ffi.pact_matching` filters them. Which events the +library forwards at all is decided by the levels of `pact.ffi` and +`pact.plugins`, as described under [Verbosity](#verbosity). + Each record from the library carries `log_id` and `test_run_id` as attributes: diff --git a/src/pact/logging.py b/src/pact/logging.py index e7580a3d2..f1cc94c5d 100644 --- a/src/pact/logging.py +++ b/src/pact/logging.py @@ -7,8 +7,8 @@ and re-emits every event through `logging`: - Events from the Pact library are emitted on the `pact.ffi` logger, with - the Rust module path appended (for example - `pact.ffi.pact_matching::matchers`). Each record carries + the Rust module path appended and its `::` separators replaced by `.` + (for example `pact.ffi.pact_matching.matchers`). Each record carries `log_id` and `test_run_id` as extra attributes. `log_id` identifies the operation which emitted the event: the mock server ID while the server handles a request, or `verify:` while verifying a @@ -190,7 +190,8 @@ def _core_callback( # Runs on a thread owned by the Pact library; an exception here has nowhere # to go, so it is discarded. with contextlib.suppress(Exception): - logging.getLogger(f"pact.ffi.{target}" if target else "pact.ffi").log( + name = f"pact.ffi.{target.replace('::', '.')}" if target else "pact.ffi" + logging.getLogger(name).log( from_ffi_level(level), "%s", message, diff --git a/tests/test_logging.py b/tests/test_logging.py index 62516be8d..108ad3ef9 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -293,7 +293,7 @@ def test_core_record(self, caplog: pytest.LogCaptureFixture) -> None: assert len(caplog.records) == 1 record = caplog.records[0] - assert record.name == "pact.ffi.pact_matching::matchers" + assert record.name == "pact.ffi.pact_matching.matchers" assert record.levelno == logging.WARNING assert record.getMessage() == "careful" assert record.__dict__["test_run_id"] == "run-1" From a96a94355999343185f74eaac41f3939bd838a7a Mon Sep 17 00:00:00 2001 From: JP-Ellis Date: Fri, 16 Oct 2026 11:04:29 +1100 Subject: [PATCH 10/12] test: cover plugin log forwarding end to end A fake plugin under PACT_PLUGIN_DIR writes a line to stderr and exits without completing the handshake. The line arrives on `pact.plugins` with the plugin instance ID, and the driver's own records about loading the plugin carry the test run ID set on the calling thread. The plugin's stderr line has no test run ID: it is not tied to any request. The test run ID reaches a plugin only as part of a request, so only the log entries a plugin sends back for that request carry it. The logging page and `set_test_run_id` claimed every plugin record carried the ID; they now say which ones do. Signed-off-by: JP-Ellis Assisted-by: Claude Code:claude-opus-5-5 --- docs/logging.md | 9 ++++--- src/pact/logging.py | 5 ++-- tests/test_logging.py | 59 +++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 68 insertions(+), 5 deletions(-) diff --git a/docs/logging.md b/docs/logging.md index 37165dbaf..14bef8a8f 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -97,9 +97,12 @@ 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 current thread which is reported as `test_run_id` on the library's records -from that thread and, because it is attached to every plugin request the -thread makes, on every plugin record. This keeps records apart when tests run -in parallel, or when a plugin's clean-up overlaps the start of the next test. +from that thread. It is also attached to every plugin request the thread +makes, so the log entries a plugin sends back while handling that request +carry it too. Lines a plugin writes to its stderr carry no `test_run_id`; +`plugin_instance_id` identifies the plugin which wrote them. This keeps +records apart when tests run in parallel, or when a plugin's clean-up overlaps +the start of the next test. 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 diff --git a/src/pact/logging.py b/src/pact/logging.py index f1cc94c5d..fe6aed955 100644 --- a/src/pact/logging.py +++ b/src/pact/logging.py @@ -353,8 +353,9 @@ def set_test_run_id(test_run_id: str | None) -> None: The ID is reported as the `test_run_id` attribute on the records the Pact library emits from the current thread. It is also attached to every - request sent to a plugin from the current thread, so every plugin record - carries it. + request sent to a plugin from the current thread, so the log entries the + plugin sends back while handling that request carry it too. Lines a + plugin writes to its stderr do not. Records from the library's own threads do not carry this ID, and are identified by their `log_id` instead. While the mock server handles a diff --git a/tests/test_logging.py b/tests/test_logging.py index 108ad3ef9..c5c51c591 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -5,10 +5,12 @@ from __future__ import annotations import atexit +import json import logging import subprocess import sys import textwrap +import time from typing import TYPE_CHECKING import aiohttp @@ -448,6 +450,63 @@ def test_verifier_records( for r in caplog.records ) + @pytest.mark.skipif(sys.platform == "win32", reason="fake plugin is a shell script") + def test_plugin_records( + self, + caplog: pytest.LogCaptureFixture, + monkeypatch: pytest.MonkeyPatch, + tmp_path: Path, + ) -> None: + # A plugin which writes to stderr and exits without completing the + # handshake. The driver forwards its output before reporting the + # failed load. + plugin_dir = tmp_path / "fake-0.0.1" + plugin_dir.mkdir() + (plugin_dir / "pact-plugin.json").write_text( + json.dumps({ + "pluginInterfaceVersion": 1, + "name": "fake", + "version": "0.0.1", + "executableType": "exec", + "entryPoint": "fake-plugin", + }) + ) + entry_point = plugin_dir / "fake-plugin" + entry_point.write_text("#!/bin/sh\necho 'fake plugin starting' >&2\nexit 1\n") + entry_point.chmod(0o755) + monkeypatch.setenv("PACT_PLUGIN_DIR", str(tmp_path)) + monkeypatch.setenv("PACT_DO_NOT_TRACK", "true") + + pact = Pact("consumer", "provider").with_specification("V4") + pact_logging.set_test_run_id("test-plugin-records") + try: + with pytest.raises(RuntimeError, match="Failed to load the plugin fake"): + pact.using_plugin("fake", "0.0.1") + finally: + pact_logging.set_test_run_id(None) + + # The plugin's output is read on a separate thread, which may lag + # behind the failed load. + plugin_records: list[logging.LogRecord] = [] + deadline = time.monotonic() + 5 + while time.monotonic() < deadline: + plugin_records = [ + r + for r in caplog.records + if r.name == "pact.plugins" and r.getMessage() == "fake plugin starting" + ] + if plugin_records: + break + time.sleep(0.05) + + assert plugin_records + assert plugin_records[0].__dict__["plugin_instance_id"] + assert any( + r.name.startswith("pact.ffi.pact_plugin_driver.") + and r.__dict__.get("test_run_id") == "test-plugin-records" + for r in caplog.records + ) + class TestSetTestRunId: """Tests for [`set_test_run_id`][pact.logging.set_test_run_id].""" From d23a694e53388ec0b3a021a46344f2f5530121ab Mon Sep 17 00:00:00 2001 From: JP-Ellis Date: Wed, 21 Oct 2026 12:16:11 +1100 Subject: [PATCH 11/12] test: cover forwarding alongside an externally applied logger A suite which calls `pact_ffi.log_to_stderr` before Pact Python loads its logging integration keeps that sink. `ensure_initialised` then cannot apply its own logger, and logs a warning in its place. The existing test of that branch replaces the FFI calls with stubs. The new test runs a mock server in a separate interpreter, after a real `log_to_stderr` call. It checks that the warning is logged and that the library's events still reach `logging`. Applying the logger cannot be undone, which is why the test needs its own interpreter. Signed-off-by: JP-Ellis Assisted-by: Claude Code:claude-opus-5-5 --- tests/test_logging.py | 58 +++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 58 insertions(+) diff --git a/tests/test_logging.py b/tests/test_logging.py index c5c51c591..0b8c44c3a 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -517,3 +517,61 @@ def test_set_and_clear(self, monkeypatch: pytest.MonkeyPatch) -> None: pact_logging.set_test_run_id("tests/test_x.py::test_y") pact_logging.set_test_run_id(None) assert calls == ["tests/test_x.py::test_y", None] + + +class TestProcessLifetime: + """ + Behaviour which depends on the state of the whole process. + + Applying the FFI logger cannot be undone, so each test runs in a separate + interpreter. + """ + + @staticmethod + def run_script(script: str) -> subprocess.CompletedProcess[str]: + return subprocess.run( # noqa: S603 + [sys.executable, "-c", textwrap.dedent(script)], + check=False, + capture_output=True, + text=True, + timeout=60, + ) + + def test_forwards_with_externally_applied_logger(self) -> None: + result = self.run_script( + """ + import logging + import urllib.request + + import pact_ffi + + pact_ffi.log_to_stderr("INFO") + + from pact import Pact + + records = [] + + class Collect(logging.Handler): + def emit(self, record): + records.append(record) + + logging.getLogger("pact").addHandler(Collect()) + logging.getLogger("pact").setLevel(logging.INFO) + + pact = Pact("consumer", "provider") + ( + pact.upon_receiving("a request") + .with_request("GET", "/") + .will_respond_with(200) + ) + with pact.serve() as srv: + urllib.request.urlopen(f"{srv.url}/").read() + + assert any( + r.name == "pact" and "configured externally" in r.getMessage() + for r in records + ), records + assert any(r.name.startswith("pact.ffi.") for r in records), records + """ + ) + assert result.returncode == 0, result.stderr From 59cf7b0d2c1693c25f81206c96ccac650d9b9147 Mon Sep 17 00:00:00 2001 From: JP-Ellis Date: Wed, 21 Oct 2026 14:44:55 +1100 Subject: [PATCH 12/12] fix: forward the Pact library at the level of pact.ffi alone `forwarding_level` took the most verbose of the levels set on `pact.ffi` and `pact.plugins`. `pact_ffi.set_log_callback_level` only filters the callback registered with `register_log_callback`: the plugin log callback receives every plugin entry whatever the level. A verbose level on `pact.plugins` therefore changed nothing about the plugin records. It only made the library forward more of its own events, which Python then discarded at `pact.ffi`. The forwarding level is now read from `pact.ffi` alone. `pact.plugins` filters its records like any other logger, and its level can change at any time. The one-time warning now names only `pact.ffi`, and the docs drop the claim that both loggers share one forwarding level. A new subprocess test sets `pact.ffi` to `ERROR` and `pact.plugins` to `DEBUG`. It checks that the forwarding level stays at `ERROR`, and that a plugin's `DEBUG` stderr line still reaches `pact.plugins`. Signed-off-by: JP-Ellis Assisted-by: Claude Code:claude-opus-5-5 --- docs/logging.md | 11 ++++---- src/pact/logging.py | 37 ++++++++++++------------- tests/test_logging.py | 64 +++++++++++++++++++++++++++++++++++++++++-- 3 files changed, 84 insertions(+), 28 deletions(-) diff --git a/docs/logging.md b/docs/logging.md index 14bef8a8f..4b4410196 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -18,8 +18,8 @@ created in a process initialises the FFI and registers the forwarding. The Rust module path's `::` separators become `.`, so the records from `pact_matching::matchers` are emitted on `pact.ffi.pact_matching.matchers`, and a level set on `pact.ffi.pact_matching` filters them. Which events the -library forwards at all is decided by the levels of `pact.ffi` and -`pact.plugins`, as described under [Verbosity](#verbosity). +library forwards at all is decided by the level of `pact.ffi`, as described +under [Verbosity](#verbosity). Each record from the library carries `log_id` and `test_run_id` as attributes: @@ -77,10 +77,9 @@ usual. With no logging configured at all, Python's last-resort handler writes warnings and errors to stderr. To silence them, add a handler such as `logging.NullHandler()` to the `pact` logger. -The `pact.ffi` and `pact.plugins` loggers share a single forwarding level: the -more verbose of the levels set on them. Setting only `pact.plugins` to `DEBUG` -therefore forwards the library's `DEBUG` events as well. Python discards them, -but only after each one has been passed from the library to the interpreter. +Plugin events do not depend on the forwarding level. Every one of them is +forwarded to the `pact.plugins` logger, and its level filters them like any +other logger's. That level can be changed at any time. The library's `TRACE` level sits below `logging.DEBUG` and is exposed as [`pact.logging.TRACE`][pact.logging.TRACE]: diff --git a/src/pact/logging.py b/src/pact/logging.py index fe6aed955..30e35a116 100644 --- a/src/pact/logging.py +++ b/src/pact/logging.py @@ -26,10 +26,11 @@ logging.getLogger("pact.ffi").setLevel(logging.DEBUG) ``` -The FFI forwards events at the most verbose level set explicitly on the -`pact.ffi` and `pact.plugins` loggers, or at [`DEFAULT_LEVEL`][DEFAULT_LEVEL] -when neither is set. That level is fixed when the FFI is initialised, so set -logger levels before creating the first `Pact` or `Verifier`. The Pact +The FFI forwards the library's events at the level set explicitly on the +`pact.ffi` logger, or at [`DEFAULT_LEVEL`][DEFAULT_LEVEL] when it has none. +That level is fixed when the FFI is initialised, so set it before creating the +first `Pact` or `Verifier`. Every plugin event is forwarded, and the level of +the `pact.plugins` logger filters them like any other records. The Pact 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 @@ -90,8 +91,8 @@ DEFAULT_LEVEL = logging.INFO """ -Level at which the Pact library forwards events when neither the `pact.ffi` nor -the `pact.plugins` logger has an explicit level. +Level at which the Pact library forwards events when the `pact.ffi` logger has +no explicit level. `INFO` is the default because the library's `DEBUG` output is dominated by per-FFI-call tracing, per-request matching dumps and, when a plugin is @@ -153,17 +154,15 @@ def forwarding_level() -> int: """ `logging` level at which the Pact library forwards events. + Plugin events are not filtered by this level: the FFI hands every one of + them to the plugin log callback. + Returns: - The most verbose level set explicitly on the `pact.ffi` and - `pact.plugins` loggers, or [`DEFAULT_LEVEL`][DEFAULT_LEVEL] when - neither has one. + The level set explicitly on the `pact.ffi` logger, or + [`DEFAULT_LEVEL`][DEFAULT_LEVEL] when it has none. """ - explicit = [ - lg.level - for lg in (logging.getLogger("pact.ffi"), logging.getLogger("pact.plugins")) - if lg.level != logging.NOTSET - ] - return min(explicit) if explicit else DEFAULT_LEVEL + level = logging.getLogger("pact.ffi").level + return level if level != logging.NOTSET else DEFAULT_LEVEL def _ffi_level() -> pact_ffi.LevelFilter: @@ -240,8 +239,8 @@ def ensure_initialised() -> None: deregisters them again. The forwarding level cannot be raised once the logger is applied. A later - call which finds a more verbose level set on the `pact.ffi` or - `pact.plugins` logger logs a warning on the `pact` logger, once. + call which finds a more verbose level set on the `pact.ffi` logger logs a + 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 @@ -262,8 +261,8 @@ def ensure_initialised() -> None: _level_warned = True logger.warning( "Pact library events are forwarded at %s, fixed when the " - "first Pact or Verifier was created. Set the levels of the " - "'pact.ffi' and 'pact.plugins' loggers before then.", + "first Pact or Verifier was created. Set the level of the " + "'pact.ffi' logger before then.", applied.name, ) return diff --git a/tests/test_logging.py b/tests/test_logging.py index 0b8c44c3a..1ad2e4c83 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -132,10 +132,11 @@ def test_default_when_unset(self) -> None: pact_logging.DEFAULT_LEVEL ) - def test_most_verbose_explicit_level_wins(self) -> None: - logging.getLogger("pact.ffi").setLevel(logging.ERROR) + def test_ignores_plugins_level(self) -> None: logging.getLogger("pact.plugins").setLevel(pact_logging.TRACE) - assert pact_logging._ffi_level() == pact_ffi.LevelFilter.TRACE # noqa: SLF001 + assert pact_logging._ffi_level() == pact_logging.to_ffi_level( # noqa: SLF001 + pact_logging.DEFAULT_LEVEL + ) def test_single_explicit_level(self) -> None: logging.getLogger("pact.ffi").setLevel(logging.ERROR) @@ -537,6 +538,63 @@ def run_script(script: str) -> subprocess.CompletedProcess[str]: timeout=60, ) + @pytest.mark.skipif(sys.platform == "win32", reason="fake plugin is a shell script") + def test_plugin_records_ignore_forwarding_level(self, tmp_path: Path) -> None: + # The plugin's stderr lines are reported at `DEBUG`, below the + # forwarding level applied from `pact.ffi`. + plugin_dir = tmp_path / "fake-0.0.1" + plugin_dir.mkdir() + (plugin_dir / "pact-plugin.json").write_text( + json.dumps({ + "pluginInterfaceVersion": 1, + "name": "fake", + "version": "0.0.1", + "executableType": "exec", + "entryPoint": "fake-plugin", + }) + ) + entry_point = plugin_dir / "fake-plugin" + entry_point.write_text("#!/bin/sh\necho 'fake plugin starting' >&2\nexit 1\n") + entry_point.chmod(0o755) + + result = self.run_script( + f""" + import logging + import os + import time + + os.environ["PACT_PLUGIN_DIR"] = {str(tmp_path)!r} + os.environ["PACT_DO_NOT_TRACK"] = "true" + logging.getLogger("pact.ffi").setLevel(logging.ERROR) + logging.getLogger("pact.plugins").setLevel(logging.DEBUG) + + import pact.logging + from pact import Pact + + assert pact.logging.forwarding_level() == logging.ERROR + records = [] + + class Collect(logging.Handler): + def emit(self, record): + records.append(record) + + logging.getLogger("pact.plugins").addHandler(Collect()) + + pact = Pact("consumer", "provider").with_specification("V4") + try: + pact.using_plugin("fake", "0.0.1") + except RuntimeError: + pass + + deadline = time.monotonic() + 5 + while time.monotonic() < deadline and not records: + time.sleep(0.05) + assert [r.getMessage() for r in records] == ["fake plugin starting"] + assert records[0].levelno < logging.ERROR, records[0].levelname + """ + ) + assert result.returncode == 0, result.stderr + def test_forwards_with_externally_applied_logger(self) -> None: result = self.run_script( """