[WIP] feat: use structlog for structured logging

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

@@ -1,11 +1,10 @@
 """titiler app."""
 
-import json
 import logging
-from logging import config as log_config
 from typing import Annotated, Literal, Optional
 
 import rasterio
+import structlog
 from fastapi import Depends, FastAPI, HTTPException, Query, Security
 from fastapi.security.api_key import APIKeyQuery
 from rio_tiler.io import Reader, STACReader
@@ -43,13 +42,65 @@
 from titiler.mosaic.errors import MOSAIC_STATUS_CODES
 from titiler.mosaic.factory import MosaicTilerFactory
 
-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)
+api_settings = ApiSettings()
 
 
-api_settings = ApiSettings()
+def configure_structlog(telemetry_enabled: bool = api_settings.telemetry_enabled):
+    """Configure structlog for the application."""
+
+    logging.basicConfig(
+        format="%(message)s",
+        level=logging.INFO,
+    )
+    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)
+
+    processors = [
+        structlog.contextvars.merge_contextvars,
+        structlog.stdlib.add_log_level,
+        structlog.stdlib.add_logger_name,
+        structlog.processors.TimeStamper(fmt="iso"),
+        structlog.processors.CallsiteParameterAdder(
+            parameters=[
+                structlog.processors.CallsiteParameter.FILENAME,
+                structlog.processors.CallsiteParameter.LINENO,
+            ]
+        ),
+        structlog.processors.StackInfoRenderer(),
+        structlog.processors.format_exc_info,
+        structlog.processors.JSONRenderer(),
+    ]
+    if telemetry_enabled:
+        from opentelemetry import trace
+
+        def add_open_telemetry_context(logger, method_name, event_dict):
+            """
+            A structlog processor to inject OpenTelemetry trace and span IDs.
+            """
+            span = trace.get_current_span()
+            if span and span.is_recording():
+                span_context = span.get_span_context()
+                if span_context.is_valid:
+                    event_dict["trace_id"] = format(span_context.trace_id, "032x")
+                    event_dict["span_id"] = format(span_context.span_id, "016x")
+                    parent = getattr(span, "parent", None)
+                    if parent:
+                        event_dict["parent_span_id"] = format(parent.span_id, "016x")
+            return event_dict
+
+        processors.insert(3, add_open_telemetry_context)
+
+    structlog.configure(
+        processors=processors,
+        wrapper_class=structlog.stdlib.BoundLogger,
+        logger_factory=structlog.stdlib.LoggerFactory(),
+        cache_logger_on_first_use=True,
+    )
+
+
+configure_structlog()
 
 app_dependencies = []
 if api_settings.global_access_token:
@@ -231,67 +282,6 @@ def validate_access_token(access_token: str = Security(api_key_query)):
     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 [
-                                    "http.method",
-                                    "http.referer",
-                                    "http.request.header.origin",
-                                    "http.route",
-                                    "http.target",
-                                    "http.request.header.content-length",
-                                    "http.request.header.accept-encoding",
-                                    "http.request.header.origin",
-                                    "titiler.path_params",
-                                    "titiler.query_params",
-                                ]
-                            }
-                        )
-                    ),
-                },
-            },
-            "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": {
-                "titiler": {
-                    "level": "INFO",
-                    "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/pyproject.toml

@@ -40,6 +40,7 @@ dependencies = [
     "rio-tiler>=7.7,<8.0",
     "morecantile",
     "simplejson",
+    "structlog",
     "typing_extensions>=4.6.1",
 ]
 

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

@@ -1,7 +1,6 @@
 """TiTiler Router factories."""
 
 import abc
-import logging
 import warnings
 from typing import (
     Any,
@@ -21,6 +20,7 @@
 import jinja2
 import numpy
 import rasterio
+import structlog
 from attrs import define, field
 from fastapi import APIRouter, Body, Depends, Path, Query
 from fastapi.dependencies.utils import get_parameterless_sub_dependant
@@ -114,7 +114,7 @@
     "response_class": Response,
 }
 
-logger = logging.getLogger(__name__)
+logger = structlog.get_logger(__name__)
 
 
 @define
@@ -888,7 +888,7 @@ def tile(
             """Create map tile from a dataset."""
             tms = self.supported_tms.get(tileMatrixSetId)
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(
                     src_path, tms=tms, **reader_params.as_dict()
                 ) as src_dst:
@@ -998,7 +998,7 @@ def tilejson(
 
             tms = self.supported_tms.get(tileMatrixSetId)
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(
                     src_path, tms=tms, **reader_params.as_dict()
                 ) as src_dst:
@@ -1159,7 +1159,7 @@ def wmts(
 
             tms = self.supported_tms.get(tileMatrixSetId)
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(
                     src_path, tms=tms, **reader_params.as_dict()
                 ) as src_dst:
@@ -1247,7 +1247,7 @@ def point(
         ):
             """Get Point value for a dataset."""
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(src_path, **reader_params.as_dict()) as src_dst:
                     pts = src_dst.point(
                         lon,
@@ -1304,7 +1304,7 @@ def preview(
         ):
             """Create preview of a dataset."""
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(src_path, **reader_params.as_dict()) as src_dst:
                     image = src_dst.preview(
                         **layer_params.as_dict(),
@@ -1374,7 +1374,7 @@ def bbox_image(
         ):
             """Create image from a bbox."""
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(src_path, **reader_params.as_dict()) as src_dst:
                     image = src_dst.part(
                         [minx, miny, maxx, maxy],
@@ -1442,7 +1442,7 @@ def feature_image(
         ):
             """Create image from a geojson feature."""
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(src_path, **reader_params.as_dict()) as src_dst:
                     image = src_dst.feature(
                         geojson.model_dump(exclude_none=True),
@@ -1606,7 +1606,7 @@ def info(
         ):
             """Return dataset's basic info or the list of available assets."""
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(src_path, **reader_params.as_dict()) as src_dst:
                     return src_dst.info(**asset_params.as_dict())
 
@@ -1632,7 +1632,7 @@ def info_geojson(
         ):
             """Return dataset's basic info as a GeoJSON feature."""
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(src_path, **reader_params.as_dict()) as src_dst:
                     bounds = src_dst.get_geographic_bounds(crs or WGS84_CRS)
                     geometry = bounds_to_geometry(bounds)
@@ -1657,7 +1657,7 @@ def available_assets(
         ):
             """Return a list of supported assets."""
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(src_path, **reader_params.as_dict()) as src_dst:
                     return src_dst.assets
 
@@ -1691,7 +1691,7 @@ def asset_statistics(
         ):
             """Per Asset statistics"""
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(src_path, **reader_params.as_dict()) as src_dst:
                     return src_dst.statistics(
                         **asset_params.as_dict(),
@@ -1729,7 +1729,7 @@ def statistics(
         ):
             """Merged assets statistics."""
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(src_path, **reader_params.as_dict()) as src_dst:
                     # Default to all available assets
                     if not layer_params.assets and not layer_params.expression:
@@ -1786,7 +1786,7 @@ def geojson_statistics(
                 fc = FeatureCollection(type="FeatureCollection", features=[geojson])
 
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(src_path, **reader_params.as_dict()) as src_dst:
                     # Default to all available assets
                     if not layer_params.assets and not layer_params.expression:
@@ -1863,7 +1863,7 @@ def info(
         ):
             """Return dataset's basic info."""
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(src_path, **reader_params.as_dict()) as src_dst:
                     return src_dst.info(**bands_params.as_dict())
 
@@ -1889,7 +1889,7 @@ def info_geojson(
         ):
             """Return dataset's basic info as a GeoJSON feature."""
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(src_path, **reader_params.as_dict()) as src_dst:
                     bounds = src_dst.get_geographic_bounds(crs or WGS84_CRS)
                     geometry = bounds_to_geometry(bounds)
@@ -1914,7 +1914,7 @@ def available_bands(
         ):
             """Return a list of supported bands."""
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(src_path, **reader_params.as_dict()) as src_dst:
                     return src_dst.bands
 
@@ -1948,7 +1948,7 @@ def statistics(
         ):
             """Get Dataset statistics."""
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(src_path, **reader_params.as_dict()) as src_dst:
                     # Default to all available bands
                     if not bands_params.bands and not bands_params.expression:
@@ -2005,7 +2005,7 @@ def geojson_statistics(
                 fc = FeatureCollection(type="FeatureCollection", features=[geojson])
 
             with rasterio.Env(**env):
-                logger.info(f"opening data with reader: {self.reader}")
+                logger.info("opening dataset", reader=self.reader)
                 with self.reader(src_path, **reader_params.as_dict()) as src_dst:
                     # Default to all available bands
                     if not bands_params.bands and not bands_params.expression: