diff --git a/README.md b/README.md index 04cce58f..a98f0444 100644 --- a/README.md +++ b/README.md @@ -47,11 +47,12 @@ Applications and model adapters implemented using this framework will be compati |Variable|Default|Description| |---|---|---| -|DIAL_SDK_LOG|WARNING|DIAL SDK log level| |DIAL_SDK_HEADERS_TO_PROXY|``|A comma-separated list of headers that should be proxied from incoming requests to outgoing requests to the DIAL API. By default, no headers are proxied.| |DIAL_SDK_SSE_HEARTBEAT_INTERVAL||When set, the SDK inserts ping comments into streaming chat completion responses after the response has been idle for the specified number of seconds, helping prevent read timeouts when the DIAL application isn't responsive.| |PYDANTIC_V2|False|When `True` and Pydantic V2 is installed, DIAL SDK classes for requests/responses will be based on Pydantic V2 `BaseModel`. Otherwise, they will be based on Pydantic V1 `BaseModel`.| +Logging-related environment variables (log level, console format, and trace/span correlation) are documented in [docs/logging.md](docs/logging.md). + --- ## Usage diff --git a/aidial_sdk/__init__.py b/aidial_sdk/__init__.py index 1485a407..77c2688d 100644 --- a/aidial_sdk/__init__.py +++ b/aidial_sdk/__init__.py @@ -1,5 +1,12 @@ from aidial_sdk.application import DIALApp from aidial_sdk.exceptions import HTTPException +from aidial_sdk.utils.log_config import LogConfig, configure_root_logger from aidial_sdk.utils.logging import logger -__all__ = ["DIALApp", "HTTPException", "logger"] +__all__ = [ + "DIALApp", + "HTTPException", + "LogConfig", + "configure_root_logger", + "logger", +] diff --git a/aidial_sdk/application.py b/aidial_sdk/application.py index 0481746b..272d13df 100644 --- a/aidial_sdk/application.py +++ b/aidial_sdk/application.py @@ -1,8 +1,7 @@ -import logging.config +import logging import re import warnings from collections.abc import Callable, Coroutine -from logging import Filter, LogRecord from typing import Any, Literal, TypeVar from fastapi import FastAPI, HTTPException, Request @@ -33,7 +32,7 @@ from aidial_sdk.utils._disconnect_middleware import DisconnectMiddleware from aidial_sdk.utils._reflection import get_method_implementation from aidial_sdk.utils.env import env_float, env_var_list -from aidial_sdk.utils.log_config import LogConfig +from aidial_sdk.utils.log_config import configure_sdk_logger from aidial_sdk.utils.logging import log_debug, set_log_deployment from aidial_sdk.utils.pydantic import model_validate_extra_fields from aidial_sdk.utils.streaming import ( @@ -42,7 +41,7 @@ to_streaming_response, ) -logging.config.dictConfig(LogConfig().model_dump()) +configure_sdk_logger() RequestType = TypeVar("RequestType", bound=FromRequestMixin) @@ -57,14 +56,14 @@ def _interpolate_deployment_id(deployment_id: str, path_params: dict) -> str: return result -class PathFilter(Filter): +class PathFilter(logging.Filter): path: str def __init__(self, path: str) -> None: super().__init__(name="") self.path = path - def filter(self, record: LogRecord): + def filter(self, record: logging.LogRecord): return not re.search(f"(\\s+){self.path}(\\s+)", record.getMessage()) diff --git a/aidial_sdk/telemetry/init.py b/aidial_sdk/telemetry/init.py index 600690c3..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,10 +79,12 @@ def init_telemetry( except ImportError: pass + # Inject otel* tracing fields onto every log record. When + # OTEL_PYTHON_LOG_CORRELATION=true, instrument() also installs OTel's + # own root-logger format (the deprecated path). if config.tracing.logging: - # Setting the root logger format in order to include - # tracing information: span_id, trace_id - LoggingInstrumentor().instrument(set_logging_format=True) + warn_otel_log_correlation() + LoggingInstrumentor().instrument() if config.logs is not None: # Adding a handler to the root logger which exports the logs to OTLP diff --git a/aidial_sdk/telemetry/types.py b/aidial_sdk/telemetry/types.py index ebe1718f..e741e48d 100644 --- a/aidial_sdk/telemetry/types.py +++ b/aidial_sdk/telemetry/types.py @@ -26,8 +26,7 @@ class LogsConfig(BaseModel): class TracingConfig(BaseModel): otlp_export: bool = "otlp" in OTEL_TRACES_EXPORTER - """Configure logging to include tracing context - into console log messages""" + """Deprecated: let OTel add tracing context to console logs. See docs/logging.md.""" logging: bool = OTEL_PYTHON_LOG_CORRELATION diff --git a/aidial_sdk/utils/_deprecations.py b/aidial_sdk/utils/_deprecations.py new file mode 100644 index 00000000..ff83e1dc --- /dev/null +++ b/aidial_sdk/utils/_deprecations.py @@ -0,0 +1,14 @@ +from aidial_sdk.utils.logging import logger + +_LOGGING_DOC = ( + "https://github.com/epam/ai-dial-sdk/blob/development/docs/logging.md" +) + + +def warn_otel_log_correlation() -> None: + logger.warning( + "OTEL_PYTHON_LOG_CORRELATION=true is not the recommended way to add " + "trace context to console logs: it double-logs SDK records and cannot " + "produce JSON. Use DIAL_SDK_TEXT_LOG_FORMAT (with otel* placeholders) " + f"instead — see {_LOGGING_DOC}." + ) diff --git a/aidial_sdk/utils/_json_log_formatter.py b/aidial_sdk/utils/_json_log_formatter.py new file mode 100644 index 00000000..647da21f --- /dev/null +++ b/aidial_sdk/utils/_json_log_formatter.py @@ -0,0 +1,56 @@ +import json +import logging +from collections import defaultdict + + +class JsonLogFormatter(logging.Formatter): + """Render a record through a JSON template whose string leaves are + `%`-format strings, then `json.dumps` the result (escaping every value). + + Any ``otel*`` field on the record (injected by the OTel logging instrumentor + when tracing is on) is auto-added to the output, unless the template already + references it under some key (e.g. ``{"trace_id": "%(otelTraceID)s"}``).""" + + def __init__(self, template: dict, datefmt: str | None = None) -> None: + super().__init__(datefmt=datefmt) + self._template = template + template_str = json.dumps(template) + self._uses_time = "%(asctime)" in template_str + self._template_str = template_str + + def _interpolate(self, node: object, fields: dict) -> object: + match node: + case str(): + return node % fields + case dict(): + return { + k: self._interpolate(v, fields) for k, v in node.items() + } + case list(): + return [self._interpolate(v, fields) for v in node] + case _: + return node + + def format(self, record: logging.LogRecord) -> str: + record.message = record.getMessage() + if self._uses_time: + record.asctime = self.formatTime(record, self.datefmt) + + # Expose the traceback via %(exc_text)s, escaped like any other value. + if record.exc_info and not record.exc_text: + record.exc_text = self.formatException(record.exc_info) + + # defaultdict(str): a missing field renders as "" instead of raising. + rendered = self._interpolate( + self._template, defaultdict(str, record.__dict__) + ) + + if isinstance(rendered, dict): + for key, value in record.__dict__.items(): + if ( + key.startswith("otel") + and f"%({key})" not in self._template_str + ): + rendered.setdefault(key, value) + + return json.dumps(rendered, ensure_ascii=False, default=str) diff --git a/aidial_sdk/utils/env.py b/aidial_sdk/utils/env.py index 61f90e44..3a297897 100644 --- a/aidial_sdk/utils/env.py +++ b/aidial_sdk/utils/env.py @@ -1,3 +1,4 @@ +import json import os @@ -16,3 +17,17 @@ def env_var_list(name: str) -> list[str]: if value is None: return [] return value.split(",") + + +def env_json_dict(name: str, default: dict) -> dict: + if (value := os.getenv(name)) is not None: + try: + obj = json.loads(value) + if not isinstance(obj, dict): + raise ValueError("the object isn't a dictionary") + return obj + except Exception: + raise ValueError( + f"The value of the {name!r} environment variable is expected to be a valid JSON dictionary." + ) + return default diff --git a/aidial_sdk/utils/log_config.py b/aidial_sdk/utils/log_config.py index 89a7b3e6..7df98f6e 100644 --- a/aidial_sdk/utils/log_config.py +++ b/aidial_sdk/utils/log_config.py @@ -1,34 +1,104 @@ +import logging import os +import sys +from typing import Literal -from aidial_sdk._pydantic._compat import BaseModel - -DIAL_SDK_LOG = os.environ.get("DIAL_SDK_LOG", "WARNING").upper() - - -class LogConfig(BaseModel): - """Logging configuration to be set for the server""" - - version: int = 1 - disable_existing_loggers: bool = False - formatters: dict = { - "default": { - "()": "uvicorn.logging.DefaultFormatter", - "fmt": "%(levelprefix)s | %(asctime)s | %(name)s | %(process)d | %(message)s", - "datefmt": "%Y-%m-%d %H:%M:%S", - "use_colors": True, - }, - } - handlers: dict = { - "default": { - "formatter": "default", - "class": "logging.StreamHandler", - "stream": "ext://sys.stderr", - }, - } - loggers: dict = { - "aidial_sdk": {"handlers": ["default"], "level": DIAL_SDK_LOG}, - "uvicorn": { - "handlers": ["default"], - "propagate": False, - }, - } +from uvicorn.logging import DefaultFormatter + +from aidial_sdk.telemetry.types import OTEL_PYTHON_LOG_CORRELATION +from aidial_sdk.utils._json_log_formatter import JsonLogFormatter +from aidial_sdk.utils.env import env_json_dict + +_DATEFMT = "%Y-%m-%d %H:%M:%S" + +_DEFAULT_TEXT_FORMAT = ( + "%(levelprefix)s | %(asctime)s | %(name)s | %(process)d | %(message)s" +) +_DEFAULT_JSON_FORMAT = { + "level": "%(levelname)s", + "time": "%(asctime)s", + "logger": "%(name)s", + "process": "%(process)d", + "message": "%(message)s", +} + + +class LogConfig: + level: str + formatter: logging.Formatter + + def __init__( + self, + *, + level: str | None = None, + log_format: Literal["text", "json"] | None = None, + text_format: str | None = None, + json_format: dict | None = None, + ) -> None: + self.level = ( + level or os.environ.get("DIAL_SDK_LOG", "WARNING") + ).upper() + resolved_format = ( + log_format or os.environ.get("DIAL_SDK_LOG_FORMAT", "text") + ).lower() + + if resolved_format == "json": + json_format = json_format or env_json_dict( + "DIAL_SDK_JSON_LOG_FORMAT", _DEFAULT_JSON_FORMAT + ) + self.formatter = JsonLogFormatter( + template=json_format, datefmt=_DATEFMT + ) + else: + text_format = text_format or os.getenv( + "DIAL_SDK_TEXT_LOG_FORMAT", _DEFAULT_TEXT_FORMAT + ) + self.formatter = DefaultFormatter( + fmt=text_format, datefmt=_DATEFMT, use_colors=True + ) + + +def configure_root_logger(config: LogConfig | None = None) -> None: + """Route all logging through a single console handler on the root logger, + using the SDK's format, so the application's own loggers get it too. Pass a + ``LogConfig`` to override the ``DIAL_SDK_LOG*`` env vars. + """ + + config = config or LogConfig() + root = logging.getLogger() + + # OTEL_PYTHON_LOG_CORRELATION installs OTEL's own root console format; defer + # to it. Otherwise take over — drop competing stderr handlers (e.g. the + # basicConfig one from ANTHROPIC_LOG) and install ours. + if not OTEL_PYTHON_LOG_CORRELATION: + for h in root.handlers[:]: + if isinstance(h, logging.StreamHandler) and h.stream is sys.stderr: + root.removeHandler(h) + handler = logging.StreamHandler(sys.stderr) + handler.setFormatter(config.formatter) + root.addHandler(handler) + + for name in ("aidial_sdk", "uvicorn", "uvicorn.access", "uvicorn.error"): + child = logging.getLogger(name) + child.handlers = [] + child.propagate = True + + logging.getLogger("aidial_sdk").setLevel(config.level) + + +def configure_sdk_logger() -> None: + """Configure only the SDK's own loggers (``aidial_sdk``, ``uvicorn``), called + once when ``DIALApp`` is imported. To format your own loggers the same way, + call ``configure_root_logger()``.""" + + config = LogConfig() + handler = logging.StreamHandler(sys.stderr) + handler.setFormatter(config.formatter) + + aidial_sdk = logging.getLogger("aidial_sdk") + aidial_sdk.handlers = [handler] + aidial_sdk.setLevel(config.level) + + uvicorn = logging.getLogger("uvicorn") + uvicorn.handlers = [handler] + uvicorn.propagate = False diff --git a/docs/logging.md b/docs/logging.md new file mode 100644 index 00000000..49a70598 --- /dev/null +++ b/docs/logging.md @@ -0,0 +1,191 @@ + +# Logging + +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) + - [Reusing the SDK logger in your app](#reusing-the-sdk-logger-in-your-app) + - [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) + +## Environment variables + +| Variable | Default | Purpose | +| --- | --- | --- | +| `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 + +`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` 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: + +```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"} +``` + +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"}}' +``` + +## Reusing the SDK logger in your app + +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. + +To give your loggers the same env-selected format, call `configure_root_logger()` once at startup, **after** `DIALApp()`/telemetry init: + +```python +import logging + +from aidial_sdk import DIALApp, configure_root_logger +from aidial_sdk.telemetry.types import TelemetryConfig + +app = DIALApp(telemetry_config=TelemetryConfig(), ...) +configure_root_logger() + +for name in ["app", "bedrock"]: + logging.getLogger(name).setLevel("INFO") +``` + +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. + +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. + +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 + +Trace/span IDs exist only when tracing is on. +Enable it with a `TelemetryConfig` **and** the OTLP exporter: + +```python +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** record (populated while a request span is active): + +| 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) | + +### JSON logs + +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 +``` + +```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"} +``` + +Reference a field in your template to rename it *(the auto-added copy is then suppressed)*: + +```sh +DIAL_SDK_JSON_LOG_FORMAT='{"level":"%(levelname)s","message":"%(message)s","trace_id":"%(otelTraceID)s"}' +``` + +```json +{"level": "INFO", "message": "hello", "trace_id": "4b45f013470528cf753a7e640da7ca1e", "otelSpanID": "ffcc9d300d9ab692", "otelTraceSampled": true, "otelServiceName": "my-service"} +``` + +### Text logs + +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 +DIAL_SDK_TEXT_LOG_FORMAT='%(levelprefix)s | %(asctime)s | trace_id=%(otelTraceID)s span_id=%(otelSpanID)s | %(message)s' +→ +INFO: | 2026-07-16 13:10:42 | trace_id=36d9c402... span_id=61f3846d... | hello +``` + +#### 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 + +| Goal | Set | +| --- | --- | +| JSON console | `DIAL_SDK_LOG_FORMAT=json` | +| 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 the `*_LOG_FORMAT` variables don't affect it — they only control +console output. 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" diff --git a/tests/test_configure_root_logger.py b/tests/test_configure_root_logger.py new file mode 100644 index 00000000..66283bc8 --- /dev/null +++ b/tests/test_configure_root_logger.py @@ -0,0 +1,65 @@ +import logging +import sys + +import pytest + +from aidial_sdk import configure_root_logger + + +def _stderr_console_handlers(root): + return [ + h + for h in root.handlers + if isinstance(h, logging.StreamHandler) + and getattr(h, "stream", None) is sys.stderr + ] + + +@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(_stderr_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(_stderr_console_handlers(clean_root)) == 1 + assert other in clean_root.handlers + + +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() + + # OTEL owns the console format; we defer and leave its handler alone. + assert _stderr_console_handlers(clean_root) == [otel_console] diff --git a/tests/test_env.py b/tests/test_env.py new file mode 100644 index 00000000..9a28a6c7 --- /dev/null +++ b/tests/test_env.py @@ -0,0 +1,33 @@ +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) 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." + ) diff --git a/tests/test_json_log_formatter.py b/tests/test_json_log_formatter.py new file mode 100644 index 00000000..83e9e837 --- /dev/null +++ b/tests/test_json_log_formatter.py @@ -0,0 +1,76 @@ +import json +import logging +import sys + +from aidial_sdk.utils._json_log_formatter import JsonLogFormatter + + +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) + 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": None}) + 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") + 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"] 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)