Add test for recommend mentors endpoint and enhance logging in services

- Introduced a new test script `test_api.py` to validate the recommend mentors API endpoint.
- Enhanced logging in `embedding_service.py`, `pinecone_service.py`, `recommendation_service.py`, `reranker_service.py`, and `scoring.py` to include timing information for various operations, improving traceability and performance monitoring.
- Improved error handling and logging messages for better clarity and debugging support.

services/embedding_service.py

@@ -1,6 +1,7 @@
 import torch
 from sentence_transformers import SentenceTransformer
 import logging
+import time
 from typing import List, Union
 from config.settings import get_settings
 
@@ -22,9 +23,10 @@ class EmbeddingService:
     def _load_model(self):
         settings = get_settings()
         try:
-            logger.info(f"Loading embedding model: {settings.EMBEDDING_MODEL_NAME}")
+            start_time = time.perf_counter()
+            logger.info(f"[EMBEDDING] Starting to load embedding model: {settings.EMBEDDING_MODEL_NAME}")
             device = "cuda" if torch.cuda.is_available() else "cpu"
-            logger.info(f"Using device: {device}")
+            logger.info(f"[EMBEDDING] Using device: {device}")
             
             EmbeddingService._model = SentenceTransformer(
                 settings.EMBEDDING_MODEL_NAME,
@@ -33,9 +35,10 @@ class EmbeddingService:
             
             EmbeddingService._model.max_seq_length = 2048
             
-            logger.info("Embedding model loaded successfully")
+            load_time = time.perf_counter() - start_time
+            logger.info(f"[EMBEDDING] Embedding model loaded successfully in {load_time:.3f}s")
         except Exception as e:
-            logger.error(f"Failed to load embedding model: {str(e)}")
+            logger.error(f"[EMBEDDING] Failed to load embedding model: {str(e)}", exc_info=True)
             raise
     
     def encode(
@@ -58,6 +61,7 @@ class EmbeddingService:
             raise ValueError("Texts cannot be empty")
         
         try:
+            encode_start = time.perf_counter()
             embeddings = EmbeddingService._model.encode(
                 texts,
                 batch_size=batch_size,
@@ -65,24 +69,26 @@ class EmbeddingService:
                 convert_to_numpy=True,
                 normalize_embeddings=False
             )
+            encode_time = time.perf_counter() - encode_start
+            logger.info(f"[EMBEDDING] Encoded {len(texts)} text(s) in {encode_time:.3f}s (is_query={is_query})")
             
             expected_dim = 1024
             if single_text:
                 embedding_list = embeddings[0].tolist()
                 if len(embedding_list) != expected_dim:
-                    logger.warning(f"Embedding dimension mismatch: expected {expected_dim}, got {len(embedding_list)}")
+                    logger.warning(f"[EMBEDDING] Embedding dimension mismatch: expected {expected_dim}, got {len(embedding_list)}")
                 return embedding_list
             
             result = []
             for emb in embeddings:
                 emb_list = emb.tolist()
                 if len(emb_list) != expected_dim:
-                    logger.warning(f"Embedding dimension mismatch: expected {expected_dim}, got {len(emb_list)}")
+                    logger.warning(f"[EMBEDDING] Embedding dimension mismatch: expected {expected_dim}, got {len(emb_list)}")
                 result.append(emb_list)
             
             return result
         except Exception as e:
-            logger.error(f"Error encoding texts: {str(e)}")
+            logger.error(f"[EMBEDDING] Error encoding texts: {str(e)}", exc_info=True)
             raise
     
     def get_model_info(self) -> dict:

services/pinecone_service.py

@@ -1,6 +1,7 @@
 from pinecone import Pinecone, ServerlessSpec
 from typing import List, Dict, Optional, Any
 import logging
+import time
 from config.settings import get_settings
 
 logger = logging.getLogger(__name__)
@@ -99,14 +100,16 @@ class PineconeService:
         include_metadata: bool = True
     ) -> List[Dict[str, Any]]:
         try:
+            start_time = time.perf_counter()
             settings = get_settings()
             expected_dim = settings.PINECONE_DIMENSION
             
             if len(query_vector) != expected_dim:
                 error_msg = f"Query vector dimension mismatch: expected {expected_dim}, got {len(query_vector)}"
-                logger.error(error_msg)
+                logger.error(f"[PINECONE] {error_msg}")
                 raise ValueError(error_msg)
             
+            logger.info(f"[PINECONE] Querying similar mentors: top_k={top_k}, filter={filter}")
             query_response = PineconeService._index.query(
                 vector=query_vector,
                 top_k=top_k,
@@ -114,6 +117,8 @@ class PineconeService:
                 include_metadata=include_metadata
             )
             
+            query_time = time.perf_counter() - start_time
+            
             results = []
             for match in query_response.matches:
                 results.append({
@@ -122,9 +127,10 @@ class PineconeService:
                     "metadata": match.metadata if include_metadata else None
                 })
             
+            logger.info(f"[PINECONE] Query completed in {query_time:.3f}s: found {len(results)} results")
             return results
         except Exception as e:
-            logger.error(f"Failed to query similar mentors: {str(e)}")
+            logger.error(f"[PINECONE] Failed to query similar mentors: {str(e)}", exc_info=True)
             raise
     
     def delete_mentor(self, mentor_id: str) -> bool:

services/recommendation_service.py

@@ -1,5 +1,6 @@
 from typing import List, Dict, Any, Optional
 import logging
+import time
 from services.embedding_service import EmbeddingService
 from services.pinecone_service import PineconeService
 from services.reranker_service import RerankerService
@@ -71,31 +72,53 @@ class RecommendationService:
         top_k: Optional[int] = None,
         final_count: Optional[int] = None
     ) -> List[Dict[str, Any]]:
