# 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 typing import Optional VLLM_CONFIGURE_LOGGING = int(os.getenv("VLLM_CONFIGURE_LOGGING", "1")) _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 # 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() 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")) 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 return logger logger = init_logger(__name__) def _trace_calls(log_path, root_dir, frame, event, arg=None): if event in ['call', 'return']: # Extract the filename, line number, function name, and the code object filename = frame.f_code.co_filename lineno = frame.f_lineno func_name = frame.f_code.co_name if not filename.startswith(root_dir): # only log the functions in the vllm root_dir return # Log every function call or return try: last_frame = frame.f_back if last_frame is not None: last_filename = last_frame.f_code.co_filename last_lineno = last_frame.f_lineno last_func_name = last_frame.f_code.co_name else: # initial frame last_filename = "" last_lineno = 0 last_func_name = "" with open(log_path, 'a') as f: if event == 'call': f.write(f"{datetime.datetime.now()} Call to" f" {func_name} in {filename}:{lineno}" f" from {last_func_name} in {last_filename}:" f"{last_lineno}\n") else: f.write(f"{datetime.datetime.now()} Return from" f" {func_name} in {filename}:{lineno}" f" to {last_func_name} in {last_filename}:" f"{last_lineno}\n") except NameError: # modules are deleted during shutdown pass return partial(_trace_calls, log_path, root_dir) def enable_trace_function_call(log_file_path: str, root_dir: Optional[str] = None): """ Enable tracing of every function call in code under `root_dir`. This is useful for debugging hangs or crashes. `log_file_path` is the path to the log file. `root_dir` is the root directory of the code to trace. If None, it is the vllm root directory. Note that this call is thread-level, any threads calling this function will have the trace enabled. Other threads will not be affected. """ logger.warning( "VLLM_TRACE_FUNCTION is enabled. It will record every" " function executed by Python. This will slow down the code. It " "is suggested to be used for debugging hang or crashes only.") logger.info("Trace frame log is saved to %s", log_file_path) if root_dir is None: # by default, this is the vllm root directory root_dir = os.path.dirname(os.path.dirname(__file__)) sys.settrace(partial(_trace_calls, log_file_path, root_dir))