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.
This commit is contained in:
parent
c8bcacc3fe
commit
63ad2cd38f
9 changed files with 248 additions and 15 deletions
|
|
@ -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()
|
||||
|
|
|
|||
|
|
@ -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,
|
||||
|
|
|
|||
|
|
@ -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:
|
||||
|
|
|
|||
|
|
@ -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)
|
||||
|
|
|
|||
|
|
@ -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)
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
||||
|
|
|
|||
|
|
@ -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:
|
||||
|
|
|
|||
151
studio/backend/tests/test_log_noise_filters.py
Normal file
151
studio/backend/tests/test_log_noise_filters.py
Normal file
|
|
@ -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
|
||||
|
|
@ -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}")
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue