feat: Enhance logging for API routes and services to improve traceability

Author: Abdul-Microsoft

infra/main.bicep

@@ -331,7 +331,6 @@ module applicationInsights 'br/public:avm/res/insights/component:0.7.1' = if (en
     flowType: 'Bluefield'
     // WAF aligned configuration for Monitoring
     workspaceResourceId: enableMonitoring ? logAnalyticsWorkspaceResourceId : ''
-    diagnosticSettings: enableMonitoring ? [{ workspaceResourceId: logAnalyticsWorkspaceResourceId }] : null
   }
 }
 // ========== Virtual Network and Networking Components ========== //

src/api/api/api_routes.py

@@ -23,6 +23,7 @@
 @router.get("/fetchChartData")
 async def fetch_chart_data():
     try:
+        logger.info("GET /fetchChartData called")
         chart_service = ChartService()
         response = await chart_service.fetch_chart_data()
         track_event_if_configured(
@@ -76,6 +77,7 @@ async def fetch_chart_data_with_filters(chart_filters: ChartFilters):
 @router.get("/fetchFilterData")
 async def fetch_filter_data():
     try:
+        logger.info("GET /fetchFilterData called")
         chart_service = ChartService()
         response = await chart_service.fetch_filter_data()
         track_event_if_configured(
@@ -103,6 +105,8 @@ async def conversation(request: Request):
         request_json = await request.json()
         conversation_id = request_json.get("conversation_id")
         query = request_json.get("query")
+        logger.info("POST /chat called: conversation_id=%s, query_length=%d",
+                    conversation_id, len(query) if query else 0)
 
         # Track chat request initiation
         track_event_if_configured("ChatRequestReceived", {
@@ -116,6 +120,7 @@ async def conversation(request: Request):
 
         chat_service = ChatService()
         result = await chat_service.stream_chat_request(conversation_id, query)
+        logger.info("Chat stream initiated successfully for conversation_id=%s", conversation_id)
         track_event_if_configured(
             "ChatStreamSuccess",
             {"conversation_id": conversation_id, "query": query}
@@ -141,6 +146,7 @@ async def conversation(request: Request):
 
 @router.get("/layout-config")
 async def get_layout_config():
+    logger.info("GET /layout-config called")
     layout_config_str = os.getenv("REACT_APP_LAYOUT_CONFIG", "")
     if layout_config_str:
         try:
@@ -164,6 +170,7 @@ async def get_layout_config():
 
 @router.get("/display-chart-default")
 async def get_chart_config():
+    logger.info("GET /display-chart-default called")
     chart_config = os.getenv("DISPLAY_CHART_DEFAULT", "")
     if chart_config:
         track_event_if_configured("ChartDisplayDefaultFetched", {"value": chart_config})
@@ -182,6 +189,7 @@ async def fetch_azure_search_content_endpoint(request: Request):
         # Parse the request JSON
         request_json = await request.json()
         url = request_json.get("url")
+        logger.info("POST /fetch-azure-search-content called: url=%s", url)
 
         if not url:
             return JSONResponse(content={"error": "URL is required"}, status_code=400)
@@ -207,8 +215,10 @@ def fetch_content():
                     data = response.json()
                     content = data.get("content", "")
                     title = data.get("sourceurl", "")
+                    logger.info("Azure Search content fetched successfully: url=%s", url)
                     return {"content": content, "title": title}
                 else:
+                    logger.warning("Azure Search content fetch failed: url=%s, status=%d", url, response.status_code)
                     return {"error": f"HTTP {response.status_code}"}
             except Exception:
                 logger.exception("Exception occurred while making the HTTP request")

src/api/api/history_routes.py

@@ -25,6 +25,7 @@ async def update_conversation(request: Request):
         # Parse request body
         request_json = await request.json()
         conversation_id = request_json.get("conversation_id")
+        logger.info("POST /history/update called: conversation_id=%s, user_id=%s", conversation_id, user_id)
 
         if not conversation_id:
             raise HTTPException(status_code=400, detail="No conversation_id found")
@@ -39,6 +40,8 @@ async def update_conversation(request: Request):
 
         if not update_response:
             raise HTTPException(status_code=500, detail="Failed to update conversation")
+        logger.info("Conversation updated successfully: conversation_id=%s, title='%s'",
+                    conversation_id, update_response.get("title"))
         track_event_if_configured("ConversationUpdated", {
             "user_id": user_id,
             "conversation_id": conversation_id,
@@ -80,6 +83,7 @@ async def update_message_feedback(request: Request):
         request_json = await request.json()
         message_id = request_json.get("message_id")
         message_feedback = request_json.get("message_feedback")
+        logger.info("POST /history/message_feedback called: message_id=%s, user_id=%s", message_id, user_id)
 
         if not message_id:
             track_event_if_configured("MessageFeedbackValidationError", {
@@ -144,6 +148,7 @@ async def delete_conversation(request: Request):
         # Parse request body
         request_json = await request.json()
         conversation_id = request_json.get("conversation_id")
+        logger.info("DELETE /history/delete called: conversation_id=%s, user_id=%s", conversation_id, user_id)
         if not conversation_id:
             track_event_if_configured("DeleteConversationValidationError", {
                 "error": "conversation_id is missing",
@@ -159,6 +164,7 @@ async def delete_conversation(request: Request):
         # Delete conversation using HistoryService
         deleted = await history_service.delete_conversation(user_id, conversation_id)
         if deleted:
+            logger.info("Conversation deleted successfully: conversation_id=%s, user_id=%s", conversation_id, user_id)
             track_event_if_configured("ConversationDeleted", {
                 "user_id": user_id,
                 "conversation_id": conversation_id
@@ -247,6 +253,7 @@ async def get_conversation_messages(request: Request):
         # Parse request body
         request_json = await request.json()
         conversation_id = request_json.get("conversation_id")
+        logger.info("POST /history/read called: conversation_id=%s, user_id=%s", conversation_id, user_id)
 
         if not conversation_id:
             track_event_if_configured("ReadConversationValidationError", {
@@ -271,6 +278,7 @@ async def get_conversation_messages(request: Request):
                 status_code=404,
                 detail=f"Conversation {conversation_id} was not found. It either does not exist or the user does not have access to it."
             )
+        logger.info("Returning %d message(s) for conversation %s", len(conversationMessages), conversation_id)
         track_event_if_configured("ConversationRead", {
             "user_id": user_id,
             "conversation_id": conversation_id,
@@ -307,6 +315,8 @@ async def rename_conversation(request: Request):
         request_json = await request.json()
         conversation_id = request_json.get("conversation_id")
         title = request_json.get("title")
+        logger.info("POST /history/rename called: conversation_id=%s, user_id=%s, new_title='%s'",
+                    conversation_id, user_id, title)
 
         if not conversation_id:
             track_event_if_configured("RenameConversationValidationError", {
@@ -328,6 +338,7 @@ async def rename_conversation(request: Request):
             raise HTTPException(status_code=400, detail="title is required")
 
         rename_conversation = await history_service.rename_conversation(user_id, conversation_id, title)
+        logger.info("Conversation renamed successfully: conversation_id=%s, new_title='%s'", conversation_id, title)
 
         track_event_if_configured("ConversationRenamed", {
             "user_id": user_id,
@@ -357,6 +368,7 @@ async def delete_all_conversations(request: Request):
         authenticated_user = get_authenticated_user_details(
             request_headers=request.headers)
         user_id = authenticated_user["user_principal_id"]
+        logger.info("DELETE /history/delete_all called: user_id=%s", user_id)
 
         # Get all user conversations
         conversations = await history_service.get_conversations(user_id, offset=0, limit=None)
@@ -368,8 +380,10 @@ async def delete_all_conversations(request: Request):
                                 detail=f"No conversations for {user_id} were found")
 
         # Delete all conversations
+        logger.info("Deleting %d conversation(s) for user %s", len(conversations), user_id)
         for conversation in conversations:
             await history_service.delete_conversation(user_id, conversation["id"])
+        logger.info("All conversations deleted successfully for user %s", user_id)
 
         track_event_if_configured("AllConversationsDeleted", {
             "user_id": user_id,
@@ -406,6 +420,7 @@ async def clear_messages(request: Request):
         # Parse request body
         request_json = await request.json()
         conversation_id = request_json.get("conversation_id")
+        logger.info("POST /history/clear called: conversation_id=%s, user_id=%s", conversation_id, user_id)
 
         if not conversation_id:
             track_event_if_configured("ClearMessagesValidationError", {
@@ -430,6 +445,7 @@ async def clear_messages(request: Request):
             raise HTTPException(
                 status_code=404,
                 detail="Failed to clear messages or conversation not found")
+        logger.info("Messages cleared successfully for conversation %s, user %s", conversation_id, user_id)
         track_event_if_configured("MessagesCleared", {
             "user_id": user_id,
             "conversation_id": conversation_id
@@ -456,6 +472,7 @@ async def clear_messages(request: Request):
 @router.get("/history/ensure")
 async def ensure_cosmos():
     try:
+        logger.info("GET /history/ensure called")
         success, err = await history_service.ensure_cosmos()
         if not success:
             track_event_if_configured("CosmosDBEnsureFailed", {

src/api/app.py

@@ -17,6 +17,10 @@
 from api.api_routes import router as backend_router
 from api.history_routes import router as history_router
 
+# Configure Azure Monitor and OpenTelemetry imports
+from azure.monitor.opentelemetry import configure_azure_monitor
+from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
+
 # Load environment variables
 load_dotenv()
 
@@ -40,16 +44,6 @@
 for logger_name in AZURE_LOGGING_PACKAGES:
     logging.getLogger(logger_name).setLevel(getattr(logging, AZURE_PACKAGE_LOGGING_LEVEL, logging.WARNING))
 
-# Suppress noisy OpenTelemetry and Azure Monitor logs
-logging.getLogger("opentelemetry.sdk").setLevel(logging.ERROR)
-logging.getLogger("opentelemetry.instrumentation.httpx").setLevel(logging.WARNING)
-logging.getLogger("opentelemetry.instrumentation.aiohttp-client").setLevel(logging.WARNING)
-logging.getLogger("azure.core.pipeline.policies.http_logging_policy").setLevel(logging.WARNING)
-logging.getLogger("azure.monitor.opentelemetry.exporter.export._base").setLevel(logging.WARNING)
-
-# Configure Azure Monitor and OpenTelemetry imports
-from azure.monitor.opentelemetry import configure_azure_monitor  # noqa: E402
-from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor  # noqa: E402
 
 
 def build_app() -> FastAPI:
@@ -83,15 +77,24 @@ async def health_check():
     instrumentation_key = os.getenv("APPLICATIONINSIGHTS_CONNECTION_STRING")
     if instrumentation_key:
         # Configure Application Insights telemetry with live metrics
-        # Set disable_offline_storage=True to reduce logs about offline storage
         configure_azure_monitor(
             connection_string=instrumentation_key,
-            enable_live_metrics=True,
-            disable_offline_storage=True  # Reduces "Storing events" logs
+            enable_live_metrics=True
         )
 
-        # Instrument FastAPI app to automatically trace all requests
-        FastAPIInstrumentor.instrument_app(fastapi_app)
+        # Suppress noisy OpenTelemetry logs
+        logging.getLogger("opentelemetry.sdk").setLevel(logging.ERROR)
+        logging.getLogger("azure.monitor.opentelemetry.exporter.export._base").setLevel(logging.WARNING)
+        logging.getLogger("azure.core.pipeline.policies.http_logging_policy").setLevel(logging.WARNING)
+        logging.getLogger("azure.core.pipeline.policies._universal").setLevel(logging.WARNING)
+        logging.getLogger("azure.core.pipeline.policies").setLevel(logging.WARNING)
+        logging.getLogger("azure.identity").setLevel(logging.WARNING)
+
+        # Instrument FastAPI app — exclude health-check URL to reduce telemetry noise
+        FastAPIInstrumentor.instrument_app(
+            fastapi_app,
+            excluded_urls="health"
+        )
         logging.info("Application Insights configured with live metrics and FastAPI instrumentation enabled")
     else:
         logging.warning("No Application Insights connection string found. Telemetry disabled.")

src/api/services/chat_service.py

@@ -120,6 +120,8 @@ async def stream_openai_text(self, conversation_id: str, query: str) -> Streamin
         """
         Get a streaming text response from OpenAI.
         """
+        logger.info("stream_openai_text called: conversation_id=%s, query_length=%d",
+                    conversation_id, len(query) if query else 0)
         async with (
             await get_azure_credential_async(client_id=self.azure_client_id) as credential,
             AIProjectClient(endpoint=self.ai_project_endpoint, credential=credential) as project_client,
@@ -139,12 +141,17 @@ async def stream_openai_text(self, conversation_id: str, query: str) -> Streamin
                 thread_conversation_id = None
                 cache = self.get_thread_cache()
                 thread_conversation_id = cache.get(conversation_id, None)
+                if thread_conversation_id:
+                    logger.info("Reusing existing thread %s for conversation %s",
+                                thread_conversation_id, conversation_id)
 
                 # Get agent with tools using provider
+                logger.info("Retrieving orchestrator agent: '%s'", self.orchestrator_agent_name)
                 agent = await provider.get_agent(
                     name=self.orchestrator_agent_name,
                     tools=custom_tool.get_sql_response
                 )
+                logger.info("Orchestrator agent retrieved successfully: '%s'", self.orchestrator_agent_name)
 
                 citations = []
                 first_chunk = True
@@ -153,9 +160,11 @@ async def stream_openai_text(self, conversation_id: str, query: str) -> Streamin
 
                 if not thread_conversation_id:
                     # Create a conversation using OpenAI client for conversation continuity
+                    logger.info("No existing thread found, creating new thread for conversation %s", conversation_id)
                     openai_client = project_client.get_openai_client()
                     conversation = await openai_client.conversations.create()
                     thread_conversation_id = conversation.id
+                    logger.info("New thread created: %s for conversation %s", thread_conversation_id, conversation_id)
 
                 def replace_citation_marker(match):
                     nonlocal citation_counter
@@ -165,6 +174,8 @@ def replace_citation_marker(match):
                         citation_marker_map[marker] = citation_counter
                     return f"[{citation_marker_map[marker]}]"
 
+                logger.info("Starting agent.run stream for conversation %s, thread %s",
+                            conversation_id, thread_conversation_id)
                 async for chunk in agent.run(query, stream=True, conversation_id=thread_conversation_id):
                     # Collect citations from Azure AI Search responses
                     for content in getattr(chunk, "contents", []):
@@ -181,10 +192,13 @@ def replace_citation_marker(match):
                         complete_response += chunk_text
                         if first_chunk:
                             first_chunk = False
+                            logger.info("First chunk received for conversation %s, streaming response", conversation_id)
                             yield "{ \"answer\": " + chunk_text
                         else:
                             yield chunk_text
 
+                logger.info("Streaming complete for conversation %s: response_length=%d, citation_count=%d",
+                            conversation_id, len(complete_response), len(citations))
                 cache[conversation_id] = thread_conversation_id
 
                 if citations:
@@ -255,6 +269,7 @@ async def stream_chat_request(self, conversation_id, query):
         """
         Handles streaming chat requests.
         """
+        logger.info("stream_chat_request called: conversation_id=%s", conversation_id)
 
         async def generate():
             try: