diff --git a/src/titiler/application/titiler/application/main.py b/src/titiler/application/titiler/application/main.py index 78a64978e..ed39f7d42 100644 --- a/src/titiler/application/titiler/application/main.py +++ b/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) diff --git a/src/titiler/core/pyproject.toml b/src/titiler/core/pyproject.toml index bd775ef9c..2e4bfc525 100644 --- a/src/titiler/core/pyproject.toml +++ b/src/titiler/core/pyproject.toml @@ -40,6 +40,7 @@ dependencies = [ "rio-tiler>=7.7,<8.0", "morecantile", "simplejson", + "structlog", "typing_extensions>=4.6.1", ] diff --git a/src/titiler/core/titiler/core/factory.py b/src/titiler/core/titiler/core/factory.py index cac758fa1..6ff54b3bb 100644 --- a/src/titiler/core/titiler/core/factory.py +++ b/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: diff --git a/src/titiler/core/titiler/core/middleware.py b/src/titiler/core/titiler/core/middleware.py index 49ae11344..d92a9cb7e 100644 --- a/src/titiler/core/titiler/core/middleware.py +++ b/src/titiler/core/titiler/core/middleware.py @@ -2,13 +2,13 @@ from __future__ import annotations -import logging import re import time from dataclasses import dataclass, field from typing import Set from urllib.parse import urlencode +import structlog from starlette.datastructures import MutableHeaders from starlette.requests import Request from starlette.types import ASGIApp, Message, Receive, Scope, Send @@ -95,63 +95,136 @@ async def send_wrapper(message: Message): await self.app(scope, receive, send_wrapper) -@dataclass(frozen=True) +@dataclass class LoggerMiddleware: - """MiddleWare to add logging.""" + """MiddleWare to add structured logging.""" app: ASGIApp - logger: logging.Logger = field( - default_factory=lambda: logging.getLogger("titiler.requests") + logger: structlog.stdlib.BoundLogger = field( + default_factory=lambda: structlog.get_logger("titiler.requests") ) + def _extract_request_data(self, request: Request) -> dict: + """Extract and organize request data into nested structure.""" + return { + "http": { + "method": request.method, + "url": str(request.url), + "scheme": request.url.scheme, + "host": request.headers.get("host", request.url.hostname or "unknown"), + "target": request.url.path + + (f"?{request.url.query}" if request.url.query else ""), + "user_agent": request.headers.get("user-agent"), + "referer": next( + (request.headers.get(attr) for attr in ["referer", "referrer"]), + None, + ), + "request": { + "headers": { + "content_length": request.headers.get("content-length"), + "accept_encoding": request.headers.get("accept-encoding"), + "origin": request.headers.get("origin"), + } + }, + }, + "net": { + "host": { + "name": request.url.hostname, + "port": request.url.port, + } + }, + "titiler": { + "query_params": dict(request.query_params), + }, + } + async def __call__(self, scope: Scope, receive: Receive, send: Send): """Handle call.""" if scope["type"] != "http": 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.request.header.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), + start_time = time.time() + + request_data = self._extract_request_data(request) + + telemetry_data = self._flatten_for_telemetry(request_data) + clean_telemetry_data = { + k: v + for k, v in telemetry_data.items() + if v is not None and not isinstance(v, dict) } - telemetry.add_span_attributes(telemetry.flatten_dict(data)) + for k, v in list(clean_telemetry_data.items()): + if not isinstance(v, (str, int, float, bool)): + clean_telemetry_data[k] = str(v) + + telemetry.add_span_attributes(clean_telemetry_data) exception: Exception | None = None + response_started = False + + async def send_wrapper(message: Message): + nonlocal response_started + if message["type"] == "http.response.start": + response_started = True + request_logger = self.logger.bind(**request_data) + request_logger.info("Request started") + + await send(message) + try: - await self.app(scope, receive, send) + await self.app(scope, receive, send_wrapper) except Exception as e: exception = e + finally: + duration = time.time() - start_time + + completion_data = { + "request": { + "duration_seconds": duration, + }, + "titiler": { + "path_params": request.path_params, + }, + } + + if route := scope.get("route"): + completion_data["http"] = {"route": route.path} + + final_logger = self.logger.bind(**{**request_data, **completion_data}) + + if exception: + final_logger.error( + "Request completed with exception", + error={ + "type": type(exception).__name__, + "message": str(exception), + "occurred": True, + }, + exc_info=True, + ) + else: + final_logger.info("Request completed successfully") - if route := scope.get("route"): - data["http.route"] = route.path - - data["titiler.path_params"] = request.path_params - - self.logger.info( - f"Request received: {request.url.path} {request.method}", - extra=data, - ) if exception: raise exception + def _flatten_for_telemetry(self, nested_data: dict) -> dict: + """Flatten nested data for telemetry compatibility.""" + flattened = {} + + def _flatten(obj, prefix=""): + for key, value in obj.items(): + new_key = f"{prefix}.{key}" if prefix else key + if isinstance(value, dict) and value: # Only flatten non-empty dicts + _flatten(value, new_key) + else: + flattened[new_key] = value + + _flatten(nested_data) + return flattened + @dataclass(frozen=True) class LowerCaseQueryStringMiddleware: diff --git a/src/titiler/core/titiler/core/telemetry.py b/src/titiler/core/titiler/core/telemetry.py index a3463bfa6..cba5d5d4d 100644 --- a/src/titiler/core/titiler/core/telemetry.py +++ b/src/titiler/core/titiler/core/telemetry.py @@ -34,20 +34,6 @@ def add_span_attributes(attributes: Dict[str, Any]) -> None: span.set_attributes(attributes) -def flatten_dict(d: dict, parent_key: str = "", sep: str = ".") -> dict: - """Flattens a nested dictionary for adding span attributes.""" - items = {} - for k, v in d.items(): - new_key = parent_key + sep + k if parent_key else k - if isinstance(v, dict): - items.update(flatten_dict(v, new_key, sep=sep)) - else: - if not isinstance(v, (str, bool, int, float)): - v = str(v) - items[new_key] = v - return items - - class SpanWrapper: """A wrapper class to safely handle an optional OpenTelemetry Span.""" diff --git a/src/titiler/mosaic/titiler/mosaic/factory.py b/src/titiler/mosaic/titiler/mosaic/factory.py index cf6237b7c..3421b4c56 100644 --- a/src/titiler/mosaic/titiler/mosaic/factory.py +++ b/src/titiler/mosaic/titiler/mosaic/factory.py @@ -1,11 +1,11 @@ """TiTiler.mosaic Router factories.""" -import logging import os from typing import Any, Callable, Dict, List, Literal, Optional, Set, Tuple, Type, Union from urllib.parse import urlencode import rasterio +import structlog from attrs import define, field from cogeo_mosaic.backends import BaseBackend, MosaicBackend from cogeo_mosaic.models import Info as mosaicInfo @@ -56,7 +56,7 @@ "yes", ] -logger = logging.getLogger(__name__) +logger = structlog.get_logger(__name__) def PixelSelectionParams( @@ -182,7 +182,7 @@ def read( """Read a MosaicJSON""" with rasterio.Env(**env): logger.info( - f"opening data with backend: {self.backend} and reader {self.dataset_reader}" + "opening dataset", backend=self.backend, reader=self.dataset_reader ) with self.backend( src_path, @@ -214,7 +214,7 @@ def bounds( """Return the bounds of the MosaicJSON.""" with rasterio.Env(**env): logger.info( - f"opening data with backend: {self.backend} and reader {self.dataset_reader}" + "opening dataset", backend=self.backend, reader=self.dataset_reader ) with self.backend( src_path, @@ -249,7 +249,7 @@ def info( """Return basic info.""" with rasterio.Env(**env): logger.info( - f"opening data with backend: {self.backend} and reader {self.dataset_reader}" + "opening dataset", backend=self.backend, reader=self.dataset_reader ) with self.backend( src_path, @@ -282,7 +282,7 @@ def info_geojson( """Return mosaic's basic info as a GeoJSON feature.""" with rasterio.Env(**env): logger.info( - f"opening data with backend: {self.backend} and reader {self.dataset_reader}" + "opening dataset", backend=self.backend, reader=self.dataset_reader ) with self.backend( src_path, @@ -332,7 +332,7 @@ async def tileset_list( """Retrieve a list of available raster tilesets for the specified dataset.""" with rasterio.Env(**env): logger.info( - f"opening data with backend: {self.backend} and reader {self.dataset_reader}" + "opening dataset", backend=self.backend, reader=self.dataset_reader ) with self.backend( src_path, @@ -433,7 +433,7 @@ async def tileset( tms = self.supported_tms.get(tileMatrixSetId) with rasterio.Env(**env): logger.info( - f"opening data with backend: {self.backend} and reader {self.dataset_reader}" + "opening dataset", backend=self.backend, reader=self.dataset_reader ) with self.backend( src_path, @@ -631,7 +631,7 @@ def tile( tms = self.supported_tms.get(tileMatrixSetId) with rasterio.Env(**env): logger.info( - f"opening data with backend: {self.backend} and reader {self.dataset_reader}" + "opening dataset", backend=self.backend, reader=self.dataset_reader ) with self.backend( src_path, @@ -763,7 +763,7 @@ def tilejson( tms = self.supported_tms.get(tileMatrixSetId) with rasterio.Env(**env): logger.info( - f"opening data with backend: {self.backend} and reader {self.dataset_reader}" + "opening dataset", backend=self.backend, reader=self.dataset_reader ) with self.backend( src_path, @@ -937,7 +937,7 @@ def wmts( tms = self.supported_tms.get(tileMatrixSetId) with rasterio.Env(**env): logger.info( - f"opening data with backend: {self.backend} and reader {self.dataset_reader}" + "opening dataset", backend=self.backend, reader=self.dataset_reader ) with self.backend( src_path, @@ -1036,7 +1036,7 @@ def point( """Get Point value for a Mosaic.""" with rasterio.Env(**env): logger.info( - f"opening data with backend: {self.backend} and reader {self.dataset_reader}" + "opening dataset", backend=self.backend, reader=self.dataset_reader ) with self.backend( src_path, @@ -1095,7 +1095,7 @@ def assets_for_bbox( """Return a list of assets which overlap a bounding box""" with rasterio.Env(**env): logger.info( - f"opening data with backend: {self.backend} and reader {self.dataset_reader}" + "opening dataset", backend=self.backend, reader=self.dataset_reader ) with self.backend( src_path, @@ -1130,7 +1130,7 @@ def assets_for_lon_lat( """Return a list of assets which overlap a point""" with rasterio.Env(**env): logger.info( - f"opening data with backend: {self.backend} and reader {self.dataset_reader}" + "opening dataset", backend=self.backend, reader=self.dataset_reader ) with self.backend( src_path, @@ -1185,7 +1185,7 @@ def assets_for_tile( tms = self.supported_tms.get(tileMatrixSetId) with rasterio.Env(**env): logger.info( - f"opening data with backend: {self.backend} and reader {self.dataset_reader}" + "opening dataset", backend=self.backend, reader=self.dataset_reader ) with self.backend( src_path, diff --git a/src/titiler/xarray/titiler/xarray/factory.py b/src/titiler/xarray/titiler/xarray/factory.py index e9adca8c1..5382569c0 100644 --- a/src/titiler/xarray/titiler/xarray/factory.py +++ b/src/titiler/xarray/titiler/xarray/factory.py @@ -1,10 +1,10 @@ """TiTiler.xarray factory.""" -import logging import warnings from typing import Any, Callable, Optional, Type, Union import rasterio +import structlog from attrs import define from fastapi import Body, Depends, Query from geojson_pydantic.features import Feature, FeatureCollection @@ -35,7 +35,7 @@ ) from titiler.xarray.io import Reader -logger = logging.getLogger(__name__) +logger = structlog.get_logger(__name__) @define(kw_only=True) @@ -107,7 +107,7 @@ def info_endpoint( ) -> 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: info = src_dst.info().model_dump() if show_times and "time" in src_dst.input.dims: @@ -142,7 +142,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) @@ -200,7 +200,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: for feature in fc.features: shape = feature.model_dump(exclude_none=True)