feat: better first time downloading, feat: more logging

progression_backend/refresh.py

@@ -1,8 +1,10 @@
 from __future__ import annotations
 
 import asyncio
+import logging
 import time
 import uuid
+from collections.abc import Callable
 from datetime import datetime, timedelta, timezone
 from typing import Any
 
@@ -12,6 +14,14 @@ from .steam_api import SteamWorkshopClient, WorkshopDetails
 from .workshop import SteamCmdRunner, directory_size, parse_about_xml, utc_now
 
 
+logger = logging.getLogger("uvicorn.error")
+ProgressCallback = Callable[[dict[str, Any]], None]
+
+
+class InitialDownloadTimeout(RuntimeError):
+    pass
+
+
 def _batches(values: list[str], size: int) -> list[list[str]]:
     return [values[index : index + size] for index in range(0, len(values), size)]
 
@@ -33,6 +43,16 @@ class RefreshService:
             settings.steamcmd_timeout_seconds,
         )
 
+    def needs_initial_download(self) -> bool:
+        rows = self.database.current_mods()
+        if not rows:
+            return True
+        return any(
+            row.get("status") != "ready"
+            or not (self.settings.workshop_content_dir / row["workshop_id"]).is_dir()
+            for row in rows
+        )
+
     def _store_metadata(
         self,
         detail: WorkshopDetails,
@@ -104,9 +124,22 @@ class RefreshService:
                 "last_downloaded_at": utc_now() if downloaded else None,
             }
 
-    def refresh(self, run_id: str, trigger: str) -> None:
+    def refresh(
+        self,
+        run_id: str,
+        trigger: str,
+        *,
+        initial_download: bool = False,
+        overall_timeout_seconds: int | None = None,
+        progress: ProgressCallback | None = None,
+    ) -> None:
         started_at = utc_now()
         started = time.monotonic()
+        deadline = (
+            started + overall_timeout_seconds
+            if initial_download and overall_timeout_seconds is not None
+            else None
+        )
         self.database.create_run(run_id, trigger, started_at)
         metrics: dict[str, Any] = {
             "collection_items": 0,
@@ -123,7 +156,24 @@ class RefreshService:
             "error": None,
         }
 
+        def report(**values: Any) -> None:
+            if progress:
+                progress(values)
+
+        def remaining_time() -> float | None:
+            if deadline is None:
+                return None
+            remaining = deadline - time.monotonic()
+            if remaining <= 0:
+                raise InitialDownloadTimeout(
+                    "The initial Workshop download reached its "
+                    f"{overall_timeout_seconds}-second limit"
+                )
+            return remaining
+
         try:
+            report(stage="collections", completed_mods=0, total_mods=0, percent=0.0)
+            remaining_time()
             collection_ids = list(self.settings.collections.values())
             response = self.steam.get_collections(collection_ids)
             named_collections: dict[str, tuple[str, list[str]]] = {}
@@ -177,6 +227,25 @@ class RefreshService:
             self.database.upsert_mods(metadata_rows)
 
             metrics["downloads_requested"] = len(targets)
