Skip to content

Pact Logs through native Python logging

Pact Python now integrates directly with Python's native logging module. As a result, test harnesses like Pytest and unittest are now significantly quieter when tests pass, and only the relevant logs are shown on failure, as capture through the test harness. We really hope this improves the developer (and agentic) experience!

This post walks through a small consumer test suite, before and after the change, with the output of each run.

The Example

The consumer is a small client for a user service:

user_client.py
from __future__ import annotations

from dataclasses import dataclass

import requests


@dataclass
class User:
    id: int
    name: str
    email: str


class UserClient:
    def __init__(self, base_url: str) -> None:
        self.base_url = base_url.rstrip("/")
        self.session = requests.Session()
        self.session.headers["Accept"] = "application/json"

    def get_user(self, user_id: int) -> User | None:
        response = self.session.get(f"{self.base_url}/users/{user_id}")
        if response.status_code == 404:
            return None
        response.raise_for_status()
        return User(**response.json())

    def create_user(self, name: str, email: str) -> User:
        response = self.session.post(
            f"{self.base_url}/users",
            json={"name": name, "email": email},
        )
        response.raise_for_status()
        return User(**response.json())

    def delete_user(self, user_id: int) -> None:
        response = self.session.delete(f"{self.base_url}/user/{user_id}")  # (1)
        response.raise_for_status()
  1. The bug: /user/ is missing its s.

The test suite has four tests: fetching a user, fetching an unknown user, creating a user and deleting a user. The first three pass. The fourth catches the bug.

test_user_client.py
from __future__ import annotations

from pathlib import Path
from typing import TYPE_CHECKING

import pytest

from pact import Pact, match
from user_client import UserClient

if TYPE_CHECKING:
    from collections.abc import Generator

PACT_DIR = Path(__file__).parent / "pacts"


@pytest.fixture
def pact() -> Generator[Pact, None, None]:
    pact = Pact("user-web", "user-service")
    yield pact
    pact.write_file(PACT_DIR)
test_get_user 
def test_get_user(pact: Pact) -> None:
    (
        pact
        .upon_receiving("a request for user 123")
        .given("user 123 exists")
        .with_request("GET", "/users/123")
        .will_respond_with(200)
        .with_body(
            {
                "id": 123,
                "name": match.str("Alice"),
                "email": match.str("alice@example.com"),
            },
            content_type="application/json",
        )
    )
    with pact.serve() as srv:
        user = UserClient(str(srv.url)).get_user(123)
    assert user is not None
    assert user.name == "Alice"
test_get_unknown_user 
def test_get_unknown_user(pact: Pact) -> None:
    (
        pact
        .upon_receiving("a request for an unknown user")
        .given("user 999 does not exist")
        .with_request("GET", "/users/999")
        .will_respond_with(404)
    )
    with pact.serve() as srv:
        assert UserClient(str(srv.url)).get_user(999) is None
test_create_user 
def test_create_user(pact: Pact) -> None:
    (
        pact
        .upon_receiving("a request to create a user")
        .with_request("POST", "/users")
        .with_body(
            {"name": "Bob", "email": "bob@example.com"},
            content_type="application/json",
        )
        .will_respond_with(201)
        .with_body(
            {
                "id": match.int(124),
                "name": "Bob",
                "email": "bob@example.com",
            },
            content_type="application/json",
        )
    )
    with pact.serve() as srv:
        user = UserClient(str(srv.url)).create_user("Bob", "bob@example.com")
    assert user.id == 124
test_delete_user 
def test_delete_user(pact: Pact) -> None:
    (
        pact
        .upon_receiving("a request to delete user 123")
        .given("user 123 exists")
        .with_request("DELETE", "/users/123")
        .will_respond_with(204)
    )
    with pact.serve() as srv:
        UserClient(str(srv.url)).delete_user(123)
test_user_client.py
from __future__ import annotations

import unittest
from pathlib import Path

from pact import Pact, match
from pact.testing.unittest import PactTestMixin
from user_client import UserClient

PACT_DIR = Path(__file__).parent / "pacts"


class UserClientTest(PactTestMixin, unittest.TestCase):
    def setUp(self) -> None:
        self.pact = Pact("user-web", "user-service").with_specification("V4")

    def tearDown(self) -> None:
        self.pact.write_file(PACT_DIR)
test_get_user 
def test_get_user(self) -> None:
    (
        self.pact
        .upon_receiving("a request for user 123")
        .given("user 123 exists")
        .with_request("GET", "/users/123")
        .will_respond_with(200)
        .with_body(
            {
                "id": 123,
                "name": match.str("Alice"),
                "email": match.str("alice@example.com"),
            },
            content_type="application/json",
        )
    )
    with self.pact.serve() as srv:
        user = UserClient(str(srv.url)).get_user(123)
    assert user is not None
    self.assertEqual(user.name, "Alice")
test_get_unknown_user 
def test_get_unknown_user(self) -> None:
    (
        self.pact
        .upon_receiving("a request for an unknown user")
        .given("user 999 does not exist")
        .with_request("GET", "/users/999")
        .will_respond_with(404)
    )
    with self.pact.serve() as srv:
        self.assertIsNone(UserClient(str(srv.url)).get_user(999))
test_create_user 
def test_create_user(self) -> None:
    (
        self.pact
        .upon_receiving("a request to create a user")
        .with_request("POST", "/users")
        .with_body(
            {"name": "Bob", "email": "bob@example.com"},
            content_type="application/json",
        )
        .will_respond_with(201)
        .with_body(
            {
                "id": match.int(124),
                "name": "Bob",
                "email": "bob@example.com",
            },
            content_type="application/json",
        )
    )
    with self.pact.serve() as srv:
        user = UserClient(str(srv.url)).create_user("Bob", "bob@example.com")
    self.assertEqual(user.id, 124)
test_delete_user

open: True

def test_delete_user(self) -> None:
    (
        self.pact
        .upon_receiving("a request to delete user 123")
        .given("user 123 exists")
        .with_request("DELETE", "/users/123")
        .will_respond_with(204)
    )
    with self.pact.serve() as srv:
        UserClient(str(srv.url)).delete_user(123)

Before: log_to_stderr

Earlier releases did not have any logging callbacks between the underlying FFI and the Python runtime. As a result, if users wanted to see logs from the underlying Rust library, they had to set pact_ffi.log_to_stderr at startup. This also cannot be modified once set, so either all tests are set to DEBUG, or all at INFO, etc.

With that configured, the library then wrote straight to the process's standard error, with no filtering from Python's logging configuration to filter or format those lines. The test runners also could only see the raw output, unable to distinguish a genuine call to print to stderr from one generated by the underlying library.

conftest.py
import pact_ffi
import pytest


@pytest.fixture(scope="session", autouse=True)
def pact_logging() -> None:
    pact_ffi.log_to_stderr("INFO")
test_user_client.py
import pact_ffi


def setUpModule() -> None:
    pact_ffi.log_to_stderr("INFO")

Passing Tests with log_to_stderr

Pytest captures the standard error of each test by default, so a plain pytest run of the three passing tests printed three dots. The issue arose when running with -s, as is common while debugging or from an IDE, in which case the FFI printed every request of every test into the progress line, clobbering the output. Unittest captures nothing, so its runs always looked like this:

pytest -s
test_user_client.py 2026-10-21T05:19:00.119769Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Received request GET /users/123
2026-10-21T05:19:00.119983Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Request matched, sending response
.2026-10-21T05:19:00.128023Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Received request GET /users/999
2026-10-21T05:19:00.128141Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Request matched, sending response
.2026-10-21T05:19:00.134604Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Received request POST /users
2026-10-21T05:19:00.135416Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Request matched, sending response
.

======================= 3 passed, 1 deselected in 0.23s ========================
python -m unittest
2026-10-21T05:19:10.320806Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Received request POST /users
2026-10-21T05:19:10.321924Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Request matched, sending response
.2026-10-21T05:19:10.328264Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Received request GET /users/999
2026-10-21T05:19:10.328375Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Request matched, sending response
.2026-10-21T05:19:10.335144Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Received request GET /users/123
2026-10-21T05:19:10.335271Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Request matched, sending response
.
----------------------------------------------------------------------
Ran 3 tests in 0.032s

OK

Failing Tests with log_to_stderr

When there is a genuine test failure, it sat among the lines of the passing tests. unittest also printed Pact Pythons' own error ahead of the E through Python's last-resourt handler.

pytest -s
test_user_client.py 2026-10-21T05:18:58.982371Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Received request GET /users/123
2026-10-21T05:18:58.982807Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Request matched, sending response
.2026-10-21T05:18:58.991686Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Received request GET /users/999
2026-10-21T05:18:58.991906Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Request matched, sending response
.2026-10-21T05:18:58.999285Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Received request POST /users
2026-10-21T05:18:59.000479Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Request matched, sending response
.2026-10-21T05:18:59.006995Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Received request DELETE /user/123
F

=================================== FAILURES ===================================
_______________________________ test_delete_user _______________________________
[...]
E   pact.error.MismatchesError: Mismatches:
E     (1) Request not found: DELETE /user/123: {'body': '', 'headers': {'accept': 'application/json', 'accept-encoding': 'gzip, deflate, zstd', 'connection': 'keep-alive', 'content-length': '0', 'host': 'localhost:62741', 'user-agent': 'python-requests/2.34.2'}}
E     (2) Missing request: DELETE /users/123: {}
------------------------------ Captured log call -------------------------------
ERROR    pact.pact:pact.py:834 Mismatches:
  (1) Request not found: DELETE /user/123: {'body': '', 'headers': {'accept': 'application/json', 'accept-encoding': 'gzip, deflate, zstd', 'connection': 'keep-alive', 'content-length': '0', 'host': 'localhost:62741', 'user-agent': 'python-requests/2.34.2'}}
  (2) Missing request: DELETE /users/123: {}
=========================== short test summary info ============================
FAILED test_user_client.py::test_delete_user - pact.error.MismatchesError: Mismatches:
========================= 1 failed, 3 passed in 0.31s ==========================
python -m unittest
2026-10-21T05:19:09.317645Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Received request POST /users
2026-10-21T05:19:09.318428Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Request matched, sending response
.2026-10-21T05:19:09.324581Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Received request DELETE /user/123
Mismatches:
  (1) Request not found: DELETE /user/123: {'body': '', 'headers': {'accept': 'application/json', 'accept-encoding': 'gzip, deflate, zstd', 'connection': 'keep-alive', 'content-length': '0', 'host': 'localhost:62820', 'user-agent': 'python-requests/2.34.2'}}
  (2) Missing request: DELETE /users/123: {}
E2026-10-21T05:19:09.333387Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Received request GET /users/999
2026-10-21T05:19:09.333539Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Request matched, sending response
.2026-10-21T05:19:09.340749Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Received request GET /users/123
2026-10-21T05:19:09.340867Z  INFO tokio-rt-worker pact_mock_server::hyper_server: Request matched, sending response
.
======================================================================
ERROR: test_delete_user (test_user_client.UserClientTest.test_delete_user)
----------------------------------------------------------------------
[...]
pact.error.MismatchesError: Mismatches:
  (1) Request not found: DELETE /user/123: {'body': '', 'headers': {'accept': 'application/json', 'accept-encoding': 'gzip, deflate, zstd', 'connection': 'keep-alive', 'content-length': '0', 'host': 'localhost:62820', 'user-agent': 'python-requests/2.34.2'}}
  (2) Missing request: DELETE /users/123: {}

----------------------------------------------------------------------
Ran 4 tests in 0.121s

FAILED (errors=1)

Worse yet was that if the log level is lowered to DEBUG, as one would likely due while troubleshooting, a number of logs emitted by the FFI between tests escaped Pytest's capture and clobbered the progress line. For example, the mock server's shut-down logs arrived after the summary, and the library's line and python's own records landed in separate sections:

