From c087f9d509fd903759b25b5e81b4a999a89a6ed3 Mon Sep 17 00:00:00 2001 From: Danny Guinther Date: Fri, 12 Apr 2024 15:02:24 -0400 Subject: [PATCH 1/8] Move logger.py to logger/__init__.py to prepare for rework --- tests/test_logger.py | 30 +++++++++++++++++++++++++- vllm/{logger.py => logger/__init__.py} | 0 2 files changed, 29 insertions(+), 1 deletion(-) rename vllm/{logger.py => logger/__init__.py} (100%) diff --git a/tests/test_logger.py b/tests/test_logger.py index 601f72b50811c..45883ddc2e206 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -1,8 +1,10 @@ +import logging import os import sys import tempfile -from vllm.logger import enable_trace_function_call +from vllm.logger import (_DATE_FORMAT, _FORMAT, NewLineFormatter, + enable_trace_function_call, init_logger) def f1(x): @@ -25,3 +27,29 @@ def test_trace_function_call(): assert "f2" in content sys.settrace(None) os.remove(path) + + +def test_vllm_root_logger_configuration(): + logger = logging.getLogger("vllm") + assert logger.level == logging.DEBUG + assert not logger.propagate + + handler = logger.handlers[0] + assert handler.stream == sys.stdout + assert handler.level == logging.INFO + + formatter = handler.formatter + assert formatter is not None + assert isinstance(formatter, NewLineFormatter) + assert formatter._fmt == _FORMAT + assert formatter.datefmt == _DATE_FORMAT + + +def test_init_logger_configures_the_logger_like_the_root_logger(): + root_logger = logging.getLogger("vllm") + logger = init_logger(__name__) + + assert logger.name == __name__ + assert logger.level == logging.DEBUG + assert logger.handlers == root_logger.handlers + assert logger.propagate == root_logger.propagate diff --git a/vllm/logger.py b/vllm/logger/__init__.py similarity index 100% rename from vllm/logger.py rename to vllm/logger/__init__.py From f5810a198cd0d2eec903eca8cf6ccdb0dbb14f06 Mon Sep 17 00:00:00 2001 From: Danny Guinther Date: Fri, 12 Apr 2024 15:31:10 -0400 Subject: [PATCH 2/8] Rework logger to enable more pythonic logging configuration --- tests/test_logger.py | 5 +- vllm/logger/__init__.py | 89 +++++++++++++++--------------- vllm/logging/__init__.py | 5 ++ vllm/logging/new_line_formatter.py | 15 +++++ 4 files changed, 67 insertions(+), 47 deletions(-) create mode 100644 vllm/logging/__init__.py create mode 100644 vllm/logging/new_line_formatter.py diff --git a/tests/test_logger.py b/tests/test_logger.py index 45883ddc2e206..c077ec1c7e9a6 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -3,8 +3,9 @@ import sys import tempfile -from vllm.logger import (_DATE_FORMAT, _FORMAT, NewLineFormatter, - enable_trace_function_call, init_logger) +from vllm.logger import (_DATE_FORMAT, _FORMAT, enable_trace_function_call, + init_logger) +from vllm.logging import NewLineFormatter def f1(x): diff --git a/vllm/logger/__init__.py b/vllm/logger/__init__.py index 046f0e9099a4b..c3217cdc084d0 100644 --- a/vllm/logger/__init__.py +++ b/vllm/logger/__init__.py @@ -1,11 +1,11 @@ -# Adapted from -# https://github.com/skypilot-org/skypilot/blob/86dc0f6283a335e4aa37b3c10716f90999f48ab6/sky/sky_logging.py """Logging configuration for vLLM.""" import datetime import logging import os import sys from functools import partial +from logging import Logger +from logging import config as logging_config from typing import Optional VLLM_CONFIGURE_LOGGING = int(os.getenv("VLLM_CONFIGURE_LOGGING", "1")) @@ -13,59 +13,58 @@ _FORMAT = "%(levelname)s %(asctime)s %(filename)s:%(lineno)d] %(message)s" _DATE_FORMAT = "%m-%d %H:%M:%S" - -class NewLineFormatter(logging.Formatter): - """Adds logging prefix to newlines to align multi-line messages.""" - - def __init__(self, fmt, datefmt=None): - logging.Formatter.__init__(self, fmt, datefmt) - - def format(self, record): - msg = logging.Formatter.format(self, record) - if record.message != "": - parts = msg.split(record.message) - msg = msg.replace("\n", "\r\n" + parts[0]) - return msg - - -_root_logger = logging.getLogger("vllm") -_default_handler: Optional[logging.Handler] = None - - -def _setup_logger(): - _root_logger.setLevel(logging.DEBUG) - global _default_handler - if _default_handler is None: - _default_handler = logging.StreamHandler(sys.stdout) - _default_handler.flush = sys.stdout.flush # type: ignore - _default_handler.setLevel(logging.INFO) - _root_logger.addHandler(_default_handler) - fmt = NewLineFormatter(_FORMAT, datefmt=_DATE_FORMAT) - _default_handler.setFormatter(fmt) - # Setting this will avoid the message - # being propagated to the parent logger. - _root_logger.propagate = False +DEFAULT_LOGGING_CONFIG = { + "formatters": { + "vllm": { + "class": "vllm.logging.NewLineFormatter", + "datefmt": _DATE_FORMAT, + "format": _FORMAT, + }, + }, + "handlers": { + "vllm": { + "class": "logging.StreamHandler", + "formatter": "vllm", + "level": "INFO", + "stream": "ext://sys.stdout", + }, + }, + "loggers": { + "vllm": { + "handlers": ["vllm"], + "level": "DEBUG", + "propagate": False, + }, + }, + "version": 1, +} + + +def _configure_vllm_root_logger() -> None: + logging_config.dictConfig(DEFAULT_LOGGING_CONFIG) # The logger is initialized when the module is imported. # This is thread-safe as the module is only imported once, # guaranteed by the Python GIL. if VLLM_CONFIGURE_LOGGING: - _setup_logger() + _configure_vllm_root_logger() -def init_logger(name: str): - # Use the same settings as above for root logger - logger = logging.getLogger(name) - logger.setLevel(os.getenv("LOG_LEVEL", "DEBUG")) +def _configure_vllm_logger(logger: Logger) -> None: + # Use the same settings as for root logger + _root_logger = logging.getLogger("vllm") + default_log_level = os.getenv("LOG_LEVEL", _root_logger.level) + logger.setLevel(default_log_level) + for handler in _root_logger.handlers: + logger.addHandler(handler) + logger.propagate = _root_logger.propagate + +def init_logger(name: str) -> Logger: + logger = logging.getLogger(name) if VLLM_CONFIGURE_LOGGING: - if _default_handler is None: - raise ValueError( - "_default_handler is not set up. This should never happen!" - " Please open an issue on Github.") - logger.addHandler(_default_handler) - logger.propagate = False + _configure_vllm_logger(logger) return logger diff --git a/vllm/logging/__init__.py b/vllm/logging/__init__.py new file mode 100644 index 0000000000000..133f3d7f8d206 --- /dev/null +++ b/vllm/logging/__init__.py @@ -0,0 +1,5 @@ +from vllm.logging.new_line_formatter import NewLineFormatter + +__all__ = [ + "NewLineFormatter", +] diff --git a/vllm/logging/new_line_formatter.py b/vllm/logging/new_line_formatter.py new file mode 100644 index 0000000000000..b24b4e11d1fcb --- /dev/null +++ b/vllm/logging/new_line_formatter.py @@ -0,0 +1,15 @@ +import logging + + +class NewLineFormatter(logging.Formatter): + """Adds logging prefix to newlines to align multi-line messages.""" + + def __init__(self, fmt, datefmt=None, style="%"): + logging.Formatter.__init__(self, fmt, datefmt, style) + + def format(self, record): + msg = logging.Formatter.format(self, record) + if record.message != "": + parts = msg.split(record.message) + msg = msg.replace("\n", "\r\n" + parts[0]) + return msg From fae8bf307827e467186ccfa76ea0860fbd5c96ce Mon Sep 17 00:00:00 2001 From: Danny Guinther Date: Wed, 17 Apr 2024 10:55:19 -0400 Subject: [PATCH 3/8] Extend logger to read logging config as specified by VLLM_LOGGING_CONFIG_PATH --- examples/logging_configuration.md | 234 ++++++++++++++++++++++++++++++ tests/test_logger.py | 196 ++++++++++++++++++++++++- vllm/logger/__init__.py | 42 ++++-- 3 files changed, 455 insertions(+), 17 deletions(-) create mode 100644 examples/logging_configuration.md diff --git a/examples/logging_configuration.md b/examples/logging_configuration.md new file mode 100644 index 0000000000000..d8d6b85263f0f --- /dev/null +++ b/examples/logging_configuration.md @@ -0,0 +1,234 @@ +# Logging Configuration + +vLLM leverages Python's `logging.config.dictConfig` functionality to enable +robust and flexible configuration of the various loggers used by vLLM. + +vLLM offers two environment variables that can be used, individually or in +combination, to accommodate a range of logging configurations that vary in +flexibility from: + +- vLLM's default logging configuration (least flexible) +- coarse grained custom logging configuration +- fine-grained custom logging configuration (most flexible) + + +## Logging Configuration Environment Variables + +### `VLLM_CONFIGURE_LOGGING` + +`VLLM_CONFIGURE_LOGGING` controls whether or not vLLM propagates configuration +from the root vLLM logger ("vllm") to other loggers used by vLLM. This +functionality is enabled by default, but can be disabled by setting +`VLLM_CONFIGURE_LOGGING=0` when running vLLM. + +If `VLLM_CONFIGURE_LOGGING` is enabled and no value is given for +`VLLM_LOGGING_CONFIG_PATH`, vLLM will use built-in default configuration to +configure the root vLLM logger and will use that same configuration when +configuring other loggers used by vLLM. + +### `VLLM_LOGGING_CONFIG_PATH` + +`VLLM_LOGGING_CONFIG_PATH` allows users to specify a path to a JSON file of +alternative, custom logging configuration that will be used instead of vLLM's +default logging configuration. The logging configuration should be provided in +JSON format following the schema specified by Python's [logging configuration +dictionary schema](https://docs.python.org/3/library/logging.config.html#dictionary-schema-details). + +If `VLLM_LOGGING_CONFIG_PATH` is specified, but `VLLM_CONFIGURE_LOGGING` is +disabled, vLLM will apply the given logging configuration, but will take no +additional actions to propagate configuration from the root vLLM logger to +other vLLM loggers. + +If `VLLM_LOGGING_CONFIG_PATH` is specified and `VLLM_CONFIGURE_LOGGING` is +enabled, vLLm will only configure loggers that were not created when applying +`logging.config.dictConfig` (or by other means) to ensure that custom +configuration of vLLM loggers is not overwritten. + + +## Examples + +### Example 1: Customize vLLM root logger and propagate to other vLLM loggers + +For this example, we will customize the vLLM root logger to use +[`python-json-logger`](https://github.com/madzak/python-json-logger) to log to +STDOUT of the console in JSON format with a log level of `INFO`. + +Because `VLLM_CONFIGURE_LOGGING` is enabled by default, the configuration we +apply to the vLLM root logger will be used when configuring other vLLM loggers, +effectively making it so all vLLM loggers log to STDOUT of the console in JSON +format. + +To begin, first, create an appropriate JSON logging configuration file: + +**/path/to/logging_config.json:** + +```json +{ + "formatters": { + "json": { + "class": "pythonjsonlogger.jsonlogger.JsonFormatter" + } + }, + "handlers": { + "console": { + "class" : "logging.StreamHandler", + "formatter": "json", + "level": "INFO", + "stream": "ext://sys.stdout" + } + }, + "loggers": { + "vllm": { + "handlers": ["console"], + "level": "INFO", + "propagate": false + } + }, + "version": 1 +} +``` + +Next, install the `python-json-logger` package if it's not already installed: + +```bash +pip install python-json-logger +``` + +Finally, run vLLM with the `VLLM_LOGGING_CONFIG_PATH` environment variable set +to the path of the custom logging configuration JSON file: + +```bash +VLLM_LOGGING_CONFIG_PATH=/path/to/logging_config.json \ + python3 -m vllm.entrypoints.openai.api_server \ + --max-model-len 2048 \ + --model mistralai/Mistral-7B-v0.1 +``` + + +### Example 2: Silence a particular vLLM logger + +To silence a particular vLLM logger, it is necessary to provide custom logging +configuration for the target logger that configures the logger to have no +handlers. When custom configuration is provided for any logger, it is also +necessary to provide configuration for the root vLLM logger since any custom +logger configuration overrides the default logging configuration behavior of +vLLM. + +First, create an appropriate JSON logging configuration file that includes +configuration for the root vLLM logger and for the logger you wish to silence: + +**/path/to/logging_config.json:** + +```json +{ + "formatters": { + "vllm": { + "class": "vllm.logging.NewLineFormatter", + "datefmt": "%m-%d %H:%M:%S", + "format": "%(levelname)s %(asctime)s %(filename)s:%(lineno)d] %(message)s" + } + }, + "handlers": { + "vllm": { + "class" : "logging.StreamHandler", + "formatter": "vllm", + "level": "INFO", + "stream": "ext://sys.stdout" + } + }, + "loggers": { + "vllm": { + "handlers": ["vllm"], + "level": "DEBUG", + "propagage": false + }, + "vllm.example_noisy_logger": { + "handlers": [] + } + }, + "version": 1 +} +``` + +Finally, run vLLM with the `VLLM_LOGGING_CONFIG_PATH` environment variable set +to the path of the custom logging configuration JSON file: + +```bash +VLLM_LOGGING_CONFIG_PATH=/path/to/logging_config.json \ + python3 -m vllm.entrypoints.openai.api_server \ + --max-model-len 2048 \ + --model mistralai/Mistral-7B-v0.1 +``` + + +### Example 3: Configure root vLLM logger without configuring other vLLM loggers + +This example is very similar to example 2, except it sets +`VLLM_CONFIGURE_LOGGING=0` to prevent vLLM from copying logging configuration +from the root vLLM logger to other vLLM loggers. + +First, create an appropriate JSON logging configuration file that includes +configuration for the root vLLM logger and any other loggers you wish to +configure: + +**/path/to/logging_config.json:** + +```json +{ + "formatters": { + "vllm": { + "class": "vllm.logging.NewLineFormatter", + "datefmt": "%m-%d %H:%M:%S", + "format": "%(levelname)s %(asctime)s %(filename)s:%(lineno)d] %(message)s" + } + }, + "handlers": { + "vllm": { + "class" : "logging.StreamHandler", + "formatter": "vllm", + "level": "WARN", + "stream": "ext://sys.stderr" + } + }, + "loggers": { + "vllm": { + "handlers": ["vllm"], + "level": "WARN", + "propagage": false + } + }, + "version": 1 +} +``` + +Finally, run vLLM with the `VLLM_LOGGING_CONFIG_PATH` environment variable set +to the path of the custom logging configuration JSON file and the +`VLLM_CONFIGURE_LOGGING` environment variable set to `0`: + +```bash +VLLM_CONFIGURE_LOGGING=0 \ + VLLM_LOGGING_CONFIG_PATH=/path/to/logging_config.json \ + python3 -m vllm.entrypoints.openai.api_server \ + --max-model-len 2048 \ + --model mistralai/Mistral-7B-v0.1 +``` + + +### Example 4: Disable vLLM default logging configuration + +To disable vLLM's default configuration of loggers, simple set +`VLLM_CONFIGURE_LOGGING=0` when running vLLM. This will prevent vLLM for +configuring the root vLLM logger and from taking any configuration actions on +other vLLM loggers. + +```bash +VLLM_CONFIGURE_LOGGING=0 \ + python3 -m vllm.entrypoints.openai.api_server \ + --max-model-len 2048 \ + --model mistralai/Mistral-7B-v0.1 +``` + + +## Additional resources + +- [`logging.config` Dictionary Schema Details](https://docs.python.org/3/library/logging.config.html#dictionary-schema-details) diff --git a/tests/test_logger.py b/tests/test_logger.py index c077ec1c7e9a6..b3bc20f29cd1a 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -1,10 +1,18 @@ +import json import logging import os import sys import tempfile +from json.decoder import JSONDecodeError +from tempfile import NamedTemporaryFile +from typing import Any +from unittest.mock import patch +from uuid import uuid4 -from vllm.logger import (_DATE_FORMAT, _FORMAT, enable_trace_function_call, - init_logger) +import pytest + +from vllm.logger import (_DATE_FORMAT, _FORMAT, _configure_vllm_root_logger, + enable_trace_function_call, init_logger) from vllm.logging import NewLineFormatter @@ -30,7 +38,10 @@ def test_trace_function_call(): os.remove(path) -def test_vllm_root_logger_configuration(): +def test_default_vllm_root_logger_configuration(): + """This test presumes that VLLM_CONFIGURE_LOGGING and + VLLM_LOGGING_CONFIG_PATH are not configured and default behavior is + activated""" logger = logging.getLogger("vllm") assert logger.level == logging.DEBUG assert not logger.propagate @@ -46,11 +57,182 @@ def test_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_init_logger_configures_the_logger_like_the_root_logger(): + """This test requires VLLM_CONFIGURE_LOGGING to be enabled. + VLLM_LOGGING_CONFIG_PATH may be configured, but is presumed to be + unimpactful since a random logger name is used for testing.""" root_logger = logging.getLogger("vllm") - logger = init_logger(__name__) + unique_name = str(uuid4()) + logger = init_logger(unique_name) - assert logger.name == __name__ - assert logger.level == logging.DEBUG + assert logger.name == unique_name + assert logger.level == root_logger.level assert logger.handlers == root_logger.handlers - assert logger.propagate == root_logger.propagate + assert not logger.propagate + + +@patch("vllm.logger.VLLM_CONFIGURE_LOGGING", 0) +@patch("vllm.logger.VLLM_LOGGING_CONFIG_PATH", None) +def test_logger_configuring_can_be_disabled(): + logger_name = unique_name() + assert logger_name not in logging.Logger.manager.loggerDict + logger = init_logger(logger_name) + assert logger_name in logging.Logger.manager.loggerDict + + assert logger.name == logger_name + assert len(logger.handlers) == 0 + + +@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(): + """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.""" + with pytest.raises(RuntimeError) as ex_info: + _configure_vllm_root_logger() + assert ex_info.type == RuntimeError + 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(): + """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.""" + 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) + + +@patch("vllm.logger.VLLM_CONFIGURE_LOGGING", 1) +@pytest.mark.parametrize("unexpected_config", ( + "Invalid string", + [{ + "version": 1, + "loggers": [] + }], + 0, +)) +def test_an_error_is_raised_when_custom_logging_config_is_unexpected_json( + 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.""" + 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 + 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(): + """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.""" + valid_logging_config = { + "loggers": { + "vllm.test_logger.logger": { + "handlers": [], + "propagate": False, + } + }, + "version": 1 + } + 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( + "logging.config.dictConfig") as dict_config_mock: + _configure_vllm_root_logger() + assert dict_config_mock.called_with(valid_logging_config) + + +@patch("vllm.logger.VLLM_CONFIGURE_LOGGING", 1) +def test_init_logger_does_not_configure_loggers_configured_by_logging_config(): + """This test calls _configure_vllm_root_logger again to test custom logging + config behavior, the call is not intercepted, but should only impact a + logger only known to this test.""" + logger_name = f"vllm.test_logger.{unique_name()}" + valid_logging_config = { + "loggers": { + logger_name: { + "handlers": [], + "level": "INFO", + "propagate": True, + } + }, + "version": 1 + } + 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): + _configure_vllm_root_logger() + root_logger = logging.getLogger("vllm") + test_logger = logging.getLogger(logger_name) + assert len(test_logger.handlers) == 0 + assert len(root_logger.handlers) > 0 + assert test_logger.level == logging.INFO + assert test_logger.level != root_logger.level + assert test_logger.propagate + + # Make sure auto-configuration of other loggers still works + other_logger = init_logger("vllm.test_logger.other") + assert other_logger.handlers == root_logger.handlers + assert other_logger.level == root_logger.level + assert not other_logger.propagate + + +@patch("vllm.logger.VLLM_CONFIGURE_LOGGING", 0) +def test_custom_logging_config_can_be_used_even_if_configure_logging_is_off(): + """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.""" + valid_logging_config = { + "loggers": { + "vllm.test_logger.logger": { + "handlers": [], + } + }, + "version": 1 + } + 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( + "logging.config.dictConfig") as dict_config_mock: + _configure_vllm_root_logger() + assert dict_config_mock.called_with(valid_logging_config) + + # Remember! The root logger is assumed to have been configured as + # though VLLM_CONFIGURE_LOGGING=1 and VLLM_LOGGING_CONFIG_PATH=None. + root_logger = logging.getLogger("vllm") + other_logger_name = f"vllm.test_logger.{unique_name()}" + other_logger = init_logger(other_logger_name) + assert other_logger.handlers != root_logger.handlers + assert other_logger.level != root_logger.level + assert other_logger.propagate + + +def unique_name() -> str: + return str(uuid4()) diff --git a/vllm/logger/__init__.py b/vllm/logger/__init__.py index c3217cdc084d0..5314fa400949e 100644 --- a/vllm/logger/__init__.py +++ b/vllm/logger/__init__.py @@ -1,14 +1,17 @@ """Logging configuration for vLLM.""" import datetime +import json import logging import os import sys from functools import partial from logging import Logger -from logging import config as logging_config -from typing import Optional +from logging.config import dictConfig +from os import path +from typing import Dict, Optional VLLM_CONFIGURE_LOGGING = int(os.getenv("VLLM_CONFIGURE_LOGGING", "1")) +VLLM_LOGGING_CONFIG_PATH = os.getenv("VLLM_LOGGING_CONFIG_PATH") _FORMAT = "%(levelname)s %(asctime)s %(filename)s:%(lineno)d] %(message)s" _DATE_FORMAT = "%m-%d %H:%M:%S" @@ -41,14 +44,25 @@ def _configure_vllm_root_logger() -> None: - logging_config.dictConfig(DEFAULT_LOGGING_CONFIG) + if VLLM_CONFIGURE_LOGGING: + logging_config: Dict = DEFAULT_LOGGING_CONFIG + if VLLM_LOGGING_CONFIG_PATH: + if not path.exists(VLLM_LOGGING_CONFIG_PATH): + raise RuntimeError( + "Could not load logging config. File does not exist:" + f" {VLLM_LOGGING_CONFIG_PATH}") + with open(VLLM_LOGGING_CONFIG_PATH, encoding="utf-8", + mode="r") as file: + custom_config = json.loads(file.read()) -# The logger is initialized when the module is imported. -# This is thread-safe as the module is only imported once, -# guaranteed by the Python GIL. -if VLLM_CONFIGURE_LOGGING: - _configure_vllm_root_logger() + if not isinstance(custom_config, dict): + raise ValueError("Invalid logging config. Expected Dict, got" + f" {type(custom_config).__name__}.") + logging_config = custom_config + + if logging_config: + dictConfig(logging_config) def _configure_vllm_logger(logger: Logger) -> None: @@ -58,16 +72,24 @@ def _configure_vllm_logger(logger: Logger) -> None: logger.setLevel(default_log_level) for handler in _root_logger.handlers: logger.addHandler(handler) - logger.propagate = _root_logger.propagate + logger.propagate = False def init_logger(name: str) -> Logger: + logger_is_new = name not in logging.Logger.manager.loggerDict logger = logging.getLogger(name) - if VLLM_CONFIGURE_LOGGING: + if VLLM_CONFIGURE_LOGGING and logger_is_new: _configure_vllm_logger(logger) return logger +# The logger is initialized when the module is imported. +# This is thread-safe as the module is only imported once, +# guaranteed by the Python GIL. +if VLLM_CONFIGURE_LOGGING: + _configure_vllm_root_logger() + + logger = init_logger(__name__) From 5dd50494a361bf1310002a16696b6624e739ba03 Mon Sep 17 00:00:00 2001 From: Danny Guinther Date: Mon, 22 Apr 2024 16:12:22 -0400 Subject: [PATCH 4/8] Move logger back to vllm/logger --- vllm/{logger/__init__.py => logger.py} | 0 1 file changed, 0 insertions(+), 0 deletions(-) rename vllm/{logger/__init__.py => logger.py} (100%) diff --git a/vllm/logger/__init__.py b/vllm/logger.py similarity index 100% rename from vllm/logger/__init__.py rename to vllm/logger.py From db2dee3cf5337bc402fb9e38e9214b05cf5713bb Mon Sep 17 00:00:00 2001 From: Danny Guinther Date: Mon, 22 Apr 2024 16:20:40 -0400 Subject: [PATCH 5/8] Fix logging auto-load logic that was lost in merge conflict --- vllm/logger.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/vllm/logger.py b/vllm/logger.py index 5314fa400949e..12cd747fab217 100644 --- a/vllm/logger.py +++ b/vllm/logger.py @@ -86,10 +86,9 @@ def init_logger(name: str) -> Logger: # The logger is initialized when the module is imported. # This is thread-safe as the module is only imported once, # guaranteed by the Python GIL. -if VLLM_CONFIGURE_LOGGING: +if VLLM_CONFIGURE_LOGGING or VLLM_LOGGING_CONFIG_PATH: _configure_vllm_root_logger() - logger = init_logger(__name__) From 169f31ea1b8acb6884b4f03718048dff922e9815 Mon Sep 17 00:00:00 2001 From: Danny Guinther Date: Wed, 1 May 2024 10:24:20 -0400 Subject: [PATCH 6/8] Move new_line_formatter.py to formatter.py for future formatters --- vllm/logging/__init__.py | 2 +- vllm/logging/{new_line_formatter.py => formatter.py} | 0 2 files changed, 1 insertion(+), 1 deletion(-) rename vllm/logging/{new_line_formatter.py => formatter.py} (100%) diff --git a/vllm/logging/__init__.py b/vllm/logging/__init__.py index 133f3d7f8d206..b9aec380776f3 100644 --- a/vllm/logging/__init__.py +++ b/vllm/logging/__init__.py @@ -1,4 +1,4 @@ -from vllm.logging.new_line_formatter import NewLineFormatter +from vllm.logging.formatter import NewLineFormatter __all__ = [ "NewLineFormatter", diff --git a/vllm/logging/new_line_formatter.py b/vllm/logging/formatter.py similarity index 100% rename from vllm/logging/new_line_formatter.py rename to vllm/logging/formatter.py From ee19e2dd5655a5ee5203084bad2eedc2194901ec Mon Sep 17 00:00:00 2001 From: Danny Guinther Date: Wed, 1 May 2024 13:53:53 -0400 Subject: [PATCH 7/8] Use logger propagation to ensure descendent loggers behave like root vllm logger --- examples/logging_configuration.md | 130 +++++++++--------------------- tests/test_logger.py | 102 ++++++++++------------- vllm/logger.py | 44 +++++----- 3 files changed, 99 insertions(+), 177 deletions(-) diff --git a/examples/logging_configuration.md b/examples/logging_configuration.md index d8d6b85263f0f..75b4b31a80462 100644 --- a/examples/logging_configuration.md +++ b/examples/logging_configuration.md @@ -3,61 +3,57 @@ vLLM leverages Python's `logging.config.dictConfig` functionality to enable robust and flexible configuration of the various loggers used by vLLM. -vLLM offers two environment variables that can be used, individually or in -combination, to accommodate a range of logging configurations that vary in -flexibility from: +vLLM offers two environment variables that can be used to accommodate a range +of logging configurations that range from simple-and-inflexible to +more-complex-and-more-flexible. -- vLLM's default logging configuration (least flexible) -- coarse grained custom logging configuration -- fine-grained custom logging configuration (most flexible) +- No vLLM logging (simple and inflexible) + - Set `VLLM_CONFIGURE_LOGGING=0` (leaving `VLLM_LOGGING_CONFIG_PATH` unset) +- vLLM's default logging configuration (simple and inflexible) + - Leave `VLLM_CONFIGURE_LOGGING` unset or set `VLLM_CONFIGURE_LOGGING=1` +- Fine-grained custom logging configuration (more complex, more flexible) + - Leave `VLLM_CONFIGURE_LOGGING` unset or set `VLLM_CONFIGURE_LOGGING=1` and + set `VLLM_LOGGING_CONFIG_PATH=` ## Logging Configuration Environment Variables ### `VLLM_CONFIGURE_LOGGING` -`VLLM_CONFIGURE_LOGGING` controls whether or not vLLM propagates configuration -from the root vLLM logger ("vllm") to other loggers used by vLLM. This -functionality is enabled by default, but can be disabled by setting -`VLLM_CONFIGURE_LOGGING=0` when running vLLM. +`VLLM_CONFIGURE_LOGGING` controls whether or not vLLM takes any action to +configure the loggers used by vLLM. This functionality is enabled by default, +but can be disabled by setting `VLLM_CONFIGURE_LOGGING=0` when running vLLM. If `VLLM_CONFIGURE_LOGGING` is enabled and no value is given for `VLLM_LOGGING_CONFIG_PATH`, vLLM will use built-in default configuration to -configure the root vLLM logger and will use that same configuration when -configuring other loggers used by vLLM. +configure the root vLLM logger. By default, no other vLLM loggers are +configured and, as such, all vLLM loggers defer to the root vLLM logger to make +all logging decisions. + +If `VLLM_CONFIGURE_LOGGING` is disabled and a value is given for +`VLLM_LOGGING_CONFIG_PATH`, an error will occur while starting vLLM. ### `VLLM_LOGGING_CONFIG_PATH` `VLLM_LOGGING_CONFIG_PATH` allows users to specify a path to a JSON file of alternative, custom logging configuration that will be used instead of vLLM's -default logging configuration. The logging configuration should be provided in -JSON format following the schema specified by Python's [logging configuration -dictionary schema](https://docs.python.org/3/library/logging.config.html#dictionary-schema-details). +built-in default logging configuration. The logging configuration should be +provided in JSON format following the schema specified by Python's [logging +configuration dictionary +schema](https://docs.python.org/3/library/logging.config.html#dictionary-schema-details). If `VLLM_LOGGING_CONFIG_PATH` is specified, but `VLLM_CONFIGURE_LOGGING` is -disabled, vLLM will apply the given logging configuration, but will take no -additional actions to propagate configuration from the root vLLM logger to -other vLLM loggers. - -If `VLLM_LOGGING_CONFIG_PATH` is specified and `VLLM_CONFIGURE_LOGGING` is -enabled, vLLm will only configure loggers that were not created when applying -`logging.config.dictConfig` (or by other means) to ensure that custom -configuration of vLLM loggers is not overwritten. +disabled, an error will occur while starting vLLM. ## Examples -### Example 1: Customize vLLM root logger and propagate to other vLLM loggers +### Example 1: Customize vLLM root logger For this example, we will customize the vLLM root logger to use [`python-json-logger`](https://github.com/madzak/python-json-logger) to log to STDOUT of the console in JSON format with a log level of `INFO`. -Because `VLLM_CONFIGURE_LOGGING` is enabled by default, the configuration we -apply to the vLLM root logger will be used when configuring other vLLM loggers, -effectively making it so all vLLM loggers log to STDOUT of the console in JSON -format. - To begin, first, create an appropriate JSON logging configuration file: **/path/to/logging_config.json:** @@ -108,11 +104,12 @@ VLLM_LOGGING_CONFIG_PATH=/path/to/logging_config.json \ ### Example 2: Silence a particular vLLM logger To silence a particular vLLM logger, it is necessary to provide custom logging -configuration for the target logger that configures the logger to have no -handlers. When custom configuration is provided for any logger, it is also -necessary to provide configuration for the root vLLM logger since any custom -logger configuration overrides the default logging configuration behavior of -vLLM. +configuration for the target logger that configures the logger so that it won't +propagate its log messages to the root vLLM logger. + +When custom configuration is provided for any logger, it is also necessary to +provide configuration for the root vLLM logger since any custom logger +configuration overrides the built-in default logging configuration used by vLLM. First, create an appropriate JSON logging configuration file that includes configuration for the root vLLM logger and for the logger you wish to silence: @@ -143,7 +140,7 @@ configuration for the root vLLM logger and for the logger you wish to silence: "propagage": false }, "vllm.example_noisy_logger": { - "handlers": [] + "propagate": false } }, "version": 1 @@ -161,65 +158,12 @@ VLLM_LOGGING_CONFIG_PATH=/path/to/logging_config.json \ ``` -### Example 3: Configure root vLLM logger without configuring other vLLM loggers - -This example is very similar to example 2, except it sets -`VLLM_CONFIGURE_LOGGING=0` to prevent vLLM from copying logging configuration -from the root vLLM logger to other vLLM loggers. - -First, create an appropriate JSON logging configuration file that includes -configuration for the root vLLM logger and any other loggers you wish to -configure: - -**/path/to/logging_config.json:** - -```json -{ - "formatters": { - "vllm": { - "class": "vllm.logging.NewLineFormatter", - "datefmt": "%m-%d %H:%M:%S", - "format": "%(levelname)s %(asctime)s %(filename)s:%(lineno)d] %(message)s" - } - }, - "handlers": { - "vllm": { - "class" : "logging.StreamHandler", - "formatter": "vllm", - "level": "WARN", - "stream": "ext://sys.stderr" - } - }, - "loggers": { - "vllm": { - "handlers": ["vllm"], - "level": "WARN", - "propagage": false - } - }, - "version": 1 -} -``` - -Finally, run vLLM with the `VLLM_LOGGING_CONFIG_PATH` environment variable set -to the path of the custom logging configuration JSON file and the -`VLLM_CONFIGURE_LOGGING` environment variable set to `0`: - -```bash -VLLM_CONFIGURE_LOGGING=0 \ - VLLM_LOGGING_CONFIG_PATH=/path/to/logging_config.json \ - python3 -m vllm.entrypoints.openai.api_server \ - --max-model-len 2048 \ - --model mistralai/Mistral-7B-v0.1 -``` - - -### Example 4: Disable vLLM default logging configuration +### Example 3: Disable vLLM default logging configuration -To disable vLLM's default configuration of loggers, simple set -`VLLM_CONFIGURE_LOGGING=0` when running vLLM. This will prevent vLLM for -configuring the root vLLM logger and from taking any configuration actions on -other vLLM loggers. +To disable vLLM's default logging configuration and silence all vLLM loggers, +simple set `VLLM_CONFIGURE_LOGGING=0` when running vLLM. This will prevent vLLM +for configuring the root vLLM logger, which in turn, silences all other vLLM +loggers. ```bash VLLM_CONFIGURE_LOGGING=0 \ diff --git a/tests/test_logger.py b/tests/test_logger.py index b3bc20f29cd1a..9532e07deac0b 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -39,9 +39,9 @@ def test_trace_function_call(): def test_default_vllm_root_logger_configuration(): - """This test presumes that VLLM_CONFIGURE_LOGGING and - VLLM_LOGGING_CONFIG_PATH are not configured and default behavior is - activated""" + """This test presumes that VLLM_CONFIGURE_LOGGING (default: True) and + VLLM_LOGGING_CONFIG_PATH (default: None) are not configured and default + behavior is activated.""" logger = logging.getLogger("vllm") assert logger.level == logging.DEBUG assert not logger.propagate @@ -59,30 +59,43 @@ def test_default_vllm_root_logger_configuration(): @patch("vllm.logger.VLLM_CONFIGURE_LOGGING", 1) @patch("vllm.logger.VLLM_LOGGING_CONFIG_PATH", None) -def test_init_logger_configures_the_logger_like_the_root_logger(): - """This test requires VLLM_CONFIGURE_LOGGING to be enabled. - VLLM_LOGGING_CONFIG_PATH may be configured, but is presumed to be - unimpactful since a random logger name is used for testing.""" +def test_descendent_loggers_depend_on_and_propagate_logs_to_root_logger(): + """This test presumes that VLLM_CONFIGURE_LOGGING (default: True) and + VLLM_LOGGING_CONFIG_PATH (default: None) are not configured and default + behavior is activated.""" root_logger = logging.getLogger("vllm") - unique_name = str(uuid4()) - logger = init_logger(unique_name) + root_handler = root_logger.handlers[0] + unique_name = f"vllm.{uuid4()}" + logger = init_logger(unique_name) assert logger.name == unique_name - assert logger.level == root_logger.level - assert logger.handlers == root_logger.handlers - assert not logger.propagate + assert logger.level == logging.NOTSET + assert not logger.handlers + assert logger.propagate + + message = "Hello, world!" + with patch.object(root_handler, "emit") as root_handle_mock: + logger.info(message) + + root_handle_mock.assert_called_once() + _, call_args, _ = root_handle_mock.mock_calls[0] + log_record = call_args[0] + assert unique_name == log_record.name + assert message == log_record.msg + assert message == log_record.msg + 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(): - logger_name = unique_name() - assert logger_name not in logging.Logger.manager.loggerDict - logger = init_logger(logger_name) - assert logger_name in logging.Logger.manager.loggerDict + """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.""" - assert logger.name == logger_name - assert len(logger.handlers) == 0 + with patch("logging.config.dictConfig") as dict_config_mock: + _configure_vllm_root_logger() + dict_config_mock.assert_not_called() @patch("vllm.logger.VLLM_CONFIGURE_LOGGING", 1) @@ -126,7 +139,7 @@ def test_an_error_is_raised_when_custom_logging_config_is_invalid_json(): 0, )) def test_an_error_is_raised_when_custom_logging_config_is_unexpected_json( - unexpected_config: Any, ): + 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.""" @@ -165,45 +178,8 @@ def test_custom_logging_config_is_parsed_and_used_when_provided(): assert dict_config_mock.called_with(valid_logging_config) -@patch("vllm.logger.VLLM_CONFIGURE_LOGGING", 1) -def test_init_logger_does_not_configure_loggers_configured_by_logging_config(): - """This test calls _configure_vllm_root_logger again to test custom logging - config behavior, the call is not intercepted, but should only impact a - logger only known to this test.""" - logger_name = f"vllm.test_logger.{unique_name()}" - valid_logging_config = { - "loggers": { - logger_name: { - "handlers": [], - "level": "INFO", - "propagate": True, - } - }, - "version": 1 - } - 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): - _configure_vllm_root_logger() - root_logger = logging.getLogger("vllm") - test_logger = logging.getLogger(logger_name) - assert len(test_logger.handlers) == 0 - assert len(root_logger.handlers) > 0 - assert test_logger.level == logging.INFO - assert test_logger.level != root_logger.level - assert test_logger.propagate - - # Make sure auto-configuration of other loggers still works - other_logger = init_logger("vllm.test_logger.other") - assert other_logger.handlers == root_logger.handlers - assert other_logger.level == root_logger.level - assert not other_logger.propagate - - @patch("vllm.logger.VLLM_CONFIGURE_LOGGING", 0) -def test_custom_logging_config_can_be_used_even_if_configure_logging_is_off(): +def test_custom_logging_config_causes_an_error_if_configure_logging_is_off(): """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.""" @@ -219,10 +195,14 @@ def test_custom_logging_config_can_be_used_even_if_configure_logging_is_off(): 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( - "logging.config.dictConfig") as dict_config_mock: - _configure_vllm_root_logger() - assert dict_config_mock.called_with(valid_logging_config) + 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/logger.py b/vllm/logger.py index 66fa6d837b243..40c29da2b70ce 100644 --- a/vllm/logger.py +++ b/vllm/logger.py @@ -44,50 +44,48 @@ def _configure_vllm_root_logger() -> None: + logging_config: Optional[Dict] = None + + if not VLLM_CONFIGURE_LOGGING and VLLM_LOGGING_CONFIG_PATH: + raise RuntimeError( + "VLLM_CONFIGURE_LOGGING evaluated to false, but " + "VLLM_LOGGING_CONFIG_PATH was given. VLLM_LOGGING_CONFIG_PATH " + "implies VLLM_CONFIGURE_LOGGING. Please enable " + "VLLM_CONFIGURE_LOGGING or unset VLLM_LOGGING_CONFIG_PATH.") + if VLLM_CONFIGURE_LOGGING: - logging_config: Dict = DEFAULT_LOGGING_CONFIG + logging_config = DEFAULT_LOGGING_CONFIG if VLLM_LOGGING_CONFIG_PATH: if not path.exists(VLLM_LOGGING_CONFIG_PATH): raise RuntimeError( - "Could not load logging config. File does not exist:" - f" {VLLM_LOGGING_CONFIG_PATH}") + "Could not load logging config. File does not exist: %s", + VLLM_LOGGING_CONFIG_PATH) with open(VLLM_LOGGING_CONFIG_PATH, encoding="utf-8", mode="r") as file: custom_config = json.loads(file.read()) if not isinstance(custom_config, dict): - raise ValueError("Invalid logging config. Expected Dict, got" - f" {type(custom_config).__name__}.") + raise ValueError("Invalid logging config. Expected Dict, got %s.", + type(custom_config).__name__) logging_config = custom_config if logging_config: dictConfig(logging_config) -def _configure_vllm_logger(logger: Logger) -> None: - # Use the same settings as for root logger - _root_logger = logging.getLogger("vllm") - default_log_level = os.getenv("LOG_LEVEL", _root_logger.level) - logger.setLevel(default_log_level) - for handler in _root_logger.handlers: - logger.addHandler(handler) - logger.propagate = False - - def init_logger(name: str) -> Logger: - logger_is_new = name not in logging.Logger.manager.loggerDict - logger = logging.getLogger(name) - if VLLM_CONFIGURE_LOGGING and logger_is_new: - _configure_vllm_logger(logger) - return logger + """The main purpose of this function is to ensure that loggers are + retrieved in such a way that we can be sure the root vllm logger has + already been configured.""" + + return logging.getLogger(name) -# The logger is initialized when the module is imported. +# The root logger is initialized when the module is imported. # This is thread-safe as the module is only imported once, # guaranteed by the Python GIL. -if VLLM_CONFIGURE_LOGGING or VLLM_LOGGING_CONFIG_PATH: - _configure_vllm_root_logger() +_configure_vllm_root_logger() logger = init_logger(__name__) From cf18a667f347d925d3a72161694527a84587d0a6 Mon Sep 17 00:00:00 2001 From: Danny Guinther Date: Wed, 1 May 2024 14:30:05 -0400 Subject: [PATCH 8/8] Remove unneeded helper method --- tests/test_logger.py | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/tests/test_logger.py b/tests/test_logger.py index 9532e07deac0b..74f1125fb37c9 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -207,12 +207,8 @@ def test_custom_logging_config_causes_an_error_if_configure_logging_is_off(): # Remember! The root logger is assumed to have been configured as # though VLLM_CONFIGURE_LOGGING=1 and VLLM_LOGGING_CONFIG_PATH=None. root_logger = logging.getLogger("vllm") - other_logger_name = f"vllm.test_logger.{unique_name()}" + other_logger_name = f"vllm.test_logger.{uuid4()}" other_logger = init_logger(other_logger_name) assert other_logger.handlers != root_logger.handlers assert other_logger.level != root_logger.level assert other_logger.propagate - - -def unique_name() -> str: - return str(uuid4())