From 3ee00fb0510e91124fc52a2a3c9d7fb1e88f8016 Mon Sep 17 00:00:00 2001 From: npeter83 Date: Sat, 19 Sep 2026 04:51:31 +0200 Subject: [PATCH] fix(logs): keep polling reads and a channel-less account out of the warnings The reads the frontend polls (unread counts, /api/me, the download index, sync status, subtitle progress) are logged at DEBUG: at INFO they were ~95% of the stored log on prod. A scheduler job failure and a playlist sync failure carry event codes, and a Google account without a YouTube channel has an empty playlist list instead of a warning every six hours. --- backend/app/logs.py | 25 +++++++++++++++- backend/app/scheduler.py | 2 +- backend/app/sync/playlists.py | 14 +++++++-- backend/app/youtube/client.py | 35 ++++++++++++++++++---- backend/tests/test_logs.py | 32 ++++++++++++++++++++ backend/tests/test_youtube_no_channel.py | 38 ++++++++++++++++++++++++ 6 files changed, 136 insertions(+), 10 deletions(-) create mode 100644 backend/tests/test_youtube_no_channel.py diff --git a/backend/app/logs.py b/backend/app/logs.py index cfb49e7c..2dbb9979 100644 --- a/backend/app/logs.py +++ b/backend/app/logs.py @@ -644,6 +644,27 @@ _REQUEST_ID_RE = re.compile(r"^[A-Za-z0-9._-]{8,64}$") # — this lowers the floor, it does not hide. _QUIET_PREFIXES = ("/healthz", "/assets/", "/static/", "/api/admin/logs") +# The reads the frontend POLLS (a `useLiveQuery`, the `me` heartbeat, the sync status, the subtitle +# progress), by route template, GET only — logged at DEBUG like the prefixes above. One open tab asked +# for the two unread counts, `/api/me` and the download index every 30 s, and at INFO those were ~95% +# of the stored log (measured on prod 2026-09-19): 11k lines a day per tab burying every line someone +# caused. The same route answered with a failure still logs at WARNING/ERROR. +_POLLED_ROUTES = frozenset( + { + "/api/me", + "/api/me/notifications/unread_count", + "/api/messages/unread_count", + "/api/downloads", + "/api/downloads/index", + "/api/downloads/usage", + "/api/sync/my-status", + "/api/admin/scheduler", + "/api/admin/downloads", + "/api/admin/downloads/storage", + "/api/plex/subtitle/{rating_key}/{sub_ord}/status", + } +) + # 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. @@ -689,7 +710,9 @@ async def log_requests(request, call_next): raise duration_ms = round((time.perf_counter() - started) * 1000, 1) status = response.status_code - quiet = request.url.path.startswith(_QUIET_PREFIXES) + quiet = request.url.path.startswith(_QUIET_PREFIXES) or ( + request.method == "GET" and _route_template(request) in _POLLED_ROUTES + ) if status >= 500: level = logging.ERROR elif status >= 400: diff --git a/backend/app/scheduler.py b/backend/app/scheduler.py index ec2e8309..c3e24d12 100644 --- a/backend/app/scheduler.py +++ b/backend/app/scheduler.py @@ -208,7 +208,7 @@ def _job(name: str, fn) -> None: _audit_run(db, actor_id, name, "ok", summary, result) except Exception as exc: db.rollback() - log.exception("job %s failed", name) + log.exception("job %s failed", name, extra=logs.event("scheduler.job.failed", job=name)) err = str(exc) or exc.__class__.__name__ _record(name, status="error", last_finished=_now_iso(), last_error=err, progress=None) if actor_id is not None: diff --git a/backend/app/sync/playlists.py b/backend/app/sync/playlists.py index 056c7a9d..2a889234 100644 --- a/backend/app/sync/playlists.py +++ b/backend/app/sync/playlists.py @@ -670,11 +670,19 @@ def sync_all_playlists(db: Session) -> dict: try: with quota.attribute(user.id, quota.QuotaAction.PLAYLISTS_PULL): total += sync_user_playlists(db, user).get("synced", 0) - except YouTubeError: + except YouTubeError as exc: db.rollback() - log.warning("Playlist sync failed for user %s", user.id) + log.warning( + "Playlist sync failed for user %s", + user.id, + extra=logs.event("sync.playlists.failed", user_id=user.id, reason=exc.reason), + ) except Exception: db.rollback() - log.exception("Playlist sync crashed for user %s", user.id) + log.exception( + "Playlist sync crashed for user %s", + user.id, + extra=logs.event("sync.playlists.crashed", user_id=user.id), + ) progress.report(i, len(users), "playlist_sync") return {"users": len(users), "playlists_synced": total} diff --git a/backend/app/youtube/client.py b/backend/app/youtube/client.py index 260aff31..2e827c16 100644 --- a/backend/app/youtube/client.py +++ b/backend/app/youtube/client.py @@ -6,6 +6,7 @@ so they don't depend on a specific user's token; subscriptions.list?mine=true al uses OAuth. """ +import logging from collections.abc import Iterator from datetime import datetime, timedelta, timezone @@ -50,7 +51,9 @@ def _error_reason(resp: httpx.Response) -> str: return reasons or "" -def _upstream_failure(method: str, path: str, resp: httpx.Response) -> YouTubeError: +def _upstream_failure( + method: str, path: str, resp: httpx.Response, expected: frozenset[str] = frozenset() +) -> YouTubeError: """Report one upstream failure and build the error to raise. Every YouTube response that is not a success goes through here — the Data API's reads, writes and deletes and the OAuth token refresh — so what may appear in a log line cannot drift apart between them, and the @@ -59,7 +62,11 @@ def _upstream_failure(method: str, path: str, resp: httpx.Response) -> YouTubeEr response at all is `_send`'s, with the reason `transport`.) The body is logged only under the requesting user's own Teljes consent: it is the request quoted back.""" reason = _error_reason(resp) - log.warning( + # A reason the caller named as an answer rather than a failure (`channelNotFound` on a `mine` + # read: the account simply has no channel) is still raised, but it is not a warning — it came + # back every six hours for an account that will never have one. + log.log( + logging.DEBUG if reason in expected else logging.WARNING, "YouTube %s %s -> %s (%s)", method, path, @@ -83,6 +90,10 @@ def _upstream_failure(method: str, path: str, resp: httpx.Response) -> YouTubeEr return YouTubeError(f"{method} {path} -> {resp.status_code}: {reason}", reason=reason) +# The `mine` reads' answer for a Google account that has no YouTube channel. +_NO_CHANNEL = frozenset({"channelNotFound"}) + + def _chunks(items: list, size: int) -> Iterator[list]: for i in range(0, len(items), size): yield items[i : i + size] @@ -167,7 +178,14 @@ class YouTubeClient: return access # --- core request --- - def _get(self, path: str, params: dict, cost: int = 1, allow_key: bool = True) -> dict: + def _get( + self, + path: str, + params: dict, + cost: int = 1, + allow_key: bool = True, + expected: frozenset[str] = frozenset(), + ) -> dict: p = dict(params) headers = {} api_key = sysconfig.get_str(self.db, "youtube_api_key") @@ -178,7 +196,7 @@ class YouTubeClient: resp = self._send("GET", f"{API_BASE}/{path}", params=p, headers=headers) quota.record_usage(cost) if resp.status_code != 200: - raise _upstream_failure("GET", path, resp) + raise _upstream_failure("GET", path, resp, expected) return resp.json() # --- endpoints --- @@ -218,7 +236,14 @@ class YouTubeClient: params = {"part": "snippet,contentDetails", "mine": "true", "maxResults": 50} if page_token: params["pageToken"] = page_token - data = self._get("playlists", params, cost=1, allow_key=False) + try: + data = self._get("playlists", params, cost=1, allow_key=False, expected=_NO_CHANNEL) + except YouTubeError as exc: + # A Google account without a YouTube channel has no playlists, and YouTube says + # so as a 404. That is an empty list, not a failed sync. + if exc.reason in _NO_CHANNEL: + return + raise for item in data.get("items", []): sn = item.get("snippet", {}) yield { diff --git a/backend/tests/test_logs.py b/backend/tests/test_logs.py index a01403fb..ece53423 100644 --- a/backend/tests/test_logs.py +++ b/backend/tests/test_logs.py @@ -219,6 +219,14 @@ def _client() -> TestClient: raise HTTPException(status_code=400, detail={"code": "bad_cursor"}) return {"ok": True} + @app.get("/api/messages/unread_count") + def _unread(): + return {"count": 0} + + @app.post("/api/messages/unread_count") + def _unread_write(): + return {"ok": True} + @app.get("/boom") def _boom(): raise RuntimeError("kaboom") @@ -323,6 +331,30 @@ def test_the_log_consoles_own_reads_are_debug_but_its_failures_are_not(sink): assert sink.objects()[-1]["level"] == "WARNING" +def test_a_polled_read_is_debug_a_write_to_the_same_route_is_not(sink): + # One open tab polled the unread counts, /api/me and the download index every 30 s: at INFO + # that was ~95% of the stored log on prod. + http = logging.getLogger("siftlode.http") + http.setLevel(logs.TRACE) + client = _client() + client.get("/api/messages/unread_count") + assert sink.objects()[-1]["level"] == "DEBUG" + client.post("/api/messages/unread_count") + assert sink.objects()[-1]["level"] == "INFO" + client.get("/api/videos/abc") + assert sink.objects()[-1]["level"] == "INFO" + + +def test_every_polled_route_is_a_route_the_app_has(): + # The list names route TEMPLATES; one renamed on the router side would silently fall back to + # INFO, so the list is held to the app's own routes. + from app.main import app + + # The schema, not `app.routes`: FastAPI 0.141 keeps an included router behind a wrapper there. + gets = {path for path, ops in app.openapi()["paths"].items() if "get" in ops} + assert logs._POLLED_ROUTES - gets == set() + + def test_a_failing_request_is_logged_by_status_and_an_unhandled_error_is_logged_at_all(sink): client = _client() client.get("/api/videos/missing/deeper") # 404 from the router diff --git a/backend/tests/test_youtube_no_channel.py b/backend/tests/test_youtube_no_channel.py new file mode 100644 index 00000000..a3c3d10f --- /dev/null +++ b/backend/tests/test_youtube_no_channel.py @@ -0,0 +1,38 @@ +"""A Google account without a YouTube channel: its `mine` playlists read answers 404 +`channelNotFound`. That is an empty list, not a failed sync — it came back as a warning every six +hours on prod for an account that will never have a channel.""" + +import logging + +import httpx +import pytest + +from app.youtube import client as yt + + +def _client(monkeypatch, status: int, reason: str) -> yt.YouTubeClient: + resp = httpx.Response( + status, + json={"error": {"code": status, "errors": [{"reason": reason, "message": "prose"}]}}, + request=httpx.Request("GET", f"{yt.API_BASE}/playlists"), + ) + c = yt.YouTubeClient.__new__(yt.YouTubeClient) # no HTTP client: `_send` is the stub + c.db = None + monkeypatch.setattr(yt.sysconfig, "get_str", lambda db, key: "") + monkeypatch.setattr(yt.quota, "record_usage", lambda cost: None) + monkeypatch.setattr(c, "_access_token", lambda: "t") + monkeypatch.setattr(c, "_send", lambda *a, **k: resp) + return c + + +def test_no_channel_is_an_empty_playlist_list_and_no_warning(monkeypatch, caplog): + caplog.set_level(logging.DEBUG, logger="siftlode") + assert list(_client(monkeypatch, 404, "channelNotFound").iter_my_playlists()) == [] + assert not [r for r in caplog.records if r.levelno >= logging.WARNING] + + +def test_any_other_failure_still_raises_and_warns(monkeypatch, caplog): + caplog.set_level(logging.DEBUG, logger="siftlode") + with pytest.raises(yt.YouTubeError): + list(_client(monkeypatch, 403, "quotaExceeded").iter_my_playlists()) + assert [r for r in caplog.records if r.levelno == logging.WARNING]