diff --git a/python/sglang/srt/managers/io_struct.py b/python/sglang/srt/managers/io_struct.py index 880191d3b..c592f0cb5 100644 --- a/python/sglang/srt/managers/io_struct.py +++ b/python/sglang/srt/managers/io_struct.py @@ -1485,6 +1485,7 @@ class FreezeGCReq(BaseReq): class ConfigureLoggingReq(BaseReq): log_requests: Optional[bool] = None log_requests_level: Optional[int] = None + log_requests_format: Optional[str] = None dump_requests_folder: Optional[str] = None dump_requests_threshold: Optional[int] = None crash_dump_folder: Optional[str] = None diff --git a/python/sglang/srt/managers/tokenizer_manager.py b/python/sglang/srt/managers/tokenizer_manager.py index f6c5dfdc5..0c20bbe7e 100644 --- a/python/sglang/srt/managers/tokenizer_manager.py +++ b/python/sglang/srt/managers/tokenizer_manager.py @@ -185,6 +185,7 @@ class TokenizerManager(TokenizerCommunicatorMixin, TokenizerManagerMultiItemMixi self.request_logger = RequestLogger( log_requests=server_args.log_requests, log_requests_level=server_args.log_requests_level, + log_requests_format=server_args.log_requests_format, ) self.preferred_sampling_params = server_args.preferred_sampling_params self.crash_dump_folder = server_args.crash_dump_folder @@ -1314,6 +1315,7 @@ class TokenizerManager(TokenizerCommunicatorMixin, TokenizerManagerMultiItemMixi self.request_logger.configure( log_requests=obj.log_requests, log_requests_level=obj.log_requests_level, + log_requests_format=obj.log_requests_format, ) if obj.dump_requests_folder is not None: self.dump_requests_folder = obj.dump_requests_folder diff --git a/python/sglang/srt/server_args.py b/python/sglang/srt/server_args.py index 36c8bc533..6078d8aca 100644 --- a/python/sglang/srt/server_args.py +++ b/python/sglang/srt/server_args.py @@ -338,6 +338,7 @@ class ServerArgs: log_level_http: Optional[str] = None log_requests: bool = False log_requests_level: int = 2 + log_requests_format: str = "text" crash_dump_folder: Optional[str] = None show_time_cost: bool = False enable_metrics: bool = False @@ -2908,6 +2909,13 @@ class ServerArgs: help="0: Log metadata (no sampling parameters). 1: Log metadata and sampling parameters. 2: Log metadata, sampling parameters and partial input/output. 3: Log every input/output.", choices=[0, 1, 2, 3], ) + parser.add_argument( + "--log-requests-format", + type=str, + default=ServerArgs.log_requests_format, + choices=["text", "json"], + help="Format for request logging: 'text' (human-readable) or 'json' (structured)", + ) parser.add_argument( "--crash-dump-folder", type=str, diff --git a/python/sglang/srt/utils/request_logger.py b/python/sglang/srt/utils/request_logger.py index 7e2e13a04..a74e3b32b 100644 --- a/python/sglang/srt/utils/request_logger.py +++ b/python/sglang/srt/utils/request_logger.py @@ -14,7 +14,9 @@ from __future__ import annotations import dataclasses +import json import logging +from datetime import datetime from functools import lru_cache from typing import TYPE_CHECKING, Any, Optional, Set, Tuple, Union @@ -25,11 +27,23 @@ if TYPE_CHECKING: logger = logging.getLogger(__name__) +_json_logger = logging.getLogger(__name__ + ".json") +_json_logger.propagate = False +_json_handler = logging.StreamHandler() +_json_handler.setFormatter(logging.Formatter("%(message)s")) +_json_logger.addHandler(_json_handler) + class RequestLogger: - def __init__(self, log_requests: bool, log_requests_level: int): + def __init__( + self, + log_requests: bool, + log_requests_level: int, + log_requests_format: str, + ): self.log_requests = log_requests self.log_requests_level = log_requests_level + self.log_requests_format = log_requests_format self.metadata: Tuple[Optional[int], Optional[Set[str]], Optional[Set[str]]] = ( self._compute_metadata() ) @@ -38,11 +52,14 @@ class RequestLogger: self, log_requests: Optional[bool] = None, log_requests_level: Optional[int] = None, + log_requests_format: Optional[str] = None, ) -> None: if log_requests is not None: self.log_requests = log_requests if log_requests_level is not None: self.log_requests_level = log_requests_level + if log_requests_format is not None: + self.log_requests_format = log_requests_format self.metadata = self._compute_metadata() def log_received_request( @@ -52,9 +69,16 @@ class RequestLogger: return max_length, skip_names, _ = self.metadata - logger.info( - f"Receive: obj={_dataclass_to_string_truncated(obj, max_length, skip_names=skip_names)}" - ) + if self.log_requests_format == "json": + log_data = { + "rid": obj.rid, + "obj": _transform_data_for_logging(obj, max_length, skip_names), + } + _log_json("request.received", log_data) + else: + logger.info( + f"Receive: obj={_dataclass_to_string_truncated(obj, max_length, skip_names=skip_names)}" + ) # FIXME: This is a temporary fix to get the text from the input ids. # We should remove this once we have a proper way. @@ -77,11 +101,22 @@ class RequestLogger: return max_length, skip_names, out_skip_names = self.metadata - if is_multimodal_gen: - msg = f"Finish: obj={_dataclass_to_string_truncated(obj, max_length, skip_names=skip_names)}" + if self.log_requests_format == "json": + log_data = { + "rid": obj.rid, + "obj": _transform_data_for_logging(obj, max_length, skip_names), + } + if not is_multimodal_gen: + log_data["out"] = _transform_data_for_logging( + out, max_length, out_skip_names + ) + _log_json("request.finished", log_data) else: - msg = f"Finish: obj={_dataclass_to_string_truncated(obj, max_length, skip_names=skip_names)}, out={_dataclass_to_string_truncated(out, max_length, skip_names=out_skip_names)}" - logger.info(msg) + if is_multimodal_gen: + msg = f"Finish: obj={_dataclass_to_string_truncated(obj, max_length, skip_names=skip_names)}" + else: + msg = f"Finish: obj={_dataclass_to_string_truncated(obj, max_length, skip_names=skip_names)}, out={_dataclass_to_string_truncated(out, max_length, skip_names=out_skip_names)}" + logger.info(msg) def _compute_metadata( self, @@ -130,6 +165,17 @@ def disable_request_logging() -> bool: return get_bool_env_var("SGLANG_DISABLE_REQUEST_LOGGING") +# TODO unify logging, e.g. allow normal logs to be JSON as well +def _log_json(event: str, data: dict) -> None: + log_data = { + "timestamp": datetime.now().isoformat(), + "event": event, + **data, + } + _json_logger.info(json.dumps(log_data, ensure_ascii=False)) + + +# TODO unify this w/ `_transform_data_for_logging` if we find performance enough def _dataclass_to_string_truncated( data: Any, max_length: int = 2048, skip_names: Optional[Set[str]] = None ) -> str: @@ -170,3 +216,37 @@ def _dataclass_to_string_truncated( ) else: return str(data) + + +def _transform_data_for_logging( + data: Any, max_length: int = 2048, skip_names: Optional[Set[str]] = None +) -> Any: + if skip_names is None: + skip_names = set() + if isinstance(data, str): + if len(data) > max_length: + half_length = max_length // 2 + return data[:half_length] + "..." + data[-half_length:] + return data + elif isinstance(data, (list, tuple)): + if len(data) > max_length: + half_length = max_length // 2 + return list(data[:half_length]) + ["..."] + list(data[-half_length:]) + return [_transform_data_for_logging(v, max_length) for v in data] + elif isinstance(data, dict): + return { + k: _transform_data_for_logging(v, max_length) + for k, v in data.items() + if k not in skip_names + } + elif dataclasses.is_dataclass(data): + fields = dataclasses.fields(data) + return { + f.name: _transform_data_for_logging(getattr(data, f.name), max_length) + for f in fields + if f.name not in skip_names + } + elif isinstance(data, (int, float, bool, type(None))): + return data + else: + return str(data) diff --git a/test/registered/debug_utils/test_request_logger.py b/test/registered/debug_utils/test_request_logger.py index 5b5de52c9..c893a605c 100644 --- a/test/registered/debug_utils/test_request_logger.py +++ b/test/registered/debug_utils/test_request_logger.py @@ -1,4 +1,5 @@ import io +import json import unittest import requests @@ -12,15 +13,16 @@ from sglang.test.test_utils import ( popen_launch_server, ) -register_cuda_ci(est_time=60, suite="nightly-1-gpu", nightly=True) +register_cuda_ci(est_time=120, suite="nightly-1-gpu", nightly=True) -class TestRequestLogger(CustomTestCase): +class BaseTestRequestLogger: + log_requests_format = None + @classmethod def setUpClass(cls): cls.stdout = io.StringIO() cls.stderr = io.StringIO() - cls.process = popen_launch_server( "Qwen/Qwen3-0.6B", DEFAULT_URL_FOR_TEST, @@ -29,6 +31,8 @@ class TestRequestLogger(CustomTestCase): "--log-requests", "--log-requests-level", "2", + "--log-requests-format", + cls.log_requests_format, "--skip-server-warmup", ], return_stdout_stderr=(cls.stdout, cls.stderr), @@ -40,7 +44,7 @@ class TestRequestLogger(CustomTestCase): cls.stdout.close() cls.stderr.close() - def test_request_logging(self): + def _send_request(self): response = requests.post( DEFAULT_URL_FOR_TEST + "/generate", json={ @@ -50,11 +54,43 @@ class TestRequestLogger(CustomTestCase): timeout=30, ) self.assertEqual(response.status_code, 200) + return self.stdout.getvalue() + self.stderr.getvalue() - combined_output = self.stdout.getvalue() + self.stderr.getvalue() + +class TestRequestLoggerText(BaseTestRequestLogger, CustomTestCase): + log_requests_format = "text" + + def test_text_format_logging(self): + combined_output = self._send_request() self.assertIn("Receive:", combined_output) self.assertIn("Finish:", combined_output) +class TestRequestLoggerJson(BaseTestRequestLogger, CustomTestCase): + log_requests_format = "json" + + def test_json_format_logging(self): + combined_output = self._send_request() + + received_found = False + finished_found = False + for line in combined_output.splitlines(): + if not line.startswith("{"): + continue + data = json.loads(line) + if data.get("event") == "request.received": + self.assertIn("rid", data) + self.assertIn("obj", data) + received_found = True + elif data.get("event") == "request.finished": + self.assertIn("rid", data) + self.assertIn("obj", data) + self.assertIn("out", data) + finished_found = True + + self.assertTrue(received_found, "request.received event not found in logs") + self.assertTrue(finished_found, "request.finished event not found in logs") + + if __name__ == "__main__": unittest.main()