Merge pull request #648 from microsoft/psl-extralogs

fix: added extra logs for debugging

Author: Roopan-Microsoft

src/backend/v3/api/router.py

@@ -749,10 +749,12 @@ async def upload_team_config(
         )
 
         # Validate search indexes
+        logger.info(f"🔍 Validating search indexes for user: {user_id}")
         search_valid, search_errors = await team_service.validate_team_search_indexes(
             json_data
         )
         if not search_valid:
+            logger.warning(f"❌ Search validation failed for user {user_id}: {search_errors}")
             error_message = (
                 f"Search index validation failed:\n\n{chr(10).join([f'• {error}' for error in search_errors])}\n\n"
                 f"Please ensure all referenced search indexes exist in your Azure AI Search service."
@@ -768,6 +770,7 @@ async def upload_team_config(
             )
             raise HTTPException(status_code=400, detail=error_message)
 
+        logger.info(f"✅ Search validation passed for user: {user_id}")
         track_event_if_configured(
             "Team configuration search validation passed",
             {"status": "passed", "user_id": user_id, "filename": file.filename},

src/backend/v3/callbacks/response_handlers.py

@@ -17,6 +17,8 @@
     WebsocketMessageType,
 )
 
+logger = logging.getLogger(__name__)
+
 
 def clean_citations(text: str) -> str:
     """Remove citation markers from agent responses while preserving formatting."""
@@ -43,18 +45,26 @@ def agent_response_callback(message: ChatMessageContent, user_id: str = None) ->
     # Get agent name to determine handling
     agent_name = message.name or "Unknown Agent"
 
+    logger.info(f"🤖 Agent Response from '{agent_name}' for user: {user_id}")
+
     role = getattr(message, "role", "unknown")
 
     # Send to WebSocket
     if user_id:
         try:
             if message.items and message.items[0].content_type == "function_call":
+                logger.info(f" Message content_type: {message.items[0].content_type}")
+                logger.info(f"🔧 Tool calls detected from agent: {agent_name}")
                 final_message = AgentToolMessage(agent_name=agent_name)
                 for item in message.items:
                     if item.content_type == "function_call":
+                        tool_name = item.name or "unknown_tool"
+                        tool_args = item.arguments or {}
+                        logger.info(f"🛠️ Tool call: {tool_name} with args: {str(tool_args)[:200]}...")
+
                         tool_call = AgentToolCall(
-                            tool_name=item.name or "unknown_tool",
-                            arguments=item.arguments or {},
+                            tool_name=tool_name,
+                            arguments=tool_args,
                         )
                         final_message.tool_calls.append(tool_call)
 
@@ -67,9 +77,18 @@ def agent_response_callback(message: ChatMessageContent, user_id: str = None) ->
                 )
                 logging.info(f"Function call: {final_message}")
             elif message.items and message.items[0].content_type == "function_result":
+                # Log function results for debugging
+                logger.info(f" Message content_type: {message.items[0].content_type}")
+                logger.info(f"📥 Function result received from agent: {agent_name}")
+                for item in message.items:
+                    if item.content_type == "function_result":
+                        result_content = str(item.result)[:300] if hasattr(item, 'result') else "No result"
+                        logger.info(f"🔍 Function result: {result_content}...")
                 # skip returning these results for now - agent will return in a later message
                 pass
             else:
+                logger.info(f" Message content_type: {message.items[0].content_type}")
+                logger.info(f"💬 Text message from agent: {agent_name}")
                 final_message = AgentMessage(
                     agent_name=agent_name,
                     timestamp=time.time() or "",

src/backend/v3/config/settings.py

@@ -61,14 +61,17 @@ def __init__(self):
         self.url = config.MCP_SERVER_ENDPOINT
         self.name = config.MCP_SERVER_NAME
         self.description = config.MCP_SERVER_DESCRIPTION
+        logger.info(f"🔧 MCP Config initialized - URL: {self.url}, Name: {self.name}")
 
     def get_headers(self, token: str):
         """Get MCP headers with authentication token."""
-        return (
+        headers = (
             {"Authorization": f"Bearer {token}", "Content-Type": "application/json"}
             if token
             else {}
         )
+        logger.debug(f"📋 MCP Headers created: {headers}")
+        return headers
 
 
 class OrchestrationConfig:
@@ -127,6 +130,7 @@ async def wait_for_approval(self, plan_id: str, timeout: Optional[float] = None)
             asyncio.TimeoutError: If timeout is exceeded
             KeyError: If plan_id is not found in approvals
         """
+        logger.info(f"Waiting for approval: {plan_id}")
         if timeout is None:
             timeout = self.default_timeout
 
@@ -142,9 +146,11 @@ async def wait_for_approval(self, plan_id: str, timeout: Optional[float] = None)
 
         try:
             await asyncio.wait_for(self._approval_events[plan_id].wait(), timeout=timeout)
+            logger.info(f"Approval received: {plan_id}")
             return self.approvals[plan_id]
         except asyncio.TimeoutError:
             # Clean up on timeout
+            logger.warning(f"Approval timeout: {plan_id}")
             self.cleanup_approval(plan_id)
             raise
         except asyncio.CancelledError:

src/backend/v3/magentic_agents/common/lifecycle.py

@@ -1,5 +1,6 @@
 from contextlib import AsyncExitStack
 from typing import Any
+import logging
 
 from azure.ai.projects.aio import AIProjectClient
 from azure.identity.aio import DefaultAzureCredential
@@ -8,6 +9,8 @@
 from v3.magentic_agents.models.agent_models import MCPConfig
 from v3.config.agent_registry import agent_registry
 
+logger = logging.getLogger(__name__)
+
 
 class MCPEnabledBase:
     """
@@ -74,6 +77,7 @@ async def _after_open(self) -> None:
 
     async def _enter_mcp_if_configured(self) -> None:
         if not self.mcp_cfg:
+            logger.error("No MCP configuration provided")
             return
         # headers = self._build_mcp_headers()
         plugin = MCPStreamableHttpPlugin(
@@ -85,7 +89,13 @@ async def _enter_mcp_if_configured(self) -> None:
         # Enter MCP async context via the stack to ensure correct LIFO cleanup
         if self._stack is None:
             self._stack = AsyncExitStack()
-        self.mcp_plugin = await self._stack.enter_async_context(plugin)
+
+        try:
+            self.mcp_plugin = await self._stack.enter_async_context(plugin)
+            logger.info(f"✅ MCP plugin '{self.mcp_cfg.name}' successfully initialized")
+        except Exception as e:
+            logger.error(f"❌ Failed to initialize MCP plugin '{self.mcp_cfg.name}': {e}")
+            raise
 
 
 class AzureAgentBase(MCPEnabledBase):

src/backend/v3/magentic_agents/foundry_agent.py

@@ -172,14 +172,22 @@ async def _after_open(self) -> None:
         # Add MCP plugins if available
         plugins = [self.mcp_plugin] if self.mcp_plugin else []
 
+        if self.mcp_plugin:
+            self.logger.info(f"🔧 Adding MCP plugin to agent: {self.agent_name}")
+            self.logger.debug(f"MCP plugin name: {getattr(self.mcp_plugin, 'name', 'Unknown')}")
+        else:
+            self.logger.debug(f"No MCP plugin for agent: {self.agent_name}")
+
         try:
+            self.logger.info(f"🤖 Creating AzureAI agent: {self.agent_name}")
             self._agent = AzureAIAgent(
                 client=self.client,
                 definition=definition,
                 plugins=plugins,
             )
+            self.logger.info(f"✅ AzureAI agent created successfully: {self.agent_name}")
         except Exception as ex:
-            self.logger.error("Failed to create AzureAIAgent: %s", ex)
+            self.logger.error("❌ Failed to create AzureAIAgent '%s': %s", self.agent_name, ex)
             raise
 
         # Register agent with global registry for tracking and cleanup

src/backend/v3/magentic_agents/proxy_agent.py

@@ -282,7 +282,7 @@ async def _wait_for_user_clarification(
         Raises:
             asyncio.TimeoutError: If timeout is exceeded (300 seconds default)
         """
-        # logger.info(f"Waiting for user clarification for request: {request_id}")
+        logger.info(f"Waiting for clarification: {request_id}")
 
         # Initialize clarification as pending using the new event-driven method
         orchestration_config.set_clarification_pending(request_id)
@@ -291,14 +291,14 @@ async def _wait_for_user_clarification(
             # Wait for clarification with timeout using the new event-driven method
             answer = await orchestration_config.wait_for_clarification(request_id)
 
-            # logger.info(f"Clarification received for request {request_id}: {answer}")
+            logger.info(f"Clarification received for {request_id} : {answer}")
             return UserClarificationResponse(
                 request_id=request_id,
                 answer=answer,
             )
         except asyncio.TimeoutError:
             # Enhanced timeout handling - notify user via WebSocket and cleanup
-            logger.debug(f"Clarification timeout for request {request_id} - notifying user and terminating process")
+            logger.warning(f"Clarification timeout for request: {request_id}")
 
             # Create timeout notification message
             from v3.models.messages import TimeoutNotification, WebsocketMessageType

src/backend/v3/orchestration/human_approval_manager.py

@@ -53,6 +53,7 @@ def __init__(self, user_id: str, *args, **kwargs):
         # Remove any custom kwargs before passing to parent
 
         plan_append = """
+
 IMPORTANT: Never ask the user for information or clarification until all agents on the team have been asked first.
 
 EXAMPLE: If the user request involves product information, first ask all agents on the team to provide the information.
@@ -69,7 +70,6 @@ def __init__(self, user_id: str, *args, **kwargs):
 - **DocumentCreationAgent** to draft a comprehensive onboarding plan that includes a checklist of resources and materials needed for effective onboarding.
 - **ProxyAgent** to review the drafted onboarding plan for clarity and completeness.
 - **MagenticManager** to finalize the onboarding plan and prepare it for presentation to stakeholders.
-
 """
 
         final_append = """

src/backend/v3/orchestration/orchestration_manager.py

@@ -39,6 +39,7 @@ async def init_orchestration(
         cls, agents: List, user_id: str = None
     ) -> MagenticOrchestration:
         """Main function to run the agents."""
+        cls.logger.info(f"Initializing orchestration for user: {user_id}")
 
         # Custom execution settings that should work with Azure OpenAI
         execution_settings = OpenAIChatPromptExecutionSettings(
@@ -97,6 +98,7 @@ async def get_current_or_new_orchestration(
         cls, user_id: str, team_config: TeamConfiguration, team_switched: bool
     ) -> MagenticOrchestration:  # add team_switched: bool parameter
         """get existing orchestration instance."""
+        cls.logger.info(f"Getting orchestration for user: {user_id}, team_switched: {team_switched}")
         current_orchestration = orchestration_config.get_current_orchestration(user_id)
         if (
             current_orchestration is None or team_switched
@@ -117,6 +119,7 @@ async def get_current_or_new_orchestration(
 
     async def run_orchestration(self, user_id, input_task) -> None:
         """Run the orchestration with user input loop."""
+        self.logger.info(f"Starting orchestration run for user: {user_id}")
 
         job_id = str(uuid.uuid4())
 
@@ -139,13 +142,15 @@ async def run_orchestration(self, user_id, input_task) -> None:
 
         runtime = InProcessRuntime()
         runtime.start()
+        self.logger.info(f"🎯 Starting task execution: {input_task.description[:100]}...")
 
         try:
 
             orchestration_result = await magentic_orchestration.invoke(
                 task=input_task.description,
                 runtime=runtime,
             )
+            self.logger.info("📊 Task invocation completed, retrieving results")
 
             try:
                 self.logger.info("\nAgent responses:")