From 0cff964ff253dd0a659c31fa4dc1dbc106a15430 Mon Sep 17 00:00:00 2001 From: npeter83 Date: Fri, 18 Sep 2026 00:57:57 +0200 Subject: [PATCH] refactor(logs): name every logger after its module, and hold it there MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 25 literal names covered 34 modules. plex/client.py, plex/stream.py, plex/subtitles.py, plex/sync.py and two Plex route modules all called themselves `siftlode.plex`; downloads/pipeline.py called itself `siftlode.worker`; routes/channels.py called itself `siftlode.api`. The `logger` column is in every stored row so E22.6's console can filter on it, and so an operator can pin a level to one part of the system — neither works when six modules share a name. `logs.get_logger(__name__)` derives it: app/plex/sync.py -> siftlode.plex.sync. One name per module, and it cannot drift from the file it sits in. tests/test_logger_names.py pins the derivation, that everything stays under the one `siftlode` tree the handler and the tests attach to, and that no module hand-rolls a name again unless the line says why (`# logger-name-ok: `). Two do: get_logger's own call, and `siftlode.http`, which is named for the traffic it carries rather than the module it lives in — it replaced uvicorn's access log and is what an operator pins when they want request lines and nothing else. app/scheduler.py called its logger `logger`; every other module calls it `log`. ruff gains LOG, G, T20, TRY400, TRY401 and S112. Four findings cleared with them: worker.py logged `str(exc)[:120]` where the traceback was the whole question, and three prints/f-strings that are deliberate now say so on the line. S110 and BLE001 stay off until S3 — 23 handlers are outstanding and each is a judgement about one of them; enabling the rules first would just mean 23 blanket noqas. --- backend/app/auth.py | 4 +- backend/app/downloads/backfill.py | 4 +- backend/app/downloads/credentials.py | 4 +- backend/app/downloads/edit.py | 8 +-- backend/app/downloads/gc.py | 6 +-- backend/app/downloads/pipeline.py | 5 +- backend/app/downloads/runner.py | 9 ++-- backend/app/email.py | 6 +-- backend/app/logs.py | 21 +++++++- backend/app/logsink.py | 10 ++-- backend/app/main.py | 4 +- backend/app/plex/client.py | 5 +- backend/app/plex/stream.py | 6 +-- backend/app/plex/subtitles.py | 5 +- backend/app/plex/sync.py | 6 +-- backend/app/plex/tmdb.py | 6 +-- backend/app/plex/watch_sync.py | 6 +-- backend/app/realtime.py | 4 +- backend/app/routes/channels.py | 5 +- backend/app/routes/plex/_shared.py | 5 +- backend/app/routes/plex/people.py | 4 +- backend/app/routes/search.py | 4 +- backend/app/scheduler.py | 22 ++++---- backend/app/state.py | 5 +- backend/app/sync/autotag.py | 7 ++- backend/app/sync/explore.py | 5 +- backend/app/sync/maintenance.py | 6 +-- backend/app/sync/playlists.py | 6 +-- backend/app/sync/runner.py | 2 +- backend/app/sync/subscriptions.py | 4 +- backend/app/sysconfig.py | 6 +-- backend/app/worker.py | 15 +++--- backend/app/youtube/client.py | 4 +- backend/ruff.toml | 15 ++++++ backend/tests/test_logger_names.py | 79 ++++++++++++++++++++++++++++ backend/tests/test_logsink.py | 4 +- scripts/e2e_seed.py | 3 +- 37 files changed, 204 insertions(+), 116 deletions(-) create mode 100644 backend/tests/test_logger_names.py diff --git a/backend/app/auth.py b/backend/app/auth.py index 2dae04ba..ab9bd6ac 100644 --- a/backend/app/auth.py +++ b/backend/app/auth.py @@ -1,5 +1,3 @@ -import logging - import httpx from fastapi import BackgroundTasks, Depends, HTTPException, Request from sqlalchemy import delete, func, select @@ -39,7 +37,7 @@ READ_SCOPES = f"{BASE_SCOPES} {READ_SCOPE}" WRITE_SCOPES = f"{BASE_SCOPES} {READ_SCOPE} {WRITE_SCOPE}" _YOUTUBE_SCOPES = frozenset({READ_SCOPE, WRITE_SCOPE}) -log = logging.getLogger("siftlode.auth") +log = logs.get_logger(__name__) def google_enabled(db: Session) -> bool: diff --git a/backend/app/downloads/backfill.py b/backend/app/downloads/backfill.py index b4de7c6a..ef17ed03 100644 --- a/backend/app/downloads/backfill.py +++ b/backend/app/downloads/backfill.py @@ -11,12 +11,12 @@ Run once per environment: docker exec siftlode-worker-1 python -c "from app.downloads import backfill; print(backfill.run())" """ -import logging from urllib.parse import urlsplit import yt_dlp from sqlalchemy import select +from app import logs from app.config import settings from app.db import SessionLocal from app.downloads import adapters @@ -24,7 +24,7 @@ from app.downloads import edit as editmod from app.downloads import formats, service from app.models import MediaAsset -log = logging.getLogger("siftlode.backfill") +log = logs.get_logger(__name__) def _extract_meta(url: str, adapter: adapters.SourceAdapter, asset_id: int) -> dict | None: diff --git a/backend/app/downloads/credentials.py b/backend/app/downloads/credentials.py index c3e20ebb..bce4ca4c 100644 --- a/backend/app/downloads/credentials.py +++ b/backend/app/downloads/credentials.py @@ -23,19 +23,19 @@ Security controls enforced here: logged, or written to a job's error/snapshot. """ -import logging import os from pathlib import Path from sqlalchemy import select from sqlalchemy.orm import Session +from app import logs from app.downloads import formats from app.downloads.adapters import _host_is from app.models import DownloadCredential, MediaAsset from app.security import decrypt_optional, encrypt -log = logging.getLogger("siftlode.downloads.credentials") +log = logs.get_logger(__name__) class HostSpec: diff --git a/backend/app/downloads/edit.py b/backend/app/downloads/edit.py index aabeba7b..161591a9 100644 --- a/backend/app/downloads/edit.py +++ b/backend/app/downloads/edit.py @@ -23,7 +23,6 @@ for a player hover-preview later. import hashlib import json -import logging import math import os import queue @@ -33,9 +32,10 @@ import threading import time from pathlib import Path +from app import logs from app.config import settings -log = logging.getLogger("siftlode.edit") +log = logs.get_logger(__name__) def encode_thread_cap() -> int: @@ -368,7 +368,9 @@ def escalate_kill(proc: subprocess.Popen, terminate, kill, grace_s: float, label try: proc.wait(timeout=grace_s) except subprocess.TimeoutExpired: - log.error("%s pid %s survived SIGKILL", label, proc.pid) + # noqa TRY400: the exception IS the message here. A TimeoutExpired's traceback is this + # `wait` call and nothing else — it would add three frames and no fact the line lacks. + log.error("%s pid %s survived SIGKILL", label, proc.pid) # noqa: TRY400 def _stop(proc: subprocess.Popen) -> None: diff --git a/backend/app/downloads/gc.py b/backend/app/downloads/gc.py index a640c22e..f3a4e6a1 100644 --- a/backend/app/downloads/gc.py +++ b/backend/app/downloads/gc.py @@ -16,7 +16,6 @@ Five passes each run: Runs in the API process (which mounts DOWNLOAD_ROOT). Pure disk/DB work — no YouTube quota. """ -import logging import time from datetime import datetime, timedelta, timezone from pathlib import Path @@ -24,14 +23,13 @@ from pathlib import Path from sqlalchemy import func, select from sqlalchemy.orm import Session -from app import sysconfig +from app import logs, sysconfig from app.config import settings from app.downloads import storage from app.models import DownloadJob, MediaAsset from app.notifications import create_notification -log = logging.getLogger("siftlode.downloads.gc") - +log = logs.get_logger(__name__) # Dot-prefixed top-level trees that are NOT part of the Plex/flat asset layout — the orphan sweep # never touches them (user clips, Plex HLS/img caches, in-progress staging, editor storyboards). _SYSTEM_TREE = {".edits", ".plex-hls", ".plex-img-cache", ".staging", ".storyboards"} diff --git a/backend/app/downloads/pipeline.py b/backend/app/downloads/pipeline.py index 758d2f4f..c9692a84 100644 --- a/backend/app/downloads/pipeline.py +++ b/backend/app/downloads/pipeline.py @@ -1,6 +1,5 @@ """Child-side download/edit pipeline — the yt-dlp download + ffmpeg edit that runs in the spawned subprocess.""" -import logging import re import shutil import time @@ -9,7 +8,7 @@ from pathlib import Path import yt_dlp -from app import sysconfig +from app import logs, sysconfig from app.config import settings from app.db import SessionLocal from app.downloads import edit as editmod @@ -29,7 +28,7 @@ from app.models import DownloadJob, MediaAsset from app.notifications import create_notification from app.titles import normalize_title -log = logging.getLogger("siftlode.worker") +log = logs.get_logger(__name__) class _Aborted(Exception): diff --git a/backend/app/downloads/runner.py b/backend/app/downloads/runner.py index 0e1c70cd..84d04c28 100644 --- a/backend/app/downloads/runner.py +++ b/backend/app/downloads/runner.py @@ -11,7 +11,6 @@ writes the terminal job/asset state itself (done / error, or a cooperative pause progress hook), then exits 0. An unexpected crash exits non-zero and the parent fails the job. """ -import logging import os import shutil import subprocess @@ -24,7 +23,7 @@ from app.db import SessionLocal from app.downloads import edit as editmod from app.models import DownloadJob -log = logging.getLogger("siftlode.worker.runner") +log = logs.get_logger(__name__) def _deprioritize() -> None: @@ -57,7 +56,11 @@ def main() -> None: logs.configure_logging("runner") _deprioritize() if len(sys.argv) != 2: - print("usage: python -m app.downloads.runner ", file=sys.stderr) + # noqa T201: this runs BEFORE configure_logging, and a usage error has to reach the + # operator who typed it whether or not logging was ever set up. + print( # noqa: T201 + "usage: python -m app.downloads.runner ", file=sys.stderr + ) raise SystemExit(2) job_id = int(sys.argv[1]) # This whole process exists to run ONE job — tag every line it prints with it, so the child's diff --git a/backend/app/email.py b/backend/app/email.py index 860a89d5..8b92813a 100644 --- a/backend/app/email.py +++ b/backend/app/email.py @@ -11,7 +11,6 @@ to be a person telling them nothing arrived. """ import html -import logging import re import smtplib import ssl @@ -21,15 +20,14 @@ from email.utils import formatdate from sqlalchemy import select from sqlalchemy.orm import Session -from app import mailtext, sysconfig +from app import logs, mailtext, sysconfig from app.config import settings from app.db import SessionLocal from app.models import User from app.notifications import create_notification from app.ratelimit import RateLimiter -log = logging.getLogger("siftlode.email") - +log = logs.get_logger(__name__) # One admin notice an hour per reason. A relay that is down fails every send, and the inbox must # stay readable; the log keeps the full record either way. _alert_throttle = RateLimiter(max_events=1, window_seconds=3600) diff --git a/backend/app/logs.py b/backend/app/logs.py index 700c6aa6..11fc15b7 100644 --- a/backend/app/logs.py +++ b/backend/app/logs.py @@ -15,7 +15,7 @@ issue attachment will carry, so it is deliberately flat and stable. Call sites stay ordinary stdlib logging: - log = logging.getLogger("siftlode.downloads") + log = logs.get_logger(__name__) # app/downloads/pipeline.py -> siftlode.downloads.pipeline log.info("job finished", extra=logs.event("download.job.done", job_id=7, bytes=n)) `event()` is optional — a bare `log.info("…")` still comes out well-formed — but the dotted code is @@ -401,6 +401,20 @@ _THIRD_PARTY_LEVELS = { } +def get_logger(name: str) -> logging.Logger: + """The logger for one module: `logs.get_logger(__name__)` in `app/plex/sync.py` is + `siftlode.plex.sync`. + + The names were literals before, and 25 of them covered 34 modules — six different Plex modules + all called themselves `siftlode.plex`, so neither a level pinned per logger nor E22.6's console + filter could tell a sync line from a stream line. Derived from `__name__` there is exactly one + name per module, it cannot drift from the file it sits in, and `test_logger_names.py` fails if a + module hand-rolls one again.""" + stem = name.removeprefix("app.") if name.startswith("app.") else "" + # logger-name-ok: this call IS the derivation + return logging.getLogger(f"siftlode.{stem}" if stem else "siftlode") + + def resolve_level(name: str) -> int: """Level name → number. Both ways in (the `LOG_LEVEL` env and the `log_level` admin knob) are already held to the `LogLevel` choices, so an unknown name here is a programming error.""" @@ -566,7 +580,10 @@ _REQUEST_ID_RE = re.compile(r"^[A-Za-z0-9._-]{8,64}$") # A FAILURE on either still logs at WARNING/ERROR — this lowers the floor, it does not hide. _QUIET_PREFIXES = ("/healthz", "/assets/", "/static/") -_request_log = logging.getLogger("siftlode.http") +# Not `siftlode.logs`: this is the replacement for uvicorn's ACCESS log, and `siftlode.http` is +# what an operator pins a level on when they want request lines and nothing else. The module it +# happens to live in is not what the name is about. +_request_log = logging.getLogger("siftlode.http") # logger-name-ok: named for the traffic async def log_requests(request, call_next): diff --git a/backend/app/logsink.py b/backend/app/logsink.py index 444fe5bd..edd65157 100644 --- a/backend/app/logsink.py +++ b/backend/app/logsink.py @@ -66,7 +66,7 @@ _LIMITS = { "exc": 32_000, } -_log = logging.getLogger("siftlode.logsink") +_log = logs.get_logger(__name__) def should_store(record: logging.LogRecord) -> bool: @@ -254,8 +254,12 @@ class LogSink(logging.Handler): with self._bind.connect() as conn, logs.erasure_guard(), conn.begin(): conn.execute(insert(LogEvent), without_erased(rows)) except Exception as exc: # noqa: BLE001 — the database is down or refused the batch - print( - f"log sink: could not store {len(rows)} log events: {logs.redact_text(str(exc))[:300]}", + # noqa T201: the sink's OWN failure. A log call here would be handed to this sink, + # which is the thing that just failed — straight into a loop. stderr is the one way + # out that does not re-enter. + print( # noqa: T201 + f"log sink: could not store {len(rows)} log events: " + f"{logs.redact_text(str(exc))[:300]}", file=sys.stderr, ) return 0 diff --git a/backend/app/main.py b/backend/app/main.py index 27cd1176..d0ebc429 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -1,5 +1,4 @@ import asyncio -import logging import math from contextlib import asynccontextmanager, suppress from pathlib import Path @@ -12,11 +11,12 @@ from fastapi.exceptions import RequestValidationError # import time is already covered. ONE format for the api, the worker, the download child and alembic # alike (app/logs.py) — this replaces the old uvicorn --log-config + the hand-rolled fallback that # used to live here, and uvicorn's access log is replaced by the `http.request` middleware below. +from app import logs from app.logs import configure_logging, current_level, log_requests, set_level configure_logging("api") -log = logging.getLogger("siftlode.app") +log = logs.get_logger(__name__) from fastapi.middleware.cors import CORSMiddleware from fastapi.responses import FileResponse, HTMLResponse, JSONResponse from fastapi.staticfiles import StaticFiles diff --git a/backend/app/plex/client.py b/backend/app/plex/client.py index d3313323..23efb475 100644 --- a/backend/app/plex/client.py +++ b/backend/app/plex/client.py @@ -6,16 +6,15 @@ metadata, image proxying, and (P5) optional watch-state write-back. Requests JSO ``Accept: application/json`` header (Plex serves XML by default). """ -import logging from urllib.parse import quote import httpx from sqlalchemy.orm import Session -from app import sysconfig +from app import logs, sysconfig from app.config import settings -log = logging.getLogger("siftlode.plex") +log = logs.get_logger(__name__) class PlexError(Exception): diff --git a/backend/app/plex/stream.py b/backend/app/plex/stream.py index aec74c3e..db518f02 100644 --- a/backend/app/plex/stream.py +++ b/backend/app/plex/stream.py @@ -18,7 +18,6 @@ segments. The remux is CPU-light (video copy + a tiny audio transcode), so it ru CPU-only prod host; only P3's full transcode is CPU-heavy. """ -import logging import os import re import secrets @@ -31,15 +30,14 @@ from pathlib import Path from sqlalchemy.orm import Session as DbSession -from app import sysconfig +from app import logs, sysconfig from app.config import settings from app.downloads.edit import encode_thread_cap from app.models import PlexItem from app.plex import paths from app.plex.sync import HW_DECODABLE_CODECS -log = logging.getLogger("siftlode.plex") - +log = logs.get_logger(__name__) _HLS_ROOT = ( Path(settings.plex_hls_dir) if settings.plex_hls_dir diff --git a/backend/app/plex/subtitles.py b/backend/app/plex/subtitles.py index 132f476e..c840e687 100644 --- a/backend/app/plex/subtitles.py +++ b/backend/app/plex/subtitles.py @@ -33,7 +33,6 @@ zero-based clock and shifted back to absolute time here with `shift_vtt`. """ import json -import logging import re import subprocess import tempfile @@ -44,6 +43,7 @@ from pathlib import Path from sqlalchemy.orm import Session +from app import logs from app.db import SessionLocal from app.models import PlexItem from app.plex import paths as plex_paths @@ -51,8 +51,7 @@ from app.plex.cache import CACHE_DIR from app.plex.client import PlexClient, PlexError from app.plex.lookups import by_rating_key -log = logging.getLogger("siftlode.plex") - +log = logs.get_logger(__name__) # Image-based subtitle codecs (Blu-ray/DVD) — can't be turned into text WebVTT (would need burn-in). BITMAP_SUBS = { "pgs", diff --git a/backend/app/plex/sync.py b/backend/app/plex/sync.py index a581a4b0..5f1c1934 100644 --- a/backend/app/plex/sync.py +++ b/backend/app/plex/sync.py @@ -15,20 +15,18 @@ dead `enabled` column) is a separate follow-up. Cast + intro/credit markers are item-detail/player path (P2), not here. """ -import logging from datetime import datetime, timezone from sqlalchemy import func, select from sqlalchemy.orm import Session -from app import sysconfig +from app import logs, sysconfig from app.models import PlexCollection, PlexItem, PlexLibrary, PlexSeason, PlexShow from app.plex import detail, people from app.plex.client import PlexClient, PlexError, PlexNotConfigured from app.plex.lookups import by_rating_key -log = logging.getLogger("siftlode.plex") - +log = logs.get_logger(__name__) # Codecs/containers a browser can play in a native