Update app.py

app.py

@@ -1,6 +1,6 @@
 """
-Elderly HealthWatch AI Backend (FastAPI) - With GCS Support
-Simplified: Just upload gcs-credentials.json to repository root
+Elderly HealthWatch AI Backend (FastAPI) - With GCS Support and Detailed Logging
+Enhanced with comprehensive logging at every step
 """
 
 import io
@@ -38,7 +38,10 @@ except Exception:
 # ============================================================================
 # Configuration
 # ============================================================================
-logging.basicConfig(level=logging.INFO)
+logging.basicConfig(
+    level=logging.INFO,
+    format='%(asctime)s - %(name)s - %(levelname)s - %(message)s'
+)
 logger = logging.getLogger("elderly_healthwatch")
 
 GRADIO_VLM_SPACE = os.getenv("GRADIO_SPACE", "developer0hye/Qwen3-VL-8B-Instruct")
@@ -50,14 +53,11 @@ GCS_BUCKET_NAME = "elderly-healthwatch-images"
 GCS_CREDENTIALS_FILE = "gcs-credentials.json"
 
 DEFAULT_VLM_PROMPT = (
-    "Analyze the provided face and eye images and extract only the following screening features: "
-    "pallor, sclera_yellowness, eye_redness, facial_mobility_metrics, and image_quality_checks. "
-    "Return a single valid JSON object only (no text, no markdown). "
-    "Each feature value must be a normalized confidence score between 0 and 1. "
-    "If a feature cannot be reliably determined, assign null."
+    "From the provided face/eye images, compute the required screening features "
+    "(pallor, sclera yellowness, redness, mobility metrics, quality checks) "
+    "and output a clean JSON feature vector only."
 )
 
-
 LLM_SYSTEM_PROMPT = (
     "System: This assistant MUST ONLY OUTPUT a single valid JSON object as its response — "
     "no prose, no explanations, no code fences, no annotations."
@@ -81,17 +81,42 @@ screenings_db: Dict[str, Dict[str, Any]] = {}
 # ============================================================================
 def setup_gcs_client():
     """Initialize GCS client from credentials file"""
+    logger.info("=" * 80)
+    logger.info("INITIALIZING GOOGLE CLOUD STORAGE")
+    logger.info("=" * 80)
+    
     if not GCS_AVAILABLE:
-        logger.warning("GCS libraries not installed")
+        logger.warning("❌ GCS libraries not installed")
         return None, None
     
     try:
+        logger.info("Looking for credentials file: %s", GCS_CREDENTIALS_FILE)
+        logger.info("Current working directory: %s", os.getcwd())
+        logger.info("Credentials file exists: %s", os.path.exists(GCS_CREDENTIALS_FILE))
+        
         if os.path.exists(GCS_CREDENTIALS_FILE):
-            logger.info("Found GCS credentials file: %s", GCS_CREDENTIALS_FILE)
+            logger.info("✅ Found GCS credentials file")
+            logger.info("File size: %d bytes", os.path.getsize(GCS_CREDENTIALS_FILE))
+            
             credentials = service_account.Credentials.from_service_account_file(GCS_CREDENTIALS_FILE)
+            logger.info("✅ Credentials loaded successfully")
+            
             client = storage.Client(credentials=credentials)
+            logger.info("✅ Storage client created")
+            
             bucket = client.bucket(GCS_BUCKET_NAME)
-            logger.info("✅ GCS initialized successfully for bucket: %s", GCS_BUCKET_NAME)
+            logger.info("✅ Bucket reference obtained: %s", GCS_BUCKET_NAME)
+            
+            # Test bucket access
+            try:
+                bucket.exists()
+                logger.info("✅ Bucket access verified")
+            except Exception as e:
+                logger.warning("⚠️ Could not verify bucket access: %s", str(e))
+            
+            logger.info("=" * 80)
+            logger.info("✅ GCS INITIALIZATION SUCCESSFUL")
+            logger.info("=" * 80)
             return client, bucket
         else:
             logger.warning("⚠️ GCS credentials file not found at: %s", GCS_CREDENTIALS_FILE)
@@ -99,25 +124,43 @@ def setup_gcs_client():
             return None, None
     
     except Exception as e:
-        logger.exception("Failed to initialize GCS: %s", str(e))
+        logger.exception("❌ Failed to initialize GCS: %s", str(e))
         return None, None
 
 gcs_client, gcs_bucket = setup_gcs_client()
 
 def upload_to_gcs(local_path: str, blob_name: str) -> Optional[str]:
     """Upload file to GCS and return public URL"""
+    logger.info("-" * 80)
+    logger.info("UPLOADING TO GCS")
+    logger.info("  - Local path: %s", local_path)
+    logger.info("  - Blob name: %s", blob_name)
+    logger.info("  - File exists: %s", os.path.exists(local_path))
+    
+    if os.path.exists(local_path):
+        logger.info("  - File size: %d bytes", os.path.getsize(local_path))
+    
     if gcs_bucket is None:
+        logger.warning("  ❌ GCS bucket not available")
         return None
     
     try:
         blob = gcs_bucket.blob(blob_name)
+        logger.info("  - Blob object created")
+        
         blob.upload_from_filename(local_path, content_type='image/jpeg')
+        logger.info("  ✅ File uploaded to GCS")
+        
         blob.make_public()
+        logger.info("  ✅ Blob made public")
+        
         public_url = blob.public_url
-        logger.info("✅ Uploaded to GCS: %s -> %s", blob_name, public_url[:60])
+        logger.info("  ✅ Public URL: %s", public_url)
+        logger.info("  - URL length: %d", len(public_url))
+        
         return public_url
     except Exception as e:
-        logger.exception("Failed to upload to GCS: %s", str(e))
+        logger.exception("❌ Failed to upload to GCS: %s", str(e))
         return None
 
 # ============================================================================
@@ -160,7 +203,10 @@ face_detector, detector_type = setup_face_detector()
 # Utility Functions
 # ============================================================================
 def load_image_from_bytes(bytes_data: bytes) -> Image.Image:
-    return Image.open(io.BytesIO(bytes_data)).convert("RGB")
+    logger.info("Loading image from bytes (size: %d)", len(bytes_data))
+    img = Image.open(io.BytesIO(bytes_data)).convert("RGB")
+    logger.info("  - Image loaded: %s, size: %s", img.mode, img.size)
+    return img
 
 def normalize_probability(val: Optional[float]) -> float:
     """Normalize probability to 0-1 range"""
@@ -340,7 +386,7 @@ def extract_json_from_llm_output(raw_text: str) -> Dict[str, Any]:
     }
 
 # ============================================================================
