Tiny add --log-requests-target (#16338)
This commit is contained in:
@@ -370,6 +370,7 @@ class TokenizerManager(TokenizerCommunicatorMixin, TokenizerManagerMultiItemMixi
|
|||||||
log_requests=self.server_args.log_requests,
|
log_requests=self.server_args.log_requests,
|
||||||
log_requests_level=self.server_args.log_requests_level,
|
log_requests_level=self.server_args.log_requests_level,
|
||||||
log_requests_format=self.server_args.log_requests_format,
|
log_requests_format=self.server_args.log_requests_format,
|
||||||
|
log_requests_target=self.server_args.log_requests_target,
|
||||||
)
|
)
|
||||||
|
|
||||||
# Dumping
|
# Dumping
|
||||||
|
|||||||
@@ -339,6 +339,7 @@ class ServerArgs:
|
|||||||
log_requests: bool = False
|
log_requests: bool = False
|
||||||
log_requests_level: int = 2
|
log_requests_level: int = 2
|
||||||
log_requests_format: str = "text"
|
log_requests_format: str = "text"
|
||||||
|
log_requests_target: Optional[List[str]] = None
|
||||||
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
|
||||||
@@ -3013,6 +3014,14 @@ class ServerArgs:
|
|||||||
choices=["text", "json"],
|
choices=["text", "json"],
|
||||||
help="Format for request logging: 'text' (human-readable) or 'json' (structured)",
|
help="Format for request logging: 'text' (human-readable) or 'json' (structured)",
|
||||||
)
|
)
|
||||||
|
parser.add_argument(
|
||||||
|
"--log-requests-target",
|
||||||
|
type=str,
|
||||||
|
nargs="+",
|
||||||
|
default=ServerArgs.log_requests_target,
|
||||||
|
help="Target(s) for request logging: 'stdout' and/or directory path(s) for file output. "
|
||||||
|
"Can specify multiple targets, e.g., '--log-requests-target stdout /my/path'. ",
|
||||||
|
)
|
||||||
parser.add_argument(
|
parser.add_argument(
|
||||||
"--crash-dump-folder",
|
"--crash-dump-folder",
|
||||||
type=str,
|
type=str,
|
||||||
|
|||||||
@@ -16,9 +16,14 @@ from __future__ import annotations
|
|||||||
import dataclasses
|
import dataclasses
|
||||||
import json
|
import json
|
||||||
import logging
|
import logging
|
||||||
|
import os
|
||||||
|
import socket
|
||||||
from datetime import datetime
|
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 logging.handlers import TimedRotatingFileHandler
|
||||||
|
from typing import TYPE_CHECKING, Any, List, Optional, Set, Tuple, Union
|
||||||
|
|
||||||
|
import torch.distributed as dist
|
||||||
|
|
||||||
from sglang.srt.environ import envs
|
from sglang.srt.environ import envs
|
||||||
from sglang.srt.utils.common import get_bool_env_var
|
from sglang.srt.utils.common import get_bool_env_var
|
||||||
@@ -28,12 +33,6 @@ 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__(
|
def __init__(
|
||||||
@@ -41,20 +40,31 @@ class RequestLogger:
|
|||||||
log_requests: bool,
|
log_requests: bool,
|
||||||
log_requests_level: int,
|
log_requests_level: int,
|
||||||
log_requests_format: str,
|
log_requests_format: str,
|
||||||
|
log_requests_target: Optional[List[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.log_requests_format = log_requests_format
|
||||||
|
self.log_requests_target = log_requests_target
|
||||||
|
|
||||||
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()
|
||||||
)
|
)
|
||||||
|
self.targets = self._setup_targets()
|
||||||
|
|
||||||
self.log_exceeded_ms = envs.SGLANG_LOG_REQUEST_EXCEEDED_MS.get()
|
self.log_exceeded_ms = envs.SGLANG_LOG_REQUEST_EXCEEDED_MS.get()
|
||||||
|
|
||||||
|
def _setup_targets(self) -> List[logging.Logger]:
|
||||||
|
if not self.log_requests_target:
|
||||||
|
return [_create_log_target_stdout()]
|
||||||
|
return [_create_log_target(t) for t in self.log_requests_target]
|
||||||
|
|
||||||
def configure(
|
def configure(
|
||||||
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,
|
log_requests_format: Optional[str] = None,
|
||||||
|
log_requests_target: Optional[List[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
|
||||||
@@ -62,7 +72,11 @@ class RequestLogger:
|
|||||||
self.log_requests_level = log_requests_level
|
self.log_requests_level = log_requests_level
|
||||||
if log_requests_format is not None:
|
if log_requests_format is not None:
|
||||||
self.log_requests_format = log_requests_format
|
self.log_requests_format = log_requests_format
|
||||||
|
if log_requests_target is not None:
|
||||||
|
self.log_requests_target = log_requests_target
|
||||||
|
|
||||||
self.metadata = self._compute_metadata()
|
self.metadata = self._compute_metadata()
|
||||||
|
self.targets = self._setup_targets()
|
||||||
|
|
||||||
def log_received_request(
|
def log_received_request(
|
||||||
self, obj: Union["GenerateReqInput", "EmbeddingReqInput"], tokenizer: Any = None
|
self, obj: Union["GenerateReqInput", "EmbeddingReqInput"], tokenizer: Any = None
|
||||||
@@ -76,9 +90,9 @@ class RequestLogger:
|
|||||||
"rid": obj.rid,
|
"rid": obj.rid,
|
||||||
"obj": _transform_data_for_logging(obj, max_length, skip_names),
|
"obj": _transform_data_for_logging(obj, max_length, skip_names),
|
||||||
}
|
}
|
||||||
_log_json("request.received", log_data)
|
self._log_json("request.received", log_data)
|
||||||
else:
|
else:
|
||||||
logger.info(
|
self._log(
|
||||||
f"Receive: obj={_dataclass_to_string_truncated(obj, max_length, skip_names=skip_names)}"
|
f"Receive: obj={_dataclass_to_string_truncated(obj, max_length, skip_names=skip_names)}"
|
||||||
)
|
)
|
||||||
|
|
||||||
@@ -116,13 +130,13 @@ class RequestLogger:
|
|||||||
log_data["out"] = _transform_data_for_logging(
|
log_data["out"] = _transform_data_for_logging(
|
||||||
out, max_length, out_skip_names
|
out, max_length, out_skip_names
|
||||||
)
|
)
|
||||||
_log_json("request.finished", log_data)
|
self._log_json("request.finished", log_data)
|
||||||
else:
|
else:
|
||||||
if is_multimodal_gen:
|
if is_multimodal_gen:
|
||||||
msg = f"Finish: obj={_dataclass_to_string_truncated(obj, max_length, skip_names=skip_names)}"
|
msg = f"Finish: obj={_dataclass_to_string_truncated(obj, max_length, skip_names=skip_names)}"
|
||||||
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)}"
|
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)
|
self._log(msg)
|
||||||
|
|
||||||
def _compute_metadata(
|
def _compute_metadata(
|
||||||
self,
|
self,
|
||||||
@@ -164,6 +178,18 @@ class RequestLogger:
|
|||||||
)
|
)
|
||||||
return max_length, skip_names, out_skip_names
|
return max_length, skip_names, out_skip_names
|
||||||
|
|
||||||
|
def _log_json(self, event: str, data: dict) -> None:
|
||||||
|
log_data = {
|
||||||
|
"timestamp": datetime.now().isoformat(),
|
||||||
|
"event": event,
|
||||||
|
**data,
|
||||||
|
}
|
||||||
|
self._log(json.dumps(log_data, ensure_ascii=False))
|
||||||
|
|
||||||
|
def _log(self, msg: str) -> None:
|
||||||
|
for target in self.targets:
|
||||||
|
target.info(msg)
|
||||||
|
|
||||||
|
|
||||||
# TODO remove this?
|
# TODO remove this?
|
||||||
@lru_cache(maxsize=2)
|
@lru_cache(maxsize=2)
|
||||||
@@ -171,14 +197,37 @@ 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 _create_log_target(target: str) -> logging.Logger:
|
||||||
def _log_json(event: str, data: dict) -> None:
|
if target.lower() == "stdout":
|
||||||
log_data = {
|
return _create_log_target_stdout()
|
||||||
"timestamp": datetime.now().isoformat(),
|
return _create_log_target_file(target)
|
||||||
"event": event,
|
|
||||||
**data,
|
|
||||||
}
|
def _create_log_target_stdout() -> logging.Logger:
|
||||||
_json_logger.info(json.dumps(log_data, ensure_ascii=False))
|
return _create_logger_with_handler(f"{__name__}.stdout", logging.StreamHandler())
|
||||||
|
|
||||||
|
|
||||||
|
def _create_log_target_file(directory: str) -> logging.Logger:
|
||||||
|
os.makedirs(directory, exist_ok=True)
|
||||||
|
hostname = socket.gethostname()
|
||||||
|
rank = dist.get_rank() if dist.is_initialized() else 0
|
||||||
|
filename = os.path.join(directory, f"{hostname}_{rank}.log")
|
||||||
|
handler = TimedRotatingFileHandler(
|
||||||
|
filename, when="H", backupCount=0, encoding="utf-8"
|
||||||
|
)
|
||||||
|
return _create_logger_with_handler(
|
||||||
|
f"{__name__}.file.{directory}.{hostname}_{rank}", handler
|
||||||
|
)
|
||||||
|
|
||||||
|
|
||||||
|
def _create_logger_with_handler(name: str, handler: logging.Handler) -> logging.Logger:
|
||||||
|
logger = logging.getLogger(name)
|
||||||
|
logger.setLevel(logging.INFO)
|
||||||
|
logger.propagate = False
|
||||||
|
if not logger.handlers:
|
||||||
|
handler.setFormatter(logging.Formatter("%(message)s"))
|
||||||
|
logger.addHandler(handler)
|
||||||
|
return logger
|
||||||
|
|
||||||
|
|
||||||
# TODO unify this w/ `_transform_data_for_logging` if we find performance enough
|
# TODO unify this w/ `_transform_data_for_logging` if we find performance enough
|
||||||
|
|||||||
@@ -1,6 +1,9 @@
|
|||||||
import io
|
import io
|
||||||
import json
|
import json
|
||||||
|
import tempfile
|
||||||
|
import time
|
||||||
import unittest
|
import unittest
|
||||||
|
from pathlib import Path
|
||||||
|
|
||||||
import requests
|
import requests
|
||||||
|
|
||||||
@@ -21,20 +24,26 @@ class BaseTestRequestLogger:
|
|||||||
|
|
||||||
@classmethod
|
@classmethod
|
||||||
def setUpClass(cls):
|
def setUpClass(cls):
|
||||||
|
cls._temp_dir_obj = tempfile.TemporaryDirectory()
|
||||||
|
cls.temp_dir = cls._temp_dir_obj.name
|
||||||
cls.stdout = io.StringIO()
|
cls.stdout = io.StringIO()
|
||||||
cls.stderr = io.StringIO()
|
cls.stderr = io.StringIO()
|
||||||
|
other_args = [
|
||||||
|
"--log-requests",
|
||||||
|
"--log-requests-level",
|
||||||
|
"2",
|
||||||
|
"--log-requests-format",
|
||||||
|
cls.log_requests_format,
|
||||||
|
"--skip-server-warmup",
|
||||||
|
"--log-requests-target",
|
||||||
|
"stdout",
|
||||||
|
cls.temp_dir,
|
||||||
|
]
|
||||||
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,
|
||||||
timeout=DEFAULT_TIMEOUT_FOR_SERVER_LAUNCH,
|
timeout=DEFAULT_TIMEOUT_FOR_SERVER_LAUNCH,
|
||||||
other_args=[
|
other_args=other_args,
|
||||||
"--log-requests",
|
|
||||||
"--log-requests-level",
|
|
||||||
"2",
|
|
||||||
"--log-requests-format",
|
|
||||||
cls.log_requests_format,
|
|
||||||
"--skip-server-warmup",
|
|
||||||
],
|
|
||||||
return_stdout_stderr=(cls.stdout, cls.stderr),
|
return_stdout_stderr=(cls.stdout, cls.stderr),
|
||||||
)
|
)
|
||||||
|
|
||||||
@@ -43,8 +52,12 @@ class BaseTestRequestLogger:
|
|||||||
kill_process_tree(cls.process.pid)
|
kill_process_tree(cls.process.pid)
|
||||||
cls.stdout.close()
|
cls.stdout.close()
|
||||||
cls.stderr.close()
|
cls.stderr.close()
|
||||||
|
cls._temp_dir_obj.cleanup()
|
||||||
|
|
||||||
def _send_request(self):
|
def _verify_logs(self, content: str, source_name: str):
|
||||||
|
raise NotImplementedError
|
||||||
|
|
||||||
|
def test_logging(self):
|
||||||
response = requests.post(
|
response = requests.post(
|
||||||
DEFAULT_URL_FOR_TEST + "/generate",
|
DEFAULT_URL_FOR_TEST + "/generate",
|
||||||
json={
|
json={
|
||||||
@@ -54,28 +67,34 @@ class BaseTestRequestLogger:
|
|||||||
timeout=30,
|
timeout=30,
|
||||||
)
|
)
|
||||||
self.assertEqual(response.status_code, 200)
|
self.assertEqual(response.status_code, 200)
|
||||||
return self.stdout.getvalue() + self.stderr.getvalue()
|
time.sleep(1)
|
||||||
|
|
||||||
|
stdout_content = self.stdout.getvalue() + self.stderr.getvalue()
|
||||||
|
self._verify_logs(stdout_content, "stdout")
|
||||||
|
|
||||||
|
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")
|
||||||
|
|
||||||
|
|
||||||
class TestRequestLoggerText(BaseTestRequestLogger, CustomTestCase):
|
class TestRequestLoggerText(BaseTestRequestLogger, CustomTestCase):
|
||||||
log_requests_format = "text"
|
log_requests_format = "text"
|
||||||
|
|
||||||
def test_text_format_logging(self):
|
def _verify_logs(self, content: str, source_name: str):
|
||||||
combined_output = self._send_request()
|
self.assertIn("Receive:", content, f"'Receive:' not found in {source_name}")
|
||||||
self.assertIn("Receive:", combined_output)
|
self.assertIn("Finish:", content, f"'Finish:' not found in {source_name}")
|
||||||
self.assertIn("Finish:", combined_output)
|
|
||||||
|
|
||||||
|
|
||||||
class TestRequestLoggerJson(BaseTestRequestLogger, CustomTestCase):
|
class TestRequestLoggerJson(BaseTestRequestLogger, CustomTestCase):
|
||||||
log_requests_format = "json"
|
log_requests_format = "json"
|
||||||
|
|
||||||
def test_json_format_logging(self):
|
def _verify_logs(self, content: str, source_name: str):
|
||||||
combined_output = self._send_request()
|
|
||||||
|
|
||||||
received_found = False
|
received_found = False
|
||||||
finished_found = False
|
finished_found = False
|
||||||
for line in combined_output.splitlines():
|
for line in content.splitlines():
|
||||||
if not line.startswith("{"):
|
if not line.strip() or not line.startswith("{"):
|
||||||
continue
|
continue
|
||||||
data = json.loads(line)
|
data = json.loads(line)
|
||||||
if data.get("event") == "request.received":
|
if data.get("event") == "request.received":
|
||||||
@@ -88,8 +107,12 @@ class TestRequestLoggerJson(BaseTestRequestLogger, CustomTestCase):
|
|||||||
self.assertIn("out", data)
|
self.assertIn("out", data)
|
||||||
finished_found = True
|
finished_found = True
|
||||||
|
|
||||||
self.assertTrue(received_found, "request.received event not found in logs")
|
self.assertTrue(
|
||||||
self.assertTrue(finished_found, "request.finished event not found in logs")
|
received_found, f"request.received event not found in {source_name}"
|
||||||
|
)
|
||||||
|
self.assertTrue(
|
||||||
|
finished_found, f"request.finished event not found in {source_name}"
|
||||||
|
)
|
||||||
|
|
||||||
|
|
||||||
if __name__ == "__main__":
|
if __name__ == "__main__":
|
||||||
|
|||||||
Reference in New Issue
Block a user