diff --git a/tests/entrypoints/serve/utils/test_request_logger.py b/tests/entrypoints/serve/utils/test_request_logger.py index c17f2471e48a..717ff190b3a7 100644 --- a/tests/entrypoints/serve/utils/test_request_logger.py +++ b/tests/entrypoints/serve/utils/test_request_logger.py @@ -1,6 +1,7 @@ # SPDX-License-Identifier: Apache-2.0 # SPDX-FileCopyrightText: Copyright contributors to the vLLM project +import logging from unittest.mock import MagicMock, patch from vllm.entrypoints.serve.utils.request_logger import RequestLogger @@ -27,10 +28,10 @@ def test_request_logger_log_outputs(): mock_logger.info.assert_called_once() call_args = mock_logger.info.call_args.args assert "Generated response %s%s" in call_args[0] + assert "output_token_ids" not in call_args[0] assert call_args[1] == "test-123" assert call_args[3] == "Hello, world!" - assert call_args[4] == [1, 2, 3, 4] - assert call_args[5] == "stop" + assert call_args[4] == "stop" def test_request_logger_log_outputs_streaming_delta(): @@ -56,8 +57,7 @@ def test_request_logger_log_outputs_streaming_delta(): assert call_args[1] == "test-456" assert call_args[2] == " (streaming delta)" assert call_args[3] == "Hello" - assert call_args[4] == [1] - assert call_args[5] is None + assert call_args[4] is None def test_request_logger_log_outputs_streaming_complete(): @@ -83,8 +83,7 @@ def test_request_logger_log_outputs_streaming_complete(): assert call_args[1] == "test-789" assert call_args[2] == " (streaming complete)" assert call_args[3] == "Complete response" - assert call_args[4] == [1, 2, 3] - assert call_args[5] == "length" + assert call_args[4] == "length" def test_request_logger_log_outputs_with_truncation(): @@ -117,11 +116,37 @@ def test_request_logger_log_outputs_with_truncation(): assert len(logged_output) == 10 # Check that token IDs were truncated to first 10 tokens - logged_token_ids = call_args[0][4] + mock_logger.debug.assert_called_once() + logged_token_ids = mock_logger.debug.call_args.args[3] assert logged_token_ids == list(range(10)) assert len(logged_token_ids) == 10 +def test_request_logger_log_output_token_ids_require_debug(): + mock_logger = MagicMock() + mock_logger.isEnabledFor.side_effect = lambda level: level >= logging.INFO + + with patch("vllm.entrypoints.serve.utils.request_logger.logger", mock_logger): + request_logger = RequestLogger(max_log_len=4) + + request_logger.log_outputs( + request_id="test-no-token-ids", + outputs="Test output", + output_token_ids=[1, 2, 3], + finish_reason="stop", + ) + + mock_logger.info.assert_called_once() + assert mock_logger.info.call_args.args == ( + "Generated response %s%s: output: %r, finish_reason: %s", + "test-no-token-ids", + "", + "Test", + "stop", + ) + mock_logger.debug.assert_not_called() + + def test_request_logger_log_outputs_none_values(): """Test log_outputs handles None values correctly.""" mock_logger = MagicMock() @@ -144,8 +169,7 @@ def test_request_logger_log_outputs_none_values(): assert "Generated response %s%s" in call_args[0] assert call_args[1] == "test-none" assert call_args[3] == "Test output" - assert call_args[4] is None - assert call_args[5] == "stop" + assert call_args[4] == "stop" def test_request_logger_log_outputs_empty_output(): @@ -170,8 +194,7 @@ def test_request_logger_log_outputs_empty_output(): assert "Generated response %s%s" in call_args[0] assert call_args[1] == "test-empty" assert call_args[3] == "" - assert call_args[4] == [] - assert call_args[5] == "stop" + assert call_args[4] == "stop" def test_request_logger_log_outputs_integration(): @@ -245,4 +268,4 @@ def test_streaming_complete_logs_full_text_content(): # Verify other parameters assert call_args[1] == "test-streaming-full-text" assert call_args[2] == " (streaming complete)" - assert call_args[5] == "streaming_complete" + assert call_args[4] == "streaming_complete" diff --git a/vllm/entrypoints/openai/cli_args.py b/vllm/entrypoints/openai/cli_args.py index 64dab7416d3b..b387fb63573a 100644 --- a/vllm/entrypoints/openai/cli_args.py +++ b/vllm/entrypoints/openai/cli_args.py @@ -141,9 +141,9 @@ class BaseFrontendArgs: """Enable the `/tokenizer_info` endpoint. May expose chat templates and other tokenizer configuration.""" enable_log_outputs: bool = False - """If set to True, log model outputs (generations). - Requires `--enable-log-requests`. As with `--enable-log-requests`, - information is only logged at INFO level at maximum.""" + """If set to True, log model outputs (generations). Requires + `--enable-log-requests`. Output text and finish reasons are logged at INFO, + while output token IDs are logged at DEBUG.""" enable_log_deltas: bool = True """If set to False, output deltas will not be logged. Relevant only if --enable-log-outputs is set. diff --git a/vllm/entrypoints/serve/utils/request_logger.py b/vllm/entrypoints/serve/utils/request_logger.py index c2a77fbb4e56..ac10feab1011 100644 --- a/vllm/entrypoints/serve/utils/request_logger.py +++ b/vllm/entrypoints/serve/utils/request_logger.py @@ -77,24 +77,28 @@ def log_outputs( delta: bool = False, ) -> None: max_log_len = self.max_log_len - if max_log_len is not None: - if outputs is not None: - outputs = outputs[:max_log_len] - - if output_token_ids is not None: - # Convert to list and apply truncation - output_token_ids = list(output_token_ids)[:max_log_len] + if max_log_len is not None and outputs is not None: + outputs = outputs[:max_log_len] stream_info = "" if is_streaming: stream_info = " (streaming delta)" if delta else " (streaming complete)" + if logger.isEnabledFor(logging.DEBUG): + if max_log_len is not None and output_token_ids is not None: + output_token_ids = list(output_token_ids)[:max_log_len] + + logger.debug( + "Generated response %s%s details: output_token_ids: %s", + request_id, + stream_info, + output_token_ids, + ) + logger.info( - "Generated response %s%s: output: %r, " - "output_token_ids: %s, finish_reason: %s", + "Generated response %s%s: output: %r, finish_reason: %s", request_id, stream_info, outputs, - output_token_ids, finish_reason, )