From f6c548856606c915a6fef7a46cbf0e9bca47b13e Mon Sep 17 00:00:00 2001 From: npeter83 Date: Thu, 11 Jun 2026 04:26:18 +0200 Subject: [PATCH] chore: structured timestamped logging across the backend MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - uvicorn --log-config (log_config.json): timestamped formatters for uvicorn access/error and the app's own "subfeed" loggers (ms precision) - Log key activity: startup/shutdown, login/denied, token refresh, YouTube API errors, subscription imports, sync pause/resume - Background sync jobs no longer swallow errors silently — failures in RSS poll, backfill, enrichment, autotag and resync are logged with tracebacks --- backend/app/auth.py | 5 ++++ backend/app/main.py | 17 +++++++++---- backend/app/state.py | 5 ++++ backend/app/sync/autotag.py | 4 ++++ backend/app/sync/runner.py | 8 +++++++ backend/app/sync/subscriptions.py | 7 +++++- backend/app/youtube/client.py | 5 ++++ backend/entrypoint.sh | 2 +- backend/log_config.json | 40 +++++++++++++++++++++++++++++++ 9 files changed, 86 insertions(+), 7 deletions(-) create mode 100644 backend/log_config.json diff --git a/backend/app/auth.py b/backend/app/auth.py index 9eab05c..1466c72 100644 --- a/backend/app/auth.py +++ b/backend/app/auth.py @@ -1,3 +1,4 @@ +import logging from datetime import datetime, timezone from authlib.integrations.starlette_client import OAuth, OAuthError @@ -14,6 +15,8 @@ from app.security import encrypt # (unsubscribe, playlist export). openid/email/profile give us the account identity. SCOPES = "openid email profile https://www.googleapis.com/auth/youtube" +log = logging.getLogger("subfeed.auth") + router = APIRouter(prefix="/auth", tags=["auth"]) oauth = OAuth() @@ -53,6 +56,7 @@ async def callback(request: Request, db: Session = Depends(get_db)): email = (userinfo.get("email") or "").lower() if not email or email not in settings.allowed_email_set: + log.warning("Login denied (not on invite list): %s", email or "") raise HTTPException( status_code=403, detail="This Google account is not on the invite list." ) @@ -81,6 +85,7 @@ async def callback(request: Request, db: Session = Depends(get_db)): db.commit() request.session["user_id"] = user.id + log.info("Login: %s (id=%s, role=%s)", email, user.id, user.role) return RedirectResponse(url="/") diff --git a/backend/app/main.py b/backend/app/main.py index 07c3e45..9690916 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -5,15 +5,20 @@ from pathlib import Path from fastapi import FastAPI, HTTPException -# Make our own loggers (e.g. the scheduler) visible in container logs — uvicorn's -# logging config otherwise filters out INFO from non-uvicorn loggers. +# When started via uvicorn --log-config the "subfeed" logger is already configured +# (see log_config.json). This block is a timestamped fallback for other entrypoints +# (tests, scripts) so our logs are never silently dropped. _subfeed_logger = logging.getLogger("subfeed") if not _subfeed_logger.handlers: _handler = logging.StreamHandler(sys.stdout) - _handler.setFormatter(logging.Formatter("%(levelname)s [%(name)s] %(message)s")) + _handler.setFormatter( + logging.Formatter("%(asctime)s %(levelname)-5s [%(name)s] %(message)s") + ) _subfeed_logger.addHandler(_handler) -_subfeed_logger.setLevel(logging.INFO) -_subfeed_logger.propagate = False + _subfeed_logger.setLevel(logging.INFO) + _subfeed_logger.propagate = False + +log = logging.getLogger("subfeed.app") from fastapi.middleware.cors import CORSMiddleware from fastapi.responses import FileResponse from fastapi.staticfiles import StaticFiles @@ -27,10 +32,12 @@ from app.scheduler import shutdown_scheduler, start_scheduler @asynccontextmanager async def lifespan(app: FastAPI): + log.info("Subfeed starting up") start_scheduler() try: yield finally: + log.info("Subfeed shutting down") shutdown_scheduler() diff --git a/backend/app/state.py b/backend/app/state.py index 3434e48..ad85e19 100644 --- a/backend/app/state.py +++ b/backend/app/state.py @@ -1,8 +1,12 @@ """Global admin-controlled app state (e.g. pausing background sync).""" +import logging + from sqlalchemy.orm import Session from app.models import AppState +log = logging.getLogger("subfeed.state") + def _row(db: Session) -> AppState: row = db.get(AppState, 1) @@ -22,3 +26,4 @@ def set_sync_paused(db: Session, paused: bool) -> None: row.sync_paused = paused db.add(row) db.commit() + log.info("Background sync %s", "paused" if paused else "resumed") diff --git a/backend/app/sync/autotag.py b/backend/app/sync/autotag.py index f6023a7..e10db9e 100644 --- a/backend/app/sync/autotag.py +++ b/backend/app/sync/autotag.py @@ -5,11 +5,14 @@ detection over a sample of recent video titles. Topics are mapped from YouTube's topicDetails categories and the channel's dominant video category. System tags are regenerated freely; user tags are never touched here. """ +import logging import re from sqlalchemy import and_, exists, func, select from sqlalchemy.orm import Session +log = logging.getLogger("subfeed.autotag") + from app.config import settings from app.models import Channel, ChannelTag, Tag, Video @@ -273,6 +276,7 @@ def run_autotag_all(db: Session, only_missing: bool = False) -> dict: tagged += 1 except Exception: db.rollback() + log.exception("Auto-tagging failed for channel %s", channel.id) removed = _cleanup_orphan_system_tags(db) return {"channels_tagged": tagged, "orphan_tags_removed": removed} diff --git a/backend/app/sync/runner.py b/backend/app/sync/runner.py index c20de95..a8f87c9 100644 --- a/backend/app/sync/runner.py +++ b/backend/app/sync/runner.py @@ -4,11 +4,15 @@ Channel/video data is shared across users, so background work acts through a "se user" (any user with a stored refresh token) unless a YOUTUBE_API_KEY is configured for public reads. """ +import logging + from sqlalchemy import select from sqlalchemy.orm import Session from app import quota from app.config import settings + +log = logging.getLogger("subfeed.sync") from app.models import Channel, OAuthToken, User from app.sync.subscriptions import import_subscriptions from app.sync.videos import ( @@ -43,6 +47,7 @@ def run_rss_poll(db: Session, channels: list[Channel] | None = None) -> int: new += poll_rss_channel(db, channel) except Exception: db.rollback() + log.exception("RSS poll failed for channel %s", channel.id) return new @@ -83,6 +88,7 @@ def run_subscription_resync(db: Session) -> dict: import_subscriptions(db, user) except Exception: db.rollback() + log.exception("Subscription resync failed for user %s", user.id) return {"users": len(users)} @@ -111,6 +117,7 @@ def run_recent_backfill( processed += 1 except Exception: db.rollback() + log.exception("Recent backfill failed for channel %s", channel.id) return {"channels_processed": processed, "videos_added": videos_added} @@ -139,4 +146,5 @@ def run_deep_backfill(db: Session, max_channels: int = 10, max_pages: int = 5) - processed += 1 except Exception: db.rollback() + log.exception("Deep backfill failed for channel %s", channel.id) return {"channels_processed": processed, "videos_added": videos_added} diff --git a/backend/app/sync/subscriptions.py b/backend/app/sync/subscriptions.py index 653eba1..9c139e3 100644 --- a/backend/app/sync/subscriptions.py +++ b/backend/app/sync/subscriptions.py @@ -1,4 +1,5 @@ """Import the authenticated user's YouTube subscriptions and channel metadata.""" +import logging from datetime import datetime, timezone from sqlalchemy import select @@ -7,6 +8,8 @@ from sqlalchemy.orm import Session from app.models import Channel, Subscription, User from app.youtube.client import YouTubeClient, best_thumbnail +log = logging.getLogger("subfeed.sync") + def _to_int(value) -> int | None: try: @@ -107,9 +110,11 @@ def import_subscriptions(db: Session, user: User) -> dict: detailed = len(items) db.commit() - return { + result = { "subscriptions": len(fetched), "channels_new": new_channels, "channels_detailed": detailed, "removed_stale": removed, } + log.info("Subscription import (user %s): %s", user.id, result) + return result diff --git a/backend/app/youtube/client.py b/backend/app/youtube/client.py index 87305cd..274861c 100644 --- a/backend/app/youtube/client.py +++ b/backend/app/youtube/client.py @@ -5,6 +5,7 @@ Public reads (channels/videos/playlistItems) use the configured API key when ava so they don't depend on a specific user's token; subscriptions.list?mine=true always uses OAuth. """ +import logging from collections.abc import Iterator from datetime import datetime, timedelta, timezone @@ -15,6 +16,8 @@ from app.config import settings from app.models import User from app.security import decrypt +log = logging.getLogger("subfeed.youtube") + GOOGLE_TOKEN_URL = "https://oauth2.googleapis.com/token" API_BASE = "https://www.googleapis.com/youtube/v3" @@ -76,6 +79,7 @@ class YouTubeClient: tok.expiry = now + timedelta(seconds=int(data.get("expires_in", 3600))) self.db.add(tok) self.db.commit() + log.info("Refreshed access token for user %s", self.user.id) return tok.access_token # --- core request --- @@ -89,6 +93,7 @@ class YouTubeClient: resp = self._http.get(f"{API_BASE}/{path}", params=p, headers=headers) quota.record_usage(self.db, cost) if resp.status_code != 200: + log.warning("YouTube API %s -> %s: %s", path, resp.status_code, resp.text[:200]) raise YouTubeError(f"GET {path} -> {resp.status_code}: {resp.text[:300]}") return resp.json() diff --git a/backend/entrypoint.sh b/backend/entrypoint.sh index 5d0809a..a340cf4 100644 --- a/backend/entrypoint.sh +++ b/backend/entrypoint.sh @@ -5,4 +5,4 @@ echo "Applying database migrations..." alembic upgrade head echo "Starting Subfeed API..." -exec uvicorn app.main:app --host 0.0.0.0 --port 8000 +exec uvicorn app.main:app --host 0.0.0.0 --port 8000 --log-config log_config.json diff --git a/backend/log_config.json b/backend/log_config.json new file mode 100644 index 0000000..47f8c1b --- /dev/null +++ b/backend/log_config.json @@ -0,0 +1,40 @@ +{ + "version": 1, + "disable_existing_loggers": false, + "formatters": { + "default": { + "()": "uvicorn.logging.DefaultFormatter", + "fmt": "%(asctime)s %(levelprefix)s [%(name)s] %(message)s" + }, + "access": { + "()": "uvicorn.logging.AccessFormatter", + "fmt": "%(asctime)s %(levelprefix)s %(client_addr)s - \"%(request_line)s\" %(status_code)s" + }, + "plain": { + "format": "%(asctime)s %(levelname)-5s [%(name)s] %(message)s" + } + }, + "handlers": { + "default": { + "class": "logging.StreamHandler", + "formatter": "default", + "stream": "ext://sys.stdout" + }, + "access": { + "class": "logging.StreamHandler", + "formatter": "access", + "stream": "ext://sys.stdout" + }, + "plain": { + "class": "logging.StreamHandler", + "formatter": "plain", + "stream": "ext://sys.stdout" + } + }, + "loggers": { + "uvicorn": { "handlers": ["default"], "level": "INFO", "propagate": false }, + "uvicorn.error": { "handlers": ["default"], "level": "INFO", "propagate": false }, + "uvicorn.access": { "handlers": ["access"], "level": "INFO", "propagate": false }, + "subfeed": { "handlers": ["plain"], "level": "INFO", "propagate": false } + } +}