From ccad74f825ff10fbc39b8279402223c448a41ebf Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Wed, 15 Jul 2026 17:50:07 +0100 Subject: [PATCH 01/20] feat: support structured logging --- .vscode/settings.json | 2 + README.md | 3 ++ aidial_sdk/utils/json_log_formatter.py | 38 +++++++++++++++++++ aidial_sdk/utils/log_config.py | 39 +++++++++++++++---- tests/test_json_log_formatter.py | 52 ++++++++++++++++++++++++++ 5 files changed, 126 insertions(+), 8 deletions(-) create mode 100644 aidial_sdk/utils/json_log_formatter.py create mode 100644 tests/test_json_log_formatter.py diff --git a/.vscode/settings.json b/.vscode/settings.json index b8f22789..636a625d 100644 --- a/.vscode/settings.json +++ b/.vscode/settings.json @@ -22,4 +22,6 @@ "files.insertFinalNewline": true, "files.trimFinalNewlines": true, "files.trimTrailingWhitespace": true, + "python-envs.defaultEnvManager": "ms-python.python:poetry", + "python-envs.defaultPackageManager": "ms-python.python:poetry", } diff --git a/README.md b/README.md index 04cce58f..80b47a94 100644 --- a/README.md +++ b/README.md @@ -48,6 +48,9 @@ Applications and model adapters implemented using this framework will be compati |Variable|Default|Description| |---|---|---| |DIAL_SDK_LOG|WARNING|DIAL SDK log level| +|DIAL_SDK_LOG_FORMAT|text|Console log format: `text` (human-readable) or `json` (single-line JSON, easy to parse).| +|DIAL_SDK_TEXT_LOG_FORMAT|`%(levelprefix)s \| %(asctime)s \| %(name)s \| %(process)d \| %(message)s`|The `%`-style [format string](https://docs.python.org/3/library/logging.html#logrecord-attributes) used when `DIAL_SDK_LOG_FORMAT=text`.| +|DIAL_SDK_JSON_LOG_FORMAT|`{"level": "%(levelname)s", "time": "%(asctime)s", "logger": "%(name)s", "process": "%(process)d", "message": "%(message)s"}`|Used when `DIAL_SDK_LOG_FORMAT=json`. A JSON document whose string leaves are `%`-style format strings; values are escaped automatically.| |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`.| diff --git a/aidial_sdk/utils/json_log_formatter.py b/aidial_sdk/utils/json_log_formatter.py new file mode 100644 index 00000000..aeba5c04 --- /dev/null +++ b/aidial_sdk/utils/json_log_formatter.py @@ -0,0 +1,38 @@ +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; the whole structure is then `json.dumps`'d, so every + interpolated value is escaped for free.""" + + def __init__(self, template: str, datefmt: str | None = None) -> None: + super().__init__(datefmt=datefmt) + self._template = json.loads(template) # must be valid JSON; fail fast + self._uses_time = "%(asctime)" in template + + def _interpolate(self, node: object, fields: dict) -> object: + if isinstance(node, str): + return node % fields + if isinstance(node, dict): + return {k: self._interpolate(v, fields) for k, v in node.items()} + if isinstance(node, list): + return [self._interpolate(v, fields) for v in node] + return node # numbers, bools, null pass through unchanged + + 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; it becomes one escaped string + # after json.dumps — never appended raw outside the JSON. + if record.exc_info and not record.exc_text: + record.exc_text = self.formatException(record.exc_info) + # defaultdict(str): a missing field renders as "" (e.g. otelTraceID + # when telemetry is off) instead of raising during %-interpolation. + rendered = self._interpolate( + self._template, defaultdict(str, record.__dict__) + ) + return json.dumps(rendered, ensure_ascii=False, default=str) diff --git a/aidial_sdk/utils/log_config.py b/aidial_sdk/utils/log_config.py index 89a7b3e6..053f3f85 100644 --- a/aidial_sdk/utils/log_config.py +++ b/aidial_sdk/utils/log_config.py @@ -4,20 +4,43 @@ DIAL_SDK_LOG = os.environ.get("DIAL_SDK_LOG", "WARNING").upper() +# DIAL_SDK_LOG_FORMAT selects the console format ("text" or "json"). The two +# defaults carry the same fields. The per-format vars override the template. +# In the JSON template every string leaf is a %-format string (same grammar as +# the text one); see docs/logging. +DIAL_SDK_LOG_FORMAT = os.environ.get("DIAL_SDK_LOG_FORMAT", "text").lower() +DIAL_SDK_TEXT_LOG_FORMAT = os.environ.get( + "DIAL_SDK_TEXT_LOG_FORMAT", + "%(levelprefix)s | %(asctime)s | %(name)s | %(process)d | %(message)s", +) +DIAL_SDK_JSON_LOG_FORMAT = os.environ.get( + "DIAL_SDK_JSON_LOG_FORMAT", + '{"level": "%(levelname)s", "time": "%(asctime)s", "logger": "%(name)s",' + ' "process": "%(process)d", "message": "%(message)s"}', +) + + +def _default_formatter() -> dict: + if DIAL_SDK_LOG_FORMAT == "json": + return { + "()": "aidial_sdk.utils.json_log_formatter.JsonLogFormatter", + "template": DIAL_SDK_JSON_LOG_FORMAT, + "datefmt": "%Y-%m-%d %H:%M:%S", + } + return { + "()": "uvicorn.logging.DefaultFormatter", + "fmt": DIAL_SDK_TEXT_LOG_FORMAT, + "datefmt": "%Y-%m-%d %H:%M:%S", + "use_colors": True, + } + 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, - }, - } + formatters: dict = {"default": _default_formatter()} handlers: dict = { "default": { "formatter": "default", diff --git a/tests/test_json_log_formatter.py b/tests/test_json_log_formatter.py new file mode 100644 index 00000000..23421d50 --- /dev/null +++ b/tests/test_json_log_formatter.py @@ -0,0 +1,52 @@ +import json +import logging +import sys + +from aidial_sdk.utils.json_log_formatter import JsonLogFormatter + + +def _format(template: str, **record_fields) -> dict: + record = logging.makeLogRecord(record_fields) + return json.loads(JsonLogFormatter(template).format(record)) + + +def test_escapes_quotes_newlines_and_percent(): + msg = 'has "quotes", a\nnewline, a \\ backslash and 50% off' + out = _format('{"message": "%(message)s"}', msg=msg) + assert out["message"] == msg # round-trips => json.dumps escaped it + + +def test_message_args_are_interpolated(): + out = _format('{"message": "%(message)s"}', msg="hi %s", args=("bob",)) + assert out["message"] == "hi bob" + + +def test_missing_field_renders_empty(): + out = _format('{"trace": "%(otelTraceID)s"}') + assert out["trace"] == "" + + +def test_nested_template(): + out = _format('{"a": {"b": "%(levelname)s"}}', levelname="INFO") + assert out["a"]["b"] == "INFO" + + +def test_non_string_leaves_pass_through(): + out = _format('{"schema": 1, "on": true, "n": null}') + assert out == {"schema": 1, "on": True, "n": None} + + +def test_exception_via_exc_text(): + try: + raise ValueError("boom") + except ValueError: + exc_info = sys.exc_info() + out = _format('{"err": "%(exc_text)s"}', msg="x", exc_info=exc_info) + assert "ValueError: boom" in out["err"] + + +if __name__ == "__main__": + for name, fn in sorted(globals().items()): + if name.startswith("test_"): + fn() + print("ok") From a3d6273529bef3a84589b1af5568c1207961abaa Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Thu, 16 Jul 2026 12:31:15 +0100 Subject: [PATCH 02/20] feat: simplify logging --- aidial_sdk/telemetry/init.py | 6 ++--- aidial_sdk/utils/env.py | 14 ++++++++++++ aidial_sdk/utils/json_log_formatter.py | 8 ++++--- aidial_sdk/utils/log_config.py | 31 ++++++++++++++------------ tests/test_json_log_formatter.py | 21 ++++++----------- 5 files changed, 46 insertions(+), 34 deletions(-) diff --git a/aidial_sdk/telemetry/init.py b/aidial_sdk/telemetry/init.py index 600690c3..4d0c8804 100644 --- a/aidial_sdk/telemetry/init.py +++ b/aidial_sdk/telemetry/init.py @@ -82,9 +82,9 @@ def init_telemetry( pass 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) + # Inject tracing context fields onto every log record: + # otelTraceID, otelSpanID, otelTraceSampled + LoggingInstrumentor().instrument() if config.logs is not None: # Adding a handler to the root logger which exports the logs to OTLP diff --git a/aidial_sdk/utils/env.py b/aidial_sdk/utils/env.py index 61f90e44..1a966c6d 100644 --- a/aidial_sdk/utils/env.py +++ b/aidial_sdk/utils/env.py @@ -1,3 +1,4 @@ +import json import os @@ -16,3 +17,16 @@ 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") + except Exception as e: + raise ValueError( + f"The value of the {name!r} environment variable is expected to be a valid JSON dictionary: {e}." + ) + return default diff --git a/aidial_sdk/utils/json_log_formatter.py b/aidial_sdk/utils/json_log_formatter.py index aeba5c04..cef8f2fd 100644 --- a/aidial_sdk/utils/json_log_formatter.py +++ b/aidial_sdk/utils/json_log_formatter.py @@ -8,10 +8,10 @@ class JsonLogFormatter(logging.Formatter): `%`-format strings; the whole structure is then `json.dumps`'d, so every interpolated value is escaped for free.""" - def __init__(self, template: str, datefmt: str | None = None) -> None: + def __init__(self, template: dict, datefmt: str | None = None) -> None: super().__init__(datefmt=datefmt) - self._template = json.loads(template) # must be valid JSON; fail fast - self._uses_time = "%(asctime)" in template + self._template = template + self._uses_time = "%(asctime)" in json.dumps(template) def _interpolate(self, node: object, fields: dict) -> object: if isinstance(node, str): @@ -26,10 +26,12 @@ 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; it becomes one escaped string # after json.dumps — never appended raw outside the JSON. if record.exc_info and not record.exc_text: record.exc_text = self.formatException(record.exc_info) + # defaultdict(str): a missing field renders as "" (e.g. otelTraceID # when telemetry is off) instead of raising during %-interpolation. rendered = self._interpolate( diff --git a/aidial_sdk/utils/log_config.py b/aidial_sdk/utils/log_config.py index 053f3f85..6478584e 100644 --- a/aidial_sdk/utils/log_config.py +++ b/aidial_sdk/utils/log_config.py @@ -1,36 +1,39 @@ import os from aidial_sdk._pydantic._compat import BaseModel +from aidial_sdk.utils.env import env_json_dict DIAL_SDK_LOG = os.environ.get("DIAL_SDK_LOG", "WARNING").upper() -# DIAL_SDK_LOG_FORMAT selects the console format ("text" or "json"). The two -# defaults carry the same fields. The per-format vars override the template. -# In the JSON template every string leaf is a %-format string (same grammar as -# the text one); see docs/logging. -DIAL_SDK_LOG_FORMAT = os.environ.get("DIAL_SDK_LOG_FORMAT", "text").lower() -DIAL_SDK_TEXT_LOG_FORMAT = os.environ.get( +_DIAL_SDK_LOG_FORMAT = os.environ.get("DIAL_SDK_LOG_FORMAT", "text").lower() +_DIAL_SDK_TEXT_LOG_FORMAT = os.environ.get( "DIAL_SDK_TEXT_LOG_FORMAT", "%(levelprefix)s | %(asctime)s | %(name)s | %(process)d | %(message)s", ) -DIAL_SDK_JSON_LOG_FORMAT = os.environ.get( +_DIAL_SDK_JSON_LOG_FORMAT = env_json_dict( "DIAL_SDK_JSON_LOG_FORMAT", - '{"level": "%(levelname)s", "time": "%(asctime)s", "logger": "%(name)s",' - ' "process": "%(process)d", "message": "%(message)s"}', + { + "level": "%(levelname)s", + "time": "%(asctime)s", + "logger": "%(name)s", + "process": "%(process)d", + "message": "%(message)s", + }, ) def _default_formatter() -> dict: - if DIAL_SDK_LOG_FORMAT == "json": + datefmt = "%Y-%m-%d %H:%M:%S" + if _DIAL_SDK_LOG_FORMAT == "json": return { "()": "aidial_sdk.utils.json_log_formatter.JsonLogFormatter", - "template": DIAL_SDK_JSON_LOG_FORMAT, - "datefmt": "%Y-%m-%d %H:%M:%S", + "template": _DIAL_SDK_JSON_LOG_FORMAT, + "datefmt": datefmt, } return { "()": "uvicorn.logging.DefaultFormatter", - "fmt": DIAL_SDK_TEXT_LOG_FORMAT, - "datefmt": "%Y-%m-%d %H:%M:%S", + "fmt": _DIAL_SDK_TEXT_LOG_FORMAT, + "datefmt": datefmt, "use_colors": True, } diff --git a/tests/test_json_log_formatter.py b/tests/test_json_log_formatter.py index 23421d50..ce2d0eb5 100644 --- a/tests/test_json_log_formatter.py +++ b/tests/test_json_log_formatter.py @@ -5,34 +5,34 @@ from aidial_sdk.utils.json_log_formatter import JsonLogFormatter -def _format(template: str, **record_fields) -> dict: +def _format(template: dict, **record_fields) -> dict: record = logging.makeLogRecord(record_fields) return json.loads(JsonLogFormatter(template).format(record)) def test_escapes_quotes_newlines_and_percent(): msg = 'has "quotes", a\nnewline, a \\ backslash and 50% off' - out = _format('{"message": "%(message)s"}', msg=msg) + out = _format({"message": "%(message)s"}, msg=msg) assert out["message"] == msg # round-trips => json.dumps escaped it def test_message_args_are_interpolated(): - out = _format('{"message": "%(message)s"}', msg="hi %s", args=("bob",)) + out = _format({"message": "%(message)s"}, msg="hi %s", args=("bob",)) assert out["message"] == "hi bob" def test_missing_field_renders_empty(): - out = _format('{"trace": "%(otelTraceID)s"}') + out = _format({"trace": "%(otelTraceID)s"}) assert out["trace"] == "" def test_nested_template(): - out = _format('{"a": {"b": "%(levelname)s"}}', levelname="INFO") + out = _format({"a": {"b": "%(levelname)s"}}, levelname="INFO") assert out["a"]["b"] == "INFO" def test_non_string_leaves_pass_through(): - out = _format('{"schema": 1, "on": true, "n": null}') + out = _format({"schema": 1, "on": True, "n": None}) assert out == {"schema": 1, "on": True, "n": None} @@ -41,12 +41,5 @@ def test_exception_via_exc_text(): raise ValueError("boom") except ValueError: exc_info = sys.exc_info() - out = _format('{"err": "%(exc_text)s"}', msg="x", exc_info=exc_info) + out = _format({"err": "%(exc_text)s"}, msg="x", exc_info=exc_info) assert "ValueError: boom" in out["err"] - - -if __name__ == "__main__": - for name, fn in sorted(globals().items()): - if name.startswith("test_"): - fn() - print("ok") From 0b71f6f397df6010615c191383be3e58c0d82b62 Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Thu, 16 Jul 2026 13:03:05 +0100 Subject: [PATCH 03/20] feat: make logging instrumentation unconditional once tracing in general is enabled. --- aidial_sdk/telemetry/init.py | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/aidial_sdk/telemetry/init.py b/aidial_sdk/telemetry/init.py index 4d0c8804..ee6f309e 100644 --- a/aidial_sdk/telemetry/init.py +++ b/aidial_sdk/telemetry/init.py @@ -81,10 +81,9 @@ def init_telemetry( except ImportError: pass - if config.tracing.logging: - # Inject tracing context fields onto every log record: - # otelTraceID, otelSpanID, otelTraceSampled - LoggingInstrumentor().instrument() + # Inject tracing context fields onto every log record: + # otelTraceID, otelSpanID, otelTraceSampled + LoggingInstrumentor().instrument() if config.logs is not None: # Adding a handler to the root logger which exports the logs to OTLP From 8b40f815c4180aa1e1bf574d5d03d328f0a9e804 Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Thu, 16 Jul 2026 14:54:48 +0100 Subject: [PATCH 04/20] chore: add doc logging --- README.md | 6 +- aidial_sdk/telemetry/types.py | 7 -- aidial_sdk/utils/env.py | 1 + docs/logging.md | 215 ++++++++++++++++++++++++++++++++++ tests/test_env.py | 19 +++ 5 files changed, 237 insertions(+), 11 deletions(-) create mode 100644 docs/logging.md create mode 100644 tests/test_env.py diff --git a/README.md b/README.md index 80b47a94..a98f0444 100644 --- a/README.md +++ b/README.md @@ -47,14 +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_LOG_FORMAT|text|Console log format: `text` (human-readable) or `json` (single-line JSON, easy to parse).| -|DIAL_SDK_TEXT_LOG_FORMAT|`%(levelprefix)s \| %(asctime)s \| %(name)s \| %(process)d \| %(message)s`|The `%`-style [format string](https://docs.python.org/3/library/logging.html#logrecord-attributes) used when `DIAL_SDK_LOG_FORMAT=text`.| -|DIAL_SDK_JSON_LOG_FORMAT|`{"level": "%(levelname)s", "time": "%(asctime)s", "logger": "%(name)s", "process": "%(process)d", "message": "%(message)s"}`|Used when `DIAL_SDK_LOG_FORMAT=json`. A JSON document whose string leaves are `%`-style format strings; values are escaped automatically.| |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 diff --git a/aidial_sdk/telemetry/types.py b/aidial_sdk/telemetry/types.py index ebe1718f..b1c48b2c 100644 --- a/aidial_sdk/telemetry/types.py +++ b/aidial_sdk/telemetry/types.py @@ -13,9 +13,6 @@ OTEL_EXPORTER_PROMETHEUS_PORT = int( os.getenv("OTEL_EXPORTER_PROMETHEUS_PORT", 9464) ) -OTEL_PYTHON_LOG_CORRELATION = ( - os.getenv("OTEL_PYTHON_LOG_CORRELATION", "false").lower() == "true" -) class LogsConfig(BaseModel): @@ -26,10 +23,6 @@ class LogsConfig(BaseModel): class TracingConfig(BaseModel): otlp_export: bool = "otlp" in OTEL_TRACES_EXPORTER - """Configure logging to include tracing context - into console log messages""" - logging: bool = OTEL_PYTHON_LOG_CORRELATION - class MetricsConfig(BaseModel): otlp_export: bool = "otlp" in OTEL_METRICS_EXPORTER diff --git a/aidial_sdk/utils/env.py b/aidial_sdk/utils/env.py index 1a966c6d..99eb55ad 100644 --- a/aidial_sdk/utils/env.py +++ b/aidial_sdk/utils/env.py @@ -25,6 +25,7 @@ def env_json_dict(name: str, default: dict) -> dict: obj = json.loads(value) if not isinstance(obj, dict): raise ValueError("the object isn't a dictionary") + return obj except Exception as e: raise ValueError( f"The value of the {name!r} environment variable is expected to be a valid JSON dictionary: {e}." diff --git a/docs/logging.md b/docs/logging.md new file mode 100644 index 00000000..ee76b280 --- /dev/null +++ b/docs/logging.md @@ -0,0 +1,215 @@ + +# Logging + +The SDK logs to the console (stderr) through stdlib `logging`, configured from +environment variables. You can pick the **format** (human-readable text or +single-line JSON), customize it, and include **trace/span IDs** for correlation. + +- [Logging](#logging) + - [Environment variables](#environment-variables) + - [Log format](#log-format) + - [JSON](#json) + - [Plain text](#plain-text) + - [Trace and span IDs](#trace-and-span-ids) + - [Enable tracing](#enable-tracing) + - [Tracing in JSON logs](#tracing-in-json-logs) + - [Tracing in text logs](#tracing-in-text-logs) + - [Summary](#summary) + - [OTLP log export](#otlp-log-export) + +## Environment variables + +All variables below are read once at import time — set them before the process starts. + +| Variable | Default | Purpose | +| --- | --- | --- | +| `DIAL_SDK_LOG` | `WARNING` | Log level for the `aidial_sdk` logger. | +| `DIAL_SDK_LOG_FORMAT` | `text` | `text` (human-readable, colored) or `json` (one line per record). | +| `DIAL_SDK_TEXT_LOG_FORMAT` | see below | `%`-style format string used when format is `text`. | +| `DIAL_SDK_JSON_LOG_FORMAT` | see below | JSON template used when format is `json`. | + +--- + +## Log format + +Set the format to `json`: + +```sh +DIAL_SDK_LOG=INFO +DIAL_SDK_LOG_FORMAT=json +``` + +Console: + +```json +{"level": "INFO", "time": "2026-07-16 13:10:41", "logger": "aidial_sdk.foo", "process": "13935", "message": "hello"} +``` + +Compare with the default `text` format: + +```txt +INFO: | 2026-07-16 13:10:41 | aidial_sdk.foo | 13935 | hello +``` + +### JSON + +The value is **a JSON document**. Every **string leaf** (at any nesting depth) is +treated as a [`%`-style format string](https://docs.python.org/3/library/logging.html#logrecord-attributes) +and interpolated against the log record; the whole structure is then `json.dumps`'d. + +```sh +DIAL_SDK_LOG_FORMAT=json +DIAL_SDK_JSON_LOG_FORMAT='{"lvl":"%(levelname)s","msg":"%(message)s","where":{"logger":"%(name)s","pid":"%(process)d"}}' +``` + +Console: + +```json +{"lvl": "INFO", "msg": "hello", "where": {"logger": "aidial_sdk.foo", "pid": "13935"}} +``` + +Default template: + +```json +{"level": "%(levelname)s", "time": "%(asctime)s", "logger": "%(name)s", "process": "%(process)d", "message": "%(message)s"} +``` + +### Plain text + +A plain `%`-style format string (rendered by uvicorn's `DefaultFormatter`, so +`%(levelprefix)s` gives the colored, aligned level). + +```sh +DIAL_SDK_TEXT_LOG_FORMAT='%(levelprefix)s %(name)s: %(message)s' +``` + +Default: + +```txt +%(levelprefix)s | %(asctime)s | %(name)s | %(process)d | %(message)s +``` + +--- + +## Trace and span IDs + +### Enable tracing + +Trace/span IDs only exist when tracing is on. Enable it by passing a +`TelemetryConfig` to your app **and** selecting the OTLP exporter: + +```python +from aidial_sdk import DIALApp +from aidial_sdk.telemetry.types import TelemetryConfig + +app = DIALApp(telemetry_config=TelemetryConfig(), ...) # requires aidial-sdk[telemetry] +``` + +```sh +OTEL_TRACES_EXPORTER=otlp +``` + +This installs OpenTelemetry's logging instrumentor, which injects these fields +onto **every** log record (populated while a request span is active): + +| Field | Example | Value with no active span | +| --- | --- | --- | +| `%(otelTraceID)s` | `4b45f013470528cf753a7e640da7ca1e` | `0` | +| `%(otelSpanID)s` | `ffcc9d300d9ab692` | `0` | +| `%(otelTraceSampled)s` | `True` | `False` | +| `%(otelServiceName)s` | your `service_name` | always set (`unknown_service` if unconfigured) | + +### Tracing in JSON logs + +Add the `otel*` placeholders to your template. They are populated automatically +under an active span; **you never need to guard against them being absent** — a +missing field renders as `""` (so the same template is safe with tracing off). + +```sh +DIAL_SDK_LOG_FORMAT=json +DIAL_SDK_JSON_LOG_FORMAT='{"lvl":"%(levelname)s","msg":"%(message)s","trace_id":"%(otelTraceID)s","span_id":"%(otelSpanID)s"}' +``` + +Console (inside a request span): + +```json +{"lvl": "INFO", "msg": "hello", "trace_id": "4b45f013470528cf753a7e640da7ca1e", "span_id": "ffcc9d300d9ab692"} +``` + +Without tracing the same setup emits `"trace_id": "", "span_id": ""` — no error. + +### Tracing in text logs + +**Option A — via `DIAL_SDK_TEXT_LOG_FORMAT`** (recommended for text): add the +placeholders yourself. + +```sh +OTEL_TRACES_EXPORTER=otlp +DIAL_SDK_TEXT_LOG_FORMAT='%(levelprefix)s | %(asctime)s | trace_id=%(otelTraceID)s span_id=%(otelSpanID)s | %(message)s' +``` + +Console: + +```txt +INFO: | 2026-07-16 13:10:42 | trace_id=36d9c402fc8b07cd7644bbf2adbbcec8 span_id=61f3846d5d19881b | hello +``` + +> ⚠️ Unlike JSON, the text formatter has **no missing-field fallback**. If the +> `otel*` fields aren't on the record (i.e. tracing is *not* enabled) it raises a +> `KeyError` and the log line is dropped. Only put `otel*` fields in the text +> format when tracing is guaranteed on. + +**Option B — via `OTEL_PYTHON_LOG_CORRELATION`** — ⚠️ **not recommended.** When +tracing is enabled, setting this makes the OTel instrumentor install its own +root-logger format that already includes trace context, without touching any +`DIAL_SDK_*` variable: + +```sh +OTEL_TRACES_EXPORTER=otlp +OTEL_PYTHON_LOG_CORRELATION=true +``` + +Console: + +```txt +2026-07-16 13:11:45,585 INFO [aidial_sdk.foo] [app.py:12] [trace_id=d67e996e... span_id=02136a2b... resource.service.name=unknown_service trace_sampled=True] - hello +``` + +Override that format with `OTEL_PYTHON_LOG_FORMAT` (default below): + +```txt +%(asctime)s %(levelname)s [%(name)s] [%(filename)s:%(lineno)d] [trace_id=%(otelTraceID)s span_id=%(otelSpanID)s resource.service.name=%(otelServiceName)s trace_sampled=%(otelTraceSampled)s] - %(message)s +``` + +> ⚠️ **Why it's not recommended:** it works by adding a handler to the **root** +> logger. Because the SDK already logs through its own handler — and your +> application most likely configures logging itself too — that root handler emits +> a **duplicate** line for every record (double logging). It also can't produce +> JSON (`OTEL_PYTHON_LOG_FORMAT` has no escaping) and breaks +> `DIAL_SDK_LOG_FORMAT=json` (you'd get one JSON line plus one text line per +> record). Use Option A instead. + +--- + +## Summary + +| Goal | What to set | +| --- | --- | +| JSON console | `DIAL_SDK_LOG_FORMAT=json` | +| Customize JSON | `DIAL_SDK_JSON_LOG_FORMAT='{…}'` | +| Customize text | `DIAL_SDK_TEXT_LOG_FORMAT='…'` | +| Trace/span in JSON | enable tracing + add `%(otelTraceID)s`/`%(otelSpanID)s` to the JSON template (safe when off) | +| Trace/span in text | enable tracing + add them to `DIAL_SDK_TEXT_LOG_FORMAT` (Option A, recommended). `OTEL_PYTHON_LOG_CORRELATION=true` (Option B) also works but double-logs — avoid. | + +**Key difference:** in JSON the `otel*` fields are auto-injected and safe to +reference whether or not tracing is on; in text you must add them manually and +they require tracing to be enabled. + +--- + +## OTLP log export + +`OTEL_LOGS_EXPORTER=otlp` ships log records to an OTLP collector as structured +data (trace context attached automatically). That pipeline uses no format string, +so none of the `*_LOG_FORMAT` variables above apply to it — they only affect what +is printed to the console. diff --git a/tests/test_env.py b/tests/test_env.py new file mode 100644 index 00000000..5a9ef2cb --- /dev/null +++ b/tests/test_env.py @@ -0,0 +1,19 @@ +import pytest + +from aidial_sdk.utils.env import env_json_dict + + +def test_env_json_dict_returns_parsed_value(monkeypatch): + monkeypatch.setenv("X", '{"a": "%(levelname)s"}') + assert env_json_dict("X", {"default": True}) == {"a": "%(levelname)s"} + + +def test_env_json_dict_falls_back_to_default(monkeypatch): + monkeypatch.delenv("X", raising=False) + assert env_json_dict("X", {"default": True}) == {"default": True} + + +def test_env_json_dict_rejects_non_dict(monkeypatch): + monkeypatch.setenv("X", "[1, 2]") + with pytest.raises(ValueError): + env_json_dict("X", {}) From 59f4b69072b406cc91a622250c9bb4b716646763 Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Thu, 16 Jul 2026 15:35:32 +0100 Subject: [PATCH 05/20] feat: add logging configuration for client --- aidial_sdk/__init__.py | 3 +- aidial_sdk/application.py | 6 +- aidial_sdk/utils/log_config.py | 86 +++++++++++++++++++++++++++-- docs/logging.md | 67 ++++++++++++++++++++++ tests/test_configure_root_logger.py | 45 +++++++++++++++ 5 files changed, 199 insertions(+), 8 deletions(-) create mode 100644 tests/test_configure_root_logger.py diff --git a/aidial_sdk/__init__.py b/aidial_sdk/__init__.py index 1485a407..2d16c9d8 100644 --- a/aidial_sdk/__init__.py +++ b/aidial_sdk/__init__.py @@ -1,5 +1,6 @@ from aidial_sdk.application import DIALApp from aidial_sdk.exceptions import HTTPException +from aidial_sdk.utils.log_config import configure_root_logger from aidial_sdk.utils.logging import logger -__all__ = ["DIALApp", "HTTPException", "logger"] +__all__ = ["DIALApp", "HTTPException", "configure_root_logger", "logger"] diff --git a/aidial_sdk/application.py b/aidial_sdk/application.py index 0481746b..4d7588f1 100644 --- a/aidial_sdk/application.py +++ b/aidial_sdk/application.py @@ -1,4 +1,4 @@ -import logging.config +import logging import re import warnings from collections.abc import Callable, Coroutine @@ -33,7 +33,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 +42,7 @@ to_streaming_response, ) -logging.config.dictConfig(LogConfig().model_dump()) +configure_sdk_logger() RequestType = TypeVar("RequestType", bound=FromRequestMixin) diff --git a/aidial_sdk/utils/log_config.py b/aidial_sdk/utils/log_config.py index 6478584e..e42c3c47 100644 --- a/aidial_sdk/utils/log_config.py +++ b/aidial_sdk/utils/log_config.py @@ -1,7 +1,13 @@ +import logging +import logging.config import os +import sys + +from uvicorn.logging import DefaultFormatter from aidial_sdk._pydantic._compat import BaseModel from aidial_sdk.utils.env import env_json_dict +from aidial_sdk.utils.json_log_formatter import JsonLogFormatter DIAL_SDK_LOG = os.environ.get("DIAL_SDK_LOG", "WARNING").upper() @@ -21,24 +27,81 @@ }, ) +_DATEFMT = "%Y-%m-%d %H:%M:%S" + +# Marks the console handler installed by configure_root_logger so repeat calls +# replace it instead of stacking duplicates (and leave other handlers alone). +_CONSOLE_HANDLER_MARKER = "_aidial_sdk_console_handler" + + +def build_formatter() -> logging.Formatter: + """The console formatter selected by ``DIAL_SDK_LOG_FORMAT`` (text or json).""" + if _DIAL_SDK_LOG_FORMAT == "json": + return JsonLogFormatter( + template=_DIAL_SDK_JSON_LOG_FORMAT, datefmt=_DATEFMT + ) + return DefaultFormatter( + fmt=_DIAL_SDK_TEXT_LOG_FORMAT, datefmt=_DATEFMT, use_colors=True + ) + def _default_formatter() -> dict: - datefmt = "%Y-%m-%d %H:%M:%S" + # dictConfig form of build_formatter(), referenced by import path so + # LogConfig.model_dump() stays serializable. if _DIAL_SDK_LOG_FORMAT == "json": return { "()": "aidial_sdk.utils.json_log_formatter.JsonLogFormatter", "template": _DIAL_SDK_JSON_LOG_FORMAT, - "datefmt": datefmt, + "datefmt": _DATEFMT, } return { "()": "uvicorn.logging.DefaultFormatter", "fmt": _DIAL_SDK_TEXT_LOG_FORMAT, - "datefmt": datefmt, + "datefmt": _DATEFMT, "use_colors": True, } -class LogConfig(BaseModel): +def configure_root_logger(*, level: str | None = None) -> None: + """Route all logging through a single console handler on the root logger, + using the SDK's env-selected format (``DIAL_SDK_LOG_FORMAT=text|json``). + + Call once at startup, after ``DIALApp()``/telemetry init. Clients get the + SDK's formatting for their own loggers for free — they only need to set + their loggers' levels. + + Idempotent: replaces the console handler a previous call installed, and + preserves any other root handlers (e.g. the OTLP export handler added by + telemetry). Child SDK/uvicorn loggers are pointed at the root handler. + + ``level`` sets the root logger's level; when ``None`` the root level is left + untouched (defaults to ``WARNING``). This does not silence loggers that set + their own level — a record created by e.g. an ``INFO``-level ``app`` logger + still reaches the root handler regardless of the root level; the root level + only applies to loggers that don't set one of their own. + """ + root = logging.getLogger() + root.handlers = [ + h + for h in root.handlers + if not getattr(h, _CONSOLE_HANDLER_MARKER, False) + ] + + handler = logging.StreamHandler(sys.stderr) + handler.setFormatter(build_formatter()) + setattr(handler, _CONSOLE_HANDLER_MARKER, True) + root.addHandler(handler) + + if level is not None: + root.setLevel(level.upper()) + + for name in ("aidial_sdk", "uvicorn", "uvicorn.access", "uvicorn.error"): + child = logging.getLogger(name) + child.handlers = [] + child.propagate = True + + +class _LogConfig(BaseModel): """Logging configuration to be set for the server""" version: int = 1 @@ -58,3 +121,18 @@ class LogConfig(BaseModel): "propagate": False, }, } + + +def configure_sdk_logger() -> None: + """Configure the SDK's own loggers. Called once when ``DIALApp`` is imported. + + By default it attaches a single stderr handler using the env-selected format + (``build_formatter()`` — text or json per ``DIAL_SDK_LOG_FORMAT``) to the + ``aidial_sdk`` and ``uvicorn`` loggers, sets ``aidial_sdk`` to ``DIAL_SDK_LOG`` + (default ``WARNING``), and stops ``uvicorn`` from propagating to the root + logger (so uvicorn lines aren't duplicated by any root handler). + + It does **not** touch the root logger or your application's loggers. To give + your own loggers the same formatting, call ``configure_root_logger()``. + """ + logging.config.dictConfig(_LogConfig().model_dump()) diff --git a/docs/logging.md b/docs/logging.md index ee76b280..16aa3b84 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -10,6 +10,7 @@ single-line JSON), customize it, and include **trace/span IDs** for correlation. - [Log format](#log-format) - [JSON](#json) - [Plain text](#plain-text) + - [Reusing the SDK logger in your app](#reusing-the-sdk-logger-in-your-app) - [Trace and span IDs](#trace-and-span-ids) - [Enable tracing](#enable-tracing) - [Tracing in JSON logs](#tracing-in-json-logs) @@ -91,6 +92,72 @@ Default: --- +## Reusing the SDK logger in your app + +Importing `aidial_sdk` (via `DIALApp`) runs `configure_sdk_logger()` once. By +default it configures **only the SDK's own loggers**: it attaches a single stderr +handler using the env-selected format (`DIAL_SDK_LOG_FORMAT`) to the `aidial_sdk` +and `uvicorn` loggers, sets `aidial_sdk` to `DIAL_SDK_LOG` (default `WARNING`), +and stops `uvicorn` from propagating to the root logger. It does **not** touch the +root logger or your application's loggers. + +So to give **your** application's loggers the same formatting — instead of +hand-rolling a formatter and a root handler — call `configure_root_logger()` once +at startup: + +```python +import logging +import os + +from aidial_sdk import DIALApp, configure_root_logger +from aidial_sdk.telemetry.types import TelemetryConfig + +app = DIALApp(telemetry_config=TelemetryConfig(), ...) + +# Install one root handler using the SDK's env-selected format. Call AFTER +# DIALApp()/telemetry init. +configure_root_logger() + +# You only declare your own loggers' levels: +for name in ["app", "bedrock"]: + logging.getLogger(name).setLevel(os.getenv("LOG_LEVEL", "INFO")) +``` + +Now every logger — the SDK's, uvicorn's, and yours — is emitted through a single +handler that honors `DIAL_SDK_LOG_FORMAT`. Run with `DIAL_SDK_LOG_FORMAT=json` +and your `app`/`bedrock` logs become JSON too, with no code change: + +```json +{"level": "INFO", "time": "2026-07-16 13:10:41", "logger": "app", "process": "13935", "message": "hello from the adapter"} +``` + +**What it does:** points the SDK/uvicorn loggers at the root logger and installs +**one** console handler there with the SDK's formatter. It's idempotent (a repeat +call replaces that handler rather than stacking a duplicate) and **preserves any +other root handler** — notably the OTLP export handler telemetry adds — so it's +safe to call after `DIALApp()`. + +### The `level` argument + +`configure_root_logger(level="INFO")` sets the level of the **root** logger — it +does **not** force every logger to `INFO`. Root's level is only the *fallback* +for loggers that don't set their own: + +- A logger **without** an explicit level (e.g. a fresh `app` logger, or a + third-party library) inherits root's level → fires at `INFO`. +- A logger **with** its own level keeps it. `aidial_sdk` stays at `DIAL_SDK_LOG` + (default `WARNING`); a logger you set to `DEBUG` stays `DEBUG` — regardless of + the root level. + +When `level` is omitted (`None`), the root level is left untouched (stdlib +default `WARNING`), and each logger's own level applies. This is why the example +above sets `app`/`bedrock` levels explicitly rather than relying on the root +level. Note that a logger's own level gates whether a record is *created*; once +created it always reaches the root handler, so a low root level never suppresses +an `INFO` record coming from an `INFO`-level `app` logger. + +--- + ## Trace and span IDs ### Enable tracing diff --git a/tests/test_configure_root_logger.py b/tests/test_configure_root_logger.py new file mode 100644 index 00000000..fce6aa29 --- /dev/null +++ b/tests/test_configure_root_logger.py @@ -0,0 +1,45 @@ +import logging + +import pytest + +from aidial_sdk import configure_root_logger +from aidial_sdk.utils.log_config import _CONSOLE_HANDLER_MARKER + + +def _console_handlers(root): + return [ + h for h in root.handlers if getattr(h, _CONSOLE_HANDLER_MARKER, False) + ] + + +@pytest.fixture +def clean_root(): + root = logging.getLogger() + saved_handlers, saved_level = root.handlers[:], root.level + root.handlers = [] + yield root + root.handlers, root.level = saved_handlers, saved_level + + +def test_installs_single_console_handler(clean_root): + configure_root_logger() + assert len(_console_handlers(clean_root)) == 1 + + +def test_idempotent_and_preserves_other_handlers(clean_root): + other = logging.NullHandler() # stands in for the OTLP export handler + clean_root.addHandler(other) + + configure_root_logger() + configure_root_logger() # repeat must not stack console handlers + + assert len(_console_handlers(clean_root)) == 1 + assert other in clean_root.handlers + + +def test_level_none_leaves_root_level_untouched(clean_root): + clean_root.setLevel(logging.WARNING) + configure_root_logger() + assert clean_root.level == logging.WARNING + configure_root_logger(level="DEBUG") + assert clean_root.level == logging.DEBUG From ecd1e9347d5a670b763c0473c534e1e66640b496 Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Thu, 16 Jul 2026 15:50:41 +0100 Subject: [PATCH 06/20] fix: simplify log config --- aidial_sdk/utils/log_config.py | 58 ++++++---------------------------- 1 file changed, 10 insertions(+), 48 deletions(-) diff --git a/aidial_sdk/utils/log_config.py b/aidial_sdk/utils/log_config.py index e42c3c47..90153768 100644 --- a/aidial_sdk/utils/log_config.py +++ b/aidial_sdk/utils/log_config.py @@ -1,11 +1,9 @@ import logging -import logging.config import os import sys from uvicorn.logging import DefaultFormatter -from aidial_sdk._pydantic._compat import BaseModel from aidial_sdk.utils.env import env_json_dict from aidial_sdk.utils.json_log_formatter import JsonLogFormatter @@ -45,23 +43,6 @@ def build_formatter() -> logging.Formatter: ) -def _default_formatter() -> dict: - # dictConfig form of build_formatter(), referenced by import path so - # LogConfig.model_dump() stays serializable. - if _DIAL_SDK_LOG_FORMAT == "json": - return { - "()": "aidial_sdk.utils.json_log_formatter.JsonLogFormatter", - "template": _DIAL_SDK_JSON_LOG_FORMAT, - "datefmt": _DATEFMT, - } - return { - "()": "uvicorn.logging.DefaultFormatter", - "fmt": _DIAL_SDK_TEXT_LOG_FORMAT, - "datefmt": _DATEFMT, - "use_colors": True, - } - - def configure_root_logger(*, level: str | None = None) -> None: """Route all logging through a single console handler on the root logger, using the SDK's env-selected format (``DIAL_SDK_LOG_FORMAT=text|json``). @@ -101,38 +82,19 @@ def configure_root_logger(*, level: str | None = None) -> None: child.propagate = True -class _LogConfig(BaseModel): - """Logging configuration to be set for the server""" - - version: int = 1 - disable_existing_loggers: bool = False - formatters: dict = {"default": _default_formatter()} - 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, - }, - } - - def configure_sdk_logger() -> None: """Configure the SDK's own loggers. Called once when ``DIALApp`` is imported. - By default it attaches a single stderr handler using the env-selected format - (``build_formatter()`` — text or json per ``DIAL_SDK_LOG_FORMAT``) to the - ``aidial_sdk`` and ``uvicorn`` loggers, sets ``aidial_sdk`` to ``DIAL_SDK_LOG`` - (default ``WARNING``), and stops ``uvicorn`` from propagating to the root - logger (so uvicorn lines aren't duplicated by any root handler). - It does **not** touch the root logger or your application's loggers. To give your own loggers the same formatting, call ``configure_root_logger()``. """ - logging.config.dictConfig(_LogConfig().model_dump()) + handler = logging.StreamHandler(sys.stderr) + handler.setFormatter(build_formatter()) + + aidial_sdk = logging.getLogger("aidial_sdk") + aidial_sdk.handlers = [handler] + aidial_sdk.setLevel(DIAL_SDK_LOG) + + uvicorn = logging.getLogger("uvicorn") + uvicorn.handlers = [handler] + uvicorn.propagate = False From ae2a9bdf5eff87c881406ea7dc5d9e8b470c22fc Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Thu, 16 Jul 2026 16:10:55 +0100 Subject: [PATCH 07/20] feat: defer to already installed root handler --- aidial_sdk/utils/log_config.py | 35 ++++++++++++++++------------- docs/logging.md | 17 +++++++++----- tests/test_configure_root_logger.py | 13 +++++++++++ 3 files changed, 43 insertions(+), 22 deletions(-) diff --git a/aidial_sdk/utils/log_config.py b/aidial_sdk/utils/log_config.py index 90153768..06917554 100644 --- a/aidial_sdk/utils/log_config.py +++ b/aidial_sdk/utils/log_config.py @@ -27,10 +27,6 @@ _DATEFMT = "%Y-%m-%d %H:%M:%S" -# Marks the console handler installed by configure_root_logger so repeat calls -# replace it instead of stacking duplicates (and leave other handlers alone). -_CONSOLE_HANDLER_MARKER = "_aidial_sdk_console_handler" - def build_formatter() -> logging.Formatter: """The console formatter selected by ``DIAL_SDK_LOG_FORMAT`` (text or json).""" @@ -51,9 +47,9 @@ def configure_root_logger(*, level: str | None = None) -> None: SDK's formatting for their own loggers for free — they only need to set their loggers' levels. - Idempotent: replaces the console handler a previous call installed, and - preserves any other root handlers (e.g. the OTLP export handler added by - telemetry). Child SDK/uvicorn loggers are pointed at the root handler. + If root already has a stderr console handler that this function did not + install — e.g. one OTEL added via ``OTEL_PYTHON_LOG_CORRELATION`` — it defers + to it and does not add a second one. ``level`` sets the root logger's level; when ``None`` the root level is left untouched (defaults to ``WARNING``). This does not silence loggers that set @@ -62,16 +58,23 @@ def configure_root_logger(*, level: str | None = None) -> None: only applies to loggers that don't set one of their own. """ root = logging.getLogger() - root.handlers = [ - h - for h in root.handlers - if not getattr(h, _CONSOLE_HANDLER_MARKER, False) - ] - handler = logging.StreamHandler(sys.stderr) - handler.setFormatter(build_formatter()) - setattr(handler, _CONSOLE_HANDLER_MARKER, True) - root.addHandler(handler) + # Drop the console handler we installed on a previous call ensuring idempotency + _MARKER = "_aidial_sdk_console_handler" + root.handlers = [h for h in root.handlers if not getattr(h, _MARKER, False)] + + # Defer to a stderr console handler already on root (e.g. OTEL's) rather + # than adding a second one that would duplicate every line. + has_console_handler = any( + isinstance(h, logging.StreamHandler) + and getattr(h, "stream", None) is sys.stderr + for h in root.handlers + ) + if not has_console_handler: + handler = logging.StreamHandler(sys.stderr) + handler.setFormatter(build_formatter()) + setattr(handler, _MARKER, True) + root.addHandler(handler) if level is not None: root.setLevel(level.upper()) diff --git a/docs/logging.md b/docs/logging.md index 16aa3b84..8969bdaa 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -11,6 +11,7 @@ single-line JSON), customize it, and include **trace/span IDs** for correlation. - [JSON](#json) - [Plain text](#plain-text) - [Reusing the SDK logger in your app](#reusing-the-sdk-logger-in-your-app) + - [The `level` argument](#the-level-argument) - [Trace and span IDs](#trace-and-span-ids) - [Enable tracing](#enable-tracing) - [Tracing in JSON logs](#tracing-in-json-logs) @@ -132,10 +133,12 @@ and your `app`/`bedrock` logs become JSON too, with no code change: ``` **What it does:** points the SDK/uvicorn loggers at the root logger and installs -**one** console handler there with the SDK's formatter. It's idempotent (a repeat -call replaces that handler rather than stacking a duplicate) and **preserves any -other root handler** — notably the OTLP export handler telemetry adds — so it's -safe to call after `DIALApp()`. +**one** console handler there with the SDK's formatter. It's idempotent. +If root already has a stderr console handler it +didn't install (e.g. one OTEL added via `OTEL_PYTHON_LOG_CORRELATION`), it +**defers** to it and adds nothing — avoiding duplicate lines. In that case the +SDK format doesn't apply to the console, which is one more reason to prefer +Option A over `OTEL_PYTHON_LOG_CORRELATION`. ### The `level` argument @@ -221,7 +224,8 @@ Console: INFO: | 2026-07-16 13:10:42 | trace_id=36d9c402fc8b07cd7644bbf2adbbcec8 span_id=61f3846d5d19881b | hello ``` -> ⚠️ Unlike JSON, the text formatter has **no missing-field fallback**. If the +> [!NOTE] +> Unlike JSON, the text formatter has **no missing-field fallback**. If the > `otel*` fields aren't on the record (i.e. tracing is *not* enabled) it raises a > `KeyError` and the log line is dropped. Only put `otel*` fields in the text > format when tracing is guaranteed on. @@ -248,7 +252,8 @@ Override that format with `OTEL_PYTHON_LOG_FORMAT` (default below): %(asctime)s %(levelname)s [%(name)s] [%(filename)s:%(lineno)d] [trace_id=%(otelTraceID)s span_id=%(otelSpanID)s resource.service.name=%(otelServiceName)s trace_sampled=%(otelTraceSampled)s] - %(message)s ``` -> ⚠️ **Why it's not recommended:** it works by adding a handler to the **root** +> [!WARNING] +> **Why it's not recommended:** it works by adding a handler to the **root** > logger. Because the SDK already logs through its own handler — and your > application most likely configures logging itself too — that root handler emits > a **duplicate** line for every record (double logging). It also can't produce diff --git a/tests/test_configure_root_logger.py b/tests/test_configure_root_logger.py index fce6aa29..998be7fb 100644 --- a/tests/test_configure_root_logger.py +++ b/tests/test_configure_root_logger.py @@ -1,4 +1,5 @@ import logging +import sys import pytest @@ -37,6 +38,18 @@ def test_idempotent_and_preserves_other_handlers(clean_root): assert other in clean_root.handlers +def test_defers_to_existing_stderr_console_handler(clean_root): + # Stand-in for OTEL's basicConfig console handler on root. + otel_console = logging.StreamHandler(sys.stderr) + clean_root.addHandler(otel_console) + + configure_root_logger() + + # We do not add our own console handler; OTEL's stays as the only one. + assert _console_handlers(clean_root) == [] + assert otel_console in clean_root.handlers + + def test_level_none_leaves_root_level_untouched(clean_root): clean_root.setLevel(logging.WARNING) configure_root_logger() From b0cbade4e8669e225ca32b34339f82679a2d8cfb Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Thu, 16 Jul 2026 16:15:19 +0100 Subject: [PATCH 08/20] feat: remove log_level --- aidial_sdk/utils/log_config.py | 12 +++-------- docs/logging.md | 31 ++++++++++------------------- tests/test_configure_root_logger.py | 25 +++++++++-------------- 3 files changed, 23 insertions(+), 45 deletions(-) diff --git a/aidial_sdk/utils/log_config.py b/aidial_sdk/utils/log_config.py index 06917554..932afe65 100644 --- a/aidial_sdk/utils/log_config.py +++ b/aidial_sdk/utils/log_config.py @@ -39,7 +39,7 @@ def build_formatter() -> logging.Formatter: ) -def configure_root_logger(*, level: str | None = None) -> None: +def configure_root_logger() -> None: """Route all logging through a single console handler on the root logger, using the SDK's env-selected format (``DIAL_SDK_LOG_FORMAT=text|json``). @@ -51,11 +51,8 @@ def configure_root_logger(*, level: str | None = None) -> None: install — e.g. one OTEL added via ``OTEL_PYTHON_LOG_CORRELATION`` — it defers to it and does not add a second one. - ``level`` sets the root logger's level; when ``None`` the root level is left - untouched (defaults to ``WARNING``). This does not silence loggers that set - their own level — a record created by e.g. an ``INFO``-level ``app`` logger - still reaches the root handler regardless of the root level; the root level - only applies to loggers that don't set one of their own. + The root logger's level is left untouched (stdlib default ``WARNING``); set + per-logger levels yourself for the loggers you care about. """ root = logging.getLogger() @@ -76,9 +73,6 @@ def configure_root_logger(*, level: str | None = None) -> None: setattr(handler, _MARKER, True) root.addHandler(handler) - if level is not None: - root.setLevel(level.upper()) - for name in ("aidial_sdk", "uvicorn", "uvicorn.access", "uvicorn.error"): child = logging.getLogger(name) child.handlers = [] diff --git a/docs/logging.md b/docs/logging.md index 8969bdaa..0ffddd4c 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -11,7 +11,7 @@ single-line JSON), customize it, and include **trace/span IDs** for correlation. - [JSON](#json) - [Plain text](#plain-text) - [Reusing the SDK logger in your app](#reusing-the-sdk-logger-in-your-app) - - [The `level` argument](#the-level-argument) + - [Log levels](#log-levels) - [Trace and span IDs](#trace-and-span-ids) - [Enable tracing](#enable-tracing) - [Tracing in JSON logs](#tracing-in-json-logs) @@ -115,8 +115,8 @@ from aidial_sdk.telemetry.types import TelemetryConfig app = DIALApp(telemetry_config=TelemetryConfig(), ...) -# Install one root handler using the SDK's env-selected format. Call AFTER -# DIALApp()/telemetry init. +# Install one root handler using the SDK's env-selected format. +# Call AFTER DIALApp()/telemetry init. configure_root_logger() # You only declare your own loggers' levels: @@ -140,24 +140,15 @@ didn't install (e.g. one OTEL added via `OTEL_PYTHON_LOG_CORRELATION`), it SDK format doesn't apply to the console, which is one more reason to prefer Option A over `OTEL_PYTHON_LOG_CORRELATION`. -### The `level` argument +### Log levels -`configure_root_logger(level="INFO")` sets the level of the **root** logger — it -does **not** force every logger to `INFO`. Root's level is only the *fallback* -for loggers that don't set their own: - -- A logger **without** an explicit level (e.g. a fresh `app` logger, or a - third-party library) inherits root's level → fires at `INFO`. -- A logger **with** its own level keeps it. `aidial_sdk` stays at `DIAL_SDK_LOG` - (default `WARNING`); a logger you set to `DEBUG` stays `DEBUG` — regardless of - the root level. - -When `level` is omitted (`None`), the root level is left untouched (stdlib -default `WARNING`), and each logger's own level applies. This is why the example -above sets `app`/`bedrock` levels explicitly rather than relying on the root -level. Note that a logger's own level gates whether a record is *created*; once -created it always reaches the root handler, so a low root level never suppresses -an `INFO` record coming from an `INFO`-level `app` logger. +`configure_root_logger()` does **not** change the root logger's level (stdlib +default `WARNING`) — it only owns the handler/format. Set levels per logger, as +in the example above. Avoid bumping the **root** level to `DEBUG`: root's level +is the fallback for every logger that hasn't set its own, so it would turn on the +very chatty (and prompt/credential-leaking) `DEBUG` streams of libraries like +`httpx`, `openai`, and `anthropic`. Raise the level only on the loggers you care +about (`app`, `bedrock`, …). --- diff --git a/tests/test_configure_root_logger.py b/tests/test_configure_root_logger.py index 998be7fb..0a66e945 100644 --- a/tests/test_configure_root_logger.py +++ b/tests/test_configure_root_logger.py @@ -4,12 +4,14 @@ import pytest from aidial_sdk import configure_root_logger -from aidial_sdk.utils.log_config import _CONSOLE_HANDLER_MARKER -def _console_handlers(root): +def _stderr_console_handlers(root): return [ - h for h in root.handlers if getattr(h, _CONSOLE_HANDLER_MARKER, False) + h + for h in root.handlers + if isinstance(h, logging.StreamHandler) + and getattr(h, "stream", None) is sys.stderr ] @@ -24,7 +26,7 @@ def clean_root(): def test_installs_single_console_handler(clean_root): configure_root_logger() - assert len(_console_handlers(clean_root)) == 1 + assert len(_stderr_console_handlers(clean_root)) == 1 def test_idempotent_and_preserves_other_handlers(clean_root): @@ -34,7 +36,7 @@ def test_idempotent_and_preserves_other_handlers(clean_root): configure_root_logger() configure_root_logger() # repeat must not stack console handlers - assert len(_console_handlers(clean_root)) == 1 + assert len(_stderr_console_handlers(clean_root)) == 1 assert other in clean_root.handlers @@ -45,14 +47,5 @@ def test_defers_to_existing_stderr_console_handler(clean_root): configure_root_logger() - # We do not add our own console handler; OTEL's stays as the only one. - assert _console_handlers(clean_root) == [] - assert otel_console in clean_root.handlers - - -def test_level_none_leaves_root_level_untouched(clean_root): - clean_root.setLevel(logging.WARNING) - configure_root_logger() - assert clean_root.level == logging.WARNING - configure_root_logger(level="DEBUG") - assert clean_root.level == logging.DEBUG + # We do not add our own; OTEL's stays as the only console handler. + assert _stderr_console_handlers(clean_root) == [otel_console] From 920c27f6c5cda55d06052f1c1bce7895f357e7a0 Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Thu, 16 Jul 2026 16:24:14 +0100 Subject: [PATCH 09/20] feat: auto-add otel* log record fields --- aidial_sdk/utils/json_log_formatter.py | 24 ++++++++++++++++++-- docs/logging.md | 29 +++++++++++++++--------- tests/test_json_log_formatter.py | 31 ++++++++++++++++++++++++++ 3 files changed, 72 insertions(+), 12 deletions(-) diff --git a/aidial_sdk/utils/json_log_formatter.py b/aidial_sdk/utils/json_log_formatter.py index cef8f2fd..80fb22df 100644 --- a/aidial_sdk/utils/json_log_formatter.py +++ b/aidial_sdk/utils/json_log_formatter.py @@ -6,12 +6,21 @@ class JsonLogFormatter(logging.Formatter): """Render a record through a JSON template whose string leaves are `%`-format strings; the whole structure is then `json.dumps`'d, so every - interpolated value is escaped for free.""" + interpolated value is escaped for free. + + Any ``otel*`` field present on the record (``otelTraceID``, ``otelSpanID``, + ... — injected by the OTel logging instrumentor when tracing is on) is added + to the output automatically, so you get trace correlation without editing the + template. A field the template already references (under any key, e.g. + ``{"trace_id": "%(otelTraceID)s"}``) is left to the template and not added + again.""" def __init__(self, template: dict, datefmt: str | None = None) -> None: super().__init__(datefmt=datefmt) self._template = template - self._uses_time = "%(asctime)" in json.dumps(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: if isinstance(node, str): @@ -37,4 +46,15 @@ def format(self, record: logging.LogRecord) -> str: rendered = self._interpolate( self._template, defaultdict(str, record.__dict__) ) + + # Auto-add otel* fields present on the record, unless the template + # already references one (under any key name). + 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) diff --git a/docs/logging.md b/docs/logging.md index 0ffddd4c..b8825dab 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -182,22 +182,31 @@ onto **every** log record (populated while a request span is active): ### Tracing in JSON logs -Add the `otel*` placeholders to your template. They are populated automatically -under an active span; **you never need to guard against them being absent** — a -missing field renders as `""` (so the same template is safe with tracing off). +Nothing to add — the JSON formatter **auto-appends** every `otel*` field present +on the record. So with the default template and tracing on: ```sh DIAL_SDK_LOG_FORMAT=json -DIAL_SDK_JSON_LOG_FORMAT='{"lvl":"%(levelname)s","msg":"%(message)s","trace_id":"%(otelTraceID)s","span_id":"%(otelSpanID)s"}' ``` Console (inside a request span): ```json -{"lvl": "INFO", "msg": "hello", "trace_id": "4b45f013470528cf753a7e640da7ca1e", "span_id": "ffcc9d300d9ab692"} +{"level": "INFO", "time": "2026-07-16 13:10:41", "logger": "aidial_sdk", "process": "13935", "message": "hello", "otelTraceID": "4b45f013470528cf753a7e640da7ca1e", "otelSpanID": "ffcc9d300d9ab692", "otelTraceSampled": true, "otelServiceName": "my-service"} ``` -Without tracing the same setup emits `"trace_id": "", "span_id": ""` — no error. +Without tracing, the `otel*` keys are simply absent (no error). + +To rename a field, reference it in your template — the auto-added copy is then +suppressed, so there's no duplicate: + +```sh +DIAL_SDK_JSON_LOG_FORMAT='{"lvl":"%(levelname)s","msg":"%(message)s","trace_id":"%(otelTraceID)s"}' +``` + +Here the output has your `trace_id` key (not `otelTraceID`), plus the other +`otel*` fields still auto-added (`otelSpanID`, `otelTraceSampled`, +`otelServiceName`). ### Tracing in text logs @@ -261,12 +270,12 @@ Override that format with `OTEL_PYTHON_LOG_FORMAT` (default below): | JSON console | `DIAL_SDK_LOG_FORMAT=json` | | Customize JSON | `DIAL_SDK_JSON_LOG_FORMAT='{…}'` | | Customize text | `DIAL_SDK_TEXT_LOG_FORMAT='…'` | -| Trace/span in JSON | enable tracing + add `%(otelTraceID)s`/`%(otelSpanID)s` to the JSON template (safe when off) | +| Trace/span in JSON | just enable tracing — `otel*` fields are auto-added to the JSON output (reference them in the template only to rename) | | Trace/span in text | enable tracing + add them to `DIAL_SDK_TEXT_LOG_FORMAT` (Option A, recommended). `OTEL_PYTHON_LOG_CORRELATION=true` (Option B) also works but double-logs — avoid. | -**Key difference:** in JSON the `otel*` fields are auto-injected and safe to -reference whether or not tracing is on; in text you must add them manually and -they require tracing to be enabled. +**Key difference:** in JSON the `otel*` fields are auto-added whenever tracing is +on (and simply absent otherwise); in text you must add them manually and they +require tracing to be enabled. --- diff --git a/tests/test_json_log_formatter.py b/tests/test_json_log_formatter.py index ce2d0eb5..191a235e 100644 --- a/tests/test_json_log_formatter.py +++ b/tests/test_json_log_formatter.py @@ -36,6 +36,37 @@ def test_non_string_leaves_pass_through(): assert out == {"schema": 1, "on": True, "n": None} +def test_otel_fields_auto_added_when_present(): + out = _format( + {"msg": "%(message)s"}, + msg="hi", + otelTraceID="abc", + otelSpanID="def", + otelTraceSampled=True, + ) + assert out == { + "msg": "hi", + "otelTraceID": "abc", + "otelSpanID": "def", + "otelTraceSampled": True, + } + + +def test_otel_fields_not_added_when_absent(): + out = _format({"msg": "%(message)s"}, msg="hi") + assert out == {"msg": "hi"} + + +def test_otel_field_referenced_in_template_is_not_duplicated(): + out = _format( + {"trace_id": "%(otelTraceID)s", "span_id": "%(otelSpanID)s"}, + otelTraceID="abc", + otelSpanID="def", + ) + # Renamed via the template -> no extra otelTraceID/otelSpanID keys. + assert out == {"trace_id": "abc", "span_id": "def"} + + def test_exception_via_exc_text(): try: raise ValueError("boom") From f5c48d66ce57b8ffd790b0de4a39e36c1bcedcbf Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Thu, 16 Jul 2026 16:25:00 +0100 Subject: [PATCH 10/20] feat: move code around --- .../utils/{json_log_formatter.py => _json_log_formatter.py} | 0 aidial_sdk/utils/log_config.py | 2 +- tests/test_json_log_formatter.py | 2 +- 3 files changed, 2 insertions(+), 2 deletions(-) rename aidial_sdk/utils/{json_log_formatter.py => _json_log_formatter.py} (100%) diff --git a/aidial_sdk/utils/json_log_formatter.py b/aidial_sdk/utils/_json_log_formatter.py similarity index 100% rename from aidial_sdk/utils/json_log_formatter.py rename to aidial_sdk/utils/_json_log_formatter.py diff --git a/aidial_sdk/utils/log_config.py b/aidial_sdk/utils/log_config.py index 932afe65..4027d841 100644 --- a/aidial_sdk/utils/log_config.py +++ b/aidial_sdk/utils/log_config.py @@ -4,8 +4,8 @@ from uvicorn.logging import DefaultFormatter +from aidial_sdk.utils._json_log_formatter import JsonLogFormatter from aidial_sdk.utils.env import env_json_dict -from aidial_sdk.utils.json_log_formatter import JsonLogFormatter DIAL_SDK_LOG = os.environ.get("DIAL_SDK_LOG", "WARNING").upper() diff --git a/tests/test_json_log_formatter.py b/tests/test_json_log_formatter.py index 191a235e..83e9e837 100644 --- a/tests/test_json_log_formatter.py +++ b/tests/test_json_log_formatter.py @@ -2,7 +2,7 @@ import logging import sys -from aidial_sdk.utils.json_log_formatter import JsonLogFormatter +from aidial_sdk.utils._json_log_formatter import JsonLogFormatter def _format(template: dict, **record_fields) -> dict: From 96299b0130eab67e7fb8bb7c932e2c39cfbbd2bb Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Thu, 16 Jul 2026 16:46:58 +0100 Subject: [PATCH 11/20] chore: simplify doc and comments --- aidial_sdk/telemetry/init.py | 3 +- aidial_sdk/utils/_json_log_formatter.py | 22 +-- aidial_sdk/utils/log_config.py | 26 +-- docs/logging.md | 245 ++++++------------------ 4 files changed, 79 insertions(+), 217 deletions(-) diff --git a/aidial_sdk/telemetry/init.py b/aidial_sdk/telemetry/init.py index ee6f309e..5e27e40f 100644 --- a/aidial_sdk/telemetry/init.py +++ b/aidial_sdk/telemetry/init.py @@ -81,8 +81,7 @@ def init_telemetry( except ImportError: pass - # Inject tracing context fields onto every log record: - # otelTraceID, otelSpanID, otelTraceSampled + # Inject otel* tracing fields onto every log record. LoggingInstrumentor().instrument() if config.logs is not None: diff --git a/aidial_sdk/utils/_json_log_formatter.py b/aidial_sdk/utils/_json_log_formatter.py index 80fb22df..572508ea 100644 --- a/aidial_sdk/utils/_json_log_formatter.py +++ b/aidial_sdk/utils/_json_log_formatter.py @@ -5,15 +5,11 @@ class JsonLogFormatter(logging.Formatter): """Render a record through a JSON template whose string leaves are - `%`-format strings; the whole structure is then `json.dumps`'d, so every - interpolated value is escaped for free. + `%`-format strings, then `json.dumps` the result (escaping every value). - Any ``otel*`` field present on the record (``otelTraceID``, ``otelSpanID``, - ... — injected by the OTel logging instrumentor when tracing is on) is added - to the output automatically, so you get trace correlation without editing the - template. A field the template already references (under any key, e.g. - ``{"trace_id": "%(otelTraceID)s"}``) is left to the template and not added - again.""" + 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) @@ -29,26 +25,22 @@ def _interpolate(self, node: object, fields: dict) -> object: return {k: self._interpolate(v, fields) for k, v in node.items()} if isinstance(node, list): return [self._interpolate(v, fields) for v in node] - return node # numbers, bools, null pass through unchanged + 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; it becomes one escaped string - # after json.dumps — never appended raw outside the JSON. + # 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 "" (e.g. otelTraceID - # when telemetry is off) instead of raising during %-interpolation. + # defaultdict(str): a missing field renders as "" instead of raising. rendered = self._interpolate( self._template, defaultdict(str, record.__dict__) ) - # Auto-add otel* fields present on the record, unless the template - # already references one (under any key name). if isinstance(rendered, dict): for key, value in record.__dict__.items(): if ( diff --git a/aidial_sdk/utils/log_config.py b/aidial_sdk/utils/log_config.py index 4027d841..5b8bd4ac 100644 --- a/aidial_sdk/utils/log_config.py +++ b/aidial_sdk/utils/log_config.py @@ -41,22 +41,16 @@ def build_formatter() -> logging.Formatter: def configure_root_logger() -> None: """Route all logging through a single console handler on the root logger, - using the SDK's env-selected format (``DIAL_SDK_LOG_FORMAT=text|json``). + using the SDK's env-selected format (``DIAL_SDK_LOG_FORMAT=text|json``), so + the application's own loggers get the SDK's formatting too. - Call once at startup, after ``DIALApp()``/telemetry init. Clients get the - SDK's formatting for their own loggers for free — they only need to set - their loggers' levels. - - If root already has a stderr console handler that this function did not - install — e.g. one OTEL added via ``OTEL_PYTHON_LOG_CORRELATION`` — it defers - to it and does not add a second one. - - The root logger's level is left untouched (stdlib default ``WARNING``); set - per-logger levels yourself for the loggers you care about. + Idempotent; call once at startup, after ``DIALApp()``/telemetry init. Leaves + the root level untouched (stdlib default ``WARNING``) — set per-logger levels + yourself. If root already has a stderr console handler this function did not + install (e.g. OTEL's via ``OTEL_PYTHON_LOG_CORRELATION``), it defers to it. """ root = logging.getLogger() - # Drop the console handler we installed on a previous call ensuring idempotency _MARKER = "_aidial_sdk_console_handler" root.handlers = [h for h in root.handlers if not getattr(h, _MARKER, False)] @@ -80,11 +74,9 @@ def configure_root_logger() -> None: def configure_sdk_logger() -> None: - """Configure the SDK's own loggers. Called once when ``DIALApp`` is imported. - - It does **not** touch the root logger or your application's loggers. To give - your own loggers the same formatting, call ``configure_root_logger()``. - """ + """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()``.""" handler = logging.StreamHandler(sys.stderr) handler.setFormatter(build_formatter()) diff --git a/docs/logging.md b/docs/logging.md index b8825dab..9c8184e7 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -1,168 +1,97 @@ # Logging -The SDK logs to the console (stderr) through stdlib `logging`, configured from -environment variables. You can pick the **format** (human-readable text or -single-line JSON), customize it, and include **trace/span IDs** for correlation. +The SDK logs to the console (stderr) through stdlib `logging`, configured from environment variables. +You pick the **format** (human-readable text or single-line JSON), customize it, and optionally include **trace/span IDs**. - [Logging](#logging) - [Environment variables](#environment-variables) - [Log format](#log-format) - - [JSON](#json) - - [Plain text](#plain-text) - [Reusing the SDK logger in your app](#reusing-the-sdk-logger-in-your-app) - - [Log levels](#log-levels) - [Trace and span IDs](#trace-and-span-ids) - - [Enable tracing](#enable-tracing) - - [Tracing in JSON logs](#tracing-in-json-logs) - - [Tracing in text logs](#tracing-in-text-logs) + - [JSON logs](#json-logs) + - [Text logs](#text-logs) - [Summary](#summary) - [OTLP log export](#otlp-log-export) ## Environment variables -All variables below are read once at import time — set them before the process starts. - | Variable | Default | Purpose | | --- | --- | --- | -| `DIAL_SDK_LOG` | `WARNING` | Log level for the `aidial_sdk` logger. | -| `DIAL_SDK_LOG_FORMAT` | `text` | `text` (human-readable, colored) or `json` (one line per record). | +| `DIAL_SDK_LOG` | `WARNING` | Level for the `aidial_sdk` logger. | +| `DIAL_SDK_LOG_FORMAT` | `text` | `text` (colored, human-readable) or `json` (one line per record). | | `DIAL_SDK_TEXT_LOG_FORMAT` | see below | `%`-style format string used when format is `text`. | | `DIAL_SDK_JSON_LOG_FORMAT` | see below | JSON template used when format is `json`. | ---- - ## Log format -Set the format to `json`: - -```sh -DIAL_SDK_LOG=INFO -DIAL_SDK_LOG_FORMAT=json -``` - -Console: - -```json -{"level": "INFO", "time": "2026-07-16 13:10:41", "logger": "aidial_sdk.foo", "process": "13935", "message": "hello"} -``` - -Compare with the default `text` format: +`text` (default) renders through uvicorn's `DefaultFormatter`, so +`%(levelprefix)s` gives the colored, aligned level. Default: ```txt +%(levelprefix)s | %(asctime)s | %(name)s | %(process)d | %(message)s +→ INFO: | 2026-07-16 13:10:41 | aidial_sdk.foo | 13935 | hello ``` -### JSON - -The value is **a JSON document**. Every **string leaf** (at any nesting depth) is -treated as a [`%`-style format string](https://docs.python.org/3/library/logging.html#logrecord-attributes) -and interpolated against the log record; the whole structure is then `json.dumps`'d. - -```sh -DIAL_SDK_LOG_FORMAT=json -DIAL_SDK_JSON_LOG_FORMAT='{"lvl":"%(levelname)s","msg":"%(message)s","where":{"logger":"%(name)s","pid":"%(process)d"}}' -``` - -Console: - -```json -{"lvl": "INFO", "msg": "hello", "where": {"logger": "aidial_sdk.foo", "pid": "13935"}} -``` +`json` renders through a JSON template: a JSON document whose every **string leaf** (at any depth) +is a [`%`-style format string](https://docs.python.org/3/library/logging.html#logrecord-attributes) +interpolated against the record, then `json.dumps`'d (so values are escaped and nesting works). Default: -Default template: - -```json +```txt {"level": "%(levelname)s", "time": "%(asctime)s", "logger": "%(name)s", "process": "%(process)d", "message": "%(message)s"} +→ +{"level": "INFO", "time": "2026-07-16 13:10:41", "logger": "aidial_sdk.foo", "process": "13935", "message": "hello"} ``` -### Plain text - -A plain `%`-style format string (rendered by uvicorn's `DefaultFormatter`, so -`%(levelprefix)s` gives the colored, aligned level). +Override either with the matching variable: ```sh DIAL_SDK_TEXT_LOG_FORMAT='%(levelprefix)s %(name)s: %(message)s' +DIAL_SDK_JSON_LOG_FORMAT='{"lvl":"%(levelname)s","msg":"%(message)s","where":{"logger":"%(name)s"}}' ``` -Default: - -```txt -%(levelprefix)s | %(asctime)s | %(name)s | %(process)d | %(message)s -``` - ---- - ## Reusing the SDK logger in your app -Importing `aidial_sdk` (via `DIALApp`) runs `configure_sdk_logger()` once. By -default it configures **only the SDK's own loggers**: it attaches a single stderr -handler using the env-selected format (`DIAL_SDK_LOG_FORMAT`) to the `aidial_sdk` -and `uvicorn` loggers, sets `aidial_sdk` to `DIAL_SDK_LOG` (default `WARNING`), -and stops `uvicorn` from propagating to the root logger. It does **not** touch the -root logger or your application's loggers. +Importing `aidial_sdk` (via `DIALApp`) runs `configure_sdk_logger()`, which +formats **only** the SDK's own loggers (`aidial_sdk`, `uvicorn`) — not the root +logger or yours. -So to give **your** application's loggers the same formatting — instead of -hand-rolling a formatter and a root handler — call `configure_root_logger()` once -at startup: +To give your loggers the same env-selected format, call `configure_root_logger()` once at startup, **after** `DIALApp()`/telemetry init: ```python import logging -import os from aidial_sdk import DIALApp, configure_root_logger from aidial_sdk.telemetry.types import TelemetryConfig app = DIALApp(telemetry_config=TelemetryConfig(), ...) - -# Install one root handler using the SDK's env-selected format. -# Call AFTER DIALApp()/telemetry init. configure_root_logger() -# You only declare your own loggers' levels: for name in ["app", "bedrock"]: - logging.getLogger(name).setLevel(os.getenv("LOG_LEVEL", "INFO")) + logging.getLogger(name).setLevel("INFO") ``` -Now every logger — the SDK's, uvicorn's, and yours — is emitted through a single -handler that honors `DIAL_SDK_LOG_FORMAT`. Run with `DIAL_SDK_LOG_FORMAT=json` -and your `app`/`bedrock` logs become JSON too, with no code change: +Now every logger emits through one handler honoring `DIAL_SDK_LOG_FORMAT` — run +with `DIAL_SDK_LOG_FORMAT=json` and your `app`/`bedrock` logs become JSON too. -```json -{"level": "INFO", "time": "2026-07-16 13:10:41", "logger": "app", "process": "13935", "message": "hello from the adapter"} -``` - -**What it does:** points the SDK/uvicorn loggers at the root logger and installs -**one** console handler there with the SDK's formatter. It's idempotent. -If root already has a stderr console handler it -didn't install (e.g. one OTEL added via `OTEL_PYTHON_LOG_CORRELATION`), it -**defers** to it and adds nothing — avoiding duplicate lines. In that case the -SDK format doesn't apply to the console, which is one more reason to prefer -Option A over `OTEL_PYTHON_LOG_CORRELATION`. +`configure_root_logger()` is idempotent and does **not** change the root +logger's level (stdlib default `WARNING`) — set levels per logger, as above. -### Log levels +Avoid raising the *root* level to `DEBUG`: it's the fallback for every logger, +so it would enable the chatty, credential-leaking `DEBUG` streams of `httpx`, +`openai`, etc. -`configure_root_logger()` does **not** change the root logger's level (stdlib -default `WARNING`) — it only owns the handler/format. Set levels per logger, as -in the example above. Avoid bumping the **root** level to `DEBUG`: root's level -is the fallback for every logger that hasn't set its own, so it would turn on the -very chatty (and prompt/credential-leaking) `DEBUG` streams of libraries like -`httpx`, `openai`, and `anthropic`. Raise the level only on the loggers you care -about (`app`, `bedrock`, …). - ---- +If root already has a stderr console handler it didn't install +(e.g. OTEL's via `OTEL_PYTHON_LOG_CORRELATION`), it defers to that and adds +nothing — so the SDK format won't apply to the console. ## Trace and span IDs -### Enable tracing - -Trace/span IDs only exist when tracing is on. Enable it by passing a -`TelemetryConfig` to your app **and** selecting the OTLP exporter: +Trace/span IDs exist only when tracing is on. +Enable it with a `TelemetryConfig` **and** the OTLP exporter: ```python -from aidial_sdk import DIALApp -from aidial_sdk.telemetry.types import TelemetryConfig - app = DIALApp(telemetry_config=TelemetryConfig(), ...) # requires aidial-sdk[telemetry] ``` @@ -171,117 +100,67 @@ OTEL_TRACES_EXPORTER=otlp ``` This installs OpenTelemetry's logging instrumentor, which injects these fields -onto **every** log record (populated while a request span is active): +onto **every** record (populated while a request span is active): -| Field | Example | Value with no active span | +| Field | Example | No active span | | --- | --- | --- | | `%(otelTraceID)s` | `4b45f013470528cf753a7e640da7ca1e` | `0` | | `%(otelSpanID)s` | `ffcc9d300d9ab692` | `0` | | `%(otelTraceSampled)s` | `True` | `False` | -| `%(otelServiceName)s` | your `service_name` | always set (`unknown_service` if unconfigured) | +| `%(otelServiceName)s` | your `service_name` | *always set* (`unknown_service` if unconfigured) | -### Tracing in JSON logs +### JSON logs -Nothing to add — the JSON formatter **auto-appends** every `otel*` field present -on the record. So with the default template and tracing on: +The JSON formatter auto-adds every `otel*` field present on the record, so there's no need to amend the format: ```sh DIAL_SDK_LOG_FORMAT=json ``` -Console (inside a request span): - ```json {"level": "INFO", "time": "2026-07-16 13:10:41", "logger": "aidial_sdk", "process": "13935", "message": "hello", "otelTraceID": "4b45f013470528cf753a7e640da7ca1e", "otelSpanID": "ffcc9d300d9ab692", "otelTraceSampled": true, "otelServiceName": "my-service"} ``` -Without tracing, the `otel*` keys are simply absent (no error). - -To rename a field, reference it in your template — the auto-added copy is then -suppressed, so there's no duplicate: +Reference a field in your template to rename it *(the auto-added copy is then suppressed)*: ```sh -DIAL_SDK_JSON_LOG_FORMAT='{"lvl":"%(levelname)s","msg":"%(message)s","trace_id":"%(otelTraceID)s"}' +DIAL_SDK_JSON_LOG_FORMAT='{"level":"%(levelname)s","message":"%(message)s","trace_id":"%(otelTraceID)s"}' ``` -Here the output has your `trace_id` key (not `otelTraceID`), plus the other -`otel*` fields still auto-added (`otelSpanID`, `otelTraceSampled`, -`otelServiceName`). +```json +{"level": "INFO", "message": "hello", "trace_id": "4b45f013470528cf753a7e640da7ca1e", "otelSpanID": "ffcc9d300d9ab692", "otelTraceSampled": true, "otelServiceName": "my-service"} +``` -### Tracing in text logs +### Text logs -**Option A — via `DIAL_SDK_TEXT_LOG_FORMAT`** (recommended for text): add the -placeholders yourself. +The text formatter has no auto-add and no missing-field fallback — add the +placeholders yourself, and only when tracing is guaranteed on (otherwise it +raises `KeyError` and drops the line): ```sh -OTEL_TRACES_EXPORTER=otlp DIAL_SDK_TEXT_LOG_FORMAT='%(levelprefix)s | %(asctime)s | trace_id=%(otelTraceID)s span_id=%(otelSpanID)s | %(message)s' -``` - -Console: - -```txt -INFO: | 2026-07-16 13:10:42 | trace_id=36d9c402fc8b07cd7644bbf2adbbcec8 span_id=61f3846d5d19881b | hello +→ +INFO: | 2026-07-16 13:10:42 | trace_id=36d9c402... span_id=61f3846d... | hello ``` > [!NOTE] -> Unlike JSON, the text formatter has **no missing-field fallback**. If the -> `otel*` fields aren't on the record (i.e. tracing is *not* enabled) it raises a -> `KeyError` and the log line is dropped. Only put `otel*` fields in the text -> format when tracing is guaranteed on. - -**Option B — via `OTEL_PYTHON_LOG_CORRELATION`** — ⚠️ **not recommended.** When -tracing is enabled, setting this makes the OTel instrumentor install its own -root-logger format that already includes trace context, without touching any -`DIAL_SDK_*` variable: - -```sh -OTEL_TRACES_EXPORTER=otlp -OTEL_PYTHON_LOG_CORRELATION=true -``` - -Console: - -```txt -2026-07-16 13:11:45,585 INFO [aidial_sdk.foo] [app.py:12] [trace_id=d67e996e... span_id=02136a2b... resource.service.name=unknown_service trace_sampled=True] - hello -``` - -Override that format with `OTEL_PYTHON_LOG_FORMAT` (default below): - -```txt -%(asctime)s %(levelname)s [%(name)s] [%(filename)s:%(lineno)d] [trace_id=%(otelTraceID)s span_id=%(otelSpanID)s resource.service.name=%(otelServiceName)s trace_sampled=%(otelTraceSampled)s] - %(message)s -``` - -> [!WARNING] -> **Why it's not recommended:** it works by adding a handler to the **root** -> logger. Because the SDK already logs through its own handler — and your -> application most likely configures logging itself too — that root handler emits -> a **duplicate** line for every record (double logging). It also can't produce -> JSON (`OTEL_PYTHON_LOG_FORMAT` has no escaping) and breaks -> `DIAL_SDK_LOG_FORMAT=json` (you'd get one JSON line plus one text line per -> record). Use Option A instead. - ---- +> `OTEL_PYTHON_LOG_CORRELATION=true` is an alternative that makes OTel add its +> own root-logger handler with trace context built in — but it double-logs (a +> duplicate line per record), can't produce JSON, and breaks +> `DIAL_SDK_LOG_FORMAT=json`. Prefer the approach above. ## Summary -| Goal | What to set | +| Goal | Set | | --- | --- | | JSON console | `DIAL_SDK_LOG_FORMAT=json` | -| Customize JSON | `DIAL_SDK_JSON_LOG_FORMAT='{…}'` | -| Customize text | `DIAL_SDK_TEXT_LOG_FORMAT='…'` | -| Trace/span in JSON | just enable tracing — `otel*` fields are auto-added to the JSON output (reference them in the template only to rename) | -| Trace/span in text | enable tracing + add them to `DIAL_SDK_TEXT_LOG_FORMAT` (Option A, recommended). `OTEL_PYTHON_LOG_CORRELATION=true` (Option B) also works but double-logs — avoid. | - -**Key difference:** in JSON the `otel*` fields are auto-added whenever tracing is -on (and simply absent otherwise); in text you must add them manually and they -require tracing to be enabled. - ---- +| Customize JSON / text | `DIAL_SDK_JSON_LOG_FORMAT` / `DIAL_SDK_TEXT_LOG_FORMAT` | +| Trace/span in JSON | enable tracing | +| Trace/span in text | enable tracing + add `otel*` placeholders to `DIAL_SDK_TEXT_LOG_FORMAT` | ## OTLP log export `OTEL_LOGS_EXPORTER=otlp` ships log records to an OTLP collector as structured -data (trace context attached automatically). That pipeline uses no format string, -so none of the `*_LOG_FORMAT` variables above apply to it — they only affect what -is printed to the console. +data (trace context attached automatically). That pipeline uses no format +string, so the `*_LOG_FORMAT` variables don't affect it — they only control +console output. From af47fa01409fec3e4bc917fe41adaa1a4aa29e11 Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Thu, 16 Jul 2026 17:00:04 +0100 Subject: [PATCH 12/20] chore: document OTEL_PYTHON_LOG_CORRELATION --- docs/logging.md | 30 +++++++++++++++++++++++++----- 1 file changed, 25 insertions(+), 5 deletions(-) diff --git a/docs/logging.md b/docs/logging.md index 9c8184e7..f0ffd9d0 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -11,6 +11,7 @@ You pick the **format** (human-readable text or single-line JSON), customize it, - [Trace and span IDs](#trace-and-span-ids) - [JSON logs](#json-logs) - [Text logs](#text-logs) + - [Legacy alternative](#legacy-alternative) - [Summary](#summary) - [OTLP log export](#otlp-log-export) @@ -143,11 +144,30 @@ DIAL_SDK_TEXT_LOG_FORMAT='%(levelprefix)s | %(asctime)s | trace_id=%(otelTraceID INFO: | 2026-07-16 13:10:42 | trace_id=36d9c402... span_id=61f3846d... | hello ``` -> [!NOTE] -> `OTEL_PYTHON_LOG_CORRELATION=true` is an alternative that makes OTel add its -> own root-logger handler with trace context built in — but it double-logs (a -> duplicate line per record), can't produce JSON, and breaks -> `DIAL_SDK_LOG_FORMAT=json`. Prefer the approach above. +#### Legacy alternative + +`OTEL_PYTHON_LOG_CORRELATION=true` is OTel's own way to add trace context to text +logs, with a built-in format overridable via `OTEL_PYTHON_LOG_FORMAT`: + +```sh +OTEL_PYTHON_LOG_CORRELATION=true +OTEL_PYTHON_LOG_FORMAT='%(asctime)s %(levelname)s trace_id=%(otelTraceID)s - %(message)s' +→ +2026-07-16 13:11:45,585 INFO trace_id=d67e996e... - hello +``` + +When `OTEL_PYTHON_LOG_FORMAT` isn't set, the [default](https://github.com/open-telemetry/opentelemetry-python-contrib/blob/v0.43b0/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/constants.py#L15) is: + +```txt +%(asctime)s %(levelname)s [%(name)s] [%(filename)s:%(lineno)d] [trace_id=%(otelTraceID)s span_id=%(otelSpanID)s resource.service.name=%(otelServiceName)s trace_sampled=%(otelTraceSampled)s] - %(message)s +→ +2026-07-16 13:11:45,585 INFO [aidial_sdk.foo] [app.py:12] [trace_id=d67e996e... span_id=02136a2b... resource.service.name=unknown_service trace_sampled=True] - hello +``` + +> [!WARNING] +> Prefer `DIAL_SDK_TEXT_LOG_FORMAT`. `OTEL_PYTHON_LOG_CORRELATION` logs every SDK +> record twice (unless `configure_root_logger()` is called) and is text-only +> (ignores `DIAL_SDK_LOG_FORMAT=json`). ## Summary From 8bc61e4d915c7bddf3cc6cc58da9cdd34c096582 Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Thu, 16 Jul 2026 17:10:08 +0100 Subject: [PATCH 13/20] feat: add deprecation warning --- aidial_sdk/telemetry/init.py | 12 +++++++----- aidial_sdk/telemetry/types.py | 6 ++++++ aidial_sdk/utils/_deprecations.py | 16 ++++++++++++++++ 3 files changed, 29 insertions(+), 5 deletions(-) create mode 100644 aidial_sdk/utils/_deprecations.py diff --git a/aidial_sdk/telemetry/init.py b/aidial_sdk/telemetry/init.py index 5e27e40f..db4458c0 100644 --- a/aidial_sdk/telemetry/init.py +++ b/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,7 +79,11 @@ def init_telemetry( except ImportError: pass - # Inject otel* tracing fields onto every log record. + # 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: + warn_otel_log_correlation() LoggingInstrumentor().instrument() if config.logs is not None: diff --git a/aidial_sdk/telemetry/types.py b/aidial_sdk/telemetry/types.py index b1c48b2c..e741e48d 100644 --- a/aidial_sdk/telemetry/types.py +++ b/aidial_sdk/telemetry/types.py @@ -13,6 +13,9 @@ OTEL_EXPORTER_PROMETHEUS_PORT = int( os.getenv("OTEL_EXPORTER_PROMETHEUS_PORT", 9464) ) +OTEL_PYTHON_LOG_CORRELATION = ( + os.getenv("OTEL_PYTHON_LOG_CORRELATION", "false").lower() == "true" +) class LogsConfig(BaseModel): @@ -23,6 +26,9 @@ class LogsConfig(BaseModel): class TracingConfig(BaseModel): otlp_export: bool = "otlp" in OTEL_TRACES_EXPORTER + """Deprecated: let OTel add tracing context to console logs. See docs/logging.md.""" + logging: bool = OTEL_PYTHON_LOG_CORRELATION + class MetricsConfig(BaseModel): otlp_export: bool = "otlp" in OTEL_METRICS_EXPORTER diff --git a/aidial_sdk/utils/_deprecations.py b/aidial_sdk/utils/_deprecations.py new file mode 100644 index 00000000..7a25ad51 --- /dev/null +++ b/aidial_sdk/utils/_deprecations.py @@ -0,0 +1,16 @@ +import warnings + +_LOGGING_DOC = ( + "https://github.com/epam/ai-dial-sdk/blob/development/docs/logging.md" +) + + +def warn_otel_log_correlation() -> None: + warnings.warn( + "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}.", + DeprecationWarning, + stacklevel=2, + ) From eaee79faffcaa96832da41ec29ab1682a295c9c2 Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Thu, 16 Jul 2026 17:20:27 +0100 Subject: [PATCH 14/20] feat: minor fixes --- aidial_sdk/utils/env.py | 4 ++-- aidial_sdk/utils/log_config.py | 1 - tests/test_env.py | 16 +++++++++++++++- 3 files changed, 17 insertions(+), 4 deletions(-) diff --git a/aidial_sdk/utils/env.py b/aidial_sdk/utils/env.py index 99eb55ad..3a297897 100644 --- a/aidial_sdk/utils/env.py +++ b/aidial_sdk/utils/env.py @@ -26,8 +26,8 @@ def env_json_dict(name: str, default: dict) -> dict: if not isinstance(obj, dict): raise ValueError("the object isn't a dictionary") return obj - except Exception as e: + except Exception: raise ValueError( - f"The value of the {name!r} environment variable is expected to be a valid JSON dictionary: {e}." + f"The value of the {name!r} environment variable is expected to be a valid JSON dictionary." ) return default diff --git a/aidial_sdk/utils/log_config.py b/aidial_sdk/utils/log_config.py index 5b8bd4ac..e17587bd 100644 --- a/aidial_sdk/utils/log_config.py +++ b/aidial_sdk/utils/log_config.py @@ -29,7 +29,6 @@ def build_formatter() -> logging.Formatter: - """The console formatter selected by ``DIAL_SDK_LOG_FORMAT`` (text or json).""" if _DIAL_SDK_LOG_FORMAT == "json": return JsonLogFormatter( template=_DIAL_SDK_JSON_LOG_FORMAT, datefmt=_DATEFMT diff --git a/tests/test_env.py b/tests/test_env.py index 5a9ef2cb..9a28a6c7 100644 --- a/tests/test_env.py +++ b/tests/test_env.py @@ -15,5 +15,19 @@ def test_env_json_dict_falls_back_to_default(monkeypatch): def test_env_json_dict_rejects_non_dict(monkeypatch): monkeypatch.setenv("X", "[1, 2]") - with pytest.raises(ValueError): + with pytest.raises(ValueError) as exc: env_json_dict("X", {}) + assert str(exc.value) == ( + "The value of the 'X' environment variable is expected to be a " + "valid JSON dictionary." + ) + + +def test_env_json_dict_rejects_invalid_json(monkeypatch): + monkeypatch.setenv("X", "{not json}") + with pytest.raises(ValueError) as exc: + env_json_dict("X", {}) + assert str(exc.value) == ( + "The value of the 'X' environment variable is expected to be a " + "valid JSON dictionary." + ) From ba6fc0a889ecc5219f3117efa3f6e3b32c92df59 Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Thu, 16 Jul 2026 17:28:46 +0100 Subject: [PATCH 15/20] chore: accept fix from github bot Co-authored-by: Copilot Autofix powered by AI <223894421+github-code-quality[bot]@users.noreply.github.com> --- aidial_sdk/application.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/aidial_sdk/application.py b/aidial_sdk/application.py index 4d7588f1..272d13df 100644 --- a/aidial_sdk/application.py +++ b/aidial_sdk/application.py @@ -2,7 +2,6 @@ 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 @@ -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()) From 4544657640a3f46e760c1be64480ebaa5a8ab947 Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Fri, 17 Jul 2026 11:46:53 +0100 Subject: [PATCH 16/20] feat: extract LogConfig with typed env-var overrides Move the DIAL_SDK_LOG* resolution into a public LogConfig class whose typed keyword args take precedence over the env vars (each unset arg falls back to its env var / default), mirroring LoggingInstrumentor. configure_root_logger() accepts a LogConfig to override the env vars in code. Co-Authored-By: Claude Opus 4.8 (1M context) --- aidial_sdk/__init__.py | 10 +++- aidial_sdk/utils/log_config.py | 104 ++++++++++++++++++++------------- docs/logging.md | 3 + tests/test_log_config.py | 63 ++++++++++++++++++++ 4 files changed, 138 insertions(+), 42 deletions(-) create mode 100644 tests/test_log_config.py diff --git a/aidial_sdk/__init__.py b/aidial_sdk/__init__.py index 2d16c9d8..77c2688d 100644 --- a/aidial_sdk/__init__.py +++ b/aidial_sdk/__init__.py @@ -1,6 +1,12 @@ from aidial_sdk.application import DIALApp from aidial_sdk.exceptions import HTTPException -from aidial_sdk.utils.log_config import configure_root_logger +from aidial_sdk.utils.log_config import LogConfig, configure_root_logger from aidial_sdk.utils.logging import logger -__all__ = ["DIALApp", "HTTPException", "configure_root_logger", "logger"] +__all__ = [ + "DIALApp", + "HTTPException", + "LogConfig", + "configure_root_logger", + "logger", +] diff --git a/aidial_sdk/utils/log_config.py b/aidial_sdk/utils/log_config.py index e17587bd..d31f45fc 100644 --- a/aidial_sdk/utils/log_config.py +++ b/aidial_sdk/utils/log_config.py @@ -1,53 +1,74 @@ import logging import os import sys +from typing import Literal from uvicorn.logging import DefaultFormatter from aidial_sdk.utils._json_log_formatter import JsonLogFormatter from aidial_sdk.utils.env import env_json_dict -DIAL_SDK_LOG = os.environ.get("DIAL_SDK_LOG", "WARNING").upper() - -_DIAL_SDK_LOG_FORMAT = os.environ.get("DIAL_SDK_LOG_FORMAT", "text").lower() -_DIAL_SDK_TEXT_LOG_FORMAT = os.environ.get( - "DIAL_SDK_TEXT_LOG_FORMAT", - "%(levelprefix)s | %(asctime)s | %(name)s | %(process)d | %(message)s", -) -_DIAL_SDK_JSON_LOG_FORMAT = env_json_dict( - "DIAL_SDK_JSON_LOG_FORMAT", - { - "level": "%(levelname)s", - "time": "%(asctime)s", - "logger": "%(name)s", - "process": "%(process)d", - "message": "%(message)s", - }, -) - _DATEFMT = "%Y-%m-%d %H:%M:%S" - -def build_formatter() -> logging.Formatter: - if _DIAL_SDK_LOG_FORMAT == "json": - return JsonLogFormatter( - template=_DIAL_SDK_JSON_LOG_FORMAT, datefmt=_DATEFMT - ) - return DefaultFormatter( - fmt=_DIAL_SDK_TEXT_LOG_FORMAT, datefmt=_DATEFMT, use_colors=True - ) - - -def configure_root_logger() -> None: +_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 env-selected format (``DIAL_SDK_LOG_FORMAT=text|json``), so - the application's own loggers get the SDK's formatting too. - - Idempotent; call once at startup, after ``DIALApp()``/telemetry init. Leaves - the root level untouched (stdlib default ``WARNING``) — set per-logger levels - yourself. If root already has a stderr console handler this function did not - install (e.g. OTEL's via ``OTEL_PYTHON_LOG_CORRELATION``), it defers to it. + 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. + + Idempotent; call once at startup, after ``DIALApp()``/telemetry init. Sets + the ``aidial_sdk`` logger to ``config.level`` but leaves the root and uvicorn + levels untouched — set your own loggers' levels yourself. If root already has + a stderr console handler this function did not install (e.g. OTEL's via + ``OTEL_PYTHON_LOG_CORRELATION``), it defers to it. """ + config = config or LogConfig() root = logging.getLogger() _MARKER = "_aidial_sdk_console_handler" @@ -62,7 +83,7 @@ def configure_root_logger() -> None: ) if not has_console_handler: handler = logging.StreamHandler(sys.stderr) - handler.setFormatter(build_formatter()) + handler.setFormatter(config.formatter) setattr(handler, _MARKER, True) root.addHandler(handler) @@ -71,17 +92,20 @@ def configure_root_logger() -> None: 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(build_formatter()) + handler.setFormatter(config.formatter) aidial_sdk = logging.getLogger("aidial_sdk") aidial_sdk.handlers = [handler] - aidial_sdk.setLevel(DIAL_SDK_LOG) + aidial_sdk.setLevel(config.level) uvicorn = logging.getLogger("uvicorn") uvicorn.handlers = [handler] diff --git a/docs/logging.md b/docs/logging.md index f0ffd9d0..94e43686 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -76,6 +76,9 @@ for name in ["app", "bedrock"]: Now every logger emits through one handler honoring `DIAL_SDK_LOG_FORMAT` — run with `DIAL_SDK_LOG_FORMAT=json` and your `app`/`bedrock` logs become JSON too. +To set any of these in code (overriding the `DIAL_SDK_LOG*` env vars), pass a +`LogConfig` — `configure_root_logger(LogConfig(log_format="json"))`. + `configure_root_logger()` is idempotent and does **not** change the root logger's level (stdlib default `WARNING`) — set levels per logger, as above. diff --git a/tests/test_log_config.py b/tests/test_log_config.py new file mode 100644 index 00000000..68d389c9 --- /dev/null +++ b/tests/test_log_config.py @@ -0,0 +1,63 @@ +import json +import logging +import sys + +import pytest +from uvicorn.logging import DefaultFormatter + +from aidial_sdk.utils._json_log_formatter import JsonLogFormatter +from aidial_sdk.utils.log_config import LogConfig, configure_root_logger + + +def test_arguments_override_env(monkeypatch): + monkeypatch.setenv("DIAL_SDK_LOG", "warning") + monkeypatch.setenv("DIAL_SDK_LOG_FORMAT", "text") + + config = LogConfig(level="debug", log_format="json") + + assert config.level == "DEBUG" # normalized upper + assert isinstance(config.formatter, JsonLogFormatter) + + +def test_falls_back_to_env_and_normalizes_case(monkeypatch): + monkeypatch.setenv("DIAL_SDK_LOG", "error") + monkeypatch.setenv("DIAL_SDK_LOG_FORMAT", "JSON") + + config = LogConfig() + + assert config.level == "ERROR" # normalized upper + assert isinstance(config.formatter, JsonLogFormatter) # normalized lower + + +def test_text_format_builds_default_formatter(): + assert isinstance(LogConfig(log_format="text").formatter, DefaultFormatter) + + +def test_json_format_argument_wins_over_env(monkeypatch): + monkeypatch.setenv("DIAL_SDK_JSON_LOG_FORMAT", '{"env": "%(message)s"}') + + config = LogConfig(log_format="json", json_format={"arg": "%(message)s"}) + record = logging.makeLogRecord({"msg": "hi"}) + + assert json.loads(config.formatter.format(record)) == {"arg": "hi"} + + +@pytest.fixture +def clean_root(): + root = logging.getLogger() + saved_handlers, saved_level = root.handlers[:], root.level + root.handlers = [] + yield root + root.handlers, root.level = saved_handlers, saved_level + + +def test_configure_root_logger_uses_passed_config(clean_root): + configure_root_logger(LogConfig(log_format="json")) + + console = [ + h + for h in clean_root.handlers + if getattr(h, "stream", None) is sys.stderr + ] + assert len(console) == 1 + assert isinstance(console[0].formatter, JsonLogFormatter) From 2763aec86cd783048cd556248967e62067219f01 Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Fri, 17 Jul 2026 11:49:52 +0100 Subject: [PATCH 17/20] chore: fix package version --- pyproject.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pyproject.toml b/pyproject.toml index 578a297c..97475c91 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -1,6 +1,6 @@ [project] name = "aidial-sdk" -version = "0.0.0" +version = "0.37.0" description = "Framework to create applications and model adapters for AI DIAL" authors = [{ name = "EPAM RAIL", email = "SpecialEPM-DIALDevTeam@epam.com" }] license = "Apache-2.0" From b5c46a0e4af28c5e37b9b8039787b2e15333a863 Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Fri, 17 Jul 2026 12:23:15 +0100 Subject: [PATCH 18/20] feat: support third-party loggers --- aidial_sdk/utils/log_config.py | 28 ++++++++++------------------ docs/logging.md | 8 +++++--- tests/test_configure_root_logger.py | 20 +++++++++++++++++--- 3 files changed, 32 insertions(+), 24 deletions(-) diff --git a/aidial_sdk/utils/log_config.py b/aidial_sdk/utils/log_config.py index d31f45fc..7df98f6e 100644 --- a/aidial_sdk/utils/log_config.py +++ b/aidial_sdk/utils/log_config.py @@ -5,6 +5,7 @@ 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 @@ -61,30 +62,20 @@ 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. - - Idempotent; call once at startup, after ``DIALApp()``/telemetry init. Sets - the ``aidial_sdk`` logger to ``config.level`` but leaves the root and uvicorn - levels untouched — set your own loggers' levels yourself. If root already has - a stderr console handler this function did not install (e.g. OTEL's via - ``OTEL_PYTHON_LOG_CORRELATION``), it defers to it. """ + config = config or LogConfig() root = logging.getLogger() - _MARKER = "_aidial_sdk_console_handler" - root.handlers = [h for h in root.handlers if not getattr(h, _MARKER, False)] - - # Defer to a stderr console handler already on root (e.g. OTEL's) rather - # than adding a second one that would duplicate every line. - has_console_handler = any( - isinstance(h, logging.StreamHandler) - and getattr(h, "stream", None) is sys.stderr - for h in root.handlers - ) - if not has_console_handler: + # 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) - setattr(handler, _MARKER, True) root.addHandler(handler) for name in ("aidial_sdk", "uvicorn", "uvicorn.access", "uvicorn.error"): @@ -99,6 +90,7 @@ 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) diff --git a/docs/logging.md b/docs/logging.md index 94e43686..49a70598 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -86,9 +86,11 @@ Avoid raising the *root* level to `DEBUG`: it's the fallback for every logger, so it would enable the chatty, credential-leaking `DEBUG` streams of `httpx`, `openai`, etc. -If root already has a stderr console handler it didn't install -(e.g. OTEL's via `OTEL_PYTHON_LOG_CORRELATION`), it defers to that and adds -nothing — so the SDK format won't apply to the console. +It **takes over** the console: any existing stderr console handler on root is +dropped — including the one `logging.basicConfig()` installs via `ANTHROPIC_LOG` +/ `OPENAI_LOG` — so third-party logs render in the SDK format too. +The one exception is `OTEL_PYTHON_LOG_CORRELATION`, whose handler it +defers to instead. ## Trace and span IDs diff --git a/tests/test_configure_root_logger.py b/tests/test_configure_root_logger.py index 0a66e945..66283bc8 100644 --- a/tests/test_configure_root_logger.py +++ b/tests/test_configure_root_logger.py @@ -40,12 +40,26 @@ def test_idempotent_and_preserves_other_handlers(clean_root): assert other in clean_root.handlers -def test_defers_to_existing_stderr_console_handler(clean_root): - # Stand-in for OTEL's basicConfig console handler on root. +def test_takes_over_foreign_stderr_console_handler(clean_root): + # Stand-in for the basicConfig handler ANTHROPIC_LOG/OPENAI_LOG install. + foreign = logging.StreamHandler(sys.stderr) + clean_root.addHandler(foreign) + + configure_root_logger() + + # Foreign handler dropped; ours is the only console handler. + assert len(_stderr_console_handlers(clean_root)) == 1 + assert foreign not in clean_root.handlers + + +def test_defers_to_otel_correlation_handler(clean_root, monkeypatch): + monkeypatch.setattr( + "aidial_sdk.utils.log_config.OTEL_PYTHON_LOG_CORRELATION", True + ) otel_console = logging.StreamHandler(sys.stderr) clean_root.addHandler(otel_console) configure_root_logger() - # We do not add our own; OTEL's stays as the only console handler. + # OTEL owns the console format; we defer and leave its handler alone. assert _stderr_console_handlers(clean_root) == [otel_console] From 20ec117ef0e0453cfa2951acc92d0730baeedda9 Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Fri, 17 Jul 2026 12:42:40 +0100 Subject: [PATCH 19/20] feat: replace warning with a logger warning --- aidial_sdk/utils/_deprecations.py | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) diff --git a/aidial_sdk/utils/_deprecations.py b/aidial_sdk/utils/_deprecations.py index 7a25ad51..ff83e1dc 100644 --- a/aidial_sdk/utils/_deprecations.py +++ b/aidial_sdk/utils/_deprecations.py @@ -1,4 +1,4 @@ -import warnings +from aidial_sdk.utils.logging import logger _LOGGING_DOC = ( "https://github.com/epam/ai-dial-sdk/blob/development/docs/logging.md" @@ -6,11 +6,9 @@ def warn_otel_log_correlation() -> None: - warnings.warn( + 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}.", - DeprecationWarning, - stacklevel=2, + f"instead — see {_LOGGING_DOC}." ) From 80d34f84461aeab886e327301e99ddde9558b27f Mon Sep 17 00:00:00 2001 From: Anton Dubovik Date: Fri, 17 Jul 2026 15:24:58 +0100 Subject: [PATCH 20/20] feat: review fix --- aidial_sdk/utils/_json_log_formatter.py | 18 +++++++++++------- 1 file changed, 11 insertions(+), 7 deletions(-) diff --git a/aidial_sdk/utils/_json_log_formatter.py b/aidial_sdk/utils/_json_log_formatter.py index 572508ea..647da21f 100644 --- a/aidial_sdk/utils/_json_log_formatter.py +++ b/aidial_sdk/utils/_json_log_formatter.py @@ -19,13 +19,17 @@ def __init__(self, template: dict, datefmt: str | None = None) -> None: self._template_str = template_str def _interpolate(self, node: object, fields: dict) -> object: - if isinstance(node, str): - return node % fields - if isinstance(node, dict): - return {k: self._interpolate(v, fields) for k, v in node.items()} - if isinstance(node, list): - return [self._interpolate(v, fields) for v in node] - return node + 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()