fix(logging): stop stream-based log collectors classifying INFO logs as errors (#38476)

Route records below WARNING to stdout (WARNING and above stay on stderr),
emit ANSI color codes only when both streams are a TTY (honoring NO_COLOR),
and parse JSON_LOGS strictly so JSON_LOGS=false no longer enables JSON logs.
This commit is contained in:
yucheng-berri 2026-08-27 17:42:00 -07:00 committed by GitHub
parent 239ec955dc
commit 22a349ee70
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
2 changed files with 200 additions and 9 deletions

View file

@ -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

View file

@ -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