Add comprehensive debug logging for provider state and autoselect model selection

Provider State Logging (providers.py):
- Add detailed logging when provider failures are recorded
- Show failure count and remaining failures before disable
- Log provider disable events with cooldown period details
- Log provider re-enable events after successful requests
- Track and display previous failure counts

Autoselect Model Selection Logging (handlers.py):
- Add detailed logging for autoselect model selection process
- Show available models and their descriptions
- Display user prompt information and length
- Log AI model selection request and response
- Show model validation and fallback logic
- Indicate whether selection was AI-selected or fallback
- Add logging for both streaming and non-streaming requests
- Display final model choice with selection method

aisbf/handlers.py

@@ -387,6 +387,11 @@ class AutoselectHandler:
 
     async def _get_model_selection(self, prompt: str) -> str:
         """Send the autoselect prompt to a model and get the selection"""
+        import logging
+        logger = logging.getLogger(__name__)
+        logger.info(f"=== AUTOSELECT MODEL SELECTION START ===")
+        logger.info(f"Using 'general' rotation for model selection")
+        
         # Use the first available provider/model for the selection
         # This is a simple implementation - could be enhanced to use a specific selection model
         rotation_handler = RotationHandler()
@@ -399,27 +404,64 @@ class AutoselectHandler:
             "stream": False
         }
         
+        logger.info(f"Selection request parameters:")
+        logger.info(f"  Temperature: 0.1 (low for deterministic selection)")
+        logger.info(f"  Max tokens: 100 (short response expected)")
+        logger.info(f"  Stream: False")
+        
         # Use the fallback rotation for the selection
         try:
+            logger.info(f"Sending selection request to rotation handler...")
             response = await rotation_handler.handle_rotation_request("general", selection_request)
+            logger.info(f"Selection response received")
+            
             content = response.get('choices', [{}])[0].get('message', {}).get('content', '')
+            logger.info(f"Raw response content: {content[:200]}..." if len(content) > 200 else f"Raw response content: {content}")
+            
             model_id = self._extract_model_selection(content)
+            
+            if model_id:
+                logger.info(f"=== AUTOSELECT MODEL SELECTION SUCCESS ===")
+                logger.info(f"Selected model ID: {model_id}")
+            else:
+                logger.warning(f"=== AUTOSELECT MODEL SELECTION FAILED ===")
+                logger.warning(f"Could not extract model ID from response")
+                logger.warning(f"Response content: {content}")
+            
             return model_id
         except Exception as e:
+            logger.error(f"=== AUTOSELECT MODEL SELECTION ERROR ===")
+            logger.error(f"Error during model selection: {str(e)}")
+            logger.error(f"Will use fallback model")
             # If selection fails, we'll handle it in the main handler
             return None
 
     async def handle_autoselect_request(self, autoselect_id: str, request_data: Dict) -> Dict:
         """Handle an autoselect request"""
+        import logging
+        logger = logging.getLogger(__name__)
+        logger.info(f"=== AUTOSELECT REQUEST START ===")
+        logger.info(f"Autoselect ID: {autoselect_id}")
+        
         autoselect_config = self.config.get_autoselect(autoselect_id)
         if not autoselect_config:
+            logger.error(f"Autoselect {autoselect_id} not found")
             raise HTTPException(status_code=400, detail=f"Autoselect {autoselect_id} not found")
 
+        logger.info(f"Autoselect config loaded")
+        logger.info(f"Available models for selection: {len(autoselect_config.available_models)}")
+        for model_info in autoselect_config.available_models:
+            logger.info(f"  - {model_info.model_id}: {model_info.description}")
+        logger.info(f"Fallback model: {autoselect_config.fallback}")
+
         # Extract the user prompt from the request
         user_messages = request_data.get('messages', [])
         if not user_messages:
+            logger.error("No messages provided")
             raise HTTPException(status_code=400, detail="No messages provided")
         
+        logger.info(f"User messages count: {len(user_messages)}")
+        
         # Build a string representation of the user prompt
         user_prompt = ""
         for msg in user_messages:
@@ -430,37 +472,73 @@ class AutoselectHandler:
                 content = str(content)
             user_prompt += f"{role}: {content}\n"
 
+        logger.info(f"User prompt length: {len(user_prompt)} characters")
+        logger.info(f"User prompt preview: {user_prompt[:200]}..." if len(user_prompt) > 200 else f"User prompt: {user_prompt}")
+
         # Build the autoselect prompt
