fix+logging: model load logging, CPU fallback, log level audit

Bugs fixed (from high-effort review):
- InsightFace CPU fallback now passes providers=['CPUExecutionProvider'] and
  wraps in _suppress_output() so broken GPU drivers don't cause fallback to
  try the same broken provider again, and C-extension noise stays suppressed
- scheduler.py: BaseException → Exception (KeyboardInterrupt already re-raised;
  winnow has no sys.exit() calls, so SystemExit would not occur, but Exception
  is the correct scope)
- compose.yml: fix inverted AUTO_MODE comment (docker run -it enables
  interactive mode via TTY, not non-interactive)

Model loading logging (embeddings.py):
- InsightFace: disk cache check, "not cached — downloading now (~300 MB)",
  "loading into memory on GPU/CPU...", "ready on GPU/CPU (Xs)"
- SigLIP: same treatment; cache path derived dynamically from model_name
  via HuggingFace slug convention (models--org--model) so it stays correct
  if the model variant ever changes

Logging level audit (INFO/DEBUG/WARNING/ERROR):
- diversity.py: internal algo steps (clustering, medoids, adaptive threshold,
  auto-stop decision) → DEBUG; final selection summaries stay INFO
- immich_api.py: "Fetching assets" and "Retained N assets" → DEBUG (callers
  already print this to the console via rprint)

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>

compose.yml

@@ -10,8 +10,8 @@ services:
 
       # ── Mode & Strategy ───────────────────────────────────────────────────
       # Auto mode is active by default when no TTY is present (Docker/cron).
-      # Run with `docker run -it` or set AUTO_MODE=true to force non-interactive
-      # in a terminal.
+      # Set AUTO_MODE=true to force auto mode in an interactive terminal.
+      # To run interactively: docker exec -it winnow winnow
       # TRAINING_MODE: face = upload to Frigate face recognition API
       #                object = save crops to output dir for manual Frigate placement
       - TRAINING_MODE=face

scheduler.py

@@ -45,7 +45,7 @@ while True:
             print("winnow run complete", flush=True)
         except KeyboardInterrupt:
             raise
-        except BaseException as e:
+        except Exception as e:
             logger.error(f"winnow run failed: {e}", exc_info=True)
             print(f"winnow run failed: {e}", flush=True)
         next_run = cron.get_next(float)

winnow/diversity.py

@@ -368,7 +368,7 @@ def _compute_adaptive_threshold(emb_normed: np.ndarray, entity_type: str) -> flo
     fraction = 0.20 if entity_type == "face" else 0.10
     threshold = max(0.05, median_dist * fraction)
 
