feat(middleware): implement request logging middleware with process time tracking

Author: ImMohammad20000

app/__init__.py

@@ -5,13 +5,12 @@
 from fastapi import FastAPI, Request, status
 from fastapi.encoders import jsonable_encoder
 from fastapi.exceptions import RequestValidationError
-from fastapi.middleware.cors import CORSMiddleware
 from fastapi.responses import JSONResponse
 from fastapi.routing import APIRoute
-from uvicorn.middleware.proxy_headers import ProxyHeadersMiddleware
 
+from app.middlewares import setup_middleware
 from app.utils.logger import get_logger
-from config import ALLOWED_ORIGINS, DOCS, SUBSCRIPTION_PATH
+from config import DOCS, SUBSCRIPTION_PATH
 
 __version__ = "1.8.1"
 
@@ -70,16 +69,7 @@ async def lifespan(app: FastAPI):
 scheduler = AsyncIOScheduler(job_defaults={"max_instances": 30}, timezone="UTC")
 logger = get_logger()
 
-
-app.add_middleware(
-    CORSMiddleware,
-    allow_origins=ALLOWED_ORIGINS,
-    allow_credentials=True,
-    allow_methods=["*"],
-    allow_headers=["*"],
-)
-
-app.add_middleware(ProxyHeadersMiddleware, trusted_hosts="*")
+setup_middleware(app)
 
 from app import routers, telegram, jobs  # noqa
 from app.routers import api_router  # noqa

app/middlewares/__init__.py

@@ -0,0 +1,20 @@
+from fastapi import FastAPI
+from fastapi.middleware.cors import CORSMiddleware
+from uvicorn.middleware.proxy_headers import ProxyHeadersMiddleware
+
+from app.utils.logger import get_logger
+from config import ALLOWED_ORIGINS
+
+from .request_logging import RequestProcessTimeLoggingMiddleware
+
+
+def setup_middleware(app: FastAPI):
+    app.add_middleware(
+        CORSMiddleware,
+        allow_origins=ALLOWED_ORIGINS,
+        allow_credentials=True,
+        allow_methods=["*"],
+        allow_headers=["*"],
+    )
+    app.add_middleware(ProxyHeadersMiddleware, trusted_hosts="*")
+    app.add_middleware(RequestProcessTimeLoggingMiddleware, access_logger=get_logger("uvicorn.access"))

app/middlewares/request_logging.py

@@ -0,0 +1,37 @@
+import logging
+from time import perf_counter
+
+from starlette.middleware.base import BaseHTTPMiddleware
+from starlette.requests import Request
+
+
+class RequestProcessTimeLoggingMiddleware(BaseHTTPMiddleware):
+    def __init__(self, app, access_logger: logging.Logger):
+        super().__init__(app)
+        self.access_logger = access_logger
+
+    async def dispatch(self, request: Request, call_next):
+        start_time = perf_counter()
+        status_code = 500
+
+        try:
+            response = await call_next(request)
+            status_code = response.status_code
+            return response
+        finally:
+            process_time_ms = (perf_counter() - start_time) * 1000
+            path = request.url.path
+            if request.url.query:
+                path = f"{path}?{request.url.query}"
+            http_version = request.scope.get("http_version", "1.1")
+            client_addr = request.client.host if request.client else "-"
+
+            self.access_logger.info(
+                '%s - "%s %s HTTP/%s" %d',
+                client_addr,
+                request.method,
+                path,
+                http_version,
+                status_code,
+                extra={"process_time": f"{process_time_ms:.2f}ms"},
+            )

app/utils/logger.py

@@ -4,7 +4,7 @@
 
 import click
 from uvicorn.config import LOGGING_CONFIG
-from uvicorn.logging import DefaultFormatter
+from uvicorn.logging import AccessFormatter, ColourizedFormatter, DefaultFormatter
 
 from config import (
     ECHO_SQL_QUERIES,
@@ -26,6 +26,37 @@ def formatMessage(self, record: logging.LogRecord) -> str:
         return super().formatMessage(recordcopy)
 
 
+class CustomAccessFormatter(AccessFormatter):
+    def formatMessage(self, record: logging.LogRecord) -> str:
+        recordcopy = copy(record)
+
+        try:
+            client_addr, method, full_path, http_version, status_code = recordcopy.args  # type: ignore[misc]
+        except Exception:
+            return super().formatMessage(record)
+
+        status_code = self.get_status_code(int(status_code))  # type: ignore[arg-type]
+        request_line = f"{method} {full_path} HTTP/{http_version}"
+        if self.use_colors:
+            request_line = click.style(request_line, bold=True)
+
+        recordcopy.__dict__.update(
+            {
+                "client_addr": client_addr,
+                "request_line": request_line,
+                "status_code": status_code,
+                "process_time": getattr(recordcopy, "process_time", "-"),
+            }
+        )
+
+        return ColourizedFormatter.formatMessage(self, recordcopy)
+
+
+class RequireProcessTimeFilter(logging.Filter):
+    def filter(self, record: logging.LogRecord) -> bool:
+        return getattr(record, "process_time", None) is not None
+
+
 LOGGING_CONFIG["formatters"]["custom"] = {
     "()": CustomLoggingFormatter,
     "fmt": "%(levelprefix)s %(asctime)s - %(nameprefix)s - %(message)s",
@@ -39,8 +70,14 @@ def formatMessage(self, record: logging.LogRecord) -> str:
 
 LOGGING_CONFIG["formatters"]["default"]["fmt"] = "%(levelprefix)s %(asctime)s - %(message)s"
 LOGGING_CONFIG["formatters"]["access"]["fmt"] = (
-    '%(levelprefix)s %(asctime)s - %(client_addr)s - "%(request_line)s" %(status_code)s'
+    '%(levelprefix)s %(asctime)s - %(client_addr)s - "%(request_line)s" %(status_code)s - %(process_time)s'
 )
+LOGGING_CONFIG["formatters"]["access"]["()"] = CustomAccessFormatter
+
+LOGGING_CONFIG.setdefault("filters", {})
+LOGGING_CONFIG["filters"]["require_process_time"] = {"()": RequireProcessTimeFilter}
+LOGGING_CONFIG["loggers"]["uvicorn.access"].setdefault("filters", [])
+LOGGING_CONFIG["loggers"]["uvicorn.access"]["filters"].append("require_process_time")
 
 LOGGING_CONFIG["loggers"]["uvicorn"]["level"] = LOG_LEVEL
 LOGGING_CONFIG["loggers"]["uvicorn.error"]["level"] = LOG_LEVEL