a6aa4fff10* Studio: exclude /api/export/status from request access logs The frontend polls /api/export/status every 5s to detect export start, so it fires continuously even when idle. Each poll emitted an info request_completed access line, making up most of the server access logs. Add it to _EXCLUDED_PATHS alongside /api/train/status. The endpoint is unchanged; export state is still logged by the export modules and streamed over SSE, so no signal is lost. * Studio: collapse hub download-progress polls in the access log download-status and gguf-download-progress (plus the dataset equivalents) are polled about twice a second for the whole download, so each emitted an info request_completed line. Add them to _QUIET_POLL_PATHS so they collapse to one heartbeat line per 10s instead of one per poll. * Studio: log hub download progress at 10% steps The access log carried no real progress, only poll pings. Emit one hub_download_progress line per 10% step from the shared snapshot progress reader, so an active download shows actual percentage without a line per poll. Throttled per job and resynced if the same download restarts. * [pre-commit.ci] auto fixes from pre-commit.com hooks for more information, see https://pre-commit.ci * Studio: drop successful chat thread/project CRUD from the access log A single chat turn fans out about twenty requests under /api/chat/threads and /api/chat/projects (list, fetch, per-message forks, and the message writes) that only reflect the UI re-rendering. Suppress their 2xx access line so the log keeps the signal (generation, tool calls, code execution, engine stats) and errors. Non-2xx on these paths still log. * Studio: silence transformers torch_dtype deprecation warning transformers logs "`torch_dtype` is deprecated! Use `dtype` instead!" once at model-config load via logger.warning_once (logging, not warnings), so a warnings filter cannot catch it. Attach a small logging.Filter in setup_logging, which runs before any model config is parsed, to drop that record on the transformers loggers that emit it. * Studio: quiet inference load-progress polls and log throttled load progress The frontend polls /api/inference/load-progress about twice a second for the whole model load, so each emitted a request_completed line. Add it to _QUIET_POLL_PATHS (heartbeat) and emit one inference_load_progress line per 10% step from the load-progress route, so a load shows real percentage instead of a line per poll. * Studio: fully suppress download/load progress poll access lines The download-status, download-progress, gguf-download-progress, active-downloads and transport-status polls (model and dataset), plus inference load-progress, fire ~2x/s for the whole download or load. Their progress is now reported by the hub_download_progress / inference_load_progress events (and the viewer's progress line), so the per-poll access line adds nothing. Drop it on 2xx and keep it on errors, instead of the prior 10s heartbeat. Chat CRUD suppression is folded into the same _is_quiet_success helper. * Studio: suppress training-tab model/dataset download-progress polls The training tab polls /api/models/download-progress and /api/datasets/download-progress about twice a second for the whole prep phase. These are separate routes from the /api/hub equivalents and only scan the cache, so their 2xx access line adds nothing (on Windows they always read 0 since the bytes live in snapshots/, not blobs/). Suppress the 2xx line and keep errors, alongside /api/models/gguf-download-progress. * Studio: drop transient pre-auth 401 on chat thread/project polls On first load the SPA fires chat thread/project GETs before the initial token refresh, so they 401 until /api/auth/refresh runs and the retries succeed. That pre-auth 401 is a bootstrap artifact, not an error; suppress it alongside the already-quiet 2xx line. Genuine 4xx/5xx on these paths, the download/load poll 401s, and all /api/auth/* still log. * Studio: quiet tab-switch list polls and per-poll scan/reconnect logs Switching between the Train, Export, and Chat tabs refetches list endpoints on a timer, and each hit re-logs internal detail. Heartbeat /api/train/runs, /api/models/checkpoints, /api/models/local and /api/rag/knowledge-bases (10s window, first hit and errors still log), and downgrade two per-poll INFO lines to debug: the checkpoints scan summary ("Found N training runs") and the per-reconnect SSE resume line. The meaningful "replayed N missed steps" line, logged only when steps were actually replayed, stays at info. * Studio: enable tokenizer parallelism for dataset prep on Windows/macOS TOKENIZERS_PARALLELISM was forced off everywhere to stop datasets' forked map() workers from deadlocking, but that fork only happens on Linux. On spawn platforms (Windows/macOS) dataset.map() runs in-process (dataset_map_num_proc returns None), so disabling tokenizer parallelism leaves the fast tokenizer single-threaded and dataset prep runs serially on one core. Keep it off on Linux (fork safety) and on for spawn platforms, where there is no fork to deadlock. Measured ~7x faster tokenization (12.5s -> 1.7s for 20k rows on a 32-core Windows box). * [pre-commit.ci] auto fixes from pre-commit.com hooks for more information, see https://pre-commit.ci * Studio: log throttled training status to the server log Training step/loss/epoch only went to the UI via SSE, so the server log showed inference engine_stats and train/runs heartbeats but nothing about the actual run. Emit one throttled training_progress line (step/total, percent, loss, epoch, eta) from the CUDA event pump: the first step, then at most every 30s, plus the final step, resyncing when a new run restarts the counter. Per-step UI streaming is unchanged. * Studio: quiet llama.cpp update-status polls and log throttled update progress The prebuilt llama.cpp update polls /api/llama/update-status about twice a second for the whole download and install. Suppress its 2xx access line (errors still log) and emit one throttled llama_update_progress line per 10% step from the status route, so the update shows progress without a line per poll. The existing "llama update: installing" and "llama update: success" events still bracket it. * Studio: quiet the export log-tail poll The Export tab polls /api/export/logs about once a second to stream the export subprocess output into the UI panel. Suppress its 2xx access line; the real progress is already logged as event-driven "Export subprocess status: <phase>" lines plus the subprocess start and checkpoint-loaded events, and errors still log. * studio: keep errors and mutations visible in access-log suppression Make the quiet-success access-log suppression GET-only so chat thread/project mutations (POST/PUT/DELETE) still log; only their list-poll 2xx and the transient pre-auth 401 are dropped. Suppress /api/export/status 2xx only (move it out of the all-status exclude set) so a 401/403/500 on it stays visible. Legacy /api/models and /api/datasets download-progress polls emit no hub_download_progress events, so heartbeat them via the 10s quiet-poll window instead of suppressing outright, keeping download visibility (notably on Linux). The event-emitting /api/hub download polls stay fully suppressed. Update and extend the middleware tests to cover GET-only suppression, the export-status error path, and the legacy download heartbeat. * [pre-commit.ci] auto fixes from pre-commit.com hooks for more information, see https://pre-commit.ci * studio: tighten access-log and training-progress comments Comment-only pass: collapse the multi-line explanations in the logging middleware and the throttled training-progress logger to fewer lines while keeping the rationale. No behavior change. * studio: log structured export_progress phases Emit a structured export_progress event per phase (consolidated in the server log like training and download progress) instead of a plain status string, and add a phase milestone at the start of the heavy export step so the merge/save/convert is visible in the server log, not only in the forwarded stdout panel. * Studio: reset training-progress log throttle on each new run start_training rebuilds the per-run progress state but left _last_progress_log_ts/_last_progress_log_step at their prior values. A run started within 30s of a previous one whose last logged step matched the new run's first step would hit the step == prev short-circuit and drop the promised first training_progress line, then stay suppressed until the old 30s window expired. Reset both fields when a new job is accepted. * Studio: keep post-bootstrap chat 401s visible in the access log The chat thread/project 401 suppression dropped every GET 401 on those prefixes, so a genuine expired-session 401 vanished alongside the transient pre-auth race. Gate the 401 drop on a per-middleware bootstrap latch that flips once /api/auth/refresh first succeeds: before that the 401s are the pre-refresh race and are suppressed; after it any chat 401 is a real failure and logs. Add a test for the post-refresh case. * [pre-commit.ci] auto fixes from pre-commit.com hooks for more information, see https://pre-commit.ci * Studio: limit chat access-log suppression to the exact list polls The chat thread/project suppression matched by startswith, so it also dropped the 2xx access line for detail and message reads (/threads/{id}, /threads/{id}/messages, /threads/{id}/messages/{id}, /projects/{id}) that are not the high-frequency list polls, losing their access and latency logging. Match the two list paths exactly instead, so only the intended list polls (and their pre-auth 401 race) are suppressed while detail and message reads keep their access line. Add a regression test. * Studio: reset inference load-progress throttle for each load The load-progress throttle (_last_load_progress_step) is a module global that persisted across loads, so a cached or small load whose first sampled /api/inference/load-progress response already reported fraction=1.0 hit step == prev (10) from a prior completed load and emitted no inference_load_progress line, while that endpoint's access log is suppressed, leaving the new load with no progress signal. Arm the throttle at load initiation in _load_model_impl so each load's first step always logs. Add a regression test. * Studio: tighten logging comments Collapse a few verbose comments (tokenizer-parallelism note, torch_dtype filter, legacy download-poll heartbeat, chat list-path suppression) to fewer lines without changing intent or code. --------- Co-authored-by: pre-commit-ci[bot] <66853113+pre-commit-ci[bot]@users.noreply.github.com>
93 lines
3.7 KiB
Python
93 lines
3.7 KiB
Python
# SPDX-License-Identifier: AGPL-3.0-only
|
|
# Copyright 2026-present the Unsloth AI Inc. team. All rights reserved. See /studio/LICENSE.AGPL-3.0
|
|
|
|
"""Structured logging configuration via structlog.
|
|
|
|
Environment-specific formats (JSON for prod, console for dev), ISO timestamps,
|
|
context-var integration, log-level filtering, and logger caching.
|
|
"""
|
|
|
|
import logging
|
|
import os
|
|
import sys
|
|
from typing import Optional
|
|
|
|
import structlog
|
|
|
|
from loggers.handlers import filter_sensitive_data
|
|
|
|
|
|
class _DropTorchDtypeDeprecation(logging.Filter):
|
|
"""Drop transformers' once-per-run "`torch_dtype` is deprecated" warning_once.
|
|
It is emitted via logging (not warnings), so a warnings filter cannot catch it."""
|
|
|
|
def filter(self, record: logging.LogRecord) -> bool:
|
|
msg = record.getMessage()
|
|
return not ("torch_dtype" in msg and "deprecated" in msg)
|
|
|
|
|
|
class LogConfig:
|
|
"""Structured logging configuration for the application."""
|
|
|
|
@staticmethod
|
|
def setup_logging(
|
|
service_name: str = "unsloth-studio-backend", env: Optional[str] = None
|
|
) -> structlog.BoundLogger:
|
|
"""Configure structured logging for the application.
|
|
Args:
|
|
service_name: Name of the service for logging identification
|
|
env: Environment (development/production), affects logging format
|
|
"""
|
|
# Log level from environment; fall back to INFO if invalid.
|
|
log_level_name = os.getenv("LOG_LEVEL", "INFO").upper()
|
|
log_level = getattr(logging, log_level_name, logging.INFO)
|
|
|
|
if sys.platform == "win32":
|
|
for stream in (sys.stdout, sys.stderr):
|
|
if hasattr(stream, "reconfigure"):
|
|
try:
|
|
stream.reconfigure(encoding = "utf-8", errors = "replace")
|
|
except Exception:
|
|
pass
|
|
|
|
structlog.configure(
|
|
processors = [
|
|
# Ordered to control output field order.
|
|
structlog.processors.TimeStamper(fmt = "iso"), # timestamp first
|
|
structlog.processors.add_log_level, # level second
|
|
structlog.contextvars.merge_contextvars,
|
|
structlog.processors.format_exc_info,
|
|
filter_sensitive_data,
|
|
# Flatten the extra field into the main dict.
|
|
lambda logger, method_name, event_dict: {
|
|
"timestamp": event_dict.get("timestamp"),
|
|
"level": event_dict.get("level"),
|
|
"event": event_dict.get("event"),
|
|
**(event_dict.get("extra", {})), # Flatten extra into main dict
|
|
**{
|
|
k: v
|
|
for k, v in event_dict.items()
|
|
if k not in ["timestamp", "level", "event", "extra"]
|
|
},
|
|
},
|
|
(
|
|
structlog.processors.JSONRenderer(sort_keys = False) # Preserve order
|
|
if env == "production"
|
|
else structlog.dev.ConsoleRenderer()
|
|
),
|
|
],
|
|
wrapper_class = structlog.make_filtering_bound_logger(log_level),
|
|
logger_factory = structlog.PrintLoggerFactory(file = sys.stdout),
|
|
cache_logger_on_first_use = True,
|
|
)
|
|
|
|
# Drop transformers' cosmetic "`torch_dtype` is deprecated" warning_once (see filter).
|
|
_dtype_filter = _DropTorchDtypeDeprecation()
|
|
for _name in (
|
|
"transformers.configuration_utils",
|
|
"transformers.modeling_utils",
|
|
"transformers.pipelines.base",
|
|
):
|
|
logging.getLogger(_name).addFilter(_dtype_filter)
|
|
|
|
return structlog.get_logger(service_name)
|