[Core][Logging] Fix JSON logging process decoration (#57957)
Signed-off-by: Mark McLoughlin <markmc@redhat.com>
Mark McLoughlin committed
Sep 25, 2026 at 17:12 UTC
a44d7b51511fff6fde2bafb9c4715433a7627d1c
6 files changed
+113
-56
examples/features/logging_configuration.md
+18
-1
@@ -75,7 +75,8 @@ To begin, first, create an appropriate JSON logging configuration file:
75
{
76
"formatters": {
77
"json": {
78
- "class": "pythonjsonlogger.jsonlogger.JsonFormatter"
78
+ "class": "pythonjsonlogger.jsonlogger.JsonFormatter",
79
+ "format": "%(asctime)s %(levelname)s %(name)s %(vllm_process_name)s %(process)d %(message)s"
80
}
81
},
82
"handlers": {
@@ -104,6 +105,22 @@ vllm serve mistralai/Mistral-7B-v0.1 --max-model-len 2048 \
105
--logging-config.pylogging_config_file /path/to/logging_config.json
106
```
107
108
+Each vLLM log record is one JSON object and includes `vllm_process_name`, which
109
+identifies vLLM's logical process (including worker ranks where applicable).
110
+The standard `process` record attribute contains the operating-system PID.
111
+vLLM avoids altering `stdout` or `stderr`, so no text is prepended to JSON
112
+log records.
113
+
114
+This applies to records emitted through the configured Python loggers. A JSON
115
+formatter cannot convert unrelated output into JSON, such as a third-party
116
+library writing directly to `stdout` or `stderr`; configure or route such
117
+output separately when a consumer requires every collected line to be JSON.
118
+
119
+When serving, `VLLM_LOGGING_CONFIG_PATH` is also used as Uvicorn's logging
120
+configuration. This example configures only `vllm`; configure `uvicorn`,
121
+`uvicorn.error`, and `uvicorn.access` with a JSON handler when those server
122
+logs must also be structured.
123
+
124
### Example 2: Silence a particular vLLM logger
125
126
To silence a particular vLLM logger, it is necessary to provide custom logging
tests/test_logger.py
+55
@@ -16,6 +16,7 @@ from uuid import uuid4
16
17
import pytest
18
19
+import vllm.logger as vllm_logger
20
from vllm.config import LoggingConfig
21
from vllm.logger import (
22
_DATE_FORMAT,
@@ -28,6 +29,7 @@ from vllm.logger import (
29
)
30
from vllm.logging_utils import NewLineFormatter
31
from vllm.logging_utils.dump_input import prepare_object_to_dump
32
+from vllm.utils.system_utils import decorate_logs
33
34
35
def f1(x):
@@ -110,6 +112,59 @@ def test_offline_llm_configures_logging_before_logging_args(monkeypatch):
112
llm_module.LLM(model="facebook/opt-125m")
113
114
115
+def test_json_logging(monkeypatch, tmp_path):
116
+ output = io.StringIO()
117
+ logging_config = {
118
+ "version": 1,
119
+ "disable_existing_loggers": False,
120
+ "formatters": {
121
+ "json": {
122
+ "class": "pythonjsonlogger.jsonlogger.JsonFormatter",
123
+ "format": (
124
+ "%(asctime)s %(levelname)s %(name)s %(vllm_process_name)s "
125
+ "%(process)d %(message)s"
126
+ ),
127
+ },
128
+ },
129
+ "handlers": {
130
+ "console": {
131
+ "class": "logging.StreamHandler",
132
+ "formatter": "json",
133
+ "stream": "ext://sys.stdout",
134
+ },
135
+ },
136
+ "loggers": {
137
+ "vllm": {
138
+ "handlers": ["console"],
139
+ "level": "INFO",
140
+ "propagate": False,
141
+ },
142
+ },
143
+ }
144
+
145
+ logging_config_path = tmp_path / "logging_config.json"
146
+ logging_config_path.write_text(json.dumps(logging_config))
147
+
148
+ try:
149
+ with monkeypatch.context() as context:
150
+ context.setattr(sys, "stdout", output)
151
+ # Restore this module-global state when the context exits.
152
+ context.setattr(vllm_logger, "_vllm_process_info", None)
153
+ _configure_vllm_root_logger(
154
+ LoggingConfig(pylogging_config_file=str(logging_config_path))
155
+ )
156
+ decorate_logs("Worker_DP0")
157
+ init_logger("vllm.structured_log_probe").info("structured log probe")
158
+
159
+ log = json.loads(output.getvalue())
160
+ finally:
161
+ _configure_vllm_root_logger(LoggingConfig())
162
+
163
+ assert log["message"] == "structured log probe"
164
+ assert log["vllm_process_name"] == "Worker_DP0"
165
+ assert log["process"] == os.getpid()
166
+
167
+
168
def test_use_color_force_color(monkeypatch):
169
"""FORCE_COLOR forces colored logs without a TTY, while NO_COLOR and an
170
explicit VLLM_LOGGING_COLOR=0 take precedence over it."""
vllm/logger.py
+27
-1
@@ -25,11 +25,36 @@ if TYPE_CHECKING:
25
from vllm.config.logging import LoggingConfig
26
27
_FORMAT = (
28
- f"{envs.VLLM_LOGGING_PREFIX}%(levelname)s %(asctime)s "
28
+ f"{envs.VLLM_LOGGING_PREFIX}(%(vllm_process_name)s "
29
+ "pid=%(process)d) %(levelname)s %(asctime)s "
30
"[%(fileinfo)s:%(lineno)d] %(message)s"
31
)
32
_DATE_FORMAT = "%m-%d %H:%M:%S"
33
34
+_base_log_record_factory = logging.getLogRecordFactory()
35
+_vllm_process_info: tuple[str, int] | None = None
36
+
37
+
38
+def _vllm_log_record_factory(*args: Any, **kwargs: Any) -> logging.LogRecord:
39
+ """Add vLLM process metadata to each log record."""
40
+ record = _base_log_record_factory(*args, **kwargs)
41
+ process_info = _vllm_process_info
42
+ pid = os.getpid()
43
+ if process_info is None or process_info[1] != pid:
44
+ record.vllm_process_name = record.processName
45
+ else:
46
+ record.vllm_process_name = process_info[0]
47
+ return record
48
+
49
+
50
+def set_vllm_process_name(process_name: str, *, skip_if_set: bool = False) -> None:
51
+ """Set the vLLM process name added to subsequent log records."""
52
+ global _vllm_process_info
53
+ pid = os.getpid()
54
+ if skip_if_set and _vllm_process_info is not None and _vllm_process_info[1] == pid:
55
+ return
56
+ _vllm_process_info = (process_name, pid)
57
+
58
59
def _use_color() -> bool:
60
if envs.NO_COLOR or envs.VLLM_LOGGING_COLOR == "0":
@@ -195,6 +220,7 @@ def _configure_vllm_root_logger(config: "LoggingConfig | None" = None) -> None:
220
)
221
222
if configure_logging:
223
+ logging.setLogRecordFactory(_vllm_log_record_factory)
224
logging_config = deepcopy(DEFAULT_LOGGING_CONFIG)
225
226
vllm_handler = logging_config["handlers"]["vllm"]
vllm/logging_utils/formatter.py
+9
@@ -91,11 +91,20 @@ class ColoredFormatter(NewLineFormatter):
91
"CRITICAL": "\033[35m", # Magenta
92
}
93
GREY = "\033[90m" # Grey for timestamp and file info
94
+ PROCESS_PREFIX_COLOR = "\033[0;36m"
95
+ PROCESS_PREFIX_RESET = "\033[0;0m"
96
RESET = "\033[0m"
97
98
def __init__(self, fmt, datefmt=None, style="%", *, log_level: str | None = None):
99
# Inject grey color codes into format string for timestamp and file info
100
if fmt:
101
+ # Wrap process prefix with cyan
102
+ fmt = fmt.replace(
103
+ "(%(vllm_process_name)s pid=%(process)d)",
104
+ f"{self.PROCESS_PREFIX_COLOR}"
105
+ "(%(vllm_process_name)s pid=%(process)d)"
106
+ f"{self.PROCESS_PREFIX_RESET}",
107
+ )
108
# Wrap %(asctime)s with grey
109
fmt = fmt.replace("%(asctime)s", f"{self.GREY}%(asctime)s{self.RESET}")
110
# Wrap [%(fileinfo)s:%(lineno)d] with grey
vllm/utils/system_utils.py
+3
-53
@@ -11,12 +11,11 @@ import signal
11
import sys
12
from collections.abc import Callable, Iterator
13
from pathlib import Path
14
-from typing import TextIO
14
15
import psutil
16
17
import vllm.envs as envs
19
-from vllm.logger import init_logger
18
+from vllm.logger import init_logger, set_vllm_process_name
19
from vllm.platforms import current_platform
20
from vllm.platforms.interface import in_wsl
21
from vllm.ray.lazy_utils import is_in_ray_actor
@@ -25,10 +24,6 @@ from .platform_utils import cuda_is_initialized, xpu_is_initialized
24
25
logger = init_logger(__name__)
26
28
-CYAN = "\033[0;36m"
29
-RESET = "\033[0;0m"
30
-
31
-
27
# Environment variable utilities
28
29
@@ -198,59 +193,14 @@ def set_process_title(
193
setproctitle.setproctitle(f"{prefix}::{name}")
194
195
201
-def _add_prefix(file: TextIO, worker_name: str, pid: int) -> None:
202
- """Add colored prefix to file output for log decoration."""
203
- is_tty = hasattr(file, "isatty") and file.isatty()
204
- if (
205
- envs.NO_COLOR
206
- or envs.VLLM_LOGGING_COLOR == "0"
207
- or (envs.VLLM_LOGGING_COLOR != "1" and not is_tty)
208
- ):
209
- prefix = f"({worker_name} pid={pid}) "
210
- else:
211
- prefix = f"{CYAN}({worker_name} pid={pid}){RESET} "
212
- # Use the original write to avoid nesting prefixes on repeated calls.
213
- file_write = getattr(file, "_original_write", file.write)
214
-
215
- def write_with_prefix(s: str):
216
- if not s:
217
- return
218
- if file.start_new_line: # type: ignore[attr-defined]
219
- file_write(prefix)
220
- idx = 0
221
- while (next_idx := s.find("\n", idx)) != -1:
222
- next_idx += 1
223
- file_write(s[idx:next_idx])
224
- if next_idx == len(s):
225
- file.start_new_line = True # type: ignore[attr-defined]
226
- return
227
- file_write(prefix)
228
- idx = next_idx
229
- file_write(s[idx:])
230
- file.start_new_line = False # type: ignore[attr-defined]
231
-
232
- file.start_new_line = True # type: ignore[attr-defined]
233
- file._original_write = file_write # type: ignore[attr-defined]
234
- file.write = write_with_prefix # type: ignore[method-assign]
235
-
236
-
196
def decorate_logs(
197
process_name: str | None = None, *, skip_if_decorated: bool = False
198
) -> None:
240
- """Decorate stdout/stderr with process name and PID prefix."""
241
- # Respect VLLM_CONFIGURE_LOGGING environment variable
242
- if not envs.VLLM_CONFIGURE_LOGGING:
243
- return
244
-
245
- if skip_if_decorated and hasattr(sys.stdout, "_original_write"):
246
- return
247
-
199
+ """Add vLLM process metadata to subsequent log records."""
200
if process_name is None:
201
process_name = get_mp_context().current_process().name
202
251
- pid = os.getpid()
252
- _add_prefix(sys.stdout, process_name, pid)
253
- _add_prefix(sys.stderr, process_name, pid)
203
+ set_vllm_process_name(process_name, skip_if_set=skip_if_decorated)
204
205
206
def kill_process_tree(pid: int):
vllm/v1/utils.py
+1
-1
@@ -530,7 +530,7 @@ def run_api_server_worker_proc(
530
client_config = client_config or {}
531
server_index = client_config.get("client_index", 0)
532
533
- # Set process title and add process-specific prefix to stdout and stderr.
533
+ # Set process title and process-specific log metadata.
534
set_process_title("APIServer", str(server_index))
535
decorate_logs()
536