From 3db52c2141e2cc466c2a0c40bc8bcfa91c7628ff Mon Sep 17 00:00:00 2001 From: Holden Date: Fri, 12 Jun 2026 15:23:44 +0000 Subject: [PATCH] fix+logging: model load logging, CPU fallback, log level audit MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- compose.yml | 4 ++-- scheduler.py | 2 +- winnow/diversity.py | 10 ++++----- winnow/embeddings.py | 52 ++++++++++++++++++++++++++++++++++---------- winnow/immich_api.py | 4 ++-- 5 files changed, 51 insertions(+), 21 deletions(-) diff --git a/compose.yml b/compose.yml index 7dfbee0..c6f367d 100644 --- a/compose.yml +++ b/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 diff --git a/scheduler.py b/scheduler.py index ae98438..c3a08a6 100644 --- a/scheduler.py +++ b/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) diff --git a/winnow/diversity.py b/winnow/diversity.py index a1359bc..2c7cae6 100644 --- a/winnow/diversity.py +++ b/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 diff --git a/winnow/embeddings.py b/winnow/embeddings.py index 16df985..ff20c80 100644 --- a/winnow/embeddings.py +++ b/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: diff --git a/winnow/immich_api.py b/winnow/immich_api.py index 3159c28..b12a66b 100644 --- a/winnow/immich_api.py +++ b/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