feat: detailed step-by-step pipeline logging

- LiveSearch: logs each step (NewsAPI/DDG source, article titles, Jina extraction per-URL)
- JinaReranker: logs input docs, per-rank scores with source/title
- RAG pipeline: logs hybrid search start/end, merged results with scores
- Entity extraction: logs to INFO instead of print()
- Quality filter: logs doc count after blocked-source filter

src/core/orchestrator/query_orchestrator.py

@@ -447,93 +447,97 @@ class QueryOrchestrator:
     
     async def _execute_live_search(self, query: str) -> List[Dict[str, Any]]:
         """
-        Execute live search with Jina Reader enhancement.
-        
-        Strategy:
-        1. Try NewsAPI first (if available and temporal query)
-        2. Fallback to DuckDuckGo
-        3. Extract full articles using Jina Reader (parallel)
-        4. Replace snippets with full content (14,000+ chars)
-        5. Fallback to snippets if extraction fails
-        
-        Args:
-            query: Search query (English)
-        
-        Returns:
-            List of enhanced live search results with full articles
+        Execute live search: NewsAPI → DuckDuckGo fallback → Jina Reader enhancement.
         """
         results = []
-        
-        # Try NewsAPI first (best for temporal queries)
+        source_used = None
+
+        # ── Step 1: Try NewsAPI first ─────────────────────────────────────────
         if self.newsapi and self.newsapi.is_available():
             try:
-                logger.info(f"Live search: trying NewsAPI first for '{query}'")
+                logger.info(f"[LiveSearch] Step 1/3 — NewsAPI search: '{query[:60]}'")
                 newsapi_results = await self.newsapi.search(query)
-                
                 if newsapi_results:
-                    logger.info(f"NewsAPI: {len(newsapi_results)} results")
+                    logger.info(f"[LiveSearch] NewsAPI returned {len(newsapi_results)} articles")
+                    for i, r in enumerate(newsapi_results[:3], 1):
+                        logger.info(f"[LiveSearch]   NewsAPI #{i}: [{r.get('published_at','?')[:10]}] {r.get('title','?')[:70]}")
                     results.extend(newsapi_results)
+                    source_used = "newsapi"
                 else:
-                    logger.info("NewsAPI: no results, falling back to DuckDuckGo")
+                    logger.info("[LiveSearch] NewsAPI returned 0 results → falling back to DuckDuckGo")
             except Exception as e:
-                logger.warning(f"NewsAPI failed: {e}, falling back to DuckDuckGo")
-        
-        # Fallback to DuckDuckGo (or primary if NewsAPI not available)
+                logger.warning(f"[LiveSearch] NewsAPI failed: {e} → falling back to DuckDuckGo")
+        else:
+            logger.info("[LiveSearch] NewsAPI not available → using DuckDuckGo directly")
+
+        # ── Step 2: DuckDuckGo fallback ───────────────────────────────────────
         if not results:
             try:
-                logger.info(f"Live search: using DuckDuckGo for '{query}'")
+                logger.info(f"[LiveSearch] Step 1/3 — DuckDuckGo search: '{query[:60]}'")
                 results = await self.live_search.search(query)
-                logger.info(f"DuckDuckGo: {len(results)} results")
+                if results:
+                    logger.info(f"[LiveSearch] DuckDuckGo returned {len(results)} articles")
+                    for i, r in enumerate(results[:3], 1):
+                        logger.info(f"[LiveSearch]   DDG #{i}: [{r.get('published_at','?')[:10]}] {r.get('title','?')[:70]}")
+                    source_used = "duckduckgo"
+                else:
+                    logger.warning("[LiveSearch] DuckDuckGo returned 0 results")
             except Exception as e:
-                logger.error(f"DuckDuckGo search error: {e}")
+                logger.error(f"[LiveSearch] DuckDuckGo search error: {e}")
                 return []
-        
+
         if not results:
-            logger.warning("No live search results from any source")
+            logger.warning("[LiveSearch] No live search results from any source")
             return results
-        
-        # Step 2: Check if Jina Reader is enabled
+
+        logger.info(f"[LiveSearch] Step 2/3 — Got {len(results)} raw results from {source_used}")
+
+        # ── Step 3: Jina Reader article extraction ────────────────────────────
         from src.core.config import settings
-        
+
         if not settings.ENABLE_JINA_READER:
-            logger.info("Jina Reader disabled - using snippets only")
+            logger.info("[LiveSearch] Step 3/3 — Jina Reader disabled, using snippets only")
             return results
-        
-        # Step 3: Try to enhance with Jina Reader
+
         try:
             from src.infrastructure.adapters.jina_reader_adapter import get_jina_reader_adapter
-            
+
             jina = get_jina_reader_adapter(
                 timeout=settings.JINA_READER_TIMEOUT,
                 max_concurrent=settings.JINA_READER_MAX_CONCURRENT
             )
-            
-            # Step 4: Extract full articles (replaces snippets)
+
+            logger.info(f"[LiveSearch] Step 3/3 — Jina Reader extracting full articles from {len(results)} URLs")
+            urls_to_extract = [r.get("url", "?")[:80] for r in results[:5]]
+            for i, url in enumerate(urls_to_extract, 1):
+                logger.info(f"[LiveSearch]   Extracting #{i}: {url}")
+
             enhanced_results = await jina.enhance_search_results(
                 results,
-                fallback_to_snippet=True  # Keep snippet if Jina fails
+                fallback_to_snippet=True
             )
-            
-            # Log enhancement stats
+
             full_articles = sum(1 for r in enhanced_results if r.get("full_article"))
             snippets = len(enhanced_results) - full_articles
-            total_chars = sum(
-                r.get("content_length", 0) 
-                for r in enhanced_results 
-                if r.get("full_article")
-            )
-            
+            total_chars = sum(r.get("content_length", 0) for r in enhanced_results if r.get("full_article"))
+            avg_chars = total_chars // full_articles if full_articles else 0
+
             logger.info(
-                f"Jina enhancement: {full_articles} full articles ({total_chars:,} chars), "
-                f"{snippets} snippets (fallback)"
+                f"[LiveSearch] Jina extraction complete: "
+                f"{full_articles}/{len(enhanced_results)} full articles, "
+                f"{snippets} snippets, "
+                f"{total_chars:,} total chars (avg {avg_chars:,}/article)"
             )
-            
+            for i, r in enumerate(enhanced_results[:5], 1):
+                status = "FULL" if r.get("full_article") else f"SNIPPET({r.get('jina_error','?')})"
+                chars = r.get("content_length", len(r.get("content", "")))
+                logger.info(f"[LiveSearch]   #{i} [{status}] {chars:,} chars — {r.get('title','?')[:60]}")
+
             return enhanced_results
-            
+
         except ImportError:
-            logger.warning("Jina Reader not available - using snippets only")
+            logger.warning("[LiveSearch] Jina Reader not available — using snippets only")
             return results
-        
         except Exception as e:
-            logger.warning(f"Jina Reader enhancement failed: {e} - using snippets")
+            logger.warning(f"[LiveSearch] Jina Reader failed: {e} — using snippets")
             return results

src/core/use_cases/rag_chat_use_case.py

@@ -359,11 +359,11 @@ JSON:"""
             from src.infrastructure.adapters.entity_extractor import entity_extractor
             if entity_extractor:
                 entities = entity_extractor.extract(query)
-                logger.info(f"[RAG] Extracted entities:")
-                print(f"  - Locations: {entities.locations}")
-                print(f"  - Organizations: {entities.organizations}")
-                print(f"  - Temporal keywords: {entities.temporal_keywords}")
-                
+                logger.info(
+                    f"[RAG] Entities — locations={entities.locations} "
+                    f"orgs={entities.organizations} "
+                    f"temporal={entities.temporal_keywords}"
+                )
                 # Auto-detect source filter if not provided
                 if not source_filter:
                     auto_source = entity_extractor.get_source_filter(entities)
@@ -481,7 +481,11 @@ JSON:"""
 
         # ── HYBRID SEARCH EXECUTION ────────────────────────────────────────────
         if use_hybrid and strategy and (strategy.use_live or strategy.use_db):
-            logger.info(f"[RAG] Executing hybrid search...")
+            logger.info(
+                f"[RAG] ═══ HYBRID SEARCH START ═══ "
+                f"live={strategy.use_live} db={strategy.use_db} "
+                f"weights={strategy.live_weight:.1f}/{strategy.db_weight:.1f}"
+            )
             
             # Execute hybrid search (parallel live + DB)
             try:
@@ -495,21 +499,31 @@ JSON:"""
                     top_k=per_lang_limit
                 )
                 
-                logger.info(f"[RAG] Hybrid search returned {len(db_results)} DB + {len(live_results)} live results")
+                logger.info(
+                    f"[RAG] Hybrid search raw results: "
+                    f"{len(db_results)} DB docs + {len(live_results)} live docs"
+                )
                 
                 # Merge and rank results
+                logger.info(f"[RAG] Merging and ranking {len(db_results)+len(live_results)} total candidates...")
                 all_docs = self.hybrid_ranker.merge_and_rank(
                     db_results=db_results,
                     live_results=live_results,
                     strategy=strategy,
                     query=expanded_query,
-                    final_top_n=top_k * 3  # Get more candidates for quality filtering
+                    final_top_n=top_k * 3
                 )
                 
-                logger.info(f"[RAG] After hybrid ranking: {len(all_docs)} results")
+                logger.info(f"[RAG] After hybrid ranking: {len(all_docs)} docs")
+                for i, doc in enumerate(all_docs[:5], 1):
+                    score = doc.get("rerank_score") or doc.get("score", 0)
+                    src = doc.get("source") or doc.get("metadata", {}).get("source", "?")
+                    stype = doc.get("source_type", "db")
+                    title = doc.get("title") or doc.get("content", "")[:60]
+                    logger.info(f"[RAG]   Merged #{i}: score={score:.3f} [{stype}] src={src} — {title[:60]}")
                 
             except Exception as e:
-                logger.info(f"[RAG] Hybrid search failed: {e} - falling back to traditional pipeline")
+                logger.warning(f"[RAG] Hybrid search failed: {e} — falling back to traditional pipeline")
                 use_hybrid = False
                 all_docs = []
         
@@ -616,6 +630,8 @@ JSON:"""
             if (d.get("metadata", {}).get("source") or "").lower().replace(" ", "") not in _BLOCKED_SOURCES
         ] or all_docs
 
+        logger.info(f"[RAG] After blocked-source filter: {len(quality_docs)} docs")
+
         # ── Relevance threshold — drop docs the reranker scored too low ───────
         # Raised from 0.15 → 0.25 based on live testing.
         # The airport article (bbc_swahili) was scoring ~0.18 on GERD queries

src/infrastructure/adapters/jina_reranker_adapter.py

@@ -75,7 +75,6 @@ class JinaRerankerAPIAdapter(RerankerPort):
     ) -> List[Dict[str, Any]]:
         """
         Rerank documents using Jina API.
-        
         Sends all docs in one request — Jina returns them sorted by relevance.
         Falls back to vector score ordering if API unavailable.
         """
@@ -83,10 +82,9 @@ class JinaRerankerAPIAdapter(RerankerPort):
             return []
 
         if not self.api_key:
-            logger.warning("Jina Reranker API disabled — falling back to score ordering")
+            logger.warning("[JinaReranker] API disabled — falling back to score ordering")
             return sorted(docs, key=lambda x: x.get("score", 0), reverse=True)[:top_n]
 
-        # Extract text content — truncate to 2048 chars (Jina handles tokenization)
         MAX_CHARS = 2048
         valid_docs = []
         doc_texts = []
@@ -99,6 +97,14 @@ class JinaRerankerAPIAdapter(RerankerPort):
         if not doc_texts:
             return []
 
+        logger.info(
+            f"[JinaReranker] Reranking {len(valid_docs)} docs for query: '{query[:60]}'"
+        )
+        for i, doc in enumerate(valid_docs[:5], 1):
+            chars = len(doc.get("content", ""))
+            src = doc.get("source") or doc.get("metadata", {}).get("source", "?")
+            logger.info(f"[JinaReranker]   Input #{i}: {chars:,} chars — src={src} — {doc.get('title', doc.get('content',''))[:60]}")
+
         t0 = time.time()
         try:
             response = self._get_client().post(
@@ -107,8 +113,8 @@ class JinaRerankerAPIAdapter(RerankerPort):
                     "model": self.model,
                     "query": query,
                     "documents": doc_texts,
-                    "top_n": len(doc_texts),  # Get all scores, we'll slice ourselves
-                    "return_documents": False,  # Save tokens — we already have the docs
+                    "top_n": len(doc_texts),
+                    "return_documents": False,
                 }
             )
 
@@ -119,42 +125,40 @@ class JinaRerankerAPIAdapter(RerankerPort):
                 results = data.get("results", [])
                 usage = data.get("usage", {})
 
-                # results = [{"index": int, "relevance_score": float}, ...]
-                # Restore scores to original docs
                 for r in results:
                     idx = r["index"]
                     if idx < len(valid_docs):
                         valid_docs[idx]["rerank_score"] = float(r["relevance_score"])
 
-                # Sort by rerank_score descending
                 valid_docs.sort(key=lambda x: x.get("rerank_score", 0), reverse=True)
 
                 logger.info(
-                    f"[JinaReranker] {len(valid_docs)} docs → top {top_n} "
-                    f"in {elapsed_ms:.0f}ms "
-                    f"(tokens={usage.get('total_tokens', '?')}, "
-                    f"top_score={valid_docs[0].get('rerank_score', 0):.3f})"
+                    f"[JinaReranker] Done in {elapsed_ms:.0f}ms — "
+                    f"{len(valid_docs)} docs ranked, tokens={usage.get('total_tokens', '?')}"
                 )
+                for i, doc in enumerate(valid_docs[:top_n], 1):
+                    score = doc.get("rerank_score", 0)
+                    src = doc.get("source") or doc.get("metadata", {}).get("source", "?")
+                    title = doc.get("title") or doc.get("content", "")[:60]
+                    logger.info(f"[JinaReranker]   Rank #{i}: score={score:.4f} src={src} — {title[:60]}")
+
                 return valid_docs[:top_n]
 
             elif response.status_code == 401:
-                logger.error("Jina Reranker API: Invalid API key")
+                logger.error("[JinaReranker] Invalid API key")
             elif response.status_code == 429:
-                logger.warning("Jina Reranker API: Rate limit exceeded")
+                logger.warning("[JinaReranker] Rate limit exceeded")
             elif response.status_code == 402:
-                logger.warning("Jina Reranker API: Insufficient tokens — top up at jina.ai")
+                logger.warning("[JinaReranker] Insufficient tokens — top up at jina.ai")
             else:
-                logger.warning(
-                    f"Jina Reranker API: HTTP {response.status_code} — {response.text[:200]}"
-                )
+                logger.warning(f"[JinaReranker] HTTP {response.status_code} — {response.text[:200]}")
 
         except httpx.TimeoutException:
-            logger.warning(f"Jina Reranker API: timeout ({self.timeout}s)")
+            logger.warning(f"[JinaReranker] Timeout ({self.timeout}s)")
         except Exception as e:
-            logger.error(f"Jina Reranker API error: {e}")
+            logger.error(f"[JinaReranker] Error: {e}")
 
-        # Fallback: sort by vector score
-        logger.warning("Jina Reranker API failed — falling back to vector score ordering")
+        logger.warning("[JinaReranker] API failed — falling back to vector score ordering")
         return sorted(docs, key=lambda x: x.get("score", 0), reverse=True)[:top_n]
 
     def is_available(self) -> bool: