Add comprehensive debug logging and fix Ollama provider handler

- Add detailed debug logging throughout the codebase to track model and provider selection
- Fix OllamaProviderHandler to accept optional api_key parameter for cloud models
- Add logging in main.py, handlers.py, providers.py, and config.py
- Add catch-all endpoint for invalid routes with helpful error messages
- Create DEBUG_GUIDE.md with comprehensive documentation
- Enhance error messages to show available providers/rotations/autoselect

Debug logging now shows:
- Request path and provider ID
- Available configurations
- Provider config and handler selection
- Model selection process
- Rate limiting application
- Request/response details

This helps diagnose issues with model and provider selection.

DEBUG_GUIDE.md

+# Debug Logging Guide for AISBF
+
+## Overview
+
+Comprehensive debug logging has been added throughout the AISBF codebase to help understand how models and providers are selected. This guide explains what information is logged and how to use it.
+
+## Recent Fixes
+
+### Fixed: Ollama Provider Handler Initialization
+**Issue**: `TypeError: OllamaProviderHandler.__init__() takes 2 positional arguments but 3 were given`
+
+**Cause**: The `get_provider_handler()` function was passing an `api_key` parameter to `OllamaProviderHandler`, but the handler only accepted `provider_id`.
+
+**Solution**: Updated `OllamaProviderHandler.__init__()` to accept an optional `api_key` parameter. This allows:
+- Local Ollama instances to work without an API key
+- Ollama cloud models to use an API key when provided
+
+The API key is now optional for Ollama and will be added to request headers as `Authorization: Bearer {api_key}` if provided.
+
+## What Was Changed
+
+### 1. main.py
+- Added detailed logging at the start of each request showing:
+  - Request path and provider ID
+  - Available providers, rotations, and autoselect configurations
+  - Request headers and body
+- Enhanced error messages when provider not found
+- Added catch-all endpoint for invalid routes
+
+### 2. aisbf/handlers.py
+- **RequestHandler**: Logs provider config, handler selection, and request parameters
+- **RotationHandler**: Logs rotation config, weighted models, and selected model details
+- Shows model selection process and rate limiting
+
+### 3. aisbf/providers.py
+- **get_provider_handler**: Logs provider config, handler class selection
+- **OllamaProviderHandler**: Logs endpoint, model, request details, and response
+
+### 4. aisbf/config.py
+- Logs configuration file locations
+- Shows loaded providers and their details
+- Logs provider lookup results
+
+## Understanding Your Issue
+
+You're seeing:
+```
+INFO:     127.0.0.1:44892 - "POST /api/ollama HTTP/1.1" 404 Not Found
+```
+
+This is because the correct endpoint format is:
+```
+POST /api/{provider_id}/chat/completions
+```
+
+For example:
+```
+POST /api/ollama/chat/completions
+```
+
+## How to Use the Debug Logs
+
+### 1. Start the Server
+```bash
+python main.py
+```
+
+### 2. Make a Request
+```bash
+curl -X POST http://localhost:8000/api/ollama/chat/completions \
+  -H "Content-Type: application/json" \
+  -d '{
+    "model": "llama2",
+    "messages": [{"role": "user", "content": "Hello"}]
+  }'
+```
+
+### 3. Check the Logs
+
+The logs will show:
+
+#### Request Entry
+```
+=== CHAT COMPLETION REQUEST START ===
+Request path: /api/ollama/chat/completions
+Provider ID: ollama
+Available providers: ['google', 'openai', 'anthropic', 'ollama']
+Available rotations: ['general']
+Available autoselect: []
+```
+
+#### Provider Selection
+```
+Provider ID 'ollama' found in providers
+Provider config: id='ollama' name='Ollama' endpoint='http://localhost:11434' type='ollama' api_key_required=False
+```
+
+#### Handler Creation
+```
+=== get_provider_handler START ===
+Provider ID: ollama
+Provider type: ollama
+Handler class: OllamaProviderHandler
+Handler created: OllamaProviderHandler
+```
+
+#### Request Processing
+```
+=== OllamaProviderHandler.handle_request START ===
+Provider ID: ollama
+Endpoint: http://localhost:11434
+Model: llama2
+Messages count: 1
+Sending POST request to http://localhost:11434/api/generate
+Response status code: 200
+```
+
+## Common Issues and Solutions
+
+### Issue 1: 404 Not Found
+**Cause**: Incorrect endpoint path
+**Solution**: Use `/api/{provider_id}/chat/completions` instead of `/api/{provider_id}`
+
+### Issue 2: Provider Not Found
+**Cause**: Provider ID doesn't exist in configuration
+**Solution**: Check the logs for available providers and verify your provider_id
+
+### Issue 3: Model Not Found
+**Cause**: Model name doesn't exist in the provider
+**Solution**: Check the provider's available models using `/api/{provider_id}/models`
+
+### Issue 4: Connection Refused
+**Cause**: Provider endpoint is not reachable
+**Solution**: Check the endpoint URL in the provider configuration and ensure the provider is running
+
+## Log Levels
+
+- **INFO**: Normal operation flow, shows what's happening
+- **DEBUG**: Detailed information for troubleshooting
+- **ERROR**: Problems that need attention
+
+## Log Files
+
+Logs are written to:
+- `~/.local/var/log/aisbf/aisbf.log` - General logs
+- `~/.local/var/log/aisbf/aisbf_error.log` - Error logs
+- `~/.local/var/log/aisbf/aisbf_stderr.log` - Standard error
+
+## Configuration Files
+
+The system looks for configuration files in this order:
+1. `~/.aisbf/` - User configuration (highest priority)
+2. `/usr/share/aisbf/` - System-wide configuration
+3. `~/.local/share/aisbf/` - User-local configuration
+4. `config/` - Source tree configuration (development mode)
+
+## Example Debug Session
+
+1. **Check available providers**:
+```bash
+curl http://localhost:8000/
+```
+
+2. **List models for a provider**:
+```bash
+curl http://localhost:8000/api/ollama/models
+```
+
+3. **Make a chat completion request**:
+```bash
+curl -X POST http://localhost:8000/api/ollama/chat/completions \
+  -H "Content-Type: application/json" \
+  -d '{
+    "model": "llama2",
+    "messages": [{"role": "user", "content": "Hello"}]
+  }'
+```
+
+4. **Review the logs** to see the complete flow of the request
+
+## Next Steps
+
+After reviewing the debug logs, you should be able to:
+- Identify which provider is being selected
+- See which model is being used
+- Understand the request flow
+- Diagnose any issues with provider or model selection
+
+If you still have issues, the debug logs will provide detailed information about what's happening at each step of the process.
\ No newline at end of file

