From afe1aebf9de55811640dfe4b096419d3e463cbc2 Mon Sep 17 00:00:00 2001 From: febux Date: Wed, 26 Aug 2026 20:00:41 +0300 Subject: [PATCH] Logs were enriched with data. --- src/contract_check/api/middleware.py | 57 ++++++- src/contract_check/bot/client.py | 2 + src/contract_check/core/billing/yookassa.py | 2 + src/contract_check/core/http_logging.py | 180 ++++++++++++++++++++ tests/unit/test_http_logging.py | 130 ++++++++++++++ 5 files changed, 368 insertions(+), 3 deletions(-) create mode 100644 src/contract_check/core/http_logging.py create mode 100644 tests/unit/test_http_logging.py diff --git a/src/contract_check/api/middleware.py b/src/contract_check/api/middleware.py index 4881c9e..fb0bd8d 100644 --- a/src/contract_check/api/middleware.py +++ b/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: diff --git a/src/contract_check/bot/client.py b/src/contract_check/bot/client.py index 2160d49..8a7546b 100644 --- a/src/contract_check/bot/client.py +++ b/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: diff --git a/src/contract_check/core/billing/yookassa.py b/src/contract_check/core/billing/yookassa.py index 96a3bf4..7a5e109 100644 --- a/src/contract_check/core/billing/yookassa.py +++ b/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: diff --git a/src/contract_check/core/http_logging.py b/src/contract_check/core/http_logging.py new file mode 100644 index 0000000..4bacba2 --- /dev/null +++ b/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"" + 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"…" + + +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]} diff --git a/tests/unit/test_http_logging.py b/tests/unit/test_http_logging.py new file mode 100644 index 0000000..23e35cc --- /dev/null +++ b/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") == "" + assert safe_body(b"--boundary\r\n...", "multipart/form-data; boundary=boundary") == ( + "" + ) + + +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 == []