Finalize diagnostics, logging controls, and email test support

backend/app/main.py

@@ -1,4 +1,8 @@
 import asyncio
+import logging
+import time
+import uuid
+from typing import Awaitable, Callable
 
 from fastapi import FastAPI, Request
 from fastapi.middleware.cors import CORSMiddleware
@@ -21,9 +25,19 @@ from .routers.feedback import router as feedback_router
 from .routers.site import router as site_router
 from .routers.events import router as events_router
 from .services.jellyfin_sync import run_daily_jellyfin_sync
-from .logging_config import configure_logging
+from .logging_config import (
+    bind_request_id,
+    configure_logging,
+    reset_request_id,
+    sanitize_headers,
+    sanitize_value,
+    summarize_http_body,
+)
 from .runtime import get_runtime_settings
 
+logger = logging.getLogger(__name__)
+_background_tasks: list[asyncio.Task[None]] = []
+
 app = FastAPI(
     title=settings.app_name,
     docs_url="/docs" if settings.api_docs_enabled else None,
@@ -41,8 +55,56 @@ app.add_middleware(
 
 
 @app.middleware("http")
-async def add_security_headers(request: Request, call_next):
-    response = await call_next(request)
+async def log_requests_and_add_security_headers(request: Request, call_next):
+    request_id = request.headers.get("X-Request-ID") or uuid.uuid4().hex[:12]
+    token = bind_request_id(request_id)
+    request.state.request_id = request_id
+    started_at = time.perf_counter()
+    body = await request.body()
+    body_summary = summarize_http_body(body, request.headers.get("content-type"))
+
+    async def receive() -> dict:
+        return {"type": "http.request", "body": body, "more_body": False}
+
+    request._receive = receive
+    logger.info(
+        "request started method=%s path=%s query=%s client=%s headers=%s body=%s",
+        request.method,
+        request.url.path,
+        sanitize_value(dict(request.query_params)),
+        request.client.host if request.client else "-",
+        sanitize_headers(
+            {
+                key: value
+                for key, value in request.headers.items()
+                if key.lower()
+                in {
+                    "content-type",
+                    "content-length",
+                    "user-agent",
+                    "x-forwarded-for",
+                    "x-forwarded-proto",
+                    "x-request-id",
+                }
+            }
+        ),
+        body_summary,
+    )
+    try:
+        response = await call_next(request)
+    except Exception:
+        duration_ms = round((time.perf_counter() - started_at) * 1000, 2)
+        logger.exception(
+            "request failed method=%s path=%s duration_ms=%s",
+            request.method,
+            request.url.path,
+            duration_ms,
+        )
+        reset_request_id(token)
+        raise
+
+    duration_ms = round((time.perf_counter() - started_at) * 1000, 2)
+    response.headers.setdefault("X-Request-ID", request_id)
     response.headers.setdefault("X-Content-Type-Options", "nosniff")
     response.headers.setdefault("X-Frame-Options", "DENY")
     response.headers.setdefault("Referrer-Policy", "no-referrer")
@@ -53,6 +115,21 @@ async def add_security_headers(request: Request, call_next):
             "Content-Security-Policy",
             "default-src 'none'; frame-ancestors 'none'; base-uri 'none'",
         )
+    logger.info(
+        "request completed method=%s path=%s status=%s duration_ms=%s response_headers=%s",
+        request.method,
+        request.url.path,
+        response.status_code,
+        duration_ms,
+        sanitize_headers(
+            {
+                key: value
+                for key, value in response.headers.items()
+                if key.lower() in {"content-type", "content-length", "x-request-id"}
+            }
+        ),
+    )
+    reset_request_id(token)
     return response
 
 
@@ -60,16 +137,69 @@ async def add_security_headers(request: Request, call_next):
 async def health() -> dict:
     return {"status": "ok"}
 
+
+async def _run_background_task(
+    name: str, coroutine_factory: Callable[[], Awaitable[None]]
+) -> None:
+    token = bind_request_id(f"task-{name}")
+    logger.info("background task started task=%s", name)
+    try:
+        await coroutine_factory()
+        logger.warning("background task exited task=%s", name)
+    except asyncio.CancelledError:
+        logger.info("background task cancelled task=%s", name)
+        raise
+    except Exception:
+        logger.exception("background task crashed task=%s", name)
+        raise
+    finally:
+        reset_request_id(token)
+
+
+def _launch_background_task(name: str, coroutine_factory: Callable[[], Awaitable[None]]) -> None:
+    task = asyncio.create_task(
+        _run_background_task(name, coroutine_factory), name=f"magent:{name}"
+    )
+    _background_tasks.append(task)
+
+
 @app.on_event("startup")
 async def startup() -> None:
+    configure_logging(
+        settings.log_level,
+        settings.log_file,
+        log_file_max_bytes=settings.log_file_max_bytes,
+        log_file_backup_count=settings.log_file_backup_count,
+        log_http_client_level=settings.log_http_client_level,
+        log_background_sync_level=settings.log_background_sync_level,
+    )
+    logger.info("startup begin app=%s build=%s", settings.app_name, settings.site_build_number)
     init_db()
     runtime = get_runtime_settings()
-    configure_logging(runtime.log_level, runtime.log_file)
-    asyncio.create_task(run_daily_jellyfin_sync())
-    asyncio.create_task(startup_warmup_requests_cache())
-    asyncio.create_task(run_requests_delta_loop())
-    asyncio.create_task(run_daily_requests_full_sync())
-    asyncio.create_task(run_daily_db_cleanup())
+    configure_logging(
+        runtime.log_level,
+        runtime.log_file,
+        log_file_max_bytes=runtime.log_file_max_bytes,
+        log_file_backup_count=runtime.log_file_backup_count,
+        log_http_client_level=runtime.log_http_client_level,
+        log_background_sync_level=runtime.log_background_sync_level,
+    )
+    logger.info(
+        "runtime settings applied log_level=%s log_file=%s log_file_max_bytes=%s log_file_backup_count=%s log_http_client_level=%s log_background_sync_level=%s request_source=%s",
+        runtime.log_level,
+        runtime.log_file,
+        runtime.log_file_max_bytes,
+        runtime.log_file_backup_count,
+        runtime.log_http_client_level,
+        runtime.log_background_sync_level,
+        runtime.requests_data_source,
+    )
+    _launch_background_task("jellyfin-sync", run_daily_jellyfin_sync)
+    _launch_background_task("requests-warmup", startup_warmup_requests_cache)
+    _launch_background_task("requests-delta-loop", run_requests_delta_loop)
+    _launch_background_task("requests-full-sync", run_daily_requests_full_sync)
+    _launch_background_task("db-cleanup", run_daily_db_cleanup)
+    logger.info("startup complete")
 
 
 app.include_router(requests_router)