aisbf/config.py

@@ -111,32 +111,58 @@ class Config:
                 print(f"Created default config file: {dst}")
 
     def _load_providers(self):
+        import logging
+        logger = logging.getLogger(__name__)
+        logger.info(f"=== Config._load_providers START ===")
+        
         providers_path = Path.home() / '.aisbf' / 'providers.json'
+        logger.info(f"Looking for providers at: {providers_path}")
+        
         if not providers_path.exists():
+            logger.info(f"User config not found, falling back to source config")
             # Fallback to source config if user config doesn't exist
             try:
                 source_dir = self._get_config_source_dir()
                 providers_path = source_dir / 'providers.json'
+                logger.info(f"Using source config at: {providers_path}")
             except FileNotFoundError:
+                logger.error("Could not find providers.json configuration file")
                 raise FileNotFoundError("Could not find providers.json configuration file")
         
+        logger.info(f"Loading providers from: {providers_path}")
         with open(providers_path) as f:
             data = json.load(f)
             self.providers = {k: ProviderConfig(**v) for k, v in data['providers'].items()}
+            logger.info(f"Loaded {len(self.providers)} providers: {list(self.providers.keys())}")
+            for provider_id, provider_config in self.providers.items():
+                logger.info(f"  - {provider_id}: type={provider_config.type}, endpoint={provider_config.endpoint}")
+            logger.info(f"=== Config._load_providers END ===")
 
     def _load_rotations(self):
+        import logging
+        logger = logging.getLogger(__name__)
+        logger.info(f"=== Config._load_rotations START ===")
+        
         rotations_path = Path.home() / '.aisbf' / 'rotations.json'
