[OpenAI] Log raw request payload for --log-requests (#20605)

This commit is contained in:
Zhirui
2026-03-16 08:45:00 +08:00
committed by GitHub
parent d852f26cb6
commit 35c249b4de
3 changed files with 155 additions and 8 deletions

View File

@@ -84,6 +84,11 @@ class OpenAIServingBase(ABC):
if error_msg:
return self.create_error_response(error_msg)
# Log the raw OpenAI request payload before conversion to tokenized form.
request_logger = self.tokenizer_manager.request_logger
if request_logger.log_requests and request_logger.log_requests_level >= 2:
request_logger.log_openai_received_request(request, request=raw_request)
# Convert to internal format
adapted_request, processed_request = self._convert_to_internal_request(
request, raw_request

View File

@@ -130,6 +130,34 @@ class RequestLogger:
decoded = tokenizer.decode(obj.input_ids, skip_special_tokens=False)
obj.text = decoded
def log_openai_received_request(
self,
obj: Any,
request: Optional["fastapi.Request"] = None,
) -> None:
"""Log the raw OpenAI request payload before request adaptation/tokenization."""
max_length, _, _ = self.metadata
max_length = max_length if max_length is not None else 2048
headers = _extract_whitelisted_headers(request)
if hasattr(obj, "model_dump"):
obj_to_log = obj.model_dump(exclude_none=True)
else:
obj_to_log = obj
if self.log_requests_format == "json":
log_data = {
"obj": _transform_data_for_logging(obj_to_log, max_length=max_length),
}
if headers:
log_data["headers"] = headers
log_json(self.targets, "request.received.openai", log_data)
else:
headers_str = f", headers={headers}" if headers else ""
self._log(
f"Receive OpenAI: obj={_dataclass_to_string_truncated(obj_to_log, max_length)}{headers_str}"
)
def log_finished_request(
self,
obj: Union["GenerateReqInput", "EmbeddingReqInput"],

View File

@@ -23,6 +23,7 @@ register_amd_ci(est_time=120, suite="nightly-amd-1-gpu", nightly=True)
TEST_ROUTING_KEY = "test-routing-key-12345"
TEST_CUSTOM_HEADER_NAME = "X-Test-Header"
TEST_CUSTOM_HEADER_VALUE = "test-header-value-67890"
TEST_MODEL_NAME = "Qwen/Qwen3-0.6B"
class BaseTestRequestLogger:
@@ -54,7 +55,7 @@ class BaseTestRequestLogger:
os.environ[key] = value
cls.process = popen_launch_server(
"Qwen/Qwen3-0.6B",
TEST_MODEL_NAME,
DEFAULT_URL_FOR_TEST,
timeout=DEFAULT_TIMEOUT_FOR_SERVER_LAUNCH,
other_args=other_args,
@@ -77,6 +78,32 @@ class BaseTestRequestLogger:
def _verify_logs(self, content: str, source_name: str):
raise NotImplementedError
def _verify_openai_logs(self, content: str, source_name: str):
raise NotImplementedError
def _wait_until_verified(
self,
verify_fn,
get_content_fn,
source_name: str,
timeout: float = 10.0,
interval: float = 0.1,
):
deadline = time.time() + timeout
last_error = None
while time.time() < deadline:
content = get_content_fn()
try:
verify_fn(content, source_name)
return
except AssertionError as err:
last_error = err
time.sleep(interval)
if last_error is not None:
raise last_error
def test_logging(self):
response = requests.post(
DEFAULT_URL_FOR_TEST + "/generate",
@@ -88,16 +115,46 @@ class BaseTestRequestLogger:
timeout=30,
)
self.assertEqual(response.status_code, 200)
time.sleep(1)
stdout_content = self.stdout.getvalue() + self.stderr.getvalue()
self._verify_logs(stdout_content, "stdout")
self._wait_until_verified(
self._verify_logs,
lambda: self.stdout.getvalue() + self.stderr.getvalue(),
"stdout",
)
self._wait_until_verified(
self._verify_logs,
lambda: "".join(f.read_text() for f in Path(self.temp_dir).glob("*.log")),
"log files",
)
log_files = list(Path(self.temp_dir).glob("*.log"))
self.assertGreater(len(log_files), 0, "No log files found in temp directory")
file_content = "".join(f.read_text() for f in log_files)
self._verify_logs(file_content, "log files")
def test_openai_chat_logging(self):
response = requests.post(
DEFAULT_URL_FOR_TEST + "/v1/chat/completions",
json={
"model": TEST_MODEL_NAME,
"messages": [{"role": "user", "content": "hello request logger"}],
"max_tokens": 8,
"temperature": 0,
},
headers=self.request_headers,
timeout=30,
)
self.assertEqual(response.status_code, 200)
self._wait_until_verified(
self._verify_openai_logs,
lambda: self.stdout.getvalue() + self.stderr.getvalue(),
"stdout",
)
self._wait_until_verified(
self._verify_openai_logs,
lambda: "".join(f.read_text() for f in Path(self.temp_dir).glob("*.log")),
"log files",
)
log_files = list(Path(self.temp_dir).glob("*.log"))
self.assertGreater(len(log_files), 0, "No log files found in temp directory")
class TestRequestLoggerText(BaseTestRequestLogger, CustomTestCase):
@@ -113,6 +170,17 @@ class TestRequestLoggerText(BaseTestRequestLogger, CustomTestCase):
"x-smg-routing-key", content, f"Header name not found in {source_name}"
)
def _verify_openai_logs(self, content: str, source_name: str):
self.assertIn(
"Receive OpenAI:", content, f"OpenAI receive log not found in {source_name}"
)
self.assertIn("'messages':", content, f"Messages not found in {source_name}")
self.assertIn(
"hello request logger",
content,
f"OpenAI user prompt not found in {source_name}",
)
class TestRequestLoggerJson(BaseTestRequestLogger, CustomTestCase):
log_requests_format = "json"
@@ -123,7 +191,10 @@ class TestRequestLoggerJson(BaseTestRequestLogger, CustomTestCase):
for line in content.splitlines():
if not line.strip() or not line.startswith("{"):
continue
data = json.loads(line)
try:
data = json.loads(line)
except json.JSONDecodeError:
continue
rid = data.get("rid", "")
if rid.startswith("HEALTH_CHECK"):
@@ -152,6 +223,34 @@ class TestRequestLoggerJson(BaseTestRequestLogger, CustomTestCase):
finished_found, f"request.finished event not found in {source_name}"
)
def _verify_openai_logs(self, content: str, source_name: str):
openai_received_found = False
for line in content.splitlines():
if not line.strip() or not line.startswith("{"):
continue
try:
data = json.loads(line)
except json.JSONDecodeError:
continue
if data.get("event") != "request.received.openai":
continue
obj = data.get("obj", {})
self.assertEqual(obj.get("model"), TEST_MODEL_NAME)
self.assertIsInstance(obj.get("messages"), list)
self.assertGreater(len(obj.get("messages")), 0)
self.assertEqual(obj["messages"][0].get("content"), "hello request logger")
self.assertEqual(
data.get("headers", {}).get("x-smg-routing-key"), TEST_ROUTING_KEY
)
openai_received_found = True
break
self.assertTrue(
openai_received_found,
f"request.received.openai event not found in {source_name}",
)
class TestCustomHeaderViaEnvVar(BaseTestRequestLogger, CustomTestCase):
"""Test that custom headers can be added via SGLANG_LOG_REQUEST_HEADERS env var."""
@@ -187,6 +286,21 @@ class TestCustomHeaderViaEnvVar(BaseTestRequestLogger, CustomTestCase):
f"Default header value not found in {source_name}",
)
def _verify_openai_logs(self, content: str, source_name: str):
self.assertIn(
"Receive OpenAI:", content, f"OpenAI receive log not found in {source_name}"
)
self.assertIn(
TEST_CUSTOM_HEADER_NAME.lower(),
content,
f"Custom header name not found in {source_name}",
)
self.assertIn(
TEST_CUSTOM_HEADER_VALUE,
content,
f"Custom header value not found in {source_name}",
)
if __name__ == "__main__":
unittest.main()