advanced logging

app.py

@@ -147,15 +147,17 @@ async def thread_safe_auth_middleware(request: Request, call_next):
         api_key = None
         
         # Check if request has MCP session ID (for established sessions)
-        session_id = request.headers.get("Mcp-Session-Id")
+        session_id = request.headers.get("Mcp-Session-Id") or request.headers.get("mcp-session-id")
         if session_id:
-            logger.debug(f"MCP Session ID present: {session_id[:8]}...")
+            logger.info(f"Request has MCP Session ID: {session_id[:8]}...")
             if session_id in session_api_keys:
                 # Use stored API key for this session
                 api_key = session_api_keys[session_id]
-                logger.debug(f"Using stored API key for session {session_id[:8]}...")
+                logger.info(f"Session found in storage, using stored API key")
             else:
-                logger.debug(f"Session ID not found in storage. Active sessions: {len(session_api_keys)}")
+                logger.warning(f"Session ID {session_id[:8]}... NOT found in storage!")
+                logger.info(f"   Active sessions ({len(session_api_keys)}): {[sid[:8] for sid in session_api_keys.keys()]}")
+                # Don't fail here - the request might have its own Bearer token
         
         # Check for Bearer token (for new sessions or explicit auth)
         authorization = request.headers.get("Authorization", "")
@@ -175,7 +177,9 @@ async def thread_safe_auth_middleware(request: Request, call_next):
         if request.method == "DELETE" and session_id:
             if session_id in session_api_keys:
                 del session_api_keys[session_id]
-                logger.debug(f"Cleaned up session {session_id[:8]}...")
+                logger.info(f"Session cleanup: Deleted session {session_id[:8]}... (Remaining sessions: {len(session_api_keys)})")
+            else:
+                logger.warning(f"Session cleanup: Attempted to delete non-existent session {session_id[:8]}...")
             return await call_next(request)
         
         if api_key:
@@ -190,13 +194,19 @@ async def thread_safe_auth_middleware(request: Request, call_next):
                 response = await call_next(request)
                 
                 # If MCP returns a session ID, store our API key for future requests
-                session_id = response.headers.get("Mcp-Session-Id")
-                if session_id and api_key:
-                    session_api_keys[session_id] = api_key
-                    logger.info(f"New MCP session created: {session_id[:8]}... (Total sessions: {len(session_api_keys)})")
-                    logger.debug(f"   Stored API key ending in ...{api_key[-4:]}")
-                elif session_id and not api_key:
-                    logger.warning(f"Session created but no API key to store: {session_id[:8]}...")
+                response_session_id = response.headers.get("Mcp-Session-Id") or response.headers.get("mcp-session-id")
+                if response_session_id:
+                    if api_key:
+                        # Check if this session already exists
+                        if response_session_id in session_api_keys:
+                            logger.debug(f"Session {response_session_id[:8]}... already exists, updating API key")
+                        else:
+                            logger.info(f"New MCP session created: {response_session_id[:8]}...")
+                        session_api_keys[response_session_id] = api_key
+                        logger.info(f"Session storage updated. Total sessions: {len(session_api_keys)}")
+                        logger.debug(f"   Active session IDs: {[sid[:8] for sid in session_api_keys.keys()]}")
+                    else:
+                        logger.warning(f"Session created but no API key to store: {response_session_id[:8]}...")
                 
                 return response
             finally:
@@ -204,6 +214,11 @@ async def thread_safe_auth_middleware(request: Request, call_next):
                 WandBApiManager.reset_context_api_key(token)
         else:
             # No API key available, let request through for MCP to handle
+            logger.warning(f"No API key available for request to {request.url.path}")
+            logger.info(f"   Session ID present: {bool(session_id)} ({session_id[:8] if session_id else 'None'}...)")
+            logger.info(f"   Bearer token present: {bool(authorization.startswith('Bearer '))}")
+            logger.info(f"   Request method: {request.method}")
+            logger.info("   Allowing request through for MCP to handle (may result in 401/404)")
             return await call_next(request)
         
     except Exception as e:
@@ -248,8 +263,46 @@ async def logging_middleware(request, call_next):
     
     # Log request details
     logger.info(f"Incoming request: {request.method} {request.url.path}")
-    logger.debug(f"   Headers: {dict(request.headers)}")
-    logger.debug(f"   Query params: {dict(request.query_params)}")
+    
+    # Log MCP-specific headers
+    mcp_session_id = request.headers.get("mcp-session-id")
+    if mcp_session_id:
+        logger.info(f"   MCP Session ID in request: {mcp_session_id[:8]}...")
+    
+    # Try to log request body for POST requests
+    if request.method == "POST" and request.url.path in ["/mcp", "/"]:
+        try:
+            # Clone the request body so we can read it
+            body_bytes = await request.body()
+            if body_bytes:
+                import json
+                try:
+                    body_json = json.loads(body_bytes)
+                    method = body_json.get("method", "unknown")
+                    request_id = body_json.get("id", "unknown")
+                    logger.info(f"   JSON-RPC request: method={method}, id={request_id}")
+                    if method == "tools/call":
+                        tool_name = body_json.get("params", {}).get("name", "unknown")
+                        logger.info(f"   Tool call request for: {tool_name}")
+                except json.JSONDecodeError:
+                    logger.debug(f"   Request body (non-JSON): {body_bytes[:100]}")
+                
+                # Reconstruct the request with the body we read
+                from starlette.datastructures import Headers
+                from starlette.requests import Request as StarletteRequest
+                
+                # Create a new request with the body we read
+                scope = request.scope
+                scope["body"] = body_bytes
+                
+                async def receive():
+                    return {"type": "http.request", "body": body_bytes}
+                
+                request = StarletteRequest(scope, receive)
+            else:
+                logger.debug("   No request body")
+        except Exception as e:
+            logger.debug(f"   Could not read request body: {e}")
     
     # Track if this is an MCP endpoint
     is_mcp = request.url.path.startswith("/mcp") or request.url.path == "/"