+        logger.info(f"Looking for rotations at: {rotations_path}")
+        
         if not rotations_path.exists():
+            logger.info(f"User config not found, falling back to source config")
             # Fallback to source config if user config doesn't exist
             try:
                 source_dir = self._get_config_source_dir()
                 rotations_path = source_dir / 'rotations.json'
+                logger.info(f"Using source config at: {rotations_path}")
             except FileNotFoundError:
+                logger.error("Could not find rotations.json configuration file")
                 raise FileNotFoundError("Could not find rotations.json configuration file")
         
+        logger.info(f"Loading rotations from: {rotations_path}")
         with open(rotations_path) as f:
             data = json.load(f)
             self.rotations = {k: RotationConfig(**v) for k, v in data['rotations'].items()}
+            logger.info(f"Loaded {len(self.rotations)} rotations: {list(self.rotations.keys())}")
+            logger.info(f"=== Config._load_rotations END ===")
 
     def _load_autoselect(self):
         autoselect_path = Path.home() / '.aisbf' / 'autoselect.json'
@@ -162,7 +188,16 @@ class Config:
             }
 
     def get_provider(self, provider_id: str) -> ProviderConfig:
-        return self.providers.get(provider_id)
+        import logging
+        logger = logging.getLogger(__name__)
+        logger.info(f"Config.get_provider called with provider_id: {provider_id}")
+        logger.info(f"Available providers: {list(self.providers.keys())}")
+        result = self.providers.get(provider_id)
+        if result:
+            logger.info(f"Found provider: {result}")
+        else:
+            logger.warning(f"Provider {provider_id} not found!")
+        return result
 
     def get_rotation(self, rotation_id: str) -> RotationConfig:
         return self.rotations.get(rotation_id)

aisbf/handlers.py

@@ -37,24 +37,47 @@ class RequestHandler:
         self.config = config
 
     async def handle_chat_completion(self, request: Request, provider_id: str, request_data: Dict) -> Dict:
+        import logging
+        logger = logging.getLogger(__name__)
+        logger.info(f"=== RequestHandler.handle_chat_completion START ===")
+        logger.info(f"Provider ID: {provider_id}")
+        logger.info(f"Request data: {request_data}")
+        
         provider_config = self.config.get_provider(provider_id)
+        logger.info(f"Provider config: {provider_config}")
+        logger.info(f"Provider type: {provider_config.type}")
+        logger.info(f"Provider endpoint: {provider_config.endpoint}")
+        logger.info(f"API key required: {provider_config.api_key_required}")
 
         if provider_config.api_key_required:
             api_key = request_data.get('api_key') or request.headers.get('Authorization', '').replace('Bearer ', '')
+            logger.info(f"API key from request: {'***' if api_key else 'None'}")
             if not api_key:
                 raise HTTPException(status_code=401, detail="API key required")
         else:
             api_key = None
+            logger.info("No API key required for this provider")
 
+        logger.info(f"Getting provider handler for {provider_id}")
         handler = get_provider_handler(provider_id, api_key)
+        logger.info(f"Provider handler obtained: {handler.__class__.__name__}")
 
         if handler.is_rate_limited():
             raise HTTPException(status_code=503, detail="Provider temporarily unavailable")
 
         try:
+            logger.info(f"Model requested: {request_data.get('model')}")
+            logger.info(f"Messages count: {len(request_data.get('messages', []))}")
+            logger.info(f"Max tokens: {request_data.get('max_tokens')}")
+            logger.info(f"Temperature: {request_data.get('temperature', 1.0)}")
+            logger.info(f"Stream: {request_data.get('stream', False)}")
+            
             # Apply rate limiting
+            logger.info("Applying rate limiting...")
             await handler.apply_rate_limit()
+            logger.info("Rate limiting applied")
 
+            logger.info(f"Sending request to provider handler...")
             response = await handler.handle_request(
                 model=request_data['model'],
                 messages=request_data['messages'],
@@ -62,7 +85,9 @@ class RequestHandler:
                 temperature=request_data.get('temperature', 1.0),
                 stream=request_data.get('stream', False)
             )
