Logs were enriched with data.

src/contract_check/api/middleware.py

@@ -1,4 +1,10 @@
-"""FastAPI middleware — correlation_id, request timing/metrics, Sentry errors."""
+"""FastAPI middleware — correlation_id, request timing/metrics, Sentry errors.
+
+Every request emits an INFO access-log line (method, path, status, duration).
+With LOG_LEVEL=DEBUG, request and response payloads are logged too
+(redacted headers, secret-bearing JSON fields masked, bodies truncated) —
+see ``core/http_logging.py``.
+"""
 
 from __future__ import annotations
 
@@ -7,15 +13,23 @@ from typing import Any
 
 from fastapi import FastAPI, Request
 from fastapi.middleware.cors import CORSMiddleware
-from fastapi.responses import JSONResponse
+from fastapi.responses import JSONResponse, Response
 
 from src.contract_check.core.config import get_settings
-from src.contract_check.core.logging import get_logger, new_correlation_id, set_correlation_id
+from src.contract_check.core.http_logging import redact_headers, safe_body
+from src.contract_check.core.logging import (
+    get_logger,
+    is_debug_enabled,
+    new_correlation_id,
+    set_correlation_id,
+)
 from src.contract_check.core.metrics import http_request_duration
 from src.contract_check.core.sentry import init_sentry
 
 log = get_logger(__name__)
 
+_QUIET_PATHS = frozenset({"/healthz", "/readyz", "/metrics"})
+
 
 def add_middleware(app: FastAPI) -> None:
     origins = get_settings().cors_origins
@@ -34,10 +48,39 @@ def add_middleware(app: FastAPI) -> None:
         set_correlation_id(cid)
         start = time.perf_counter()
         status = 200
+        path = request.url.path
+        debug_payloads = is_debug_enabled() and path not in _QUIET_PATHS
+        if debug_payloads:
+            request_body = await request.body()
+            log.debug(
+                "http_request_payload",
+                method=request.method,
+                path=path,
+                query=request.url.query or None,
+                headers=redact_headers(request.headers),
+                body=safe_body(request_body, request.headers.get("content-type")),
+            )
         try:
             response = await call_next(request)
             status = response.status_code
             response.headers["x-correlation-id"] = cid
+            if debug_payloads:
+                response_body = b"".join([chunk async for chunk in response.body_iterator])
+                log.debug(
+                    "http_response_payload",
+                    method=request.method,
+                    path=path,
+                    status_code=status,
+                    headers=redact_headers(response.headers),
+                    body=safe_body(response_body, response.headers.get("content-type")),
+                )
+                response = Response(
+                    content=response_body,
+                    status_code=status,
+                    headers=dict(response.headers),
+                    background=response.background,
+                )
+                response.headers["x-correlation-id"] = cid
             return response
         except Exception as exc:
             status = 500
@@ -50,6 +93,14 @@ def add_middleware(app: FastAPI) -> None:
                 path=request.url.path,
                 status=str(status),
             ).observe(duration)
+            if path not in _QUIET_PATHS:
+                log.info(
+                    "http_request",
+                    method=request.method,
+                    path=path,
+                    status=str(status),
+                    duration_ms=round(duration * 1000, 2),
+                )
 
     @app.exception_handler(Exception)
     async def _exception_handler(_request: Request, exc: Exception) -> JSONResponse:

src/contract_check/bot/client.py

@@ -13,6 +13,7 @@ from dataclasses import dataclass
 import httpx
 
 from src.contract_check.bot.config import BotSettings
+from src.contract_check.core.http_logging import http_log_event_hooks
 from src.contract_check.core.logging import get_logger
 
 log = get_logger(__name__)
@@ -95,6 +96,7 @@ class ApiClient:
             self._client = httpx.AsyncClient(
                 base_url=self._settings.api_url,
                 timeout=httpx.Timeout(30.0, connect=5.0),
+                event_hooks=http_log_event_hooks(service="api"),
             )
 
     async def aclose(self) -> None:

src/contract_check/core/billing/yookassa.py

@@ -26,6 +26,7 @@ from src.contract_check.core.billing.port import (
     RefundResult,
 )
 from src.contract_check.core.config import Settings
+from src.contract_check.core.http_logging import http_log_event_hooks
 from src.contract_check.core.logging import get_logger
 
 log = get_logger(__name__)
@@ -58,6 +59,7 @@ class YookassaProvider:
                 "Content-Type": "application/json",
             },
             timeout=httpx.Timeout(timeout),
+            event_hooks=http_log_event_hooks(service="yookassa"),
         )
 
     async def aclose(self) -> None:

src/contract_check/core/http_logging.py

@@ -0,0 +1,180 @@
+"""Shared HTTP payload logging — redacted request/response bodies for httpx.
+
+Every event here is DEBUG-level: payloads may carry PII (contract text, report
+markdown) and secrets (tokens, passwords), so they stay out of the default
+INFO stream and are opt-in via LOG_LEVEL=DEBUG. Headers and JSON fields whose
+names look secret are redacted, and every body is truncated to a fixed char
+budget so a single log line can never dominate the log stream.
+"""
+
+from __future__ import annotations
+
+import json
+import time
+from collections.abc import Mapping
+from typing import Any
+from urllib.parse import parse_qsl
+
+import httpx
+
+from src.contract_check.core.logging import BoundLogger, get_logger, is_debug_enabled
+
+DEFAULT_MAX_PAYLOAD_CHARS = 2000
+
+_SENSITIVE_HEADERS = frozenset(
+    {
+        "authorization",
+        "proxy-authorization",
+        "cookie",
+        "set-cookie",
+        "x-api-key",
+        "api-key",
+    }
+)
+
+_SENSITIVE_JSON_KEYS = frozenset(
+    {
+        "password",
+        "current_password",
+        "new_password",
+        "token",
+        "access_token",
+        "refresh_token",
+        "id_token",
+        "api_key",
+        "apikey",
+        "secret",
+        "secret_key",
+        "client_secret",
+        "authorization",
+        "session",
+        "credential",
+        "credentials",
+        "private_key",
+    }
+)
+
+_TEXT_CONTENT_MARKERS = ("json", "text", "xml", "urlencoded", "graphql")
+
+
+def redact_headers(headers: Mapping[str, str] | httpx.Headers) -> dict[str, str]:
+    """Copy headers with secret-bearing ones reduced to a short prefix."""
+    redacted: dict[str, str] = {}
+    for key, value in headers.items():
+        lowered = key.lower()
+        if lowered in _SENSITIVE_HEADERS:
+            redacted[lowered] = value[:4] + "***" if len(value) > 4 else "***"
+        else:
+            redacted[lowered] = value
+    return redacted
+
+
+def redact_json(value: Any) -> Any:
+    """Recursively replace values of secret-looking keys in parsed JSON."""
+    if isinstance(value, dict):
+        return {
+            key: "***" if str(key).lower() in _SENSITIVE_JSON_KEYS else redact_json(item)
+            for key, item in value.items()
+        }
+    if isinstance(value, list):
+        return [redact_json(item) for item in value]
+    return value
+
+
+def safe_body(
+    body: bytes | str | Mapping[str, Any] | list[Any] | None,
+    content_type: str | None = None,
+    max_chars: int = DEFAULT_MAX_PAYLOAD_CHARS,
+) -> str | None:
+    """Render a body safe for logging: redacted if parseable, truncated, binary-summarized."""
+    if body is None:
+        return None
+    content_type_lower = (content_type or "").lower()
+    if isinstance(body, Mapping | list):
+        try:
+            text = json.dumps(redact_json(body), ensure_ascii=False, default=str)
+        except (TypeError, ValueError):
+            text = str(body)
+        return _truncate(text, max_chars)
+    if isinstance(body, bytes):
+        if not any(marker in content_type_lower for marker in _TEXT_CONTENT_MARKERS):
+            return f"<binary {len(body)} bytes>"
+        return _truncate(
+            _redact_text(body.decode("utf-8", errors="replace"), content_type_lower), max_chars
+        )
+    return _truncate(_redact_text(str(body), content_type_lower), max_chars)
+
+
+def _redact_text(text: str, content_type_lower: str) -> str:
+    if "json" in content_type_lower:
+        try:
+            return json.dumps(redact_json(json.loads(text)), ensure_ascii=False)
+        except ValueError:
+            return text
+    if "urlencoded" in content_type_lower:
+        pairs = parse_qsl(text, keep_blank_values=True)
+        if pairs:
+            return "&".join(
+                f"{key}={'***' if key.lower() in _SENSITIVE_JSON_KEYS else value}"
+                for key, value in pairs
+            )
+    return text
+
+
+def _truncate(text: str, max_chars: int) -> str:
+    if len(text) <= max_chars:
+        return text
+    return text[:max_chars] + f"…<truncated +{len(text) - max_chars} chars>"
+
+
+def http_log_event_hooks(
+    logger: BoundLogger | None = None,
+    *,
+    service: str = "http",
+    max_payload_chars: int = DEFAULT_MAX_PAYLOAD_CHARS,
+) -> dict[str, list[Any]]:
+    """Event hooks for ``httpx.AsyncClient(event_hooks=...)``.
+
+    Emits ``http_request`` before send and ``http_response`` after receive,
+    each at DEBUG with method, url, redacted headers, duration and a
+    redacted/truncated payload. No-op (beyond a timestamp stamp) unless
+    DEBUG logging is enabled.
+    """
+    log = logger or get_logger(f"http.{service}")
+    started_key = f"{service}_http_log_started_at"
+
+    async def _log_request(request: httpx.Request) -> None:
+        request.extensions[started_key] = time.perf_counter()
+        if not is_debug_enabled():
+            return
+        log.debug(
+            "http_request",
+            service=service,
+            method=request.method,
+            url=str(request.url),
+            headers=redact_headers(request.headers),
+            body=safe_body(request.content, request.headers.get("content-type"), max_payload_chars),
+        )
+
+    async def _log_response(response: httpx.Response) -> None:
+        if not is_debug_enabled():
+            return
+        request = response.request
+        started = request.extensions.get(started_key)
+        duration_ms = round((time.perf_counter() - started) * 1000, 2) if started else None
+        try:
+            body = response.text
+        except Exception:
+            body = None
+        log.debug(
+            "http_response",
+            service=service,
+            method=request.method,
+            url=str(request.url),
+            status_code=response.status_code,
+            duration_ms=duration_ms,
+            headers=redact_headers(response.headers),
+            body=safe_body(body, response.headers.get("content-type"), max_payload_chars),
+        )
+
+    return {"request": [_log_request], "response": [_log_response]}

