| 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 |
| 8 | |
| 9 | |
| 10 | def test_request_logger_log_outputs(): |
| 11 | """Test the new log_outputs functionality.""" |
| 12 | # Create a mock logger to capture log calls |
| 13 | mock_logger = MagicMock() |
| 14 | |
| 15 | with patch("vllm.entrypoints.serve.utils.request_logger.logger", mock_logger): |
| 16 | request_logger = RequestLogger(max_log_len=None) |
| 17 | |
| 18 | # Test basic output logging |
| 19 | request_logger.log_outputs( |
| 20 | request_id="test-123", |
| 21 | outputs="Hello, world!", |
| 22 | output_token_ids=[1, 2, 3, 4], |
| 23 | finish_reason="stop", |
| 24 | is_streaming=False, |
| 25 | delta=False, |
| 26 | ) |
| 27 | |
| 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!" |
| 34 | assert call_args[4] == "stop" |
| 35 | |
| 36 | |
| 37 | def test_request_logger_log_outputs_streaming_delta(): |
| 38 | """Test log_outputs with streaming delta mode.""" |
| 39 | mock_logger = MagicMock() |
| 40 | |
| 41 | with patch("vllm.entrypoints.serve.utils.request_logger.logger", mock_logger): |
| 42 | request_logger = RequestLogger(max_log_len=None) |
| 43 | |
| 44 | # Test streaming delta logging |
| 45 | request_logger.log_outputs( |
| 46 | request_id="test-456", |
| 47 | outputs="Hello", |
| 48 | output_token_ids=[1], |
| 49 | finish_reason=None, |
| 50 | is_streaming=True, |
| 51 | delta=True, |
| 52 | ) |
| 53 | |
| 54 | mock_logger.info.assert_called_once() |
| 55 | call_args = mock_logger.info.call_args.args |
| 56 | assert "Generated response %s%s" in call_args[0] |
| 57 | assert call_args[1] == "test-456" |
| 58 | assert call_args[2] == " (streaming delta)" |
| 59 | assert call_args[3] == "Hello" |
| 60 | assert call_args[4] is None |
| 61 | |
| 62 | |
| 63 | def test_request_logger_log_outputs_streaming_complete(): |
| 64 | """Test log_outputs with streaming complete mode.""" |
| 65 | mock_logger = MagicMock() |
| 66 | |
| 67 | with patch("vllm.entrypoints.serve.utils.request_logger.logger", mock_logger): |
| 68 | request_logger = RequestLogger(max_log_len=None) |
| 69 | |
| 70 | # Test streaming complete logging |
| 71 | request_logger.log_outputs( |
| 72 | request_id="test-789", |
| 73 | outputs="Complete response", |
| 74 | output_token_ids=[1, 2, 3], |
| 75 | finish_reason="length", |
| 76 | is_streaming=True, |
| 77 | delta=False, |
| 78 | ) |
| 79 | |
| 80 | mock_logger.info.assert_called_once() |
| 81 | call_args = mock_logger.info.call_args.args |
| 82 | assert "Generated response %s%s" in call_args[0] |
| 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] == "length" |
| 87 | |
| 88 | |
| 89 | def test_request_logger_log_outputs_with_truncation(): |
| 90 | """Test log_outputs respects max_log_len setting.""" |
| 91 | mock_logger = MagicMock() |
| 92 | |
| 93 | with patch("vllm.entrypoints.serve.utils.request_logger.logger", mock_logger): |
| 94 | # Set max_log_len to 10 |
| 95 | request_logger = RequestLogger(max_log_len=10) |
| 96 | |
| 97 | # Test output truncation |
| 98 | long_output = "This is a very long output that should be truncated" |
| 99 | long_token_ids = list(range(20)) # 20 tokens |
| 100 | |
| 101 | request_logger.log_outputs( |
| 102 | request_id="test-truncate", |
| 103 | outputs=long_output, |
| 104 | output_token_ids=long_token_ids, |
| 105 | finish_reason="stop", |
| 106 | is_streaming=False, |
| 107 | delta=False, |
| 108 | ) |
| 109 | |
| 110 | mock_logger.info.assert_called_once() |
| 111 | call_args = mock_logger.info.call_args |
| 112 | |
| 113 | # Check that output was truncated to first 10 characters |
| 114 | logged_output = call_args[0][3] |
| 115 | assert logged_output == "This is a " |
| 116 | assert len(logged_output) == 10 |
| 117 | |
| 118 | # Check that token IDs were truncated to first 10 tokens |
| 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() |
| 153 | |
| 154 | with patch("vllm.entrypoints.serve.utils.request_logger.logger", mock_logger): |
| 155 | request_logger = RequestLogger(max_log_len=None) |
| 156 | |
| 157 | # Test with None output_token_ids |
| 158 | request_logger.log_outputs( |
| 159 | request_id="test-none", |
| 160 | outputs="Test output", |
| 161 | output_token_ids=None, |
| 162 | finish_reason="stop", |
| 163 | is_streaming=False, |
| 164 | delta=False, |
| 165 | ) |
| 166 | |
| 167 | mock_logger.info.assert_called_once() |
| 168 | call_args = mock_logger.info.call_args.args |
| 169 | assert "Generated response %s%s" in call_args[0] |
| 170 | assert call_args[1] == "test-none" |
| 171 | assert call_args[3] == "Test output" |
| 172 | assert call_args[4] == "stop" |
| 173 | |
| 174 | |
| 175 | def test_request_logger_log_outputs_empty_output(): |
| 176 | """Test log_outputs handles empty output correctly.""" |
| 177 | mock_logger = MagicMock() |
| 178 | |
| 179 | with patch("vllm.entrypoints.serve.utils.request_logger.logger", mock_logger): |
| 180 | request_logger = RequestLogger(max_log_len=5) |
| 181 | |
| 182 | # Test with empty output |
| 183 | request_logger.log_outputs( |
| 184 | request_id="test-empty", |
| 185 | outputs="", |
| 186 | output_token_ids=[], |
| 187 | finish_reason="stop", |
| 188 | is_streaming=False, |
| 189 | delta=False, |
| 190 | ) |
| 191 | |
| 192 | mock_logger.info.assert_called_once() |
| 193 | call_args = mock_logger.info.call_args.args |
| 194 | assert "Generated response %s%s" in call_args[0] |
| 195 | assert call_args[1] == "test-empty" |
| 196 | assert call_args[3] == "" |
| 197 | assert call_args[4] == "stop" |
| 198 | |
| 199 | |
| 200 | def test_request_logger_log_outputs_integration(): |
| 201 | """Test that log_outputs can be called alongside log_inputs.""" |
| 202 | mock_logger = MagicMock() |
| 203 | |
| 204 | with patch("vllm.entrypoints.serve.utils.request_logger.logger", mock_logger): |
| 205 | request_logger = RequestLogger(max_log_len=None) |
| 206 | |
| 207 | # Test that both methods can be called without interference |
| 208 | request_logger.log_inputs( |
| 209 | request_id="test-integration", |
| 210 | prompt="Test prompt", |
| 211 | prompt_token_ids=[1, 2, 3], |
| 212 | prompt_embeds=None, |
| 213 | params=None, |
| 214 | lora_request=None, |
| 215 | ) |
| 216 | |
| 217 | request_logger.log_outputs( |
| 218 | request_id="test-integration", |
| 219 | outputs="Test output", |
| 220 | output_token_ids=[4, 5, 6], |
| 221 | finish_reason="stop", |
| 222 | is_streaming=False, |
| 223 | delta=False, |
| 224 | ) |
| 225 | |
| 226 | # Should have been called twice - once for inputs, once for outputs |
| 227 | assert mock_logger.info.call_count == 2 |
| 228 | |
| 229 | # Check that the calls were made with correct patterns |
| 230 | input_call = mock_logger.info.call_args_list[0][0] |
| 231 | output_call = mock_logger.info.call_args_list[1][0] |
| 232 | |
| 233 | assert "Received request %s" in input_call[0] |
| 234 | assert input_call[1] == "test-integration" |
| 235 | |
| 236 | assert "Generated response %s%s" in output_call[0] |
| 237 | assert output_call[1] == "test-integration" |
| 238 | |
| 239 | |
| 240 | def test_streaming_complete_logs_full_text_content(): |
| 241 | """Test that streaming complete logging includes |
| 242 | full accumulated text, not just token count.""" |
| 243 | mock_logger = MagicMock() |
| 244 | |
| 245 | with patch("vllm.entrypoints.serve.utils.request_logger.logger", mock_logger): |
| 246 | request_logger = RequestLogger(max_log_len=None) |
| 247 | |
| 248 | # Test with actual content instead of token count format |
| 249 | full_response = "This is a complete response from streaming" |
| 250 | request_logger.log_outputs( |
| 251 | request_id="test-streaming-full-text", |
| 252 | outputs=full_response, |
| 253 | output_token_ids=None, |
| 254 | finish_reason="streaming_complete", |
| 255 | is_streaming=True, |
| 256 | delta=False, |
| 257 | ) |
| 258 | |
| 259 | mock_logger.info.assert_called_once() |
| 260 | call_args = mock_logger.info.call_args.args |
| 261 | |
| 262 | # Verify the logged output is the full text, not a token count format |
| 263 | logged_output = call_args[3] |
| 264 | assert logged_output == full_response |
| 265 | assert "tokens>" not in logged_output |
| 266 | assert "streaming_complete" not in logged_output |
| 267 | |
| 268 | # Verify other parameters |
| 269 | assert call_args[1] == "test-streaming-full-text" |
| 270 | assert call_args[2] == " (streaming complete)" |
| 271 | assert call_args[4] == "streaming_complete" |