Feature/refactor middlewares (#1115)

* refactor middlewares

* update from comments

* update tests

* log request after processing

* update changelog

* update logger name

Author: vincentsarago

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**

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 @@ def validate_access_token(access_token: str = Security(api_key_query)):
 )
 
 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)
 

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 @@ async def route1():
         """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}"