Add logging configuration and middleware for improved request tracking

app/core/config.py

@@ -16,6 +16,11 @@ class Settings(BaseSettings):
     RELOAD: bool = True
     LOG_LEVEL: str = "info"
 
+    LOG_FILE: str = "logs/app.log"
+    LOG_MAX_SIZE: int = 10 * 1024 * 1024
+    LOG_BACKUP_COUNT: int = 5
+    LOG_FORMAT: str = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
+
     DATABASE_URL: str = "sqlite+aiosqlite:///data/soundboard.db"
     DATABASE_ECHO: bool = False
 

app/core/database.py

@@ -5,6 +5,7 @@ from sqlmodel import SQLModel
 from sqlmodel.ext.asyncio.session import AsyncSession
 
 from app.core.config import settings
+from app.core.logging import get_logger
 from app.models import (  # noqa: F401
     plan,
     playlist,
@@ -23,10 +24,12 @@ engine: AsyncEngine = create_async_engine(
 
 
 async def get_db() -> AsyncGenerator[AsyncSession, None]:
+    logger = get_logger(__name__)
     async with AsyncSession(engine) as session:
         try:
             yield session
-        except Exception:
+        except Exception as e:
+            logger.exception("Database session error: %s", e)
             await session.rollback()
             raise
         finally:
@@ -34,5 +37,12 @@ async def get_db() -> AsyncGenerator[AsyncSession, None]:
 
 
 async def init_db() -> None:
-    async with engine.begin() as conn:
-        await conn.run_sync(SQLModel.metadata.create_all)
+    logger = get_logger(__name__)
+    try:
+        logger.info("Initializing database tables")
+        async with engine.begin() as conn:
+            await conn.run_sync(SQLModel.metadata.create_all)
+        logger.info("Database tables created successfully")
+    except Exception as e:
+        logger.exception("Failed to initialize database: %s", e)
+        raise

app/core/logging.py

@@ -0,0 +1,37 @@
+import logging
+import logging.handlers
+from pathlib import Path
+
+from app.core.config import settings
+
+
+def setup_logging() -> None:
+    """Set up logging configuration."""
+    log_dir = Path(settings.LOG_FILE).parent
+    log_dir.mkdir(exist_ok=True)
+
+    logger = logging.getLogger()
+    logger.setLevel(settings.LOG_LEVEL.upper())
+
+    if logger.handlers:
+        logger.handlers.clear()
+
+    formatter = logging.Formatter(settings.LOG_FORMAT)
+
+    console_handler = logging.StreamHandler()
+    console_handler.setFormatter(formatter)
+    logger.addHandler(console_handler)
+
+    file_handler = logging.handlers.RotatingFileHandler(
+        settings.LOG_FILE,
+        maxBytes=settings.LOG_MAX_SIZE,
+        backupCount=settings.LOG_BACKUP_COUNT,
+        encoding="utf-8",
+    )
+    file_handler.setFormatter(formatter)
+    logger.addHandler(file_handler)
+
+
+def get_logger(name: str) -> logging.Logger:
+    """Get a logger instance."""
+    return logging.getLogger(name)

app/main.py

@@ -4,20 +4,36 @@ from contextlib import asynccontextmanager
 from fastapi import FastAPI
 
 from app.core.database import init_db
+from app.core.logging import get_logger, setup_logging
+from app.middleware.logging import LoggingMiddleware
 
 
 @asynccontextmanager
 async def lifespan(_app: FastAPI) -> AsyncGenerator[None, None]:
+    """Application lifespan context manager for setup and teardown."""
+    setup_logging()
+    logger = get_logger(__name__)
+    logger.info("Starting application")
 
     await init_db()
+    logger.info("Database initialized")
+
     yield
 
+    logger.info("Shutting down application")
+
 
 def create_app() -> FastAPI:
+    """Create and configure the FastAPI application."""
     app = FastAPI(lifespan=lifespan)
 
+    app.add_middleware(LoggingMiddleware)
+
+    logger = get_logger(__name__)
+
     @app.get("/")
     def health() -> dict[str, str]:
+        logger.info("Health check endpoint accessed")
         return {"status": "healthy"}
 
     return app

app/middleware/__init__.py

@@ -2,4 +2,4 @@
 
 from app.middleware.logging import LoggingMiddleware
 
-__all__ = ["LoggingMiddleware"]
+__all__ = ["LoggingMiddleware"]

app/middleware/logging.py

@@ -0,0 +1,63 @@
+import time
+import uuid
+from collections.abc import Awaitable, Callable
+from typing import Any
+
+from fastapi import Request, Response
+from starlette.middleware.base import BaseHTTPMiddleware
+
+from app.core.logging import get_logger
+
+
+class LoggingMiddleware(BaseHTTPMiddleware):
+    """Middleware for logging HTTP requests and responses."""
+
+    def __init__(self, app: Any, *args: Any, **kwargs: Any) -> None:
+        """Initialize the logging middleware."""
+        super().__init__(app, *args, **kwargs)
+        self.logger = get_logger(__name__)
+
+    async def dispatch(
+        self,
+        request: Request,
+        call_next: Callable[[Request], Awaitable[Response]],
+    ) -> Response:
+        """Process the request and log details."""
+        request_id = str(uuid.uuid4())
+        start_time = time.time()
+
+        self.logger.info(
+            "Request started [%s]: %s %s - Client: %s",
+            request_id,
+            request.method,
+            request.url.path,
+            request.client.host if request.client else "unknown",
+        )
+
+        try:
+            response = await call_next(request)
+            process_time = time.time() - start_time
+
+            self.logger.info(
+                "Request completed [%s]: %s %s - Status: %d - Duration: %.3fs",
+                request_id,
+                request.method,
+                request.url.path,
+                response.status_code,
+                process_time,
+            )
+
+            response.headers["X-Process-Time"] = str(process_time)
+        except Exception:
+            process_time = time.time() - start_time
+
+            self.logger.exception(
+                "Request failed [%s]: %s %s - Duration: %.3fs",
+                request_id,
+                request.method,
+                request.url.path,
+                process_time,
+            )
+            raise
+        else:
+            return response

logs/.gitignore

@@ -0,0 +1,2 @@
+*
+!.gitignore