+            logger.info(f"Response received from provider")
             handler.record_success()
+            logger.info(f"=== RequestHandler.handle_chat_completion END ===")
             return response
         except Exception as e:
             handler.record_failure()
@@ -129,37 +154,67 @@ class RotationHandler:
         self.config = config
 
     async def handle_rotation_request(self, rotation_id: str, request_data: Dict) -> Dict:
+        import logging
+        logger = logging.getLogger(__name__)
+        logger.info(f"=== RotationHandler.handle_rotation_request START ===")
+        logger.info(f"Rotation ID: {rotation_id}")
+        
         rotation_config = self.config.get_rotation(rotation_id)
         if not rotation_config:
+            logger.error(f"Rotation {rotation_id} not found")
             raise HTTPException(status_code=400, detail=f"Rotation {rotation_id} not found")
 
+        logger.info(f"Rotation config: {rotation_config}")
         providers = rotation_config.providers
+        logger.info(f"Number of providers in rotation: {len(providers)}")
+        
         weighted_models = []
 
         for provider in providers:
+            logger.info(f"Processing provider: {provider['provider_id']}")
             for model in provider['models']:
+                logger.info(f"  Model: {model['name']}, weight: {model['weight']}")
                 weighted_models.extend([model] * model['weight'])
 
+        logger.info(f"Total weighted models: {len(weighted_models)}")
         if not weighted_models:
+            logger.error("No models available in rotation")
             raise HTTPException(status_code=400, detail="No models available in rotation")
 
         import random
         selected_model = random.choice(weighted_models)
+        logger.info(f"Selected model: {selected_model}")
 
         provider_id = selected_model['provider_id']
         api_key = selected_model.get('api_key')
         model_name = selected_model['name']
         
+        logger.info(f"Selected provider_id: {provider_id}")
+        logger.info(f"Selected model_name: {model_name}")
+        logger.info(f"API key present: {bool(api_key)}")
+
+        logger.info(f"Getting provider handler for {provider_id}")
         handler = get_provider_handler(provider_id, api_key)
+        logger.info(f"Provider handler obtained: {handler.__class__.__name__}")
 
         if handler.is_rate_limited():
             raise HTTPException(status_code=503, detail="All providers temporarily unavailable")
 
         try:
+            logger.info(f"Model requested: {model_name}")
+            logger.info(f"Messages count: {len(request_data.get('messages', []))}")
+            logger.info(f"Max tokens: {request_data.get('max_tokens')}")
+            logger.info(f"Temperature: {request_data.get('temperature', 1.0)}")
+            logger.info(f"Stream: {request_data.get('stream', False)}")
+            
             # Apply rate limiting with model-specific rate limit if available
             rate_limit = selected_model.get('rate_limit')
+            logger.info(f"Model-specific rate limit: {rate_limit}")
+            logger.info("Applying rate limiting...")
             await handler.apply_rate_limit(rate_limit)
+            logger.info("Rate limiting applied")
 
+            logger.info(f"Sending request to provider handler...")
             response = await handler.handle_request(
                 model=model_name,
                 messages=request_data['messages'],
@@ -167,7 +222,9 @@ class RotationHandler:
                 temperature=request_data.get('temperature', 1.0),
                 stream=request_data.get('stream', False)
             )
+            logger.info(f"Response received from provider")
             handler.record_success()
+            logger.info(f"=== RotationHandler.handle_rotation_request END ===")
             return response
         except Exception as e:
             handler.record_failure()

aisbf/providers.py

@@ -249,30 +249,65 @@ class AnthropicProviderHandler(BaseProviderHandler):
         ]
 
 class OllamaProviderHandler(BaseProviderHandler):
-    def __init__(self, provider_id: str):
-        super().__init__(provider_id)
+    def __init__(self, provider_id: str, api_key: Optional[str] = None):
+        super().__init__(provider_id, api_key)
         self.client = httpx.AsyncClient(base_url=config.providers[provider_id].endpoint)
 
     async def handle_request(self, model: str, messages: List[Dict], max_tokens: Optional[int] = None,
                            temperature: Optional[float] = 1.0, stream: Optional[bool] = False) -> Dict:
+        import logging
+        logger = logging.getLogger(__name__)
+        logger.info(f"=== OllamaProviderHandler.handle_request START ===")
+        logger.info(f"Provider ID: {self.provider_id}")
+        logger.info(f"Endpoint: {self.client.base_url}")
+        logger.info(f"Model: {model}")
+        logger.info(f"Messages count: {len(messages)}")
+        logger.info(f"Max tokens: {max_tokens}")
+        logger.info(f"Temperature: {temperature}")
+        logger.info(f"Stream: {stream}")
+        logger.info(f"API key provided: {bool(self.api_key)}")
+        
         if self.is_rate_limited():
+            logger.error("Provider is rate limited")
             raise Exception("Provider rate limited")
 
         try:
             # Apply rate limiting
+            logger.info("Applying rate limiting...")
             await self.apply_rate_limit()
+            logger.info("Rate limiting applied")
 
-            response = await self.client.post("/api/generate", json={
+            prompt = "\n\n".join([f"{msg['role']}: {msg['content']}" for msg in messages])
+            logger.info(f"Prompt length: {len(prompt)} characters")
+            
+            request_data = {
                 "model": model,
-                "prompt": "\n\n".join([f"{msg['role']}: {msg['content']}" for msg in messages]),
+                "prompt": prompt,
                 "options": {
                     "temperature": temperature,
                     "num_predict": max_tokens
                 }
-            })
+            }
+            
+            # Add API key to headers if provided (for Ollama cloud models)
+            headers = {}
+            if self.api_key:
+                headers["Authorization"] = f"Bearer {self.api_key}"
+                logger.info("API key added to request headers for Ollama cloud")
+            
+            logger.info(f"Sending POST request to {self.client.base_url}/api/generate")
+            logger.info(f"Request data: {request_data}")
+            logger.info(f"Request headers: {headers}")
+            
+            response = await self.client.post("/api/generate", json=request_data, headers=headers)
+            logger.info(f"Response status code: {response.status_code}")
             response.raise_for_status()
+            
+            response_json = response.json()
+            logger.info(f"Response received: {response_json}")
             self.record_success()
-            return response.json()
+            logger.info(f"=== OllamaProviderHandler.handle_request END ===")
+            return response_json
         except Exception as e:
             self.record_failure()
             raise e
@@ -294,8 +329,29 @@ PROVIDER_HANDLERS = {
 }
 
 def get_provider_handler(provider_id: str, api_key: Optional[str] = None) -> BaseProviderHandler:
+    import logging
+    logger = logging.getLogger(__name__)
+    logger.info(f"=== get_provider_handler START ===")
+    logger.info(f"Provider ID: {provider_id}")
+    logger.info(f"API key provided: {bool(api_key)}")
+    
     provider_config = config.get_provider(provider_id)
+    logger.info(f"Provider config: {provider_config}")
+    logger.info(f"Provider type: {provider_config.type}")
+    logger.info(f"Provider endpoint: {provider_config.endpoint}")
+    
     handler_class = PROVIDER_HANDLERS.get(provider_config.type)
+    logger.info(f"Handler class: {handler_class.__name__ if handler_class else 'None'}")
+    logger.info(f"Available handler types: {list(PROVIDER_HANDLERS.keys())}")
+    
     if not handler_class:
+        logger.error(f"Unsupported provider type: {provider_config.type}")
         raise ValueError(f"Unsupported provider type: {provider_config.type}")
-    return handler_class(provider_id, api_key)
+    
+    # All handlers now accept api_key as optional parameter
+    logger.info(f"Creating handler with provider_id and optional api_key")
+    handler = handler_class(provider_id, api_key)
+    
+    logger.info(f"Handler created: {handler.__class__.__name__}")
+    logger.info(f"=== get_provider_handler END ===")
+    return handler

main.py

@@ -120,7 +120,14 @@ async def root():
 
 @app.post("/api/{provider_id}/chat/completions")
 async def chat_completions(provider_id: str, request: Request, body: ChatCompletionRequest):
-    logger.debug(f"Received chat_completions request for provider: {provider_id}")
+    logger.info(f"=== CHAT COMPLETION REQUEST START ===")
+    logger.info(f"Request path: {request.url.path}")
+    logger.info(f"Provider ID: {provider_id}")
+    logger.info(f"Request headers: {dict(request.headers)}")
+    logger.info(f"Request body: {body}")
+    logger.info(f"Available providers: {list(config.providers.keys())}")
+    logger.info(f"Available rotations: {list(config.rotations.keys())}")
+    logger.info(f"Available autoselect: {list(config.autoselect.keys())}")
     logger.debug(f"Request headers: {dict(request.headers)}")
     logger.debug(f"Request body: {body}")
 
@@ -144,14 +151,20 @@ async def chat_completions(provider_id: str, request: Request, body: ChatComplet
 
     # Check if it's a rotation
     if provider_id in config.rotations:
+        logger.info(f"Provider ID '{provider_id}' found in rotations")
         logger.debug("Handling rotation request")
         return await rotation_handler.handle_rotation_request(provider_id, body_dict)
 
     # Check if it's a provider
     if provider_id not in config.providers:
-        logger.error(f"Provider {provider_id} not found")
+        logger.error(f"Provider ID '{provider_id}' not found in providers")
+        logger.error(f"Available providers: {list(config.providers.keys())}")
+        logger.error(f"Available rotations: {list(config.rotations.keys())}")
+        logger.error(f"Available autoselect: {list(config.autoselect.keys())}")
         raise HTTPException(status_code=400, detail=f"Provider {provider_id} not found")
     
+    logger.info(f"Provider ID '{provider_id}' found in providers")
+
     provider_config = config.get_provider(provider_id)
     logger.debug(f"Provider config: {provider_config}")
 
@@ -185,14 +198,20 @@ async def list_models(request: Request, provider_id: str):
 
     # Check if it's a rotation
     if provider_id in config.rotations:
+        logger.info(f"Provider ID '{provider_id}' found in rotations")
         logger.debug("Handling rotation model list request")
         return await rotation_handler.handle_rotation_model_list(provider_id)
 
     # Check if it's a provider
     if provider_id not in config.providers:
-        logger.error(f"Provider {provider_id} not found")
+        logger.error(f"Provider ID '{provider_id}' not found in providers")
+        logger.error(f"Available providers: {list(config.providers.keys())}")
+        logger.error(f"Available rotations: {list(config.rotations.keys())}")
+        logger.error(f"Available autoselect: {list(config.autoselect.keys())}")
         raise HTTPException(status_code=400, detail=f"Provider {provider_id} not found")
     
+    logger.info(f"Provider ID '{provider_id}' found in providers")
+
     provider_config = config.get_provider(provider_id)
 
     try:
@@ -204,6 +223,31 @@ async def list_models(request: Request, provider_id: str):
         logger.error(f"Error handling list_models: {str(e)}", exc_info=True)
         raise
 
+@app.post("/api/{provider_id}")
+async def catch_all_post(provider_id: str, request: Request):
+    """Catch-all for POST requests to help debug routing issues"""
+    logger.info(f"=== CATCH-ALL POST REQUEST ===")
+    logger.info(f"Request path: {request.url.path}")
+    logger.info(f"Provider ID: {provider_id}")
+    logger.info(f"Request headers: {dict(request.headers)}")
+    logger.info(f"Available providers: {list(config.providers.keys())}")
+    logger.info(f"Available rotations: {list(config.rotations.keys())}")
+    logger.info(f"Available autoselect: {list(config.autoselect.keys())}")
+    
+    error_msg = f"""
+    Invalid endpoint: {request.url.path}
+    
+    The correct endpoint format is: /api/{{provider_id}}/chat/completions
+    
+    Available providers: {list(config.providers.keys())}
+    Available rotations: {list(config.rotations.keys())}
+    Available autoselect: {list(config.autoselect.keys())}
+    
+    Example: POST /api/ollama/chat/completions
+    """
+    logger.error(error_msg)
+    raise HTTPException(status_code=404, detail=error_msg.strip())
+
 def main():
     """Main entry point for the AISBF server"""
     import uvicorn