Enhance logging and telemetry across the application, including improved error handling and attribute tracking in OpenTelemetry spans

Author: Abdul-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

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):
@@ -87,6 +96,7 @@ async def start_processing(request: Request):
         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 +113,7 @@ async def start_processing(request: Request):
             "message": "Files processed",
         }
     except Exception as e:
+        track_event_if_configured("ProcessingFailed", {"batch_id": batch_id, "error": str(e)})
         record_exception_to_trace(e)
         raise HTTPException(status_code=500, detail=str(e)) from e
 
@@ -146,6 +157,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 +199,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 +283,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 +386,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 +413,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 +431,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 +446,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 +553,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 +676,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 +685,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 +738,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 +763,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 +801,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 +810,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 +829,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/app.py

@@ -47,14 +47,17 @@
     format='%(asctime)s - %(name)s - %(levelname)s - %(message)s'
 )
 
+# Suppress noisy Azure SDK and OpenTelemetry internal loggers.
+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.cosmos").setLevel(logging.WARNING)
+logging.getLogger("opentelemetry.sdk").setLevel(logging.WARNING)
+logging.getLogger("azure.monitor.opentelemetry.exporter.export._base").setLevel(logging.WARNING)
+
 # Package config: Azure loggers set to WARNING to suppress INFO
 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("azure.core.pipeline.policies.http_logging_policy").setLevel(logging.WARNING)
-# logging.getLogger("azure.monitor.opentelemetry.exporter.export._base").setLevel(logging.WARNING)
 
 logger = AppLogger("app")
 
@@ -70,7 +73,7 @@ async def lifespan(app: FastAPI):
 
     # Startup
     try:
-        logger.logger.info("Initializing SQL agents...")
+        logger.info("Initializing SQL agents...")
 
         # Create Azure credentials and client
         creds = get_azure_credential(app_config.azure_client_id)
@@ -91,20 +94,20 @@ async def lifespan(app: FastAPI):
 
         # Set the global agents instance
         set_sql_agents(sql_agents)
-        logger.logger.info("SQL agents initialized successfully.")
+        logger.info("SQL agents initialized successfully.")
 
     except Exception as exc:
-        logger.logger.error("Failed to initialize SQL agents: %s", exc)
+        logger.error("Failed to initialize SQL agents")
         # Don't raise the exception to allow the app to start even if agents fail
 
     yield  # Application runs here
 
     # Shutdown
     try:
         if sql_agents:
-            logger.logger.info("Application shutting down - cleaning up SQL agents...")
+            logger.info("Application shutting down - cleaning up SQL agents...")
             await sql_agents.delete_agents()
-            logger.logger.info("SQL agents cleaned up successfully.")
+            logger.info("SQL agents cleaned up successfully.")
 
             # Clear the global agents instance
             await clear_sql_agents()
@@ -113,7 +116,7 @@ async def lifespan(app: FastAPI):
             await azure_client.close()
 
     except Exception as exc:
-        logger.logger.error("Error during agent cleanup: %s", exc)
+        logger.error("Error during agent cleanup")
 
 
 def create_app() -> FastAPI:
@@ -133,8 +136,7 @@ def create_app() -> FastAPI:
     # This must happen AFTER app creation but BEFORE route registration
     instrumentation_key = os.getenv("APPLICATIONINSIGHTS_CONNECTION_STRING")
     if instrumentation_key:
-        # Fix: Patch buggy instrumentors before Azure Monitor loads them
-        # See: https://github.com/microsoft/semantic-kernel/issues/13715
+        # Patch azure.ai.agents, azure.ai.projects instrumentor to handle dict response_format (prevents ValueError)
         patch_instrumentors()
 
         # Configure Azure Monitor with FULL auto-instrumentation
@@ -149,9 +151,9 @@ def create_app() -> FastAPI:
             excluded_urls="health,socket,ws",
         )
 
-        logger.logger.info("Application Insights configured with full auto-instrumentation")
+        logger.info("Application Insights configured with full auto-instrumentation")
     else:
-        logger.logger.warning("No Application Insights connection string found. Telemetry disabled.")
+        logger.warning("No Application Insights connection string found. Telemetry disabled.")
 
     # Include routers with /api prefix
     app.include_router(backend_router, prefix="/api", tags=["backend"])

src/backend/common/logger/app_logger.py

@@ -43,8 +43,8 @@ def info(self, message: Any, **kwargs) -> None:
     def warning(self, message: Any, **kwargs) -> None:
         self.logger.warning(self._format_message(message, **kwargs))
 
-    def error(self, message: Any, **kwargs) -> None:
-        self.logger.error(self._format_message(message, **kwargs))
+    def error(self, message: Any, exc_info=True, **kwargs) -> None:
+        self.logger.error(self._format_message(message, **kwargs), exc_info=exc_info)
 
     def critical(self, message: Any, **kwargs) -> None:
         self.logger.critical(self._format_message(message, **kwargs))

src/backend/common/services/batch_service.py

@@ -285,6 +285,7 @@ async def upload_file_to_batch(self, batch_id: str, user_id: str, file: UploadFi
                 content_type=file.content_type,
                 metadata={"batch_id": batch_id, "user_id": user_id, "file_id": file_id},
             )
+            self.logger.info("File uploaded to blob storage", filename=file.filename, batch_id=batch_id)
 
             # Create file entry
             await self.database.add_file(batch_id, file_id, file.filename, blob_path)
@@ -370,6 +371,7 @@ async def delete_batch_and_files(self, batch_id: str, user_id: str):
                 # Delete file and log entry from database
                 await self.database.delete_file(user_id, str(file_record.file_id))
             await self.database.delete_batch(user_id, batch_id)
+            self.logger.info("Batch and all files deleted successfully", batch_id=batch_id)
             return {"message": "Files deleted successfully"}
 
         except (RuntimeError, ValueError, IOError) as e:
@@ -429,6 +431,7 @@ async def update_batch(self, batch_id: str, status: ProcessStatus):
         batch_record.status = status
         batch_record.updated_at = datetime.utcnow()
         await self.database.update_batch(batch_record)
+        self.logger.info("Batch status updated", batch_id=batch_id, status=status.value)
 
     async def create_candidate(self, file_id: str, candidate: str):
         """Create a new candidate entry in the database and upload the candita file to storage."""