tests/unit/test_http_logging.py

@@ -0,0 +1,130 @@
+"""Unit tests for shared HTTP payload logging (core/http_logging.py).
+
+Covers header redaction, JSON secret masking, truncation, binary
+summarization, and that the httpx event hooks emit payload-bearing
+http_request/http_response events at DEBUG.
+"""
+
+from __future__ import annotations
+
+import json
+
+import httpx
+import pytest
+from structlog.testing import capture_logs
+
+from contract_check.core import http_logging as hhttp
+from contract_check.core.http_logging import (
+    http_log_event_hooks,
+    redact_headers,
+    redact_json,
+    safe_body,
+)
+
+
+def test_redact_headers_masks_secret_bearers() -> None:
+    headers = {
+        "Authorization": "Basic abcdefgh",
+        "X-API-Key": "short",
+        "Content-Type": "application/json",
+    }
+    redacted = redact_headers(headers)
+    assert redacted["authorization"] == "Basi***"
+    assert redacted["x-api-key"] == "shor***"
+    assert redacted["content-type"] == "application/json"
+
+
+def test_redact_json_masks_secret_keys_recursively() -> None:
+    payload = {
+        "username": "san",
+        "password": "hunter2",
+        "nested": {"access_token": "jwt", "items": [{"client_secret": "s"}]},
+        "keep": "value",
+    }
+    redacted = redact_json(payload)
+    assert redacted["password"] == "***"
+    assert redacted["nested"]["access_token"] == "***"
+    assert redacted["nested"]["items"][0]["client_secret"] == "***"
+    assert redacted["username"] == "san"
+    assert redacted["keep"] == "value"
+
+
+def test_safe_body_redacts_json_bodies() -> None:
+    body = json.dumps({"grant_type": "password", "password": "hunter2"}).encode()
+    rendered = safe_body(body, "application/json; charset=utf-8")
+    assert rendered is not None
+    assert "hunter2" not in rendered
+    assert json.loads(rendered)["password"] == "***"
+
+
+def test_safe_body_redacts_urlencoded_bodies() -> None:
+    rendered = safe_body(b"username=san&password=hunter2", "application/x-www-form-urlencoded")
+    assert rendered == "username=san&password=***"
+
+
+def test_safe_body_summarizes_binary_payloads() -> None:
+    assert safe_body(b"%PDF-1.7 fake", "application/pdf") == "<binary 13 bytes>"
+    assert safe_body(b"--boundary\r\n...", "multipart/form-data; boundary=boundary") == (
+        "<binary 15 bytes>"
+    )
+
+
+def test_safe_body_truncates_long_text() -> None:
+    rendered = safe_body("x" * 500, "text/plain", max_chars=100)
+    assert rendered is not None
+    assert rendered.startswith("x" * 100)
+    assert "+400 chars" in rendered
+
+
+def test_safe_body_handles_none_and_plain_text() -> None:
+    assert safe_body(None, "application/json") is None
+    assert safe_body("hello", "text/plain") == "hello"
+
+
+async def test_event_hooks_log_request_and_response_payloads(
+    monkeypatch: pytest.MonkeyPatch,
+) -> None:
+    monkeypatch.setattr(hhttp, "is_debug_enabled", lambda: True)
+    with capture_logs() as logs:
+        transport = httpx.MockTransport(
+            lambda request: httpx.Response(200, json={"ok": True, "token": "jwt-secret"})  # noqa: S106
+        )
+        async with httpx.AsyncClient(
+            transport=transport,
+            headers={"Authorization": "Bearer supersecretjwt"},
+            event_hooks=http_log_event_hooks(service="test-svc"),
+        ) as client:
+            response = await client.post(
+                "https://api.test/v1/things",
+                json={"name": "thing", "password": "hunter2"},
+            )
+        assert response.status_code == 200
+
+    events = {entry.get("event"): entry for entry in logs}
+    request_entry = events["http_request"]
+    assert request_entry["service"] == "test-svc"
+    assert request_entry["method"] == "POST"
+    assert request_entry["url"] == "https://api.test/v1/things"
+    assert request_entry["headers"]["authorization"] == "Bear***"
+    assert request_entry["headers"]["content-type"] == "application/json"
+    assert "hunter2" not in request_entry["body"]
+    assert json.loads(request_entry["body"])["password"] == "***"
+
+    response_entry = events["http_response"]
+    assert response_entry["status_code"] == 200
+    assert response_entry["duration_ms"] is not None
+    assert "jwt-secret" not in response_entry["body"]
+    assert json.loads(response_entry["body"])["token"] == "***"
+
+
+async def test_event_hooks_silent_without_debug(monkeypatch: pytest.MonkeyPatch) -> None:
+    monkeypatch.setattr(hhttp, "is_debug_enabled", lambda: False)
+    with capture_logs() as logs:
+        transport = httpx.MockTransport(lambda request: httpx.Response(204))
+        async with httpx.AsyncClient(
+            transport=transport,
+            event_hooks=http_log_event_hooks(service="test-svc"),
+        ) as client:
+            await client.get("https://api.test/v1/things")
+
+    assert logs == []