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}")