diff --git a/routstr/core/exceptions.py b/routstr/core/exceptions.py index fe1a2ef3..b8dcdc38 100644 --- a/routstr/core/exceptions.py +++ b/routstr/core/exceptions.py @@ -54,6 +54,21 @@ class EhbpTimeoutError(UpstreamError): ) +def _error_message_from_detail(detail: object) -> str | None: + """Extract a message from an HTTPException ``detail``, capped at 200 chars.""" + if isinstance(detail, dict): + error = detail.get("error") + if isinstance(error, dict): + msg = error.get("message") + return str(msg)[:200] if isinstance(msg, str) else None + if isinstance(error, str): + return error[:200] + return None + if isinstance(detail, str): + return detail[:200] + return None + + async def http_exception_handler(request: Request, exc: Exception) -> JSONResponse: """Handle HTTP exceptions and include request ID in response.""" request_id = getattr(request.state, "request_id", "unknown") @@ -63,28 +78,41 @@ async def http_exception_handler(request: Request, exc: Exception) -> JSONRespon detail = getattr(exc, "detail", str(exc)) path = request.url.path - # 4xx is client behaviour; the uvicorn access log already records it. + error_type: str | None = None + error_code: str | None = None + if isinstance(detail, dict): + error = detail.get("error") + if isinstance(error, dict): + error_type = error.get("type") + error_code = error.get("code") + + # 5xx logs as error/warning, 4xx at INFO. if status_code >= 500: - error_type = None - if isinstance(detail, dict): - error = detail.get("error") - if isinstance(error, dict): - error_type = error.get("type") - log = ( + log_fn = ( logger.warning if error_type in {"mint_unreachable", "mint_rate_limited"} else logger.error ) - log( - f"HTTP {status_code} on {path}: {detail}", - extra={ - "request_id": request_id, - "status_code": status_code, - "detail": detail, - "path": path, - "error_type": error_type, - }, - ) + else: + log_fn = logger.info + log_fn( + f"HTTP {status_code} on {path}: {detail}", + extra={ + "request_id": request_id, + "status_code": status_code, + "detail": detail, + "path": path, + "error_type": error_type, + "error_code": error_code, + "level": "http" if status_code < 500 else "server", + }, + ) + # Stash for LoggingMiddleware's completion log. + request.state.error_detail = { + "error_type": error_type, + "error_code": error_code, + "error_message": _error_message_from_detail(detail), + } if isinstance(detail, dict) and "error" in detail: content = {"detail": detail, **detail} diff --git a/routstr/core/middleware.py b/routstr/core/middleware.py index d4ddfb8f..cbcab96b 100644 --- a/routstr/core/middleware.py +++ b/routstr/core/middleware.py @@ -137,15 +137,22 @@ class LoggingMiddleware(BaseHTTPMiddleware): if should_log: duration = time.time() - start_time + extra: dict[str, object] = { + "request_id": request_id, + "method": request.method, + "path": path, + "status_code": response.status_code, + "duration_ms": round(duration * 1000, 2), + } + if response.status_code >= 400: + error_detail = getattr(request.state, "error_detail", None) + if isinstance(error_detail, dict): + extra["error_type"] = error_detail.get("error_type") + extra["error_code"] = error_detail.get("error_code") + extra["error_message"] = error_detail.get("error_message") logger.info( "Request completed", - extra={ - "request_id": request_id, - "method": request.method, - "path": path, - "status_code": response.status_code, - "duration_ms": round(duration * 1000, 2), - }, + extra=extra, ) if hasattr(response, "headers"): response.headers["x-routstr-request-id"] = request_id diff --git a/tests/unit/test_log_4xx_detail.py b/tests/unit/test_log_4xx_detail.py new file mode 100644 index 00000000..575d09fc --- /dev/null +++ b/tests/unit/test_log_4xx_detail.py @@ -0,0 +1,237 @@ +"""Tests for error detail in the 4xx "Request completed" log.""" + +import logging +from collections.abc import Iterator +from pathlib import Path +from typing import Any + +import pytest +from fastapi import FastAPI, HTTPException +from fastapi.testclient import TestClient +from pythonjsonlogger import jsonlogger +from starlette.requests import Request + +from routstr.core.exceptions import http_exception_handler +from routstr.core.logging import ( + DailyRotatingFileHandler, + RequestIdFilter, + SecurityFilter, + VersionFilter, +) +from routstr.core.middleware import LoggingMiddleware + + +@pytest.fixture +def handler(tmp_path: Path) -> Iterator[DailyRotatingFileHandler]: + log_dir = tmp_path / "logs" + log_dir.mkdir() + h = DailyRotatingFileHandler( + str(log_dir / "app.log"), when="midnight", interval=1, backupCount=30 + ) + h.setLevel(logging.DEBUG) + h.setFormatter( + jsonlogger.JsonFormatter( + "%(asctime)s %(name)s %(levelname)s %(message)s %(pathname)s " + "%(lineno)d %(version)s %(request_id)s", + datefmt="%Y-%m-%d %H:%M:%S", + ) + ) + for f in (VersionFilter(), RequestIdFilter(), SecurityFilter()): + h.addFilter(f) + try: + yield h + finally: + h.close() + + +def _read_last_record(handler: DailyRotatingFileHandler) -> dict[str, Any]: + handler.flush() + text = Path(handler.baseFilename).read_text() + assert text.strip(), "log file is empty" + import json as _json + + return _json.loads(text.strip().splitlines()[-1]) + + +# --------------------------------------------------------------------------- +# http_exception_handler +# --------------------------------------------------------------------------- + + +@pytest.mark.asyncio +async def test_http_exception_handler_logs_400_at_info() -> None: + request = Request( + { + "type": "http", + "method": "POST", + "path": "/v1/wallet/refund", + "headers": [], + "query_string": b"", + "scheme": "http", + "server": ("test", 80), + "client": ("test", 123), + } + ) + request.state.request_id = "req-4xx" + + calls: list[tuple[tuple, dict]] = [] + with pytest.MonkeyPatch.context() as m: + m.setattr( + "routstr.core.exceptions.logger.info", + lambda *a, **k: calls.append((a, k)), + ) + await http_exception_handler( + request, + HTTPException(status_code=400, detail="Balance too small to refund"), + ) + + assert calls, "logger.info was not called for a 4xx response" + extra = calls[0][1].get("extra", {}) + assert extra["status_code"] == 400 + assert extra["request_id"] == "req-4xx" + assert extra["path"] == "/v1/wallet/refund" + + +@pytest.mark.asyncio +async def test_http_exception_handler_stashes_error_detail_for_middleware() -> None: + request = Request( + { + "type": "http", + "method": "POST", + "path": "/v1/chat/completions", + "headers": [], + "query_string": b"", + "scheme": "http", + "server": ("test", 80), + "client": ("test", 123), + } + ) + request.state.request_id = "req-abc" + + await http_exception_handler( + request, + HTTPException( + status_code=400, + detail={ + "error": { + "message": "Invalid token format", + "type": "invalid_request_error", + "code": "invalid_token", + } + }, + ), + ) + + assert request.state.error_detail == { + "error_type": "invalid_request_error", + "error_code": "invalid_token", + "error_message": "Invalid token format", + } + + +@pytest.mark.asyncio +async def test_http_exception_handler_stash_truncates_long_string_details() -> None: + request = Request( + { + "type": "http", + "method": "POST", + "path": "/v1/chat/completions", + "headers": [], + "query_string": b"", + "scheme": "http", + "server": ("test", 80), + "client": ("test", 123), + } + ) + request.state.request_id = "req-trunc" + + long_detail = "x" * 500 + await http_exception_handler( + request, HTTPException(status_code=400, detail=long_detail) + ) + + msg = request.state.error_detail["error_message"] + assert isinstance(msg, str) + assert len(msg) == 200 + + +# --------------------------------------------------------------------------- +# LoggingMiddleware integration +# --------------------------------------------------------------------------- + + +def _build_app_with_middleware(handler: DailyRotatingFileHandler) -> FastAPI: + """Middleware + custom handler, wired like ``main.py``.""" + app = FastAPI() + app.add_middleware(LoggingMiddleware) + app.add_exception_handler(HTTPException, http_exception_handler) # type: ignore + + @app.get("/boom") + async def boom() -> None: + raise HTTPException( + status_code=400, + detail={ + "error": { + "message": "Balance too small to refund", + "type": "invalid_request_error", + "code": "balance_too_small", + } + }, + ) + + return app + + +def test_middleware_completion_log_includes_error_detail_for_4xx( + handler: DailyRotatingFileHandler, +) -> None: + app = _build_app_with_middleware(handler) + + middleware_logger = logging.getLogger("routstr.core.middleware") + middleware_logger.setLevel(logging.INFO) + middleware_logger.propagate = False + original_handlers = middleware_logger.handlers + middleware_logger.handlers = [handler] + try: + with TestClient(app, raise_server_exceptions=False) as client: + response = client.get("/boom") + assert response.status_code == 400 + finally: + middleware_logger.handlers = original_handlers + + record = _read_last_record(handler) + assert record["message"] == "Request completed" + assert record["status_code"] == 400 + assert record["error_type"] == "invalid_request_error" + assert record["error_code"] == "balance_too_small" + assert record["error_message"] == "Balance too small to refund" + + +def test_middleware_completion_log_omits_error_fields_for_2xx( + handler: DailyRotatingFileHandler, +) -> None: + app = FastAPI() + app.add_middleware(LoggingMiddleware) + + @app.get("/ok") + async def ok() -> dict[str, str]: + return {"status": "ok"} + + middleware_logger = logging.getLogger("routstr.core.middleware") + middleware_logger.setLevel(logging.INFO) + middleware_logger.propagate = False + original_handlers = middleware_logger.handlers + middleware_logger.handlers = [handler] + try: + with TestClient(app) as client: + response = client.get("/ok") + assert response.status_code == 200 + finally: + middleware_logger.handlers = original_handlers + + record = _read_last_record(handler) + assert record["message"] == "Request completed" + assert record["status_code"] == 200 + assert "error_type" not in record + assert "error_code" not in record + assert "error_message" not in record