From 9a966adf51bcd9d14d175d9ef424b7ac1769e4a4 Mon Sep 17 00:00:00 2001 From: Daniel Han Date: Wed, 17 Jun 2026 05:37:57 -0700 Subject: [PATCH] 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> --- studio/backend/core/inference/api_monitor.py | 9 + studio/backend/core/inference/llama_cpp.py | 24 +++ studio/backend/core/inference/llama_stats.py | 118 ++++++++++++++ studio/backend/loggers/handlers.py | 57 ++++++- studio/backend/tests/test_api_monitor.py | 38 +++++ studio/backend/tests/test_llama_stats.py | 128 +++++++++++++++ .../backend/tests/test_logging_middleware.py | 94 +++++++++++ unsloth_cli/commands/studio.py | 46 ++++++ unsloth_cli/tests/test_studio_verbose_flag.py | 154 ++++++++++++++++++ 9 files changed, 666 insertions(+), 2 deletions(-) create mode 100644 studio/backend/core/inference/llama_stats.py create mode 100644 studio/backend/tests/test_llama_stats.py create mode 100644 unsloth_cli/tests/test_studio_verbose_flag.py diff --git a/studio/backend/core/inference/api_monitor.py b/studio/backend/core/inference/api_monitor.py index b4ecba1b9d..f76a38576f 100644 --- a/studio/backend/core/inference/api_monitor.py +++ b/studio/backend/core/inference/api_monitor.py @@ -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() diff --git a/studio/backend/core/inference/llama_cpp.py b/studio/backend/core/inference/llama_cpp.py index 9221323bd9..31e5d9dec0 100644 --- a/studio/backend/core/inference/llama_cpp.py +++ b/studio/backend/core/inference/llama_cpp.py @@ -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). diff --git a/studio/backend/core/inference/llama_stats.py b/studio/backend/core/inference/llama_stats.py new file mode 100644 index 0000000000..6047aedbc0 --- /dev/null +++ b/studio/backend/core/inference/llama_stats.py @@ -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:[{labels}] " (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 diff --git a/studio/backend/loggers/handlers.py b/studio/backend/loggers/handlers.py index b8691587ac..f471ceb300 100644 --- a/studio/backend/loggers/handlers.py +++ b/studio/backend/loggers/handlers.py @@ -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), ) diff --git a/studio/backend/tests/test_api_monitor.py b/studio/backend/tests/test_api_monitor.py index f0943cd76c..56bc404350 100644 --- a/studio/backend/tests/test_api_monitor.py +++ b/studio/backend/tests/test_api_monitor.py @@ -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("...") diff --git a/studio/backend/tests/test_llama_stats.py b/studio/backend/tests/test_llama_stats.py new file mode 100644 index 0000000000..5e43d80f25 --- /dev/null +++ b/studio/backend/tests/test_llama_stats.py @@ -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) diff --git a/studio/backend/tests/test_logging_middleware.py b/studio/backend/tests/test_logging_middleware.py index 34d43942ef..89061a5cbd 100644 --- a/studio/backend/tests/test_logging_middleware.py +++ b/studio/backend/tests/test_logging_middleware.py @@ -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() diff --git a/unsloth_cli/commands/studio.py b/unsloth_cli/commands/studio.py index 69df81acad..fa7a103797 100644 --- a/unsloth_cli/commands/studio.py +++ b/unsloth_cli/commands/studio.py @@ -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 /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) diff --git a/unsloth_cli/tests/test_studio_verbose_flag.py b/unsloth_cli/tests/test_studio_verbose_flag.py new file mode 100644 index 0000000000..4af32fd4a2 --- /dev/null +++ b/unsloth_cli/tests/test_studio_verbose_flag.py @@ -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