diff --git a/docs/consumer.md b/docs/consumer.md index 7c69684a9..06dc5957b 100644 --- a/docs/consumer.md +++ b/docs/consumer.md @@ -194,22 +194,15 @@ 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. - -The recommended approach is to set up logging in a pytest fixture within your `conftest.py`: +Logs from the mock server and from plugins go to Python's `logging` module, on the `pact.ffi` and `pact.plugins` loggers. No set-up is needed; under pytest, they appear in the captured log of a failing test. To see more detail when diagnosing a failure, lower the level before creating the first `Pact`: ```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.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 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 6fb46f28b..20cc79a59 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -1,124 +1,125 @@ -# 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 | + +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: + +- `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 -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): - -- `"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 +## Verbosity -/// 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] (`logging.INFO`) when neither is +set. `DEBUG` and below add per-FFI-call tracing, per-request matching dumps +and, once a plugin is loaded, transport chatter from `hyper`, `rustls` and +`reqwest`; opt into that detail explicitly when debugging a failure: ```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.DEBUG) ``` -This ensures that: - -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). -/// +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. -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 - -For applications that need to capture and process logs programmatically, you can use [`log_to_buffer`][pact_ffi.log_to_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. 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 +of one provider verification share `verify:`. + +## 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 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 pact_ffi +import logging -# Configure logging to an internal buffer -pact_ffi.log_to_buffer("DEBUG") +logging.basicConfig(level=logging.INFO) ``` -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). -/// - -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 +Under pytest, `--log-cli-level=INFO` shows the records as each test runs. ## 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/docs/provider.md b/docs/provider.md index 5b01087d1..849d538e9 100644 --- a/docs/provider.md +++ b/docs/provider.md @@ -135,22 +135,15 @@ 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. - -The recommended approach is to set up logging in a pytest fixture within your `conftest.py`: +Logs from the verifier and from plugins go to Python's `logging` module, on the `pact.ffi` and `pact.plugins` loggers. No set-up is needed; under pytest, they appear in the captured log of a failing test. To see more detail when diagnosing a failure, lower the level before creating the first `Verifier`: ```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.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 loggers, the attributes on each record, and how to migrate from `pact_ffi.log_to_stderr`. ### Publishing Results 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/pyproject.toml b/pyproject.toml index ab062c077..e4c5ee799 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 "yarl~=1.0", diff --git a/src/pact/__init__.py b/src/pact/__init__.py index a84f9ab38..f8f4bf740 100644 --- a/src/pact/__init__.py +++ b/src/pact/__init__.py @@ -111,6 +111,7 @@ from __future__ import annotations +from pact import logging as logging from pact import xml as xml from pact.__version__ import __version__, __version_tuple__ from pact.pact import Pact @@ -125,5 +126,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..23a9d93a1 --- /dev/null +++ b/src/pact/logging.py @@ -0,0 +1,341 @@ +""" +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`][verifier.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 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 + 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. + +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`][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`][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 one of them before `pact` was imported is kept: 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 warnings +from typing import TYPE_CHECKING + +import pact_ffi + +if TYPE_CHECKING: + from collections.abc import Callable + +__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`. +""" + +logging.addLevelName(TRACE, "TRACE") + +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]] = [ + (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): + name = f"pact.ffi.{target.replace('::', '.')}" if target else "pact.ffi" + logging.getLogger(name).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 +_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. Later calls return immediately. + + 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 + `pact` logger and the callbacks are registered against that logger + instead. + """ + global _initialised # noqa: PLW0603 + + with _lock: + if _initialised: + return + pact_ffi.set_log_callback_level(_ffi_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: 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 + + +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 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 + 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: + 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/src/pact/pact.py b/src/pact/pact.py index db0c08755..c06b0cd4e 100644 --- a/src/pact/pact.py +++ b/src/pact/pact.py @@ -85,6 +85,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 @@ -141,6 +142,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() diff --git a/src/pact/verifier.py b/src/pact/verifier.py index cd01fef8a..79a4217bc 100644 --- a/src/pact/verifier.py +++ b/src/pact/verifier.py @@ -88,6 +88,7 @@ import pact_ffi from pact._server import MessageProducer, StateCallback from pact._util import apply_args +from pact.logging import ensure_initialised from pact.types import ( UNSET, Message, @@ -235,6 +236,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/conftest.py b/tests/conftest.py index f41ae4845..31ccf665d 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -13,16 +13,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 fe60e24ca..3834fee61 100644 --- a/tests/interaction/test_http_interaction.py +++ b/tests/interaction/test_http_interaction.py @@ -697,7 +697,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..08d37d2d0 --- /dev/null +++ b/tests/test_logging.py @@ -0,0 +1,462 @@ +""" +Unit tests for [`pact.logging`][pact.logging]. +""" + +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 +import pytest + +import pact_ffi +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( + 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(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", + ] + + 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_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() + # 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"): + 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 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.""" + + @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) + + 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 + ) + + @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") + caplog.set_level(logging.DEBUG, logger="pact.plugins") + caplog.set_level(logging.DEBUG, logger="pact.ffi") + + 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].""" + + 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]