logger.py 8.84 KB
Newer Older
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
Woosuk Kwon's avatar
Woosuk Kwon committed
7
import logging
8
import os
9
import sys
10
from collections.abc import Hashable
11
from functools import lru_cache, partial
12
13
14
from logging import Logger
from logging.config import dictConfig
from os import path
15
from types import MethodType
16
from typing import Any, Literal, cast
Woosuk Kwon's avatar
Woosuk Kwon committed
17

18
19
20
21
import vllm.envs as envs

VLLM_CONFIGURE_LOGGING = envs.VLLM_CONFIGURE_LOGGING
VLLM_LOGGING_CONFIG_PATH = envs.VLLM_LOGGING_CONFIG_PATH
22
VLLM_LOGGING_LEVEL = envs.VLLM_LOGGING_LEVEL
23
VLLM_LOGGING_PREFIX = envs.VLLM_LOGGING_PREFIX
24
VLLM_LOGGING_STREAM = envs.VLLM_LOGGING_STREAM
25

26
27
28
29
_FORMAT = (
    f"{VLLM_LOGGING_PREFIX}%(levelname)s %(asctime)s "
    "[%(fileinfo)s:%(lineno)d] %(message)s"
)
Woosuk Kwon's avatar
Woosuk Kwon committed
30
31
_DATE_FORMAT = "%m-%d %H:%M:%S"

32
33
34
DEFAULT_LOGGING_CONFIG = {
    "formatters": {
        "vllm": {
35
            "class": "vllm.logging_utils.NewLineFormatter",
36
37
38
39
40
41
42
43
            "datefmt": _DATE_FORMAT,
            "format": _FORMAT,
        },
    },
    "handlers": {
        "vllm": {
            "class": "logging.StreamHandler",
            "formatter": "vllm",
44
            "level": VLLM_LOGGING_LEVEL,
45
            "stream": VLLM_LOGGING_STREAM,
46
47
48
49
50
51
52
53
54
55
        },
    },
    "loggers": {
        "vllm": {
            "handlers": ["vllm"],
            "level": "DEBUG",
            "propagate": False,
        },
    },
    "version": 1,
56
    "disable_existing_loggers": False,
57
58
59
}


60
61
@lru_cache
def _print_debug_once(logger: Logger, msg: str, *args: Hashable) -> None:
62
63
    # Set the stacklevel to 3 to print the original caller's line info
    logger.debug(msg, *args, stacklevel=3)
64
65


66
@lru_cache
67
def _print_info_once(logger: Logger, msg: str, *args: Hashable) -> None:
68
69
    # Set the stacklevel to 3 to print the original caller's line info
    logger.info(msg, *args, stacklevel=3)
70
71
72


@lru_cache
73
def _print_warning_once(logger: Logger, msg: str, *args: Hashable) -> None:
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
    # Set the stacklevel to 3 to print the original caller's line info
    logger.warning(msg, *args, stacklevel=3)


LogScope = Literal["process", "global", "local"]


def _should_log_with_scope(scope: LogScope) -> bool:
    """Decide whether to log based on scope"""
    if scope == "global":
        from vllm.distributed.parallel_state import is_global_first_rank

        return is_global_first_rank()
    if scope == "local":
        from vllm.distributed.parallel_state import is_local_first_rank

        return is_local_first_rank()
    # default "process" scope: always log
    return True
93
94
95
96
97
98


class _VllmLogger(Logger):
    """
    Note:
        This class is just to provide type information.
99
        We actually patch the methods directly on the [`logging.Logger`][]
100
101
102
103
        instance to avoid conflicting with other libraries such as
        `intel_extension_for_pytorch.utils._logger`.
    """

104
105
106
    def debug_once(
        self, msg: str, *args: Hashable, scope: LogScope = "process"
    ) -> None:
107
108
109
110
        """
        As [`debug`][logging.Logger.debug], but subsequent calls with
        the same message are silently dropped.
        """
111
112
        if not _should_log_with_scope(scope):
            return
113
114
        _print_debug_once(self, msg, *args)

115
    def info_once(self, msg: str, *args: Hashable, scope: LogScope = "process") -> None:
116
        """
117
118
        As [`info`][logging.Logger.info], but subsequent calls with
        the same message are silently dropped.
119
        """
120
121
        if not _should_log_with_scope(scope):
            return
122
        _print_info_once(self, msg, *args)
123

124
125
126
    def warning_once(
        self, msg: str, *args: Hashable, scope: LogScope = "process"
    ) -> None:
127
        """
128
129
        As [`warning`][logging.Logger.warning], but subsequent calls with
        the same message are silently dropped.
130
        """
131
132
        if not _should_log_with_scope(scope):
            return
133
        _print_warning_once(self, msg, *args)
134
135


136
137
# Pre-defined methods mapping to avoid repeated dictionary creation
_METHODS_TO_PATCH = {
138
139
140
    "debug_once": _VllmLogger.debug_once,
    "info_once": _VllmLogger.info_once,
    "warning_once": _VllmLogger.warning_once,
141
142
143
}


144
def _configure_vllm_root_logger() -> None:
145
    logging_config = dict[str, Any]()
146
147
148
149
150
151

    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 "
152
153
            "VLLM_CONFIGURE_LOGGING or unset VLLM_LOGGING_CONFIG_PATH."
        )
Woosuk Kwon's avatar
Woosuk Kwon committed
154

155
156
    if VLLM_CONFIGURE_LOGGING:
        logging_config = DEFAULT_LOGGING_CONFIG
Woosuk Kwon's avatar
Woosuk Kwon committed
157

158
159
160
161
    if VLLM_LOGGING_CONFIG_PATH:
        if not path.exists(VLLM_LOGGING_CONFIG_PATH):
            raise RuntimeError(
                "Could not load logging config. File does not exist: %s",
162
163
                VLLM_LOGGING_CONFIG_PATH,
            )
164
        with open(VLLM_LOGGING_CONFIG_PATH, encoding="utf-8") as file:
165
            custom_config = json.loads(file.read())
Woosuk Kwon's avatar
Woosuk Kwon committed
166

167
        if not isinstance(custom_config, dict):
168
169
170
171
            raise ValueError(
                "Invalid logging config. Expected dict, got %s.",
                type(custom_config).__name__,
            )
172
        logging_config = custom_config
Woosuk Kwon's avatar
Woosuk Kwon committed
173

174
175
176
177
178
    for formatter in logging_config.get("formatters", {}).values():
        # This provides backwards compatibility after #10134.
        if formatter.get("class") == "vllm.logging.NewLineFormatter":
            formatter["class"] = "vllm.logging_utils.NewLineFormatter"

179
180
    if logging_config:
        dictConfig(logging_config)
Woosuk Kwon's avatar
Woosuk Kwon committed
181
182


183
def init_logger(name: str) -> _VllmLogger:
184
185
186
    """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."""
Woosuk Kwon's avatar
Woosuk Kwon committed
187

188
189
    logger = logging.getLogger(name)

190
    for method_name, method in _METHODS_TO_PATCH.items():
191
192
193
        setattr(logger, method_name, MethodType(method, logger))

    return cast(_VllmLogger, logger)
Woosuk Kwon's avatar
Woosuk Kwon committed
194
195


196
# The root logger is initialized when the module is imported.
Woosuk Kwon's avatar
Woosuk Kwon committed
197
198
# This is thread-safe as the module is only imported once,
# guaranteed by the Python GIL.
199
_configure_vllm_root_logger()
200
201
202
203
204

logger = init_logger(__name__)


def _trace_calls(log_path, root_dir, frame, event, arg=None):
205
    if event in ["call", "return"]:
206
207
208
209
210
211
212
213
214
        # 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:
215
216
217
218
219
220
221
222
223
224
            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 = ""
225
            with open(log_path, "a") as f:
226
                ts = datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S.%f")
227
228
229
230
231
232
233
                if event == "call":
                    f.write(
                        f"{ts} Call to"
                        f" {func_name} in {filename}:{lineno}"
                        f" from {last_func_name} in {last_filename}:"
                        f"{last_lineno}\n"
                    )
234
                else:
235
236
237
238
239
240
                    f.write(
                        f"{ts} Return from"
                        f" {func_name} in {filename}:{lineno}"
                        f" to {last_func_name} in {last_filename}:"
                        f"{last_lineno}\n"
                    )
241
242
243
244
245
246
        except NameError:
            # modules are deleted during shutdown
            pass
    return partial(_trace_calls, log_path, root_dir)


247
def enable_trace_function_call(log_file_path: str, root_dir: str | None = None):
248
249
250
251
252
253
254
255
256
257
258
259
260
    """
    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 "
261
262
        "is suggested to be used for debugging hang or crashes only."
    )
263
    logger.info("Trace frame log is saved to %s", log_file_path)
264
265
266
267
    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))