+        logger.info(f"Building autoselect prompt...")
         autoselect_prompt = self._build_autoselect_prompt(user_prompt, autoselect_config)
+        logger.info(f"Autoselect prompt built (length: {len(autoselect_prompt)} characters)")
 
         # Get the model selection
+        logger.info(f"Requesting model selection from AI...")
         selected_model_id = await self._get_model_selection(autoselect_prompt)
 
         # Validate the selected model
+        logger.info(f"=== MODEL VALIDATION ===")
         if not selected_model_id:
             # Fallback to the configured fallback model
+            logger.warning(f"No model ID returned from selection")
+            logger.warning(f"Using fallback model: {autoselect_config.fallback}")
             selected_model_id = autoselect_config.fallback
         else:
             # Check if the selected model is in the available models list
             available_ids = [m.model_id for m in autoselect_config.available_models]
             if selected_model_id not in available_ids:
+                logger.warning(f"Selected model '{selected_model_id}' not in available models list")
+                logger.warning(f"Available models: {available_ids}")
+                logger.warning(f"Using fallback model: {autoselect_config.fallback}")
                 selected_model_id = autoselect_config.fallback
+            else:
+                logger.info(f"Selected model '{selected_model_id}' is valid and available")
+
+        logger.info(f"=== FINAL MODEL CHOICE ===")
+        logger.info(f"Selected model ID: {selected_model_id}")
+        logger.info(f"Selection method: {'AI-selected' if selected_model_id != autoselect_config.fallback else 'Fallback'}")
 
         # Now proxy the actual request to the selected rotation
+        logger.info(f"Proxying request to rotation: {selected_model_id}")
         rotation_handler = RotationHandler()
-        return await rotation_handler.handle_rotation_request(selected_model_id, request_data)
+        response = await rotation_handler.handle_rotation_request(selected_model_id, request_data)
+        logger.info(f"=== AUTOSELECT REQUEST END ===")
+        return response
 
     async def handle_autoselect_streaming_request(self, autoselect_id: str, request_data: Dict):
         """Handle an autoselect streaming request"""
+        import logging
+        logger = logging.getLogger(__name__)
+        logger.info(f"=== AUTOSELECT STREAMING REQUEST START ===")
+        logger.info(f"Autoselect ID: {autoselect_id}")
+        
         autoselect_config = self.config.get_autoselect(autoselect_id)
         if not autoselect_config:
+            logger.error(f"Autoselect {autoselect_id} not found")
             raise HTTPException(status_code=400, detail=f"Autoselect {autoselect_id} not found")
 
+        logger.info(f"Autoselect config loaded")
+        logger.info(f"Available models for selection: {len(autoselect_config.available_models)}")
+        for model_info in autoselect_config.available_models:
+            logger.info(f"  - {model_info.model_id}: {model_info.description}")
+        logger.info(f"Fallback model: {autoselect_config.fallback}")
+
         # Extract the user prompt from the request
         user_messages = request_data.get('messages', [])
         if not user_messages:
+            logger.error("No messages provided")
             raise HTTPException(status_code=400, detail="No messages provided")
         
+        logger.info(f"User messages count: {len(user_messages)}")
+        
         # Build a string representation of the user prompt
         user_prompt = ""
         for msg in user_messages:
@@ -470,21 +548,41 @@ class AutoselectHandler:
                 content = str(content)
             user_prompt += f"{role}: {content}\n"
 
+        logger.info(f"User prompt length: {len(user_prompt)} characters")
+        logger.info(f"User prompt preview: {user_prompt[:200]}..." if len(user_prompt) > 200 else f"User prompt: {user_prompt}")
+
         # Build the autoselect prompt
+        logger.info(f"Building autoselect prompt...")
         autoselect_prompt = self._build_autoselect_prompt(user_prompt, autoselect_config)
+        logger.info(f"Autoselect prompt built (length: {len(autoselect_prompt)} characters)")
 
         # Get the model selection
+        logger.info(f"Requesting model selection from AI...")
         selected_model_id = await self._get_model_selection(autoselect_prompt)
 
         # Validate the selected model
+        logger.info(f"=== MODEL VALIDATION ===")
         if not selected_model_id:
+            logger.warning(f"No model ID returned from selection")
+            logger.warning(f"Using fallback model: {autoselect_config.fallback}")
             selected_model_id = autoselect_config.fallback
         else:
             available_ids = [m.model_id for m in autoselect_config.available_models]
             if selected_model_id not in available_ids:
+                logger.warning(f"Selected model '{selected_model_id}' not in available models list")
+                logger.warning(f"Available models: {available_ids}")
+                logger.warning(f"Using fallback model: {autoselect_config.fallback}")
                 selected_model_id = autoselect_config.fallback
+            else:
+                logger.info(f"Selected model '{selected_model_id}' is valid and available")
+
+        logger.info(f"=== FINAL MODEL CHOICE ===")
+        logger.info(f"Selected model ID: {selected_model_id}")
+        logger.info(f"Selection method: {'AI-selected' if selected_model_id != autoselect_config.fallback else 'Fallback'}")
+        logger.info(f"Request mode: Streaming")
 
         # Now proxy the actual streaming request to the selected rotation
+        logger.info(f"Proxying streaming request to rotation: {selected_model_id}")
         rotation_handler = RotationHandler()
         
         async def stream_generator():
@@ -496,8 +594,10 @@ class AutoselectHandler:
                 for chunk in response:
                     yield f"data: {chunk}\n\n".encode('utf-8')
             except Exception as e:
+                logger.error(f"Error in streaming response: {str(e)}")
                 yield f"data: {str(e)}\n\n".encode('utf-8')
 
+        logger.info(f"=== AUTOSELECT STREAMING REQUEST END ===")
         return StreamingResponse(stream_generator(), media_type="text/event-stream")
 
     async def handle_autoselect_model_list(self, autoselect_id: str) -> List[Dict]:

aisbf/providers.py

@@ -62,14 +62,56 @@ class BaseProviderHandler:
             self.last_request_time = time.time()
 
     def record_failure(self):
+        import logging
+        logger = logging.getLogger(__name__)
+        
         self.error_tracking['failures'] += 1
         self.error_tracking['last_failure'] = time.time()
+        
+        failure_count = self.error_tracking['failures']
+        logger.warning(f"=== PROVIDER FAILURE RECORDED ===")
+        logger.warning(f"Provider: {self.provider_id}")
+        logger.warning(f"Failure count: {failure_count}/3")
+        logger.warning(f"Last failure time: {self.error_tracking['last_failure']}")
+        
         if self.error_tracking['failures'] >= 3:
             self.error_tracking['disabled_until'] = time.time() + 300  # 5 minutes
+            disabled_until_time = self.error_tracking['disabled_until']
+            cooldown_remaining = int(disabled_until_time - time.time())
+            logger.error(f"!!! PROVIDER DISABLED !!!")
+            logger.error(f"Provider: {self.provider_id}")
+            logger.error(f"Reason: 3 consecutive failures reached")
+            logger.error(f"Disabled until: {disabled_until_time}")
+            logger.error(f"Cooldown period: {cooldown_remaining} seconds (5 minutes)")
+            logger.error(f"Provider will be automatically re-enabled after cooldown")
+        else:
+            remaining_failures = 3 - failure_count
+            logger.warning(f"Provider still active. {remaining_failures} more failure(s) will disable it")
+        logger.warning(f"=== END FAILURE RECORDING ===")
 
     def record_success(self):
+        import logging
+        logger = logging.getLogger(__name__)
+        
+        was_disabled = self.error_tracking['disabled_until'] is not None
+        previous_failures = self.error_tracking['failures']
+        
         self.error_tracking['failures'] = 0
         self.error_tracking['disabled_until'] = None
+        
+        logger.info(f"=== PROVIDER SUCCESS RECORDED ===")
+        logger.info(f"Provider: {self.provider_id}")
+        logger.info(f"Previous failure count: {previous_failures}")
+        logger.info(f"Failure count reset to: 0")
+        
+        if was_disabled:
+            logger.info(f"!!! PROVIDER RE-ENABLED !!!")
+            logger.info(f"Provider: {self.provider_id}")
+            logger.info(f"Reason: Successful request after cooldown period")
+            logger.info(f"Provider is now active and available for requests")
+        else:
+            logger.info(f"Provider remains active")
+        logger.info(f"=== END SUCCESS RECORDING ===")
 
 class GoogleProviderHandler(BaseProviderHandler):
     def __init__(self, provider_id: str, api_key: str):