-# VLM Integration - WITH GCS URL SUPPORT
+# VLM Integration - WITH GCS URL SUPPORT AND DETAILED LOGGING
 # ============================================================================
 def get_gradio_client(space: str) -> Client:
     """Get Gradio client with optional auth"""
@@ -350,14 +396,39 @@ def get_gradio_client(space: str) -> Client:
 
 def call_vlm_with_urls(face_url: str, eye_url: str, prompt: Optional[str] = None) -> Tuple[Optional[Dict], str]:
     """Call VLM using image URLs instead of file handles"""
+    logger.info("=" * 80)
+    logger.info("STARTING VLM CALL WITH URLS")
+    logger.info("=" * 80)
+    
+    # Step 1: Validate inputs
+    logger.info("STEP 1: Validating inputs")
+    logger.info("  - Face URL provided: %s", bool(face_url))
+    logger.info("  - Face URL length: %d", len(face_url) if face_url else 0)
+    logger.info("  - Face URL (full): %s", face_url)
+    logger.info("  - Eye URL provided: %s", bool(eye_url))
+    logger.info("  - Eye URL length: %d", len(eye_url) if eye_url else 0)
+    logger.info("  - Eye URL (full): %s", eye_url)
+    
     prompt = prompt or DEFAULT_VLM_PROMPT
+    logger.info("  - Prompt provided: %s", bool(prompt))
+    logger.info("  - Prompt length: %d chars", len(prompt))
+    logger.info("  - Prompt (first 200 chars): %s", prompt[:200])
     
-    logger.info("🔗 VLM Input - Face URL: %s", face_url[:80])
-    logger.info("🔗 VLM Input - Eye URL: %s", eye_url[:80])
+    # Step 2: Initialize Gradio client
+    logger.info("STEP 2: Initializing Gradio client")
+    logger.info("  - VLM Space: %s", GRADIO_VLM_SPACE)
+    logger.info("  - HF Token provided: %s", bool(HF_TOKEN))
     
-    client = get_gradio_client(GRADIO_VLM_SPACE)
+    try:
+        client = get_gradio_client(GRADIO_VLM_SPACE)
+        logger.info("  ✅ Gradio client initialized successfully")
+    except Exception as e:
+        logger.error("  ❌ Failed to initialize Gradio client: %s", str(e))
+        logger.exception("Client initialization error:")
+        raise
     
