chore: structured timestamped logging across the backend

- 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

@@ -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 "<no email>")
         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="/")
 
 

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
+# When started via uvicorn --log-config the "subfeed" logger is already configured
-# logging config otherwise filters out INFO from non-uvicorn loggers.
+# (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.setLevel(logging.INFO)
-_subfeed_logger.propagate = False
+    _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()
 
 

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")

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}
 

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}

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

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()
 

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

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 }
+  }
+}