diff --git a/litellm/_logging.py b/litellm/_logging.py index 36fd51206c2..fbb35b72be2 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -5,7 +5,7 @@ import os import sys from datetime import datetime from logging import Formatter -from typing import Any, Final +from typing import Any, Final, TextIO import litellm from litellm.constants import ( @@ -234,11 +234,65 @@ class CorrelationContextFilter(logging.Filter): _correlation_filter: Final = CorrelationContextFilter() -json_logs = bool(os.getenv("JSON_LOGS", False)) +_LOG_FORMAT_PREFIX: Final = "%(asctime)s - %(name)s:%(levelname)s" +_LOG_FORMAT_SUFFIX: Final = ": %(filename)s:%(lineno)s - %(message)s" +_PLAIN_LOG_FORMAT: Final = _LOG_FORMAT_PREFIX + _LOG_FORMAT_SUFFIX +_COLOR_LOG_FORMAT: Final = f"\033[92m{_LOG_FORMAT_PREFIX}\033[0m{_LOG_FORMAT_SUFFIX}" + + +def _stream_is_tty(stream: TextIO | None) -> bool: + """True when the stream is an open interactive terminal; never raises. + + A stream can be None (pythonw/embedded interpreters), lack isatty entirely + (GUI log-redirect shims), or be closed; import must survive all three. + """ + try: + return stream is not None and stream.isatty() + except (AttributeError, ValueError): + return False + + +def _plain_log_format(stdout: TextIO | None, stderr: TextIO | None) -> str: + """The plain-text log format, colorized only when both streams are an interactive terminal. + + Honors the NO_COLOR convention from no-color.org: color is disabled when + NO_COLOR is present with a non-empty value. + """ + if os.environ.get("NO_COLOR"): + return _PLAIN_LOG_FORMAT + return _COLOR_LOG_FORMAT if _stream_is_tty(stdout) and _stream_is_tty(stderr) else _PLAIN_LOG_FORMAT + + +class LevelRoutingStreamHandler(logging.StreamHandler): + """Writes records below WARNING to stdout and WARNING and above to stderr. + + Collectors that derive severity from the stream report every stderr line as an error. + """ + + def emit(self, record: logging.LogRecord) -> None: + preferred: Final = sys.stdout if record.levelno < logging.WARNING else sys.stderr + if preferred is None or getattr(preferred, "closed", False): + self.stream = sys.stderr # rebind-ok: fall back to the pre-fix stream rather than raising per record + else: + self.stream = preferred # rebind-ok: StreamHandler.emit writes self.stream under the handler lock + super().emit(record) + + +def _parse_json_logs_env(value: str | None) -> bool: + """Strict opt-in parse for the JSON_LOGS env var: only "true" (any case) enables JSON logs. + + Matches the reader in litellm-proxy-extras/_logging.py. The previous + bool(os.getenv(...)) treated any non-empty value, including "false" and "0", + as enabled. + """ + return (value or "").lower() == "true" + + +json_logs: Final = _parse_json_logs_env(os.getenv("JSON_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()) -handler: Final = logging.StreamHandler() +handler: Final = LevelRoutingStreamHandler() handler.setLevel(numeric_level) handler.addFilter(_secret_filter) handler.addFilter(_correlation_filter) @@ -447,7 +501,7 @@ if json_logs: _setup_json_exception_handlers(JsonFormatter()) else: formatter: Final = CorrelationPlainFormatter( - "\033[92m%(asctime)s - %(name)s:%(levelname)s\033[0m: %(filename)s:%(lineno)s - %(message)s", + _plain_log_format(sys.stdout, sys.stderr), datefmt="%H:%M:%S", ) @@ -628,7 +682,7 @@ def _turn_on_json(): - Adds a JSON formatter to all loggers """ - handler: Final = logging.StreamHandler() + handler: Final = LevelRoutingStreamHandler() handler.setFormatter(JsonFormatter()) _initialize_loggers_with_handler(handler) # Set up exception handlers diff --git a/tests/test_litellm/test_logging.py b/tests/test_litellm/test_logging.py index db8dfaa3ad6..087a1c8b3ad 100644 --- a/tests/test_litellm/test_logging.py +++ b/tests/test_litellm/test_logging.py @@ -12,13 +12,18 @@ import logging import litellm from litellm._logging import ( + _COLOR_LOG_FORMAT, + _PLAIN_LOG_FORMAT, ALL_LOGGERS, CorrelationContextFilter, CorrelationPlainFormatter, JsonFormatter, + LevelRoutingStreamHandler, SecretRedactionFilter, StdoutLogTruncationFilter, _initialize_loggers_with_handler, + _parse_json_logs_env, + _plain_log_format, _stdout_truncation_marker, _turn_on_json, session_id_var, @@ -57,11 +62,10 @@ def test_json_mode_emits_one_record_per_logger(capfd): verbose_router_logger.info("second info from router") verbose_proxy_logger.info("third info from proxy") - # Capture stdout + # All three records are INFO, so they must route to stdout and none to stderr out, err = capfd.readouterr() - print("out", out) - print("err", err) - lines = [l for l in err.splitlines() if l.strip()] + assert [raw for raw in err.splitlines() if raw.strip()] == [] + lines = [raw for raw in out.splitlines() if raw.strip()] # Expect exactly three JSON lines assert len(lines) == 3, f"got {len(lines)} lines, want 3: {lines!r}" @@ -831,3 +835,136 @@ def test_set_session_id_bounds_length(): assert len(session_id_var.get()) == 256 finally: session_id_var.reset(token) + + +class _FakeStream: + def __init__(self, tty: bool) -> None: + self._tty = tty + + def isatty(self) -> bool: + return self._tty + + +def test_records_below_warning_go_to_stdout_and_the_rest_to_stderr(capsys): + logger = logging.getLogger("test_level_routing") + logger.handlers.clear() + logger.propagate = False + logger.setLevel(logging.DEBUG) + handler = LevelRoutingStreamHandler() + handler.setFormatter(logging.Formatter("%(levelname)s %(message)s")) + logger.addHandler(handler) + + try: + logger.debug("d") + logger.info("i") + logger.warning("w") + logger.error("e") + logger.critical("c") + finally: + logger.handlers.clear() + + out, err = capsys.readouterr() + assert out.splitlines() == ["DEBUG d", "INFO i"] + assert err.splitlines() == ["WARNING w", "ERROR e", "CRITICAL c"] + + +def test_verbose_loggers_route_records_by_level(): + for lg in (verbose_logger, verbose_router_logger, verbose_proxy_logger): + assert any(isinstance(h, LevelRoutingStreamHandler) for h in lg.handlers), lg.name + + +@pytest.mark.parametrize( + "stdout_tty, stderr_tty, no_color, want_color", + [ + (True, True, None, True), + (False, False, None, False), + (False, True, None, False), + (True, False, None, False), + (True, True, "1", False), + (True, True, "", True), + ], +) +def test_plain_log_format_colorizes_only_for_a_terminal(monkeypatch, stdout_tty, stderr_tty, no_color, want_color): + if no_color is None: + monkeypatch.delenv("NO_COLOR", raising=False) + else: + monkeypatch.setenv("NO_COLOR", no_color) + + fmt = _plain_log_format(_FakeStream(stdout_tty), _FakeStream(stderr_tty)) + + assert fmt == (_COLOR_LOG_FORMAT if want_color else _PLAIN_LOG_FORMAT) + assert ("\033[" in fmt) is want_color + + +def test_plain_format_carries_no_ansi_codes(): + assert "\033[" not in _PLAIN_LOG_FORMAT + + +class _Brokenstream: + """A write-only shim without isatty, like GUI log redirectors install.""" + + +class _ClosedStream: + closed = True + + def isatty(self) -> bool: + raise ValueError("I/O operation on closed file") + + +@pytest.mark.parametrize( + "stdout, stderr", + [ + (None, None), + (_FakeStream(True), None), + (_Brokenstream(), _FakeStream(True)), + (_ClosedStream(), _FakeStream(True)), + ], +) +def test_plain_log_format_survives_hostile_streams(stdout, stderr): + """sys.stdout/sys.stderr can be None, shimmed, or closed; import must not crash.""" + assert _plain_log_format(stdout, stderr) == _PLAIN_LOG_FORMAT + + +def test_level_routing_handler_falls_back_to_stderr_when_stdout_is_unusable(monkeypatch, capsys): + logger = logging.getLogger("test_level_routing_fallback") + logger.handlers.clear() + logger.propagate = False + logger.setLevel(logging.DEBUG) + handler = LevelRoutingStreamHandler() + handler.setFormatter(logging.Formatter("%(levelname)s %(message)s")) + logger.addHandler(handler) + + try: + monkeypatch.setattr(sys, "stdout", None) + logger.info("stdout is gone") + finally: + logger.handlers.clear() + + err = capsys.readouterr().err + assert "INFO stdout is gone" in err + assert "--- Logging error ---" not in err + + +@pytest.mark.parametrize( + "value, want", + [ + ("true", True), + ("True", True), + ("TRUE", True), + ("false", False), + ("False", False), + ("0", False), + ("1", False), + ("", False), + (None, False), + ], +) +def test_parse_json_logs_env_enables_only_on_true(value, want): + """JSON_LOGS=false / 0 must not enable JSON logs (LIT-5558).""" + assert _parse_json_logs_env(value) is want + + +def test_plain_log_format_survives_none_streams(): + """sys.stdout/sys.stderr can be None in embedded interpreters; import must not crash.""" + assert _plain_log_format(None, None) == _PLAIN_LOG_FORMAT + assert _plain_log_format(_FakeStream(True), None) == _PLAIN_LOG_FORMAT