fix: Enhance logging and error tracking across API routes and services

Author: Abdul-Microsoft

src/api/api/api_routes.py

@@ -12,24 +12,13 @@
 from services.chart_service import ChartService
 from common.logging.event_utils import track_event_if_configured
 from helpers.azure_credential_utils import get_azure_credential
-from azure.monitor.opentelemetry import configure_azure_monitor
 from opentelemetry import trace
 from opentelemetry.trace import Status, StatusCode
 
 router = APIRouter()
 
 logger = logging.getLogger(__name__)
 
-# Check if the Application Insights Instrumentation Key is set in the environment variables
-instrumentation_key = os.getenv("APPLICATIONINSIGHTS_CONNECTION_STRING")
-if instrumentation_key:
-    # Configure Application Insights if the Instrumentation Key is found
-    configure_azure_monitor(connection_string=instrumentation_key)
-    logging.info("Application Insights configured with the provided Instrumentation Key")
-else:
-    # Log a warning if the Instrumentation Key is not found
-    logging.warning("No Application Insights Instrumentation Key found. Skipping configuration")
-
 
 @router.get("/fetchChartData")
 async def fetch_chart_data():
@@ -43,6 +32,10 @@ async def fetch_chart_data():
         return JSONResponse(content=response)
     except Exception as e:
         logger.exception("Error in fetch_chart_data: %s", str(e))
+        track_event_if_configured("FetchChartDataError", {
+            "error": str(e),
+            "error_type": type(e).__name__
+        })
         span = trace.get_current_span()
         if span is not None:
             span.record_exception(e)
@@ -53,7 +46,7 @@ async def fetch_chart_data():
 @router.post("/fetchChartDataWithFilters")
 async def fetch_chart_data_with_filters(chart_filters: ChartFilters):
     try:
-        logger.info(f"Received filters: {chart_filters}")
+        logger.info("Received filters: %s", chart_filters)
         chart_service = ChartService()
         response = await chart_service.fetch_chart_data_with_filters(chart_filters)
         track_event_if_configured(
@@ -69,6 +62,10 @@ async def fetch_chart_data_with_filters(chart_filters: ChartFilters):
         return JSONResponse(content=response)
     except Exception as e:
         logger.exception("Error in fetch_chart_data_with_filters: %s", str(e))
+        track_event_if_configured("FetchChartDataWithFiltersError", {
+            "error": str(e),
+            "error_type": type(e).__name__
+        })
         span = trace.get_current_span()
         if span is not None:
             span.record_exception(e)
@@ -88,6 +85,10 @@ async def fetch_filter_data():
         return JSONResponse(content=response)
     except Exception as e:
         logger.exception("Error in fetch_filter_data: %s", str(e))
+        track_event_if_configured("FetchFilterDataError", {
+            "error": str(e),
+            "error_type": type(e).__name__
+        })
         span = trace.get_current_span()
         if span is not None:
             span.record_exception(e)
@@ -102,6 +103,17 @@ async def conversation(request: Request):
         request_json = await request.json()
         conversation_id = request_json.get("conversation_id")
         query = request_json.get("query")
+        
+        # Track chat request initiation
+        track_event_if_configured("ChatRequestReceived", {
+            "conversation_id": conversation_id
+        })
+        
+        # Attach conversation_id to current span for Application Insights correlation
+        span = trace.get_current_span()
+        if span and conversation_id:
+            span.set_attribute("conversation_id", conversation_id)
+        
         chat_service = ChatService()
         result = await chat_service.stream_chat_request(conversation_id, query)
         track_event_if_configured(
@@ -112,6 +124,14 @@ async def conversation(request: Request):
 
     except Exception as ex:
         logger.exception("Error in conversation endpoint: %s", str(ex))
+        
+        # Track specific error type
+        track_event_if_configured("ChatRequestError", {
+            "conversation_id": request_json.get("conversation_id") if 'request_json' in locals() else "",
+            "error": str(ex),
+            "error_type": type(ex).__name__
+        })
+        
         span = trace.get_current_span()
         if span is not None:
             span.record_exception(ex)
@@ -129,6 +149,10 @@ async def get_layout_config():
             return JSONResponse(content=layout_config_json)    # Return the parsed JSON
         except json.JSONDecodeError as e:
             logger.exception("Failed to parse layout config JSON: %s", str(e))
+            track_event_if_configured("LayoutConfigParseError", {
+                "error": str(e),
+                "error_type": "JSONDecodeError"
+            })
             span = trace.get_current_span()
             if span is not None:
                 span.record_exception(e)

src/api/api/history_routes.py

@@ -5,24 +5,13 @@
 from auth.auth_utils import get_authenticated_user_details
 from services.history_service import HistoryService
 from common.logging.event_utils import track_event_if_configured
-from azure.monitor.opentelemetry import configure_azure_monitor
 from opentelemetry import trace
 from opentelemetry.trace import Status, StatusCode
 
 router = APIRouter()
 
 logger = logging.getLogger(__name__)
 
-# Check if the Application Insights Instrumentation Key is set in the environment variables
-instrumentation_key = os.getenv("APPLICATIONINSIGHTS_CONNECTION_STRING")
-if instrumentation_key:
-    # Configure Application Insights if the Instrumentation Key is found
-    configure_azure_monitor(connection_string=instrumentation_key)
-    logging.info("Application Insights configured with the provided Instrumentation Key")
-else:
-    # Log a warning if the Instrumentation Key is not found
-    logging.warning("No Application Insights Instrumentation Key found. Skipping configuration")
-
 # Single instance of HistoryService (if applicable)
 history_service = HistoryService()
 
@@ -41,6 +30,11 @@ async def update_conversation(request: Request):
         if not conversation_id:
             raise HTTPException(status_code=400, detail="No conversation_id found")
 
+        # Attach conversation_id to current span for Application Insights correlation
+        span = trace.get_current_span()
+        if span and conversation_id:
+            span.set_attribute("conversation_id", conversation_id)
+
         # Call HistoryService to update conversation
         update_response = await history_service.update_conversation(user_id, request_json)
 
@@ -65,6 +59,10 @@ async def update_conversation(request: Request):
         )
     except Exception as e:
         logger.exception("Exception in /history/update: %s", str(e))
+        track_event_if_configured("ConversationUpdateError", {
+            "error": str(e),
+            "error_type": type(e).__name__
+        })
         span = trace.get_current_span()
         if span is not None:
             span.record_exception(e)
@@ -126,6 +124,10 @@ async def update_message_feedback(request: Request):
 
     except Exception as e:
         logger.exception("Exception in /history/message_feedback: %s", str(e))
+        track_event_if_configured("MessageFeedbackError", {
+            "error": str(e),
+            "error_type": type(e).__name__
+        })
         span = trace.get_current_span()
         if span is not None:
             span.record_exception(e)
@@ -150,6 +152,11 @@ async def delete_conversation(request: Request):
             })
             raise HTTPException(status_code=400, detail="conversation_id is required")
 
