sort out telemetry in logging middleware

Author: hrodmn

src/titiler/application/titiler/application/main.py

@@ -45,6 +45,7 @@
 
 logging.getLogger("botocore.credentials").disabled = True
 logging.getLogger("botocore.utils").disabled = True
+logging.getLogger("rasterio.session").setLevel(logging.ERROR)
 logging.getLogger("rio-tiler").setLevel(logging.ERROR)
 
 
@@ -238,14 +239,14 @@ def validate_access_token(access_token: str = Security(api_key_query)):
                             {
                                 k: f"%({k})s"
                                 for k in [
-                                    "method",
-                                    "referer",
-                                    "origin",
-                                    "route",
-                                    "path",
-                                    "path_params",
-                                    "query_params",
-                                    "headers",
+                                    "http.method",
+                                    "http.referer",
+                                    "http.origin",
+                                    "http.route",
+                                    "http.path",
+                                    "http.request.header",
+                                    "titiler.path_params",
+                                    "titiler.query_params",
                                 ]
                             }
                         )
@@ -267,12 +268,12 @@ def validate_access_token(access_token: str = Security(api_key_query)):
                 },
             },
             "loggers": {
-                "titlier": {
-                    "level": "WARNING",
+                "titiler": {
+                    "level": "INFO",
                     "handlers": ["console_detailed"],
                     "propagate": False,
                 },
-                "titiler-requests": {
+                "titiler.requests": {
                     "level": "INFO",
                     "handlers": ["console_request"],
                     "propagate": False,

src/titiler/core/tests/test_logger_middleware.py

@@ -1,4 +1,4 @@
-"""Test titiler.core.middleware.TotalTimeMiddleware."""
+"""Test titiler.core.middleware.LoggerMiddleware."""
 
 import json
 import logging
@@ -11,7 +11,7 @@
 from titiler.core.middleware import LoggerMiddleware
 
 
-def test_timing_middleware(caplog):
+def test_logger_middleware(caplog):
     """Create App."""
     app = FastAPI()
 
@@ -44,14 +44,14 @@ async def route3(value: str = Path()):
                             {
                                 k: f"%({k})s"
                                 for k in [
-                                    "method",
-                                    "referer",
-                                    "origin",
-                                    "route",
-                                    "path",
-                                    "path_params",
-                                    "query_params",
-                                    "headers",
+                                    "http.method",
+                                    "http.referer",
+                                    "http.origin",
+                                    "http.route",
+                                    "http.path",
+                                    "titiler.path_params",
+                                    "titiler.query_params",
+                                    "http.request.header.",
                                 ]
                             }
                         )
@@ -84,32 +84,32 @@ async def route3(value: str = Path()):
             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"
+            assert hasattr(log, "titiler.query_params")
+            assert getattr(log, "http.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"}
+            assert getattr(log, "titiler.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"
+            assert getattr(log, "titiler.query_params") == {"hey": "yo"}
+            assert getattr(log, "http.request.header.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}"
+            assert hasattr(log, "titiler.query_params")
+            assert getattr(log, "http.route") == "/route2/{value}"
 
             caplog.clear()
             with pytest.raises(Exception):  # noqa: B017
@@ -118,5 +118,5 @@ async def route3(value: str = Path()):
                 assert log.name == "titiler.requests"
                 assert log.levelname == "INFO"
                 assert log.message == "Request received: /route3/val GET"
-                assert hasattr(log, "query_params")
+                assert hasattr(log, "titiler.query_params")
                 assert log.route == "/route3/{value}"

src/titiler/core/tests/test_telemetry.py

@@ -85,7 +85,3 @@ def test_tracing_enabled_success_path(memory_exporter):
     span = next(filter(lambda x: x.name == "TilerFactory.tile", finished_spans), None)
     assert span
     assert span.status.status_code == StatusCode.OK
-    assert span.attributes["titiler.path_param.tileMatrixSetId"] == "WebMercatorQuad"
-    assert span.attributes["titiler.path_param.z"] == TEST_Z
-    assert span.attributes["titiler.path_param.x"] == TEST_X
-    assert span.attributes["titiler.path_param.y"] == TEST_Y

src/titiler/core/titiler/core/factory.py

@@ -699,28 +699,28 @@ async def tileset(
                     minzoom = src_dst.minzoom
                     maxzoom = src_dst.maxzoom
 
-                collection_bbox = {
-                    "lowerLeft": [bounds[0], bounds[1]],
-                    "upperRight": [bounds[2], bounds[3]],
-                    "crs": CRS_to_uri(tms.rasterio_geographic_crs),
-                }
+                    collection_bbox = {
+                        "lowerLeft": [bounds[0], bounds[1]],
+                        "upperRight": [bounds[2], bounds[3]],
+                        "crs": CRS_to_uri(tms.rasterio_geographic_crs),
+                    }
 
-                tilematrix_limit = []
-                for zoom in range(minzoom, maxzoom + 1, 1):
-                    matrix = tms.matrix(zoom)
-                    ulTile = tms.tile(bounds[0], bounds[3], int(matrix.id))
-                    lrTile = tms.tile(bounds[2], bounds[1], int(matrix.id))
-                    minx, maxx = (min(ulTile.x, lrTile.x), max(ulTile.x, lrTile.x))
-                    miny, maxy = (min(ulTile.y, lrTile.y), max(ulTile.y, lrTile.y))
-                    tilematrix_limit.append(
-                        {
-                            "tileMatrix": matrix.id,
-                            "minTileRow": max(miny, 0),
-                            "maxTileRow": min(maxy, matrix.matrixHeight),
-                            "minTileCol": max(minx, 0),
-                            "maxTileCol": min(maxx, matrix.matrixWidth),
-                        }
-                    )
+                    tilematrix_limit = []
+                    for zoom in range(minzoom, maxzoom + 1, 1):
+                        matrix = tms.matrix(zoom)
+                        ulTile = tms.tile(bounds[0], bounds[3], int(matrix.id))
+                        lrTile = tms.tile(bounds[2], bounds[1], int(matrix.id))
+                        minx, maxx = (min(ulTile.x, lrTile.x), max(ulTile.x, lrTile.x))
+                        miny, maxy = (min(ulTile.y, lrTile.y), max(ulTile.y, lrTile.y))
+                        tilematrix_limit.append(
+                            {
+                                "tileMatrix": matrix.id,
+                                "minTileRow": max(miny, 0),
+                                "maxTileRow": min(maxy, matrix.matrixHeight),
+                                "minTileCol": max(minx, 0),
+                                "maxTileCol": min(maxx, matrix.matrixWidth),
+                            }
+                        )
 
             query_string = (
                 f"?{urlencode(request.query_params._list)}"

src/titiler/core/titiler/core/middleware.py

@@ -110,18 +110,26 @@ async def __call__(self, scope: Scope, receive: Receive, send: Send):
             return await self.app(scope, receive, send)
 
         request = Request(scope, receive=receive)
-
         data = {
             "http.method": request.method,
+            "http.url": str(request.url),
+            "http.scheme": request.url.scheme,
+            "http.host": request.headers.get("host", request.url.hostname or "unknown"),
+            "http.target": request.url.path
+            + (f"?{request.url.query}" if request.url.query else ""),
+            "http.user_agent": request.headers.get("user-agent"),
             "http.referer": next(
                 (request.headers.get(attr) for attr in ["referer", "referrer"]),
                 None,
             ),
-            "http.origin": request.headers.get("origin"),
-            "http.path": request.url.path,
-            "http.headers": dict(request.headers),
-            "path_params": request.path_params,
-            "query_params": dict(request.query_params),
+            "http.request_content_length": request.headers.get("content-length"),
+            "http.request.header.accept-encoding": request.headers.get(
+                "accept-encoding"
+            ),
+            "http.request.header.origin": request.headers.get("origin"),
+            "net.host.name": request.url.hostname,
+            "net.host.port": request.url.port,
+            "titiler.query_params": dict(request.query_params),
         }
 
         telemetry.add_span_attributes(telemetry.flatten_dict(data))
@@ -133,7 +141,9 @@ async def __call__(self, scope: Scope, receive: Receive, send: Send):
             exception = e
 
         if route := scope.get("route"):
-            data["route"] = route.path
+            data["http.route"] = route.path
+
+        data["titiler.path_params"] = request.path_params
 
         self.logger.info(
             f"Request received: {request.url.path} {request.method}",