pytest
test_user_client.py .2026-10-21T05:19:00.884736Z DEBUG ThreadId(01) pact_ffi::plugins: pact_ffi::plugins::pactffi_cleanup_plugins FFI function invoked
.2026-10-21T05:19:00.891625Z DEBUG ThreadId(01) pact_ffi::plugins: pact_ffi::plugins::pactffi_cleanup_plugins FFI function invoked
.2026-10-21T05:19:00.898938Z DEBUG ThreadId(01) pact_ffi::plugins: pact_ffi::plugins::pactffi_cleanup_plugins FFI function invoked
F                                                 [100%]

=================================== FAILURES ===================================
_______________________________ test_delete_user _______________________________
[...]
----------------------------- Captured stderr call -----------------------------
2026-10-21T05:19:00.899490Z DEBUG ThreadId(01) pact_ffi::mock_server::handles: Failed to parse the value, treating it as a plain string: expected value at line 1 column 1
2026-10-21T05:19:00.899526Z DEBUG ThreadId(01) pact_ffi::mock_server: pact_ffi::mock_server::pactffi_create_mock_server_for_transport FFI function invoked
2026-10-21T05:19:00.906081Z DEBUG tokio-rt-worker pact_mock_server::hyper_server: Received connection from remote [::1]:62763
[...]
2026-10-21T05:19:00.906443Z DEBUG tokio-rt-worker pact_matching: --> Mismatches: [PathMismatch { expected: "/users/123", actual: "/user/123", mismatch: "Expected '/user/123' to be equal to '/users/123'" }]
2026-10-21T05:19:00.906467Z DEBUG tokio-rt-worker pact_mock_server::hyper_server: Request did not match: Request was not expected - HTTP Request ( method: DELETE, path: /user/123, query: None, headers: Some({"connection": ["keep-alive"], "host": ["localhost:62762"], "user-agent": ["python-requests/2.34.2"], "accept-encoding": ["gzip", "deflate", "zstd"], "accept": ["application/json"], "content-length": ["0"]}), body: Empty )
2026-10-21T05:19:00.906892Z DEBUG ThreadId(01) pact_ffi::mock_server: pact_ffi::mock_server::pactffi_mock_server_matched FFI function invoked
2026-10-21T05:19:00.906932Z DEBUG ThreadId(01) pact_ffi::mock_server: pact_ffi::mock_server::pactffi_mock_server_mismatches FFI function invoked
2026-10-21T05:19:00.907148Z DEBUG ThreadId(01) pact_ffi::mock_server: pact_ffi::mock_server::pactffi_mock_server_mismatches FFI function invoked
------------------------------ Captured log call -------------------------------
ERROR    pact.pact:pact.py:834 Mismatches:
  (1) Request not found: DELETE /user/123: {'body': '', 'headers': {'accept': 'application/json', 'accept-encoding': 'gzip, deflate, zstd', 'connection': 'keep-alive', 'content-length': '0', 'host': 'localhost:62762', 'user-agent': 'python-requests/2.34.2'}}
  (2) Missing request: DELETE /users/123: {}