+        # Attach conversation_id to current span for Application Insights correlation
+        span = trace.get_current_span()
+        if span and conversation_id:
+            span.set_attribute("conversation_id", conversation_id)
+
         # Delete conversation using HistoryService
         deleted = await history_service.delete_conversation(user_id, conversation_id)
         if deleted:
@@ -173,6 +180,10 @@ async def delete_conversation(request: Request):
                 detail=f"Conversation {conversation_id} not found or user does not have permission.")
     except Exception as e:
         logger.exception("Exception in /history/delete: %s", str(e))
+        track_event_if_configured("ConversationDeleteError", {
+            "error": str(e),
+            "error_type": type(e).__name__
+        })
         span = trace.get_current_span()
         if span is not None:
             span.record_exception(e)
@@ -191,7 +202,7 @@ async def list_conversations(
             request_headers=request.headers)
         user_id = authenticated_user["user_principal_id"]
 
-        logger.info(f"user_id: {user_id}, offset: {offset}, limit: {limit}")
+        logger.info("Fetching conversations - user_id: %s, offset: %s, limit: %s", user_id, offset, limit)
 
         # Get conversations
         conversations = await history_service.get_conversations(user_id, offset=offset, limit=limit)
@@ -216,6 +227,10 @@ async def list_conversations(
 
     except Exception as e:
         logger.exception("Exception in /history/list: %s", str(e))
+        track_event_if_configured("ConversationsListError", {
+            "error": str(e),
+            "error_type": type(e).__name__
+        })
         span = trace.get_current_span()
         if span is not None:
             span.record_exception(e)
@@ -241,6 +256,11 @@ async def get_conversation_messages(request: Request):
             })
             raise HTTPException(status_code=400, detail="conversation_id is required")
 
+        # Attach conversation_id to current span for Application Insights correlation
+        span = trace.get_current_span()
+        if span and conversation_id:
+            span.set_attribute("conversation_id", conversation_id)
+
         # Get conversation details
         conversationMessages = await history_service.get_conversation_messages(user_id, conversation_id)
         if not conversationMessages:
@@ -266,6 +286,10 @@ async def get_conversation_messages(request: Request):
 
     except Exception as e:
         logger.exception("Exception in /history/read: %s", str(e))
+        track_event_if_configured("ConversationReadError", {
+            "error": str(e),
+            "error_type": type(e).__name__
+        })
         span = trace.get_current_span()
         if span is not None:
             span.record_exception(e)
@@ -291,6 +315,12 @@ async def rename_conversation(request: Request):
                 "user_id": user_id
             })
             raise HTTPException(status_code=400, detail="conversation_id is required")
+
+        # Attach conversation_id to current span for Application Insights correlation
+        span = trace.get_current_span()
+        if span and conversation_id:
+            span.set_attribute("conversation_id", conversation_id)
+
         if not title:
             track_event_if_configured("RenameConversationValidationError", {
                 "error": "title is required",
@@ -310,6 +340,10 @@ async def rename_conversation(request: Request):
 
     except Exception as e:
         logger.exception("Exception in /history/rename: %s", str(e))
+        track_event_if_configured("ConversationRenameError", {
+            "error": str(e),
+            "error_type": type(e).__name__
+        })
         span = trace.get_current_span()
         if span is not None:
             span.record_exception(e)
@@ -351,6 +385,10 @@ async def delete_all_conversations(request: Request):
 
     except Exception as e:
         logging.exception("Exception in /history/delete_all: %s", str(e))
+        track_event_if_configured("AllConversationsDeleteError", {
+            "error": str(e),
+            "error_type": type(e).__name__
+        })
         span = trace.get_current_span()
         if span is not None:
             span.record_exception(e)
@@ -377,6 +415,11 @@ async def clear_messages(request: Request):
             })
             raise HTTPException(status_code=400, detail="conversation_id is required")
 
+        # Attach conversation_id to current span for Application Insights correlation
+        span = trace.get_current_span()
+        if span and conversation_id:
+            span.set_attribute("conversation_id", conversation_id)
+
         # Delete conversation messages from CosmosDB
         success = await history_service.clear_messages(user_id, conversation_id)
 
@@ -400,6 +443,10 @@ async def clear_messages(request: Request):
 
     except Exception as e:
         logger.exception("Exception in /history/clear: %s", str(e))
+        track_event_if_configured("MessagesClearError", {
+            "error": str(e),
+            "error_type": type(e).__name__
+        })
         span = trace.get_current_span()
         if span is not None:
             span.record_exception(e)
@@ -429,6 +476,10 @@ async def ensure_cosmos():
             status_code=200)
     except Exception as e:
         logger.exception("Exception in /history/ensure: %s", str(e))
+        track_event_if_configured("CosmosDBEnsureError", {
+            "error": str(e),
+            "error_type": type(e).__name__
+        })
         span = trace.get_current_span()
         if span is not None:
             span.record_exception(e)

src/api/app.py

@@ -40,6 +40,17 @@
 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 before importing routes
+from azure.monitor.opentelemetry import configure_azure_monitor
+from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
+
 
 def build_app() -> FastAPI:
     """
@@ -67,6 +78,24 @@ async def health_check():
         """Health check endpoint"""
         return {"status": "healthy"}
 
+    # Configure Azure Monitor and instrument FastAPI for OpenTelemetry
+    # This enables automatic request tracing, dependency tracking, and proper operation_id
+    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
+        )
+        
+        # Instrument FastAPI app to automatically trace all requests
+        FastAPIInstrumentor.instrument_app(fastapi_app)
+        logging.info("Application Insights configured with live metrics and FastAPI instrumentation enabled")
+    else:
+        logging.warning("No Application Insights connection string found. Telemetry disabled.")
+
     return fastapi_app
 
 

src/api/helpers/chat_helper.py

@@ -35,7 +35,7 @@ def process_rag_response(rag_response, query):
         {query}
         {rag_response}
         """
-        logger.info(f">>> Processing chart data for response: {rag_response}")
+        logger.info("Processing chart data for response: %s", rag_response)
         completion = client.chat.completions.create(
             model=config.azure_openai_deployment_model,
             messages=[
@@ -45,10 +45,10 @@ def process_rag_response(rag_response, query):
             temperature=0,
         )
         chart_data = completion.choices[0].message.content.strip().replace("```json", "").replace("```", "")
-        logger.info(f">>> Generated chart data: {chart_data}")
+        logger.info("Generated chart data: %s", chart_data)
         return json.loads(chart_data)
     except Exception as e:
-        logger.error(f"Error processing RAG response: {e}")
+        logger.error("Error processing RAG response: %s", str(e))
         return {"error": "Chart could not be generated from this data. Please ask a different question."}