feat: support structured logs

README.md

@@ -47,11 +47,12 @@ Applications and model adapters implemented using this framework will be compati
 
 |Variable|Default|Description|
 |---|---|---|
-|DIAL_SDK_LOG|WARNING|DIAL SDK log level|
 |DIAL_SDK_HEADERS_TO_PROXY|``|A comma-separated list of headers that should be proxied from incoming requests to outgoing requests to the DIAL API. By default, no headers are proxied.|
 |DIAL_SDK_SSE_HEARTBEAT_INTERVAL||When set, the SDK inserts ping comments into streaming chat completion responses after the response has been idle for the specified number of seconds, helping prevent read timeouts when the DIAL application isn't responsive.|
 |PYDANTIC_V2|False|When `True` and Pydantic V2 is installed, DIAL SDK classes for requests/responses will be based on Pydantic V2 `BaseModel`. Otherwise, they will be based on Pydantic V1 `BaseModel`.|
 
+Logging-related environment variables (log level, console format, and trace/span correlation) are documented in [docs/logging.md](docs/logging.md).
+
 ---
 
 ## Usage

aidial_sdk/__init__.py

@@ -1,5 +1,12 @@
 from aidial_sdk.application import DIALApp
 from aidial_sdk.exceptions import HTTPException
+from aidial_sdk.utils.log_config import LogConfig, configure_root_logger
 from aidial_sdk.utils.logging import logger
 
-__all__ = ["DIALApp", "HTTPException", "logger"]
+__all__ = [
+    "DIALApp",
+    "HTTPException",
+    "LogConfig",
+    "configure_root_logger",
+    "logger",
+]

aidial_sdk/application.py

@@ -1,8 +1,7 @@
-import logging.config
+import logging
 import re
 import warnings
 from collections.abc import Callable, Coroutine
-from logging import Filter, LogRecord
 from typing import Any, Literal, TypeVar
 
 from fastapi import FastAPI, HTTPException, Request
@@ -33,7 +32,7 @@
 from aidial_sdk.utils._disconnect_middleware import DisconnectMiddleware
 from aidial_sdk.utils._reflection import get_method_implementation
 from aidial_sdk.utils.env import env_float, env_var_list
-from aidial_sdk.utils.log_config import LogConfig
+from aidial_sdk.utils.log_config import configure_sdk_logger
 from aidial_sdk.utils.logging import log_debug, set_log_deployment
 from aidial_sdk.utils.pydantic import model_validate_extra_fields
 from aidial_sdk.utils.streaming import (
@@ -42,7 +41,7 @@
     to_streaming_response,
 )
 
-logging.config.dictConfig(LogConfig().model_dump())
+configure_sdk_logger()
 
 RequestType = TypeVar("RequestType", bound=FromRequestMixin)
 
@@ -57,14 +56,14 @@ def _interpolate_deployment_id(deployment_id: str, path_params: dict) -> str:
     return result
 
 
-class PathFilter(Filter):
+class PathFilter(logging.Filter):
     path: str
 
     def __init__(self, path: str) -> None:
         super().__init__(name="")
         self.path = path
 
-    def filter(self, record: LogRecord):
+    def filter(self, record: logging.LogRecord):
         return not re.search(f"(\\s+){self.path}(\\s+)", record.getMessage())
 
 

aidial_sdk/telemetry/init.py

@@ -30,12 +30,10 @@
 from prometheus_client import start_http_server
 
 from aidial_sdk.telemetry.types import TelemetryConfig