-    logger.info(
+    logger.debug(
         f"Adaptive threshold: {threshold:.4f} "
         f"(median_dist={median_dist:.4f}, fraction={fraction}, type={entity_type})"
     )
@@ -410,7 +410,7 @@ def _cluster_aware_selection(
 
     # --- Stage 1: K-Medoids clustering ---
     k = min(max(5, target // 4), n // 3, n)  # e.g., 5-20 clusters
-    logger.info(f"Clustering {n} embeddings into {k} groups (K-Medoids)...")
+    logger.debug(f"Clustering {n} embeddings into {k} groups (K-Medoids)...")
 
     # Compute full cosine distance matrix
     dist_matrix = 1 - emb_normed @ emb_normed.T
@@ -419,7 +419,7 @@ def _cluster_aware_selection(
     selected = list(medoid_indices)
     selected_set = set(selected)
 
-    logger.info(f"Selected {len(selected)} cluster medoids as initial picks.")
+    logger.debug(f"Selected {len(selected)} cluster medoids as initial picks.")
 
     # --- Stage 2: FPS with hard example weighting ---
     min_dists = np.full(n, np.inf)
@@ -444,8 +444,8 @@ def _cluster_aware_selection(
             break  # All points selected
 
         if limit == "auto" and best_dist < auto_threshold:
-            logger.info(
-                f"Auto-stop: Next best image {best_dist:.3f} away " f"(adaptive threshold {auto_threshold:.4f})."
+            logger.debug(
+                f"Auto-stop: next best image {best_dist:.3f} away (adaptive threshold {auto_threshold:.4f})."
             )
             break
 

winnow/embeddings.py

@@ -9,8 +9,10 @@ Unified embedding interface for faces and objects.
 import importlib
 import logging
 import os
+import time
 import warnings
 from contextlib import contextmanager
+from pathlib import Path
 
 import cv2
 import numpy as np
@@ -90,9 +92,16 @@ def get_insightface_app():
         import onnxruntime as ort
         from insightface.app import FaceAnalysis
 
+        # Disk cache check — lets the user know whether a download is coming
+        buffalo_path = Path(insightface_home) / "models" / "buffalo_l"
+        if buffalo_path.exists() and any(buffalo_path.iterdir()):
+            logger.info("InsightFace Buffalo_L: found in model cache")
+        else:
+            logger.info("InsightFace Buffalo_L: not cached — downloading now (~300 MB)")
+
         # Get providers, excluding TensorRT to avoid noisy errors
         providers = [p for p in ort.get_available_providers() if p != "TensorrtExecutionProvider"]
-        logger.info(f"Available ONNX providers: {providers}")
+        logger.debug(f"ONNX providers available: {providers}")
 
         gpu_providers = {
             "CUDAExecutionProvider",
@@ -111,12 +120,14 @@ def get_insightface_app():
             )
 
         device_str = "GPU" if ctx_id >= 0 else "CPU"
-        logger.info(f"Loading InsightFace Buffalo_L on {device_str} (ctx_id={ctx_id})...")
+        logger.info(f"InsightFace Buffalo_L: loading into memory on {device_str}...")
 
+        t0 = time.time()
         with _suppress_output():
             _insightface_app = FaceAnalysis(name="buffalo_l", root=insightface_home, providers=providers)
             _insightface_app.prepare(ctx_id=ctx_id, det_size=(640, 640))
 
+        logger.info(f"InsightFace Buffalo_L: ready on {device_str} ({time.time() - t0:.1f}s)")
         return _insightface_app
 
     except ImportError:
@@ -125,15 +136,22 @@ def get_insightface_app():
     except Exception as e:
         logger.error(f"Failed to load InsightFace: {e}")
         if ctx_id == 0:
-            logger.warning("Retrying InsightFace on CPU...")
+            logger.warning("InsightFace GPU load failed — retrying on CPU...")
             try:
                 from insightface.app import FaceAnalysis
 
-                _insightface_app = FaceAnalysis(name="buffalo_l", root=insightface_home)
-                _insightface_app.prepare(ctx_id=-1, det_size=(640, 640))
+                t0 = time.time()
+                with _suppress_output():
+                    _insightface_app = FaceAnalysis(
+                        name="buffalo_l",
+                        root=insightface_home,
+                        providers=["CPUExecutionProvider"],
+                    )
+                    _insightface_app.prepare(ctx_id=-1, det_size=(640, 640))
+                logger.info(f"InsightFace Buffalo_L: ready on CPU (fallback, {time.time() - t0:.1f}s)")
                 return _insightface_app
             except Exception as ex:
-                logger.error(f"CPU fallback failed: {ex}")
+                logger.error(f"InsightFace CPU fallback failed: {ex}")
         return None
 
 
@@ -182,7 +200,18 @@ def get_siglip_model():
         from transformers import AutoImageProcessor, SiglipVisionModel
 
         model_name = "google/siglip-base-patch16-224"
-        logger.info(f"Loading SigLIP model ({model_name})...")
+
+        # Disk cache check — path derived from model_name using HuggingFace's slug convention
+        hf_home = os.environ.get("HF_HOME", os.path.join(os.path.expanduser("~"), ".cache", "huggingface"))
+        cache_slug = "models--" + model_name.replace("/", "--")
+        model_cache = Path(hf_home) / "hub" / cache_slug
+        if model_cache.exists() and any(model_cache.iterdir()):
+            logger.info(f"SigLIP {model_name}: found in model cache")
+        else:
+            logger.info(f"SigLIP {model_name}: not cached — downloading now (~380 MB)")
+
+        logger.info(f"SigLIP {model_name}: loading into memory...")
+        t0 = time.time()
 
         with warnings.catch_warnings():
             warnings.filterwarnings("ignore", category=FutureWarning)
@@ -196,15 +225,16 @@ def get_siglip_model():
         if not _is_force_cpu():
             if torch.cuda.is_available():
                 _siglip_model = _siglip_model.cuda()
-                logger.info("SigLIP running on CUDA GPU")
+                device_name = "CUDA GPU"
             elif hasattr(torch.backends, "mps") and torch.backends.mps.is_available():
                 _siglip_model = _siglip_model.to("mps")
-                logger.info("SigLIP running on Apple MPS")
+                device_name = "Apple MPS"
             else:
-                logger.info("SigLIP running on CPU")
+                device_name = "CPU"
         else:
-            logger.info("FORCE_CPU set. SigLIP running on CPU")
+            device_name = "CPU (FORCE_CPU)"
 
+        logger.info(f"SigLIP {model_name}: ready on {device_name} ({time.time() - t0:.1f}s)")
         return _siglip_model, _siglip_processor
 
     except ImportError as e:

winnow/immich_api.py

@@ -49,7 +49,7 @@ def fetch_all_assets(person: dict) -> list[dict]:
     url = f"{Config.IMMICH_URL}/api/search/metadata"
     page_size = 1000
 
-    logger.info(f"Fetching assets for {name}...")
+    logger.debug(f"Fetching assets for {name}...")
 
     assets = []
     for page in range(1, MAX_PAGES + 1):
@@ -212,6 +212,6 @@ def filter_recent_assets(assets: list[dict], years: int | None = None) -> list[d
         except ValueError:
             continue
 
-    logger.info(f"Retained {len(recent)} assets (filtered {skipped} old assets).")
+    logger.debug(f"Retained {len(recent)} assets (filtered {skipped} old assets).")
     return recent