-    # Try different message formats that VLM spaces commonly accept
+    # Step 3: Prepare message formats
+    logger.info("STEP 3: Preparing message formats")
     message_formats = [
         # Format 1: URLs in files array
         {"text": prompt, "files": [face_url, eye_url]},
@@ -368,80 +439,135 @@ def call_vlm_with_urls(face_url: str, eye_url: str, prompt: Optional[str] = None
         # Format 4: Images array
         {"text": prompt, "images": [face_url, eye_url]},
     ]
+    logger.info("  - Prepared %d message format variations", len(message_formats))
     
     last_error = None
     
+    # Step 4: Try each message format
     for idx, message in enumerate(message_formats, 1):
+        logger.info("-" * 80)
+        logger.info("STEP 4.%d: Trying message format %d/%d", idx, idx, len(message_formats))
+        logger.info("  - Format keys: %s", list(message.keys()))
+        logger.info("  - Format structure (first 300 chars): %s", str(message)[:300])
+        
         try:
-            logger.info("Trying VLM message format %d/%d: %s", idx, len(message_formats), list(message.keys()))
+            logger.info("  - Calling VLM API with /chat_fn endpoint...")
             result = client.predict(message=message, history=[], api_name="/chat_fn")
+            logger.info("  ✅ API call succeeded!")
             
-            logger.info("✅ VLM call succeeded with format %d", idx)
-            logger.info("VLM raw result type: %s", type(result))
+            # Step 5: Process result
+            logger.info("STEP 5: Processing VLM result")
+            logger.info("  - Result type: %s", type(result))
+            logger.info("  - Result (first 500 chars): %s", str(result)[:500])
             
-            # Process the result
+            # Parse result structure
             if isinstance(result, (list, tuple)):
-                logger.info("VLM returned list/tuple with %d elements", len(result))
+                logger.info("  - Result is list/tuple with %d elements", len(result))
                 out = result[0] if len(result) > 0 else {}
+                logger.info("  - Extracted first element, type: %s", type(out))
             elif isinstance(result, dict):
-                logger.info("VLM returned dict with keys: %s", list(result.keys()))
+                logger.info("  - Result is dict with keys: %s", list(result.keys()))
                 out = result
             else:
-                logger.info("VLM returned type: %s, converting to string", type(result))
+                logger.info("  - Result is %s, converting to dict", type(result))
                 out = {"text": str(result)}
             
-            # Extract text from various possible formats
+            # Step 6: Extract text from result
+            logger.info("STEP 6: Extracting text from result")
             text_out = None
+            
             if isinstance(out, dict):
+                logger.info("  - Checking dict keys for text content...")
                 text_out = out.get("text") or out.get("output") or out.get("content") or out.get("response")
+                logger.info("  - Found text in key: %s", 
+                           "text" if out.get("text") else 
+                           "output" if out.get("output") else 
+                           "content" if out.get("content") else 
+                           "response" if out.get("response") else "none")
             
             if not text_out:
+                logger.info("  - No text in dict, trying alternative methods")
                 if isinstance(result, str):
                     text_out = result
+                    logger.info("  - Using result as string directly")
                 else:
                     text_out = json.dumps(out)
+                    logger.info("  - Converting to JSON string")
             
-            logger.info("VLM extracted text (first 300 chars): %s", text_out[:300] if text_out else "EMPTY")
+            logger.info("  - Extracted text length: %d chars", len(text_out) if text_out else 0)
+            logger.info("  - Extracted text (first 500 chars): %s", text_out[:500] if text_out else "EMPTY")
+            logger.info("  - Extracted text (last 200 chars): %s", text_out[-200:] if text_out and len(text_out) > 200 else "")
             
+            # Validate extracted text
             if not text_out or len(text_out.strip()) == 0:
-                logger.warning("VLM returned empty text, trying next format...")
+                logger.warning("  ⚠️ VLM returned empty text, trying next format...")
                 last_error = "Empty response"
                 continue
             
-            # Try to parse JSON
+            # Step 7: Try to parse JSON
+            logger.info("STEP 7: Attempting to parse JSON from text")
             parsed = None
+            
             try:
                 parsed = json.loads(text_out)
                 if not isinstance(parsed, dict):
-                    logger.warning("VLM JSON parsed but not a dict: %s", type(parsed))
+                    logger.warning("  ⚠️ JSON parsed but result is not a dict, type: %s", type(parsed))
                     parsed = None
                 else:
-                    logger.info("✅ VLM successfully parsed JSON with keys: %s", list(parsed.keys()))
-            except Exception:
+                    logger.info("  ✅ Successfully parsed JSON directly")
+                    logger.info("  - JSON keys: %s", list(parsed.keys()))
+                    logger.info("  - JSON (formatted): %s", json.dumps(parsed, indent=2)[:500])
+            except Exception as parse_err:
+                logger.info("  - Direct JSON parsing failed: %s", str(parse_err))
+                logger.info("  - Attempting to extract JSON from surrounding text...")
+                
                 # Try to extract JSON from text
                 try:
                     first = text_out.find("{")
                     last = text_out.rfind("}")
+                    logger.info("  - First '{' at position: %d", first)
+                    logger.info("  - Last '}' at position: %d", last)
+                    
                     if first != -1 and last != -1 and last > first:
                         json_str = text_out[first:last+1]
+                        logger.info("  - Extracted JSON string length: %d", len(json_str))
+                        logger.info("  - Extracted JSON string: %s", json_str[:300])
+                        
                         parsed = json.loads(json_str)
                         if isinstance(parsed, dict):
-                            logger.info("✅ Successfully extracted JSON from text with keys: %s", list(parsed.keys()))
+                            logger.info("  ✅ Successfully extracted and parsed JSON from text")
+                            logger.info("  - JSON keys: %s", list(parsed.keys()))
                         else:
+                            logger.warning("  ⚠️ Extracted JSON is not a dict, type: %s", type(parsed))
                             parsed = None
+                    else:
+                        logger.warning("  ⚠️ Could not find valid JSON delimiters")
                 except Exception as extract_err:
-                    logger.info("Could not extract JSON from VLM text: %s", str(extract_err))
+                    logger.warning("  ❌ JSON extraction failed: %s", str(extract_err))
                     parsed = None
             
-            # Success! Return the result
+            # Step 8: Return successful result
+            logger.info("=" * 80)
+            logger.info("✅ VLM CALL COMPLETED SUCCESSFULLY")
+            logger.info("  - Using message format: %d", idx)
+            logger.info("  - Parsed JSON: %s", "Yes" if parsed else "No (raw text only)")
+            logger.info("  - Response length: %d chars", len(text_out))
+            logger.info("=" * 80)
+            
             return parsed, text_out
             
         except Exception as e:
-            logger.warning("VLM format %d failed: %s", idx, str(e))
+            logger.warning("  ❌ VLM format %d failed: %s", idx, str(e))
+            logger.exception("Detailed error for format %d:", idx)
             last_error = str(e)
             continue
     
     # All formats failed
+    logger.error("=" * 80)
+    logger.error("❌ ALL VLM MESSAGE FORMATS FAILED")
+    logger.error("  - Tried %d different formats", len(message_formats))
+    logger.error("  - Last error: %s", last_error)
+    logger.error("=" * 80)
     raise RuntimeError(f"All VLM message formats failed. Last error: {last_error}")
 
 def call_vlm(face_path: str, eye_path: str, prompt: Optional[str] = None) -> Tuple[Optional[Dict], str]:
@@ -449,10 +575,23 @@ def call_vlm(face_path: str, eye_path: str, prompt: Optional[str] = None) -> Tup
     Call VLM - wrapper that handles both local files and GCS URLs
     Strategy: Try GCS first (if available), fallback to file handles
     """
+    logger.info("=" * 80)
+    logger.info("VLM CALL ORCHESTRATOR")
+    logger.info("=" * 80)
+    logger.info("Input files:")
+    logger.info("  - Face image: %s", face_path)
+    logger.info("  - Eye image: %s", eye_path)
+    logger.info("  - Face exists: %s", os.path.exists(face_path))
+    logger.info("  - Eye exists: %s", os.path.exists(eye_path))
+    
+    if os.path.exists(face_path):
+        logger.info("  - Face size: %d bytes", os.path.getsize(face_path))
+    if os.path.exists(eye_path):
+        logger.info("  - Eye size: %d bytes", os.path.getsize(eye_path))
     
     # Strategy 1: Try GCS URLs (if GCS is set up)
     if gcs_bucket is not None:
-        logger.info("🌐 GCS is available, uploading images and using URLs for VLM")
+        logger.info("🌐 GCS is available, attempting URL-based VLM call")
         
         try:
             # Generate unique blob names
@@ -460,10 +599,19 @@ def call_vlm(face_path: str, eye_path: str, prompt: Optional[str] = None) -> Tup
             face_blob_name = f"vlm_temp/{unique_id}_face.jpg"
             eye_blob_name = f"vlm_temp/{unique_id}_eye.jpg"
             
+            logger.info("  - Generated unique ID: %s", unique_id)
+            logger.info("  - Face blob name: %s", face_blob_name)
+            logger.info("  - Eye blob name: %s", eye_blob_name)
+            
             # Upload to GCS
+            logger.info("Uploading images to GCS...")
             face_url = upload_to_gcs(face_path, face_blob_name)
             eye_url = upload_to_gcs(eye_path, eye_blob_name)
             
+            logger.info("Upload results:")
+            logger.info("  - Face URL: %s", face_url if face_url else "FAILED")
+            logger.info("  - Eye URL: %s", eye_url if eye_url else "FAILED")
+            
             if face_url and eye_url:
                 logger.info("✅ Successfully uploaded to GCS, calling VLM with URLs")
                 return call_vlm_with_urls(face_url, eye_url, prompt)
@@ -471,48 +619,78 @@ def call_vlm(face_path: str, eye_path: str, prompt: Optional[str] = None) -> Tup
                 logger.warning("⚠️ GCS upload failed, falling back to file handles")
         except Exception as e:
             logger.warning("⚠️ GCS error, falling back to file handles: %s", str(e))
+            logger.exception("GCS error details:")
     else:
         logger.info("ℹ️ GCS not available, using file handles for VLM")
     
     # Strategy 2: Fallback to file handles (original method)
+    logger.info("-" * 80)
+    logger.info("USING FILE HANDLE STRATEGY")
+    logger.info("-" * 80)
+    
     if not os.path.exists(face_path) or not os.path.exists(eye_path):
+        logger.error("❌ File paths missing!")
+        logger.error("  - Face exists: %s", os.path.exists(face_path))
+        logger.error("  - Eye exists: %s", os.path.exists(eye_path))
         raise FileNotFoundError("Face or eye image path missing")
     
-    logger.info("📁 VLM Input - Face file: %s (size: %d bytes)", face_path, os.path.getsize(face_path))
-    logger.info("📁 VLM Input - Eye file: %s (size: %d bytes)", eye_path, os.path.getsize(eye_path))
-    
     prompt = prompt or DEFAULT_VLM_PROMPT
+    logger.info("  - Using prompt: %s", prompt[:100])
+    
+    logger.info("  - Creating Gradio client...")
     client = get_gradio_client(GRADIO_VLM_SPACE)
-    message = {"text": prompt, "files": [handle_file(face_path), handle_file(eye_path)]}
+    logger.info("  ✅ Client created")
+    
+    logger.info("  - Creating file handles...")
+    face_handle = handle_file(face_path)
+    eye_handle = handle_file(eye_path)
+    logger.info("  ✅ File handles created")
+    logger.info("    - Face handle type: %s", type(face_handle))
+    logger.info("    - Eye handle type: %s", type(eye_handle))
+    
+    message = {"text": prompt, "files": [face_handle, eye_handle]}
+    logger.info("  - Message structure: %s", list(message.keys()))
     
     try:
-        logger.info("Calling VLM with file handles")
+        logger.info("  - Calling VLM API...")
         result = client.predict(message=message, history=[], api_name="/chat_fn")
-        logger.info("VLM raw result: %s", str(result)[:500])
+        logger.info("  ✅ VLM API call succeeded")
+        logger.info("  - Raw result type: %s", type(result))
+        logger.info("  - Raw result (first 500 chars): %s", str(result)[:500])
     except Exception as e:
-        logger.exception("VLM call with file handles failed")
+        logger.exception("❌ VLM call with file handles failed")
         raise RuntimeError(f"VLM call failed: {e}")
     
     # Process result (same as in call_vlm_with_urls)
+    logger.info("Processing result...")
     if isinstance(result, (list, tuple)):
         out = result[0] if len(result) > 0 else {}
+        logger.info("  - Extracted from list, type: %s", type(out))
     elif isinstance(result, dict):
         out = result
+        logger.info("  - Using dict directly")
     else:
         out = {"text": str(result)}
+        logger.info("  - Wrapped in dict")
     
     text_out = None
     if isinstance(out, dict):
         text_out = out.get("text") or out.get("output") or out.get("content")
+        logger.info("  - Extracted text from dict key")
     
     if not text_out:
         if isinstance(result, str):
             text_out = result
+            logger.info("  - Using result string directly")
         else:
             text_out = json.dumps(out)
+            logger.info("  - Converted to JSON string")
+    
+    logger.info("  - Final text length: %d", len(text_out) if text_out else 0)
+    logger.info("  - Final text (first 500 chars): %s", text_out[:500] if text_out else "EMPTY")
     
     if not text_out or len(text_out.strip()) == 0:
-        logger.warning("VLM returned empty text")
+        logger.warning("  ⚠️ VLM returned empty text")
         text_out = "{}"
     
     parsed = None
@@ -520,7 +698,10 @@ def call_vlm(face_path: str, eye_path: str, prompt: Optional[str] = None) -> Tup
         parsed = json.loads(text_out)
         if not isinstance(parsed, dict):
             parsed = None
+        else:
+            logger.info("  ✅ Parsed JSON successfully")
     except Exception:
+        logger.info("  - Direct JSON parse failed, trying extraction...")
         try:
             first = text_out.find("{")
             last = text_out.rfind("}")
@@ -528,9 +709,17 @@ def call_vlm(face_path: str, eye_path: str, prompt: Optional[str] = None) -> Tup
                 parsed = json.loads(text_out[first:last+1])
                 if not isinstance(parsed, dict):
                     parsed = None
+                else:
+                    logger.info("  ✅ Extracted and parsed JSON")
         except Exception:
+            logger.warning("  ⚠️ JSON extraction failed")
             pass
     
+    logger.info("=" * 80)
+    logger.info("VLM CALL COMPLETED")
+    logger.info("  - Parsed JSON: %s", "Yes" if parsed else "No")
+    logger.info("=" * 80)
+    
     return parsed, text_out
 
 # ============================================================================
@@ -604,12 +793,21 @@ def get_fallback_risk_assessment(vlm_output: Any, reason: str = "LLM unavailable
 
 def call_llm(vlm_output: Any, use_fallback_on_error: bool = True) -> Dict[str, Any]:
     """Call LLM with VLM output and return structured risk assessment"""
+    logger.info("=" * 80)
+    logger.info("STARTING LLM CALL")
+    logger.info("=" * 80)
+    
     if not GRADIO_AVAILABLE:
+        logger.error("❌ Gradio not available")
         if use_fallback_on_error:
             return get_fallback_risk_assessment(vlm_output, reason="gradio_not_available")
         raise RuntimeError("gradio_client not installed")
     
     vlm_text = vlm_output if isinstance(vlm_output, str) else json.dumps(vlm_output, default=str)
+    logger.info("VLM input to LLM:")
+    logger.info("  - Type: %s", type(vlm_output))
+    logger.info("  - Length: %d chars", len(vlm_text))
+    logger.info("  - Content (first 500 chars): %s", vlm_text[:500])
     
     if not vlm_text or vlm_text.strip() in ["{}", "[]", ""]:
         logger.warning("VLM output is empty, using fallback assessment")
@@ -628,9 +826,17 @@ def call_llm(vlm_output: Any, use_fallback_on_error: bool = True) -> Dict[str, A
         "VLM Output:\n" + vlm_text + "\n"
     )
     
+    logger.info("LLM instruction length: %d chars", len(instruction))
+    
     try:
+        logger.info("Creating LLM client for space: %s", LLM_GRADIO_SPACE)
         client = get_gradio_client(LLM_GRADIO_SPACE)
-        logger.info("Calling LLM Space: %s", LLM_GRADIO_SPACE)
+        logger.info("✅ LLM client created")
+        
+        logger.info("Calling LLM with parameters:")
+        logger.info("  - max_new_tokens: 1024")
+        logger.info("  - temperature: 0.2")
+        logger.info("  - top_p: 0.9")
         
         result = client.predict(
             input_data=instruction,
@@ -646,12 +852,19 @@ def call_llm(vlm_output: Any, use_fallback_on_error: bool = True) -> Dict[str, A
             api_name="/chat"
         )
         
+        logger.info("✅ LLM API call succeeded")
+        logger.info("LLM result type: %s", type(result))
+        
         text_out = json.dumps(result) if isinstance(result, (dict, list)) else str(result)
-        logger.info("LLM raw output:\n%s", text_out[:1000])
+        logger.info("LLM raw output length: %d chars", len(text_out))
+        logger.info("LLM raw output (first 1000 chars):\n%s", text_out[:1000])
         
+        logger.info("Attempting to extract JSON from LLM output...")
         parsed = extract_json_from_llm_output(text_out)
-        logger.info("LLM parsed JSON:\n%s", json.dumps(parsed, indent=2))
+        logger.info("✅ JSON extraction successful")
+        logger.info("Parsed LLM JSON:\n%s", json.dumps(parsed, indent=2))
         
+        # Validation
         all_zero = all(
             parsed.get(k, 0) == 0 
             for k in ["jaundice_probability", "anemia_probability", 
@@ -659,15 +872,18 @@ def call_llm(vlm_output: Any, use_fallback_on_error: bool = True) -> Dict[str, A
         )
         
         if all_zero and parsed.get("risk_score", 0) == 0:
-            logger.warning("LLM returned all-zero assessment")
+            logger.warning("⚠️ LLM returned all-zero assessment")
             parsed["summary"] = "Image analysis incomplete. Please ensure photos are clear and well-lit."
             parsed["recommendation"] = "Retake photos with face clearly visible and eyes open."
             parsed["confidence"] = 0.1
         
+        logger.info("=" * 80)
+        logger.info("✅ LLM CALL COMPLETED SUCCESSFULLY")
+        logger.info("=" * 80)
         return parsed
         
     except Exception as e:
-        logger.exception("LLM call failed: %s", str(e))
+        logger.exception("❌ LLM call failed: %s", str(e))
         
         error_msg = str(e).lower()
         if "quota" in error_msg or "gpu" in error_msg:
@@ -685,21 +901,35 @@ def call_llm(vlm_output: Any, use_fallback_on_error: bool = True) -> Dict[str, A
 # ============================================================================
 async def process_screening(screening_id: str):
     """Main processing pipeline"""
+    logger.info("=" * 80)
+    logger.info("BACKGROUND PROCESSING STARTED FOR: %s", screening_id)
+    logger.info("=" * 80)
+    
     try:
         if screening_id not in screenings_db:
-            logger.error("Screening %s not found", screening_id)
+            logger.error("Screening %s not found in database", screening_id)
             return
         
         screenings_db[screening_id]["status"] = "processing"
-        logger.info("Starting processing for %s", screening_id)
+        logger.info("Status updated to: processing")
         
         entry = screenings_db[screening_id]
         face_path = entry["face_image_path"]
         eye_path = entry["eye_image_path"]
         
+        logger.info("Processing images:")
+        logger.info("  - Face: %s", face_path)
+        logger.info("  - Eye: %s", eye_path)
+        
         # Load images and get quality metrics
+        logger.info("Loading face image for quality check...")
         face_img = Image.open(face_path).convert("RGB")
+        logger.info("  ✅ Face image loaded: %s", face_img.size)
+        
+        logger.info("Running face detection...")
         detection_result = detect_face_and_eyes(face_img)
+        logger.info("  - Face detected: %s", detection_result["face_detected"])
+        logger.info("  - Face confidence: %.3f", detection_result["face_confidence"])
         
         quality_metrics = {
             "face_detected": detection_result["face_detected"],
@@ -713,13 +943,22 @@ async def process_screening(screening_id: str):
             "face_blur_estimate": int(np.var(np.asarray(face_img.convert("L"))))
         }
         screenings_db[screening_id]["quality_metrics"] = quality_metrics
+        logger.info("✅ Quality metrics computed and stored")
         
-        # Call VLM (will use GCS URLs if available)
+        # Call VLM
+        logger.info("Calling VLM...")
         vlm_features, vlm_raw = await asyncio.to_thread(call_vlm, face_path, eye_path)
+        logger.info("✅ VLM call completed")
+        logger.info("  - Features returned: %s", bool(vlm_features))
+        logger.info("  - Raw output length: %d", len(vlm_raw) if vlm_raw else 0)
         
-        # Call LLM with fallback enabled
+        # Call LLM
+        logger.info("Calling LLM...")
         llm_input = vlm_raw if vlm_raw else (vlm_features if vlm_features else "{}")
         structured_risk = await asyncio.to_thread(call_llm, llm_input, use_fallback_on_error=True)
+        logger.info("✅ LLM call completed")
+        logger.info("  - Risk score: %.2f", structured_risk.get("risk_score", 0))
+        logger.info("  - Using fallback: %s", structured_risk.get("fallback_mode", False))
         
         # Store results
         screenings_db[screening_id]["ai_results"] = {
@@ -757,10 +996,12 @@ async def process_screening(screening_id: str):
             "recommendations": recommendations
         })
         
-        logger.info("Completed processing for %s", screening_id)
+        logger.info("=" * 80)
+        logger.info("✅ PROCESSING COMPLETED SUCCESSFULLY FOR: %s", screening_id)
+        logger.info("=" * 80)
         
     except Exception as e:
-        logger.exception("Processing failed for %s", screening_id)
+        logger.exception("❌ Processing failed for %s", screening_id)
         if screening_id in screenings_db:
             screenings_db[screening_id]["status"] = "failed"
             screenings_db[screening_id]["error"] = str(e)
@@ -768,7 +1009,7 @@ async def process_screening(screening_id: str):
 # ============================================================================
 # FastAPI App & Routes
 # ============================================================================
-app = FastAPI(title="Elderly HealthWatch AI Backend")
+app = FastAPI(title="Elderly HealthWatch AI Backend - Enhanced Logging")
 app.add_middleware(
     CORSMiddleware,
     allow_origins=["*"],
@@ -780,9 +1021,9 @@ app.add_middleware(
 @app.get("/")
 async def read_root():
     return {
-        "message": "Elderly HealthWatch AI Backend",
+        "message": "Elderly HealthWatch AI Backend - Enhanced Logging Version",
         "gcs_enabled": gcs_bucket is not None,
-        "version": "1.0.0-gcs"
+        "version": "1.0.0-gcs-logging"
     }
 
 @app.get("/health")
@@ -817,7 +1058,8 @@ async def health_check():
         "llm_message": llm_message,
         "gcs_available": gcs_bucket is not None,
         "gcs_bucket": GCS_BUCKET_NAME if gcs_bucket else None,
-        "fallback_enabled": True
+        "fallback_enabled": True,
+        "enhanced_logging": True
     }
 
 @app.post("/api/v1/validate-eye-photo")
@@ -870,19 +1112,29 @@ async def upload_images(
     eye_image: UploadFile = File(...)
 ):
     """Upload images and start background processing"""
+    logger.info("=" * 80)
+    logger.info("NEW UPLOAD REQUEST")
+    logger.info("=" * 80)
+    
     try:
         screening_id = str(uuid.uuid4())
+        logger.info("Generated screening ID: %s", screening_id)
         
         face_path = os.path.join(TMP_DIR, f"{screening_id}_face.jpg")
         eye_path = os.path.join(TMP_DIR, f"{screening_id}_eye.jpg")
         
+        logger.info("Reading uploaded files...")
         face_bytes = await face_image.read()
         eye_bytes = await eye_image.read()
+        logger.info("  - Face image: %d bytes", len(face_bytes))
+        logger.info("  - Eye image: %d bytes", len(eye_bytes))
         
+        logger.info("Saving images to disk...")
         with open(face_path, "wb") as f:
             f.write(face_bytes)
         with open(eye_path, "wb") as f:
             f.write(eye_bytes)
+        logger.info("  ✅ Images saved")
         
         screenings_db[screening_id] = {
             "id": screening_id,
@@ -896,12 +1148,14 @@ async def upload_images(
             "recommendations": {}
         }
         
+        logger.info("Adding background task...")
         background_tasks.add_task(process_screening, screening_id)
+        logger.info("✅ Upload successful, processing queued")
         
         return {"screening_id": screening_id}
         
     except Exception as e:
-        logger.exception("Upload failed")
+        logger.exception("❌ Upload failed")
         raise HTTPException(status_code=500, detail=str(e))
 
 @app.post("/api/v1/analyze/{screening_id}")
@@ -949,6 +1203,10 @@ async def get_vitals_from_upload(
     eye_image: UploadFile = File(...)
 ):
     """Synchronous VLM + LLM pipeline with GCS support"""
+    logger.info("=" * 80)
+    logger.info("GET VITALS REQUEST (SYNCHRONOUS)")
+    logger.info("=" * 80)
+    
     if not GRADIO_AVAILABLE:
         raise HTTPException(
             status_code=503, 
@@ -960,6 +1218,7 @@ async def get_vitals_from_upload(
         face_path = os.path.join(TMP_DIR, f"{uid}_face.jpg")
         eye_path = os.path.join(TMP_DIR, f"{uid}_eye.jpg")
         
+        logger.info("Reading and saving images...")
         face_bytes = await face_image.read()
         eye_bytes = await eye_image.read()
         
@@ -967,14 +1226,19 @@ async def get_vitals_from_upload(
             f.write(face_bytes)
         with open(eye_path, "wb") as f:
             f.write(eye_bytes)
+        logger.info("✅ Images saved: %d + %d bytes", len(face_bytes), len(eye_bytes))
         
-        # Call VLM (will use GCS if available)
+        # Call VLM
         vlm_features, vlm_raw = await asyncio.to_thread(call_vlm, face_path, eye_path)
         
         # Call LLM
         llm_input = vlm_raw if vlm_raw else (vlm_features if vlm_features else "{}")
         structured_risk = await asyncio.to_thread(call_llm, llm_input, use_fallback_on_error=True)
         
+        logger.info("=" * 80)
+        logger.info("✅ GET VITALS COMPLETED")
+        logger.info("=" * 80)
+        
         return {
             "vlm_features": vlm_features,
             "vlm_raw": vlm_raw,
@@ -984,7 +1248,7 @@ async def get_vitals_from_upload(
         }
         
     except Exception as e:
-        logger.exception("Get vitals failed")
+        logger.exception("❌ Get vitals failed")
         error_msg = str(e).lower()
         
         if "quota" in error_msg or "gpu" in error_msg:
@@ -1001,6 +1265,8 @@ async def get_vitals_from_upload(
 @app.post("/api/v1/get-vitals/{screening_id}")
 async def get_vitals_for_screening(screening_id: str):
     """Re-run VLM + LLM on existing screening"""
+    logger.info("GET VITALS FOR EXISTING SCREENING: %s", screening_id)
+    
     if screening_id not in screenings_db:
         raise HTTPException(status_code=404, detail="Screening not found")
     
@@ -1024,6 +1290,8 @@ async def get_vitals_for_screening(screening_id: str):
             "using_fallback": structured_risk.get("fallback_mode", False)
         })
         
+        logger.info("✅ Get vitals completed for screening: %s", screening_id)
+        
         return {
             "screening_id": screening_id,
             "vlm_features": vlm_features,
@@ -1033,9 +1301,12 @@ async def get_vitals_for_screening(screening_id: str):
         }
         
     except Exception as e:
-        logger.exception("Get vitals for screening failed")
+        logger.exception("❌ Get vitals for screening failed")
         raise HTTPException(status_code=500, detail=str(e))
 
 if __name__ == "__main__":
     import uvicorn
-    uvicorn.run("app:app", host="0.0.0.0", port=7860, reload=False)
+    logger.info("=" * 80)
+    logger.info("STARTING FASTAPI SERVER")
+    logger.info("=" * 80)
+    uvicorn.run("app_with_detailed_logs:app", host="0.0.0.0", port=7860, reload=False)