--------------------------- Captured stderr teardown ---------------------------
2026-10-21T05:19:01.005709Z DEBUG ThreadId(01) pact_ffi::mock_server::handles: pact_ffi::mock_server::handles::pactffi_pact_handle_write_file FFI function invoked
2026-10-21T05:19:01.010873Z DEBUG ThreadId(01) pact_models::pact: Merging pact with file "~/src/user-web/pacts/user-web-user-service.json"
=========================== short test summary info ============================
FAILED test_user_client.py::test_delete_user - pact.error.MismatchesError: Mismatches:
========================= 1 failed, 3 passed in 0.35s ==========================
2026-10-21T05:19:01.112666Z DEBUG ThreadId(01) pact_ffi::mock_server: pact_ffi::mock_server::pactffi_cleanup_mock_server FFI function invoked
2026-10-21T05:19:01.112742Z DEBUG ThreadId(01) pact_matching::metrics: Could not get the tokio runtime, will not send metrics - there is no reactor running, must be called from the context of a Tokio 1.x runtime
2026-10-21T05:19:01.113247Z DEBUG ThreadId(01) pact_mock_server::mock_server: Mock server 54e16c07-d609-462e-a9fd-5a4cdb71a231 shutdown - MockServerMetrics { requests: 1, requests_by_path: {"/user/123": 1} }
2026-10-21T05:19:01.113291Z DEBUG ThreadId(01) pact_mock_server::server_manager: Shutting down mock server with ID 54e16c07-d609-462e-a9fd-5a4cdb71a231 - MockServerMetrics { requests: 1, requests_by_path: {"/user/123": 1} }
2026-10-21T05:19:01.113327Z DEBUG ThreadId(01) pact_ffi::plugins: pact_ffi::plugins::pactffi_cleanup_plugins FFI function invoked

After: Logs Through logging

Pact Python now registers a log callback with the Pact library when the first Pact or Verifier is created. Each event from the library becomes a record on a logger under pact.ffi, named after the Rust module which emitted it.

Pytest captures these records like any others. It captures only warnings and errors by default, so set its log_level to see the library's INFO records too:

pyproject.toml
[tool.pytest]
log_level = "INFO"

Add PactTestMixin to the test case, ahead of unittest.TestCase:

test_user_client.py
import unittest

from pact.testing.unittest import PactTestMixin


class UserClientTest(PactTestMixin, unittest.TestCase): ...

The mixin collects the Pact records of each test. When a test fails or errors, it writes them to standard error under a banner naming the test.

Passing Tests with logging

The three passing tests print three dots. Pytest's log capture works independently of its output capture, so the run stays quiet with -s too:

pytest -s
test_user_client.py ...

======================= 3 passed, 1 deselected in 0.43s ========================
python -m unittest
...
----------------------------------------------------------------------
Ran 3 tests in 0.028s

OK

Failing Tests with logging

The failing test now reports the mock server's record and Pact Python's error together, in the order they were logged:

pytest
test_user_client.py ...F                                                 [100%]

=================================== FAILURES ===================================
_______________________________ test_delete_user _______________________________
[...]
E   pact.error.MismatchesError: Mismatches:
E     (1) Request not found: DELETE /user/123: {'body': '', 'headers': {'accept': 'application/json', 'accept-encoding': 'gzip, deflate, zstd', 'connection': 'keep-alive', 'content-length': '0', 'host': 'localhost:62771', 'user-agent': 'python-requests/2.34.2'}}
E     (2) Missing request: DELETE /users/123: {}
------------------------------ Captured log call -------------------------------
INFO     pact.ffi.pact_mock_server.hyper_server:logging.py:197 Received request DELETE /user/123
ERROR    pact.pact:pact.py:843 Mismatches:
  (1) Request not found: DELETE /user/123: {'body': '', 'headers': {'accept': 'application/json', 'accept-encoding': 'gzip, deflate, zstd', 'connection': 'keep-alive', 'content-length': '0', 'host': 'localhost:62771', 'user-agent': 'python-requests/2.34.2'}}
  (2) Missing request: DELETE /users/123: {}
=========================== short test summary info ============================
FAILED test_user_client.py::test_delete_user - pact.error.MismatchesError: Mismatches:
========================= 1 failed, 3 passed in 1.24s ==========================

The logging.py:197 location is where Pact Python emits each forwarded record. A log_format without %(filename)s:%(lineno)d leaves it out.

python -m unittest
.Mismatches:
  (1) Request not found: DELETE /user/123: {'body': '', 'headers': {'accept': 'application/json', 'accept-encoding': 'gzip, deflate, zstd', 'connection': 'keep-alive', 'content-length': '0', 'host': 'localhost:62830', 'user-agent': 'python-requests/2.34.2'}}
  (2) Missing request: DELETE /users/123: {}
