diff --git a/tests/test_logger.py b/tests/test_logger.py index 01672358902f..8900e9c2a1e6 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -49,10 +49,13 @@ def test_trace_function_call(): os.remove(path) -def test_default_vllm_root_logger_configuration(): +def test_default_vllm_root_logger_configuration(monkeypatch): """This test presumes that VLLM_CONFIGURE_LOGGING (default: True) and VLLM_LOGGING_CONFIG_PATH (default: None) are not configured and default behavior is activated.""" + monkeypatch.setenv("VLLM_LOGGING_COLOR", "0") + _configure_vllm_root_logger() + logger = logging.getLogger("vllm") assert logger.level == logging.DEBUG assert not logger.propagate @@ -70,12 +73,13 @@ def test_default_vllm_root_logger_configuration(): assert formatter.datefmt == _DATE_FORMAT -@patch("vllm.logger.VLLM_CONFIGURE_LOGGING", 1) -@patch("vllm.logger.VLLM_LOGGING_CONFIG_PATH", None) -def test_descendent_loggers_depend_on_and_propagate_logs_to_root_logger(): +def test_descendent_loggers_depend_on_and_propagate_logs_to_root_logger(monkeypatch): """This test presumes that VLLM_CONFIGURE_LOGGING (default: True) and VLLM_LOGGING_CONFIG_PATH (default: None) are not configured and default behavior is activated.""" + monkeypatch.setenv("VLLM_CONFIGURE_LOGGING", "1") + monkeypatch.delenv("VLLM_LOGGING_CONFIG_PATH", raising=False) + root_logger = logging.getLogger("vllm") root_handler = root_logger.handlers[0] @@ -99,49 +103,50 @@ def test_descendent_loggers_depend_on_and_propagate_logs_to_root_logger(): assert log_record.levelno == logging.INFO -@patch("vllm.logger.VLLM_CONFIGURE_LOGGING", 0) -@patch("vllm.logger.VLLM_LOGGING_CONFIG_PATH", None) -def test_logger_configuring_can_be_disabled(): +def test_logger_configuring_can_be_disabled(monkeypatch): """This test calls _configure_vllm_root_logger again to test custom logging config behavior, however mocks are used to ensure no changes in behavior or configuration occur.""" + monkeypatch.setenv("VLLM_CONFIGURE_LOGGING", "0") + monkeypatch.delenv("VLLM_LOGGING_CONFIG_PATH", raising=False) with patch("vllm.logger.dictConfig") as dict_config_mock: _configure_vllm_root_logger() dict_config_mock.assert_not_called() -@patch("vllm.logger.VLLM_CONFIGURE_LOGGING", 1) -@patch( - "vllm.logger.VLLM_LOGGING_CONFIG_PATH", - "/if/there/is/a/file/here/then/you/did/this/to/yourself.json", -) -def test_an_error_is_raised_when_custom_logging_config_file_does_not_exist(): +def test_an_error_is_raised_when_custom_logging_config_file_does_not_exist(monkeypatch): """This test calls _configure_vllm_root_logger again to test custom logging config behavior, however it fails before any change in behavior or configuration occurs.""" + monkeypatch.setenv("VLLM_CONFIGURE_LOGGING", "1") + monkeypatch.setenv( + "VLLM_LOGGING_CONFIG_PATH", + "/if/there/is/a/file/here/then/you/did/this/to/yourself.json", + ) + with pytest.raises(RuntimeError) as ex_info: _configure_vllm_root_logger() assert ex_info.type == RuntimeError # noqa: E721 assert "File does not exist" in str(ex_info) -@patch("vllm.logger.VLLM_CONFIGURE_LOGGING", 1) -def test_an_error_is_raised_when_custom_logging_config_is_invalid_json(): +def test_an_error_is_raised_when_custom_logging_config_is_invalid_json(monkeypatch): """This test calls _configure_vllm_root_logger again to test custom logging config behavior, however it fails before any change in behavior or configuration occurs.""" + monkeypatch.setenv("VLLM_CONFIGURE_LOGGING", "1") + with NamedTemporaryFile(encoding="utf-8", mode="w") as logging_config_file: logging_config_file.write("---\nloggers: []\nversion: 1") logging_config_file.flush() - with patch("vllm.logger.VLLM_LOGGING_CONFIG_PATH", logging_config_file.name): - with pytest.raises(JSONDecodeError) as ex_info: - _configure_vllm_root_logger() - assert ex_info.type == JSONDecodeError - assert "Expecting value" in str(ex_info) + monkeypatch.setenv("VLLM_LOGGING_CONFIG_PATH", logging_config_file.name) + with pytest.raises(JSONDecodeError) as ex_info: + _configure_vllm_root_logger() + assert ex_info.type == JSONDecodeError + assert "Expecting value" in str(ex_info) -@patch("vllm.logger.VLLM_CONFIGURE_LOGGING", 1) @pytest.mark.parametrize( "unexpected_config", ( @@ -151,26 +156,30 @@ def test_an_error_is_raised_when_custom_logging_config_is_invalid_json(): ), ) def test_an_error_is_raised_when_custom_logging_config_is_unexpected_json( + monkeypatch, unexpected_config: Any, ): """This test calls _configure_vllm_root_logger again to test custom logging config behavior, however it fails before any change in behavior or configuration occurs.""" + monkeypatch.setenv("VLLM_CONFIGURE_LOGGING", "1") + with NamedTemporaryFile(encoding="utf-8", mode="w") as logging_config_file: logging_config_file.write(json.dumps(unexpected_config)) logging_config_file.flush() - with patch("vllm.logger.VLLM_LOGGING_CONFIG_PATH", logging_config_file.name): - with pytest.raises(ValueError) as ex_info: - _configure_vllm_root_logger() - assert ex_info.type == ValueError # noqa: E721 - assert "Invalid logging config. Expected dict, got" in str(ex_info) + monkeypatch.setenv("VLLM_LOGGING_CONFIG_PATH", logging_config_file.name) + with pytest.raises(ValueError) as ex_info: + _configure_vllm_root_logger() + assert ex_info.type == ValueError # noqa: E721 + assert "Invalid logging config. Expected dict, got" in str(ex_info) -@patch("vllm.logger.VLLM_CONFIGURE_LOGGING", 1) -def test_custom_logging_config_is_parsed_and_used_when_provided(): +def test_custom_logging_config_is_parsed_and_used_when_provided(monkeypatch): """This test calls _configure_vllm_root_logger again to test custom logging config behavior, however mocks are used to ensure no changes in behavior or configuration occur.""" + monkeypatch.setenv("VLLM_CONFIGURE_LOGGING", "1") + valid_logging_config = { "loggers": { "vllm.test_logger.logger": { @@ -183,19 +192,18 @@ def test_custom_logging_config_is_parsed_and_used_when_provided(): with NamedTemporaryFile(encoding="utf-8", mode="w") as logging_config_file: logging_config_file.write(json.dumps(valid_logging_config)) logging_config_file.flush() - with ( - patch("vllm.logger.VLLM_LOGGING_CONFIG_PATH", logging_config_file.name), - patch("vllm.logger.dictConfig") as dict_config_mock, - ): + monkeypatch.setenv("VLLM_LOGGING_CONFIG_PATH", logging_config_file.name) + with patch("vllm.logger.dictConfig") as dict_config_mock: _configure_vllm_root_logger() dict_config_mock.assert_called_with(valid_logging_config) -@patch("vllm.logger.VLLM_CONFIGURE_LOGGING", 0) -def test_custom_logging_config_causes_an_error_if_configure_logging_is_off(): +def test_custom_logging_config_causes_an_error_if_configure_logging_is_off(monkeypatch): """This test calls _configure_vllm_root_logger again to test custom logging config behavior, however mocks are used to ensure no changes in behavior or configuration occur.""" + monkeypatch.setenv("VLLM_CONFIGURE_LOGGING", "0") + valid_logging_config = { "loggers": { "vllm.test_logger.logger": { @@ -207,15 +215,15 @@ def test_custom_logging_config_causes_an_error_if_configure_logging_is_off(): with NamedTemporaryFile(encoding="utf-8", mode="w") as logging_config_file: logging_config_file.write(json.dumps(valid_logging_config)) logging_config_file.flush() - with patch("vllm.logger.VLLM_LOGGING_CONFIG_PATH", logging_config_file.name): - with pytest.raises(RuntimeError) as ex_info: - _configure_vllm_root_logger() - assert ex_info.type is RuntimeError - expected_message_snippet = ( - "VLLM_CONFIGURE_LOGGING evaluated to false, but " - "VLLM_LOGGING_CONFIG_PATH was given." - ) - assert expected_message_snippet in str(ex_info) + monkeypatch.setenv("VLLM_LOGGING_CONFIG_PATH", logging_config_file.name) + with pytest.raises(RuntimeError) as ex_info: + _configure_vllm_root_logger() + assert ex_info.type is RuntimeError + expected_message_snippet = ( + "VLLM_CONFIGURE_LOGGING evaluated to false, but " + "VLLM_LOGGING_CONFIG_PATH was given." + ) + assert expected_message_snippet in str(ex_info) # Remember! The root logger is assumed to have been configured as # though VLLM_CONFIGURE_LOGGING=1 and VLLM_LOGGING_CONFIG_PATH=None. diff --git a/vllm/envs.py b/vllm/envs.py index 1ff620af5722..614bc94b978b 100755 --- a/vllm/envs.py +++ b/vllm/envs.py @@ -42,6 +42,8 @@ if TYPE_CHECKING: VLLM_LOGGING_PREFIX: str = "" VLLM_LOGGING_STREAM: str = "ext://sys.stdout" VLLM_LOGGING_CONFIG_PATH: str | None = None + VLLM_LOGGING_COLOR: str = "auto" + NO_COLOR: bool = False VLLM_LOG_STATS_INTERVAL: float = 10.0 VLLM_TRACE_FUNCTION: int = 0 VLLM_ATTENTION_BACKEND: str | None = None @@ -616,6 +618,11 @@ environment_variables: dict[str, Callable[[], Any]] = { "VLLM_LOGGING_STREAM": lambda: os.getenv("VLLM_LOGGING_STREAM", "ext://sys.stdout"), # if set, VLLM_LOGGING_PREFIX will be prepended to all log messages "VLLM_LOGGING_PREFIX": lambda: os.getenv("VLLM_LOGGING_PREFIX", ""), + # Controls colored logging output. Options: "auto" (default, colors when terminal), + # "1" (always use colors), "0" (never use colors) + "VLLM_LOGGING_COLOR": lambda: os.getenv("VLLM_LOGGING_COLOR", "auto"), + # Standard unix flag for disabling ANSI color codes + "NO_COLOR": lambda: os.getenv("NO_COLOR", "0") != "0", # If set, vllm will log stats at this interval in seconds # If not set, vllm will log stats every 10 seconds. "VLLM_LOG_STATS_INTERVAL": lambda: val @@ -1578,6 +1585,7 @@ def compile_factors() -> dict[str, object]: "VLLM_LOGGING_PREFIX", "VLLM_LOGGING_STREAM", "VLLM_LOGGING_CONFIG_PATH", + "VLLM_LOGGING_COLOR", "VLLM_LOG_STATS_INTERVAL", "VLLM_DEBUG_LOG_API_SERVER_RESPONSE", "VLLM_TUNED_CONFIG_FOLDER", @@ -1608,6 +1616,7 @@ def compile_factors() -> dict[str, object]: "VLLM_TEST_FORCE_LOAD_FORMAT", "LOCAL_RANK", "CUDA_VISIBLE_DEVICES", + "NO_COLOR", } from vllm.config.utils import normalize_value diff --git a/vllm/logger.py b/vllm/logger.py index 934100829684..772e36497b45 100644 --- a/vllm/logger.py +++ b/vllm/logger.py @@ -17,18 +17,25 @@ from typing import Any, Literal, cast import vllm.envs as envs -VLLM_CONFIGURE_LOGGING = envs.VLLM_CONFIGURE_LOGGING -VLLM_LOGGING_CONFIG_PATH = envs.VLLM_LOGGING_CONFIG_PATH -VLLM_LOGGING_LEVEL = envs.VLLM_LOGGING_LEVEL -VLLM_LOGGING_PREFIX = envs.VLLM_LOGGING_PREFIX -VLLM_LOGGING_STREAM = envs.VLLM_LOGGING_STREAM - _FORMAT = ( - f"{VLLM_LOGGING_PREFIX}%(levelname)s %(asctime)s " + f"{envs.VLLM_LOGGING_PREFIX}%(levelname)s %(asctime)s " "[%(fileinfo)s:%(lineno)d] %(message)s" ) _DATE_FORMAT = "%m-%d %H:%M:%S" + +def _use_color() -> bool: + if envs.NO_COLOR or envs.VLLM_LOGGING_COLOR == "0": + return False + if envs.VLLM_LOGGING_COLOR == "1": + return True + if envs.VLLM_LOGGING_STREAM == "ext://sys.stdout": # stdout + return hasattr(sys.stdout, "isatty") and sys.stdout.isatty() + elif envs.VLLM_LOGGING_STREAM == "ext://sys.stderr": # stderr + return hasattr(sys.stderr, "isatty") and sys.stderr.isatty() + return False + + DEFAULT_LOGGING_CONFIG = { "formatters": { "vllm": { @@ -36,13 +43,19 @@ DEFAULT_LOGGING_CONFIG = { "datefmt": _DATE_FORMAT, "format": _FORMAT, }, + "vllm_color": { + "class": "vllm.logging_utils.ColoredFormatter", + "datefmt": _DATE_FORMAT, + "format": _FORMAT, + }, }, "handlers": { "vllm": { "class": "logging.StreamHandler", - "formatter": "vllm", - "level": VLLM_LOGGING_LEVEL, - "stream": VLLM_LOGGING_STREAM, + # Choose formatter based on color setting. + "formatter": "vllm_color" if _use_color() else "vllm", + "level": envs.VLLM_LOGGING_LEVEL, + "stream": envs.VLLM_LOGGING_STREAM, }, }, "loggers": { @@ -144,7 +157,7 @@ _METHODS_TO_PATCH = { def _configure_vllm_root_logger() -> None: logging_config = dict[str, Any]() - if not VLLM_CONFIGURE_LOGGING and VLLM_LOGGING_CONFIG_PATH: + if not envs.VLLM_CONFIGURE_LOGGING and envs.VLLM_LOGGING_CONFIG_PATH: raise RuntimeError( "VLLM_CONFIGURE_LOGGING evaluated to false, but " "VLLM_LOGGING_CONFIG_PATH was given. VLLM_LOGGING_CONFIG_PATH " @@ -152,16 +165,22 @@ def _configure_vllm_root_logger() -> None: "VLLM_CONFIGURE_LOGGING or unset VLLM_LOGGING_CONFIG_PATH." ) - if VLLM_CONFIGURE_LOGGING: + if envs.VLLM_CONFIGURE_LOGGING: logging_config = DEFAULT_LOGGING_CONFIG - if VLLM_LOGGING_CONFIG_PATH: - if not path.exists(VLLM_LOGGING_CONFIG_PATH): + vllm_handler = logging_config["handlers"]["vllm"] + # Refresh these values in case env vars have changed. + vllm_handler["level"] = envs.VLLM_LOGGING_LEVEL + vllm_handler["stream"] = envs.VLLM_LOGGING_STREAM + vllm_handler["formatter"] = "vllm_color" if _use_color() else "vllm" + + if envs.VLLM_LOGGING_CONFIG_PATH: + if not path.exists(envs.VLLM_LOGGING_CONFIG_PATH): raise RuntimeError( "Could not load logging config. File does not exist: %s", - VLLM_LOGGING_CONFIG_PATH, + envs.VLLM_LOGGING_CONFIG_PATH, ) - with open(VLLM_LOGGING_CONFIG_PATH, encoding="utf-8") as file: + with open(envs.VLLM_LOGGING_CONFIG_PATH, encoding="utf-8") as file: custom_config = json.loads(file.read()) if not isinstance(custom_config, dict): diff --git a/vllm/logging_utils/__init__.py b/vllm/logging_utils/__init__.py index 44b40ead973b..8d3354df215b 100644 --- a/vllm/logging_utils/__init__.py +++ b/vllm/logging_utils/__init__.py @@ -1,12 +1,13 @@ # SPDX-License-Identifier: Apache-2.0 # SPDX-FileCopyrightText: Copyright contributors to the vLLM project -from vllm.logging_utils.formatter import NewLineFormatter +from vllm.logging_utils.formatter import ColoredFormatter, NewLineFormatter from vllm.logging_utils.lazy import lazy from vllm.logging_utils.log_time import logtime __all__ = [ "NewLineFormatter", + "ColoredFormatter", "lazy", "logtime", ] diff --git a/vllm/logging_utils/formatter.py b/vllm/logging_utils/formatter.py index 02ba308e1879..3ad4ef8d119a 100644 --- a/vllm/logging_utils/formatter.py +++ b/vllm/logging_utils/formatter.py @@ -75,3 +75,53 @@ class NewLineFormatter(logging.Formatter): parts = msg.split(record.message) msg = msg.replace("\n", "\r\n" + parts[0]) return msg + + +class ColoredFormatter(NewLineFormatter): + """Adds ANSI color codes to log levels for terminal output. + + This formatter adds colors by injecting them into the format string for + static elements (timestamp, filename, line number) and modifying the + levelname attribute for dynamic color selection. + """ + + # ANSI color codes + COLORS = { + "DEBUG": "\033[37m", # White + "INFO": "\033[32m", # Green + "WARNING": "\033[33m", # Yellow + "ERROR": "\033[31m", # Red + "CRITICAL": "\033[35m", # Magenta + } + GREY = "\033[90m" # Grey for timestamp and file info + RESET = "\033[0m" + + def __init__(self, fmt, datefmt=None, style="%"): + # Inject grey color codes into format string for timestamp and file info + if fmt: + # Wrap %(asctime)s with grey + fmt = fmt.replace("%(asctime)s", f"{self.GREY}%(asctime)s{self.RESET}") + # Wrap [%(fileinfo)s:%(lineno)d] with grey + fmt = fmt.replace( + "[%(fileinfo)s:%(lineno)d]", + f"{self.GREY}[%(fileinfo)s:%(lineno)d]{self.RESET}", + ) + + # Call parent __init__ with potentially modified format string + super().__init__(fmt, datefmt, style) + + def format(self, record): + # Store original levelname to restore later (in case record is reused) + orig_levelname = record.levelname + + # Only modify levelname - it needs dynamic color based on severity + if (color_code := self.COLORS.get(record.levelname)) is not None: + record.levelname = f"{color_code}{record.levelname}{self.RESET}" + + # Call parent format which will handle everything else + msg = super().format(record) + + # Restore original levelname + record.levelname = orig_levelname + + return msg diff --git a/vllm/utils/system_utils.py b/vllm/utils/system_utils.py index 5968884e232a..cc872040b6c5 100644 --- a/vllm/utils/system_utils.py +++ b/vllm/utils/system_utils.py @@ -22,7 +22,7 @@ from .platform_utils import cuda_is_initialized, xpu_is_initialized logger = init_logger(__name__) -CYAN = "\033[1;36m" +CYAN = "\033[0;36m" RESET = "\033[0;0m" @@ -142,7 +142,10 @@ def set_process_title( def _add_prefix(file: TextIO, worker_name: str, pid: int) -> None: """Add colored prefix to file output for log decoration.""" - prefix = f"{CYAN}({worker_name} pid={pid}){RESET} " + if envs.NO_COLOR: + prefix = f"({worker_name} pid={pid}) " + else: + prefix = f"{CYAN}({worker_name} pid={pid}){RESET} " file_write = file.write def write_with_prefix(s: str):