diff --git a/python/sglang/srt/entrypoints/openai/serving_base.py b/python/sglang/srt/entrypoints/openai/serving_base.py index ea61d595b..164ccdd5a 100644 --- a/python/sglang/srt/entrypoints/openai/serving_base.py +++ b/python/sglang/srt/entrypoints/openai/serving_base.py @@ -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 diff --git a/python/sglang/srt/utils/request_logger.py b/python/sglang/srt/utils/request_logger.py index aad5664a7..e20a19a91 100644 --- a/python/sglang/srt/utils/request_logger.py +++ b/python/sglang/srt/utils/request_logger.py @@ -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"], diff --git a/test/registered/utils/test_request_logger.py b/test/registered/utils/test_request_logger.py index 14a801652..28af9f949 100644 --- a/test/registered/utils/test_request_logger.py +++ b/test/registered/utils/test_request_logger.py @@ -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()