+from aidial_sdk.utils._deprecations import warn_otel_log_correlation
 
 
-def init_telemetry(
-    app: FastAPI | None,
-    config: TelemetryConfig,
-):
+def init_telemetry(app: FastAPI | None, config: TelemetryConfig):
     resource = Resource.create(
         attributes=(
             {SERVICE_NAME: config.service_name} if config.service_name else None
@@ -81,10 +79,12 @@ def init_telemetry(
         except ImportError:
             pass
 
+        # Inject otel* tracing fields onto every log record. When
+        # OTEL_PYTHON_LOG_CORRELATION=true, instrument() also installs OTel's
+        # own root-logger format (the deprecated path).
         if config.tracing.logging:
-            # Setting the root logger format in order to include
-            # tracing information: span_id, trace_id
-            LoggingInstrumentor().instrument(set_logging_format=True)
+            warn_otel_log_correlation()
+        LoggingInstrumentor().instrument()
 
     if config.logs is not None:
         # Adding a handler to the root logger which exports the logs to OTLP

aidial_sdk/telemetry/types.py

@@ -26,8 +26,7 @@ class LogsConfig(BaseModel):
 class TracingConfig(BaseModel):
     otlp_export: bool = "otlp" in OTEL_TRACES_EXPORTER
 
-    """Configure logging to include tracing context
-    into console log messages"""
+    """Deprecated: let OTel add tracing context to console logs. See docs/logging.md."""
     logging: bool = OTEL_PYTHON_LOG_CORRELATION
 
 

aidial_sdk/utils/_deprecations.py

@@ -0,0 +1,14 @@
+from aidial_sdk.utils.logging import logger
+
+_LOGGING_DOC = (
+    "https://github.com/epam/ai-dial-sdk/blob/development/docs/logging.md"
+)
+
+
+def warn_otel_log_correlation() -> None:
+    logger.warning(
+        "OTEL_PYTHON_LOG_CORRELATION=true is not the recommended way to add "
+        "trace context to console logs: it double-logs SDK records and cannot "
+        "produce JSON. Use DIAL_SDK_TEXT_LOG_FORMAT (with otel* placeholders) "
+        f"instead — see {_LOGGING_DOC}."
+    )

aidial_sdk/utils/_json_log_formatter.py

@@ -0,0 +1,56 @@
+import json
+import logging
+from collections import defaultdict
+
+
+class JsonLogFormatter(logging.Formatter):
+    """Render a record through a JSON template whose string leaves are
+    `%`-format strings, then `json.dumps` the result (escaping every value).
+
+    Any ``otel*`` field on the record (injected by the OTel logging instrumentor
+    when tracing is on) is auto-added to the output, unless the template already
+    references it under some key (e.g. ``{"trace_id": "%(otelTraceID)s"}``)."""
+
+    def __init__(self, template: dict, datefmt: str | None = None) -> None:
+        super().__init__(datefmt=datefmt)
+        self._template = template
+        template_str = json.dumps(template)
+        self._uses_time = "%(asctime)" in template_str
+        self._template_str = template_str
+
+    def _interpolate(self, node: object, fields: dict) -> object:
+        match node:
+            case str():
+                return node % fields
+            case dict():
+                return {
+                    k: self._interpolate(v, fields) for k, v in node.items()
+                }
+            case list():
+                return [self._interpolate(v, fields) for v in node]
+            case _:
+                return node
+
+    def format(self, record: logging.LogRecord) -> str:
+        record.message = record.getMessage()
+        if self._uses_time:
+            record.asctime = self.formatTime(record, self.datefmt)
+
+        # Expose the traceback via %(exc_text)s, escaped like any other value.
+        if record.exc_info and not record.exc_text:
+            record.exc_text = self.formatException(record.exc_info)
+
+        # defaultdict(str): a missing field renders as "" instead of raising.
+        rendered = self._interpolate(
+            self._template, defaultdict(str, record.__dict__)
+        )
+
+        if isinstance(rendered, dict):
+            for key, value in record.__dict__.items():
+                if (
+                    key.startswith("otel")
+                    and f"%({key})" not in self._template_str
+                ):
+                    rendered.setdefault(key, value)
+
+        return json.dumps(rendered, ensure_ascii=False, default=str)

aidial_sdk/utils/env.py

@@ -1,3 +1,4 @@
+import json
 import os
 
 
@@ -16,3 +17,17 @@ def env_var_list(name: str) -> list[str]:
     if value is None:
         return []
     return value.split(",")
+
+
+def env_json_dict(name: str, default: dict) -> dict:
+    if (value := os.getenv(name)) is not None:
+        try:
+            obj = json.loads(value)
+            if not isinstance(obj, dict):
+                raise ValueError("the object isn't a dictionary")
+            return obj
+        except Exception:
+            raise ValueError(
+                f"The value of the {name!r} environment variable is expected to be a valid JSON dictionary."
+            )
+    return default

aidial_sdk/utils/log_config.py

@@ -1,34 +1,104 @@
+import logging
 import os
+import sys
+from typing import Literal
 
-from aidial_sdk._pydantic._compat import BaseModel
-
-DIAL_SDK_LOG = os.environ.get("DIAL_SDK_LOG", "WARNING").upper()
-
-
-class LogConfig(BaseModel):
-    """Logging configuration to be set for the server"""
-
-    version: int = 1
-    disable_existing_loggers: bool = False
-    formatters: dict = {
-        "default": {
-            "()": "uvicorn.logging.DefaultFormatter",
-            "fmt": "%(levelprefix)s | %(asctime)s | %(name)s | %(process)d | %(message)s",
-            "datefmt": "%Y-%m-%d %H:%M:%S",
-            "use_colors": True,
-        },
-    }
-    handlers: dict = {
-        "default": {
-            "formatter": "default",
-            "class": "logging.StreamHandler",
-            "stream": "ext://sys.stderr",
-        },
-    }
-    loggers: dict = {
-        "aidial_sdk": {"handlers": ["default"], "level": DIAL_SDK_LOG},
-        "uvicorn": {
-            "handlers": ["default"],
-            "propagate": False,
-        },
-    }
+from uvicorn.logging import DefaultFormatter
+
+from aidial_sdk.telemetry.types import OTEL_PYTHON_LOG_CORRELATION
+from aidial_sdk.utils._json_log_formatter import JsonLogFormatter
+from aidial_sdk.utils.env import env_json_dict
+
+_DATEFMT = "%Y-%m-%d %H:%M:%S"
+
+_DEFAULT_TEXT_FORMAT = (
+    "%(levelprefix)s | %(asctime)s | %(name)s | %(process)d | %(message)s"
+)
+_DEFAULT_JSON_FORMAT = {
+    "level": "%(levelname)s",
+    "time": "%(asctime)s",
+    "logger": "%(name)s",
+    "process": "%(process)d",
+    "message": "%(message)s",
+}
+
+
+class LogConfig:
+    level: str
+    formatter: logging.Formatter
+
+    def __init__(
+        self,
+        *,
+        level: str | None = None,
+        log_format: Literal["text", "json"] | None = None,
+        text_format: str | None = None,
+        json_format: dict | None = None,
+    ) -> None:
+        self.level = (
+            level or os.environ.get("DIAL_SDK_LOG", "WARNING")
+        ).upper()
+        resolved_format = (
+            log_format or os.environ.get("DIAL_SDK_LOG_FORMAT", "text")
+        ).lower()
+
+        if resolved_format == "json":
+            json_format = json_format or env_json_dict(
+                "DIAL_SDK_JSON_LOG_FORMAT", _DEFAULT_JSON_FORMAT
+            )
+            self.formatter = JsonLogFormatter(
+                template=json_format, datefmt=_DATEFMT
+            )
+        else:
+            text_format = text_format or os.getenv(
+                "DIAL_SDK_TEXT_LOG_FORMAT", _DEFAULT_TEXT_FORMAT
+            )
+            self.formatter = DefaultFormatter(
+                fmt=text_format, datefmt=_DATEFMT, use_colors=True
+            )
+
+
+def configure_root_logger(config: LogConfig | None = None) -> None:
+    """Route all logging through a single console handler on the root logger,
+    using the SDK's format, so the application's own loggers get it too. Pass a
+    ``LogConfig`` to override the ``DIAL_SDK_LOG*`` env vars.
+    """
+
+    config = config or LogConfig()
+    root = logging.getLogger()
+
+    # OTEL_PYTHON_LOG_CORRELATION installs OTEL's own root console format; defer
+    # to it. Otherwise take over — drop competing stderr handlers (e.g. the
+    # basicConfig one from ANTHROPIC_LOG) and install ours.
+    if not OTEL_PYTHON_LOG_CORRELATION:
+        for h in root.handlers[:]:
+            if isinstance(h, logging.StreamHandler) and h.stream is sys.stderr:
+                root.removeHandler(h)
+        handler = logging.StreamHandler(sys.stderr)
+        handler.setFormatter(config.formatter)
+        root.addHandler(handler)
+
+    for name in ("aidial_sdk", "uvicorn", "uvicorn.access", "uvicorn.error"):
+        child = logging.getLogger(name)
+        child.handlers = []
+        child.propagate = True
+
+    logging.getLogger("aidial_sdk").setLevel(config.level)
+
+
+def configure_sdk_logger() -> None:
+    """Configure only the SDK's own loggers (``aidial_sdk``, ``uvicorn``), called
+    once when ``DIALApp`` is imported. To format your own loggers the same way,
+    call ``configure_root_logger()``."""
+
+    config = LogConfig()
+    handler = logging.StreamHandler(sys.stderr)
+    handler.setFormatter(config.formatter)
+
+    aidial_sdk = logging.getLogger("aidial_sdk")
+    aidial_sdk.handlers = [handler]
+    aidial_sdk.setLevel(config.level)
+
+    uvicorn = logging.getLogger("uvicorn")
+    uvicorn.handlers = [handler]
+    uvicorn.propagate = False