E--- Pact logs for test_user_client.UserClientTest.test_delete_user ---
INFO pact.ffi.pact_mock_server.hyper_server: Received request DELETE /user/123
ERROR pact.pact: Mismatches:
  (1) Request not found: DELETE /user/123: {'body': '', 'headers': {'accept': 'application/json', 'accept-encoding': 'gzip, deflate, zstd', 'connection': 'keep-alive', 'content-length': '0', 'host': 'localhost:62830', 'user-agent': 'python-requests/2.34.2'}}
  (2) Missing request: DELETE /users/123: {}
--- end of Pact logs ---
..
======================================================================
ERROR: test_delete_user (test_user_client.UserClientTest.test_delete_user)
----------------------------------------------------------------------
[...]
pact.error.MismatchesError: Mismatches:
  (1) Request not found: DELETE /user/123: {'body': '', 'headers': {'accept': 'application/json', 'accept-encoding': 'gzip, deflate, zstd', 'connection': 'keep-alive', 'content-length': '0', 'host': 'localhost:62830', 'user-agent': 'python-requests/2.34.2'}}
  (2) Missing request: DELETE /users/123: {}

----------------------------------------------------------------------
Ran 4 tests in 0.090s

FAILED (errors=1)

The suite configures no logging, so Python's last-resort handler still prints the bare Mismatches: error ahead of the E. The mixin collects records at the forwarding level whatever the root logger's level, so the banner also holds the INFO record from the mock server.

Debugging a Mismatch

The logger names follow the Rust module paths, so standard logging levels can pick out the useful parts of the DEBUG output. The pact.ffi logger sets which events the library forwards at all. The pact_ffi crate traces every FFI call at DEBUG, and raising pact.ffi.pact_ffi back to INFO drops those traces:

conftest.py
import logging

logging.getLogger("pact.ffi").setLevel(logging.DEBUG)  # (1)
logging.getLogger("pact.ffi.pact_ffi").setLevel(logging.INFO)  # (2)
  1. The level of pact.ffi sets which events the library forwards at all, so it must be the lowest of all the pact.ffi levels.
  2. A logger beneath pact.ffi can raise its level above DEBUG. Lowering it below DEBUG shows nothing more, as the library never forwards those events.
pyproject.toml
[tool.pytest]
log_level = "DEBUG"
test_user_client.py
import logging

logging.getLogger("pact.ffi").setLevel(logging.DEBUG)  # (1)
logging.getLogger("pact.ffi.pact_ffi").setLevel(logging.INFO)  # (2)
  1. The level of pact.ffi sets which events the library forwards at all, so it must be the lowest of all the pact.ffi levels.
  2. A logger beneath pact.ffi can raise its level above DEBUG. Lowering it below DEBUG shows nothing more, as the library never forwards those events.

The failure report now follows the request from start to finish. Under pytest, the urllib3 records from the client and the matching records from the mock server appear in one sequence. The banner of the mixin holds the Pact records alone, including those logged during tearDown:

pytest
------------------------------ Captured log call -------------------------------
DEBUG    urllib3.connectionpool:connectionpool.py:247 Starting new HTTP connection (1): localhost:62806
DEBUG    pact.ffi.pact_mock_server.hyper_server:logging.py:197 Received connection from remote [::1]:62807
DEBUG    pact.ffi.pact_mock_server.hyper_server:logging.py:197 Creating pact request from hyper request path=/user/123
DEBUG    pact.ffi.pact_mock_server.hyper_server:logging.py:197 Extracting query from uri /user/123
INFO     pact.ffi.pact_mock_server.hyper_server:logging.py:197 Received request DELETE /user/123
[...]
DEBUG    pact.ffi.pact_matching:logging.py:197 comparing to expected HTTP Request ( method: DELETE, path: /users/123, query: None, headers: None, body: Missing )
[...]
DEBUG    pact.ffi.pact_matching.matchingrules:logging.py:197 String -> String: comparing '/users/123' to '/user/123' ==> false cascaded=false matcher=Equality
DEBUG    pact.ffi.pact_matching:logging.py:197 expected content type = '*/*', actual content type = '*/*'
DEBUG    pact.ffi.pact_matching:logging.py:197 content type header matcher = 'RuleList { rules: [], rule_logic: And, cascaded: false }'
DEBUG    pact.ffi.pact_matching:logging.py:197 --> Mismatches: [PathMismatch { expected: "/users/123", actual: "/user/123", mismatch: "Expected '/user/123' to be equal to '/users/123'" }]
DEBUG    pact.ffi.pact_mock_server.hyper_server:logging.py:197 Request did not match: Request was not expected - HTTP Request ( method: DELETE, path: /user/123, query: None, headers: Some({"accept-encoding": ["gzip", "deflate", "zstd"], "accept": ["application/json"], "connection": ["keep-alive"], "content-length": ["0"], "host": ["localhost:62806"], "user-agent": ["python-requests/2.34.2"]}), body: Empty )
DEBUG    urllib3.connectionpool:connectionpool.py:550 http://localhost:62806 "DELETE /user/123 HTTP/1.1" 500 453
ERROR    pact.pact:pact.py:843 Mismatches:
  (1) Request not found: DELETE /user/123: {'body': '', 'headers': {'accept': 'application/json', 'accept-encoding': 'gzip, deflate, zstd', 'connection': 'keep-alive', 'content-length': '0', 'host': 'localhost:62806', 'user-agent': 'python-requests/2.34.2'}}
  (2) Missing request: DELETE /users/123: {}
---------------------------- Captured log teardown -----------------------------
DEBUG    pact.ffi.pact_models.pact:logging.py:197 Merging pact with file "~/src/user-web/pacts/user-web-user-service.json"
python -m unittest
.Mismatches:
  (1) Request not found: DELETE /user/123: {'body': '', 'headers': {'accept': 'application/json', 'accept-encoding': 'gzip, deflate, zstd', 'connection': 'keep-alive', 'content-length': '0', 'host': 'localhost:62853', 'user-agent': 'python-requests/2.34.2'}}
  (2) Missing request: DELETE /users/123: {}
E--- Pact logs for test_user_client.UserClientTest.test_delete_user ---
DEBUG pact.ffi.pact_mock_server.hyper_server: Received connection from remote [::1]:62854
DEBUG pact.ffi.pact_mock_server.hyper_server: Creating pact request from hyper request path=/user/123
DEBUG pact.ffi.pact_mock_server.hyper_server: Extracting query from uri /user/123
INFO pact.ffi.pact_mock_server.hyper_server: Received request DELETE /user/123
[...]
DEBUG pact.ffi.pact_matching.matchingrules: String -> String: comparing '/users/123' to '/user/123' ==> false cascaded=false matcher=Equality
DEBUG pact.ffi.pact_matching: expected content type = '*/*', actual content type = '*/*'
DEBUG pact.ffi.pact_matching: content type header matcher = 'RuleList { rules: [], rule_logic: And, cascaded: false }'
DEBUG pact.ffi.pact_matching: --> Mismatches: [PathMismatch { expected: "/users/123", actual: "/user/123", mismatch: "Expected '/user/123' to be equal to '/users/123'" }]
DEBUG pact.ffi.pact_mock_server.hyper_server: Request did not match: Request was not expected - HTTP Request ( method: DELETE, path: /user/123, query: None, headers: Some({"content-length": ["0"], "user-agent": ["python-requests/2.34.2"], "connection": ["keep-alive"], "host": ["localhost:62853"], "accept": ["application/json"], "accept-encoding": ["gzip", "deflate", "zstd"]}), body: Empty )
ERROR pact.pact: Mismatches:
  (1) Request not found: DELETE /user/123: {'body': '', 'headers': {'accept': 'application/json', 'accept-encoding': 'gzip, deflate, zstd', 'connection': 'keep-alive', 'content-length': '0', 'host': 'localhost:62853', 'user-agent': 'python-requests/2.34.2'}}
  (2) Missing request: DELETE /users/123: {}
