[Frontend] Log output token IDs at DEBUG level (#52098)
Signed-off-by: ruirui6946 <142162413+ruirui6946@users.noreply.github.com>
yang rui committed
Aug 13, 2026 at 21:11 UTC
152c913a6309305820a98745ae53d9e39b9200fc
3 files changed
+52
-25
tests/entrypoints/serve/utils/test_request_logger.py
+35
-12
@@ -1,6 +1,7 @@
1
# SPDX-License-Identifier: Apache-2.0
2
# SPDX-FileCopyrightText: Copyright contributors to the vLLM project
3
4
+import logging
5
from unittest.mock import MagicMock, patch
6
7
from vllm.entrypoints.serve.utils.request_logger import RequestLogger
@@ -27,10 +28,10 @@ def test_request_logger_log_outputs():
28
mock_logger.info.assert_called_once()
29
call_args = mock_logger.info.call_args.args
30
assert "Generated response %s%s" in call_args[0]
31
+ assert "output_token_ids" not in call_args[0]
32
assert call_args[1] == "test-123"
33
assert call_args[3] == "Hello, world!"
32
- assert call_args[4] == [1, 2, 3, 4]
33
- assert call_args[5] == "stop"
34
+ assert call_args[4] == "stop"
35
36
37
def test_request_logger_log_outputs_streaming_delta():
@@ -56,8 +57,7 @@ def test_request_logger_log_outputs_streaming_delta():
57
assert call_args[1] == "test-456"
58
assert call_args[2] == " (streaming delta)"
59
assert call_args[3] == "Hello"
59
- assert call_args[4] == [1]
60
- assert call_args[5] is None
60
+ assert call_args[4] is None
61
62
63
def test_request_logger_log_outputs_streaming_complete():
@@ -83,8 +83,7 @@ def test_request_logger_log_outputs_streaming_complete():
83
assert call_args[1] == "test-789"
84
assert call_args[2] == " (streaming complete)"
85
assert call_args[3] == "Complete response"
86
- assert call_args[4] == [1, 2, 3]
87
- assert call_args[5] == "length"
86
+ assert call_args[4] == "length"
87
88
89
def test_request_logger_log_outputs_with_truncation():
@@ -117,11 +116,37 @@ def test_request_logger_log_outputs_with_truncation():
116
assert len(logged_output) == 10
117
118
# Check that token IDs were truncated to first 10 tokens
120
- logged_token_ids = call_args[0][4]
119
+ mock_logger.debug.assert_called_once()
120
+ logged_token_ids = mock_logger.debug.call_args.args[3]
121
assert logged_token_ids == list(range(10))
122
assert len(logged_token_ids) == 10
123
124
125
+def test_request_logger_log_output_token_ids_require_debug():
126
+ mock_logger = MagicMock()
127
+ mock_logger.isEnabledFor.side_effect = lambda level: level >= logging.INFO
128
+
129
+ with patch("vllm.entrypoints.serve.utils.request_logger.logger", mock_logger):
130
+ request_logger = RequestLogger(max_log_len=4)
131
+
132
+ request_logger.log_outputs(
133
+ request_id="test-no-token-ids",
134
+ outputs="Test output",
135
+ output_token_ids=[1, 2, 3],
136
+ finish_reason="stop",
137
+ )
138
+
139
+ mock_logger.info.assert_called_once()
140
+ assert mock_logger.info.call_args.args == (
141
+ "Generated response %s%s: output: %r, finish_reason: %s",
142
+ "test-no-token-ids",
143
+ "",
144
+ "Test",
145
+ "stop",
146
+ )
147
+ mock_logger.debug.assert_not_called()
148
+
149
+
150
def test_request_logger_log_outputs_none_values():
151
"""Test log_outputs handles None values correctly."""
152
mock_logger = MagicMock()
@@ -144,8 +169,7 @@ def test_request_logger_log_outputs_none_values():
169
assert "Generated response %s%s" in call_args[0]
170
assert call_args[1] == "test-none"
171
assert call_args[3] == "Test output"
147
- assert call_args[4] is None
148
- assert call_args[5] == "stop"
172
+ assert call_args[4] == "stop"
173
174
175
def test_request_logger_log_outputs_empty_output():
@@ -170,8 +194,7 @@ def test_request_logger_log_outputs_empty_output():
194
assert "Generated response %s%s" in call_args[0]
195
assert call_args[1] == "test-empty"
196
assert call_args[3] == ""
173
- assert call_args[4] == []
174
- assert call_args[5] == "stop"
197
+ assert call_args[4] == "stop"
198
199
200
def test_request_logger_log_outputs_integration():
@@ -245,4 +268,4 @@ def test_streaming_complete_logs_full_text_content():
268
# Verify other parameters
269
assert call_args[1] == "test-streaming-full-text"
270
assert call_args[2] == " (streaming complete)"
248
- assert call_args[5] == "streaming_complete"
271
+ assert call_args[4] == "streaming_complete"
vllm/entrypoints/openai/cli_args.py
+3
-3
@@ -141,9 +141,9 @@ class BaseFrontendArgs:
141
"""Enable the `/tokenizer_info` endpoint. May expose chat
142
templates and other tokenizer configuration."""
143
enable_log_outputs: bool = False
144
- """If set to True, log model outputs (generations).
145
- Requires `--enable-log-requests`. As with `--enable-log-requests`,
146
- information is only logged at INFO level at maximum."""
144
+ """If set to True, log model outputs (generations). Requires
145
+ `--enable-log-requests`. Output text and finish reasons are logged at INFO,
146
+ while output token IDs are logged at DEBUG."""
147
enable_log_deltas: bool = True
148
"""If set to False, output deltas will not be logged. Relevant only if
149
--enable-log-outputs is set.
vllm/entrypoints/serve/utils/request_logger.py
+14
-10
@@ -77,24 +77,28 @@ class RequestLogger:
77
delta: bool = False,
78
) -> None:
79
max_log_len = self.max_log_len
80
- if max_log_len is not None:
81
- if outputs is not None:
82
- outputs = outputs[:max_log_len]
83
-
84
- if output_token_ids is not None:
85
- # Convert to list and apply truncation
86
- output_token_ids = list(output_token_ids)[:max_log_len]
80
+ if max_log_len is not None and outputs is not None:
81
+ outputs = outputs[:max_log_len]
82
83
stream_info = ""
84
if is_streaming:
85
stream_info = " (streaming delta)" if delta else " (streaming complete)"
86
87
+ if logger.isEnabledFor(logging.DEBUG):
88
+ if max_log_len is not None and output_token_ids is not None:
89
+ output_token_ids = list(output_token_ids)[:max_log_len]
90
+
91
+ logger.debug(
92
+ "Generated response %s%s details: output_token_ids: %s",
93
+ request_id,
94
+ stream_info,
95
+ output_token_ids,
96
+ )
97
+
98
logger.info(
93
- "Generated response %s%s: output: %r, "
94
- "output_token_ids: %s, finish_reason: %s",
99
+ "Generated response %s%s: output: %r, finish_reason: %s",
100
request_id,
101
stream_info,
102
outputs,
98
- output_token_ids,
103
finish_reason,
104
)