Repository: developmentseed/titiler (python)

Issue:
update logging middleware with more request details
We could include more info about the route, path parameters, query parameters, etc like we recently added to the maap-eoapi deployment in https://github.com/MAAP-Project/maap-eoapi/pull/49

https://github.com/developmentseed/titiler/blob/6d1519e9a289a1f1f8e15c04020920f82cf02c60/src/titiler/core/titiler/core/middleware.py#L100-L135

Pull request:
Feature/refactor middlewares
closes #1107 

This PR does:
- refactor middleware classes to use python's dataclasses (a.la @alukach 🙏)
- re-write the LoggerMiddleware to enable more output data and custom logger  

Patch:
diff --git a/CHANGES.md b/CHANGES.md
index df651ca..60021ee 100644
--- a/CHANGES.md
+++ b/CHANGES.md
@@ -12,6 +12,80 @@
 
 * add point value query on right-click to map viewer (@hrodmn, https://github.com/developmentseed/titiler/pull/1100)
 
+* refactor middlewares to use python's dataclasses
+
+* update `LoggerMiddleware` output format and options **breaking change**
+
+    ```python
+    from fastapi import FastAPI
+
+    from titiler.core.middlewares import LoggerMiddleware
+
+    # before
+    app = FastAPI()
+    app.add_middlewares(LoggerMiddleware, querystrings=True, headers=True)
+
+    # now
+    app = FastAPI()
+    app.add_middlewares(
+        LoggerMiddleware,
+        # custom Logger
+        logger=logging.getLogger("mytiler.requests"),  # default to logging.getLogger("titiler.requests")
+    )
+    ```
+
+    Note: logger needs then to be `configured` at runtime. e.g :
+
+    ```python
+    from logging import config
+    config.dictConfig(
+        {
+            "version": 1,
+            "disable_existing_loggers": False,
+            "formatters": {
+                "detailed": {
+                    "format": "%(asctime)s - %(levelname)s - %(name)s - %(message)s"
+                },
+                "request": {
+                    "format": (
+                        "%(asctime)s - %(levelname)s - %(name)s - %(message)s "
+                        + json.dumps(
+                            {
+                                k: f"%({k})s"
+                                for k in [
+                                    "method",
+                                    "referer",
+                                    "origin",
+                                    "route",
+                                    "path",
+                                    "path_params",
+                                    "query_params",
+                                    "headers",
+                                ]
+                            }
+                        )
+                    ),
+                },
+            },
+            "handlers": {
+                "console_request": {
+                    "class": "logging.StreamHandler",
+                    "level": "DEBUG",
+                    "formatter": "request",
+                    "stream": "ext://sys.stdout",
+                },
+            },
+            "loggers": {
+                "mytiler.requests": {
+                    "level": "INFO",
+                    "handlers": ["console_request"],
+                    "propagate": False,
+                },
+            },
+        }
+    )
+    ```
+
 ### titiler.xarray
 
 * change `get_variable.drop_dim` parameter type from `str` to `List[str]` **breaking change**
diff --git a/src/titiler/application/titiler/application/main.py b/src/titiler/application/titiler/application/main.py
index a47d0f5..afd4c84 100644
--- a/src/titiler/application/titiler/application/main.py
+++ b/src/titiler/application/titiler/application/main.py
@@ -1,6 +1,8 @@
 """titiler app."""
 
+import json
 import logging
+from logging import config as log_config
 
 import jinja2
 import rasterio
@@ -201,9 +203,68 @@ app.add_middleware(
 )
 
 if api_settings.debug:
-    app.add_middleware(LoggerMiddleware, headers=True, querystrings=True)
+    app.add_middleware(LoggerMiddleware)
     app.add_middleware(TotalTimeMiddleware)
 
+    log_config.dictConfig(
+        {
+            "version": 1,
+            "disable_existing_loggers": False,
+            "formatters": {
+                "detailed": {
+                    "format": "%(asctime)s - %(levelname)s - %(name)s - %(message)s"
+                },
+                "request": {
+                    "format": (
+                        "%(asctime)s - %(levelname)s - %(name)s - %(message)s "
+                        + json.dumps(
+                            {
+                                k: f"%({k})s"
+                                for k in [
+                                    "method",
+                                    "referer",
+                                    "origin",
+                                    "route",
+                                    "path",
+                                    "path_params",
+                                    "query_params",
+                                    "headers",
+                                ]
+                            }
+                        )
+                    ),
+                },
+            },
+            "handlers": {
+                "console_detailed": {
+                    "class": "logging.StreamHandler",
+                    "level": "WARNING",
+                    "formatter": "detailed",
+                    "stream": "ext://sys.stdout",
+                },
+                "console_request": {
+                    "class": "logging.StreamHandler",
+                    "level": "DEBUG",
+                    "formatter": "request",
+                    "stream": "ext://sys.stdout",
+                },
+            },
+            "loggers": {
+                "titlier": {
+                    "level": "WARNING",
+                    "handlers": ["console_detailed"],
+                    "propagate": False,
+                },
+                "titiler-requests": {
+                    "level": "INFO",
+                    "handlers": ["console_request"],
+                    "propagate": False,
+                },
+            },
+        }
+    )
+
+
 if api_settings.lower_case_query_parameters:
     app.add_middleware(LowerCaseQueryStringMiddleware)
 
diff --git a/src/titiler/core/titiler/core/middleware.py b/src/titiler/core/titiler/core/middleware.py
index da21ec8..161c389 100644
--- a/src/titiler/core/titiler/core/middleware.py
+++ b/src/titiler/core/titiler/core/middleware.py
@@ -1,39 +1,34 @@
 """Titiler middlewares."""
 
+from __future__ import annotations
+
 import logging
 import re
 import time
-from typing import Optional, Set
+from dataclasses import dataclass, field
+from typing import Set
 from urllib.parse import urlencode
 
-from fastapi.logger import logger
 from starlette.datastructures import MutableHeaders
 from starlette.requests import Request
 from starlette.types import ASGIApp, Message, Receive, Scope, Send
 
 
+@dataclass(frozen=True)
 class CacheControlMiddleware:
-    """MiddleWare to add CacheControl in response headers."""
-
-    def __init__(
-        self,
-        app: ASGIApp,
-        cachecontrol: Optional[str] = None,
-        cachecontrol_max_http_code: Optional[int] = 500,
-        exclude_path: Optional[Set[str]] = None,
-    ) -> None:
-        """Init Middleware.
-
-        Args:
-            app (ASGIApp): starlette/FastAPI application.
-            cachecontrol (str): Cache-Control string to add to the response.
-            exclude_path (set): Set of regex expression to use to filter the path.
-
-        """
-        self.app = app
-        self.cachecontrol = cachecontrol
-        self.cachecontrol_max_http_code = cachecontrol_max_http_code
-        self.exclude_path = exclude_path or set()
+    """MiddleWare to add CacheControl in response headers.
+
+    Args:
+        app (ASGIApp): starlette/FastAPI application.
+        cachecontrol (str): Cache-Control string to add to the response.
+        exclude_path (set): Set of regex expression to use to filter the path.
+
+    """
+
+    app: ASGIApp
+    cachecontrol: str | None = None
+    cachecontrol_max_http_code: int = 500
+    exclude_path: Set[str] = field(default_factory=set)
 
     async def __call__(self, scope: Scope, receive: Receive, send: Send):
         """Handle call."""
@@ -60,17 +55,16 @@ class CacheControlMiddleware:
         await self.app(scope, receive, send_wrapper)
 
 
+@dataclass(frozen=True)
 class TotalTimeMiddleware:
-    """MiddleWare to add Total process time in response headers."""
+    """MiddleWare to add Total process time in response headers.
 
-    def __init__(self, app: ASGIApp) -> None:
-        """Init Middleware.
+    Args:
+        app (ASGIApp): starlette/FastAPI application.
 
-        Args:
-            app (ASGIApp): starlette/FastAPI application.
+    """
 
-        """
-        self.app = app
+    app: ASGIApp
 
     async def __call__(self, scope: Scope, receive: Receive, send: Send):
         """Handle call."""
@@ -82,6 +76,8 @@ class TotalTimeMiddleware:
 
         async def send_wrapper(message: Message):
             """Send Message."""
+            nonlocal start_time
+
             if message["type"] == "http.response.start":
                 response_headers = MutableHeaders(scope=message)
                 process_time = time.time() - start_time
@@ -97,57 +93,60 @@ class TotalTimeMiddleware:
         await self.app(scope, receive, send_wrapper)
 
 
+@dataclass(frozen=True)
 class LoggerMiddleware:
     """MiddleWare to add logging."""
 
-    def __init__(
-        self,
-        app: ASGIApp,
-        querystrings: bool = False,
-        headers: bool = False,
-    ) -> None:
-        """Init Middleware.
-
-        Args:
-            app (ASGIApp): starlette/FastAPI application.
-
-        """
-        self.app = app
-        self.querystrings = querystrings
-        self.headers = headers
-        self.logger = logger
-        logger.setLevel(logging.DEBUG)
+    app: ASGIApp
+    logger: logging.Logger = field(
+        default_factory=lambda: logging.getLogger("titiler.requests")
+    )
 
     async def __call__(self, scope: Scope, receive: Receive, send: Send):
         """Handle call."""
-        if scope["type"] == "http":
-            request = Request(scope)
-
-            self.logger.debug(str(request.url))
-
-            qs = dict(request.query_params)
-            if qs and self.querystrings:
-                self.logger.debug(qs)
-
-            if self.headers:
-                self.logger.debug(dict(request.headers))
-
-        await self.app(scope, receive, send)
-
+        if scope["type"] != "http":
+            return await self.app(scope, receive, send)
 
+        exception: Exception | None = None
+        try:
+            await self.app(scope, receive, send)
+        except Exception as e:
+            exception = e
+
+        request = Request(scope, receive=receive)
+
+        data = {
+            "method": request.method,
+            "referer": next(
+                (request.headers.get(attr) for attr in ["referer", "referrer"]),
+                None,
+            ),
+            "origin": request.headers.get("origin"),
+            "path": request.url.path,
+            "path_params": request.path_params,
+            "query_params": dict(request.query_params),
+            "headers": dict(request.headers),
+        }
+
+        if route := scope.get("route"):
+            data["route"] = route.path
+
+        self.logger.info(
+            f"Request received: {request.url.path} {request.method}",
+            extra=data,
+        )
+        if exception:
+            raise exception
+
+
+@dataclass(frozen=True)
 class LowerCaseQueryStringMiddleware:
     """Middleware to make URL parameters case-insensitive.
     taken from: https://github.com/tiangolo/fastapi/issues/826
-    """
 
-    def __init__(self, app: ASGIApp) -> None:
-        """Init Middleware.
-
-        Args:
-            app (ASGIApp): starlette/FastAPI application.
+    """
 
-        """
-        self.app = app
+    app: ASGIApp
 
     async def __call__(self, scope: Scope, receive: Receive, send: Send):
         """Handle call."""


Test patch:
diff --git a/src/titiler/core/tests/test_logger_middleware.py b/src/titiler/core/tests/test_logger_middleware.py
index 9c298f5..cb24cf7 100644
--- a/src/titiler/core/tests/test_logger_middleware.py
+++ b/src/titiler/core/tests/test_logger_middleware.py
@@ -1,12 +1,17 @@
 """Test titiler.core.middleware.TotalTimeMiddleware."""
 
-from fastapi import FastAPI
+import json
+import logging
+from logging import config
+
+import pytest
+from fastapi import FastAPI, Path
 from starlette.testclient import TestClient
 
 from titiler.core.middleware import LoggerMiddleware
 
 
-def test_timing_middleware_exclude(caplog):
+def test_timing_middleware(caplog):
     """Create App."""
     app = FastAPI()
 
@@ -15,18 +20,103 @@ def test_timing_middleware_exclude(caplog):
         """route1."""
         return "Yo"
 
-    app.add_middleware(LoggerMiddleware, querystrings=True, headers=True)
+    @app.get("/route2/{value}")
+    async def route2(value: str = Path()):
+        """route2."""
+        return value
+
+    @app.get("/route3/{value}")
+    async def route3(value: str = Path()):
+        """route3."""
+        raise Exception("something went wrong")
+
+    app.add_middleware(LoggerMiddleware)
+
+    config.dictConfig(
+        {
+            "version": 1,
+            "disable_existing_loggers": False,
+            "formatters": {
+                "request": {
+                    "format": (
+                        "%(asctime)s - %(levelname)s - %(name)s - %(message)s "
+                        + json.dumps(
+                            {
+                                k: f"%({k})s"
+                                for k in [
+                                    "method",
+                                    "referer",
+                                    "origin",
+                                    "route",
+                                    "path",
+                                    "path_params",
+                                    "query_params",
+                                    "headers",
+                                ]
+                            }
+                        )
+                    ),
+                },
+            },
+            "handlers": {
+                "console_request": {
+                    "class": "logging.StreamHandler",
+                    "level": "DEBUG",
+                    "formatter": "request",
+                    "stream": "ext://sys.stdout",
+                },
+            },
+            "loggers": {
+                "titiler.requests": {
+                    "level": "INFO",
+                    "handlers": ["console_request"],
+                    "propagate": True,
+                },
+            },
+        }
+    )
 
     with TestClient(app) as client:
-        caplog.clear()
-        client.get("/route1")
-        assert len([rec.message for rec in caplog.records]) == 2
-
-        caplog.clear()
-        client.get("/route1", params={"hey": "yo"})
-        assert len([rec.message for rec in caplog.records]) == 3
-
-        caplog.clear()
-        client.get("/route1", params={"hey": "yo"}, headers={"accept-encoding": "gzip"})
-        h = caplog.records[2].message
-        assert "'accept-encoding': 'gzip'" in h
+        with caplog.at_level(logging.INFO, logger="titiler.requests"):
+            caplog.clear()
+            client.get("/route1")
+            log = caplog.records[0]
+            assert log.name == "titiler.requests"
+            assert log.levelname == "INFO"
+            assert log.message == "Request received: /route1 GET"
+            assert hasattr(log, "query_params")
+            assert log.route == "/route1"
+
+            caplog.clear()
+            client.get("/route1", params={"hey": "yo"})
+            log = caplog.records[0]
+            assert log.message == "Request received: /route1 GET"
+            assert log.query_params == {"hey": "yo"}
+
+            caplog.clear()
+            client.get(
+                "/route1", params={"hey": "yo"}, headers={"accept-encoding": "gzip"}
+            )
+            log = caplog.records[0]
+            assert log.message == "Request received: /route1 GET"
+            assert log.query_params == {"hey": "yo"}
+            assert log.headers["accept-encoding"] == "gzip"
+
+            caplog.clear()
+            client.get("/route2/val")
+            log = caplog.records[0]
+            assert log.name == "titiler.requests"
+            assert log.levelname == "INFO"
+            assert log.message == "Request received: /route2/val GET"
+            assert hasattr(log, "query_params")
+            assert log.route == "/route2/{value}"
+
+            caplog.clear()
+            with pytest.raises(Exception):  # noqa: B017
+                client.get("/route3/val")
+                log = caplog.records[0]
+                assert log.name == "titiler.requests"
+                assert log.levelname == "INFO"
+                assert log.message == "Request received: /route3/val GET"
+                assert hasattr(log, "query_params")
+                assert log.route == "/route3/{value}"