diff --git a/litellm/__init__.py b/litellm/__init__.py index 62477dd6264..42455706387 100644 --- a/litellm/__init__.py +++ b/litellm/__init__.py @@ -53,6 +53,8 @@ from litellm._logging import ( verbose_logger, json_logs, _turn_on_json, + ecs_logs, + _turn_on_ecs, # pyright: ignore[reportPrivateUsage] # re-exported, matches _turn_on_json above log_level, ) import re diff --git a/litellm/_logging.py b/litellm/_logging.py index c73b5175a31..93dd631e5bd 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -3,7 +3,7 @@ import contextvars import logging import os import sys -from datetime import datetime +from datetime import datetime, timezone from logging import Formatter from typing import Any, Final, TextIO from urllib.parse import unquote @@ -372,6 +372,8 @@ def _parse_json_logs_env(value: str | None) -> bool: json_logs: Final = _parse_json_logs_env(os.getenv("JSON_LOGS")) +# LITELLM_ECS_LOGS takes precedence over JSON_LOGS since ECS is a superset of structured JSON. +ecs_logs: Final = _parse_json_logs_env(os.getenv("LITELLM_ECS_LOGS")) # Create a handler for the logger (you may need to adapt this based on your needs) log_level: Final = os.getenv("LITELLM_LOG", "DEBUG") numeric_level: Final[str] = getattr(logging, log_level.upper()) @@ -528,6 +530,65 @@ class CorrelationPlainFormatter(logging.Formatter): return f"{formatted} [{' '.join(parts)}]" +_ECS_RESERVED_KEYS: Final = frozenset({"@timestamp", "log", "message", "service", "ecs", "error"}) + + +class ECSFormatter(Formatter): + """Formats log records according to Elastic Common Schema (ECS) v8.x. + + Enables structured log ingestion into the Elastic Stack and other ECS-aware + platforms. Activate via the LITELLM_ECS_LOGS=true environment variable or + call _turn_on_ecs() at application startup. + + Reference: https://www.elastic.co/guide/en/ecs/current/index.html + """ + + ECS_VERSION = "8.11.0" + + def __init__(self, service_name: str | None = None) -> None: + super().__init__() + self._service_name = service_name or os.getenv("LITELLM_SERVICE_NAME", "litellm") + + def formatTime(self, record: logging.LogRecord, datefmt: str | None = None) -> str: + dt: Final = datetime.fromtimestamp(record.created, tz=timezone.utc) + return dt.strftime("%Y-%m-%dT%H:%M:%S.") + f"{dt.microsecond // 1000:03d}Z" + + def format(self, record: logging.LogRecord) -> str: + message_str: Final = record.getMessage() + + ecs_record: Final[dict[str, object]] = { # mutable-ok: one-shot, serialized immediately + "@timestamp": self.formatTime(record), + "log": { # mutable-ok: one-shot nested structure + "level": record.levelname.lower(), + "logger": record.name, + "origin": { # mutable-ok: one-shot nested structure + "file": { # mutable-ok: one-shot nested structure + "name": record.filename, + "line": record.lineno, + }, + "function": record.funcName, + }, + }, + "message": message_str, + "service": {"name": self._service_name}, # mutable-ok: one-shot nested structure + "ecs": {"version": self.ECS_VERSION}, # mutable-ok: one-shot nested structure + } + + if record.exc_info and record.exc_info[1] is not None: + exc_type, exc_value, _ = record.exc_info + ecs_record["error"] = { # mutable-ok: one-shot, set once and never mutated further + "type": exc_type.__name__ if exc_type else None, + "message": str(exc_value), + "stack_trace": record.exc_text or self.formatException(record.exc_info), + } + + for key, value in record.__dict__.items(): + if key not in _STANDARD_RECORD_ATTRS and key not in _ECS_RESERVED_KEYS: + ecs_record[key] = value + + return safe_dumps(ecs_record, value_transform=_redact_structured_value) + + # Function to set up exception handlers for JSON logging def _setup_json_exception_handlers(formatter): # Create a handler with JSON formatting for exceptions @@ -578,8 +639,12 @@ def _setup_json_exception_handlers(formatter): pass -# Create a formatter and set it for the handler -if json_logs: +# Create a formatter and set it for the handler. +# LITELLM_ECS_LOGS takes precedence over JSON_LOGS since ECS is a superset of structured JSON. +if ecs_logs: + handler.setFormatter(ECSFormatter()) + _setup_json_exception_handlers(ECSFormatter()) +elif json_logs: handler.setFormatter(JsonFormatter()) _setup_json_exception_handlers(JsonFormatter()) else: @@ -715,12 +780,13 @@ def _initialize_loggers_with_handler(handler: logging.Handler): def _get_uvicorn_json_log_config(): """ - Generate a uvicorn log_config dictionary that applies JSON formatting to all loggers. + Generate a uvicorn log_config dictionary that applies structured formatting to all loggers. - This ensures that uvicorn's access logs, error logs, and all application logs - are formatted as JSON when json_logs is enabled. + Uses ECSFormatter when LITELLM_ECS_LOGS=true so uvicorn access/error logs + are consistent with application logs for downstream ECS consumers. + Falls back to JsonFormatter when only JSON_LOGS=true. """ - json_formatter_class: Final = "litellm._logging.JsonFormatter" + formatter_class: Final = "litellm._logging.ECSFormatter" if ecs_logs else "litellm._logging.JsonFormatter" # Use the module-level log_level variable for consistency uvicorn_log_level: Final = log_level.upper() @@ -730,13 +796,13 @@ def _get_uvicorn_json_log_config(): "disable_existing_loggers": False, "formatters": { "json": { - "()": json_formatter_class, + "()": formatter_class, }, "default": { - "()": json_formatter_class, + "()": formatter_class, }, "access": { - "()": json_formatter_class, + "()": formatter_class, }, }, "handlers": { @@ -783,10 +849,21 @@ def _turn_on_json(): handler.setLevel(numeric_level) handler.setFormatter(JsonFormatter()) _initialize_loggers_with_handler(handler) - # Set up exception handlers _setup_json_exception_handlers(JsonFormatter()) +def _turn_on_ecs(): + """Switch all litellm loggers to ECS-formatted JSON output. + + Idempotent; safe to call multiple times or from sitecustomize.py. + """ + handler: Final = LevelRoutingStreamHandler() + handler.setLevel(numeric_level) + handler.setFormatter(ECSFormatter()) + _initialize_loggers_with_handler(handler) + _setup_json_exception_handlers(ECSFormatter()) + + def _turn_on_debug(): verbose_logger.setLevel(level=logging.DEBUG) # set package log to debug verbose_router_logger.setLevel(level=logging.DEBUG) # set router logs to debug diff --git a/litellm/proxy/proxy_cli.py b/litellm/proxy/proxy_cli.py index e245367b1b4..6ac8eb8cbbe 100644 --- a/litellm/proxy/proxy_cli.py +++ b/litellm/proxy/proxy_cli.py @@ -266,8 +266,7 @@ class ProxyInitializationHelpers: if log_config is not None: print(f"Using log_config: {log_config}") uvicorn_args["log_config"] = log_config - elif litellm.json_logs: - # Use JSON log config for uvicorn to ensure all logs (including exceptions) are JSON + elif litellm.ecs_logs or litellm.json_logs: uvicorn_args["log_config"] = _get_uvicorn_json_log_config() if keepalive_timeout is not None: uvicorn_args["timeout_keep_alive"] = keepalive_timeout diff --git a/litellm/sitecustomize.py b/litellm/sitecustomize.py new file mode 100644 index 00000000000..096e1394e5a --- /dev/null +++ b/litellm/sitecustomize.py @@ -0,0 +1,34 @@ +""" +ECS logging early-startup hook template for litellm. + +This file is a deploy-time template. It will NOT auto-execute from its current +location inside the litellm package. Python only auto-runs sitecustomize.py if +it exists as a top-level module in a site-packages directory. + +To enable ECS-compliant log output without touching application code: + + 1. Find your environment's site-packages path: + python -c "import site; print(site.getsitepackages()[0])" + + 2. If no sitecustomize.py exists there yet, copy this file: + cp litellm/sitecustomize.py /sitecustomize.py + + If one already exists, append this import to it: + echo "import litellm.sitecustomize" >> /sitecustomize.py + + 3. Set the environment variable before starting your process: + export LITELLM_ECS_LOGS=true + +Alternatively, call litellm._logging._turn_on_ecs() directly at the top of +your application's entrypoint if you prefer not to touch site-packages. +""" + +import os + +if os.environ.get("LITELLM_ECS_LOGS", "").lower() == "true": + try: + from litellm._logging import _turn_on_ecs # pyright: ignore[reportPrivateUsage] # public entry point + + _turn_on_ecs() + except Exception: + pass diff --git a/tests/test_litellm/test_logging.py b/tests/test_litellm/test_logging.py index bf3757e6886..7c78e9e2b99 100644 --- a/tests/test_litellm/test_logging.py +++ b/tests/test_litellm/test_logging.py @@ -1,5 +1,6 @@ import ast import asyncio +import importlib import json import logging import re @@ -20,6 +21,7 @@ from litellm._logging import ( AccessLogRedactionFilter, CorrelationContextFilter, CorrelationPlainFormatter, + ECSFormatter, JsonFormatter, LevelRoutingStreamHandler, SecretRedactionFilter, @@ -29,6 +31,7 @@ from litellm._logging import ( _parse_json_logs_env, _plain_log_format, _stdout_truncation_marker, + _turn_on_ecs, _turn_on_json, session_id_var, set_session_id, @@ -1178,3 +1181,241 @@ def test_access_redaction_survives_the_uvicorn_json_log_config(): lg.handlers[:] = handlers lg.setLevel(level) lg.propagate = True + + +# --------------------------------------------------------------------------- +# ECS formatter tests +# --------------------------------------------------------------------------- + + +def test_ecs_formatter_required_fields(): + formatter = ECSFormatter() + record = logging.LogRecord( + name="LiteLLM", + level=logging.INFO, + pathname="proxy_server.py", + lineno=42, + msg="test message", + args=(), + exc_info=None, + ) + obj = json.loads(formatter.format(record)) + + assert obj["message"] == "test message" + assert "@timestamp" in obj + assert obj["log"]["level"] == "info" + assert obj["log"]["logger"] == "LiteLLM" + assert obj["log"]["origin"]["file"]["name"] == "proxy_server.py" + assert obj["log"]["origin"]["file"]["line"] == 42 + assert obj["service"]["name"] == "litellm" + assert obj["ecs"]["version"] == "8.11.0" + + +def test_ecs_formatter_timestamp_is_utc_iso8601_with_ms(): + formatter = ECSFormatter() + record = logging.LogRecord( + name="LiteLLM", + level=logging.DEBUG, + pathname="", + lineno=0, + msg="ts test", + args=(), + exc_info=None, + ) + obj = json.loads(formatter.format(record)) + assert re.match( + r"^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z$", obj["@timestamp"] + ), f"Non-ECS timestamp: {obj['@timestamp']!r}" + + +def test_ecs_formatter_log_level_is_lowercase(): + formatter = ECSFormatter() + for level, expected in [ + (logging.DEBUG, "debug"), + (logging.INFO, "info"), + (logging.WARNING, "warning"), + (logging.ERROR, "error"), + (logging.CRITICAL, "critical"), + ]: + record = logging.LogRecord( + name="LiteLLM", + level=level, + pathname="", + lineno=0, + msg="test", + args=(), + exc_info=None, + ) + obj = json.loads(formatter.format(record)) + assert obj["log"]["level"] == expected + + +def test_ecs_formatter_error_fields_on_exception(): + formatter = ECSFormatter() + try: + raise ValueError("something broke") + except ValueError: + exc_info = sys.exc_info() + + record = logging.LogRecord( + name="LiteLLM", + level=logging.ERROR, + pathname="", + lineno=0, + msg="error occurred", + args=(), + exc_info=exc_info, + ) + record.exc_text = formatter.formatException(exc_info) + obj = json.loads(formatter.format(record)) + + assert "error" in obj + assert obj["error"]["type"] == "ValueError" + assert obj["error"]["message"] == "something broke" + assert "stack_trace" in obj["error"] + assert "ValueError" in obj["error"]["stack_trace"] + + +def test_ecs_formatter_extra_fields_passthrough(): + formatter = ECSFormatter() + record = logging.LogRecord( + name="LiteLLM", + level=logging.DEBUG, + pathname="", + lineno=0, + msg="request received", + args=(), + exc_info=None, + ) + record.api_base = "https://api.openai.com" + record.model = "gpt-4" + obj = json.loads(formatter.format(record)) + + assert obj["api_base"] == "https://api.openai.com" + assert obj["model"] == "gpt-4" + + +def test_ecs_formatter_redacts_a_credential_in_a_structured_extra_value(): + """Parity with JsonFormatter: safe_dumps(value_transform=_redact_structured_value) + must also run for ECS output, or a secret nested in an extra={...} dict leaks.""" + formatter = ECSFormatter() + record = logging.LogRecord( + name="LiteLLM", + level=logging.DEBUG, + pathname="", + lineno=0, + msg="request sent", + args=(), + exc_info=None, + ) + record.litellm_params = {"api_key": "sk-1234567890abcdefghijklmnopqrstuvwxyz"} + obj = json.loads(formatter.format(record)) + + assert "sk-1234567890abcdefghijklmnopqrstuvwxyz" not in json.dumps(obj) + assert "REDACTED" in obj["litellm_params"]["api_key"] + + +def test_ecs_formatter_no_ecs_reserved_key_collision(): + formatter = ECSFormatter() + record = logging.LogRecord( + name="LiteLLM", + level=logging.INFO, + pathname="", + lineno=0, + msg="test", + args=(), + exc_info=None, + ) + # Attempt to inject via extra - should not overwrite ECS structure + record.message = "injected" + obj = json.loads(formatter.format(record)) + assert obj["message"] == "test" + + +def test_ecs_mode_emits_one_record_per_logger(capfd): + _turn_on_ecs() + for lg in (verbose_logger, verbose_router_logger, verbose_proxy_logger): + lg.setLevel(logging.INFO) + + verbose_logger.info("first info") + verbose_router_logger.info("second info from router") + verbose_proxy_logger.info("third info from proxy") + + # All three records are INFO, so they must route to stdout and none to stderr + out, err = capfd.readouterr() + assert [raw for raw in err.splitlines() if raw.strip()] == [] + lines = [raw for raw in out.splitlines() if raw.strip()] + + assert len(lines) == 3, f"got {len(lines)} lines, want 3: {lines!r}" + for line in lines: + obj = json.loads(line) + assert "@timestamp" in obj + assert obj["log"]["level"] == "info" + assert obj["ecs"]["version"] == "8.11.0" + assert obj["service"]["name"] == "litellm" + + +def test_get_uvicorn_json_log_config_uses_ecs_formatter_when_ecs_logs_enabled(monkeypatch): + """Regression test: _get_uvicorn_json_log_config() must select ECSFormatter for + every uvicorn formatter entry when LITELLM_ECS_LOGS is on, or uvicorn's own + access/error logs stay plain JSON while application logs are ECS.""" + import litellm._logging as litellm_logging + + monkeypatch.setattr(litellm_logging, "ecs_logs", True) + log_config = _get_uvicorn_json_log_config() + + for formatter_config in log_config["formatters"].values(): + assert formatter_config["()"] == "litellm._logging.ECSFormatter" + + +def _run_sitecustomize_hook(): + """Re-run litellm/sitecustomize.py's module body the way a copy of it in + site-packages runs at interpreter startup.""" + return importlib.reload(importlib.import_module("litellm.sitecustomize")) + + +def _loggers_are_on_ecs() -> bool: + return any(isinstance(handler.formatter, ECSFormatter) for handler in verbose_logger.handlers) + + +def test_sitecustomize_hook_turns_on_ecs_when_the_env_var_is_set(monkeypatch): + """The hook is the documented zero-code-change path to ECS logs. Without this, + renaming _turn_on_ecs would leave the hook's except-Exception swallowing the + ImportError and ECS logging would silently never switch on.""" + plain = logging.StreamHandler() + plain.setFormatter(JsonFormatter()) + _initialize_loggers_with_handler(plain) + monkeypatch.setenv("LITELLM_ECS_LOGS", "true") + + _run_sitecustomize_hook() + + assert _loggers_are_on_ecs() + + +def test_sitecustomize_hook_leaves_logging_alone_when_the_env_var_is_unset(monkeypatch): + plain = logging.StreamHandler() + plain.setFormatter(JsonFormatter()) + _initialize_loggers_with_handler(plain) + monkeypatch.delenv("LITELLM_ECS_LOGS", raising=False) + + _run_sitecustomize_hook() + + assert not _loggers_are_on_ecs() + + +def test_sitecustomize_hook_never_breaks_interpreter_startup(monkeypatch): + """A copy of this file in site-packages runs for every process in the environment, + so a broken or half-installed litellm must not raise out of it.""" + + def _raise(*_args, **_kwargs): + raise RuntimeError("litellm is half-installed") + + plain = logging.StreamHandler() + plain.setFormatter(JsonFormatter()) + _initialize_loggers_with_handler(plain) + monkeypatch.setenv("LITELLM_ECS_LOGS", "true") + monkeypatch.setattr(litellm._logging, "_turn_on_ecs", _raise) + + _run_sitecustomize_hook() + + assert not _loggers_are_on_ecs()