diff --git a/.buildkite/test_areas/misc.yaml b/.buildkite/test_areas/misc.yaml index 0c0e8c9a4d..dea2ca7a6f 100644 --- a/.buildkite/test_areas/misc.yaml +++ b/.buildkite/test_areas/misc.yaml @@ -530,7 +530,7 @@ steps: - vllm/v1/ - vllm/version.py - cmake/utils.cmake - - tests/test_access_log_filter.py + - tests/test_uvicorn_logging.py - tests/test_attention_backend_registry.py - tests/test_audio_media_size_precheck.py - tests/test_cmake_utils.py @@ -571,7 +571,7 @@ steps: - pip install cmake # test_cmake_utils.py shells out to cmake; the CPU image has none - python3 standalone_tests/lazy_imports.py - pytest -v -s device_allocator - - pytest -v -s test_access_log_filter.py + - pytest -v -s test_uvicorn_logging.py - pytest -v -s test_attention_backend_registry.py - pytest -v -s test_audio_media_size_precheck.py - pytest -v -s test_cmake_utils.py diff --git a/examples/features/logging_configuration.md b/examples/features/logging_configuration.md index f2e1e5b8a0..ee2d16aba0 100644 --- a/examples/features/logging_configuration.md +++ b/examples/features/logging_configuration.md @@ -6,6 +6,7 @@ robust and flexible configuration of the various loggers used by vLLM. For `vllm serve`, configure logging with CLI arguments: - Use the built-in configuration, optionally with `--log-level`. +- Emit structured JSON with `--logging-config.formatter json`. - Use a custom Python logging configuration file with `--logging-config.pylogging_config_file`. - Disable vLLM logging configuration with @@ -14,7 +15,7 @@ For `vllm serve`, configure logging with CLI arguments: ## CLI logging configuration `--logging-config` accepts a JSON object. Its fields are `log_level`, -`configure_logging`, and `pylogging_config_file`. For example: +`formatter`, `configure_logging`, and `pylogging_config_file`. For example: ```bash vllm serve mistralai/Mistral-7B-v0.1 \ @@ -28,6 +29,25 @@ vllm serve mistralai/Mistral-7B-v0.1 \ --logging-config.log_level DEBUG ``` +The built-in `text` formatter is selected by default. To emit one JSON object +per vLLM and Uvicorn log record, select the built-in `json` formatter: + +```bash +vllm serve mistralai/Mistral-7B-v0.1 \ + --logging-config.formatter json +``` + +The built-in JSON output includes `asctime`, `levelname`, `name`, +`processName`, `process`, `message`, and `vllm_process_name`. `processName` is +Python's process name, `vllm_process_name` identifies vLLM's logical process +(including worker ranks where applicable), and `process` is the +operating-system PID. + +The built-in profile formats records emitted through vLLM's Python loggers and +Uvicorn's server and access loggers when using `vllm serve`. It does not convert +direct writes to `stdout` or `stderr`. Use a custom configuration to format +other loggers. + `--log-level` is a shortcut for `--logging-config.log_level` and takes precedence if both are supplied. It sets the level of vLLM's built-in logging configuration. `--log-config-file` is deprecated and will be removed in @@ -41,11 +61,11 @@ The custom logging configuration file must be JSON following Python's [logging configuration dictionary schema](https://docs.python.org/3/library/logging.config.html#dictionary-schema-details). -!!! note "Custom configurations override `--log-level`" +!!! note "Custom configurations override built-in formatter settings" When `pylogging_config_file` is set, vLLM loads that JSON file and replaces - its built-in `dictConfig`; it does not merge the two. Therefore, - `--log-level` applies only when no custom configuration file is provided. - Set logger and handler levels in the custom file itself. vLLM applies the + its built-in `dictConfig`; it does not merge the two. Therefore, `log_level` + and `formatter` apply only when no custom configuration file is provided. + Set levels and formatters in the custom file itself. vLLM applies the resolved configuration in its child processes as well. ## Environment variables @@ -62,10 +82,11 @@ for those settings. ### Example 1: Customize vLLM root logger -For this example, we will customize the vLLM root logger to use +For more control over fields and handlers, configure the vLLM root logger and +Uvicorn's server and access loggers with [`python-json-logger`](https://github.com/nhairs/python-json-logger) -(which is part of the container image) to log to -STDOUT of the console in JSON format with a log level of `INFO`. +(which is part of the container image) to log to STDOUT in JSON format at +`INFO` level. To begin, first, create an appropriate JSON logging configuration file: @@ -92,8 +113,24 @@ To begin, first, create an appropriate JSON logging configuration file: "handlers": ["console"], "level": "INFO", "propagate": false + }, + "uvicorn": { + "handlers": ["console"], + "level": "INFO", + "propagate": false + }, + "uvicorn.error": { + "handlers": ["console"], + "level": "INFO", + "propagate": false + }, + "uvicorn.access": { + "handlers": ["console"], + "level": "INFO", + "propagate": false } }, + "disable_existing_loggers": false, "version": 1 } ``` @@ -105,21 +142,20 @@ vllm serve mistralai/Mistral-7B-v0.1 --max-model-len 2048 \ --logging-config.pylogging_config_file /path/to/logging_config.json ``` -Each vLLM log record is one JSON object and includes `vllm_process_name`, which -identifies vLLM's logical process (including worker ranks where applicable). -The standard `process` record attribute contains the operating-system PID. -vLLM avoids altering `stdout` or `stderr`, so no text is prepended to JSON -log records. +With this custom configuration, each vLLM and Uvicorn log record is one JSON +object. The example selects `vllm_process_name` and `process` explicitly; both +fields are also present in the built-in JSON output described above. vLLM +avoids altering `stdout` or `stderr`, so no text is prepended to JSON log +records. This applies to records emitted through the configured Python loggers. A JSON formatter cannot convert unrelated output into JSON, such as a third-party library writing directly to `stdout` or `stderr`; configure or route such output separately when a consumer requires every collected line to be JSON. -When serving, `VLLM_LOGGING_CONFIG_PATH` is also used as Uvicorn's logging -configuration. This example configures only `vllm`; configure `uvicorn`, -`uvicorn.error`, and `uvicorn.access` with a JSON handler when those server -logs must also be structured. +When serving, vLLM also passes this file to Uvicorn as its logging +configuration. The `uvicorn`, `uvicorn.error`, and `uvicorn.access` entries +format its server and access logs as JSON. ### Example 2: Silence a particular vLLM logger diff --git a/tests/entrypoints/launchers/test_cli_args.py b/tests/entrypoints/launchers/test_cli_args.py index de32e82ba4..97c1aa5fc7 100644 --- a/tests/entrypoints/launchers/test_cli_args.py +++ b/tests/entrypoints/launchers/test_cli_args.py @@ -76,6 +76,8 @@ def test_logging_config_cli_args(serve_parser): [ "--logging-config", '{"log_level":"WARNING","pylogging_config_file":"/tmp/json.json"}', + "--logging-config.formatter", + "json", "--log-level", "DEBUG", "--log-config-file", @@ -85,6 +87,7 @@ def test_logging_config_cli_args(serve_parser): config = AsyncEngineArgs.from_cli_args(args).create_logging_config() assert config.log_level == "DEBUG" + assert config.formatter == "json" assert config.pylogging_config_file == "/tmp/flat.json" diff --git a/tests/test_logger.py b/tests/test_logger.py index f194853fa4..2a2f9d34be 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -4,6 +4,7 @@ import enum import io import json import logging +import multiprocessing import os import sys import tempfile @@ -21,6 +22,7 @@ from vllm.config import LoggingConfig from vllm.logger import ( _DATE_FORMAT, _FORMAT, + _JSON_FORMAT, _configure_vllm_root_logger, _use_color, configure_logging, @@ -204,6 +206,35 @@ def test_configure_logging_preserves_application_record_factory( logging.setLogRecordFactory(original_factory) +def test_builtin_json_formatter(monkeypatch): + output = io.StringIO() + + try: + with monkeypatch.context() as context: + context.setattr(sys, "stdout", output) + context.setattr(vllm_logger, "_vllm_process_info", None) + _configure_vllm_root_logger(LoggingConfig(formatter="json")) + decorate_logs("Worker_DP0") + init_logger("vllm.structured_log_probe").info("structured log probe") + + log = json.loads(output.getvalue()) + formatter = logging.getLogger("vllm").handlers[0].formatter + finally: + _configure_vllm_root_logger(LoggingConfig()) + + assert log == { + "asctime": log["asctime"], + "levelname": "INFO", + "name": "vllm.structured_log_probe", + "processName": multiprocessing.current_process().name, + "process": os.getpid(), + "message": "structured log probe", + "vllm_process_name": "Worker_DP0", + } + assert formatter is not None + assert formatter._fmt == _JSON_FORMAT + + 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.""" diff --git a/tests/test_access_log_filter.py b/tests/test_uvicorn_logging.py similarity index 99% rename from tests/test_access_log_filter.py rename to tests/test_uvicorn_logging.py index 4f03892e77..f331a91214 100644 --- a/tests/test_access_log_filter.py +++ b/tests/test_uvicorn_logging.py @@ -1,10 +1,10 @@ # SPDX-License-Identifier: Apache-2.0 # SPDX-FileCopyrightText: Copyright contributors to the vLLM project -"""Tests for the UvicornAccessLogFilter class.""" +"""Tests for Uvicorn logging configuration and access log filtering.""" import logging -from vllm.logging_utils.access_log_filter import ( +from vllm.logging_utils.uvicorn_logging import ( UvicornAccessLogFilter, create_uvicorn_log_config, ) diff --git a/vllm/config/logging.py b/vllm/config/logging.py index bb807d617d..e3a69778de 100644 --- a/vllm/config/logging.py +++ b/vllm/config/logging.py @@ -9,6 +9,7 @@ import vllm.envs as envs from vllm.config.utils import config LogLevel = Literal["CRITICAL", "ERROR", "WARNING", "INFO", "DEBUG", "NOTSET"] +LogFormatter = Literal["text", "json"] @config @@ -17,8 +18,8 @@ class LoggingConfig: Supply a JSON object with ``--logging-config`` or individual fields with dotted arguments such as ``--logging-config.log_level DEBUG`` and - ``--logging-config.pylogging_config_file logging.json``. ``--log-level`` - and legacy ``--log-config-file`` override their matching fields. Set + ``--logging-config.formatter json``. ``--log-level`` and legacy + ``--log-config-file`` override their matching fields. Set ``configure_logging`` to false to skip applying a ``dictConfig``. """ @@ -27,6 +28,9 @@ class LoggingConfig: ) """Log level used when no custom logging configuration is provided.""" + formatter: LogFormatter = "text" + """Formatter used by the built-in logging configuration.""" + configure_logging: bool = Field(default_factory=lambda: envs.VLLM_CONFIGURE_LOGGING) """Whether to apply a Python logging configuration. @@ -41,6 +45,6 @@ class LoggingConfig: """Path to a Python logging JSON file using [``dictConfig`` schema](https://docs.python.org/3/library/logging.config.html#configuration-file-format). - A custom ``dictConfig`` is authoritative over ``log_level`` for logger, - handler, and formatter settings. + A custom ``dictConfig`` is authoritative over ``log_level`` and + ``formatter`` for logger, handler, and formatter settings. """ diff --git a/vllm/entrypoints/launchers/utils/server_utils.py b/vllm/entrypoints/launchers/utils/server_utils.py index ada01706db..815374dec3 100644 --- a/vllm/entrypoints/launchers/utils/server_utils.py +++ b/vllm/entrypoints/launchers/utils/server_utils.py @@ -8,6 +8,7 @@ from contextlib import asynccontextmanager from fastapi import FastAPI from vllm import envs +from vllm.config.logging import LogFormatter from vllm.engine.protocol import EngineClient from vllm.logger import init_logger from vllm.utils.gc_utils import freeze_gc_heap @@ -33,8 +34,8 @@ def get_uvicorn_log_config(args: Namespace) -> dict | None: Priority: 1. If log_config_file is specified, use it - 2. If disable_access_log_for_endpoints is specified, create a config with - the access log filter + 2. If disable_access_log_for_endpoints or JSON formatting is specified, + create a config with the requested filter and format 3. Otherwise, return None (use uvicorn defaults) """ # First, try to load from file if specified @@ -48,19 +49,21 @@ def get_uvicorn_log_config(args: Namespace) -> dict | None: if log_config is not None: return log_config - # If endpoints to filter are specified, create a config with the filter - if args.disable_access_log_for_endpoints: + formatter: LogFormatter = ( + logging_config.formatter if logging_config is not None else "text" + ) + if args.disable_access_log_for_endpoints or formatter == "json": from vllm.logging_utils import create_uvicorn_log_config - # Parse comma-separated string into list excluded_paths = [ p.strip() - for p in args.disable_access_log_for_endpoints.split(",") + for p in (args.disable_access_log_for_endpoints or "").split(",") if p.strip() ] return create_uvicorn_log_config( excluded_paths=excluded_paths, log_level=args.uvicorn_log_level, + formatter=formatter, ) return None diff --git a/vllm/logger.py b/vllm/logger.py index 24692aa392..6a5e994601 100644 --- a/vllm/logger.py +++ b/vllm/logger.py @@ -20,6 +20,7 @@ from typing import TYPE_CHECKING, Any, Literal, cast import vllm.envs as envs from vllm.logging_utils import ColoredFormatter, NewLineFormatter +from vllm.logging_utils.formatter import JSON_FORMAT as _JSON_FORMAT if TYPE_CHECKING: from vllm.config.logging import LoggingConfig @@ -30,7 +31,6 @@ _FORMAT = ( "[%(fileinfo)s:%(lineno)d] %(message)s" ) _DATE_FORMAT = "%m-%d %H:%M:%S" - _vllm_process_info: tuple[str, int] | None = None @@ -211,10 +211,12 @@ def _configure_vllm_root_logger(config: "LoggingConfig | None" = None) -> None: configure_logging = envs.VLLM_CONFIGURE_LOGGING log_level = envs.VLLM_LOGGING_LEVEL log_config_file = envs.VLLM_LOGGING_CONFIG_PATH + log_formatter = "text" else: configure_logging = config.configure_logging log_level = config.log_level log_config_file = config.pylogging_config_file + log_formatter = config.formatter if not configure_logging and log_config_file: raise RuntimeError( @@ -233,12 +235,22 @@ def _configure_vllm_root_logger(config: "LoggingConfig | None" = None) -> None: # Refresh these values in case env vars have changed. vllm_handler["level"] = log_level vllm_handler["stream"] = envs.VLLM_LOGGING_STREAM - vllm_handler["formatter"] = "vllm_color" if _use_color() else "vllm" + for formatter in logging_config["formatters"].values(): + formatter["log_level"] = log_level + + if log_formatter == "json": + logging_config["formatters"] = { + "vllm_json": { + "class": "pythonjsonlogger.jsonlogger.JsonFormatter", + "format": _JSON_FORMAT, + } + } + vllm_handler["formatter"] = "vllm_json" + else: + vllm_handler["formatter"] = "vllm_color" if _use_color() else "vllm" vllm_loggers = logging_config["loggers"]["vllm"] vllm_loggers["level"] = log_level - for formatter in logging_config["formatters"].values(): - formatter["log_level"] = log_level if log_config_file: if not path.exists(log_config_file): diff --git a/vllm/logging_utils/__init__.py b/vllm/logging_utils/__init__.py index b83d499dbb..ddd18567f9 100644 --- a/vllm/logging_utils/__init__.py +++ b/vllm/logging_utils/__init__.py @@ -1,14 +1,14 @@ # SPDX-License-Identifier: Apache-2.0 # SPDX-FileCopyrightText: Copyright contributors to the vLLM project -from vllm.logging_utils.access_log_filter import ( - UvicornAccessLogFilter, - create_uvicorn_log_config, -) from vllm.logging_utils.formatter import ColoredFormatter, NewLineFormatter from vllm.logging_utils.lazy import lazy from vllm.logging_utils.log_time import logtime from vllm.logging_utils.torch_tensor import tensors_str_no_data +from vllm.logging_utils.uvicorn_logging import ( + UvicornAccessLogFilter, + create_uvicorn_log_config, +) __all__ = [ "NewLineFormatter", diff --git a/vllm/logging_utils/formatter.py b/vllm/logging_utils/formatter.py index 205bb36405..13ec3c6617 100644 --- a/vllm/logging_utils/formatter.py +++ b/vllm/logging_utils/formatter.py @@ -4,6 +4,10 @@ import logging from pathlib import Path +JSON_FORMAT = ( + "%(asctime)s %(levelname)s %(name)s %(processName)s %(process)d %(message)s" +) + class NewLineFormatter(logging.Formatter): """Adds logging prefix to newlines to align multi-line messages.""" diff --git a/vllm/logging_utils/access_log_filter.py b/vllm/logging_utils/uvicorn_logging.py similarity index 87% rename from vllm/logging_utils/access_log_filter.py rename to vllm/logging_utils/uvicorn_logging.py index 086449ead8..04a4549361 100644 --- a/vllm/logging_utils/access_log_filter.py +++ b/vllm/logging_utils/uvicorn_logging.py @@ -1,15 +1,13 @@ # SPDX-License-Identifier: Apache-2.0 # SPDX-FileCopyrightText: Copyright contributors to the vLLM project -"""Access log filter for uvicorn to exclude specific endpoints from logging. - -This module provides a logging filter that can be used to suppress access logs -for specific endpoints (e.g., /health, /metrics) to reduce log noise in -production environments. -""" +"""Uvicorn logging configuration and access log filtering.""" import logging +from typing import Literal from urllib.parse import urlparse +from vllm.logging_utils.formatter import JSON_FORMAT + class UvicornAccessLogFilter(logging.Filter): """A logging filter that excludes access logs for specified endpoint paths. @@ -70,8 +68,9 @@ class UvicornAccessLogFilter(logging.Filter): def create_uvicorn_log_config( excluded_paths: list[str] | None = None, log_level: str = "info", + formatter: Literal["text", "json"] = "text", ) -> dict: - """Create a uvicorn logging configuration with access log filtering. + """Create a uvicorn logging configuration with optional access filtering. This function generates a logging configuration dictionary that can be passed to uvicorn's `log_config` parameter. It sets up the access log @@ -80,6 +79,7 @@ def create_uvicorn_log_config( Args: excluded_paths: List of URL paths to exclude from access logs. log_level: The log level for uvicorn loggers. + formatter: Format used for uvicorn logs. Returns: A dictionary containing the logging configuration. @@ -140,4 +140,13 @@ def create_uvicorn_log_config( }, }, } + if formatter == "json": + json_formatter = { + "class": "pythonjsonlogger.jsonlogger.JsonFormatter", + "format": JSON_FORMAT, + } + config["formatters"] = { + "default": json_formatter.copy(), + "access": json_formatter.copy(), + } return config