From 63ad2cd38fc2a499c983874ac8ff84e93be95941 Mon Sep 17 00:00:00 2001 From: Daniel Han Date: Thu, 25 Jun 2026 12:47:11 +0000 Subject: [PATCH 1/8] Studio: trim log noise (scanner probes, library chatter, load narration) with a --verbose escape hatch Default-level logs accumulated low-signal lines: uvicorn 'Invalid HTTP request received' from port scanners, per-probe request_completed access lines for CONNECT / absolute-form / non-standard methods, third-party library INFO (httpx 'HTTP Request: ... 200 OK', HF/transformers banners), and repeated model-load narration. None of it helps operate Studio, and it buries real warnings/errors. Changes (all backwards-compatible; --verbose or LOG_LEVEL=DEBUG restores everything): - loggers/config.py: logs_verbose() helper; raise noisy third-party loggers to WARNING and captureWarnings(True) unless verbose. Errors still surface. - run.py: --verbose/-v flag (sets UNSLOTH_STUDIO_VERBOSE + LOG_LEVEL=DEBUG); uvicorn drop-filter for h11 'Invalid HTTP request' scanner warnings. - loggers/handlers.py: LoggingMiddleware skips scanner/proxy probes (non-standard method or absolute-form target); a normal GET/POST 404 still logs. - llama_cpp.py: only mirror llama-server output line-by-line to the logger when verbose (the full output is always tee'd to the per-server log file); demote GGUF metadata descriptors to debug. - Demote repetitive load narration to debug: execute_tool per-call, Top GGUF/hub model lists, 'Loaded default model defaults', per-message tokenizer dump. - tests/test_log_noise_filters.py: scanner skip + real-404 kept, verbose round trip, uvicorn drop-filter, library quieting. Throughput logging is unchanged: the periodic vLLM-style engine_stats line (configurable via UNSLOTH_STUDIO_ENGINE_STATS_INTERVAL_S, idle-skipping) stays. --- studio/backend/core/inference/inference.py | 6 +- studio/backend/core/inference/llama_cpp.py | 13 +- studio/backend/core/inference/orchestrator.py | 4 +- studio/backend/core/inference/tools.py | 2 +- studio/backend/loggers/config.py | 25 +++ studio/backend/loggers/handlers.py | 28 +++- studio/backend/run.py | 32 ++++ .../backend/tests/test_log_noise_filters.py | 151 ++++++++++++++++++ studio/backend/utils/models/model_config.py | 2 +- 9 files changed, 248 insertions(+), 15 deletions(-) create mode 100644 studio/backend/tests/test_log_noise_filters.py 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..e8ea62b833 100644 --- a/studio/backend/core/inference/llama_cpp.py +++ b/studio/backend/core/inference/llama_cpp.py @@ -3134,11 +3134,18 @@ 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 +3432,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..f73978db72 100644 --- a/studio/backend/core/inference/orchestrator.py +++ b/studio/backend/core/inference/orchestrator.py @@ -133,10 +133,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: 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/loggers/config.py b/studio/backend/loggers/config.py index 8977ab4907..ab5c073fbd 100644 --- a/studio/backend/loggers/config.py +++ b/studio/backend/loggers/config.py @@ -16,6 +16,26 @@ 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 +92,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..2f48eab143 100644 --- a/studio/backend/loggers/handlers.py +++ b/studio/backend/loggers/handlers.py @@ -20,6 +20,14 @@ 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,6 +54,9 @@ _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"} +) _EXCLUDED_PATHS = { "/api/train/status", "/api/train/metrics", @@ -100,11 +111,18 @@ class LoggingMiddleware: return path = scope["path"] - excluded = ( - path in _EXCLUDED_PATHS - or path.startswith("/assets/") - or path.endswith(_EXCLUDED_SUFFIXES) - ) + # Scanner/proxy probes (CONNECT, absolute-form "GET http://...", PRI, + # random verbs) are never legitimate app traffic; drop their access + # line unless verbose. A normal GET/POST 404 is real signal and stays. + scanner = scope["method"] not in _STANDARD_METHODS or "://" in path + if scanner and not _logs_verbose(): + excluded = True + else: + excluded = ( + path in _EXCLUDED_PATHS + or path.startswith("/assets/") + or path.endswith(_EXCLUDED_SUFFIXES) + ) start_time = time.perf_counter() status_code = 500 diff --git a/studio/backend/run.py b/studio/backend/run.py index d4cbc26b41..a40cf72754 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,11 @@ 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" + os.environ.setdefault("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..2cf56e76b4 --- /dev/null +++ b/studio/backend/tests/test_log_noise_filters.py @@ -0,0 +1,151 @@ +# 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 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" + + +# ── 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/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}") From d39cff25b897a7c2f3fc1c56acf5adf266447541 Mon Sep 17 00:00:00 2001 From: "pre-commit-ci[bot]" <66853113+pre-commit-ci[bot]@users.noreply.github.com> Date: Thu, 25 Jun 2026 12:48:18 +0000 Subject: [PATCH 2/8] [pre-commit.ci] auto fixes from pre-commit.com hooks for more information, see https://pre-commit.ci --- studio/backend/core/inference/llama_cpp.py | 1 - studio/backend/loggers/config.py | 14 ++++++-- studio/backend/loggers/handlers.py | 5 +-- .../backend/tests/test_log_noise_filters.py | 36 ++++++++++++------- 4 files changed, 36 insertions(+), 20 deletions(-) diff --git a/studio/backend/core/inference/llama_cpp.py b/studio/backend/core/inference/llama_cpp.py index e8ea62b833..47ca32f2a1 100644 --- a/studio/backend/core/inference/llama_cpp.py +++ b/studio/backend/core/inference/llama_cpp.py @@ -3135,7 +3135,6 @@ class LlamaCppBackend: """ try: from loggers.config import logs_verbose - mirror = logs_verbose() for line in self._process.stdout: line = line.rstrip() diff --git a/studio/backend/loggers/config.py b/studio/backend/loggers/config.py index ab5c073fbd..ecccf7807c 100644 --- a/studio/backend/loggers/config.py +++ b/studio/backend/loggers/config.py @@ -22,8 +22,18 @@ _TRUTHY = {"1", "true", "yes", "on"} # (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", + "httpx", + "httpcore", + "huggingface_hub", + "transformers", + "datasets", + "multipart", + "watchfiles", + "urllib3", + "filelock", + "fsspec", + "asyncio", + "PIL", ) diff --git a/studio/backend/loggers/handlers.py b/studio/backend/loggers/handlers.py index 2f48eab143..3d1c642c4b 100644 --- a/studio/backend/loggers/handlers.py +++ b/studio/backend/loggers/handlers.py @@ -24,7 +24,6 @@ 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() @@ -54,9 +53,7 @@ _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"} -) +_STANDARD_METHODS = frozenset({"GET", "POST", "PUT", "PATCH", "DELETE", "HEAD", "OPTIONS"}) _EXCLUDED_PATHS = { "/api/train/status", "/api/train/metrics", diff --git a/studio/backend/tests/test_log_noise_filters.py b/studio/backend/tests/test_log_noise_filters.py index 2cf56e76b4..33edac4bd0 100644 --- a/studio/backend/tests/test_log_noise_filters.py +++ b/studio/backend/tests/test_log_noise_filters.py @@ -33,13 +33,13 @@ def logs(monkeypatch): return capture -@pytest.fixture(autouse=True) +@pytest.fixture(autouse = True) def _not_verbose(monkeypatch): - monkeypatch.delenv("UNSLOTH_STUDIO_VERBOSE", raising=False) + monkeypatch.delenv("UNSLOTH_STUDIO_VERBOSE", raising = False) monkeypatch.setenv("LOG_LEVEL", "INFO") -def _scope(path, method="GET"): +def _scope(path, method = "GET"): return {"type": "http", "path": path, "method": method} @@ -62,12 +62,16 @@ async def _send(message): # ── 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 -]) + +@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 == [] @@ -82,16 +86,20 @@ def test_normal_404_is_still_logged(logs): 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)) + _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" # ── verbose helper (B1/B2) ───────────────────────────────────────────── + def test_logs_verbose_env_and_debug(monkeypatch): - monkeypatch.delenv("UNSLOTH_STUDIO_VERBOSE", raising=False) + monkeypatch.delenv("UNSLOTH_STUDIO_VERBOSE", raising = False) monkeypatch.setenv("LOG_LEVEL", "INFO") assert logs_verbose() is False monkeypatch.setenv("LOG_LEVEL", "DEBUG") @@ -103,6 +111,7 @@ def test_logs_verbose_env_and_debug(monkeypatch): # ── uvicorn h11 drop-filter (B2) ─────────────────────────────────────── + def _uvicorn_record(msg): return logging.LogRecord("uvicorn.error", logging.WARNING, __file__, 0, msg, None, None) @@ -133,10 +142,11 @@ def test_uvicorn_drop_filter_verbose_keeps_all(monkeypatch): # ── 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.delenv("UNSLOTH_STUDIO_VERBOSE", raising = False) monkeypatch.setenv("LOG_LEVEL", "INFO") LogConfig.setup_logging() assert logging.getLogger("httpx").level == logging.WARNING From 600d23286f82e9eaded0bed26e563b5061f24584 Mon Sep 17 00:00:00 2001 From: Daniel Han Date: Fri, 26 Jun 2026 08:06:52 +0000 Subject: [PATCH 3/8] Studio: suppress high-frequency success polls and unify --verbose across the CLI A real long session was dominated by one near-duplicate line: GET /api/export/status 200 logged every ~5s accounted for 838 of 1106 lines (81%) in a sample run. These status/progress polls carry no signal on success (the operation's own module logs state changes), so suppress them on 2xx while still logging any error. - loggers/handlers.py: add /api/export/status, /api/export/logs, /api/inference/load-progress to the poll set; restructure the middleware so scanners and static assets stay quiet always, status/progress polls are quiet only on success, and every error (and normal GET/POST 404) still logs. - unsloth_cli/commands/studio.py: _enable_verbose_access_logs() (the shared chokepoint for unsloth run / unsloth studio run / unsloth studio --verbose) now also sets UNSLOTH_STUDIO_VERBOSE + LOG_LEVEL=DEBUG, so one --verbose restores every suppressed log, not just the access-log dedup. - tests: success poll suppressed on 200, logged on 401; load-progress suppressed. Measured on a real session log this removes 83% of lines / 85% of bytes. --- studio/backend/loggers/handlers.py | 40 ++++++++++++------- .../backend/tests/test_log_noise_filters.py | 28 +++++++++++++ unsloth_cli/commands/studio.py | 8 +++- 3 files changed, 60 insertions(+), 16 deletions(-) diff --git a/studio/backend/loggers/handlers.py b/studio/backend/loggers/handlers.py index 3d1c642c4b..32f9bba408 100644 --- a/studio/backend/loggers/handlers.py +++ b/studio/backend/loggers/handlers.py @@ -54,11 +54,17 @@ _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", @@ -108,18 +114,15 @@ class LoggingMiddleware: return path = scope["path"] + method = scope["method"] # Scanner/proxy probes (CONNECT, absolute-form "GET http://...", PRI, - # random verbs) are never legitimate app traffic; drop their access - # line unless verbose. A normal GET/POST 404 is real signal and stays. - scanner = scope["method"] not in _STANDARD_METHODS or "://" in path - if scanner and not _logs_verbose(): - excluded = True - else: - excluded = ( - path in _EXCLUDED_PATHS - or path.startswith("/assets/") - or path.endswith(_EXCLUDED_SUFFIXES) - ) + # 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 @@ -144,12 +147,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/tests/test_log_noise_filters.py b/studio/backend/tests/test_log_noise_filters.py index 33edac4bd0..4203c5b32e 100644 --- a/studio/backend/tests/test_log_noise_filters.py +++ b/studio/backend/tests/test_log_noise_filters.py @@ -84,6 +84,34 @@ def test_normal_404_is_still_logged(logs): 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( diff --git a/unsloth_cli/commands/studio.py b/unsloth_cli/commands/studio.py index 5975e7e355..3eb1ed5d68 100644 --- a/unsloth_cli/commands/studio.py +++ b/unsloth_cli/commands/studio.py @@ -25,10 +25,14 @@ 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" + os.environ.setdefault("LOG_LEVEL", "DEBUG") # Resolve install root: UNSLOTH_STUDIO_HOME, then STUDIO_HOME alias, then From 1e9d4cfe296cfcb80775eef1a26167ad4628082c Mon Sep 17 00:00:00 2001 From: "pre-commit-ci[bot]" <66853113+pre-commit-ci[bot]@users.noreply.github.com> Date: Fri, 26 Jun 2026 08:08:32 +0000 Subject: [PATCH 4/8] [pre-commit.ci] auto fixes from pre-commit.com hooks for more information, see https://pre-commit.ci --- studio/backend/tests/test_log_noise_filters.py | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/studio/backend/tests/test_log_noise_filters.py b/studio/backend/tests/test_log_noise_filters.py index 4203c5b32e..52b956f256 100644 --- a/studio/backend/tests/test_log_noise_filters.py +++ b/studio/backend/tests/test_log_noise_filters.py @@ -88,15 +88,19 @@ 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)) + _run( + LoggingMiddleware(_status_app(200))(_scope("/api/export/status"), _noop_receive, _send) + ) assert logs.events == [] @@ -108,7 +112,11 @@ def test_success_poll_error_is_still_logged(logs): def test_load_progress_poll_suppressed(logs): - _run(LoggingMiddleware(_status_app(200))(_scope("/api/inference/load-progress"), _noop_receive, _send)) + _run( + LoggingMiddleware(_status_app(200))( + _scope("/api/inference/load-progress"), _noop_receive, _send + ) + ) assert logs.events == [] From 9af9c064c503c6e4766e884171a52ca292180ef2 Mon Sep 17 00:00:00 2001 From: Daniel Han Date: Sat, 27 Jun 2026 07:46:19 +0000 Subject: [PATCH 5/8] Studio: throttle repeated progress logs to a ~10s heartbeat Some progress logs are needed but repeat redundantly: during a long model load the inference subprocess streams the same keepalive status (e.g. "Downloading (xet transport)...", "Loading model...") every tick, and the orchestrator logged each one. Add a ProgressThrottle that logs the first message for a key, any time the message changes (a phase change), then at most once per interval while it stays the same; start/completion/errors keep logging at their own sites. - loggers/progress.py: ProgressThrottle (dedupe + heartbeat), verbose-aware, interval via UNSLOTH_STUDIO_PROGRESS_LOG_INTERVAL_S (default 10s; 0 = log all). - core/inference/orchestrator.py: throttle the two "Subprocess status" sites; the deadline reset still runs on every tick (only the log line is throttled); reset the key on load completion so the next load logs immediately. - core/training/training.py: per-step metrics already stream over SSE (not logged per step), so add a throttled progress heartbeat ("step N/M, loss=..., epoch") so training progress is visible in the log without a line per step. - tests/test_progress_throttle.py: first/changed/heartbeat/reset/verbose/zero. --- studio/backend/core/inference/orchestrator.py | 16 +++- studio/backend/core/training/training.py | 16 ++++ studio/backend/loggers/progress.py | 64 +++++++++++++++ .../backend/tests/test_progress_throttle.py | 77 +++++++++++++++++++ 4 files changed, 170 insertions(+), 3 deletions(-) create mode 100644 studio/backend/loggers/progress.py create mode 100644 studio/backend/tests/test_progress_throttle.py diff --git a/studio/backend/core/inference/orchestrator.py b/studio/backend/core/inference/orchestrator.py index f73978db72..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 @@ -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/training/training.py b/studio/backend/core/training/training.py index 9d991c6512..84bcc2a2e8 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 diff --git a/studio/backend/loggers/progress.py b/studio/backend/loggers/progress.py new file mode 100644 index 0000000000..8deee865fa --- /dev/null +++ b/studio/backend/loggers/progress.py @@ -0,0 +1,64 @@ +# 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/tests/test_progress_throttle.py b/studio/backend/tests/test_progress_throttle.py new file mode 100644 index 0000000000..1f48c5a911 --- /dev/null +++ b/studio/backend/tests/test_progress_throttle.py @@ -0,0 +1,77 @@ +# 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 From 5b5a8634452eaafdcd2a137642154a1257df85ff Mon Sep 17 00:00:00 2001 From: "pre-commit-ci[bot]" <66853113+pre-commit-ci[bot]@users.noreply.github.com> Date: Sat, 27 Jun 2026 07:50:11 +0000 Subject: [PATCH 6/8] [pre-commit.ci] auto fixes from pre-commit.com hooks for more information, see https://pre-commit.ci --- studio/backend/loggers/progress.py | 7 +++++-- studio/backend/tests/test_progress_throttle.py | 7 ++++--- 2 files changed, 9 insertions(+), 5 deletions(-) diff --git a/studio/backend/loggers/progress.py b/studio/backend/loggers/progress.py index 8deee865fa..0a136532d9 100644 --- a/studio/backend/loggers/progress.py +++ b/studio/backend/loggers/progress.py @@ -24,7 +24,6 @@ def _interval_default() -> float: def _verbose() -> bool: from loggers.config import logs_verbose - return logs_verbose() @@ -40,7 +39,11 @@ class ProgressThrottle: self._last_msg: dict = {} self._guard = threading.Lock() - def should_log(self, key, message: str = "") -> bool: + def should_log( + self, + key, + message: str = "", + ) -> bool: if self._interval <= 0 or _verbose(): return True now = time.monotonic() diff --git a/studio/backend/tests/test_progress_throttle.py b/studio/backend/tests/test_progress_throttle.py index 1f48c5a911..323a0ce7d6 100644 --- a/studio/backend/tests/test_progress_throttle.py +++ b/studio/backend/tests/test_progress_throttle.py @@ -17,7 +17,7 @@ def _not_verbose(monkeypatch): 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 True # first assert t.should_log(k, "Downloading...") is False # identical repeat within window assert t.should_log(k, "Downloading...") is False @@ -27,11 +27,12 @@ def test_message_change_always_logs(): 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 + 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 @@ -73,5 +74,5 @@ def test_verbose_disables_throttle(monkeypatch): 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("b", "m") is True # different key, independent assert t.should_log("a", "m") is False From 75e0d2573e5128d1177d05808c0025150b8f52dc Mon Sep 17 00:00:00 2001 From: Daniel Han Date: Sat, 27 Jun 2026 08:34:05 +0000 Subject: [PATCH 7/8] Studio: make --verbose a complete escape hatch (force DEBUG, skip dedup) --- studio/backend/loggers/handlers.py | 6 +++++- studio/backend/run.py | 4 +++- .../backend/tests/test_log_noise_filters.py | 19 +++++++++++++++++++ unsloth_cli/commands/studio.py | 3 ++- unsloth_cli/tests/test_studio_verbose_flag.py | 17 +++++++++++++++++ 5 files changed, 46 insertions(+), 3 deletions(-) diff --git a/studio/backend/loggers/handlers.py b/studio/backend/loggers/handlers.py index 32f9bba408..a1c88e7943 100644 --- a/studio/backend/loggers/handlers.py +++ b/studio/backend/loggers/handlers.py @@ -92,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 diff --git a/studio/backend/run.py b/studio/backend/run.py index a40cf72754..4bb1350707 100644 --- a/studio/backend/run.py +++ b/studio/backend/run.py @@ -1374,7 +1374,9 @@ if __name__ == "__main__": # suppression site see it; also restore library/DEBUG logging. if args.verbose: os.environ["UNSLOTH_STUDIO_VERBOSE"] = "1" - os.environ.setdefault("LOG_LEVEL", "DEBUG") + # 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 index 52b956f256..8299aa4b84 100644 --- a/studio/backend/tests/test_log_noise_filters.py +++ b/studio/backend/tests/test_log_noise_filters.py @@ -131,6 +131,25 @@ def test_verbose_keeps_scanner_requests(logs, monkeypatch): 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) ───────────────────────────────────────────── diff --git a/unsloth_cli/commands/studio.py b/unsloth_cli/commands/studio.py index 3eb1ed5d68..e85353014e 100644 --- a/unsloth_cli/commands/studio.py +++ b/unsloth_cli/commands/studio.py @@ -32,7 +32,8 @@ def _enable_verbose_access_logs() -> None: 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" - os.environ.setdefault("LOG_LEVEL", "DEBUG") + # 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 ───────────────────────── From e7df5a38502867c86b68e30c4f00d3e5670332f3 Mon Sep 17 00:00:00 2001 From: Daniel Han Date: Sat, 27 Jun 2026 12:33:28 +0000 Subject: [PATCH 8/8] Studio: evict training progress-throttle key on error/stop, not just complete --- studio/backend/core/training/training.py | 4 ++ .../test_training_progress_throttle_reset.py | 55 +++++++++++++++++++ 2 files changed, 59 insertions(+) create mode 100644 studio/backend/tests/test_training_progress_throttle_reset.py diff --git a/studio/backend/core/training/training.py b/studio/backend/core/training/training.py index 84bcc2a2e8..9d43d14718 100644 --- a/studio/backend/core/training/training.py +++ b/studio/backend/core/training/training.py @@ -1054,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/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