| 1 | # SPDX-License-Identifier: Apache-2.0 |
| 2 | # SPDX-FileCopyrightText: Copyright contributors to the vLLM project |
| 3 | """Logging configuration for vLLM.""" |
| 4 | |
| 5 | import datetime |
| 6 | import json |
| 7 | import logging |
| 8 | import os |
| 9 | import sys |
| 10 | from collections.abc import Callable, Generator, Hashable |
| 11 | from contextlib import contextmanager |
| 12 | from copy import deepcopy |
| 13 | from dataclasses import replace |
| 14 | from functools import lru_cache, partial |
| 15 | from logging import Logger |
| 16 | from logging.config import dictConfig |
| 17 | from os import path |
| 18 | from types import MethodType |
| 19 | from typing import TYPE_CHECKING, Any, Literal, cast |
| 20 | |
| 21 | import vllm.envs as envs |
| 22 | from vllm.logging_utils import ColoredFormatter, NewLineFormatter |
| 23 | from vllm.logging_utils.formatter import JSON_FORMAT as _JSON_FORMAT |
| 24 | |
| 25 | if TYPE_CHECKING: |
| 26 | from vllm.config.logging import LoggingConfig |
| 27 | |
| 28 | _FORMAT = ( |
| 29 | f"{envs.VLLM_LOGGING_PREFIX}(%(vllm_process_name)s " |
| 30 | "pid=%(process)d) %(levelname)s %(asctime)s " |
| 31 | "[%(fileinfo)s:%(lineno)d] %(message)s" |
| 32 | ) |
| 33 | _DATE_FORMAT = "%m-%d %H:%M:%S" |
| 34 | _vllm_process_info: tuple[str, int] | None = None |
| 35 | |
| 36 | |
| 37 | class _VllmLogRecordFactory: |
| 38 | """Add vLLM process metadata while preserving the wrapped record factory.""" |
| 39 | |
| 40 | def __init__(self, factory: Callable[..., logging.LogRecord]) -> None: |
| 41 | self._factory = factory |
| 42 | |
| 43 | def __call__(self, *args: Any, **kwargs: Any) -> logging.LogRecord: |
| 44 | record = self._factory(*args, **kwargs) |
| 45 | process_info = _vllm_process_info |
| 46 | pid = os.getpid() |
| 47 | if process_info is None or process_info[1] != pid: |
| 48 | record.vllm_process_name = record.processName |
| 49 | else: |
| 50 | record.vllm_process_name = process_info[0] |
| 51 | return record |
| 52 | |
| 53 | |
| 54 | def set_vllm_process_name(process_name: str, *, skip_if_set: bool = False) -> None: |
| 55 | """Set the vLLM process name added to subsequent log records.""" |
| 56 | global _vllm_process_info |
| 57 | pid = os.getpid() |
| 58 | if skip_if_set and _vllm_process_info is not None and _vllm_process_info[1] == pid: |
| 59 | return |
| 60 | _vllm_process_info = (process_name, pid) |
| 61 | |
| 62 | |
| 63 | def _use_color() -> bool: |
| 64 | if envs.NO_COLOR or envs.VLLM_LOGGING_COLOR == "0": |
| 65 | return False |
| 66 | if envs.VLLM_LOGGING_COLOR == "1" or envs.FORCE_COLOR: |
| 67 | return True |
| 68 | if envs.VLLM_LOGGING_STREAM == "ext://sys.stdout": # stdout |
| 69 | return hasattr(sys.stdout, "isatty") and sys.stdout.isatty() |
| 70 | elif envs.VLLM_LOGGING_STREAM == "ext://sys.stderr": # stderr |
| 71 | return hasattr(sys.stderr, "isatty") and sys.stderr.isatty() |
| 72 | return False |
| 73 | |
| 74 | |
| 75 | DEFAULT_LOGGING_CONFIG: dict[str, dict[str, Any] | Any] = { |
| 76 | "formatters": { |
| 77 | # The "()" factory form forwards custom kwargs such as log_level. |
| 78 | "vllm": { |
| 79 | "()": "vllm.logging_utils.NewLineFormatter", |
| 80 | "datefmt": _DATE_FORMAT, |
| 81 | "format": _FORMAT, |
| 82 | "log_level": envs.VLLM_LOGGING_LEVEL, |
| 83 | }, |
| 84 | "vllm_color": { |
| 85 | "()": "vllm.logging_utils.ColoredFormatter", |
| 86 | "datefmt": _DATE_FORMAT, |
| 87 | "format": _FORMAT, |
| 88 | "log_level": envs.VLLM_LOGGING_LEVEL, |
| 89 | }, |
| 90 | }, |
| 91 | "handlers": { |
| 92 | "vllm": { |
| 93 | "class": "logging.StreamHandler", |
| 94 | # Choose formatter based on color setting. |
| 95 | "formatter": "vllm_color" if _use_color() else "vllm", |
| 96 | "level": envs.VLLM_LOGGING_LEVEL, |
| 97 | "stream": envs.VLLM_LOGGING_STREAM, |
| 98 | }, |
| 99 | }, |
| 100 | "loggers": { |
| 101 | "vllm": { |
| 102 | "handlers": ["vllm"], |
| 103 | "level": envs.VLLM_LOGGING_LEVEL, |
| 104 | "propagate": False, |
| 105 | }, |
| 106 | }, |
| 107 | "version": 1, |
| 108 | "disable_existing_loggers": False, |
| 109 | } |
| 110 | |
| 111 | _last_configured_logging_config: "LoggingConfig | None" = None |
| 112 | |
| 113 | |
| 114 | @lru_cache |
| 115 | def _print_debug_once(logger: Logger, msg: str, *args: Hashable) -> None: |
| 116 | # Set the stacklevel to 3 to print the original caller's line info |
| 117 | logger.debug(msg, *args, stacklevel=3) |
| 118 | |
| 119 | |
| 120 | @lru_cache |
| 121 | def _print_info_once(logger: Logger, msg: str, *args: Hashable) -> None: |
| 122 | # Set the stacklevel to 3 to print the original caller's line info |
| 123 | logger.info(msg, *args, stacklevel=3) |
| 124 | |
| 125 | |
| 126 | @lru_cache |
| 127 | def _print_warning_once(logger: Logger, msg: str, *args: Hashable) -> None: |
| 128 | # Set the stacklevel to 3 to print the original caller's line info |
| 129 | logger.warning(msg, *args, stacklevel=3) |
| 130 | |
| 131 | |
| 132 | @lru_cache |
| 133 | def _print_error_once(logger: Logger, msg: str, *args: Hashable) -> None: |
| 134 | # Set the stacklevel to 3 to print the original caller's line info |
| 135 | logger.error(msg, *args, stacklevel=3) |
| 136 | |
| 137 | |
| 138 | LogScope = Literal["process", "global", "local"] |
| 139 | |
| 140 | |
| 141 | def _should_log_with_scope(scope: LogScope) -> bool: |
| 142 | """Decide whether to log based on scope.""" |
| 143 | if scope == "global": |
| 144 | from vllm.distributed.parallel_state import is_global_first_rank |
| 145 | |
| 146 | return is_global_first_rank() |
| 147 | if scope == "local": |
| 148 | from vllm.distributed.parallel_state import is_local_first_rank |
| 149 | |
| 150 | return is_local_first_rank() |
| 151 | return True |
| 152 | |
| 153 | |
| 154 | class _VllmLogger(Logger): |
| 155 | """Note: |
| 156 | This class is just to provide type information. |
| 157 | We actually patch the methods directly on the [`logging.Logger`][] |
| 158 | instance to avoid conflicting with other libraries such as |
| 159 | `intel_extension_for_pytorch.utils._logger`. |
| 160 | |
| 161 | """ |
| 162 | |
| 163 | def debug_once(self, msg: str, *args: Hashable, scope: LogScope = "local") -> None: |
| 164 | """As [`debug`][logging.Logger.debug], but subsequent calls with |
| 165 | the same message are silently dropped. |
| 166 | """ |
| 167 | if not _should_log_with_scope(scope): |
| 168 | return |
| 169 | _print_debug_once(self, msg, *args) |
| 170 | |
| 171 | def info_once(self, msg: str, *args: Hashable, scope: LogScope = "local") -> None: |
| 172 | """As [`info`][logging.Logger.info], but subsequent calls with |
| 173 | the same message are silently dropped. |
| 174 | """ |
| 175 | if not _should_log_with_scope(scope): |
| 176 | return |
| 177 | _print_info_once(self, msg, *args) |
| 178 | |
| 179 | def warning_once( |
| 180 | self, msg: str, *args: Hashable, scope: LogScope = "local" |
| 181 | ) -> None: |
| 182 | """As [`warning`][logging.Logger.warning], but subsequent calls with |
| 183 | the same message are silently dropped. |
| 184 | """ |
| 185 | if not _should_log_with_scope(scope): |
| 186 | return |
| 187 | _print_warning_once(self, msg, *args) |
| 188 | |
| 189 | def error_once(self, msg: str, *args: Hashable, scope: LogScope = "local") -> None: |
| 190 | """As [`error`][logging.Logger.error], but subsequent calls with |
| 191 | the same message are silently dropped. |
| 192 | """ |
| 193 | if not _should_log_with_scope(scope): |
| 194 | return |
| 195 | _print_error_once(self, msg, *args) |
| 196 | |
| 197 | |
| 198 | # Pre-defined methods mapping to avoid repeated dictionary creation |
| 199 | _METHODS_TO_PATCH = { |
| 200 | "debug_once": _VllmLogger.debug_once, |
| 201 | "info_once": _VllmLogger.info_once, |
| 202 | "warning_once": _VllmLogger.warning_once, |
| 203 | "error_once": _VllmLogger.error_once, |
| 204 | } |
| 205 | |
| 206 | |
| 207 | def _configure_vllm_root_logger(config: "LoggingConfig | None" = None) -> None: |
| 208 | """Configure logging from explicit config or bootstrap environment values.""" |
| 209 | logging_config: dict[str, dict[str, Any] | Any] = {} |
| 210 | if config is None: |
| 211 | configure_logging = envs.VLLM_CONFIGURE_LOGGING |
| 212 | log_level = envs.VLLM_LOGGING_LEVEL |
| 213 | log_config_file = envs.VLLM_LOGGING_CONFIG_PATH |
| 214 | log_formatter = "text" |
| 215 | else: |
| 216 | configure_logging = config.configure_logging |
| 217 | log_level = config.log_level |
| 218 | log_config_file = config.pylogging_config_file |
| 219 | log_formatter = config.formatter |
| 220 | |
| 221 | if not configure_logging and log_config_file: |
| 222 | raise RuntimeError( |
| 223 | "Logging configuration is disabled, but a Python logging config " |
| 224 | "file was given. pylogging_config_file requires " |
| 225 | "configure_logging to be enabled." |
| 226 | ) |
| 227 | |
| 228 | if configure_logging: |
| 229 | factory = logging.getLogRecordFactory() |
| 230 | if not isinstance(factory, _VllmLogRecordFactory): |
| 231 | logging.setLogRecordFactory(_VllmLogRecordFactory(factory)) |
| 232 | logging_config = deepcopy(DEFAULT_LOGGING_CONFIG) |
| 233 | |
| 234 | vllm_handler = logging_config["handlers"]["vllm"] |
| 235 | # Refresh these values in case env vars have changed. |
| 236 | vllm_handler["level"] = log_level |
| 237 | vllm_handler["stream"] = envs.VLLM_LOGGING_STREAM |
| 238 | for formatter in logging_config["formatters"].values(): |
| 239 | formatter["log_level"] = log_level |
| 240 | |
| 241 | if log_formatter == "json": |
| 242 | logging_config["formatters"] = { |
| 243 | "vllm_json": { |
| 244 | "class": "pythonjsonlogger.jsonlogger.JsonFormatter", |
| 245 | "format": _JSON_FORMAT, |
| 246 | } |
| 247 | } |
| 248 | vllm_handler["formatter"] = "vllm_json" |
| 249 | else: |
| 250 | vllm_handler["formatter"] = "vllm_color" if _use_color() else "vllm" |
| 251 | |
| 252 | vllm_loggers = logging_config["loggers"]["vllm"] |
| 253 | vllm_loggers["level"] = log_level |
| 254 | |
| 255 | if log_config_file: |
| 256 | if not path.exists(log_config_file): |
| 257 | raise RuntimeError( |
| 258 | "Could not load logging config. File does not exist: %s", |
| 259 | log_config_file, |
| 260 | ) |
| 261 | with open(log_config_file, encoding="utf-8") as file: |
| 262 | custom_config = json.loads(file.read()) |
| 263 | |
| 264 | if not isinstance(custom_config, dict): |
| 265 | raise ValueError( |
| 266 | "Invalid logging config. Expected dict, got %s.", |
| 267 | type(custom_config).__name__, |
| 268 | ) |
| 269 | logging_config = custom_config |
| 270 | |
| 271 | for formatter in logging_config.get("formatters", {}).values(): |
| 272 | # This provides backwards compatibility after #10134. |
| 273 | if formatter.get("class") == "vllm.logging.NewLineFormatter": |
| 274 | formatter["class"] = "vllm.logging_utils.NewLineFormatter" |
| 275 | |
| 276 | if logging_config: |
| 277 | dictConfig(logging_config) |
| 278 | |
| 279 | # Transformers uses httpx to access the Hugging Face Hub. httpx is quite verbose, |
| 280 | # so we set its logging level to WARNING when vLLM's logging level is INFO. |
| 281 | # httpx2 is the successor huggingface_hub switches to in its 2.x releases. |
| 282 | if log_level == "INFO": |
| 283 | logging.getLogger("httpx").setLevel(logging.WARNING) |
| 284 | logging.getLogger("httpx2").setLevel(logging.WARNING) |
| 285 | |
| 286 | |
| 287 | def configure_logging(config: "LoggingConfig") -> None: |
| 288 | """Apply a logging configuration in the current process.""" |
| 289 | _configure_vllm_root_logger(config) |
| 290 | global _last_configured_logging_config |
| 291 | _last_configured_logging_config = config |
| 292 | _log_platform_warnings(config) |
| 293 | |
| 294 | |
| 295 | def _log_platform_warnings(config: "LoggingConfig") -> None: |
| 296 | """Emit platform diagnostics only after an enabled config is active.""" |
| 297 | if not config.configure_logging: |
| 298 | return |
| 299 | |
| 300 | # Import lazily because platform modules use init_logger during import. |
| 301 | from vllm.platforms import current_platform |
| 302 | |
| 303 | current_platform.log_warnings() |
| 304 | |
| 305 | |
| 306 | def configure_logging_if_needed(config: "LoggingConfig") -> None: |
| 307 | """Apply a logging configuration unless it is already active in this process.""" |
| 308 | if config != _last_configured_logging_config: |
| 309 | configure_logging(config) |
| 310 | |
| 311 | |
| 312 | def configure_logging_from_args(args: Any) -> "LoggingConfig": |
| 313 | """Apply parsed logging arguments and retain them for child processes.""" |
| 314 | from vllm.config.logging import LoggingConfig |
| 315 | |
| 316 | config = getattr(args, "logging_config", None) or LoggingConfig() |
| 317 | if hasattr(args, "log_level"): |
| 318 | config = replace(config, log_level=args.log_level) |
| 319 | if hasattr(args, "log_config_file"): |
| 320 | config = replace(config, pylogging_config_file=args.log_config_file) |
| 321 | |
| 322 | configure_logging_if_needed(config) |
| 323 | args.log_config_file = config.pylogging_config_file |
| 324 | args.logging_config = config |
| 325 | return config |
| 326 | |
| 327 | |
| 328 | def init_logger(name: str) -> _VllmLogger: |
| 329 | """Retrieve a logger and add vLLM's convenience logging methods.""" |
| 330 | logger = logging.getLogger(name) |
| 331 | |
| 332 | for method_name, method in _METHODS_TO_PATCH.items(): |
| 333 | setattr(logger, method_name, MethodType(method, logger)) |
| 334 | |
| 335 | return cast(_VllmLogger, logger) |
| 336 | |
| 337 | |
| 338 | @contextmanager |
| 339 | def suppress_logging(level: int = logging.INFO) -> Generator[None, Any, None]: |
| 340 | current_level = logging.root.manager.disable |
| 341 | logging.disable(level) |
| 342 | yield |
| 343 | logging.disable(current_level) |
| 344 | |
| 345 | |
| 346 | def current_formatter_type(logger: Logger) -> Literal["color", "newline", None]: |
| 347 | lgr: Logger | None = logger |
| 348 | while lgr is not None: |
| 349 | if lgr.handlers and len(lgr.handlers) == 1 and lgr.handlers[0].name == "vllm": |
| 350 | formatter = lgr.handlers[0].formatter |
| 351 | if isinstance(formatter, ColoredFormatter): |
| 352 | return "color" |
| 353 | if isinstance(formatter, NewLineFormatter): |
| 354 | return "newline" |
| 355 | lgr = lgr.parent |
| 356 | return None |
| 357 | |
| 358 | |
| 359 | logger = init_logger(__name__) |
| 360 | |
| 361 | |
| 362 | def _trace_calls(log_path, root_dir, frame, event, arg=None): |
| 363 | if event in ["call", "return"]: |
| 364 | # Extract the filename, line number, function name, and the code object |
| 365 | filename = frame.f_code.co_filename |
| 366 | lineno = frame.f_lineno |
| 367 | func_name = frame.f_code.co_name |
| 368 | if not filename.startswith(root_dir): |
| 369 | # only log the functions in the vllm root_dir |
| 370 | return |
| 371 | # Log every function call or return |
| 372 | try: |
| 373 | last_frame = frame.f_back |
| 374 | if last_frame is not None: |
| 375 | last_filename = last_frame.f_code.co_filename |
| 376 | last_lineno = last_frame.f_lineno |
| 377 | last_func_name = last_frame.f_code.co_name |
| 378 | else: |
| 379 | # initial frame |
| 380 | last_filename = "" |
| 381 | last_lineno = 0 |
| 382 | last_func_name = "" |
| 383 | with open(log_path, "a") as f: |
| 384 | ts = datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S.%f") |
| 385 | if event == "call": |
| 386 | f.write( |
| 387 | f"{ts} Call to" |
| 388 | f" {func_name} in {filename}:{lineno}" |
| 389 | f" from {last_func_name} in {last_filename}:" |
| 390 | f"{last_lineno}\n" |
| 391 | ) |
| 392 | else: |
| 393 | f.write( |
| 394 | f"{ts} Return from" |
| 395 | f" {func_name} in {filename}:{lineno}" |
| 396 | f" to {last_func_name} in {last_filename}:" |
| 397 | f"{last_lineno}\n" |
| 398 | ) |
| 399 | except NameError: |
| 400 | # modules are deleted during shutdown |
| 401 | pass |
| 402 | return partial(_trace_calls, log_path, root_dir) |
| 403 | |
| 404 | |
| 405 | def enable_trace_function_call(log_file_path: str, root_dir: str | None = None): |
| 406 | """Enable tracing of every function call in code under `root_dir`. |
| 407 | This is useful for debugging hangs or crashes. |
| 408 | `log_file_path` is the path to the log file. |
| 409 | `root_dir` is the root directory of the code to trace. If None, it is the |
| 410 | vllm root directory. |
| 411 | |
| 412 | Note that this call is thread-level, any threads calling this function |
| 413 | will have the trace enabled. Other threads will not be affected. |
| 414 | """ |
| 415 | logger.warning( |
| 416 | "VLLM_TRACE_FUNCTION is enabled. It will record every" |
| 417 | " function executed by Python. This will slow down the code. It " |
| 418 | "is suggested to be used for debugging hang or crashes only." |
| 419 | ) |
| 420 | logger.info("Trace frame log is saved to %s", log_file_path) |
| 421 | if root_dir is None: |
| 422 | # by default, this is the vllm root directory |
| 423 | root_dir = os.path.dirname(os.path.dirname(__file__)) |
| 424 | sys.settrace(partial(_trace_calls, log_file_path, root_dir)) |