+            total_targets = len(targets)
+            completed_targets = 0
+            title_by_id = {
+                workshop_id: details[workshop_id].title
+                for workshop_id in targets
+                if workshop_id in details
+            }
+            report(
+                stage="downloading" if targets else "inspecting",
+                completed_mods=0,
+                total_mods=total_targets,
+                percent=100.0 if not targets else 0.0,
+            )
+            if initial_download:
+                logger.info(
+                    "Initial Workshop download started: %d mods, %.1f-hour hard limit",
+                    total_targets,
+                    (overall_timeout_seconds or 0) / 3600,
+                )
             if targets and not self.runner.available():
                 reason = (
                     f"SteamCMD was not found at '{self.settings.steamcmd_path}'. "
@@ -195,40 +264,116 @@ class RefreshService:
                         metrics["downloads_failed"] += 1
                 self.database.upsert_mods(inspection_rows)
             else:
-                for batch_number, batch in enumerate(
-                    _batches(targets, self.settings.steamcmd_batch_size), start=1
-                ):
-                    result = self.runner.run_batch(batch)
-                    self.database.add_download_attempt(
-                        {
-                            "run_id": run_id,
-                            "batch_number": batch_number,
-                            "item_count": len(batch),
-                            "workshop_ids": batch,
-                            "started_at": result.started_at,
-                            "finished_at": result.finished_at,
-                            "elapsed_seconds": result.elapsed_seconds,
-                            "exit_code": result.exit_code,
-                            "status": result.status,
-                            "output_tail": result.output_tail,
-                        }
+                download_queue = list(targets)
+                ready_target_ids: set[str] = set()
+                batch_number = 0
+                pass_number = 1
+                while download_queue:
+                    batches = _batches(
+                        download_queue, self.settings.steamcmd_batch_size
                     )
-                    inspection_rows = []
-                    for workshop_id in batch:
-                        failure = (
-                            "SteamCMD reported a download failure"
-                            if workshop_id in result.failed_ids
-                            else None
+                    for pass_batch_number, batch in enumerate(batches, start=1):
+                        remaining = remaining_time()
+                        batch_number += 1
+                        logger.info(
+                            "%s pass %d batch %d/%d starting (%d mods): %s",
+                            "Initial Workshop download"
+                            if initial_download
+                            else "Workshop refresh",
+                            pass_number,
+                            pass_batch_number,
+                            len(batches),
+                            len(batch),
+                            ", ".join(
+                                f"{title_by_id.get(workshop_id, 'Unknown mod')} "
+                                f"[{workshop_id}]"
+                                for workshop_id in batch
+                            ),
                         )
-                        success, values = self._inspection_values(
-                            workshop_id, downloaded=True, forced_error=failure
+                        result = self.runner.run_batch(
+                            batch, timeout_seconds=remaining
                         )
-                        inspection_rows.append(values)
-                        if success:
-                            metrics["downloads_succeeded"] += 1
-                        else:
-                            metrics["downloads_failed"] += 1
-                    self.database.upsert_mods(inspection_rows)
+                        self.database.add_download_attempt(
+                            {
+                                "run_id": run_id,
+                                "batch_number": batch_number,
+                                "item_count": len(batch),
+                                "workshop_ids": batch,
+                                "started_at": result.started_at,
+                                "finished_at": result.finished_at,
+                                "elapsed_seconds": result.elapsed_seconds,
+                                "exit_code": result.exit_code,
+                                "status": result.status,
+                                "output_tail": result.output_tail,
+                            }
+                        )
+                        inspection_rows = []
+                        for workshop_id in batch:
+                            failure = (
+                                "SteamCMD reported a download failure"
+                                if workshop_id in result.failed_ids
+                                else None
+                            )
+                            success, values = self._inspection_values(
+                                workshop_id, downloaded=True, forced_error=failure
+                            )
+                            inspection_rows.append(values)
+                            if success:
+                                metrics["downloads_succeeded"] += 1
+                                ready_target_ids.add(workshop_id)
+                            else:
+                                metrics["downloads_failed"] += 1
+                            completed_targets = len(ready_target_ids)
+                            percent = round(
+                                (completed_targets / max(total_targets, 1)) * 100,
+                                1,
+                            )
+                            title = title_by_id.get(workshop_id, "Unknown mod")
+                            outcome = "ready" if success else "failed"
+                            report(
+                                stage="downloading",
+                                completed_mods=completed_targets,
+                                total_mods=total_targets,
+                                percent=percent,
+                                current_workshop_id=workshop_id,
+                                current_title=title,
+                                current_status=outcome,
+                            )
+                            logger.info(
+                                "%s %d/%d (%.1f%%) %s: %s [%s]",
+                                "Initial mod download"
+                                if initial_download
+                                else "Mod refresh",
+                                completed_targets,
+                                total_targets,
+                                percent,
+                                outcome,
+                                title,
+                                workshop_id,
+                            )
+                        self.database.upsert_mods(inspection_rows)
+                        remaining_time()
+
+                    if not initial_download:
+                        break
+                    download_queue = [
+                        workshop_id
+                        for workshop_id in download_queue
+                        if workshop_id not in ready_target_ids
+                    ]
+                    if download_queue:
+                        remaining = remaining_time()
+                        retry_delay = min(30.0, remaining or 30.0)
+                        logger.warning(
+                            "Initial Workshop download pass %d left %d mods; "
+                            "retrying in %.0f seconds",
+                            pass_number,
+                            len(download_queue),
+                            retry_delay,
+                        )
+                        time.sleep(retry_delay)
+                        remaining_time()
+                        pass_number += 1
 
             # Re-inspect ready cached items whose metadata has never been parsed by this backend.
             current = self.database.mod_map(unique_ids)
@@ -259,12 +404,37 @@ class RefreshService:
                 metrics["error"] = (
                     f"{metrics['unique_items'] - metrics['ready_items']} items are not ready"
                 )
+            report(
+                stage=metrics["status"],
+                completed_mods=completed_targets,
+                total_mods=total_targets,
+                percent=round(
+                    (completed_targets / max(total_targets, 1)) * 100, 1
+                )
+                if total_targets
+                else 100.0,
+            )
         except Exception as error:  # noqa: BLE001 - the run must always persist a terminal state
             metrics["status"] = "failed"
             metrics["error"] = str(error)
             metrics["bytes_after"] = directory_size(self.settings.workshop_content_dir)
             metrics["cache_bytes"] = metrics["bytes_after"]
+            metrics["bytes_downloaded"] = max(
+                metrics["bytes_after"] - metrics["bytes_before"], 0
+            )
+            report(stage="failed", error=str(error))
+            logger.error(
+                "%s failed: %s",
+                "Initial Workshop download" if initial_download else "Workshop refresh",
+                error,
+            )
         finally:
+            if metrics["unique_items"]:
+                metrics["ready_items"] = sum(
+                    1
+                    for row in self.database.current_mods()
+                    if row.get("status") == "ready"
+                )
             elapsed = max(time.monotonic() - started, 0.001)
             metrics["elapsed_seconds"] = round(elapsed, 3)
             metrics["average_mbps"] = round(
@@ -272,20 +442,37 @@ class RefreshService:
             )
             metrics["finished_at"] = utc_now()
             self.database.finish_run(run_id, metrics)
+            logger.info(
+                "%s finished: status=%s, ready=%d/%d, elapsed=%.1fs, "
+                "cache=%d bytes",
+                "Initial Workshop download" if initial_download else "Workshop refresh",
+                metrics["status"],
+                metrics["ready_items"],
+                metrics["unique_items"],
+                elapsed,
+                metrics["cache_bytes"],
+            )
 
 
 class RefreshCoordinator:
     def __init__(
-        self, service: RefreshService, interval_seconds: int, refresh_on_startup: bool
+        self,
+        service: RefreshService,
+        interval_seconds: int,
+        refresh_on_startup: bool,
+        initial_download_timeout_seconds: int = 43200,
     ):
         self.service = service
         self.interval_seconds = interval_seconds
         self.refresh_on_startup = refresh_on_startup
+        self.initial_download_timeout_seconds = initial_download_timeout_seconds
         self.current_run_id: str | None = None
         self.next_refresh_at: str | None = None
         self._refresh_task: asyncio.Task[None] | None = None
         self._scheduler_task: asyncio.Task[None] | None = None
         self._stop = asyncio.Event()
+        self._active_initial_download = False
+        self._progress: dict[str, Any] | None = None
 
     async def start(self) -> None:
         if self._scheduler_task:
@@ -303,19 +490,48 @@ class RefreshCoordinator:
             return self.current_run_id or "", False
         run_id = uuid.uuid4().hex
         self.current_run_id = run_id
+        initial_download = self.service.needs_initial_download()
+        self._active_initial_download = initial_download
+        self._progress = {
+            "stage": "starting",
+            "completed_mods": 0,
+            "total_mods": 0,
+            "percent": 0.0,
+        }
+
+        def update_progress(values: dict[str, Any]) -> None:
+            self._progress = {**(self._progress or {}), **values}
 
         async def run() -> None:
             try:
-                await asyncio.to_thread(self.service.refresh, run_id, trigger)
+                await asyncio.to_thread(
+                    self.service.refresh,
+                    run_id,
+                    trigger,
+                    initial_download=initial_download,
+                    overall_timeout_seconds=(
+                        self.initial_download_timeout_seconds
+                        if initial_download
+                        else None
+                    ),
+                    progress=update_progress,
+                )
             finally:
                 self.current_run_id = None
+                self._active_initial_download = False
 
         self._refresh_task = asyncio.create_task(run())
         return run_id, True
 
+    async def _wait_for_initial_download(self, started: bool) -> None:
+        if started and self._active_initial_download and self._refresh_task:
+            self.next_refresh_at = None
+            await asyncio.shield(self._refresh_task)
+
     async def _scheduler_loop(self) -> None:
         if self.refresh_on_startup:
-            await self.trigger("startup")
+            _, started = await self.trigger("startup")
+            await self._wait_for_initial_download(started)
         while not self._stop.is_set():
             next_time = datetime.now(timezone.utc) + timedelta(
                 seconds=self.interval_seconds
@@ -324,7 +540,8 @@ class RefreshCoordinator:
             try:
                 await asyncio.wait_for(self._stop.wait(), timeout=self.interval_seconds)
             except asyncio.TimeoutError:
-                await self.trigger("scheduled")
+                _, started = await self.trigger("scheduled")
+                await self._wait_for_initial_download(started)
 
     def state(self) -> dict[str, Any]:
         return {
@@ -332,4 +549,11 @@ class RefreshCoordinator:
             "current_run_id": self.current_run_id,
             "next_refresh_at": self.next_refresh_at,
             "interval_seconds": self.interval_seconds,
+            "initial_download": bool(
+                self._active_initial_download
+                and self._refresh_task
+                and not self._refresh_task.done()
+            ),
+            "initial_download_timeout_seconds": self.initial_download_timeout_seconds,
+            "progress": dict(self._progress) if self._progress else None,
         }