+        pipeline_start = time.perf_counter()
+        logger.info("[RECOMMEND] Starting recommendation pipeline")
+        
         try:
             top_k = top_k or self.settings.RECOMMENDATION_TOP_K
             final_count = final_count or self.settings.RECOMMENDATION_FINAL_COUNT
+            logger.info(f"[RECOMMEND] Configuration: top_k={top_k}, rerank_k={self.settings.RECOMMENDATION_RERANK_K}, final_count={final_count}")
             
+            query_build_start = time.perf_counter()
             query_text = build_mentee_query_text(mentee_data)
+            query_build_time = time.perf_counter() - query_build_start
+            logger.info(f"[RECOMMEND] Query text built in {query_build_time:.3f}s: {query_text[:100]}...")
+            
+            embedding_start = time.perf_counter()
             query_embedding = self.embedding_service.encode(query_text, is_query=True)
+            embedding_time = time.perf_counter() - embedding_start
+            logger.info(f"[RECOMMEND] Query embedding generated in {embedding_time:.3f}s")
             
+            filter_start = time.perf_counter()
             filter_dict = self._build_filter(mentee_data)
+            filter_time = time.perf_counter() - filter_start
+            logger.info(f"[RECOMMEND] Filter built in {filter_time:.3f}s: {filter_dict}")
             
+            pinecone_start = time.perf_counter()
             similar_mentors = self.pinecone_service.query_similar(
                 query_vector=query_embedding,
                 top_k=top_k,
                 filter=filter_dict if filter_dict else None,
                 include_metadata=True
             )
+            pinecone_time = time.perf_counter() - pinecone_start
+            logger.info(f"[RECOMMEND] Pinecone query completed in {pinecone_time:.3f}s: found {len(similar_mentors)} candidates")
             
             if not similar_mentors:
+                logger.warning("[RECOMMEND] No similar mentors found, returning empty list")
                 return []
             
+            metadata_start = time.perf_counter()
             for mentor in similar_mentors:
                 metadata = mentor.get("metadata", {})
                 mentor["mentor_text"] = metadata.get("mentor_text", "")
                 if not mentor["mentor_text"]:
-                    logger.warning(f"Mentor {mentor.get('mentor_id', 'unknown')} missing mentor_text in metadata")
+                    logger.warning(f"[RECOMMEND] Mentor {mentor.get('mentor_id', 'unknown')} missing mentor_text in metadata")
+            metadata_time = time.perf_counter() - metadata_start
+            logger.info(f"[RECOMMEND] Metadata extraction completed in {metadata_time:.3f}s")
             
+            reranker_start = time.perf_counter()
             reranker = RerankerService()
             rerank_k = self.settings.RECOMMENDATION_RERANK_K
             
@@ -105,21 +128,34 @@ class RecommendationService:
                     candidates=similar_mentors,
                     top_k=rerank_k
                 )
+                reranker_time = time.perf_counter() - reranker_start
+                logger.info(f"[RECOMMEND] Reranking completed in {reranker_time:.3f}s: {len(reranked_mentors)} mentors reranked")
             except Exception as e:
-                logger.error(f"Reranker failed: {e}. Falling back to cosine similarity.", exc_info=True)
+                reranker_time = time.perf_counter() - reranker_start
+                logger.error(f"[RECOMMEND] Reranker failed after {reranker_time:.3f}s: {e}. Falling back to cosine similarity.", exc_info=True)
                 for mentor in similar_mentors:
                     mentor["reranker_score"] = mentor.get("score", 0.0)
                 reranked_mentors = sorted(similar_mentors, key=lambda x: x.get("reranker_score", 0.0), reverse=True)[:rerank_k]
             
+            scoring_start = time.perf_counter()
             reranked = rerank_mentors(
                 reranked_mentors,
                 mentee_data,
                 final_count=final_count
             )
+            scoring_time = time.perf_counter() - scoring_start
+            logger.info(f"[RECOMMEND] Final scoring completed in {scoring_time:.3f}s: {len(reranked)} final recommendations")
+            
+            total_time = time.perf_counter() - pipeline_start
+            logger.info(f"[RECOMMEND] Recommendation pipeline completed in {total_time:.3f}s")
+            logger.info(f"[RECOMMEND] Time breakdown - Query: {query_build_time:.3f}s, Embedding: {embedding_time:.3f}s, "
+                       f"Pinecone: {pinecone_time:.3f}s, Metadata: {metadata_time:.3f}s, "
+                       f"Reranker: {reranker_time:.3f}s, Scoring: {scoring_time:.3f}s")
             
             return reranked
         except Exception as e:
-            logger.error(f"Failed to recommend mentors: {str(e)}")
+            total_time = time.perf_counter() - pipeline_start
+            logger.error(f"[RECOMMEND] Failed to recommend mentors after {total_time:.3f}s: {str(e)}", exc_info=True)
             raise
     
     def _build_filter(self, mentee_data: Dict[str, Any]) -> Optional[Dict[str, Any]]:

services/reranker_service.py

@@ -1,6 +1,7 @@
 from transformers import AutoTokenizer, AutoModelForSequenceClassification
 import torch
 import logging
+import time
 
 logger = logging.getLogger(__name__)
 
@@ -19,45 +20,69 @@ class RerankerService:
         
         try:
             self.model_name = "AITeamVN/Vietnamese_Reranker"
-            logger.info(f"Loading reranker model: {self.model_name}")
+            logger.info(f"[RERANKER] Starting to load reranker model: {self.model_name}")
+            start_time = time.perf_counter()
             
+            logger.info(f"[RERANKER] Loading tokenizer...")
+            tokenizer_start = time.perf_counter()
             self.tokenizer = AutoTokenizer.from_pretrained(self.model_name)
+            tokenizer_time = time.perf_counter() - tokenizer_start
+            logger.info(f"[RERANKER] Tokenizer loaded in {tokenizer_time:.3f}s")
+            
+            logger.info(f"[RERANKER] Loading model...")
+            model_start = time.perf_counter()
             self.model = AutoModelForSequenceClassification.from_pretrained(self.model_name)
             self.model.eval()
+            model_time = time.perf_counter() - model_start
+            logger.info(f"[RERANKER] Model loaded in {model_time:.3f}s")
             
             self.device = torch.device("cuda" if torch.cuda.is_available() else "cpu")
+            logger.info(f"[RERANKER] Moving model to device: {self.device}")
+            device_start = time.perf_counter()
             self.model.to(self.device)
+            device_time = time.perf_counter() - device_start
+            logger.info(f"[RERANKER] Model moved to device in {device_time:.3f}s")
             
-            logger.info(f"Reranker model loaded successfully on device: {self.device}")
+            total_time = time.perf_counter() - start_time
+            logger.info(f"[RERANKER] Reranker model loaded successfully on device: {self.device} (Total time: {total_time:.3f}s)")
             RerankerService._initialized = True
         except Exception as e:
-            logger.error(f"Failed to load reranker model: {str(e)}", exc_info=True)
+            logger.error(f"[RERANKER] Failed to load reranker model: {str(e)}", exc_info=True)
             raise
 
     def rerank(self, query_text: str, candidates: list, top_k: int = None) -> list:
         if not candidates:
+            logger.info("[RERANKER] No candidates provided, returning empty list")
             return []
 
         if not query_text:
-            logger.warning("Empty query text provided to reranker")
+            logger.warning("[RERANKER] Empty query text provided to reranker")
             return candidates
 
         try:
+            start_time = time.perf_counter()
+            logger.info(f"[RERANKER] Starting reranking for {len(candidates)} candidates")
+            
             pairs = []
             valid_candidates = []
             
+            prep_start = time.perf_counter()
             for cand in candidates:
                 mentor_text = cand.get("mentor_text", "")
                 if mentor_text:
                     pairs.append((query_text, mentor_text))
                     valid_candidates.append(cand)
                 else:
-                    logger.warning(f"Mentor {cand.get('mentor_id', 'unknown')} missing mentor_text, skipping reranking")
+                    logger.warning(f"[RERANKER] Mentor {cand.get('mentor_id', 'unknown')} missing mentor_text, skipping reranking")
+            
+            prep_time = time.perf_counter() - prep_start
+            logger.info(f"[RERANKER] Prepared {len(pairs)} pairs in {prep_time:.3f}s")
             
             if not pairs:
-                logger.warning("No valid candidate pairs for reranking, returning original candidates")
+                logger.warning("[RERANKER] No valid candidate pairs for reranking, returning original candidates")
                 return candidates
 
+            tokenizer_start = time.perf_counter()
             inputs = self.tokenizer(
                 pairs,
                 padding=True,
@@ -65,26 +90,37 @@ class RerankerService:
                 max_length=512,
                 return_tensors="pt"
             ).to(self.device)
+            tokenizer_time = time.perf_counter() - tokenizer_start
+            logger.info(f"[RERANKER] Tokenization completed in {tokenizer_time:.3f}s")
 
+            inference_start = time.perf_counter()
             with torch.no_grad():
                 outputs = self.model(**inputs)
                 scores = torch.sigmoid(outputs.logits).squeeze(-1).cpu().tolist()
+            inference_time = time.perf_counter() - inference_start
+            logger.info(f"[RERANKER] Model inference completed in {inference_time:.3f}s for {len(pairs)} pairs")
 
             if isinstance(scores, float):
                 scores = [scores]
 
+            scoring_start = time.perf_counter()
             for cand, score in zip(valid_candidates, scores):
                 cand["reranker_score"] = float(score)
 
             sorted_candidates = sorted(valid_candidates, key=lambda x: x.get("reranker_score", 0.0), reverse=True)
+            scoring_time = time.perf_counter() - scoring_start
+            logger.info(f"[RERANKER] Scoring and sorting completed in {scoring_time:.3f}s")
             
-            if top_k:
-                return sorted_candidates[:top_k]
-            return sorted_candidates
+            result = sorted_candidates[:top_k] if top_k else sorted_candidates
+            total_time = time.perf_counter() - start_time
+            logger.info(f"[RERANKER] Reranking completed: {len(result)} results returned (Total time: {total_time:.3f}s)")
+            
+            return result
         except Exception as e:
-            logger.error(f"Error during reranking: {str(e)}", exc_info=True)
+            logger.error(f"[RERANKER] Error during reranking: {str(e)}", exc_info=True)
             for cand in candidates:
                 if "reranker_score" not in cand:
                     cand["reranker_score"] = cand.get("score", 0.0)
             return sorted(candidates, key=lambda x: x.get("reranker_score", 0.0), reverse=True)[:top_k] if top_k else candidates
 
+

test_api.py

