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.
This commit is contained in:
+24
-1
@@ -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:
|
||||
|
||||
@@ -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:
|
||||
|
||||
@@ -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}
|
||||
|
||||
@@ -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 "<none>"
|
||||
|
||||
|
||||
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 {
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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]
|
||||
Reference in New Issue
Block a user