Support JSON format request logging for easier parsing (#15743)
This commit is contained in:
@@ -1485,6 +1485,7 @@ class FreezeGCReq(BaseReq):
|
|||||||
class ConfigureLoggingReq(BaseReq):
|
class ConfigureLoggingReq(BaseReq):
|
||||||
log_requests: Optional[bool] = None
|
log_requests: Optional[bool] = None
|
||||||
log_requests_level: Optional[int] = None
|
log_requests_level: Optional[int] = None
|
||||||
|
log_requests_format: Optional[str] = None
|
||||||
dump_requests_folder: Optional[str] = None
|
dump_requests_folder: Optional[str] = None
|
||||||
dump_requests_threshold: Optional[int] = None
|
dump_requests_threshold: Optional[int] = None
|
||||||
crash_dump_folder: Optional[str] = None
|
crash_dump_folder: Optional[str] = None
|
||||||
|
|||||||
@@ -185,6 +185,7 @@ class TokenizerManager(TokenizerCommunicatorMixin, TokenizerManagerMultiItemMixi
|
|||||||
self.request_logger = RequestLogger(
|
self.request_logger = RequestLogger(
|
||||||
log_requests=server_args.log_requests,
|
log_requests=server_args.log_requests,
|
||||||
log_requests_level=server_args.log_requests_level,
|
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.preferred_sampling_params = server_args.preferred_sampling_params
|
||||||
self.crash_dump_folder = server_args.crash_dump_folder
|
self.crash_dump_folder = server_args.crash_dump_folder
|
||||||
@@ -1314,6 +1315,7 @@ class TokenizerManager(TokenizerCommunicatorMixin, TokenizerManagerMultiItemMixi
|
|||||||
self.request_logger.configure(
|
self.request_logger.configure(
|
||||||
log_requests=obj.log_requests,
|
log_requests=obj.log_requests,
|
||||||
log_requests_level=obj.log_requests_level,
|
log_requests_level=obj.log_requests_level,
|
||||||
|
log_requests_format=obj.log_requests_format,
|
||||||
)
|
)
|
||||||
if obj.dump_requests_folder is not None:
|
if obj.dump_requests_folder is not None:
|
||||||
self.dump_requests_folder = obj.dump_requests_folder
|
self.dump_requests_folder = obj.dump_requests_folder
|
||||||
|
|||||||
@@ -338,6 +338,7 @@ class ServerArgs:
|
|||||||
log_level_http: Optional[str] = None
|
log_level_http: Optional[str] = None
|
||||||
log_requests: bool = False
|
log_requests: bool = False
|
||||||
log_requests_level: int = 2
|
log_requests_level: int = 2
|
||||||
|
log_requests_format: str = "text"
|
||||||
crash_dump_folder: Optional[str] = None
|
crash_dump_folder: Optional[str] = None
|
||||||
show_time_cost: bool = False
|
show_time_cost: bool = False
|
||||||
enable_metrics: 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.",
|
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],
|
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(
|
parser.add_argument(
|
||||||
"--crash-dump-folder",
|
"--crash-dump-folder",
|
||||||
type=str,
|
type=str,
|
||||||
|
|||||||
@@ -14,7 +14,9 @@
|
|||||||
from __future__ import annotations
|
from __future__ import annotations
|
||||||
|
|
||||||
import dataclasses
|
import dataclasses
|
||||||
|
import json
|
||||||
import logging
|
import logging
|
||||||
|
from datetime import datetime
|
||||||
from functools import lru_cache
|
from functools import lru_cache
|
||||||
from typing import TYPE_CHECKING, Any, Optional, Set, Tuple, Union
|
from typing import TYPE_CHECKING, Any, Optional, Set, Tuple, Union
|
||||||
|
|
||||||
@@ -25,11 +27,23 @@ if TYPE_CHECKING:
|
|||||||
|
|
||||||
logger = logging.getLogger(__name__)
|
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:
|
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 = log_requests
|
||||||
self.log_requests_level = log_requests_level
|
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.metadata: Tuple[Optional[int], Optional[Set[str]], Optional[Set[str]]] = (
|
||||||
self._compute_metadata()
|
self._compute_metadata()
|
||||||
)
|
)
|
||||||
@@ -38,11 +52,14 @@ class RequestLogger:
|
|||||||
self,
|
self,
|
||||||
log_requests: Optional[bool] = None,
|
log_requests: Optional[bool] = None,
|
||||||
log_requests_level: Optional[int] = None,
|
log_requests_level: Optional[int] = None,
|
||||||
|
log_requests_format: Optional[str] = None,
|
||||||
) -> None:
|
) -> None:
|
||||||
if log_requests is not None:
|
if log_requests is not None:
|
||||||
self.log_requests = log_requests
|
self.log_requests = log_requests
|
||||||
if log_requests_level is not None:
|
if log_requests_level is not None:
|
||||||
self.log_requests_level = log_requests_level
|
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()
|
self.metadata = self._compute_metadata()
|
||||||
|
|
||||||
def log_received_request(
|
def log_received_request(
|
||||||
@@ -52,9 +69,16 @@ class RequestLogger:
|
|||||||
return
|
return
|
||||||
|
|
||||||
max_length, skip_names, _ = self.metadata
|
max_length, skip_names, _ = self.metadata
|
||||||
logger.info(
|
if self.log_requests_format == "json":
|
||||||
f"Receive: obj={_dataclass_to_string_truncated(obj, max_length, skip_names=skip_names)}"
|
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.
|
# FIXME: This is a temporary fix to get the text from the input ids.
|
||||||
# We should remove this once we have a proper way.
|
# We should remove this once we have a proper way.
|
||||||
@@ -77,11 +101,22 @@ class RequestLogger:
|
|||||||
return
|
return
|
||||||
|
|
||||||
max_length, skip_names, out_skip_names = self.metadata
|
max_length, skip_names, out_skip_names = self.metadata
|
||||||
if is_multimodal_gen:
|
if self.log_requests_format == "json":
|
||||||
msg = f"Finish: obj={_dataclass_to_string_truncated(obj, max_length, skip_names=skip_names)}"
|
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:
|
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)}"
|
if is_multimodal_gen:
|
||||||
logger.info(msg)
|
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(
|
def _compute_metadata(
|
||||||
self,
|
self,
|
||||||
@@ -130,6 +165,17 @@ def disable_request_logging() -> bool:
|
|||||||
return get_bool_env_var("SGLANG_DISABLE_REQUEST_LOGGING")
|
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(
|
def _dataclass_to_string_truncated(
|
||||||
data: Any, max_length: int = 2048, skip_names: Optional[Set[str]] = None
|
data: Any, max_length: int = 2048, skip_names: Optional[Set[str]] = None
|
||||||
) -> str:
|
) -> str:
|
||||||
@@ -170,3 +216,37 @@ def _dataclass_to_string_truncated(
|
|||||||
)
|
)
|
||||||
else:
|
else:
|
||||||
return str(data)
|
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)
|
||||||
|
|||||||
@@ -1,4 +1,5 @@
|
|||||||
import io
|
import io
|
||||||
|
import json
|
||||||
import unittest
|
import unittest
|
||||||
|
|
||||||
import requests
|
import requests
|
||||||
@@ -12,15 +13,16 @@ from sglang.test.test_utils import (
|
|||||||
popen_launch_server,
|
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
|
@classmethod
|
||||||
def setUpClass(cls):
|
def setUpClass(cls):
|
||||||
cls.stdout = io.StringIO()
|
cls.stdout = io.StringIO()
|
||||||
cls.stderr = io.StringIO()
|
cls.stderr = io.StringIO()
|
||||||
|
|
||||||
cls.process = popen_launch_server(
|
cls.process = popen_launch_server(
|
||||||
"Qwen/Qwen3-0.6B",
|
"Qwen/Qwen3-0.6B",
|
||||||
DEFAULT_URL_FOR_TEST,
|
DEFAULT_URL_FOR_TEST,
|
||||||
@@ -29,6 +31,8 @@ class TestRequestLogger(CustomTestCase):
|
|||||||
"--log-requests",
|
"--log-requests",
|
||||||
"--log-requests-level",
|
"--log-requests-level",
|
||||||
"2",
|
"2",
|
||||||
|
"--log-requests-format",
|
||||||
|
cls.log_requests_format,
|
||||||
"--skip-server-warmup",
|
"--skip-server-warmup",
|
||||||
],
|
],
|
||||||
return_stdout_stderr=(cls.stdout, cls.stderr),
|
return_stdout_stderr=(cls.stdout, cls.stderr),
|
||||||
@@ -40,7 +44,7 @@ class TestRequestLogger(CustomTestCase):
|
|||||||
cls.stdout.close()
|
cls.stdout.close()
|
||||||
cls.stderr.close()
|
cls.stderr.close()
|
||||||
|
|
||||||
def test_request_logging(self):
|
def _send_request(self):
|
||||||
response = requests.post(
|
response = requests.post(
|
||||||
DEFAULT_URL_FOR_TEST + "/generate",
|
DEFAULT_URL_FOR_TEST + "/generate",
|
||||||
json={
|
json={
|
||||||
@@ -50,11 +54,43 @@ class TestRequestLogger(CustomTestCase):
|
|||||||
timeout=30,
|
timeout=30,
|
||||||
)
|
)
|
||||||
self.assertEqual(response.status_code, 200)
|
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("Receive:", combined_output)
|
||||||
self.assertIn("Finish:", 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__":
|
if __name__ == "__main__":
|
||||||
unittest.main()
|
unittest.main()
|
||||||
|
|||||||
Reference in New Issue
Block a user