diff --git a/studio/backend/core/inference/inference.py b/studio/backend/core/inference/inference.py index 4dca4db768..1653b9572c 100644 --- a/studio/backend/core/inference/inference.py +++ b/studio/backend/core/inference/inference.py @@ -1737,15 +1737,15 @@ class InferenceBackend: logger.debug("Removing final assistant message to ensure proper alternation") chat_messages.pop() - logger.info(f"Sending {len(chat_messages)} messages to tokenizer:") + logger.debug(f"Sending {len(chat_messages)} messages to tokenizer:") for i, msg in enumerate(chat_messages): - logger.info(f" {i}: {msg['role']} - {msg['content'][:50]}...") + logger.debug(f" {i}: {msg['role']} - {msg['content'][:50]}...") try: formatted_prompt = tokenizer.apply_chat_template( chat_messages, tokenize = False, add_generation_prompt = True ) - logger.info(f"Successfully applied tokenizer's native chat template") + logger.debug(f"Successfully applied tokenizer's native chat template") return formatted_prompt except Exception as e: error_msg = str(e).lower() diff --git a/studio/backend/core/inference/llama_cpp.py b/studio/backend/core/inference/llama_cpp.py index 31969afb14..47ca32f2a1 100644 --- a/studio/backend/core/inference/llama_cpp.py +++ b/studio/backend/core/inference/llama_cpp.py @@ -3134,11 +3134,17 @@ class LlamaCppBackend: drain-thread join in ``_wait_for_health``. """ try: + from loggers.config import logs_verbose + mirror = logs_verbose() for line in self._process.stdout: line = line.rstrip() if line: self._stdout_lines.append(line) - logger.debug(f"[llama-server] {line}") + # The full output is always tee'd to the log file below; only + # mirror it line-by-line to the logger when verbose, else it's + # a firehose at DEBUG. + if mirror: + logger.debug(f"[llama-server] {line}") fh = getattr(self, "_llama_log_fh", None) if fh is not None: try: @@ -3425,9 +3431,9 @@ class LlamaCppBackend: ) if self._context_length: - logger.info(f"GGUF metadata: context_length={self._context_length}") + logger.debug(f"GGUF metadata: context_length={self._context_length}") if self._chat_template: - logger.info(f"GGUF metadata: chat_template={len(self._chat_template)} chars") + logger.debug(f"GGUF metadata: chat_template={len(self._chat_template)} chars") # Detect thinking/reasoning support from chat template. flags = detect_reasoning_flags( self._chat_template, diff --git a/studio/backend/core/inference/orchestrator.py b/studio/backend/core/inference/orchestrator.py index 5dbd5fb479..6a3bb43d0d 100644 --- a/studio/backend/core/inference/orchestrator.py +++ b/studio/backend/core/inference/orchestrator.py @@ -19,6 +19,7 @@ import base64 import os import signal from loggers import get_logger +from loggers.progress import progress_throttle import multiprocessing as mp import queue import threading @@ -133,10 +134,10 @@ class InferenceOrchestrator: ][:40] if gguf_ids: self._top_gguf_cache = gguf_ids - logger.info("Top GGUF models: %s", gguf_ids) + logger.debug("Top GGUF models: %s", gguf_ids) if hub_ids: self._top_hub_cache = hub_ids - logger.info("Top hub models: %s", hub_ids) + logger.debug("Top hub models: %s", hub_ids) except Exception as e: logger.warning("Failed to fetch top models: %s", e) finally: @@ -335,7 +336,11 @@ class InferenceOrchestrator: raise RuntimeError(f"Subprocess error: {error_msg}") if rtype == "status": - logger.info("Subprocess status: %s", resp.get("message", "")) + msg = resp.get("message", "") + # Throttle the repeated heartbeat line to ~10s, but keep resetting + # the deadline on every tick (the subprocess is still alive). + if progress_throttle.should_log(("inference-load", id(self)), msg): + logger.info("Subprocess status: %s", msg) # Reset deadline — subprocess is still alive and working deadline = time.monotonic() + timeout continue @@ -540,9 +545,11 @@ class InferenceOrchestrator: rid = resp.get("request_id") rtype = resp.get("type", "") - # Status messages: log and skip + # Status messages: log (throttled to ~10s) and skip if rtype == "status": - logger.info("Subprocess status: %s", resp.get("message", "")) + msg = resp.get("message", "") + if progress_throttle.should_log(("inference-dispatch", id(self)), msg): + logger.info("Subprocess status: %s", msg) continue # Route to mailbox if a matching request_id exists @@ -821,6 +828,9 @@ class InferenceOrchestrator: if isinstance(_tpl_info, dict): self.models[self.active_model_name]["chat_template_info"] = _tpl_info self.loading_models.discard(model_name) + # Clear the heartbeat state so the next load logs its first + # status line immediately instead of being throttled. + progress_throttle.reset(("inference-load", id(self))) logger.info("Model '%s' loaded successfully in subprocess", model_name) return True else: diff --git a/studio/backend/core/inference/tools.py b/studio/backend/core/inference/tools.py index a5c193ff39..7e1d5b0a59 100644 --- a/studio/backend/core/inference/tools.py +++ b/studio/backend/core/inference/tools.py @@ -984,7 +984,7 @@ def execute_tool( safety checks, blocklist, or resource caps (secrets still stripped). Only affects local code tools; web_search / MCP are unchanged. """ - logger.info(f"execute_tool: name={name}, session_id={session_id}, timeout={timeout}") + logger.debug(f"execute_tool: name={name}, session_id={session_id}, timeout={timeout}") effective_timeout = _EXEC_TIMEOUT if timeout is _TIMEOUT_UNSET else timeout if name == "search_knowledge_base": return _search_knowledge_base(arguments, rag_scope) diff --git a/studio/backend/core/training/training.py b/studio/backend/core/training/training.py index 9d991c6512..9d43d14718 100644 --- a/studio/backend/core/training/training.py +++ b/studio/backend/core/training/training.py @@ -22,6 +22,7 @@ import time import structlog from datetime import datetime, timezone from loggers import get_logger +from loggers.progress import progress_throttle from dataclasses import dataclass, field from pathlib import Path from typing import Optional, Tuple, Any, TYPE_CHECKING @@ -938,6 +939,20 @@ class TrainingBackend: if status: self._progress.status_message = status + # Throttled (~10s) heartbeat so training progress shows in the log + # without a line per step; per-step metrics still stream to the UI + # over SSE. Empty message -> a pure time heartbeat (step changes + # every tick, so it must not key the throttle on the message). + if progress_throttle.should_log(("training", self.current_job_id)): + _loss_str = f"{_safe_loss:.4f}" if _safe_loss is not None else "n/a" + logger.info( + "Training progress: step %s/%s, loss=%s, epoch=%.2f", + self._progress.step, + self._progress.total_steps or "?", + _loss_str, + float(self._progress.epoch or 0.0), + ) + # Update metric histories using sanitized values. step = event.get("step", 0) loss = _safe_loss @@ -1023,6 +1038,7 @@ class TrainingBackend: elif etype == "complete": self._progress.is_training = False self._progress.is_completed = True + progress_throttle.reset(("training", self.current_job_id)) self._output_dir = event.get("output_dir") msg = event.get("status_message", "Training completed") self._progress.status_message = msg @@ -1038,6 +1054,10 @@ class TrainingBackend: elif etype == "error": self._progress.is_training = False self._progress.error = event.get("error", "Unknown error") + # Evict the throttle key on error/stop too (not just on complete), + # so a re-run reusing the job_id logs its first heartbeat at once + # and the entry doesn't linger for the process lifetime. + progress_throttle.reset(("training", self.current_job_id)) logger.error("Training error: %s", event.get("error")) stack = event.get("stack", "") if stack: diff --git a/studio/backend/loggers/config.py b/studio/backend/loggers/config.py index 8977ab4907..ecccf7807c 100644 --- a/studio/backend/loggers/config.py +++ b/studio/backend/loggers/config.py @@ -16,6 +16,36 @@ import structlog from loggers.handlers import filter_sensitive_data +_TRUTHY = {"1", "true", "yes", "on"} + +# Libraries whose INFO/DEBUG chatter carries no operational signal for Studio +# (per-request "HTTP Request: ... 200 OK", HF/transformers banners, multipart +# part dumps). Raised to WARNING unless verbose, so their errors still surface. +_NOISY_LIBS = ( + "httpx", + "httpcore", + "huggingface_hub", + "transformers", + "datasets", + "multipart", + "watchfiles", + "urllib3", + "filelock", + "fsspec", + "asyncio", + "PIL", +) + + +def logs_verbose() -> bool: + """True when the user asked to keep everything (`--verbose` / LOG_LEVEL=DEBUG). + + The single switch every log-noise suppression checks, so verbose restores the + full firehose and nothing is permanently hidden.""" + if (os.getenv("UNSLOTH_STUDIO_VERBOSE", "") or "").strip().lower() in _TRUTHY: + return True + return os.getenv("LOG_LEVEL", "INFO").upper() == "DEBUG" + class LogConfig: """Structured logging configuration for the application.""" @@ -72,4 +102,9 @@ class LogConfig: cache_logger_on_first_use = True, ) + if not logs_verbose(): + for name in _NOISY_LIBS: + logging.getLogger(name).setLevel(logging.WARNING) + logging.captureWarnings(True) + return structlog.get_logger(service_name) diff --git a/studio/backend/loggers/handlers.py b/studio/backend/loggers/handlers.py index f471ceb300..a1c88e7943 100644 --- a/studio/backend/loggers/handlers.py +++ b/studio/backend/loggers/handlers.py @@ -20,6 +20,13 @@ from utils.native_path_leases import redact_native_paths logger = structlog.get_logger(__name__) +def _logs_verbose() -> bool: + # Lazy import: config.py imports this module, so importing it at module load + # would be circular. By request time both modules are fully initialized. + from loggers.config import logs_verbose + return logs_verbose() + + def _env_int(name: str, default: int) -> int: try: raw = (os.environ.get(name) or "").strip() @@ -46,11 +53,18 @@ _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_-]+" ) +_STANDARD_METHODS = frozenset({"GET", "POST", "PUT", "PATCH", "DELETE", "HEAD", "OPTIONS"}) +# Status/progress polls the UI hits every few seconds while an operation runs. +# Their successful 200s carry no signal (the operation's own module logs state +# changes), so they're suppressed on success but STILL logged on any error. _EXCLUDED_PATHS = { "/api/train/status", "/api/train/metrics", "/api/train/hardware", "/api/system", + "/api/export/status", + "/api/export/logs", + "/api/inference/load-progress", } _EXCLUDED_SUFFIXES = ( ".png", @@ -78,7 +92,11 @@ class LoggingMiddleware: """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.""" + heartbeat window. Stamps only on emit, so steady polls still log. Verbose + keeps every line (the direct backend --verbose path doesn't zero the dedup + env vars, so honor it here too, not just via the CLI helper).""" + if _logs_verbose(): + return False 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 @@ -100,11 +118,15 @@ class LoggingMiddleware: return path = scope["path"] - excluded = ( - path in _EXCLUDED_PATHS - or path.startswith("/assets/") - or path.endswith(_EXCLUDED_SUFFIXES) - ) + method = scope["method"] + # Scanner/proxy probes (CONNECT, absolute-form "GET http://...", PRI, + # random verbs) are never legitimate app traffic. Static assets are pure + # noise too. Both are quiet even on 4xx. Status/progress polls + # (_EXCLUDED_PATHS) are quiet on success but still log on error. A normal + # GET/POST 404 is real signal and stays. Verbose keeps everything. + scanner = method not in _STANDARD_METHODS or "://" in path + static = path.startswith("/assets/") or path.endswith(_EXCLUDED_SUFFIXES) + success_poll = path in _EXCLUDED_PATHS start_time = time.perf_counter() status_code = 500 @@ -129,12 +151,21 @@ class LoggingMiddleware: raise else: 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 + is_success = 200 <= status_code < 300 + if _logs_verbose(): + suppress = False + elif scanner or static: + suppress = True + elif success_poll and is_success: + suppress = True + else: + suppress = False + if not suppress and not self._is_redundant_repeat( + method, path, scope.get("query_string", b""), status_code, end_time ): logger.info( "request_completed", - method = scope["method"], + method = method, path = path, status_code = status_code, process_time_ms = round((end_time - start_time) * 1000, 2), diff --git a/studio/backend/loggers/progress.py b/studio/backend/loggers/progress.py new file mode 100644 index 0000000000..0a136532d9 --- /dev/null +++ b/studio/backend/loggers/progress.py @@ -0,0 +1,67 @@ +# SPDX-License-Identifier: AGPL-3.0-only +# Copyright 2026-present the Unsloth AI Inc. team. All rights reserved. See /studio/LICENSE.AGPL-3.0 + +"""Heartbeat throttle for repeated progress logs. + +A long download / model load / training run streams the same progress line over +and over. ProgressThrottle keeps progress visible but not redundant: it logs the +first message for a key, any time the message changes (a new phase), then at most +once per interval while it stays the same. Start/completion/error lines live at +their own call sites and are never gated here. Verbose restores every line. +""" + +import os +import threading +import time + + +def _interval_default() -> float: + try: + return max(0.0, float(os.environ.get("UNSLOTH_STUDIO_PROGRESS_LOG_INTERVAL_S", "10"))) + except ValueError: + return 10.0 + + +def _verbose() -> bool: + from loggers.config import logs_verbose + return logs_verbose() + + +class ProgressThrottle: + """Emit a progress line at most once per ``interval_s`` per key, plus whenever + the message changes. ``interval_s=0`` (or verbose) logs everything. Pass a + stable/empty ``message`` for a pure time heartbeat (e.g. a step counter that + changes every tick), or the real status text to also log on phase changes.""" + + def __init__(self, interval_s: "float | None" = None) -> None: + self._interval = _interval_default() if interval_s is None else interval_s + self._last_emit: dict = {} + self._last_msg: dict = {} + self._guard = threading.Lock() + + def should_log( + self, + key, + message: str = "", + ) -> bool: + if self._interval <= 0 or _verbose(): + return True + now = time.monotonic() + with self._guard: + changed = self._last_msg.get(key) != message + last = self._last_emit.get(key) + if changed or last is None or (now - last) >= self._interval: + self._last_emit[key] = now + self._last_msg[key] = message + return True + return False + + def reset(self, key) -> None: + """Forget a key so its next message logs immediately (call on completion).""" + with self._guard: + self._last_emit.pop(key, None) + self._last_msg.pop(key, None) + + +# Shared instance for the subprocess status / training heartbeats. +progress_throttle = ProgressThrottle() diff --git a/studio/backend/run.py b/studio/backend/run.py index d4cbc26b41..4bb1350707 100644 --- a/studio/backend/run.py +++ b/studio/backend/run.py @@ -131,6 +131,26 @@ def _install_uvicorn_startup_log_rewrite(bind_host: str, display_host: str) -> N for name in ("uvicorn", "uvicorn.error"): logging.getLogger(name).addFilter(f) + # Drop h11's per-probe "Invalid HTTP request received" warnings: port + # scanners and TLS-on-HTTP handshakes spam these and they carry no signal. + # Verbose keeps them. + from loggers.config import logs_verbose + + _h11_junk = ("Invalid HTTP request received", "Invalid HTTP method") + + class _DropScannerNoise(logging.Filter): + def filter(self, record: logging.LogRecord) -> bool: + if logs_verbose(): + return True + try: + return not record.getMessage().startswith(_h11_junk) + except Exception: + return True + + drop = _DropScannerNoise() + for name in ("uvicorn", "uvicorn.error"): + logging.getLogger(name).addFilter(drop) + def _local_port_open( host: str, @@ -1271,6 +1291,13 @@ def _build_arg_parser(): help = "Path to frontend build", ) parser.add_argument("--silent", action = "store_true", help = "Suppress output") + parser.add_argument( + "--verbose", + "-v", + action = "store_true", + help = "Keep all logs (no noise suppression): library INFO, per-request " + "scanner lines, llama-server output, and full model-load narration.", + ) parser.add_argument( "--api-only", action = "store_true", @@ -1343,6 +1370,13 @@ if __name__ == "__main__": parser = _build_arg_parser() args = parser.parse_args() + # Set verbose env before run_server() so setup_logging() and every + # suppression site see it; also restore library/DEBUG logging. + if args.verbose: + os.environ["UNSLOTH_STUDIO_VERBOSE"] = "1" + # Force DEBUG: --verbose must restore the demoted lines even when a + # launcher already exported LOG_LEVEL=INFO/WARNING (setdefault would not). + os.environ["LOG_LEVEL"] = "DEBUG" if not _PARALLEL_MIN <= args.parallel <= _PARALLEL_MAX: parser.error(f"--parallel must be between {_PARALLEL_MIN} and {_PARALLEL_MAX}") if args.secure and not args.cloudflare: diff --git a/studio/backend/tests/test_log_noise_filters.py b/studio/backend/tests/test_log_noise_filters.py new file mode 100644 index 0000000000..8299aa4b84 --- /dev/null +++ b/studio/backend/tests/test_log_noise_filters.py @@ -0,0 +1,216 @@ +# SPDX-License-Identifier: AGPL-3.0-only +# Copyright 2026-present the Unsloth AI Inc. team. All rights reserved. See /studio/LICENSE.AGPL-3.0 + +"""Log-noise suppression: scanner-request skip, uvicorn h11 drop-filter, +library quieting, and the --verbose / LOG_LEVEL=DEBUG escape hatch.""" + +import asyncio +import logging + +import pytest + +from loggers import handlers as hmod +from loggers.config import LogConfig, logs_verbose, _NOISY_LIBS +from loggers.handlers import LoggingMiddleware +from run import _install_uvicorn_startup_log_rewrite + + +class _LogCapture: + def __init__(self): + self.events = [] + + def info(self, event, **kw): + self.events.append(("info", event, kw)) + + def error(self, event, **kw): + self.events.append(("error", event, kw)) + + +@pytest.fixture +def logs(monkeypatch): + capture = _LogCapture() + monkeypatch.setattr(hmod, "logger", capture) + return capture + + +@pytest.fixture(autouse = True) +def _not_verbose(monkeypatch): + monkeypatch.delenv("UNSLOTH_STUDIO_VERBOSE", raising = False) + monkeypatch.setenv("LOG_LEVEL", "INFO") + + +def _scope(path, method = "GET"): + return {"type": "http", "path": path, "method": method} + + +async def _noop_receive(): + return {"type": "http.disconnect"} + + +def _run(coro): + return asyncio.run(coro) + + +async def _ok_app(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 + + +# ── scanner request skip (B3) ────────────────────────────────────────── + + +@pytest.mark.parametrize( + "scope", + [ + _scope("www.baidu.com:443", method = "CONNECT"), + _scope("*", method = "PRI"), + _scope("/", method = "FOOBAR"), + _scope("http://example.com/", method = "GET"), # absolute-form + ], +) +def test_scanner_requests_are_not_logged(logs, scope): + _run(LoggingMiddleware(_ok_app)(scope, _noop_receive, _send)) + assert logs.events == [] + + +def test_normal_404_is_still_logged(logs): + _run(LoggingMiddleware(_ok_app)(_scope("/api/does-not-exist"), _noop_receive, _send)) + assert len(logs.events) == 1 + assert logs.events[0][1] == "request_completed" + assert logs.events[0][2]["status_code"] == 404 + + +def _status_app(status): + async def app(scope, receive, send): + await send({"type": "http.response.start", "status": status, "headers": []}) + await send({"type": "http.response.body", "body": b""}) + + return app + + +# ── status/progress poll: quiet on success, logged on error ──────────── + + +def test_success_poll_200_suppressed(logs): + # The high-frequency /api/export/status poll (838x in a real run) is silenced. + for _ in range(5): + _run( + LoggingMiddleware(_status_app(200))(_scope("/api/export/status"), _noop_receive, _send) + ) + assert logs.events == [] + + +def test_success_poll_error_is_still_logged(logs): + # ... but a 401/500 on that same poll path must surface. + _run(LoggingMiddleware(_status_app(401))(_scope("/api/export/status"), _noop_receive, _send)) + assert len(logs.events) == 1 + assert logs.events[0][2]["status_code"] == 401 + + +def test_load_progress_poll_suppressed(logs): + _run( + LoggingMiddleware(_status_app(200))( + _scope("/api/inference/load-progress"), _noop_receive, _send + ) + ) + assert logs.events == [] + + +def test_verbose_keeps_scanner_requests(logs, monkeypatch): + monkeypatch.setenv("UNSLOTH_STUDIO_VERBOSE", "1") + _run( + LoggingMiddleware(_ok_app)( + _scope("www.baidu.com:443", method = "CONNECT"), _noop_receive, _send + ) + ) + assert len(logs.events) == 1 + assert logs.events[0][2]["method"] == "CONNECT" + + +def test_duplicate_success_get_deduped_by_default(logs): + # Two identical successful GETs within the window: only the first logs. + mw = LoggingMiddleware(_status_app(200)) + for _ in range(2): + _run(mw(_scope("/api/runs"), _noop_receive, _send)) + assert len(logs.events) == 1 + + +def test_verbose_keeps_duplicate_success_get(logs, monkeypatch): + # ... but --verbose must emit every line, including the duplicate. The direct + # backend --verbose path doesn't zero the dedup env vars, so the dedup helper + # itself has to honor verbose (regression: it previously dropped the repeat). + monkeypatch.setenv("UNSLOTH_STUDIO_VERBOSE", "1") + mw = LoggingMiddleware(_status_app(200)) + for _ in range(2): + _run(mw(_scope("/api/runs"), _noop_receive, _send)) + assert len(logs.events) == 2 + + +# ── verbose helper (B1/B2) ───────────────────────────────────────────── + + +def test_logs_verbose_env_and_debug(monkeypatch): + monkeypatch.delenv("UNSLOTH_STUDIO_VERBOSE", raising = False) + monkeypatch.setenv("LOG_LEVEL", "INFO") + assert logs_verbose() is False + monkeypatch.setenv("LOG_LEVEL", "DEBUG") + assert logs_verbose() is True + monkeypatch.setenv("LOG_LEVEL", "INFO") + monkeypatch.setenv("UNSLOTH_STUDIO_VERBOSE", "1") + assert logs_verbose() is True + + +# ── uvicorn h11 drop-filter (B2) ─────────────────────────────────────── + + +def _uvicorn_record(msg): + return logging.LogRecord("uvicorn.error", logging.WARNING, __file__, 0, msg, None, None) + + +def test_uvicorn_drop_filter_drops_invalid_http(monkeypatch): + log = logging.getLogger("uvicorn.error") + log.filters = [] + try: + _install_uvicorn_startup_log_rewrite("127.0.0.1", "127.0.0.1") + # filter() returns False to drop, else the (truthy) record. + assert log.filter(_uvicorn_record("Invalid HTTP request received")) is False + # real warnings/errors pass through + assert log.filter(_uvicorn_record("Worker failed to boot")) + finally: + log.filters = [] + + +def test_uvicorn_drop_filter_verbose_keeps_all(monkeypatch): + monkeypatch.setenv("UNSLOTH_STUDIO_VERBOSE", "1") + log = logging.getLogger("uvicorn.error") + log.filters = [] + try: + _install_uvicorn_startup_log_rewrite("127.0.0.1", "127.0.0.1") + assert log.filter(_uvicorn_record("Invalid HTTP request received")) + finally: + log.filters = [] + + +# ── library quieting (B1) ────────────────────────────────────────────── + + +def test_setup_logging_quiets_libraries(monkeypatch): + for name in _NOISY_LIBS: + logging.getLogger(name).setLevel(logging.NOTSET) + monkeypatch.delenv("UNSLOTH_STUDIO_VERBOSE", raising = False) + monkeypatch.setenv("LOG_LEVEL", "INFO") + LogConfig.setup_logging() + assert logging.getLogger("httpx").level == logging.WARNING + assert logging.getLogger("transformers").level == logging.WARNING + + +def test_setup_logging_verbose_does_not_quiet(monkeypatch): + for name in _NOISY_LIBS: + logging.getLogger(name).setLevel(logging.NOTSET) + monkeypatch.setenv("UNSLOTH_STUDIO_VERBOSE", "1") + LogConfig.setup_logging() + assert logging.getLogger("httpx").level == logging.NOTSET diff --git a/studio/backend/tests/test_progress_throttle.py b/studio/backend/tests/test_progress_throttle.py new file mode 100644 index 0000000000..323a0ce7d6 --- /dev/null +++ b/studio/backend/tests/test_progress_throttle.py @@ -0,0 +1,78 @@ +# SPDX-License-Identifier: AGPL-3.0-only +# Copyright 2026-present the Unsloth AI Inc. team. All rights reserved. See /studio/LICENSE.AGPL-3.0 + +"""Heartbeat throttle for repeated progress logs.""" + +import pytest + +from loggers.progress import ProgressThrottle + + +@pytest.fixture(autouse = True) +def _not_verbose(monkeypatch): + monkeypatch.delenv("UNSLOTH_STUDIO_VERBOSE", raising = False) + monkeypatch.setenv("LOG_LEVEL", "INFO") + + +def test_first_message_logs_then_identical_repeats_throttle(): + t = ProgressThrottle(interval_s = 100) # large window: only the first logs + k = "load" + assert t.should_log(k, "Downloading...") is True # first + assert t.should_log(k, "Downloading...") is False # identical repeat within window + assert t.should_log(k, "Downloading...") is False + + +def test_message_change_always_logs(): + t = ProgressThrottle(interval_s = 100) + k = "load" + assert t.should_log(k, "Loading model...") is True + assert t.should_log(k, "Loading model...") is False + assert t.should_log(k, "Importing Unsloth...") is True # phase change logs + + +def test_heartbeat_emits_after_interval(): + import time + + t = ProgressThrottle(interval_s = 0.05) + k = "load" + assert t.should_log(k, "same") is True + assert t.should_log(k, "same") is False + time.sleep(0.06) + assert t.should_log(k, "same") is True # interval elapsed -> heartbeat + + +def test_empty_message_is_pure_time_heartbeat(): + # A step counter changes every tick, so callers pass an empty message and rely + # only on the interval. Identical empty messages must not all log. + t = ProgressThrottle(interval_s = 100) + k = ("training", "job1") + assert t.should_log(k) is True + assert t.should_log(k) is False + assert t.should_log(k) is False + + +def test_reset_logs_next_immediately(): + t = ProgressThrottle(interval_s = 100) + k = "load" + assert t.should_log(k, "x") is True + assert t.should_log(k, "x") is False + t.reset(k) + assert t.should_log(k, "x") is True # fresh after reset + + +def test_zero_interval_logs_everything(): + t = ProgressThrottle(interval_s = 0) + assert all(t.should_log("k", "same") for _ in range(5)) + + +def test_verbose_disables_throttle(monkeypatch): + monkeypatch.setenv("UNSLOTH_STUDIO_VERBOSE", "1") + t = ProgressThrottle(interval_s = 100) + assert all(t.should_log("k", "same") for _ in range(5)) + + +def test_distinct_keys_are_independent(): + t = ProgressThrottle(interval_s = 100) + assert t.should_log("a", "m") is True + assert t.should_log("b", "m") is True # different key, independent + assert t.should_log("a", "m") is False diff --git a/studio/backend/tests/test_training_progress_throttle_reset.py b/studio/backend/tests/test_training_progress_throttle_reset.py new file mode 100644 index 0000000000..d9f5bb7ad3 --- /dev/null +++ b/studio/backend/tests/test_training_progress_throttle_reset.py @@ -0,0 +1,55 @@ +# SPDX-License-Identifier: AGPL-3.0-only +# Copyright 2026-present the Unsloth AI Inc. team. All rights reserved. See /studio/LICENSE.AGPL-3.0 + +"""The training progress-log throttle key must be evicted on terminal events. + +A long run logs a throttled "Training progress" heartbeat keyed by +("training", job_id). That key has to be released on BOTH complete and error/stop +(not just complete), so a re-run reusing the job_id logs its first heartbeat +immediately and the entry doesn't linger for the process lifetime. +""" + +import os +import sys + +import pytest + +_backend = os.path.join(os.path.dirname(__file__), "..") +if _backend not in sys.path: + sys.path.insert(0, _backend) + +from core.training.training import TrainingBackend +from loggers.progress import progress_throttle + + +@pytest.fixture(autouse = True) +def _not_verbose(monkeypatch): + # Verbose makes should_log() always True, which would mask the throttle. + monkeypatch.delenv("UNSLOTH_STUDIO_VERBOSE", raising = False) + monkeypatch.setenv("LOG_LEVEL", "INFO") + + +def _seed_throttled(job_id: str): + # First call logs, the immediate repeat is throttled within the 10s window. + key = ("training", job_id) + progress_throttle.reset(key) + assert progress_throttle.should_log(key) is True + assert progress_throttle.should_log(key) is False + return key + + +def test_error_event_resets_progress_throttle(): + b = TrainingBackend() + b.current_job_id = "job-err" + key = _seed_throttled("job-err") + b._handle_event({"type": "error", "error": "boom"}) + # Evicted -> the next run's first heartbeat logs at once. + assert progress_throttle.should_log(key) is True + + +def test_complete_event_resets_progress_throttle(): + b = TrainingBackend() + b.current_job_id = "job-done" + key = _seed_throttled("job-done") + b._handle_event({"type": "complete"}) + assert progress_throttle.should_log(key) is True diff --git a/studio/backend/utils/models/model_config.py b/studio/backend/utils/models/model_config.py index 5d8458e5f0..1796b88724 100644 --- a/studio/backend/utils/models/model_config.py +++ b/studio/backend/utils/models/model_config.py @@ -2457,7 +2457,7 @@ def load_model_defaults(model_name: str) -> Dict[str, Any]: if default_config_path.exists(): with open(default_config_path, "r", encoding = "utf-8") as f: config = yaml.safe_load(f) or {} - logger.info(f"Loaded default model defaults from {default_config_path}") + logger.debug(f"Loaded default model defaults from {default_config_path}") return config logger.warning(f"No default config found for model {model_name}") diff --git a/unsloth_cli/commands/studio.py b/unsloth_cli/commands/studio.py index 5975e7e355..e85353014e 100644 --- a/unsloth_cli/commands/studio.py +++ b/unsloth_cli/commands/studio.py @@ -25,10 +25,15 @@ 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.""" + """Make --verbose restore EVERY log: per-request access lines (disable the + burst dedup + quiet-poll heartbeat) plus all other noise suppression + (scanner probes, library INFO, llama-server mirror, model-load narration) + via UNSLOTH_STUDIO_VERBOSE + DEBUG. Inherited by the spawned server's env.""" os.environ["UNSLOTH_STUDIO_ACCESS_LOG_DEDUP_MS"] = "0" os.environ["UNSLOTH_STUDIO_ACCESS_LOG_POLL_DEDUP_MS"] = "0" + os.environ["UNSLOTH_STUDIO_VERBOSE"] = "1" + # Force DEBUG so demoted lines reappear even if LOG_LEVEL was preset. + os.environ["LOG_LEVEL"] = "DEBUG" # Resolve install root: UNSLOTH_STUDIO_HOME, then STUDIO_HOME alias, then diff --git a/unsloth_cli/tests/test_studio_verbose_flag.py b/unsloth_cli/tests/test_studio_verbose_flag.py index 4af32fd4a2..7b313d9686 100644 --- a/unsloth_cli/tests/test_studio_verbose_flag.py +++ b/unsloth_cli/tests/test_studio_verbose_flag.py @@ -139,6 +139,23 @@ def test_run_verbose_does_not_duplicate_existing_llama_verbose(monkeypatch): assert captured[0].count("--log-verbose") == 1, captured[0] +# ── --verbose forces DEBUG even when LOG_LEVEL is preset ────────────── + + +def test_verbose_overrides_existing_log_level(monkeypatch): + # A launcher exporting LOG_LEVEL=INFO must not keep the demoted lines hidden: + # --verbose has to force DEBUG (setdefault would leave it at INFO). + monkeypatch.setenv("LOG_LEVEL", "INFO") + monkeypatch.delenv("UNSLOTH_STUDIO_VERBOSE", raising = False) + + _studio()._enable_verbose_access_logs() + + import os as _os + + assert _os.environ["UNSLOTH_STUDIO_VERBOSE"] == "1" + assert _os.environ["LOG_LEVEL"] == "DEBUG" + + # ── --verbose before a subcommand is rejected ─────────────────────────