From 1fc404ebfded277f0737a8c65219f1d73d17c471 Mon Sep 17 00:00:00 2001 From: Dariusz L Date: Sat, 25 Apr 2026 23:43:17 +0200 Subject: [PATCH] Add detailed logging to model linker and sources Add extensive observability/logging across ModelLinker and source search modules. __init__.py: introduce summarize_result and log_search_result helpers, replace ad-hoc logger calls with log_info/log_exception, and add start/result/summary logs for local, popular, model_list, HuggingFace and CivitAI searches (including extra metadata like confidence, files_count, results_count). core/sources/civitai.py: log cache hits, API call start, response counts, model/version/file checks, no-result info and improved exception logging. core/sources/huggingface.py: log cache hits, API call start, response counts, per-repo debug info, repo tree sizes, no-result info and improved exception logging. Changes are focused on diagnostics and do not alter core search logic. --- __init__.py | 87 ++++++++++++++++++++++++++++++++++--- core/sources/civitai.py | 22 +++++++++- core/sources/huggingface.py | 23 ++++++++-- 3 files changed, 121 insertions(+), 11 deletions(-) diff --git a/__init__.py b/__init__.py index 7299882..08a699b 100644 --- a/__init__.py +++ b/__init__.py @@ -766,6 +766,37 @@ class ModelLinkerExtension: async def search_sources(request): """Search for model download sources.""" try: + def summarize_result(source_name, result, extra=None): + if isinstance(result, dict): + summary = { + "source": source_name, + "name": result.get("name"), + "filename": result.get("filename"), + "match_type": result.get("match_type"), + "repo_id": result.get("repo_id"), + "model_id": result.get("model_id"), + "version_id": result.get("version_id"), + "url": result.get("url"), + "download_url": result.get("download_url"), + "size": result.get("size"), + } + else: + summary = {"source": source_name, "result": result} + + if extra: + summary.update(extra) + + return summary + + def log_search_result(source_name, result, extra=None): + details = summarize_result(source_name, result, extra) + if result and ( + not isinstance(result, list) or len(result) > 0 + ): + log_info(f"Search source [{source_name}] FOUND: {details}") + else: + log_info(f"Search source [{source_name}] no result: {details}") + data = await request.json() filename = data.get("filename", "") category = data.get("category", "") @@ -809,8 +840,7 @@ class ModelLinkerExtension: search_huggingface_source = "huggingface" in normalized_sources search_civitai_source = "civitai" in normalized_sources - # Debug logging - self.logger.info( + log_info( f"Search request: filename={filename}, category={category}, is_urn={is_urn}, model_id={data.get('model_id')}, version_id={data.get('version_id')}, sources={sorted(normalized_sources)}" ) @@ -825,7 +855,11 @@ class ModelLinkerExtension: # 1. Search local databases (curated + model-list) if search_local: + log_info( + f"Search source [local] start: filename={filename}, category={category}" + ) popular_info = get_popular_model_url(filename) + log_search_result("popular", popular_info) if popular_info: results["popular"] = { "source": "popular", @@ -835,6 +869,15 @@ class ModelLinkerExtension: results["found"] = True model_list_result = search_model_list(filename) + log_search_result( + "model_list", + model_list_result, + { + "confidence": model_list_result.get("confidence") + if model_list_result + else None + }, + ) if model_list_result: confidence = model_list_result.get("confidence", 0) if is_urn and confidence >= 70: @@ -846,13 +889,18 @@ class ModelLinkerExtension: # 2. Search HuggingFace for exact file match if search_huggingface_source: + log_info(f"Search source [huggingface] start: filename={filename}") hf_result = search_huggingface_for_file(filename) + log_search_result("huggingface", hf_result) if hf_result: results["huggingface"] = hf_result results["found"] = True # 3. Search CivitAI - use direct download for URNs if search_civitai_source: + log_info( + f"Search source [civitai] start: filename={filename}, category={category}, is_urn={is_urn}" + ) # For URNs, use direct model_id/version_id to get download URL if is_urn: # Get model_id and version_id from request data @@ -897,15 +945,40 @@ class ModelLinkerExtension: "base_model": model_info.get("base_model"), "tags": model_info.get("tags", []), } + log_search_result( + "civitai/urn", + results["civitai"], + { + "files_count": len( + model_info.get("files", []) + ) + }, + ) results["found"] = True + else: + log_search_result( + "civitai/urn", + None, + { + "model_id": model_id, + "version_id": version_id, + }, + ) elif category: # Fallback to search if no IDs - self.logger.info( + log_info( f"URN: No model_id/version_id, falling back to CivitAI search" ) civitai_results = search_civitai( filename, model_type=category ) + log_search_result( + "civitai/fallback", + civitai_results[0] if civitai_results else None, + { + "results_count": len(civitai_results), + }, + ) if civitai_results: first_result = civitai_results[0] results["civitai"] = { @@ -924,16 +997,18 @@ class ModelLinkerExtension: results["found"] = True else: civitai_result = search_civitai_for_file(filename) + log_search_result("civitai", civitai_result) if civitai_result: results["civitai"] = civitai_result results["found"] = True + log_info( + f"Search summary: found={results['found']}, searched_sources={results['searched_sources']}" + ) return web.json_response(results) except Exception as e: - self.logger.error( - f"Model Linker search error: {e}", exc_info=True - ) + log_exception(f"Model Linker search error: {e}") return web.json_response({"error": str(e)}, status=500) @routes.post("/model_linker/download") diff --git a/core/sources/civitai.py b/core/sources/civitai.py index 1c6c798..30d9181 100644 --- a/core/sources/civitai.py +++ b/core/sources/civitai.py @@ -133,6 +133,7 @@ def search_civitai_for_file( cache_key = f"civit_{filename}_exact{exact_only}" if cache_key in _search_cache: + log_debug(f"CivitAI search cache hit for {filename} (exact_only={exact_only})") return _search_cache[cache_key] try: @@ -144,14 +145,22 @@ def search_civitai_for_file( headers["Authorization"] = f"Bearer {api_key}" search_url = f"{CIVITAI_API_URL}/models?query={quote(search_term)}&limit=10" + log_info( + f"CivitAI search start: filename={filename}, query={search_term}, exact_only={exact_only}" + ) response = requests.get(search_url, headers=headers, timeout=15) if response.status_code != 200: - log_debug(f"CivitAI search returned {response.status_code}") + log_warn( + f"CivitAI search returned {response.status_code} for query={search_term}" + ) return None data = response.json() items = data.get("items", []) + log_info( + f"CivitAI search API returned {len(items)} models for query={search_term}" + ) filename_base = os.path.splitext(filename.lower())[0] @@ -159,11 +168,17 @@ def search_civitai_for_file( model_id = item.get("id") model_name = item.get("name", "") model_type = item.get("type", "") + log_debug( + f"CivitAI checking model_id={model_id}, model_name={model_name}, model_type={model_type}" + ) model_versions = item.get("modelVersions", []) for version in model_versions: version_id = version.get("id") files = version.get("files", []) + log_debug( + f"CivitAI checking version_id={version_id} with {len(files)} files for model_id={model_id}" + ) for file_info in files: file_name = file_info.get("name", "") @@ -220,10 +235,13 @@ def search_civitai_for_file( # Not found _search_cache[cache_key] = None + log_info( + f"CivitAI search no result: filename={filename}, query={search_term}, models_checked={len(items)}" + ) return None except Exception as e: - log_error(f"CivitAI search error: {e}") + log_exception(f"CivitAI search error for {filename}: {e}") return None diff --git a/core/sources/huggingface.py b/core/sources/huggingface.py index 82d20ba..c993878 100644 --- a/core/sources/huggingface.py +++ b/core/sources/huggingface.py @@ -98,6 +98,7 @@ def search_huggingface_for_file( cache_key = f"hf_{filename}_exact{exact_only}" if cache_key in _search_cache: + log_debug(f"HuggingFace search cache hit for {filename} (exact_only={exact_only})") return _search_cache[cache_key] try: @@ -110,19 +111,29 @@ def search_huggingface_for_file( # Search for repos containing this filename search_url = f"{HF_API_URL}/models?search={quote(filename_base)}&limit=10" + log_info( + f"HuggingFace search start: filename={filename}, query={filename_base}, exact_only={exact_only}" + ) response = requests.get(search_url, headers=headers, timeout=10) if response.status_code != 200: - log_debug(f"HuggingFace search returned {response.status_code}") + log_warn( + f"HuggingFace search returned {response.status_code} for query={filename_base}" + ) return None repos = response.json() + log_info( + f"HuggingFace search API returned {len(repos)} repos for query={filename_base}" + ) for repo in repos: repo_id = repo.get("id", "") if not repo_id: continue + log_debug(f"HuggingFace checking repo {repo_id} for filename={filename}") + # Check if this repo actually has a matching file files_url = f"{HF_API_URL}/models/{repo_id}/tree/main" @@ -130,6 +141,9 @@ def search_huggingface_for_file( files_response = requests.get(files_url, headers=headers, timeout=10) if files_response.status_code == 200: files = files_response.json() + log_debug( + f"HuggingFace repo {repo_id} returned {len(files)} tree items" + ) for file_info in files: file_path = file_info.get("path", "") @@ -178,15 +192,18 @@ def search_huggingface_for_file( return result except Exception as e: - log_debug(f"Error checking repo {repo_id}: {e}") + log_debug(f"Error checking HuggingFace repo {repo_id}: {e}") continue # Not found _search_cache[cache_key] = None + log_info( + f"HuggingFace search no result: filename={filename}, query={filename_base}, repos_checked={len(repos)}" + ) return None except Exception as e: - log_error(f"HuggingFace search error: {e}") + log_exception(f"HuggingFace search error for {filename}: {e}") return None