@@ -0,0 +1,110 @@
+import requests
+import json
+
+BASE_URL = "https://mentorme666-mentorme.hf.space/api/v1"
+
+def test_recommend():
+    """Test recommend mentors endpoint"""
+    print("Testing Recommend Mentors...")
+    print("="*60)
+    
+    recommendation_data = {
+        "goals": "Tôi muốn học Python và FastAPI để phát triển web",
+        "desired_skills": [
+            {"id": 1, "name": "Python"},
+            {"id": 2, "name": "FastAPI"}
+        ],
+        "interests": [
+            {"id": 1, "name": "Web Development"}
+        ],
+        "min_rating": 4.0,
+        "require_availability": True,
+        "skill_ids": [1, 2],
+        "domain_ids": [1],
+        "top_k": 30,
+        "final_count": 6
+    }
+    
+    try:
+        print(f"Request URL: {BASE_URL}/recommend")
+        print(f"Request Data: {json.dumps(recommendation_data, indent=2, ensure_ascii=False)}")
+        print("\nSending request...")
+        
+        response = requests.post(
+            f"{BASE_URL}/recommend",
+            json=recommendation_data,
+            headers={
+                "Content-Type": "application/json",
+                "User-Agent": "Mozilla/5.0",
+                "Accept": "application/json"
+            },
+            timeout=60
+        )
+        
+        print(f"\n{'='*60}")
+        print("Response:")
+        print(f"{'='*60}")
+        print(f"Status Code: {response.status_code}")
+        print(f"URL: {response.url}")
+        
+        if response.status_code == 200:
+            try:
+                result = response.json()
+                print(f"\nResponse JSON:")
+                print(json.dumps(result, indent=2, ensure_ascii=False))
+                
+                if "mentors" in result:
+                    print(f"\nFound {result.get('count', 0)} recommended mentors:")
+                    for i, mentor in enumerate(result["mentors"], 1):
+                        print(f"\n{i}. Mentor ID: {mentor.get('mentor_id')}")
+                        print(f"   Score: {mentor.get('score', 0):.4f}")
+                        print(f"   Semantic Similarity: {mentor.get('semantic_similarity', 0):.4f}")
+                        print(f"   Reason: {mentor.get('reason', 'N/A')}")
+                        if "metadata" in mentor:
+                            meta = mentor["metadata"]
+                            print(f"   Rating: {meta.get('rating', 'N/A')}")
+                            print(f"   Available Slots: {meta.get('available_slots', 0)}")
+                
+                if "query_text" in result:
+                    print(f"\nQuery Text: {result['query_text']}")
+                
+                print(f"\n{'='*60}")
+                print("[PASSED] Test completed successfully!")
+                return True
+            except json.JSONDecodeError:
+                print(f"Response Text: {response.text}")
+                print(f"\n{'='*60}")
+                print("[FAILED] Invalid JSON response")
+                return False
+        else:
+            print(f"Response Text: {response.text}")
+            print(f"\n{'='*60}")
+            print(f"[FAILED] Status code: {response.status_code}")
+            return False
+            
+    except requests.exceptions.Timeout:
+        print(f"\n{'='*60}")
+        print("[FAILED] Request timeout")
+        return False
+    except requests.exceptions.ConnectionError as e:
+        print(f"\n{'='*60}")
+        print(f"[FAILED] Connection error: {str(e)}")
+        return False
+    except Exception as e:
+        print(f"\n{'='*60}")
+        print(f"[FAILED] Error: {str(e)}")
+        return False
+
+if __name__ == "__main__":
+    print("\n" + "="*60)
+    print("MentorMe AI Service - Recommend API Test")
+    print("="*60 + "\n")
+    
+    success = test_recommend()
+    
+    print("\n" + "="*60)
+    if success:
+        print("Test Result: PASSED")
+    else:
+        print("Test Result: FAILED")
+    print("="*60 + "\n")

utils/scoring.py

@@ -1,15 +1,23 @@
 from typing import List, Dict, Any
 import math
+import logging
+import time
 from config.settings import get_settings
 
+logger = logging.getLogger(__name__)
+
 def rerank_mentors(
     similar_mentors: List[Dict[str, Any]],
     mentee_data: Dict[str, Any],
     final_count: int = 8
 ) -> List[Dict[str, Any]]:
+    start_time = time.perf_counter()
+    logger.info(f"[SCORING] Starting final scoring for {len(similar_mentors)} mentors, final_count={final_count}")
+    
     settings = get_settings()
     scored_mentors = []
     
+    scoring_start = time.perf_counter()
     for mentor in similar_mentors:
         metadata = mentor.get("metadata", {})
         
@@ -48,9 +56,19 @@ def rerank_mentors(
             "reason": reason
         })
     
+    scoring_time = time.perf_counter() - scoring_start
+    logger.info(f"[SCORING] Scoring completed in {scoring_time:.3f}s")
+    
+    sort_start = time.perf_counter()
     scored_mentors.sort(key=lambda x: x["score"], reverse=True)
+    sort_time = time.perf_counter() - sort_start
+    logger.info(f"[SCORING] Sorting completed in {sort_time:.3f}s")
+    
+    result = scored_mentors[:final_count]
+    total_time = time.perf_counter() - start_time
+    logger.info(f"[SCORING] Final scoring completed in {total_time:.3f}s: {len(result)} mentors returned")
     
-    return scored_mentors[:final_count]
+    return result
 
 def _calculate_rating_score(rating: float) -> float:
     if rating <= 0: