Merge pull request #389 from microsoft/psl-logging-enhancement

feat: improve Application Insights logging and telemetry handling

Author: Roopan-Microsoft

infra/main.bicep

@@ -285,7 +285,6 @@ module applicationInsights 'br/public:avm/res/insights/component:0.7.0' = if (en
     name: 'appi-${solutionSuffix}'
     location: location
     workspaceResourceId: logAnalyticsWorkspaceResourceId
-    diagnosticSettings: [{ workspaceResourceId: logAnalyticsWorkspaceResourceId }]
     tags: allTags
     enableTelemetry: enableTelemetry
     retentionInDays: 365

infra/main.json

@@ -6,7 +6,7 @@
     "_generator": {
       "name": "bicep",
       "version": "0.41.2.15936",
-      "templateHash": "18262017557117529046"
+      "templateHash": "3093757051086668797"
     },
     "name": "Modernize Your Code Solution Accelerator",
     "description": "CSA CTO Gold Standard Solution Accelerator for Modernize Your Code. \r\n"
@@ -3919,13 +3919,6 @@
             "value": "[parameters('location')]"
           },
           "workspaceResourceId": "[if(variables('useExistingLogAnalytics'), createObject('value', parameters('existingLogAnalyticsWorkspaceId')), createObject('value', reference('logAnalyticsWorkspace').outputs.resourceId.value))]",
-          "diagnosticSettings": {
-            "value": [
-              {
-                "workspaceResourceId": "[if(variables('useExistingLogAnalytics'), parameters('existingLogAnalyticsWorkspaceId'), reference('logAnalyticsWorkspace').outputs.resourceId.value)]"
-              }
-            ]
-          },
           "tags": {
             "value": "[variables('allTags')]"
           },
