fix: ошибки БД и отказ проверки JWT пишутся в лог (I-2, T16.9)
Обработчики IntegrityError (409) и SQLAlchemyError (500) молча отдавали ответ. Теперь каждая такая ошибка — одна запись ERROR: путь и метод запроса, классы ошибок SQLAlchemy и драйвера, SQLSTATE, SQL-текст с плейсхолдерами (усечён до 200 символов) и стек вызовов. Текст исключения в лог не идёт: str() ошибки asyncpg/SQLAlchemy содержит параметры запроса и DETAIL PostgreSQL со значениями ключей (email, ИНН). Ответы прежние. JwksVerifier.verify: TypeError/ValueError, превращаемые в AuthError, теперь пишут warning в том же санированном виде repr(str(exc))[:200]. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
This commit is contained in:
parent
8d7d014391
commit
6a6ffb54f4
@ -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)
|
||||
|
||||
|
||||
@ -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": "ошибка базы данных"},
|
||||
|
||||
@ -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
|
||||
|
||||
106
api/tests/test_exception_handlers.py
Normal file
106
api/tests/test_exception_handlers.py
Normal file
@ -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
|
||||
Loading…
x
Reference in New Issue
Block a user