Merge pull request #757 from Routstr/feat/log-4xx-error-detail-v2

feat(logs): echo 4xx error reason in Request completed log

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}

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

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