Studio: trim serving-log noise and surface llama-server engine stats (#6377)
* Studio: trim serving-log noise and surface llama-server engine stats Studio prints one structured line per HTTP request, so the SPA's polling and per-invalidation fan-out bury the lines that matter. - Dedup identical successful GETs within a short window (default 300ms, UNSLOTH_STUDIO_ACCESS_LOG_DEDUP_MS) so a burst logs once. The dedup key includes the query string, so distinct query-driven GETs are not collapsed. Runs after the response is sent, so it adds no request latency; mutations, non-2xx, and loading polls are untouched. - Collapse pure-liveness polls (/api/health, /api/auth/status, /api/inference/status, /api/inference/monitor) to a longer heartbeat (default 10s, UNSLOTH_STUDIO_ACCESS_LOG_POLL_DEDUP_MS). The API monitor console polls /monitor every 1.5s while open. - Translate llama-server's Prometheus /metrics into a periodic vLLM-style engine_stats line (generation/prompt throughput and requests in flight) from a daemon poller, gated on UNSLOTH_STUDIO_ENGINE_STATS. Throughput uses llama-server's predicted_tokens_seconds / prompt_tokens_seconds gauges, with a tokens_predicted_total / prompt_tokens_total counter-delta fallback; it does not use n_decode_total (which counts llama_decode() calls, not tokens). No KV field is emitted, since llama.cpp does not expose kv_cache_usage_ratio. --metrics is added only when probe_server_capabilities reports the binary supports it, so older/custom binaries still load. The poller keeps retrying through transient scrape failures (stop() drives shutdown) and a malformed sample cannot crash its thread. - api_monitor.append_reply: once the preview cap is reached, skip the per-chunk re-concat (avoids O(n^2) on long generations) while still recording the "..." truncation marker for a reply that lands exactly on the cap. - unsloth studio --verbose and unsloth studio run --verbose both restore every per-request log; --verbose before a subcommand is rejected with guidance (matching --secure / --parallel). run --verbose still forwards --log-verbose to llama-server, preserving the pre-existing pass-through verbosity. * [pre-commit.ci] auto fixes from pre-commit.com hooks for more information, see https://pre-commit.ci --------- Co-authored-by: pre-commit-ci[bot] <66853113+pre-commit-ci[bot]@users.noreply.github.com>
This commit is contained in:
Daniel Han
GitHub
parent
435cdbc372
commit
9a966adf51
9 changed files with 666 additions and 2 deletions
|
|
@ -134,6 +134,15 @@ class ApiMonitor:
|
|||
entry = self._find_locked(entry_id)
|
||||
if entry is None:
|
||||
return
|
||||
# Preview is capped: once the "..." marker is present the head is
|
||||
# frozen, so skip the per-chunk re-concat (avoids O(n^2) on long
|
||||
# generations). A reply that landed exactly on the cap has no marker
|
||||
# yet, so let one more append record the truncation before freezing.
|
||||
if len(entry.reply) >= _MAX_REPLY_CHARS:
|
||||
if not entry.reply.endswith("..."):
|
||||
entry.reply = _trim(entry.reply + text, _MAX_REPLY_CHARS)
|
||||
entry.updated_at = time.time()
|
||||
return
|
||||
entry.reply = _trim(entry.reply + text, _MAX_REPLY_CHARS)
|
||||
entry.updated_at = time.time()
|
||||
|
||||
|
|
|
|||
|
|
@ -1160,6 +1160,7 @@ class LlamaCppBackend:
|
|||
self._is_diffusion: bool = False
|
||||
self._diffusion_visual_bin: Optional[str] = None
|
||||
self._healthy = False
|
||||
self._stats_logger = None # vLLM-style engine-stats poller, set on load
|
||||
# Set by _classify_gpu_offload after _wait_for_health.
|
||||
self._gpu_offload_active: Optional[bool] = None
|
||||
self._context_length: Optional[int] = None
|
||||
|
|
@ -1689,6 +1690,7 @@ class LlamaCppBackend:
|
|||
"supports_cache_ram": False,
|
||||
"supports_ctx_checkpoints": False,
|
||||
"supports_no_cache_prompt": False,
|
||||
"supports_metrics": False,
|
||||
}
|
||||
try:
|
||||
mtime = int(Path(bin_path).stat().st_mtime)
|
||||
|
|
@ -1707,6 +1709,7 @@ class LlamaCppBackend:
|
|||
supports_cache_ram = False
|
||||
supports_ctx_checkpoints = False
|
||||
supports_no_cache_prompt = False
|
||||
supports_metrics = False
|
||||
try:
|
||||
probe_env = cls._llama_server_env_for_binary(bin_path)
|
||||
result = subprocess.run(
|
||||
|
|
@ -1802,6 +1805,7 @@ class LlamaCppBackend:
|
|||
supports_cache_ram = _is_real("--cache-ram")
|
||||
supports_ctx_checkpoints = _is_real("--ctx-checkpoints")
|
||||
supports_no_cache_prompt = _is_real("--no-cache-prompt")
|
||||
supports_metrics = _is_real("--metrics")
|
||||
except (OSError, subprocess.SubprocessError) as exc:
|
||||
logger.debug(f"llama-server --help probe failed: {exc}")
|
||||
|
||||
|
|
@ -1817,6 +1821,7 @@ class LlamaCppBackend:
|
|||
"supports_cache_ram": supports_cache_ram,
|
||||
"supports_ctx_checkpoints": supports_ctx_checkpoints,
|
||||
"supports_no_cache_prompt": supports_no_cache_prompt,
|
||||
"supports_metrics": supports_metrics,
|
||||
}
|
||||
cls._capability_cache[cache_key] = info
|
||||
return info
|
||||
|
|
@ -5059,6 +5064,10 @@ class LlamaCppBackend:
|
|||
fully_gpu_offloaded = True
|
||||
|
||||
server_caps = self.probe_server_capabilities(binary)
|
||||
# Expose Prometheus /metrics for the engine-stats logger, only
|
||||
# when the binary advertises it (older/custom binaries may not).
|
||||
if server_caps.get("supports_metrics"):
|
||||
cmd.append("--metrics")
|
||||
cmd.extend(
|
||||
self._ctx_integrity_flags(
|
||||
n_parallel,
|
||||
|
|
@ -5597,6 +5606,18 @@ class LlamaCppBackend:
|
|||
logger.info(
|
||||
f"llama-server ready on port {self._port} for model '{model_identifier}'"
|
||||
)
|
||||
# Poll llama-server /metrics -> vLLM-style engine_stats logs
|
||||
# (only when the binary exposes /metrics).
|
||||
if server_caps.get("supports_metrics"):
|
||||
try:
|
||||
from core.inference.llama_stats import maybe_start_stats_logger
|
||||
if self._stats_logger is not None:
|
||||
self._stats_logger.stop()
|
||||
self._stats_logger = maybe_start_stats_logger(self.base_url, logger)
|
||||
except Exception as e:
|
||||
logger.debug(f"engine-stats logger not started: {e}")
|
||||
else:
|
||||
self._stats_logger = None
|
||||
|
||||
# Probe outside _lock (interruptible by /unload); init inside.
|
||||
self._is_audio = False
|
||||
|
|
@ -6104,6 +6125,9 @@ class LlamaCppBackend:
|
|||
except Exception as e:
|
||||
logger.warning(f"Error killing llama-server process: {e}")
|
||||
finally:
|
||||
if self._stats_logger is not None:
|
||||
self._stats_logger.stop()
|
||||
self._stats_logger = None
|
||||
self._process = None
|
||||
# Clear healthy so a /load during the replacement's warm-up can't
|
||||
# short-circuit against the previous server's health (#5401).
|
||||
|
|
|
|||
118
studio/backend/core/inference/llama_stats.py
Normal file
118
studio/backend/core/inference/llama_stats.py
Normal file
|
|
@ -0,0 +1,118 @@
|
|||
# SPDX-License-Identifier: AGPL-3.0-only
|
||||
# Copyright 2026-present the Unsloth AI Inc. team. All rights reserved. See /studio/LICENSE.AGPL-3.0
|
||||
|
||||
"""Translate llama-server's Prometheus /metrics into a periodic, vLLM-style
|
||||
engine-stats log line (generation/prompt throughput, requests in flight).
|
||||
|
||||
llama-server already computes these (it needs `--metrics`); this lifts them
|
||||
into Studio's structured log so the terminal shows serving health, not just
|
||||
per-request access lines. Emitted only while there is activity.
|
||||
"""
|
||||
|
||||
import os
|
||||
import re
|
||||
import threading
|
||||
import time
|
||||
import urllib.request
|
||||
|
||||
# Prometheus body lines: "llamacpp:<name>[{labels}] <value>" (skip "#" HELP/TYPE).
|
||||
_METRIC_RE = re.compile(r"^llamacpp:(\w+)(?:\{[^}]*\})?\s+([0-9.eE+-]+)", re.MULTILINE)
|
||||
_OFF = {"0", "false", "no", "off"}
|
||||
|
||||
|
||||
class LlamaServerStatsLogger:
|
||||
"""Daemon poller that logs vLLM-style engine stats from llama-server.
|
||||
|
||||
Keeps retrying through transient scrape failures; the backend stops it via
|
||||
stop() on unload/reload, so a brief /metrics stall does not silence stats.
|
||||
"""
|
||||
|
||||
def __init__(
|
||||
self,
|
||||
base_url,
|
||||
logger,
|
||||
interval_s = 10.0,
|
||||
):
|
||||
self._url = f"{base_url.rstrip('/')}/metrics"
|
||||
self._log = logger
|
||||
self._interval = max(1.0, float(interval_s))
|
||||
self._stop = threading.Event()
|
||||
self._thread = None
|
||||
|
||||
def start(self):
|
||||
if self._thread is None:
|
||||
self._thread = threading.Thread(target = self._run, name = "llama-stats", daemon = True)
|
||||
self._thread.start()
|
||||
|
||||
def stop(self):
|
||||
self._stop.set()
|
||||
|
||||
def _scrape(self):
|
||||
try:
|
||||
with urllib.request.urlopen(self._url, timeout = 3) as r:
|
||||
if r.status != 200:
|
||||
return None
|
||||
body = r.read().decode("utf-8", "replace")
|
||||
except Exception:
|
||||
return None
|
||||
out = {}
|
||||
for k, v in _METRIC_RE.findall(body):
|
||||
try: # a malformed value must not kill the daemon thread
|
||||
out[k] = float(v)
|
||||
except ValueError:
|
||||
continue
|
||||
return out
|
||||
|
||||
def _run(self):
|
||||
misses = 0
|
||||
prev = None # (monotonic_t, tokens_predicted_total, prompt_tokens_total)
|
||||
while not self._stop.wait(self._interval):
|
||||
m = self._scrape()
|
||||
if not m:
|
||||
misses += 1
|
||||
if misses == 3: # transient stall (load/GC); keep polling.
|
||||
self._log.debug("engine_stats: /metrics scrape failing, still retrying")
|
||||
continue # real shutdown is driven by stop() from _kill_process
|
||||
misses = 0
|
||||
# Generation tokens come from tokens_predicted_total (counter) and
|
||||
# predicted_tokens_seconds (gauge); n_decode_total counts
|
||||
# llama_decode() calls, not tokens, so it must not feed tok/s.
|
||||
now = time.monotonic()
|
||||
predicted = m.get("tokens_predicted_total", 0.0)
|
||||
prompt = m.get("prompt_tokens_total", 0.0)
|
||||
gen_delta = prompt_delta = 0.0
|
||||
if prev is not None and now > prev[0]:
|
||||
dt = now - prev[0]
|
||||
gen_delta = max(0.0, (predicted - prev[1]) / dt)
|
||||
prompt_delta = max(0.0, (prompt - prev[2]) / dt)
|
||||
prev = (now, predicted, prompt)
|
||||
# Prefer llama.cpp's own throughput gauges; fall back to the counter
|
||||
# delta for binaries that expose only the counters.
|
||||
gen_tps = m.get("predicted_tokens_seconds") or gen_delta
|
||||
prompt_tps = m.get("prompt_tokens_seconds") or prompt_delta
|
||||
running, waiting = (
|
||||
int(m.get("requests_processing", 0)),
|
||||
int(m.get("requests_deferred", 0)),
|
||||
)
|
||||
# Gate on real activity this tick so a stale gauge never logs at idle.
|
||||
if running or waiting or gen_delta or prompt_delta:
|
||||
self._log.info(
|
||||
"engine_stats",
|
||||
gen_tok_s = round(float(gen_tps), 1),
|
||||
prompt_tok_s = round(float(prompt_tps), 1),
|
||||
running = running,
|
||||
waiting = waiting,
|
||||
)
|
||||
|
||||
|
||||
def maybe_start_stats_logger(base_url, logger):
|
||||
"""Start a stats logger unless UNSLOTH_STUDIO_ENGINE_STATS disables it."""
|
||||
if (os.environ.get("UNSLOTH_STUDIO_ENGINE_STATS", "1") or "").strip().lower() in _OFF:
|
||||
return None
|
||||
try:
|
||||
interval = float(os.environ.get("UNSLOTH_STUDIO_ENGINE_STATS_INTERVAL_S", "10"))
|
||||
except ValueError:
|
||||
interval = 10.0
|
||||
sl = LlamaServerStatsLogger(base_url, logger, interval)
|
||||
sl.start()
|
||||
return sl
|
||||
|
|
@ -8,6 +8,7 @@ filter_sensitive_data (structlog processor for sanitization), and
|
|||
get_logger (factory for structured loggers).
|
||||
"""
|
||||
|
||||
import os
|
||||
import re
|
||||
import time
|
||||
|
||||
|
|
@ -17,6 +18,31 @@ from starlette.types import ASGIApp, Message, Receive, Scope, Send
|
|||
from utils.native_path_leases import redact_native_paths
|
||||
|
||||
logger = structlog.get_logger(__name__)
|
||||
|
||||
|
||||
def _env_int(name: str, default: int) -> int:
|
||||
try:
|
||||
raw = (os.environ.get(name) or "").strip()
|
||||
return int(raw) if raw else default
|
||||
except ValueError:
|
||||
return default
|
||||
|
||||
|
||||
# Drop duplicate successful-GET access logs repeated within the window: the SPA
|
||||
# fans one cache invalidation into many identical list fetches; only the first
|
||||
# informs. Loading polls, mutations, and errors are unaffected. 0 = log all.
|
||||
_ACCESS_LOG_DEDUP_MS = _env_int("UNSLOTH_STUDIO_ACCESS_LOG_DEDUP_MS", 300)
|
||||
# Pure-liveness/UI polls whose access line carries no signal beyond "client still
|
||||
# polling" (state changes are logged by their own modules). Collapsed to a longer
|
||||
# heartbeat instead of one line per poll; first hit and any error still log. 0 = off.
|
||||
_QUIET_POLL_DEDUP_MS = _env_int("UNSLOTH_STUDIO_ACCESS_LOG_POLL_DEDUP_MS", 10000)
|
||||
_QUIET_POLL_PATHS = {
|
||||
"/api/health",
|
||||
"/api/auth/status",
|
||||
"/api/inference/status",
|
||||
"/api/inference/monitor",
|
||||
}
|
||||
_DEDUP_MAP_MAX = 4096
|
||||
_NATIVE_PATH_LEASE_RE = re.compile(
|
||||
r"(?i)(\b(?:native_path_lease|nativePathLease)[\"']?\s*[:=]\s*[\"']?)[A-Za-z0-9_-]+\.[A-Za-z0-9_-]+"
|
||||
)
|
||||
|
|
@ -43,6 +69,30 @@ class LoggingMiddleware:
|
|||
|
||||
def __init__(self, app: ASGIApp) -> None:
|
||||
self.app = app
|
||||
# (method, path, query, status_code) -> monotonic ts of the last EMITTED log.
|
||||
self._last_log: dict[tuple[str, str, bytes, int], float] = {}
|
||||
|
||||
def _is_redundant_repeat(
|
||||
self, method: str, path: str, query: bytes, status_code: int, now: float
|
||||
) -> bool:
|
||||
"""True if an identical GET/2xx log fired < window ago. The query string
|
||||
is part of the identity, so distinct query-driven GETs are not collapsed.
|
||||
Mutations and non-2xx are never deduped. Quiet-poll paths use a longer
|
||||
heartbeat window. Stamps only on emit, so steady polls still log."""
|
||||
if method != "GET" or not (200 <= status_code < 300):
|
||||
return False
|
||||
window_ms = _QUIET_POLL_DEDUP_MS if path in _QUIET_POLL_PATHS else _ACCESS_LOG_DEDUP_MS
|
||||
if window_ms <= 0:
|
||||
return False
|
||||
key = (method, path, query, status_code)
|
||||
last = self._last_log.get(key)
|
||||
if last is not None and (now - last) * 1000.0 < window_ms:
|
||||
return True
|
||||
self._last_log[key] = now
|
||||
if len(self._last_log) > _DEDUP_MAP_MAX:
|
||||
cutoff = now - (max(_ACCESS_LOG_DEDUP_MS, _QUIET_POLL_DEDUP_MS) / 1000.0)
|
||||
self._last_log = {k: v for k, v in self._last_log.items() if v >= cutoff}
|
||||
return False
|
||||
|
||||
async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None:
|
||||
if scope["type"] != "http":
|
||||
|
|
@ -78,13 +128,16 @@ class LoggingMiddleware:
|
|||
)
|
||||
raise
|
||||
else:
|
||||
if not excluded:
|
||||
end_time = time.perf_counter()
|
||||
if not excluded and not self._is_redundant_repeat(
|
||||
scope["method"], path, scope.get("query_string", b""), status_code, end_time
|
||||
):
|
||||
logger.info(
|
||||
"request_completed",
|
||||
method = scope["method"],
|
||||
path = path,
|
||||
status_code = status_code,
|
||||
process_time_ms = round((time.perf_counter() - start_time) * 1000, 2),
|
||||
process_time_ms = round((end_time - start_time) * 1000, 2),
|
||||
)
|
||||
|
||||
|
||||
|
|
|
|||
|
|
@ -220,3 +220,41 @@ def test_api_monitor_trim_guards_tiny_limit():
|
|||
assert _trim("abcdefgh", 3) == "..."
|
||||
assert _trim("abcdefgh", 4) == "a..."
|
||||
assert _trim("abcdefgh", 100) == "abcdefgh"
|
||||
|
||||
|
||||
def test_api_monitor_append_reply_caps_without_regrowing():
|
||||
import core.inference.api_monitor as m
|
||||
|
||||
monitor = ApiMonitor(max_entries = 1)
|
||||
entry_id = monitor.start(
|
||||
endpoint = "/v1/chat/completions",
|
||||
method = "POST",
|
||||
model = "m",
|
||||
prompt = "go",
|
||||
)
|
||||
monitor.append_reply(entry_id, "x" * (m._MAX_REPLY_CHARS + 500))
|
||||
capped = monitor.snapshot()[0]["reply"]
|
||||
assert len(capped) == m._MAX_REPLY_CHARS and capped.endswith("...")
|
||||
|
||||
# Chunks past the cap must not change or grow the stored preview.
|
||||
monitor.append_reply(entry_id, "y" * 1000)
|
||||
assert monitor.snapshot()[0]["reply"] == capped
|
||||
|
||||
|
||||
def test_api_monitor_append_reply_exact_cap_then_more_marks_truncated():
|
||||
import core.inference.api_monitor as m
|
||||
|
||||
monitor = ApiMonitor(max_entries = 1)
|
||||
entry_id = monitor.start(
|
||||
endpoint = "/v1/chat/completions",
|
||||
method = "POST",
|
||||
model = "m",
|
||||
prompt = "go",
|
||||
)
|
||||
# A reply landing exactly on the cap has no "..." marker yet.
|
||||
monitor.append_reply(entry_id, "x" * m._MAX_REPLY_CHARS)
|
||||
assert not monitor.snapshot()[0]["reply"].endswith("...")
|
||||
# One more chunk must record the truncation, not silently freeze.
|
||||
monitor.append_reply(entry_id, "y")
|
||||
reply = monitor.snapshot()[0]["reply"]
|
||||
assert len(reply) == m._MAX_REPLY_CHARS and reply.endswith("...")
|
||||
|
|
|
|||
128
studio/backend/tests/test_llama_stats.py
Normal file
128
studio/backend/tests/test_llama_stats.py
Normal file
|
|
@ -0,0 +1,128 @@
|
|||
# SPDX-License-Identifier: AGPL-3.0-only
|
||||
# Copyright 2026-present the Unsloth AI Inc. team. All rights reserved. See /studio/LICENSE.AGPL-3.0
|
||||
|
||||
"""Tests for the llama-server /metrics -> engine_stats translator: generation
|
||||
throughput comes from generated-token metrics (not llama_decode() calls), and
|
||||
the unexposed kv_cache_usage_ratio is never fabricated into the log line."""
|
||||
|
||||
from core.inference.llama_stats import LlamaServerStatsLogger
|
||||
|
||||
|
||||
class _Capture:
|
||||
def __init__(self):
|
||||
self.events = []
|
||||
|
||||
def info(self, event, **kw):
|
||||
self.events.append((event, dict(kw)))
|
||||
|
||||
def debug(self, *a, **k):
|
||||
pass
|
||||
|
||||
|
||||
def _drive(snaps):
|
||||
"""Run _run() synchronously over `snaps`, then stop deterministically."""
|
||||
cap = _Capture()
|
||||
lg = LlamaServerStatsLogger("http://127.0.0.1:0", cap)
|
||||
lg._interval = 0.001 # bypass the 1s floor for a fast, synchronous run
|
||||
state = {"i": 0}
|
||||
|
||||
def fake_scrape():
|
||||
i = state["i"]
|
||||
state["i"] += 1
|
||||
if i >= len(snaps):
|
||||
lg.stop()
|
||||
return None
|
||||
return snaps[i]
|
||||
|
||||
lg._scrape = fake_scrape
|
||||
lg._run()
|
||||
return [kw for ev, kw in cap.events if ev == "engine_stats"]
|
||||
|
||||
|
||||
def test_gen_tok_s_uses_token_metrics_not_decode_calls():
|
||||
# tokens_predicted_total jumps 95 while n_decode_total only moves 9; the
|
||||
# gauge reports 95 tok/s. Decode-call rate (9) must not be reported.
|
||||
snaps = [
|
||||
{
|
||||
"tokens_predicted_total": 0.0,
|
||||
"prompt_tokens_total": 0.0,
|
||||
"n_decode_total": 0.0,
|
||||
"predicted_tokens_seconds": 95.0,
|
||||
"prompt_tokens_seconds": 30.0,
|
||||
"requests_processing": 1.0,
|
||||
},
|
||||
{
|
||||
"tokens_predicted_total": 95.0,
|
||||
"prompt_tokens_total": 30.0,
|
||||
"n_decode_total": 9.0,
|
||||
"predicted_tokens_seconds": 95.0,
|
||||
"prompt_tokens_seconds": 30.0,
|
||||
"requests_processing": 1.0,
|
||||
},
|
||||
]
|
||||
stats = _drive(snaps)
|
||||
assert stats, "expected engine_stats while a request is processing"
|
||||
assert all(s["gen_tok_s"] == 95.0 for s in stats)
|
||||
assert all(s["prompt_tok_s"] == 30.0 for s in stats)
|
||||
|
||||
|
||||
def test_kv_cache_pct_not_emitted_when_metric_absent():
|
||||
# llama.cpp does not expose kv_cache_usage_ratio, so it must not appear.
|
||||
snaps = [
|
||||
{
|
||||
"tokens_predicted_total": 0.0,
|
||||
"prompt_tokens_total": 0.0,
|
||||
"predicted_tokens_seconds": 10.0,
|
||||
"requests_processing": 1.0,
|
||||
},
|
||||
{
|
||||
"tokens_predicted_total": 10.0,
|
||||
"prompt_tokens_total": 5.0,
|
||||
"predicted_tokens_seconds": 10.0,
|
||||
"requests_processing": 1.0,
|
||||
},
|
||||
]
|
||||
stats = _drive(snaps)
|
||||
assert stats
|
||||
assert all("kv_cache_pct" not in s for s in stats)
|
||||
|
||||
|
||||
def test_scrape_parses_labelled_and_bare_metrics(monkeypatch):
|
||||
# Prometheus samples may carry labels; both labelled and bare lines parse.
|
||||
import core.inference.llama_stats as ls
|
||||
|
||||
body = (
|
||||
'llamacpp:tokens_predicted_total{model="m"} 20\n'
|
||||
'llamacpp:prompt_tokens_total{model="m"} 5\n'
|
||||
"llamacpp:requests_processing 1\n"
|
||||
"# HELP llamacpp:ignored ignored\n"
|
||||
)
|
||||
|
||||
class _Resp:
|
||||
status = 200
|
||||
|
||||
def read(self):
|
||||
return body.encode()
|
||||
|
||||
def __enter__(self):
|
||||
return self
|
||||
|
||||
def __exit__(self, *a):
|
||||
return False
|
||||
|
||||
monkeypatch.setattr(ls.urllib.request, "urlopen", lambda *a, **k: _Resp())
|
||||
m = ls.LlamaServerStatsLogger("http://127.0.0.1:0", _Capture())._scrape()
|
||||
assert m["tokens_predicted_total"] == 20.0
|
||||
assert m["prompt_tokens_total"] == 5.0
|
||||
assert m["requests_processing"] == 1.0
|
||||
|
||||
|
||||
def test_counter_delta_fallback_without_gauges():
|
||||
# Older binaries expose only the counters; throughput falls back to deltas.
|
||||
snaps = [
|
||||
{"tokens_predicted_total": 100.0, "prompt_tokens_total": 0.0, "requests_processing": 1.0},
|
||||
{"tokens_predicted_total": 100.0, "prompt_tokens_total": 0.0, "requests_processing": 1.0},
|
||||
]
|
||||
stats = _drive(snaps)
|
||||
# running=1 keeps it emitting; gen_tok_s falls back to the (here zero) delta.
|
||||
assert stats and all(s["gen_tok_s"] >= 0.0 for s in stats)
|
||||
|
|
@ -123,6 +123,100 @@ def test_non_http_scope_passes_through(logs):
|
|||
assert logs.events == []
|
||||
|
||||
|
||||
def test_duplicate_get_within_window_deduped(logs, monkeypatch):
|
||||
monkeypatch.setattr(hmod, "_ACCESS_LOG_DEDUP_MS", 1000)
|
||||
|
||||
async def app(scope, receive, send):
|
||||
await send({"type": "http.response.start", "status": 200, "headers": []})
|
||||
await send({"type": "http.response.body", "body": b"ok"})
|
||||
|
||||
async def send(message):
|
||||
pass
|
||||
|
||||
mw = LoggingMiddleware(app)
|
||||
for _ in range(3):
|
||||
_run(mw(_http_scope("/api/chat/projects"), _noop_receive, send))
|
||||
|
||||
# Only the first of the identical GET/200 burst is logged.
|
||||
assert len(logs.events) == 1
|
||||
assert logs.events[0][1] == "request_completed"
|
||||
|
||||
|
||||
def test_mutations_and_errors_are_never_deduped(logs, monkeypatch):
|
||||
monkeypatch.setattr(hmod, "_ACCESS_LOG_DEDUP_MS", 1000)
|
||||
|
||||
async def post_ok(scope, receive, send):
|
||||
await send({"type": "http.response.start", "status": 200, "headers": []})
|
||||
await send({"type": "http.response.body", "body": b"ok"})
|
||||
|
||||
async def get_404(scope, receive, send):
|
||||
await send({"type": "http.response.start", "status": 404, "headers": []})
|
||||
await send({"type": "http.response.body", "body": b""})
|
||||
|
||||
async def send(message):
|
||||
pass
|
||||
|
||||
mw = LoggingMiddleware(post_ok)
|
||||
for _ in range(2):
|
||||
_run(mw(_http_scope("/api/chat/threads", method = "POST"), _noop_receive, send))
|
||||
mw_404 = LoggingMiddleware(get_404)
|
||||
for _ in range(2):
|
||||
_run(mw_404(_http_scope("/api/models"), _noop_receive, send))
|
||||
|
||||
# 2 mutations + 2 errors all logged (dedup only touches GET/2xx).
|
||||
assert len(logs.events) == 4
|
||||
|
||||
|
||||
def test_quiet_poll_paths_use_longer_heartbeat_window(logs, monkeypatch):
|
||||
# Burst dedup off, quiet-poll heartbeat on: only liveness paths collapse.
|
||||
monkeypatch.setattr(hmod, "_ACCESS_LOG_DEDUP_MS", 0)
|
||||
monkeypatch.setattr(hmod, "_QUIET_POLL_DEDUP_MS", 1000)
|
||||
|
||||
async def app(scope, receive, send):
|
||||
await send({"type": "http.response.start", "status": 200, "headers": []})
|
||||
await send({"type": "http.response.body", "body": b"ok"})
|
||||
|
||||
async def send(message):
|
||||
pass
|
||||
|
||||
mw = LoggingMiddleware(app)
|
||||
for _ in range(3):
|
||||
_run(mw(_http_scope("/api/inference/monitor"), _noop_receive, send)) # quiet
|
||||
for _ in range(3):
|
||||
_run(mw(_http_scope("/api/chat/projects"), _noop_receive, send)) # normal
|
||||
|
||||
paths = [e[2]["path"] for e in logs.events]
|
||||
assert paths.count("/api/inference/monitor") == 1 # collapsed to one heartbeat
|
||||
assert paths.count("/api/chat/projects") == 3 # base dedup off -> all logged
|
||||
|
||||
|
||||
def test_distinct_query_strings_are_not_deduped(logs, monkeypatch):
|
||||
monkeypatch.setattr(hmod, "_ACCESS_LOG_DEDUP_MS", 1000)
|
||||
|
||||
async def app(scope, receive, send):
|
||||
await send({"type": "http.response.start", "status": 200, "headers": []})
|
||||
await send({"type": "http.response.body", "body": b"ok"})
|
||||
|
||||
async def send(message):
|
||||
pass
|
||||
|
||||
def scope(query):
|
||||
return {
|
||||
"type": "http",
|
||||
"path": "/api/models/browse-folders",
|
||||
"method": "GET",
|
||||
"query_string": query,
|
||||
}
|
||||
|
||||
mw = LoggingMiddleware(app)
|
||||
_run(mw(scope(b"path=/tmp/a"), _noop_receive, send))
|
||||
_run(mw(scope(b"path=/tmp/b"), _noop_receive, send)) # distinct query -> logs
|
||||
_run(mw(scope(b"path=/tmp/a"), _noop_receive, send)) # repeat of first -> deduped
|
||||
|
||||
# Two distinct query strings log; the immediate repeat of the first does not.
|
||||
assert len(logs.events) == 2
|
||||
|
||||
|
||||
def test_fastapi_static_asset_success_skips_log(tmp_path, logs):
|
||||
assets_dir = tmp_path / "assets"
|
||||
assets_dir.mkdir()
|
||||
|
|
|
|||
|
|
@ -24,6 +24,13 @@ import typer
|
|||
studio_app = typer.Typer(help = "Unsloth Studio commands.")
|
||||
|
||||
|
||||
def _enable_verbose_access_logs() -> None:
|
||||
"""Restore every per-request access log by disabling the burst dedup and the
|
||||
quiet-poll heartbeat. Inherited by the spawned/re-exec'd server via the env."""
|
||||
os.environ["UNSLOTH_STUDIO_ACCESS_LOG_DEDUP_MS"] = "0"
|
||||
os.environ["UNSLOTH_STUDIO_ACCESS_LOG_POLL_DEDUP_MS"] = "0"
|
||||
|
||||
|
||||
# Resolve install root: UNSLOTH_STUDIO_HOME, then STUDIO_HOME alias, then
|
||||
# sys.prefix inference (so a direct call to <root>/bin/unsloth resolves after
|
||||
# the installer's env var has expired), then legacy ~/.unsloth/studio.
|
||||
|
|
@ -668,6 +675,13 @@ def studio_default(
|
|||
"if the tunnel can't start. Without it, --not-secure also serves the raw "
|
||||
"0.0.0.0 port, which is reachable from anywhere on the network.",
|
||||
),
|
||||
verbose: bool = typer.Option(
|
||||
False,
|
||||
"--verbose",
|
||||
"-v",
|
||||
help = "Log every API request, including the high-frequency polling that is "
|
||||
"deduplicated by default.",
|
||||
),
|
||||
):
|
||||
"""Launch the Unsloth Studio server."""
|
||||
# Runs before every subcommand (run/setup/update/...).
|
||||
|
|
@ -705,6 +719,16 @@ def studio_default(
|
|||
err = True,
|
||||
)
|
||||
raise typer.Exit(2)
|
||||
# Same for --verbose: it would not reach the subcommand.
|
||||
if verbose:
|
||||
typer.echo(
|
||||
f"Error: --verbose on `unsloth studio` applies to the "
|
||||
f"plain-server path only. For `unsloth studio "
|
||||
f"{ctx.invoked_subcommand}`, put it after the subcommand: "
|
||||
f"`unsloth studio {ctx.invoked_subcommand} --verbose ...`",
|
||||
err = True,
|
||||
)
|
||||
raise typer.Exit(2)
|
||||
return
|
||||
|
||||
# --secure requires the tunnel; force a loopback bind.
|
||||
|
|
@ -718,6 +742,11 @@ def studio_default(
|
|||
raise typer.Exit(2)
|
||||
host = "127.0.0.1"
|
||||
|
||||
# --verbose restores the per-request access logs that are suppressed by
|
||||
# default (plain-server path; the `run` subcommand has its own --verbose).
|
||||
if verbose:
|
||||
_enable_verbose_access_logs()
|
||||
|
||||
# Use the studio venv if it exists and we aren't already in it.
|
||||
studio_venv_dir = STUDIO_HOME / "unsloth_studio"
|
||||
in_studio_venv = sys.prefix.startswith(str(studio_venv_dir))
|
||||
|
|
@ -926,6 +955,13 @@ def run(
|
|||
gguf_variant: Optional[str] = typer.Option(
|
||||
None, "--gguf-variant", help = "GGUF quant variant (e.g. UD-Q4_K_XL)"
|
||||
),
|
||||
verbose: bool = typer.Option(
|
||||
False,
|
||||
"--verbose",
|
||||
"-v",
|
||||
help = "Log every API request, including the high-frequency polling that is "
|
||||
"deduplicated by default.",
|
||||
),
|
||||
max_seq_length: int = typer.Option(
|
||||
0,
|
||||
"--max-seq-length",
|
||||
|
|
@ -1009,6 +1045,14 @@ def run(
|
|||
"""
|
||||
extra_llama_args: List[str] = list(ctx.args) if ctx.args else []
|
||||
|
||||
# Set before any re-exec so the in-venv server inherits it via the env.
|
||||
# `run --verbose` used to pass through to llama-server (its own -v); keep
|
||||
# that by forwarding --log-verbose so we add Studio logs without dropping it.
|
||||
if verbose:
|
||||
_enable_verbose_access_logs()
|
||||
if not any(a in ("--verbose", "-v", "--log-verbose") for a in extra_llama_args):
|
||||
extra_llama_args.append("--log-verbose")
|
||||
|
||||
# Promote legacy exact `-m`/`-hfr`/`-f` back into typer params;
|
||||
# clusters stay in extras.
|
||||
model, extra_llama_args = _consume_legacy_short_aliases(
|
||||
|
|
@ -1127,6 +1171,8 @@ def run(
|
|||
args.append("--cloudflare" if cloudflare else "--no-cloudflare")
|
||||
args.append("--secure" if secure else "--not-secure")
|
||||
args.append("--tensor-parallel" if tensor_parallel else "--no-tensor-parallel")
|
||||
if verbose:
|
||||
args.append("--verbose")
|
||||
# llama-server pass-through extras → child ctx.args → load payload.
|
||||
if extra_llama_args:
|
||||
args.extend(extra_llama_args)
|
||||
|
|
|
|||
154
unsloth_cli/tests/test_studio_verbose_flag.py
Normal file
154
unsloth_cli/tests/test_studio_verbose_flag.py
Normal file
|
|
@ -0,0 +1,154 @@
|
|||
# SPDX-License-Identifier: AGPL-3.0-only
|
||||
# Copyright 2026-present the Unsloth AI Inc. team. All rights reserved. See /studio/LICENSE.AGPL-3.0
|
||||
|
||||
"""Tests for the `--verbose/-v` Studio flag: option registration on both the
|
||||
plain callback and the `run` subcommand, re-exec forwarding, the access-log
|
||||
env override, and rejection before a subcommand. Modeled on
|
||||
test_studio_secure_flag.py."""
|
||||
|
||||
from __future__ import annotations
|
||||
|
||||
import sys
|
||||
from pathlib import Path
|
||||
|
||||
from typer.testing import CliRunner
|
||||
|
||||
_REPO_ROOT = Path(__file__).resolve().parents[2]
|
||||
if str(_REPO_ROOT) not in sys.path:
|
||||
sys.path.insert(0, str(_REPO_ROOT))
|
||||
|
||||
_DEDUP = "UNSLOTH_STUDIO_ACCESS_LOG_DEDUP_MS"
|
||||
_POLL = "UNSLOTH_STUDIO_ACCESS_LOG_POLL_DEDUP_MS"
|
||||
_BASE = ["--model", "unsloth/Qwen3-1.7B-GGUF"]
|
||||
|
||||
|
||||
def _studio():
|
||||
from unsloth_cli.commands import studio as _studio_mod
|
||||
return _studio_mod
|
||||
|
||||
|
||||
# ── option registration ──────────────────────────────────────────────
|
||||
|
||||
|
||||
def test_run_exposes_verbose_option_default_off():
|
||||
import inspect
|
||||
|
||||
opt = inspect.signature(_studio().run).parameters["verbose"].default
|
||||
decls = set(getattr(opt, "param_decls", []) or [])
|
||||
assert "--verbose" in decls and "-v" in decls
|
||||
assert getattr(opt, "default", None) is False
|
||||
|
||||
|
||||
def test_studio_default_exposes_verbose_option_default_off():
|
||||
import inspect
|
||||
|
||||
opt = inspect.signature(_studio().studio_default).parameters["verbose"].default
|
||||
decls = set(getattr(opt, "param_decls", []) or [])
|
||||
assert "--verbose" in decls and "-v" in decls
|
||||
assert getattr(opt, "default", None) is False
|
||||
|
||||
|
||||
# ── re-exec capture plumbing (mirrors test_studio_secure_flag.py) ─────
|
||||
|
||||
|
||||
class _ExecCaptured(SystemExit):
|
||||
def __init__(self, argv):
|
||||
super().__init__(0)
|
||||
self.argv = list(argv)
|
||||
|
||||
|
||||
def _invoke_run(monkeypatch, args):
|
||||
import typer as _typer
|
||||
|
||||
studio_mod = _studio()
|
||||
captured = []
|
||||
monkeypatch.setattr(sys, "prefix", "/nonexistent/outer/venv")
|
||||
fake_venv = Path("/fake/studio/venv/unsloth_studio")
|
||||
monkeypatch.setattr(studio_mod, "_studio_venv_python", lambda: fake_venv / "bin" / "python")
|
||||
fake_bin = fake_venv / "bin" / "unsloth"
|
||||
real_is_file = Path.is_file
|
||||
monkeypatch.setattr(
|
||||
Path,
|
||||
"is_file",
|
||||
lambda self: True if str(self) == str(fake_bin) else real_is_file(self),
|
||||
)
|
||||
from unsloth_cli import _tool_policy as _tp_mod
|
||||
|
||||
monkeypatch.setattr(
|
||||
_tp_mod,
|
||||
"resolve_tool_policy",
|
||||
lambda host, flag, yes, silent: False if flag is None else bool(flag),
|
||||
)
|
||||
monkeypatch.setattr(sys, "platform", "linux")
|
||||
|
||||
def fake_execvp(file, argv):
|
||||
captured.append(list(argv))
|
||||
raise _ExecCaptured(argv)
|
||||
|
||||
monkeypatch.setattr(studio_mod.os, "execvp", fake_execvp)
|
||||
app = _typer.Typer()
|
||||
app.command(
|
||||
context_settings = {"allow_extra_args": True, "ignore_unknown_options": True},
|
||||
)(studio_mod.run)
|
||||
CliRunner().invoke(app, args, catch_exceptions = True)
|
||||
return captured
|
||||
|
||||
|
||||
# ── re-exec forwarding + env override ─────────────────────────────────
|
||||
|
||||
|
||||
def test_run_verbose_sets_env_and_forwards_on_reexec(monkeypatch):
|
||||
monkeypatch.delenv(_DEDUP, raising = False)
|
||||
monkeypatch.delenv(_POLL, raising = False)
|
||||
captured = _invoke_run(monkeypatch, _BASE + ["--verbose"])
|
||||
assert len(captured) == 1, captured
|
||||
assert "--verbose" in captured[0], captured[0]
|
||||
import os as _os
|
||||
|
||||
assert _os.environ.get(_DEDUP) == "0"
|
||||
assert _os.environ.get(_POLL) == "0"
|
||||
|
||||
|
||||
def test_run_without_verbose_leaves_env_unset(monkeypatch):
|
||||
monkeypatch.delenv(_DEDUP, raising = False)
|
||||
monkeypatch.delenv(_POLL, raising = False)
|
||||
captured = _invoke_run(monkeypatch, _BASE)
|
||||
assert len(captured) == 1, captured
|
||||
assert "--verbose" not in captured[0], captured[0]
|
||||
assert "--log-verbose" not in captured[0], captured[0]
|
||||
import os as _os
|
||||
|
||||
assert _os.environ.get(_DEDUP) is None
|
||||
assert _os.environ.get(_POLL) is None
|
||||
|
||||
|
||||
def test_run_verbose_preserves_llama_server_verbosity(monkeypatch):
|
||||
# Studio consumes --verbose but still forwards llama-server's own verbosity.
|
||||
monkeypatch.delenv(_DEDUP, raising = False)
|
||||
monkeypatch.delenv(_POLL, raising = False)
|
||||
captured = _invoke_run(monkeypatch, _BASE + ["--verbose"])
|
||||
assert len(captured) == 1, captured
|
||||
assert "--log-verbose" in captured[0], captured[0]
|
||||
|
||||
|
||||
def test_run_verbose_does_not_duplicate_existing_llama_verbose(monkeypatch):
|
||||
monkeypatch.delenv(_DEDUP, raising = False)
|
||||
monkeypatch.delenv(_POLL, raising = False)
|
||||
captured = _invoke_run(monkeypatch, _BASE + ["--verbose", "--log-verbose"])
|
||||
assert len(captured) == 1, captured
|
||||
assert captured[0].count("--log-verbose") == 1, captured[0]
|
||||
|
||||
|
||||
# ── --verbose before a subcommand is rejected ─────────────────────────
|
||||
|
||||
|
||||
def test_studio_default_rejects_verbose_with_subcommand():
|
||||
import typer as _typer
|
||||
|
||||
studio_mod = _studio()
|
||||
app = _typer.Typer()
|
||||
app.add_typer(studio_mod.studio_app, name = "studio")
|
||||
result = CliRunner().invoke(app, ["studio", "--verbose", "run", "--model", "X"])
|
||||
assert result.exit_code == 2, result.output
|
||||
combined = (result.output or "") + (getattr(result, "stderr", "") or "")
|
||||
assert "--verbose" in combined, combined
|
||||
Loading…
Add table
Add a link
Reference in a new issue