B

app/services/subscriptions.py

@@ -2,6 +2,7 @@ from __future__ import annotations
 
 import base64
 import json
+import logging
 import re
 from typing import Any, Iterable
 from urllib.parse import parse_qs, unquote, urlparse
@@ -16,6 +17,7 @@ from app.services.fetch_cache import build_fetch_cache_key, load_fetch_cache, sa
 from app.services.headers import parse_subscription_userinfo
 
 
+logger = logging.getLogger(__name__)
 _fetch_cache: TTLCache[FetchResult] = TTLCache()
 _provider_cache: TTLCache[ProviderDocument] = TTLCache()
 _snapshot_cache: TTLCache[SourceSnapshot] = TTLCache()
@@ -26,6 +28,7 @@ async def fetch_source(name: str, source: SourceConfig) -> FetchResult:
     ttl = source.cache_ttl_seconds or settings.cache_ttl_seconds
     cached = _fetch_cache.get(name)
     if cached is not None:
+        logger.info("fetch_source memory cache hit: source=%s ttl=%s", name, ttl)
         return cached
 
     cache_key = build_fetch_cache_key(name=name, url=source.url)
@@ -35,17 +38,24 @@ async def fetch_source(name: str, source: SourceConfig) -> FetchResult:
         ttl_seconds=ttl,
     )
     if disk_cached is not None:
+        logger.info("fetch_source disk cache hit: source=%s ttl=%s path=%s", name, ttl, settings.fetch_cache_dir)
         result = FetchResult(text=disk_cached.text, headers=disk_cached.headers)
         _fetch_cache.set(name, result, ttl)
         return result
 
     headers = {"User-Agent": settings.default_user_agent}
     headers.update(source.headers)
+    logger.info("fetch_source upstream request: source=%s url=%s ttl=%s", name, source.url, ttl)
 
     async with httpx.AsyncClient(timeout=settings.request_timeout_seconds, follow_redirects=True) as client:
-        response = await client.get(source.url, headers=headers)
-        response.raise_for_status()
+        try:
+            response = await client.get(source.url, headers=headers)
+            response.raise_for_status()
+        except Exception:
+            logger.exception("fetch_source upstream request failed: source=%s url=%s", name, source.url)
+            raise
         result = FetchResult(text=response.text, headers=dict(response.headers))
+        logger.info("fetch_source upstream success: source=%s status=%s bytes=%s", name, response.status_code, len(result.text))
         _fetch_cache.set(name, result, ttl)
         save_fetch_cache(
             cache_dir=settings.fetch_cache_dir,
@@ -66,8 +76,9 @@ async def build_provider_document(name: str, source: SourceConfig) -> ProviderDo
 
     fetched = await fetch_source(name, source)
 
-    proxies = parse_source_proxies(fetched.text, source.kind)
+    proxies = parse_source_proxies(fetched.text, source.kind, source_name=name)
     proxies = transform_proxies(proxies, source, settings.max_proxy_name_length)
+    logger.info("build_provider_document success: source=%s proxies=%s", name, len(proxies))
 
     document = ProviderDocument(proxies=proxies)
     _provider_cache.set(cache_key, document, ttl)
@@ -98,6 +109,7 @@ async def build_source_snapshot(name: str, source: SourceConfig) -> SourceSnapsh
 async def build_source_snapshots(source_items: Iterable[tuple[str, SourceConfig]]) -> list[SourceSnapshot]:
     snapshots: list[SourceSnapshot] = []
     for name, source in source_items:
+        logger.info("build_source_snapshots start: source=%s", name)
         snapshots.append(await build_source_snapshot(name, source))
     return snapshots
 
@@ -152,7 +164,7 @@ def parse_clash_yaml_proxies(text: str) -> list[dict[str, Any]]:
     return normalized
 
 
-def parse_source_proxies(text: str, source_kind: str) -> list[dict[str, Any]]:
+def parse_source_proxies(text: str, source_kind: str, source_name: str = "-") -> list[dict[str, Any]]:
     parsers: dict[str, list] = {
         "auto": [parse_clash_yaml_proxies, parse_base64_uri_proxies, parse_uri_text_proxies],
         "clash_yaml": [parse_clash_yaml_proxies],
@@ -164,10 +176,25 @@ def parse_source_proxies(text: str, source_kind: str) -> list[dict[str, Any]]:
         try:
             proxies = parser(text)
             if proxies:
+                logger.info(
+                    "parse_source_proxies success: source=%s kind=%s parser=%s proxies=%s",
+                    source_name,
+                    source_kind,
+                    parser.__name__,
+                    len(proxies),
+                )
                 return proxies
         except Exception as exc:  # noqa: BLE001
+            logger.warning(
+                "parse_source_proxies parser failed: source=%s kind=%s parser=%s error=%s",
+                source_name,
+                source_kind,
+                parser.__name__,
+                exc,
+            )
             errors.append(f"{parser.__name__}: {exc}")
     detail = "; ".join(errors) if errors else f"unsupported source kind: {source_kind}"
+    logger.error("parse_source_proxies failed: source=%s kind=%s detail=%s", source_name, source_kind, detail)
     raise ValueError(f"Failed to parse upstream subscription: {detail}")