feat(core): add structured logging and request pipeline middleware [AYG-66] (#2)

* feat(core): add structured logging and request pipeline middleware [AYG-66]

Add structlog-based structured logging (JSON/console modes) and request
pipeline middleware providing UUID v4 request IDs, correlation ID
propagation, security headers on all responses (including CORS preflight),
and status-based log levels (info/warning/error for 2xx/4xx/5xx).

- Create backend/app/core/logging.py: structlog configuration with
  JSON renderer (production) and ConsoleRenderer (local dev), base
  fields (timestamp, level, event, service, version, environment),
  contextvars integration for request-scoped fields
- Create backend/app/core/middleware.py: RequestPipelineMiddleware
  with request_id generation, X-Correlation-ID propagation, 6 security
  headers (X-Content-Type-Options, X-Frame-Options, X-XSS-Protection,
  Referrer-Policy, Permissions-Policy, HSTS production-only),
  X-Request-ID on every response including error and exception paths
- Wire into main.py with documented middleware ordering (outermost
  wraps CORSMiddleware so preflight OPTIONS get headers too)
- 32 new unit tests (6 logging + 26 middleware) covering CORS preflight
  header behavior, X-Request-ID on 4xx/5xx/exception paths, and
  negative tests proving Authorization/Cookie values never logged

Fixes AYG-66

🤖 Generated by Aygentic

Co-Authored-By: Aygentic <noreply@aygentic.com>

* docs(core): update architecture, test registry, and deployment docs for AYG-66 [skip ci]

Updated documentation based on structured logging and request pipeline middleware implementation.

Related to AYG-66

🤖 Generated by Aygentic

Co-Authored-By: Aygentic <noreply@aygentic.com>

---------

Co-authored-by: Aygentic <noreply@aygentic.com>

Author: amostt

backend/app/core/logging.py

@@ -0,0 +1,77 @@
+"""Structured logging configuration using structlog.
+
+Provides JSON output for production/CI and human-readable console output
+for local development, controlled by the LOG_FORMAT setting.
+
+Every log entry includes base fields: timestamp, level, event, service,
+version, environment. Request-scoped fields (request_id, correlation_id)
+are bound via structlog.contextvars by the request pipeline middleware.
+"""
+
+from __future__ import annotations
+
+import logging
+from collections.abc import MutableMapping
+from typing import Any
+
+import structlog
+
+
+def _add_service_info(
+    service: str,
+    version: str,
+    environment: str,
+) -> structlog.types.Processor:
+    """Return a processor that injects service metadata into every log entry."""
+
+    def processor(
+        _logger: Any, _method_name: str, event_dict: MutableMapping[str, Any]
+    ) -> MutableMapping[str, Any]:
+        event_dict.setdefault("service", service)
+        event_dict.setdefault("version", version)
+        event_dict.setdefault("environment", environment)
+        return event_dict
+
+    return processor
+
+
+def setup_logging(settings: Any) -> None:
+    """Configure structlog with JSON or console rendering.
+
+    Args:
+        settings: A settings object with LOG_LEVEL, LOG_FORMAT,
+                  SERVICE_NAME, SERVICE_VERSION, and ENVIRONMENT attributes.
+    """
+    log_level = getattr(logging, settings.LOG_LEVEL.upper(), logging.INFO)
+
+    shared_processors: list[structlog.types.Processor] = [
+        structlog.contextvars.merge_contextvars,
+        structlog.processors.add_log_level,
+        structlog.processors.TimeStamper(fmt="iso"),
+        _add_service_info(
+            service=settings.SERVICE_NAME,
+            version=settings.SERVICE_VERSION,
+            environment=settings.ENVIRONMENT,
+        ),
+        structlog.processors.StackInfoRenderer(),
+        structlog.processors.format_exc_info,
+        structlog.processors.UnicodeDecoder(),
+    ]
+
+    if settings.LOG_FORMAT == "console":
+        renderer: structlog.types.Processor = structlog.dev.ConsoleRenderer()
+    else:
+        renderer = structlog.processors.JSONRenderer()
+
+    structlog.configure(
+        processors=[*shared_processors, renderer],
+        wrapper_class=structlog.make_filtering_bound_logger(log_level),
+        logger_factory=structlog.PrintLoggerFactory(),
+        cache_logger_on_first_use=True,
+        context_class=dict,
+    )
+
+
+def get_logger(**initial_values: Any) -> Any:
+    """Return a structlog bound logger, optionally with initial bound values."""
+    return structlog.get_logger(**initial_values)

backend/app/core/middleware.py

@@ -0,0 +1,155 @@
+"""Request pipeline middleware: request ID, correlation, security headers, logging.
+
+Generates a UUID v4 request_id for every request, propagates correlation IDs,
+applies security headers, and logs each request with status-appropriate level.
+
+This middleware MUST be the outermost middleware (added last in code) so that
+security headers and X-Request-ID are set on ALL responses, including CORS
+preflight OPTIONS responses handled by CORSMiddleware.
+"""
+
+from __future__ import annotations
+
+import re
+import time
+from typing import Any
+from uuid import uuid4
+
+import structlog
+from starlette.middleware.base import BaseHTTPMiddleware, RequestResponseEndpoint
+from starlette.requests import Request
+from starlette.responses import Response
+from starlette.types import ASGIApp
+
+# Correlation ID validation: alphanumeric, hyphens, underscores, dots; max 128 chars.
+# Rejects injection payloads (newlines, control chars) that could forge log entries.
+_CORRELATION_ID_PATTERN = re.compile(r"^[a-zA-Z0-9\-_.]{1,128}$")
+
+# Security headers applied to every response (PRD Section 4.1.12)
+_SECURITY_HEADERS: dict[str, str] = {
+    "X-Content-Type-Options": "nosniff",
+    "X-Frame-Options": "DENY",
+    "X-XSS-Protection": "0",
+    "Referrer-Policy": "strict-origin-when-cross-origin",
+    "Permissions-Policy": "camera=(), microphone=(), geolocation=()",
+}
+
+# HSTS header only applied in production
+_HSTS_VALUE = "max-age=31536000; includeSubDomains"
+
+
+class RequestPipelineMiddleware(BaseHTTPMiddleware):
+    """Middleware that provides request tracing, security headers, and request logging.
+
+    Args:
+        app: The ASGI application.
+        environment: Deployment environment (e.g. "local", "staging", "production").
+                     Controls whether HSTS header is applied.
+    """
+
+    def __init__(self, app: ASGIApp, environment: str = "local") -> None:
+        super().__init__(app)
+        self.environment = environment
+
+    async def dispatch(
+        self, request: Request, call_next: RequestResponseEndpoint
+    ) -> Response:
+        # 1. Generate request_id (UUID v4)
+        request_id = str(uuid4())
+
+        # 2. Read X-Correlation-ID or fall back to request_id.
+        #    Validate format to prevent log injection (SEC-001).
+        raw_correlation = request.headers.get("x-correlation-id")
+        if raw_correlation and _CORRELATION_ID_PATTERN.match(raw_correlation):
+            correlation_id = raw_correlation
+        else:
+            correlation_id = request_id
+
+        # 3. Store in request.state for downstream handlers and error handlers
+        request.state.request_id = request_id
+        request.state.correlation_id = correlation_id
+
+        # 4. Bind to structlog contextvars for automatic inclusion in all logs
+        structlog.contextvars.clear_contextvars()
+        structlog.contextvars.bind_contextvars(
+            request_id=request_id,
+            correlation_id=correlation_id,
+        )
+
+        # 5. Record start time
+        start = time.perf_counter()
+
+        # 6. Process request — wrap in try/except so headers are set even
+        #    when an exception propagates past all exception handlers.
+        try:
+            response = await call_next(request)
+        except Exception:
+            # Log the exception so it's not silently swallowed (BUG-001).
+            # In practice, global exception handlers (errors.py) catch most
+            # exceptions before they reach here.
+            structlog.get_logger().exception(
+                "unhandled_exception_in_middleware",
+                method=request.method,
+                path=request.url.path,
+            )
+            response = Response(
+                content='{"error":"INTERNAL_ERROR","message":"An unexpected error occurred."}',
+                status_code=500,
+                media_type="application/json",
+            )
+
+        # 7. Calculate duration
+        duration_ms = round((time.perf_counter() - start) * 1000, 2)
+
+        # 8. Apply security headers
+        _apply_security_headers(response, self.environment)
+
+        # 9. Set X-Request-ID response header
+        response.headers["X-Request-ID"] = request_id
+
+        # 10. Log request with appropriate level based on status code
+        _log_request(request, response, duration_ms)
+
+        # 11. Clear contextvars after logging to prevent leakage (FUNC-001)
+        structlog.contextvars.clear_contextvars()
+
+        return response
+
+
+def _apply_security_headers(response: Response, environment: str) -> None:
+    """Apply security headers to the response."""
+    for header, value in _SECURITY_HEADERS.items():
+        response.headers[header] = value
+
+    if environment == "production":
+        response.headers["Strict-Transport-Security"] = _HSTS_VALUE
+
+
+def _log_request(request: Request, response: Response, duration_ms: float) -> None:
+    """Log the completed request at the appropriate level.
+
+    - 2xx → info
+    - 4xx → warning
+    - 5xx → error
+    """
+    logger: Any = structlog.get_logger()
+
+    log_kwargs: dict[str, Any] = {
+        "method": request.method,
+        "path": request.url.path,
+        "status_code": response.status_code,
+        "duration_ms": duration_ms,
+    }
+
+    # Include user_id if set by auth middleware/handler
+    user_id = getattr(request.state, "user_id", None)
+    if user_id is not None:
+        log_kwargs["user_id"] = user_id
+
+    status = response.status_code
+    if status >= 500:
+        logger.error("request_completed", **log_kwargs)
+    elif status >= 400:
+        logger.warning("request_completed", **log_kwargs)
+    else:
+        logger.info("request_completed", **log_kwargs)

backend/app/main.py

@@ -6,6 +6,11 @@
 from app.api.main import api_router
 from app.core.config import settings
 from app.core.errors import register_exception_handlers
+from app.core.logging import setup_logging
+from app.core.middleware import RequestPipelineMiddleware
+
+# Configure structured logging (JSON in production, console in local dev)
+setup_logging(settings)
 
 
 def custom_generate_unique_id(route: APIRoute) -> str:
@@ -34,4 +39,10 @@ def custom_generate_unique_id(route: APIRoute) -> str:
         allow_headers=["*"],
     )
 
+# Request pipeline middleware: request ID, correlation, security headers, logging.
+# Added AFTER CORSMiddleware in code — Starlette adds middleware as a stack
+# (last-added = outermost), so this wraps CORS. This ensures security headers
+# and X-Request-ID are set on ALL responses, including CORS preflight OPTIONS.
+app.add_middleware(RequestPipelineMiddleware, environment=settings.ENVIRONMENT)
+
 app.include_router(api_router, prefix=settings.API_V1_STR)

backend/pyproject.toml

@@ -19,6 +19,7 @@ dependencies = [
     "sentry-sdk[fastapi]>=2.0.0,<3.0.0",
     "pyjwt<3.0.0,>=2.8.0",
     "pwdlib[argon2,bcrypt]>=0.3.0",
+    "structlog>=24.1.0,<26.0.0",
 ]
 
 [dependency-groups]