DEBUG pact.ffi.pact_matching.metrics: Could not get the tokio runtime, will not send metrics - there is no reactor running, must be called from the context of a Tokio 1.x runtime
DEBUG pact.ffi.pact_mock_server.mock_server: Mock server f825f1a6-a695-41d1-9c31-aaead2883862 shutdown - MockServerMetrics { requests: 1, requests_by_path: {"/user/123": 1} }
DEBUG pact.ffi.pact_mock_server.server_manager: Shutting down mock server with ID f825f1a6-a695-41d1-9c31-aaead2883862 - MockServerMetrics { requests: 1, requests_by_path: {"/user/123": 1} }
DEBUG pact.ffi.pact_models.pact: Merging pact with file "~/src/user-web/pacts/user-web-user-service.json"
--- end of Pact logs ---
..
======================================================================
ERROR: test_delete_user (test_user_client.UserClientTest.test_delete_user)
[...]
pact.error.MismatchesError: Mismatches:
  (1) Request not found: DELETE /user/123: {'body': '', 'headers': {'accept': 'application/json', 'accept-encoding': 'gzip, deflate, zstd', 'connection': 'keep-alive', 'content-length': '0', 'host': 'localhost:62853', 'user-agent': 'python-requests/2.34.2'}}
  (2) Missing request: DELETE /users/123: {}

----------------------------------------------------------------------
Ran 4 tests in 0.202s

FAILED (errors=1)

The three passing tests still print three dots.

Set the Level Before the First Pact

The library's forwarding level is fixed when the first Pact or Verifier is created. Set the level of pact.ffi before then, for example at the top of conftest.py or of the test module. A call to caplog.set_level inside a test cannot bring back records which were never forwarded.

Test Run IDs

When several tests run at once, knowing which log belongs to which test is just as important as seeing the logs at all. To help with this, the pytest plugin and the mixin also set a Pact test run ID for each test: the pytest node ID, or the unittest test ID. Every record the library emits on the test's thread carries this ID as a test_run_id attribute. The ID is also sent along with every request the test makes to a plugin, so the log entries the plugin sends back carry it too. The mock server handles requests on its own threads, so its records carry the mock server's ID as log_id instead. A custom handler or formatter can use these attributes to group records by test, which is especially useful when tests run in parallel.

There is nothing to set up for this. Pact Python registers the pytest plugin automatically, and it is careful not to load the Pact library itself, so a pytest session which never uses Pact is unaffected. If you would rather go without it, pass -p no:pact. A PactTestMixin test case can also run under pytest, in which case the mixin hands the run ID back to the pytest node ID once the test finishes.

Plugin Logs

Plugins run as separate processes, each with logs of its own. Pact Python forwards both the lines each plugin writes to its standard error and the log entries it sends back over its RPC connection to the pact.plugins logger. Each record carries the plugin_instance_id of the plugin which emitted it. Unlike the pact.ffi loggers, every plugin entry is forwarded, so the level of pact.plugins alone decides which ones are shown, and it can be changed at any time.

The library also keeps every plugin entry in a buffer for the life of the process. If you need them after the fact, pass a plugin_instance_id to pact.plugins.get_logs to read the entries for that plugin instance, along with their timestamps and sources.

Migrating

Migrating is mostly a matter of deleting code. Remove every call to pact_ffi.log_to_stderr, log_to_stdout, log_to_file, init and init_with_log_level. Once Pact Python's logging integration is loaded, these functions no longer do anything except emit a UserWarning, which pytest lists in its summary:

pytest
=============================== warnings summary ===============================
test_user_client.py::test_get_user
  ~/src/user-web/conftest.py:7: UserWarning: pact_ffi.log_to_stderr 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.
    pact_ffi.log_to_stderr("INFO")

For the full details, the Logging guide lists every logger and record attribute, including the log_id which identifies each mock server and provider verification.