| 1 | # SPDX-License-Identifier: Apache-2.0 |
| 2 | # SPDX-FileCopyrightText: Copyright contributors to the vLLM project |
| 3 | import enum |
| 4 | import io |
| 5 | import json |
| 6 | import logging |
| 7 | import multiprocessing |
| 8 | import os |
| 9 | import sys |
| 10 | import tempfile |
| 11 | from dataclasses import dataclass |
| 12 | from json.decoder import JSONDecodeError |
| 13 | from tempfile import NamedTemporaryFile |
| 14 | from typing import Any |
| 15 | from unittest.mock import patch |
| 16 | from uuid import uuid4 |
| 17 | |
| 18 | import pytest |
| 19 | |
| 20 | import vllm.logger as vllm_logger |
| 21 | from vllm.config import LoggingConfig |
| 22 | from vllm.logger import ( |
| 23 | _DATE_FORMAT, |
| 24 | _FORMAT, |
| 25 | _JSON_FORMAT, |
| 26 | _configure_vllm_root_logger, |
| 27 | _use_color, |
| 28 | configure_logging, |
| 29 | enable_trace_function_call, |
| 30 | init_logger, |
| 31 | ) |
| 32 | from vllm.logging_utils import NewLineFormatter |
| 33 | from vllm.logging_utils.dump_input import prepare_object_to_dump |
| 34 | from vllm.utils.system_utils import decorate_logs |
| 35 | |
| 36 | |
| 37 | def f1(x): |
| 38 | return f2(x) |
| 39 | |
| 40 | |
| 41 | def f2(x): |
| 42 | return x |
| 43 | |
| 44 | |
| 45 | def test_trace_function_call(): |
| 46 | fd, path = tempfile.mkstemp() |
| 47 | cur_dir = os.path.dirname(__file__) |
| 48 | enable_trace_function_call(path, cur_dir) |
| 49 | f1(1) |
| 50 | with open(path) as f: |
| 51 | content = f.read() |
| 52 | |
| 53 | assert "f1" in content |
| 54 | assert "f2" in content |
| 55 | sys.settrace(None) |
| 56 | os.remove(path) |
| 57 | |
| 58 | |
| 59 | def test_caplog_vllm_captures_info_before_runtime_logging_is_configured(caplog_vllm): |
| 60 | message = "Capture this unconfigured INFO record" |
| 61 | logger = init_logger(f"vllm.test_logger.{uuid4()}") |
| 62 | |
| 63 | logger.info(message) |
| 64 | |
| 65 | assert message in caplog_vllm.text |
| 66 | |
| 67 | |
| 68 | def test_default_vllm_root_logger_configuration(monkeypatch): |
| 69 | """This test presumes that VLLM_CONFIGURE_LOGGING (default: True) and |
| 70 | VLLM_LOGGING_CONFIG_PATH (default: None) are not configured and default |
| 71 | behavior is activated.""" |
| 72 | monkeypatch.setenv("VLLM_LOGGING_COLOR", "0") |
| 73 | early_logger = init_logger(f"vllm.test_logger.{uuid4()}") |
| 74 | configure_logging(LoggingConfig()) |
| 75 | |
| 76 | logger = logging.getLogger("vllm") |
| 77 | assert logger.level == logging.INFO |
| 78 | assert not logger.propagate |
| 79 | assert early_logger.isEnabledFor(logging.INFO) |
| 80 | |
| 81 | handler = logger.handlers[0] |
| 82 | assert isinstance(handler, logging.StreamHandler) |
| 83 | assert handler.stream == sys.stdout |
| 84 | # we use DEBUG level for testing by default |
| 85 | # assert handler.level == logging.INFO |
| 86 | |
| 87 | formatter = handler.formatter |
| 88 | assert formatter is not None |
| 89 | assert isinstance(formatter, NewLineFormatter) |
| 90 | assert formatter._fmt == _FORMAT |
| 91 | assert formatter.datefmt == _DATE_FORMAT |
| 92 | |
| 93 | |
| 94 | def test_offline_llm_configures_logging_before_logging_args(monkeypatch): |
| 95 | import vllm.entrypoints.llm as llm_module |
| 96 | |
| 97 | class StopInitialization(Exception): |
| 98 | pass |
| 99 | |
| 100 | configured = False |
| 101 | |
| 102 | def configure_logging(_): |
| 103 | nonlocal configured |
| 104 | configured = True |
| 105 | |
| 106 | def log_args(_): |
| 107 | assert configured |
| 108 | raise StopInitialization |
| 109 | |
| 110 | monkeypatch.setattr(llm_module, "configure_logging_if_needed", configure_logging) |
| 111 | monkeypatch.setattr(llm_module, "log_non_default_args", log_args) |
| 112 | |
| 113 | with pytest.raises(StopInitialization): |
| 114 | llm_module.LLM(model="facebook/opt-125m") |
| 115 | |
| 116 | |
| 117 | def test_json_logging(monkeypatch, tmp_path): |
| 118 | output = io.StringIO() |
| 119 | logging_config = { |
| 120 | "version": 1, |
| 121 | "disable_existing_loggers": False, |
| 122 | "formatters": { |
| 123 | "json": { |
| 124 | "class": "pythonjsonlogger.jsonlogger.JsonFormatter", |
| 125 | "format": ( |
| 126 | "%(asctime)s %(levelname)s %(name)s %(vllm_process_name)s " |
| 127 | "%(process)d %(message)s" |
| 128 | ), |
| 129 | }, |
| 130 | }, |
| 131 | "handlers": { |
| 132 | "console": { |
| 133 | "class": "logging.StreamHandler", |
| 134 | "formatter": "json", |
| 135 | "stream": "ext://sys.stdout", |
| 136 | }, |
| 137 | }, |
| 138 | "loggers": { |
| 139 | "vllm": { |
| 140 | "handlers": ["console"], |
| 141 | "level": "INFO", |
| 142 | "propagate": False, |
| 143 | }, |
| 144 | }, |
| 145 | } |
| 146 | |
| 147 | logging_config_path = tmp_path / "logging_config.json" |
| 148 | logging_config_path.write_text(json.dumps(logging_config)) |
| 149 | |
| 150 | try: |
| 151 | with monkeypatch.context() as context: |
| 152 | context.setattr(sys, "stdout", output) |
| 153 | # Restore this module-global state when the context exits. |
| 154 | context.setattr(vllm_logger, "_vllm_process_info", None) |
| 155 | _configure_vllm_root_logger( |
| 156 | LoggingConfig(pylogging_config_file=str(logging_config_path)) |
| 157 | ) |
| 158 | decorate_logs("Worker_DP0") |
| 159 | init_logger("vllm.structured_log_probe").info("structured log probe") |
| 160 | |
| 161 | log = json.loads(output.getvalue()) |
| 162 | finally: |
| 163 | _configure_vllm_root_logger(LoggingConfig()) |
| 164 | |
| 165 | assert log["message"] == "structured log probe" |
| 166 | assert log["vllm_process_name"] == "Worker_DP0" |
| 167 | assert log["process"] == os.getpid() |
| 168 | |
| 169 | |
| 170 | @pytest.mark.parametrize("factory_order", ["before", "after", "replacement"]) |
| 171 | def test_configure_logging_preserves_application_record_factory( |
| 172 | monkeypatch, factory_order |
| 173 | ): |
| 174 | """Application fields survive initial configuration and reconfiguration.""" |
| 175 | original_factory = logging.getLogRecordFactory() |
| 176 | monkeypatch.setattr(vllm_logger, "dictConfig", lambda _: None) |
| 177 | monkeypatch.setattr(vllm_logger, "_last_configured_logging_config", None) |
| 178 | monkeypatch.setattr(vllm_logger, "_vllm_process_info", None) |
| 179 | config = LoggingConfig() |
| 180 | formatter = logging.Formatter("%(request_id)s %(vllm_process_name)s %(message)s") |
| 181 | |
| 182 | try: |
| 183 | logging.setLogRecordFactory(logging.LogRecord) |
| 184 | if factory_order != "before": |
| 185 | configure_logging(config) |
| 186 | base_factory = ( |
| 187 | logging.LogRecord |
| 188 | if factory_order == "replacement" |
| 189 | else logging.getLogRecordFactory() |
| 190 | ) |
| 191 | |
| 192 | def application_factory(*args, **kwargs): |
| 193 | record = base_factory(*args, **kwargs) |
| 194 | record.request_id = "request-123" |
| 195 | return record |
| 196 | |
| 197 | logging.setLogRecordFactory(application_factory) |
| 198 | decorate_logs("Worker_DP0") |
| 199 | for _ in range(2): |
| 200 | configure_logging(config) |
| 201 | record = logging.getLogger("application").makeRecord( |
| 202 | "application", logging.INFO, __file__, 1, "probe", (), None |
| 203 | ) |
| 204 | assert formatter.format(record) == "request-123 Worker_DP0 probe" |
| 205 | finally: |
| 206 | logging.setLogRecordFactory(original_factory) |
| 207 | |
| 208 | |
| 209 | def test_builtin_json_formatter(monkeypatch): |
| 210 | output = io.StringIO() |
| 211 | |
| 212 | try: |
| 213 | with monkeypatch.context() as context: |
| 214 | context.setattr(sys, "stdout", output) |
| 215 | context.setattr(vllm_logger, "_vllm_process_info", None) |
| 216 | _configure_vllm_root_logger(LoggingConfig(formatter="json")) |
| 217 | decorate_logs("Worker_DP0") |
| 218 | init_logger("vllm.structured_log_probe").info("structured log probe") |
| 219 | |
| 220 | log = json.loads(output.getvalue()) |
| 221 | formatter = logging.getLogger("vllm").handlers[0].formatter |
| 222 | finally: |
| 223 | _configure_vllm_root_logger(LoggingConfig()) |
| 224 | |
| 225 | assert log == { |
| 226 | "asctime": log["asctime"], |
| 227 | "levelname": "INFO", |
| 228 | "name": "vllm.structured_log_probe", |
| 229 | "processName": multiprocessing.current_process().name, |
| 230 | "process": os.getpid(), |
| 231 | "message": "structured log probe", |
| 232 | "vllm_process_name": "Worker_DP0", |
| 233 | } |
| 234 | assert formatter is not None |
| 235 | assert formatter._fmt == _JSON_FORMAT |
| 236 | |
| 237 | |
| 238 | def test_use_color_force_color(monkeypatch): |
| 239 | """FORCE_COLOR forces colored logs without a TTY, while NO_COLOR and an |
| 240 | explicit VLLM_LOGGING_COLOR=0 take precedence over it.""" |
| 241 | monkeypatch.setattr(sys, "stdout", io.StringIO()) |
| 242 | monkeypatch.setattr(sys, "stderr", io.StringIO()) |
| 243 | for var in ("NO_COLOR", "FORCE_COLOR", "VLLM_LOGGING_COLOR"): |
| 244 | monkeypatch.delenv(var, raising=False) |
| 245 | |
| 246 | assert not _use_color() |
| 247 | |
| 248 | monkeypatch.setenv("FORCE_COLOR", "1") |
| 249 | assert _use_color() |
| 250 | |
| 251 | monkeypatch.setenv("VLLM_LOGGING_COLOR", "0") |
| 252 | assert not _use_color() |
| 253 | monkeypatch.delenv("VLLM_LOGGING_COLOR") |
| 254 | |
| 255 | monkeypatch.setenv("NO_COLOR", "1") |
| 256 | assert not _use_color() |
| 257 | |
| 258 | |
| 259 | def test_descendent_loggers_depend_on_and_propagate_logs_to_root_logger(monkeypatch): |
| 260 | """This test presumes that VLLM_CONFIGURE_LOGGING (default: True) and |
| 261 | VLLM_LOGGING_CONFIG_PATH (default: None) are not configured and default |
| 262 | behavior is activated.""" |
| 263 | monkeypatch.setenv("VLLM_CONFIGURE_LOGGING", "1") |
| 264 | monkeypatch.delenv("VLLM_LOGGING_CONFIG_PATH", raising=False) |
| 265 | |
| 266 | root_logger = logging.getLogger("vllm") |
| 267 | root_handler = root_logger.handlers[0] |
| 268 | |
| 269 | unique_name = f"vllm.{uuid4()}" |
| 270 | logger = init_logger(unique_name) |
| 271 | assert logger.name == unique_name |
| 272 | assert logger.level == logging.NOTSET |
| 273 | assert not logger.handlers |
| 274 | assert logger.propagate |
| 275 | |
| 276 | message = "Hello, world!" |
| 277 | with patch.object(root_handler, "emit") as root_handle_mock: |
| 278 | logger.info(message) |
| 279 | |
| 280 | root_handle_mock.assert_called_once() |
| 281 | _, call_args, _ = root_handle_mock.mock_calls[0] |
| 282 | log_record = call_args[0] |
| 283 | assert unique_name == log_record.name |
| 284 | assert message == log_record.msg |
| 285 | assert message == log_record.msg |
| 286 | assert log_record.levelno == logging.INFO |
| 287 | |
| 288 | |
| 289 | def test_logger_configuring_can_be_disabled(monkeypatch): |
| 290 | """This test calls _configure_vllm_root_logger again to test custom logging |
| 291 | config behavior, however mocks are used to ensure no changes in behavior or |
| 292 | configuration occur.""" |
| 293 | monkeypatch.setenv("VLLM_CONFIGURE_LOGGING", "0") |
| 294 | monkeypatch.delenv("VLLM_LOGGING_CONFIG_PATH", raising=False) |
| 295 | |
| 296 | original_factory = logging.getLogRecordFactory() |
| 297 | with patch("vllm.logger.dictConfig") as dict_config_mock: |
| 298 | configure_logging(LoggingConfig(configure_logging=False)) |
| 299 | dict_config_mock.assert_not_called() |
| 300 | assert logging.getLogRecordFactory() is original_factory |
| 301 | |
| 302 | |
| 303 | def test_an_error_is_raised_when_custom_logging_config_file_does_not_exist(monkeypatch): |
| 304 | """This test calls _configure_vllm_root_logger again to test custom logging |
| 305 | config behavior, however it fails before any change in behavior or |
| 306 | configuration occurs.""" |
| 307 | monkeypatch.setenv("VLLM_CONFIGURE_LOGGING", "1") |
| 308 | monkeypatch.setenv( |
| 309 | "VLLM_LOGGING_CONFIG_PATH", |
| 310 | "/if/there/is/a/file/here/then/you/did/this/to/yourself.json", |
| 311 | ) |
| 312 | |
| 313 | with pytest.raises(RuntimeError) as ex_info: |
| 314 | _configure_vllm_root_logger() |
| 315 | assert ex_info.type == RuntimeError # noqa: E721 |
| 316 | assert "File does not exist" in str(ex_info) |
| 317 | |
| 318 | |
| 319 | def test_an_error_is_raised_when_custom_logging_config_is_invalid_json(monkeypatch): |
| 320 | """This test calls _configure_vllm_root_logger again to test custom logging |
| 321 | config behavior, however it fails before any change in behavior or |
| 322 | configuration occurs.""" |
| 323 | monkeypatch.setenv("VLLM_CONFIGURE_LOGGING", "1") |
| 324 | |
| 325 | with NamedTemporaryFile(encoding="utf-8", mode="w") as logging_config_file: |
| 326 | logging_config_file.write("---\nloggers: []\nversion: 1") |
| 327 | logging_config_file.flush() |
| 328 | monkeypatch.setenv("VLLM_LOGGING_CONFIG_PATH", logging_config_file.name) |
| 329 | with pytest.raises(JSONDecodeError) as ex_info: |
| 330 | _configure_vllm_root_logger() |
| 331 | assert ex_info.type == JSONDecodeError |
| 332 | assert "Expecting value" in str(ex_info) |
| 333 | |
| 334 | |
| 335 | @pytest.mark.parametrize( |
| 336 | "unexpected_config", |
| 337 | ( |
| 338 | "Invalid string", |
| 339 | [{"version": 1, "loggers": []}], |
| 340 | 0, |
| 341 | ), |
| 342 | ) |
| 343 | def test_an_error_is_raised_when_custom_logging_config_is_unexpected_json( |
| 344 | monkeypatch, |
| 345 | unexpected_config: Any, |
| 346 | ): |
| 347 | """This test calls _configure_vllm_root_logger again to test custom logging |
| 348 | config behavior, however it fails before any change in behavior or |
| 349 | configuration occurs.""" |
| 350 | monkeypatch.setenv("VLLM_CONFIGURE_LOGGING", "1") |
| 351 | |
| 352 | with NamedTemporaryFile(encoding="utf-8", mode="w") as logging_config_file: |
| 353 | logging_config_file.write(json.dumps(unexpected_config)) |
| 354 | logging_config_file.flush() |
| 355 | monkeypatch.setenv("VLLM_LOGGING_CONFIG_PATH", logging_config_file.name) |
| 356 | with pytest.raises(ValueError) as ex_info: |
| 357 | _configure_vllm_root_logger() |
| 358 | assert ex_info.type == ValueError # noqa: E721 |
| 359 | assert "Invalid logging config. Expected dict, got" in str(ex_info) |
| 360 | |
| 361 | |
| 362 | def test_custom_logging_config_is_parsed_and_used_when_provided(monkeypatch): |
| 363 | """This test calls _configure_vllm_root_logger again to test custom logging |
| 364 | config behavior, however mocks are used to ensure no changes in behavior or |
| 365 | configuration occur.""" |
| 366 | monkeypatch.setenv("VLLM_CONFIGURE_LOGGING", "1") |
| 367 | |
| 368 | valid_logging_config = { |
| 369 | "loggers": { |
| 370 | "vllm.test_logger.logger": { |
| 371 | "handlers": [], |
| 372 | "propagate": False, |
| 373 | } |
| 374 | }, |
| 375 | "version": 1, |
| 376 | } |
| 377 | with NamedTemporaryFile(encoding="utf-8", mode="w") as logging_config_file: |
| 378 | logging_config_file.write(json.dumps(valid_logging_config)) |
| 379 | logging_config_file.flush() |
| 380 | monkeypatch.delenv("VLLM_LOGGING_CONFIG_PATH", raising=False) |
| 381 | with patch("vllm.logger.dictConfig") as dict_config_mock: |
| 382 | configure_logging( |
| 383 | LoggingConfig(pylogging_config_file=logging_config_file.name) |
| 384 | ) |
| 385 | dict_config_mock.assert_called_with(valid_logging_config) |
| 386 | |
| 387 | |
| 388 | def test_custom_logging_config_causes_an_error_if_configure_logging_is_off(monkeypatch): |
| 389 | """This test calls _configure_vllm_root_logger again to test custom logging |
| 390 | config behavior, however mocks are used to ensure no changes in behavior or |
| 391 | configuration occur.""" |
| 392 | monkeypatch.setenv("VLLM_CONFIGURE_LOGGING", "0") |
| 393 | |
| 394 | valid_logging_config = { |
| 395 | "loggers": { |
| 396 | "vllm.test_logger.logger": { |
| 397 | "handlers": [], |
| 398 | } |
| 399 | }, |
| 400 | "version": 1, |
| 401 | } |
| 402 | with NamedTemporaryFile(encoding="utf-8", mode="w") as logging_config_file: |
| 403 | logging_config_file.write(json.dumps(valid_logging_config)) |
| 404 | logging_config_file.flush() |
| 405 | monkeypatch.delenv("VLLM_LOGGING_CONFIG_PATH", raising=False) |
| 406 | with pytest.raises(RuntimeError) as ex_info: |
| 407 | configure_logging( |
| 408 | LoggingConfig( |
| 409 | configure_logging=False, |
| 410 | pylogging_config_file=logging_config_file.name, |
| 411 | ) |
| 412 | ) |
| 413 | assert ex_info.type is RuntimeError |
| 414 | expected_message_snippet = ( |
| 415 | "Logging configuration is disabled, but a Python logging config " |
| 416 | "file was given." |
| 417 | ) |
| 418 | assert expected_message_snippet in str(ex_info) |
| 419 | |
| 420 | # Remember! The root logger is assumed to have been configured as |
| 421 | # though VLLM_CONFIGURE_LOGGING=1 and VLLM_LOGGING_CONFIG_PATH=None. |
| 422 | root_logger = logging.getLogger("vllm") |
| 423 | other_logger_name = f"vllm.test_logger.{uuid4()}" |
| 424 | other_logger = init_logger(other_logger_name) |
| 425 | assert other_logger.handlers != root_logger.handlers |
| 426 | assert other_logger.level != root_logger.level |
| 427 | assert other_logger.propagate |
| 428 | |
| 429 | |
| 430 | def test_prepare_object_to_dump(): |
| 431 | str_obj = "str" |
| 432 | assert prepare_object_to_dump(str_obj) == "'str'" |
| 433 | |
| 434 | list_obj = [1, 2, 3] |
| 435 | assert prepare_object_to_dump(list_obj) == "[1, 2, 3]" |
| 436 | |
| 437 | dict_obj = {"a": 1, "b": "b"} |
| 438 | assert prepare_object_to_dump(dict_obj) in [ |
| 439 | "{a: 1, b: 'b'}", |
| 440 | "{b: 'b', a: 1}", |
| 441 | ] |
| 442 | |
| 443 | set_obj = {1, 2, 3} |
| 444 | assert prepare_object_to_dump(set_obj) == "[1, 2, 3]" |
| 445 | |
| 446 | tuple_obj = ("a", "b", "c") |
| 447 | assert prepare_object_to_dump(tuple_obj) == "['a', 'b', 'c']" |
| 448 | |
| 449 | class CustomEnum(enum.Enum): |
| 450 | A = enum.auto() |
| 451 | B = enum.auto() |
| 452 | C = enum.auto() |
| 453 | |
| 454 | assert prepare_object_to_dump(CustomEnum.A) == repr(CustomEnum.A) |
| 455 | |
| 456 | @dataclass |
| 457 | class CustomClass: |
| 458 | a: int |
| 459 | b: str |
| 460 | |
| 461 | assert prepare_object_to_dump(CustomClass(1, "b")) == "CustomClass(a=1, b='b')" |
| 462 | |
| 463 | |
| 464 | # Add vllm prefix to make sure logs go through the vllm logger |
| 465 | test_logger = init_logger("vllm.test_logger") |
| 466 | |
| 467 | |
| 468 | def mp_function(**kwargs): |
| 469 | # This function runs in a subprocess |
| 470 | if logging_config := kwargs.pop("logging_config", None): |
| 471 | configure_logging(logging_config) |
| 472 | |
| 473 | test_logger.warning("This is a subprocess: %s", kwargs.get("a")) |
| 474 | test_logger.error("This is a subprocess error.") |
| 475 | test_logger.debug("This is a subprocess debug message: %s.", kwargs.get("b")) |
| 476 | |
| 477 | |
| 478 | def test_caplog_mp_fork(caplog_vllm, caplog_mp_fork): |
| 479 | with caplog_vllm.at_level(logging.DEBUG, logger="vllm"), caplog_mp_fork(): |
| 480 | import multiprocessing |
| 481 | |
| 482 | ctx = multiprocessing.get_context("fork") |
| 483 | p = ctx.Process( |
| 484 | target=mp_function, |
| 485 | name=f"SubProcess{1}", |
| 486 | kwargs={"a": "AAAA", "b": "BBBBB"}, |
| 487 | ) |
| 488 | p.start() |
| 489 | p.join() |
| 490 | |
| 491 | assert "AAAA" in caplog_vllm.text |
| 492 | assert "BBBBB" in caplog_vllm.text |
| 493 | |
| 494 | |
| 495 | def test_caplog_mp_spawn(caplog_mp_spawn): |
| 496 | with caplog_mp_spawn(logging.DEBUG) as log_holder: |
| 497 | import multiprocessing |
| 498 | |
| 499 | ctx = multiprocessing.get_context("spawn") |
| 500 | p = ctx.Process( |
| 501 | target=mp_function, |
| 502 | name=f"SubProcess{1}", |
| 503 | kwargs={ |
| 504 | "a": "AAAA", |
| 505 | "b": "BBBBB", |
| 506 | "logging_config": LoggingConfig( |
| 507 | pylogging_config_file=os.environ["VLLM_LOGGING_CONFIG_PATH"] |
| 508 | ), |
| 509 | }, |
| 510 | ) |
| 511 | p.start() |
| 512 | p.join() |
| 513 | |
| 514 | assert "AAAA" in log_holder.text |
| 515 | assert "BBBBB" in log_holder.text |