diff --git a/api/src/core/auth.py b/api/src/core/auth.py index 19af572..c1c7682 100644 --- a/api/src/core/auth.py +++ b/api/src/core/auth.py @@ -240,7 +240,9 @@ class JwksVerifier: except jwt.PyJWTError as exc: raise _to_auth_error(exc) from exc except (TypeError, ValueError) as exc: - # страховка: несовместимые ключ и алгоритм не должны превращаться в 500 + # страховка: несовместимые ключ и алгоритм не должны превращаться в 500; причина — в лог (repr экранирует + # переводы строк, усечение ограничивает размер), клиенту — общее сообщение + logger.warning("Ключ проверки подписи не подошёл к токену JWT: {}", repr(str(exc))[:_LOG_TEXT_LIMIT]) raise AuthError("недействительный токен") from exc return _claims_from_payload(payload, self._email_claim) diff --git a/api/src/core/exception_handlers.py b/api/src/core/exception_handlers.py index 42a585b..6ede971 100644 --- a/api/src/core/exception_handlers.py +++ b/api/src/core/exception_handlers.py @@ -1,8 +1,38 @@ +"""Обработчики исключений приложения: единый формат ответа `{"detail": ...}`. + +Ошибки БД (`IntegrityError` → 409, прочие `SQLAlchemyError` → 500) пишутся в лог одной записью уровня ERROR без +текста исключения: `str()` ошибки SQLAlchemy/asyncpg содержит параметры запроса и DETAIL PostgreSQL со значениями +ключей (email, ИНН) — это персональные данные. В лог идут путь и метод запроса, классы ошибок, SQLSTATE, текст SQL +с плейсхолдерами (без значений, усечён) и стек вызовов без сообщения исключения. +""" + +import traceback + from fastapi import FastAPI, HTTPException, Request, status from fastapi.encoders import jsonable_encoder from fastapi.exceptions import RequestValidationError from fastapi.responses import JSONResponse -from sqlalchemy.exc import IntegrityError, SQLAlchemyError +from loguru import logger +from sqlalchemy.exc import DBAPIError, IntegrityError, SQLAlchemyError + +LOG_STATEMENT_LIMIT = 200 # символов SQL-текста (с плейсхолдерами) в записи лога + + +def log_db_error(request: Request, exc: SQLAlchemyError, message: str) -> None: + """Одна запись ERROR об ошибке БД при обработке запроса — без параметров запроса и текста ошибки драйвера.""" + orig = exc.orig if isinstance(exc, DBAPIError) else None + statement = exc.statement if isinstance(exc, DBAPIError) else None + logger.error( + message + " path={path}, method={method}, error_type={error_type}, db_error_type={db_error_type}, " + "sqlstate={sqlstate}, statement={statement}\n{stack}", + path=request.url.path, + method=request.method, + error_type=type(exc).__name__, + db_error_type=type(orig).__name__ if orig is not None else None, + sqlstate=getattr(orig, "sqlstate", None), + statement=repr(statement[:LOG_STATEMENT_LIMIT]) if statement else None, + stack="".join(traceback.format_tb(exc.__traceback__)).rstrip(), + ) def register_exception_handlers(app: FastAPI) -> None: @@ -15,14 +45,16 @@ def register_exception_handlers(app: FastAPI) -> None: ) @app.exception_handler(IntegrityError) - async def integrity_error_handler(_: Request, exc: IntegrityError): + async def integrity_error_handler(request: Request, exc: IntegrityError): + log_db_error(request, exc, "Нарушение целостности данных в БД при обработке запроса.") return JSONResponse( status_code=status.HTTP_409_CONFLICT, content={"detail": "нарушение целостности данных в БД"}, ) @app.exception_handler(SQLAlchemyError) - async def sqlalchemy_error_handler(_: Request, exc: SQLAlchemyError): + async def sqlalchemy_error_handler(request: Request, exc: SQLAlchemyError): + log_db_error(request, exc, "Ошибка базы данных при обработке запроса.") return JSONResponse( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, content={"detail": "ошибка базы данных"}, diff --git a/api/tests/test_auth_core.py b/api/tests/test_auth_core.py index 5df00f9..1911f89 100644 --- a/api/tests/test_auth_core.py +++ b/api/tests/test_auth_core.py @@ -697,3 +697,22 @@ async def test_dev_token_rejected_when_debug_off(monkeypatch: pytest.MonkeyPatch assert verifier is not None with pytest.raises(AuthError): await verifier.verify(token) + + +class _BrokenKeyClient: + """Источник ключей, на котором проверка падает `ValueError` с переводом строки и длинным текстом (T16.9).""" + + def get_signing_key_from_jwt(self, token: str) -> jwt.PyJWK: + raise ValueError("несовместимый ключ\nпод-строка " + "x" * 1000) + + +async def test_jwks_type_or_value_error_is_logged_sanitized(log_messages: list[str]) -> None: + """TypeError/ValueError при проверке — AuthError и одна warning-запись: без сырых переводов строк, усечённая.""" + verifier = JwksVerifier(jwk_client=_BrokenKeyClient()) + with pytest.raises(AuthError, match="недействительный токен"): + await verifier.verify(jwt.encode(_payload(), DEV_SECRET, "HS256")) + (message,) = log_messages + assert "Ключ проверки подписи не подошёл" in message + assert "\n" not in message + assert "\\n" in message # перевод строки экранирован repr + assert len(message) <= LOG_LINE_MAX diff --git a/api/tests/test_exception_handlers.py b/api/tests/test_exception_handlers.py new file mode 100644 index 0000000..b52f736 --- /dev/null +++ b/api/tests/test_exception_handlers.py @@ -0,0 +1,106 @@ +"""Обработчики ошибок БД (`src/core/exception_handlers.py`, финальное ревью I-2): ответ прежний, в лог — одна запись +ERROR без параметров запроса и DETAIL PostgreSQL (персональные данные).""" + +from collections.abc import Iterator +from http import HTTPStatus +from typing import Any + +import httpx +import pytest +from fastapi import FastAPI +from loguru import logger +from sqlalchemy.exc import IntegrityError, OperationalError, SQLAlchemyError + +from src.core.exception_handlers import LOG_STATEMENT_LIMIT, register_exception_handlers + +SECRET = "ivan.petrov@rshb.ru" + + +class _DriverError(Exception): + """Ошибка драйвера: как у asyncpg, текст содержит DETAIL со значением ключа, есть `sqlstate`.""" + + sqlstate = "23505" + + +def _app() -> FastAPI: + app = FastAPI() + register_exception_handlers(app) + + @app.get("/integrity") + async def integrity() -> None: + raise IntegrityError( + "INSERT INTO dkb.app_user (email) VALUES ($1)", + (SECRET,), + _DriverError(f"duplicate key\nDETAIL: Key (email)=({SECRET}) already exists."), + ) + + @app.get("/operational") + async def operational() -> None: + raise OperationalError("SELECT " + "x" * 1000 + " WHERE email = $1", (SECRET,), ConnectionError(SECRET)) + + @app.get("/generic") + async def generic() -> None: + raise SQLAlchemyError(f"ошибка без DBAPI: {SECRET}") + + return app + + +@pytest.fixture +def records() -> Iterator[list[Any]]: + """Записи loguru уровня DEBUG и выше за время теста (временный sink).""" + collected: list[Any] = [] + handler_id = logger.add(lambda message: collected.append(message.record), level="DEBUG") + try: + yield collected + finally: + logger.remove(handler_id) + + +async def _get(path: str) -> httpx.Response: + transport = httpx.ASGITransport(app=_app()) + async with httpx.AsyncClient(transport=transport, base_url="http://test") as client: + return await client.get(path) + + +@pytest.mark.parametrize( + ("path", "status", "detail", "error_type"), + [ + ("/integrity", HTTPStatus.CONFLICT, "нарушение целостности данных в БД", "IntegrityError"), + ("/operational", HTTPStatus.INTERNAL_SERVER_ERROR, "ошибка базы данных", "OperationalError"), + ("/generic", HTTPStatus.INTERNAL_SERVER_ERROR, "ошибка базы данных", "SQLAlchemyError"), + ], +) +async def test_db_error_logged_once_without_pii( + records: list[Any], path: str, status: HTTPStatus, detail: str, error_type: str +) -> None: + response = await _get(path) + + assert response.status_code == status + assert response.json() == {"detail": detail} + errors = [r for r in records if r["level"].no >= logger.level("ERROR").no] + assert len(errors) == 1 + (record,) = errors + assert record["level"].name == "ERROR" + message = record["message"] + assert f"path={path}" in message + assert "method=GET" in message + assert f"error_type={error_type}" in message + assert record["exception"] is None # текст исключения (параметры, DETAIL) в лог не попадает + assert SECRET not in message + assert "test_exception_handlers.py" in message # стек вызовов — есть + + +async def test_integrity_error_log_has_driver_class_sqlstate_and_statement(records: list[Any]) -> None: + await _get("/integrity") + (record,) = [r for r in records if r["level"].name == "ERROR"] + assert "db_error_type=_DriverError" in record["message"] + assert "sqlstate=23505" in record["message"] + assert "statement='INSERT INTO dkb.app_user (email) VALUES ($1)'" in record["message"] + + +async def test_long_statement_is_truncated(records: list[Any]) -> None: + await _get("/operational") + (record,) = [r for r in records if r["level"].name == "ERROR"] + statement = record["extra"]["statement"] + assert len(statement) <= LOG_STATEMENT_LIMIT + 2 # repr добавляет кавычки + assert "WHERE email" not in statement