diff --git a/tests/test_logger.py b/tests/test_logger.py index 1810eeba16..f194853fa4 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -165,6 +165,45 @@ def test_json_logging(monkeypatch, tmp_path): assert log["process"] == os.getpid() +@pytest.mark.parametrize("factory_order", ["before", "after", "replacement"]) +def test_configure_logging_preserves_application_record_factory( + monkeypatch, factory_order +): + """Application fields survive initial configuration and reconfiguration.""" + original_factory = logging.getLogRecordFactory() + monkeypatch.setattr(vllm_logger, "dictConfig", lambda _: None) + monkeypatch.setattr(vllm_logger, "_last_configured_logging_config", None) + monkeypatch.setattr(vllm_logger, "_vllm_process_info", None) + config = LoggingConfig() + formatter = logging.Formatter("%(request_id)s %(vllm_process_name)s %(message)s") + + try: + logging.setLogRecordFactory(logging.LogRecord) + if factory_order != "before": + configure_logging(config) + base_factory = ( + logging.LogRecord + if factory_order == "replacement" + else logging.getLogRecordFactory() + ) + + def application_factory(*args, **kwargs): + record = base_factory(*args, **kwargs) + record.request_id = "request-123" + return record + + logging.setLogRecordFactory(application_factory) + decorate_logs("Worker_DP0") + for _ in range(2): + configure_logging(config) + record = logging.getLogger("application").makeRecord( + "application", logging.INFO, __file__, 1, "probe", (), None + ) + assert formatter.format(record) == "request-123 Worker_DP0 probe" + finally: + logging.setLogRecordFactory(original_factory) + + def test_use_color_force_color(monkeypatch): """FORCE_COLOR forces colored logs without a TTY, while NO_COLOR and an explicit VLLM_LOGGING_COLOR=0 take precedence over it.""" @@ -223,9 +262,11 @@ def test_logger_configuring_can_be_disabled(monkeypatch): monkeypatch.setenv("VLLM_CONFIGURE_LOGGING", "0") monkeypatch.delenv("VLLM_LOGGING_CONFIG_PATH", raising=False) + original_factory = logging.getLogRecordFactory() with patch("vllm.logger.dictConfig") as dict_config_mock: configure_logging(LoggingConfig(configure_logging=False)) dict_config_mock.assert_not_called() + assert logging.getLogRecordFactory() is original_factory def test_an_error_is_raised_when_custom_logging_config_file_does_not_exist(monkeypatch): diff --git a/vllm/logger.py b/vllm/logger.py index 5e5f63aefc..24692aa392 100644 --- a/vllm/logger.py +++ b/vllm/logger.py @@ -7,7 +7,7 @@ import json import logging import os import sys -from collections.abc import Generator, Hashable +from collections.abc import Callable, Generator, Hashable from contextlib import contextmanager from copy import deepcopy from dataclasses import replace @@ -31,20 +31,24 @@ _FORMAT = ( ) _DATE_FORMAT = "%m-%d %H:%M:%S" -_base_log_record_factory = logging.getLogRecordFactory() _vllm_process_info: tuple[str, int] | None = None -def _vllm_log_record_factory(*args: Any, **kwargs: Any) -> logging.LogRecord: - """Add vLLM process metadata to each log record.""" - record = _base_log_record_factory(*args, **kwargs) - process_info = _vllm_process_info - pid = os.getpid() - if process_info is None or process_info[1] != pid: - record.vllm_process_name = record.processName - else: - record.vllm_process_name = process_info[0] - return record +class _VllmLogRecordFactory: + """Add vLLM process metadata while preserving the wrapped record factory.""" + + def __init__(self, factory: Callable[..., logging.LogRecord]) -> None: + self._factory = factory + + def __call__(self, *args: Any, **kwargs: Any) -> logging.LogRecord: + record = self._factory(*args, **kwargs) + process_info = _vllm_process_info + pid = os.getpid() + if process_info is None or process_info[1] != pid: + record.vllm_process_name = record.processName + else: + record.vllm_process_name = process_info[0] + return record def set_vllm_process_name(process_name: str, *, skip_if_set: bool = False) -> None: @@ -220,7 +224,9 @@ def _configure_vllm_root_logger(config: "LoggingConfig | None" = None) -> None: ) if configure_logging: - logging.setLogRecordFactory(_vllm_log_record_factory) + factory = logging.getLogRecordFactory() + if not isinstance(factory, _VllmLogRecordFactory): + logging.setLogRecordFactory(_VllmLogRecordFactory(factory)) logging_config = deepcopy(DEFAULT_LOGGING_CONFIG) vllm_handler = logging_config["handlers"]["vllm"]