@@ -12902,11 +12895,11 @@
       },
       "dependsOn": [
         "applicationInsights",
+        "[format('avmPrivateDnsZones[{0}]', variables('dnsZoneIndex').storageBlob)]",
         "[format('avmPrivateDnsZones[{0}]', variables('dnsZoneIndex').ods)]",
         "[format('avmPrivateDnsZones[{0}]', variables('dnsZoneIndex').agentSvc)]",
-        "[format('avmPrivateDnsZones[{0}]', variables('dnsZoneIndex').storageBlob)]",
-        "[format('avmPrivateDnsZones[{0}]', variables('dnsZoneIndex').oms)]",
         "[format('avmPrivateDnsZones[{0}]', variables('dnsZoneIndex').monitor)]",
+        "[format('avmPrivateDnsZones[{0}]', variables('dnsZoneIndex').oms)]",
         "dataCollectionEndpoint",
         "logAnalyticsWorkspace",
         "virtualNetwork"
@@ -16624,15 +16617,9 @@
           "osType": {
             "value": "Windows"
           },
-          "vmSize": {
-            "value": "[if(not(empty(parameters('vmSize'))), parameters('vmSize'), 'Standard_D2s_v5')]"
-          },
-          "adminUsername": {
-            "value": "[if(not(empty(parameters('vmAdminUsername'))), parameters('vmAdminUsername'), 'JumpboxAdminUser')]"
-          },
-          "adminPassword": {
-            "value": "[if(not(empty(parameters('vmAdminPassword'))), parameters('vmAdminPassword'), 'JumpboxAdminP@ssw0rd1234!')]"
-          },
+          "vmSize": "[if(not(empty(parameters('vmSize'))), createObject('value', parameters('vmSize')), createObject('value', 'Standard_D2s_v5'))]",
+          "adminUsername": "[if(not(empty(parameters('vmAdminUsername'))), createObject('value', parameters('vmAdminUsername')), createObject('value', 'JumpboxAdminUser'))]",
+          "adminPassword": "[if(not(empty(parameters('vmAdminPassword'))), createObject('value', parameters('vmAdminPassword')), createObject('value', 'JumpboxAdminP@ssw0rd1234!'))]",
           "managedIdentities": {
             "value": {
               "systemAssigned": true
@@ -31930,8 +31917,8 @@
       "dependsOn": [
         "aiServices",
         "[format('avmPrivateDnsZones[{0}]', variables('dnsZoneIndex').openAI)]",
-        "[format('avmPrivateDnsZones[{0}]', variables('dnsZoneIndex').aiServices)]",
         "[format('avmPrivateDnsZones[{0}]', variables('dnsZoneIndex').cognitiveServices)]",
+        "[format('avmPrivateDnsZones[{0}]', variables('dnsZoneIndex').aiServices)]",
         "virtualNetwork"
       ]
     },

infra/main_custom.bicep

@@ -288,7 +288,6 @@ module applicationInsights 'br/public:avm/res/insights/component:0.7.0' = if (en
     name: 'appi-${solutionSuffix}'
     location: location
     workspaceResourceId: logAnalyticsWorkspaceResourceId
-    diagnosticSettings: [{ workspaceResourceId: logAnalyticsWorkspaceResourceId }]
     tags: allTags
     enableTelemetry: enableTelemetry
     retentionInDays: 365

src/backend/api/api_routes.py

@@ -44,6 +44,15 @@ def record_exception_to_trace(e):
         span.set_status(Status(StatusCode.ERROR, str(e)))
 
 
+def set_span_attributes(**attributes):
+    """Set key-value attributes on the current OpenTelemetry span."""
+    span = trace.get_current_span()
+    if span and span.is_recording():
+        for key, value in attributes.items():
+            if value:
+                span.set_attribute(key, str(value))
+
+
 # start processing the batch
 @router.post("/start-processing")
 async def start_processing(request: Request):
@@ -82,11 +91,13 @@ async def start_processing(request: Request):
       500:
         description: Internal server error
     """
+    batch_id = None
     try:
         payload = await request.json()
         batch_id = payload.get("batch_id")
         translate_from = payload.get("translate_from")
         translate_to = payload.get("translate_to")
+        set_span_attributes(batch_id=batch_id)
 
         track_event_if_configured(
             "ProcessingStart",
@@ -103,6 +114,10 @@ async def start_processing(request: Request):
             "message": "Files processed",
         }
     except Exception as e:
+        event_data = {"error": str(e)}
+        if batch_id is not None:
+            event_data["batch_id"] = batch_id
+        track_event_if_configured("ProcessingFailed", event_data)
         record_exception_to_trace(e)
         raise HTTPException(status_code=500, detail=str(e)) from e
 
@@ -146,6 +161,7 @@ async def download_files(batch_id: str):
     # call batch_service get_batch_for_zip to get all files for batch_id
     batch_service = BatchService()
     await batch_service.initialize_database()
+    set_span_attributes(batch_id=batch_id)
 
     file_data = await batch_service.get_batch_for_zip(batch_id)
     if not file_data:
@@ -187,6 +203,7 @@ async def download_files(batch_id: str):
         )
         return Response(zip_data, media_type="application/zip", headers=headers)
     except Exception as e:
+        track_event_if_configured("DownloadZipFailed", {"batch_id": batch_id, "error": str(e)})
         record_exception_to_trace(e)
         raise HTTPException(
             status_code=404, detail=f"Error creating ZIP file: {str(e)}"
@@ -270,7 +287,7 @@ async def batch_status_updates(
         await close_connection(batch_id)
     except Exception as e:
         record_exception_to_trace(e)
-        logger.error("Error in WebSocket connection", error=str(e))
+        logger.error("Error in WebSocket connection", error=str(e), batch_id=batch_id)
         await close_connection(batch_id)
 
 
@@ -373,15 +390,16 @@ async def get_batch_status(request: Request, batch_id: str):
         # Authenticate user
         authenticated_user = get_authenticated_user(request)
         user_id = authenticated_user.user_principal_id
+        set_span_attributes(batch_id=batch_id, user_id=user_id)
         if not user_id:
             track_event_if_configured(
-                "UserIdNotFound", {"status_code": 400, "detail": "no user"}
+                "UserIdNotFound", {"status_code": 400, "detail": "no user", "batch_id": batch_id}
             )
             raise HTTPException(status_code=401, detail="User not authenticated")
 
         # Validate batch_id format
         if not batch_service.is_valid_uuid(batch_id):
-            track_event_if_configured("InvalidBatchId", {"batch_id": batch_id})
+            track_event_if_configured("InvalidBatchId", {"batch_id": batch_id, "user_id": user_id})
             raise HTTPException(status_code=400, detail="Invalid batch_id format")
 
         # Fetch batch details
@@ -399,7 +417,7 @@ async def get_batch_status(request: Request, batch_id: str):
         record_exception_to_trace(e)
         raise e
     except Exception as e:
-        logger.error("Error retrieving batch history", error=str(e))
+        logger.error("Error retrieving batch history", error=str(e), batch_id=batch_id)
         record_exception_to_trace(e)
         error_message = str(e)
         if "403" in error_message:
@@ -417,9 +435,10 @@ async def get_batch_summary(request: Request, batch_id: str):
         # Authenticate user
         authenticated_user = get_authenticated_user(request)
         user_id = authenticated_user.user_principal_id
+        set_span_attributes(batch_id=batch_id, user_id=user_id)
         if not user_id:
             track_event_if_configured(
-                "UserIdNotFound", {"status_code": 400, "detail": "no user"}
+                "UserIdNotFound", {"status_code": 400, "detail": "no user", "batch_id": batch_id}
             )
             raise HTTPException(status_code=401, detail="User not authenticated")
 
@@ -431,16 +450,16 @@ async def get_batch_summary(request: Request, batch_id: str):
             )
             raise HTTPException(status_code=404, detail="No batch summary found.")
         track_event_if_configured(
-            "BatchSummaryRetrieved", {"batch_summary": batch_summary}
+            "BatchSummaryRetrieved", {"batch_id": batch_id, "user_id": user_id, "batch_summary": batch_summary}
         )
         return batch_summary
 
     except HTTPException as e:
-        logger.error("Error fetching batch summary", error=str(e))
+        logger.error("Error fetching batch summary", error=str(e), batch_id=batch_id)
         record_exception_to_trace(e)
         raise e
     except Exception as e:
-        logger.error("Error fetching batch summary", error=str(e))
+        logger.error("Error fetching batch summary", error=str(e), batch_id=batch_id)
         record_exception_to_trace(e)
         raise HTTPException(status_code=404, detail="Batch not found") from e
 
@@ -538,16 +557,17 @@ async def upload_file(
         authenticated_user = get_authenticated_user(request)
         user_id = authenticated_user.user_principal_id
 
+        set_span_attributes(batch_id=batch_id, user_id=user_id)
         if not user_id:
             track_event_if_configured(
-                "UserIdNotFound", {"status_code": 400, "detail": "no user"}
+                "UserIdNotFound", {"status_code": 400, "detail": "no user", "batch_id": batch_id}
             )
             raise HTTPException(status_code=401, detail="User not authenticated")
 
         # Validate batch_id format
-        logger.info(f"batch_id: {batch_id}")
+        logger.info("Upload request received", batch_id=batch_id, filename=str(file.filename))
         if not batch_service.is_valid_uuid(batch_id):
-            track_event_if_configured("InvalidBatchId", {"batch_id": batch_id})
+            track_event_if_configured("InvalidBatchId", {"batch_id": batch_id, "user_id": user_id})
             raise HTTPException(status_code=400, detail="Invalid batch_id format")
 
         # Upload file via BatchService
@@ -660,6 +680,7 @@ async def get_file_details(request: Request, file_id: str):
         # Authenticate user
         authenticated_user = get_authenticated_user(request)
         user_id = authenticated_user.user_principal_id
+        set_span_attributes(file_id=file_id, user_id=user_id)
         if not user_id:
             track_event_if_configured(
                 "UserIdNotFound", {"endpoint": "get_file_details"}
@@ -668,22 +689,22 @@ async def get_file_details(request: Request, file_id: str):
 
         # Validate file_id format
         if not batch_service.is_valid_uuid(file_id):
-            track_event_if_configured("InvalidFileId", {"file_id": file_id})
+            track_event_if_configured("InvalidFileId", {"file_id": file_id, "user_id": user_id})
             raise HTTPException(status_code=400, detail="Invalid file_id format")
 
         # Fetch file details
         file_data = await batch_service.get_file_report(file_id)
         if not file_data:
-            track_event_if_configured("FileNotFound", {"file_id": file_id})
+            track_event_if_configured("FileNotFound", {"file_id": file_id, "user_id": user_id})
             raise HTTPException(status_code=404, detail="File not found")
-        track_event_if_configured("FileDetailsRetrieved", {"file_data": file_data})
+        track_event_if_configured("FileDetailsRetrieved", {"file_id": file_id, "user_id": user_id, "file_data": file_data})
         return file_data
 
     except HTTPException as e:
         record_exception_to_trace(e)
         raise e
     except Exception as e:
-        logger.error("Error retrieving file details", error=str(e))
+        logger.error("Error retrieving file details", error=str(e), file_id=file_id)
         record_exception_to_trace(e)
         raise HTTPException(status_code=500, detail="Internal server error") from e
 
@@ -721,15 +742,16 @@ async def delete_batch_details(request: Request, batch_id: str):
         # Authenticate user
         authenticated_user = get_authenticated_user(request)
         user_id = authenticated_user.user_principal_id
+        set_span_attributes(batch_id=batch_id, user_id=user_id)
         if not user_id:
             track_event_if_configured(
-                "UserIdNotFound", {"endpoint": "delete_batch_details"}
+                "UserIdNotFound", {"batch_id": batch_id, "endpoint": "delete_batch_details"}
             )
             raise HTTPException(status_code=401, detail="User not authenticated")
 
         # Validate file_id format
         if not batch_service.is_valid_uuid(batch_id):
-            track_event_if_configured("InvalidBatchId", {"batch_id": batch_id})
+            track_event_if_configured("InvalidBatchId", {"batch_id": batch_id, "user_id": user_id})
             raise HTTPException(
                 status_code=400, detail=f"Invalid batch_id format: {batch_id}"
             )
@@ -745,7 +767,7 @@ async def delete_batch_details(request: Request, batch_id: str):
         record_exception_to_trace(e)
         raise e
     except Exception as e:
-        logger.error("Failed to delete batch from database", error=str(e))
+        logger.error("Failed to delete batch from database", error=str(e), batch_id=batch_id)
         record_exception_to_trace(e)
         raise HTTPException(status_code=500, detail="Database connection error") from e
 
@@ -783,6 +805,7 @@ async def delete_file_details(request: Request, file_id: str):
         # Authenticate user
         authenticated_user = get_authenticated_user(request)
         user_id = authenticated_user.user_principal_id
+        set_span_attributes(file_id=file_id, user_id=user_id)
         if not user_id:
             track_event_if_configured(
                 "UserIdNotFound", {"endpoint": "delete_file_details"}
@@ -791,15 +814,15 @@ async def delete_file_details(request: Request, file_id: str):
 
         # Validate file_id format
         if not batch_service.is_valid_uuid(file_id):
-            track_event_if_configured("InvalidFileId", {"file_id": file_id})
+            track_event_if_configured("InvalidFileId", {"file_id": file_id, "user_id": user_id})
             raise HTTPException(
                 status_code=400, detail=f"Invalid file_id format: {file_id}"
             )
 
         # Delete file
         file_delete = await batch_service.delete_file(file_id, user_id)
         if file_delete is None:
-            track_event_if_configured("FileDeleteNotFound", {"file_id": file_id})
+            track_event_if_configured("FileDeleteNotFound", {"file_id": file_id, "user_id": user_id})
             raise HTTPException(status_code=404, detail=f"File not found: {file_id}")
 
         logger.info(f"File deleted successfully: {file_delete}")
@@ -810,7 +833,7 @@ async def delete_file_details(request: Request, file_id: str):
         record_exception_to_trace(e)
         raise e
     except Exception as e:
-        logger.error("Failed to delete file from database", error=str(e))
+        logger.error("Failed to delete file from database", error=str(e), file_id=file_id)
         record_exception_to_trace(e)
         raise HTTPException(status_code=500, detail="Database connection error") from e
 

src/backend/api/event_utils.py

@@ -3,69 +3,18 @@
 import os
 
 # Third-party
-from applicationinsights import TelemetryClient
-from applicationinsights.channel import SynchronousQueue, SynchronousSender, TelemetryChannel
+from azure.monitor.events.extension import track_event
 
 from dotenv import load_dotenv
 
 load_dotenv()
 
-# Global telemetry client (initialized once)
-_telemetry_client = None
-
-
-def _get_telemetry_client():
-    """Get or create the Application Insights telemetry client."""
-    global _telemetry_client
-
-    if _telemetry_client is None:
-        connection_string = os.getenv("APPLICATIONINSIGHTS_CONNECTION_STRING")
-        if connection_string:
-            try:
-                # Extract instrumentation key from connection string
-                # Format: InstrumentationKey=xxx;IngestionEndpoint=https://...
-                parts = dict(part.split('=', 1) for part in connection_string.split(';') if '=' in part)
-                instrumentation_key = parts.get('InstrumentationKey')
-
-                if instrumentation_key:
-                    # Create a synchronous channel for immediate sending
-                    sender = SynchronousSender()
-                    queue = SynchronousQueue(sender)
-                    channel = TelemetryChannel(None, queue)
-
-                    _telemetry_client = TelemetryClient(instrumentation_key, channel)
-                    logging.info("Application Insights TelemetryClient initialized successfully")
-                else:
-                    logging.error("Could not extract InstrumentationKey from connection string")
-            except Exception as e:
-                logging.error(f"Failed to initialize TelemetryClient: {e}")
-
-    return _telemetry_client
-
 
 def track_event_if_configured(event_name: str, event_data: dict):
-    """Track a custom event to Application Insights customEvents table.
-
-    This uses the Application Insights SDK TelemetryClient which properly
-    sends custom events to the customEvents table in Application Insights.
-    """
+    """Track a custom event to Application Insights customEvents table."""
     instrumentation_key = os.getenv("APPLICATIONINSIGHTS_CONNECTION_STRING")
     if instrumentation_key:
-        try:
-            client = _get_telemetry_client()
-            if client:
-                # Convert all values to strings to ensure compatibility
-                properties = {k: str(v) for k, v in event_data.items()}
-
-                # Track the custom event
-                client.track_event(event_name, properties=properties)
-                client.flush()  # Ensure immediate sending
-
-                logging.debug(f"Tracked custom event: {event_name} with data: {event_data}")
-            else:
-                logging.warning("TelemetryClient not available, custom event not tracked")
-        except Exception as e:
-            logging.error(f"Failed to track event {event_name}: {e}")
+        track_event(event_name, event_data)
     else:
         logging.warning(
             f"Skipping track_event for {event_name} as Application Insights is not configured"