[Bugfix][Logging] Preserve application log record factories (#58747)

Signed-off-by: mgoin <mgoin64@gmail.com>
Co-authored-by: OpenAI Codex <noreply@openai.com>

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):

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"]