Fix spool weight tracking for fallback archives, VT trays, and notifications (#839)

  Usage tracking failed silently when FTP download failed (fallback archive
  with no 3MF), when printing from external spool holder (VT tray not
  iterated by AMS fallback), and notifications showed "Unknown" for time
  and filament. Now resolves 3MF from library/previous archives, tracks
  VT tray remain% deltas, enriches notifications with usage tracker
  results, and captures print time from MQTT for fallback archives.

CHANGELOG.md

@@ -24,6 +24,7 @@ All notable changes to Bambuddy will be documented in this file.
 - **Camera Snapshot Temp Files World-Readable** — Camera snapshot and plate detection endpoints created temporary JPEG files in `/tmp` with default 0644 permissions, making them readable by any local user. Switched from `NamedTemporaryFile(delete=False)` to `mkstemp` with explicit 0600 permissions so only the application user can read them. Cleanup was already handled via `finally` blocks. Reported responsibly by Sacha Vaudey via security@bambuddy.cool.
 
 ### Fixed
+- **Spool Weight Not Updated After Print** ([#839](https://github.com/maziggy/bambuddy/issues/839)) — Filament usage tracking failed silently in several scenarios: (1) when FTP download failed and a fallback archive was created without a 3MF file, the primary tracking path was skipped entirely — now falls back to matching the 3MF from the library or a previous archive of the same file; (2) external/VT tray spools were never tracked by the AMS remain% fallback because it only iterated AMS unit trays — now captures and tracks VT tray remain% deltas; (3) notifications showed "Unknown" for time and filament on fallback archives — now enriches notifications with usage tracker results and captures estimated print time from MQTT at archive creation.
 - **File Manager Stale UI After Deleting Folders/Files** — Deleting a folder, file, or bulk-deleting items in the file manager appeared to succeed (toast shown) but the UI didn't update until a page reload. The delete endpoints (`delete_folder`, `delete_file`, `bulk_delete`) relied on FastAPI's dependency cleanup auto-commit which runs after the response is sent — the frontend received the success response, refetched the folder/file list, but the delete hadn't been committed yet. Added explicit `db.commit()` before returning in all three endpoints.
 - **Spool Manager Deducts Double the Filament Used** ([#880](https://github.com/maziggy/bambuddy/issues/880)) — After a print completed, the built-in spool manager subtracted twice the actual filament consumption. The printer's MQTT status message contains both updated AMS remain percentages and the `FINISH` state, which triggered two independent deduction paths in the same event loop cycle: the AMS weight sync (absolute SET from remain%) and the usage tracker (additive delta from 3MF data). The AMS weight sync now skips updates while a print session is active, letting the usage tracker handle deductions precisely via 3MF slicer data.
 - **Thumbnails Broken After Backend Restart** — Archive and library thumbnails returned 401 Unauthorized after a backend restart because stream tokens are stored in memory and lost on restart. The frontend now detects failed token-protected image loads and automatically refreshes the stream token, so thumbnails recover without a page reload.

backend/app/main.py

@@ -1788,6 +1788,16 @@ async def on_print_start(printer_id: int, data: dict):
                 else:
                     print_name = "Unknown Print"
 
+                # Recover estimated print time from MQTT (best-effort for notifications)
+                fallback_print_time = None
+                mqtt_remaining = data.get("remaining_time")
+                if mqtt_remaining and isinstance(mqtt_remaining, (int, float)) and mqtt_remaining > 0:
+                    fallback_print_time = int(mqtt_remaining)
+                if fallback_print_time is None:
+                    mc_remaining = (data.get("raw_data") or {}).get("mc_remaining_time")
+                    if mc_remaining and isinstance(mc_remaining, (int, float)) and mc_remaining > 0:
+                        fallback_print_time = int(mc_remaining * 60)
+
                 # Create minimal archive entry
                 fallback_archive = PrintArchive(
                     printer_id=printer_id,
@@ -1795,6 +1805,7 @@ async def on_print_start(printer_id: int, data: dict):
                     file_path="",  # Empty - no 3MF file available
                     file_size=0,
                     print_name=print_name,
+                    print_time_seconds=fallback_print_time,
                     status="printing",
                     started_at=datetime.now(timezone.utc),
                     extra_data={"no_3mf_available": True, "original_subtask": subtask_name, "_print_data": data},
@@ -2691,6 +2702,21 @@ async def on_print_complete(printer_id: int, data: dict):
                             "[NOTIFY-BG] Could not look up queue item for no-archive notification: %s", lookup_err
                         )
 
+                    # Enrich with usage tracker results (captured in enclosing scope)
+                    if usage_results:
+                        if no_archive_data is None:
+                            no_archive_data = {}
+                        total_from_usage = sum(r.get("weight_used", 0) for r in usage_results)
+                        if total_from_usage > 0:
+                            no_archive_data["actual_filament_grams"] = round(total_from_usage, 1)
+                        no_archive_data["usage_results"] = usage_results
+
+                    # Try MQTT remaining_time for print duration when no queue/library data
+                    if no_archive_data and not no_archive_data.get("print_time_seconds"):
+                        mqtt_remaining = data.get("remaining_time")
+                        if mqtt_remaining and isinstance(mqtt_remaining, (int, float)) and mqtt_remaining > 0:
+                            no_archive_data["print_time_seconds"] = int(mqtt_remaining)
+
                     ps = data.get("status", "completed")
                     logger.info(
                         "[NOTIFY-BG] Sending notification without archive: printer=%s, status=%s", printer_id, ps
@@ -3014,6 +3040,12 @@ async def on_print_complete(printer_id: int, data: dict):
                                 slots = [{**s, "used_g": round(s["used_g"] * scale, 1)} for s in slots]
                             archive_data["filament_slots"] = slots
 
+                        # Enrich filament_grams from usage_results when archive has no 3MF data
+                        if not archive_data.get("actual_filament_grams") and usage_results:
+                            total_from_usage = sum(r.get("weight_used", 0) for r in usage_results)
+                            if total_from_usage > 0:
+                                archive_data["actual_filament_grams"] = round(total_from_usage, 1)
+
                         # Pass usage tracker results for AMS slot info in notifications
                         if usage_results:
                             archive_data["usage_results"] = usage_results

backend/app/services/usage_tracker.py

@@ -237,11 +237,10 @@ async def on_print_start(printer_id: int, data: dict, printer_manager, db: Async
 
     ams_raw = state.raw_data.get("ams", [])
     ams_data = ams_raw.get("ams", []) if isinstance(ams_raw, dict) else ams_raw if isinstance(ams_raw, list) else []
-    if not ams_data:
-        logger.debug("[UsageTracker] No AMS data for printer %d, skipping", printer_id)
-        return
 
     tray_remain_start: dict[tuple[int, int], int] = {}
+    skipped_invalid: list[str] = []
+
     for ams_unit in ams_data:
         ams_id = int(ams_unit.get("id", 0))
         for tray in ams_unit.get("tray", []):
@@ -249,6 +248,35 @@ async def on_print_start(printer_id: int, data: dict, printer_manager, db: Async
             remain = tray.get("remain", -1)
             if isinstance(remain, int) and 0 <= remain <= 100:
                 tray_remain_start[(ams_id, tray_id)] = remain
+            else:
+                skipped_invalid.append(f"AMS{ams_id}-T{tray_id}(remain={remain})")
+
+    # Also capture VT (external) tray remain% — these are separate from AMS units
+    vt_tray_raw = state.raw_data.get("vt_tray") or []
+    if isinstance(vt_tray_raw, dict):
+        vt_tray_raw = [vt_tray_raw]
+    for vt in vt_tray_raw:
+        if not isinstance(vt, dict):
+            continue
+        vt_id = int(vt.get("id", 254))
+        # VT tray id 254 → (ams_id=255, tray_id=0), id 255 → (ams_id=255, tray_id=1)
+        vt_tray_id = vt_id - 254
+        remain = vt.get("remain", -1)
+        if isinstance(remain, int) and 0 <= remain <= 100:
+            tray_remain_start[(255, vt_tray_id)] = remain
+        else:
+            skipped_invalid.append(f"VT{vt_id}(remain={remain})")
+
+    if skipped_invalid:
+        logger.info(
+            "[UsageTracker] Skipped trays with invalid remain%% for printer %d: %s",
+            printer_id,
+            ", ".join(skipped_invalid),
+        )
+
+    if not ams_data and not vt_tray_raw:
+        logger.debug("[UsageTracker] No AMS or VT tray data for printer %d, skipping", printer_id)
+        return
 
     print_name = data.get("subtask_name", "") or data.get("filename", "unknown")
 
@@ -400,94 +428,123 @@ async def on_print_complete(
                 ams_raw.get("ams", []) if isinstance(ams_raw, dict) else ams_raw if isinstance(ams_raw, list) else []
             )
 
+            # Collect all trays to check: AMS trays + VT (external) trays
+            # Each entry: (ams_id_for_assignment, tray_id_for_assignment, current_remain, label)
+            trays_to_check: list[tuple[int, int, int, str]] = []
+
             for ams_unit in ams_data:
                 ams_id = int(ams_unit.get("id", 0))
                 for tray in ams_unit.get("tray", []):
                     tray_id = int(tray.get("id", 0))
-                    key = (ams_id, tray_id)
+                    remain = tray.get("remain", -1)
+                    trays_to_check.append((ams_id, tray_id, remain, f"AMS{ams_id}-T{tray_id}"))
+
+            # VT (external) trays — same remain% delta logic
+            vt_tray_raw = state.raw_data.get("vt_tray") or []
+            if isinstance(vt_tray_raw, dict):
+                vt_tray_raw = [vt_tray_raw]
+            for vt in vt_tray_raw:
+                if not isinstance(vt, dict):
+                    continue
+                vt_id = int(vt.get("id", 254))
+                vt_tray_id = vt_id - 254  # 254→0, 255→1
+                remain = vt.get("remain", -1)
+                trays_to_check.append((255, vt_tray_id, remain, f"VT{vt_id}"))
 
-                    if key in handled_trays:
-                        continue  # Already tracked via 3MF
+            for assign_ams_id, assign_tray_id, current_remain, tray_label in trays_to_check:
+                key = (assign_ams_id, assign_tray_id)
 
-                    if key not in session.tray_remain_start:
-                        continue
+                if key in handled_trays:
+                    continue  # Already tracked via 3MF
 
-                    current_remain = tray.get("remain", -1)
-                    if not isinstance(current_remain, int) or current_remain < 0 or current_remain > 100:
-                        continue
+                if key not in session.tray_remain_start:
+                    continue
 
-                    start_remain = session.tray_remain_start[key]
-                    delta_pct = start_remain - current_remain
+                if not isinstance(current_remain, int) or current_remain < 0 or current_remain > 100:
+                    logger.info(
+                        "[UsageTracker] %s: invalid remain%% at completion (%s), skipping fallback for printer %d",
+                        tray_label,
+                        current_remain,
+                        printer_id,
+                    )
+                    continue
 
-                    if delta_pct <= 0:
-                        continue  # No consumption or tray was refilled
+                start_remain = session.tray_remain_start[key]
+                delta_pct = start_remain - current_remain
 
-                    spool_id = await _resolve_spool_id_for_tray(
-                        printer_id=printer_id,
-                        ams_id=ams_id,
-                        tray_id=tray_id,
-                        db=db,
-                        spool_assignments_snapshot=session.spool_assignments,
-                        print_started_at=session.started_at,
-                    )
-                    if spool_id is None:
-                        continue
-
-                    # Load spool
-                    spool_result = await db.execute(select(Spool).where(Spool.id == spool_id))
-                    spool = spool_result.scalar_one_or_none()
-                    if not spool:
-                        continue
-
-                    # Compute weight consumed
-                    weight_grams = (delta_pct / 100.0) * spool.label_weight
-
-                    # Update spool
-                    spool.weight_used = (spool.weight_used or 0) + weight_grams
-                    spool.last_used = datetime.now(timezone.utc)
-
-                    # Calculate cost for this usage
-                    cost = None
-                    cost_per_kg = spool.cost_per_kg if spool.cost_per_kg is not None else default_filament_cost
-                    if cost_per_kg > 0:
-                        cost = round((weight_grams / 1000.0) * cost_per_kg, 2)
-
-                    # Insert usage history record
-                    history = SpoolUsageHistory(
-                        spool_id=spool.id,
-                        printer_id=printer_id,
-                        print_name=session.print_name,
-                        weight_used=round(weight_grams, 1),
-                        percent_used=delta_pct,
-                        status=status,
-                        cost=cost,
-                        archive_id=archive_id,
-                    )
-                    db.add(history)
-
-                    handled_trays.add(key)
-                    results.append(
-                        {
-                            "spool_id": spool.id,
-                            "weight_used": round(weight_grams, 1),
-                            "percent_used": delta_pct,
-                            "ams_id": ams_id,
-                            "tray_id": tray_id,
-                            "material": spool.material,
-                            "cost": cost,
-                        }
-                    )
+                if delta_pct <= 0:
+                    continue  # No consumption or tray was refilled
 
+                spool_id = await _resolve_spool_id_for_tray(
+                    printer_id=printer_id,
+                    ams_id=assign_ams_id,
+                    tray_id=assign_tray_id,
+                    db=db,
+                    spool_assignments_snapshot=session.spool_assignments,
+                    print_started_at=session.started_at,
+                )
+                if spool_id is None:
                     logger.info(
-                        "[UsageTracker] Spool %d consumed %.1fg (%d%%) on printer %d AMS%d-T%d (AMS fallback, %s)",
-                        spool.id,
-                        weight_grams,
-                        delta_pct,
+                        "[UsageTracker] %s: no spool assigned, skipping fallback for printer %d",
+                        tray_label,
                         printer_id,
-                        ams_id,
-                        tray_id,
-                        status,
                     )
+                    continue
+
+                # Load spool
+                spool_result = await db.execute(select(Spool).where(Spool.id == spool_id))
+                spool = spool_result.scalar_one_or_none()
+                if not spool:
+                    continue
+
+                # Compute weight consumed
+                weight_grams = (delta_pct / 100.0) * spool.label_weight
+
+                # Update spool
+                spool.weight_used = (spool.weight_used or 0) + weight_grams
+                spool.last_used = datetime.now(timezone.utc)
+
+                # Calculate cost for this usage
+                cost = None
+                cost_per_kg = spool.cost_per_kg if spool.cost_per_kg is not None else default_filament_cost
+                if cost_per_kg > 0:
+                    cost = round((weight_grams / 1000.0) * cost_per_kg, 2)
+
+                # Insert usage history record
+                history = SpoolUsageHistory(
+                    spool_id=spool.id,
+                    printer_id=printer_id,
+                    print_name=session.print_name,
+                    weight_used=round(weight_grams, 1),
+                    percent_used=delta_pct,
+                    status=status,
+                    cost=cost,
+                    archive_id=archive_id,
+                )
+                db.add(history)
+
+                handled_trays.add(key)
+                results.append(
+                    {
+                        "spool_id": spool.id,
+                        "weight_used": round(weight_grams, 1),
+                        "percent_used": delta_pct,
+                        "ams_id": assign_ams_id,
+                        "tray_id": assign_tray_id,
+                        "material": spool.material,
+                        "cost": cost,
+                    }
+                )
+
+                logger.info(
+                    "[UsageTracker] Spool %d consumed %.1fg (%d%%) on printer %d %s (AMS fallback, %s)",
+                    spool.id,
+                    weight_grams,
+                    delta_pct,
+                    printer_id,
+                    tray_label,
+                    status,
+                )
 
     if results:
         await db.commit()
@@ -510,6 +567,74 @@ async def on_print_complete(
     return results
 
 
+async def _resolve_3mf_fallback(archive, db: AsyncSession, base_dir):
+    """Try to find a 3MF file from library or a previous archive when the current archive has none.
+
+    This handles fallback archives (FTP download failed) where the 3MF may already exist
+    locally from a library upload or a previous successful print of the same file.
+    """
+    from pathlib import Path
+
+    from backend.app.models.archive import PrintArchive
+    from backend.app.models.library import LibraryFile
+
+    # Derive search name from archive filename (e.g. "benchy.3mf" or "benchy.gcode.3mf")
+    search_name = archive.filename or archive.print_name
+    if not search_name:
+        return None
+    # Normalize: strip path parts, get base name
+    search_name = search_name.split("/")[-1]
+    search_base = search_name.replace(".gcode.3mf", "").replace(".gcode", "").replace(".3mf", "")
+    if not search_base:
+        return None
+
+    # 1. Try library files matching the name (match base name at file boundary)
+    try:
+        lib_result = await db.execute(
+            select(LibraryFile)
+            .where(LibraryFile.file_path.ilike(f"%/{search_base}.%") | LibraryFile.file_path.ilike(f"{search_base}.%"))
+            .where(LibraryFile.file_path.ilike("%.3mf"))
+            .order_by(LibraryFile.created_at.desc())
+            .limit(3)
+        )
+        for lib_file in lib_result.scalars().all():
+            lib_path = Path(lib_file.file_path)
+            candidate = lib_path if lib_path.is_absolute() else base_dir / lib_file.file_path
+            if candidate.exists() and candidate.suffix == ".3mf":
+                logger.info("[UsageTracker] 3MF fallback: found library file %s for archive %s", candidate, archive.id)
+                return candidate
+    except Exception as e:
+        logger.debug("[UsageTracker] 3MF fallback: library lookup failed: %s", e)
+
+    # 2. Try previous archives with the same filename that have a valid file_path
+    try:
+        prev_result = await db.execute(
+            select(PrintArchive)
+            .where(PrintArchive.id != archive.id)
+            .where(PrintArchive.printer_id == archive.printer_id)
+            .where(PrintArchive.file_path != "")
+            .where(PrintArchive.file_path.isnot(None))
+            .where(
+                PrintArchive.filename.ilike(f"%{search_base}.%") | PrintArchive.filename.ilike(f"{search_base}.%"),
+            )
+            .order_by(PrintArchive.created_at.desc())
+            .limit(3)
+        )
+        for prev_archive in prev_result.scalars().all():
+            candidate = base_dir / prev_archive.file_path
+            if candidate.exists() and candidate.suffix == ".3mf":
+                logger.info(
+                    "[UsageTracker] 3MF fallback: found previous archive %s file for archive %s",
+                    prev_archive.id,
+                    archive.id,
+                )
+                return candidate
+    except Exception as e:
+        logger.debug("[UsageTracker] 3MF fallback: previous archive lookup failed: %s", e)
+
+    return None
+
+
 async def _track_from_3mf(
     printer_id: int,
     archive_id: int,
@@ -540,6 +665,8 @@ async def _track_from_3mf(
     5. Position-based default using sorted available tray IDs (handles external spools)
     6. Default mapping: slot_id - 1 = global_tray_id (last resort)
     """
+    from pathlib import Path
+
     from backend.app.core.config import settings as app_settings
     from backend.app.models.archive import PrintArchive
     from backend.app.models.print_queue import PrintQueueItem
@@ -547,13 +674,24 @@ async def _track_from_3mf(
 
     result = await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id))
     archive = result.scalar_one_or_none()
-    if not archive or not archive.file_path:
-        logger.info("[UsageTracker] 3MF: archive %s has no file_path, skipping", archive_id)
+    if not archive:
+        logger.info("[UsageTracker] 3MF: archive %s not found, skipping", archive_id)
         return []
 
-    file_path = app_settings.base_dir / archive.file_path
-    if not file_path.exists():
-        logger.info("[UsageTracker] 3MF: file not found: %s", file_path)
+    file_path: Path | None = None
+
+    # Try archive's own file_path first
+    if archive.file_path:
+        candidate = app_settings.base_dir / archive.file_path
+        if candidate.exists():
+            file_path = candidate
+
+    # Fallback: find 3MF from library or a previous archive with the same filename
+    if file_path is None:
+        file_path = await _resolve_3mf_fallback(archive, db, app_settings.base_dir)
+
+    if file_path is None:
+        logger.info("[UsageTracker] 3MF: no file available for archive %s, skipping", archive_id)
         return []
 
     filament_usage = extract_filament_usage_from_3mf(file_path)