Update telemetry event dependency to OpenTelemetry LoggingHandler

featuremanagement/azuremonitor/_send_telemetry.py

@@ -7,22 +7,25 @@
 
 import logging
 import inspect
+from logging import INFO
 from typing import Any, Callable, Dict, Optional
 from .._models import VariantAssignmentReason, EvaluationEvent, TargetingContext
 
 logger = logging.getLogger(__name__)
 
+# Set up a separate logger for feature-evaluation telemetry events to avoid propagating to the root logger
+_event_logger = logging.getLogger(__name__ + ".events")
+_event_logger.propagate = False
+
 try:
-    from azure.monitor.events.extension import track_event as azure_monitor_track_event  # type: ignore
+    from opentelemetry.sdk._logs import LoggingHandler
     from opentelemetry.context.context import Context
     from opentelemetry.sdk.trace import Span, SpanProcessor
 
-    HAS_AZURE_MONITOR_EVENTS_EXTENSION = True
+    HAS_OPENTELEMETRY_LOGGING = True
 except ImportError:
-    HAS_AZURE_MONITOR_EVENTS_EXTENSION = False
-    logger.warning(
-        "azure-monitor-events-extension is not installed. Telemetry will not be sent to Application Insights."
-    )
+    HAS_OPENTELEMETRY_LOGGING = False
+    LoggingHandler = object  # type: ignore
     SpanProcessor = object  # type: ignore
     Span = object  # type: ignore
     Context = object  # type: ignore
@@ -37,11 +40,24 @@
 VERSION = "Version"
 VARIANT_ASSIGNMENT_PERCENTAGE = "VariantAssignmentPercentage"
 MICROSOFT_TARGETING_ID = "Microsoft.TargetingId"
+AZURE_MONITOR_EVENT_NAME = "microsoft.custom_event.name"
 
 EVENT_NAME = "FeatureEvaluation"
 
 EVALUATION_EVENT_VERSION = "1.0.0"
 
+_EVENTS_LOGGER_INITIALIZED: bool = False
+
+
+def _initialize_event_logger() -> None:
+    global _EVENTS_LOGGER_INITIALIZED  # pylint: disable=global-statement
+    if _EVENTS_LOGGER_INITIALIZED:
+        return
+
+    _event_logger.addHandler(LoggingHandler())
+    _event_logger.setLevel(INFO)
+    _EVENTS_LOGGER_INITIALIZED = True
+
 
 def track_event(event_name: str, user: str, event_properties: Optional[Dict[str, Optional[str]]] = None) -> None:
     """
@@ -51,15 +67,22 @@ def track_event(event_name: str, user: str, event_properties: Optional[Dict[str,
     :param str user: The user ID to associate with the event.
     :param dict[str, str] event_properties: A dictionary of named string properties.
     """
-    if not HAS_AZURE_MONITOR_EVENTS_EXTENSION:
+    if not HAS_OPENTELEMETRY_LOGGING:
         return
 
+    _initialize_event_logger()
+
     event_properties = event_properties or {}
 
     if user:
         event_properties[TARGETING_ID] = user
 
-    azure_monitor_track_event(event_name, event_properties)
+    # Azure Monitor exporter maps this attribute to customEvent telemetry name.
+    custom_event_attributes = {
+        **event_properties,
+        AZURE_MONITOR_EVENT_NAME: event_name,
+    }
+    _event_logger.info(event_name, extra=custom_event_attributes)
 
 
 def publish_telemetry(evaluation_event: EvaluationEvent) -> None:
@@ -68,7 +91,7 @@ def publish_telemetry(evaluation_event: EvaluationEvent) -> None:
 
     :param EvaluationEvent evaluation_event: The evaluation event to publish telemetry for.
     """
-    if not HAS_AZURE_MONITOR_EVENTS_EXTENSION:
+    if not HAS_OPENTELEMETRY_LOGGING:
         return
 
     feature = evaluation_event.feature
@@ -136,8 +159,8 @@ def on_start(self, span: Span, parent_context: Optional[Context] = None) -> None
         :param Span span: The span that was started.
         :param parent_context: The parent context of the span.
         """
-        if not HAS_AZURE_MONITOR_EVENTS_EXTENSION:
-            logger.warning("Azure Monitor Events Extension is not installed.")
+        if not HAS_OPENTELEMETRY_LOGGING:
+            logger.info("OpenTelemetry logging handler is not installed.")
             return
         if self._targeting_context_accessor and callable(self._targeting_context_accessor):
             if inspect.iscoroutinefunction(self._targeting_context_accessor):

pyproject.toml

@@ -58,10 +58,9 @@ Homepage = "https://github.com/microsoft/FeatureManagement-Python"
 Issues = "https://github.com/microsoft/FeatureManagement-Python/issues"
 
 [project.optional-dependencies]
-AzureMonitor = ["azure-monitor-events-extension<2.0.0"]
+AzureMonitor = ["opentelemetry-sdk~=1.20"]
 test = [
     "azure-monitor-opentelemetry < 2.0.0",
-    "azure-monitor-events-extension < 2.0.0",
 ]
 dev = [
     "pytest >= 7.0.0, < 10.0.0",
@@ -74,6 +73,6 @@ dev = [
     "sphinx_rtd_theme >= 2.0.0, < 4.0.0",
     "sphinx-toolbox >= 3.0.0, < 5.0.0",
     "myst_parser >= 2.0.0, < 6.0.0",
-    "opentelemetry-api >= 1.20.0, < 2.0.0",
-    "opentelemetry-sdk >= 1.20.0, < 2.0.0",
+    "opentelemetry-api~=1.20",
+    "opentelemetry-sdk~=1.20",
 ]

samples/requirements.txt

@@ -1,6 +1,5 @@
 featuremanagement
 azure-appconfiguration-provider
 azure-monitor-opentelemetry
-azure-monitor-events-extension
 quart
 azure-identity

tests/test_send_telemetry_appinsights.py

@@ -13,6 +13,10 @@
 from featuremanagement.azuremonitor import TargetingSpanProcessor
 
 
+def _event_properties(mock_logger_info):
+    return mock_logger_info.call_args.kwargs["extra"]
+
+
 @pytest.mark.usefixtures("caplog")
 class TestSendTelemetryAppinsights:
 
@@ -40,23 +44,46 @@ def test_send_telemetry_appinsights(self):
         evaluation_event.variant = variant
         evaluation_event.reason = VariantAssignmentReason.DEFAULT_WHEN_DISABLED
 
-        with patch("featuremanagement.azuremonitor._send_telemetry.azure_monitor_track_event") as mock_track_event:
-            # This is called like this so we can override the track_event function
+        with (
+            patch("featuremanagement.azuremonitor._send_telemetry._initialize_event_logger"),
+            patch("featuremanagement.azuremonitor._send_telemetry._event_logger.info") as mock_logger_info,
+        ):
+            # This is called like this so we can override the _event_logger.info function
             featuremanagement.azuremonitor._send_telemetry.publish_telemetry(  # pylint: disable=protected-access
                 evaluation_event
             )
-            mock_track_event.assert_called_once()
-            assert mock_track_event.call_args[0][0] == "FeatureEvaluation"
-            assert mock_track_event.call_args[0][1]["FeatureName"] == "TestFeature"
-            assert mock_track_event.call_args[0][1]["Enabled"] == "True"
-            assert mock_track_event.call_args[0][1]["TargetingId"] == "test_user"
-            assert mock_track_event.call_args[0][1]["Variant"] == "TestVariant"
-            assert mock_track_event.call_args[0][1]["ETag"] == "cmwBRcIAq1jUyKL3Kj8bvf9jtxBrFg-R-ayExStMC90"
+            mock_logger_info.assert_called_once()
+            assert mock_logger_info.call_args[0][0] == "FeatureEvaluation"
+            event_properties = _event_properties(mock_logger_info)
+            assert event_properties["TargetingId"] == "test_user"
+            assert event_properties["FeatureName"] == "TestFeature"
+            assert event_properties["Enabled"] == "True"
+            assert event_properties["Variant"] == "TestVariant"
+            assert event_properties["ETag"] == "cmwBRcIAq1jUyKL3Kj8bvf9jtxBrFg-R-ayExStMC90"
+            assert event_properties["FeatureFlagReference"] == "fake-store-uri/kv/.appconfig.featureflag/TestFeature"
+            assert event_properties["FeatureFlagId"] == "fake-feature-flag-id"
+
+    def test_track_event_preserves_reserved_custom_event_name(self):
+        with (
+            patch("featuremanagement.azuremonitor._send_telemetry._initialize_event_logger"),
+            patch("featuremanagement.azuremonitor._send_telemetry._event_logger.info") as mock_event_logger_info,
+        ):
+            featuremanagement.azuremonitor._send_telemetry.track_event(  # pylint: disable=protected-access
+                "FeatureEvaluation",
+                "test_user",
+                {
+                    "microsoft.custom_event.name": "override_attempt",
+                    "CustomProperty": "custom_value",
+                },
+            )
+
+            mock_event_logger_info.assert_called_once()
+            assert mock_event_logger_info.call_args[0][0] == "FeatureEvaluation"
             assert (
-                mock_track_event.call_args[0][1]["FeatureFlagReference"]
-                == "fake-store-uri/kv/.appconfig.featureflag/TestFeature"
+                mock_event_logger_info.call_args.kwargs["extra"]["microsoft.custom_event.name"] == "FeatureEvaluation"
             )
-            assert mock_track_event.call_args[0][1]["FeatureFlagId"] == "fake-feature-flag-id"
+            assert mock_event_logger_info.call_args.kwargs["extra"]["CustomProperty"] == "custom_value"
+            assert mock_event_logger_info.call_args.kwargs["extra"]["TargetingId"] == "test_user"
 
     def test_send_telemetry_appinsights_no_user(self):
         feature_flag = FeatureFlag.convert_from_json({"id": "TestFeature"})
@@ -67,18 +94,22 @@ def test_send_telemetry_appinsights_no_user(self):
         evaluation_event.variant = variant
         evaluation_event.reason = VariantAssignmentReason.DEFAULT_WHEN_DISABLED
 
-        with patch("featuremanagement.azuremonitor._send_telemetry.azure_monitor_track_event") as mock_track_event:
-            # This is called like this so we can override the track_event function
+        with (
+            patch("featuremanagement.azuremonitor._send_telemetry._initialize_event_logger"),
+            patch("featuremanagement.azuremonitor._send_telemetry._event_logger.info") as mock_logger_info,
+        ):
+            # This is called like this so we can override the _event_logger.info function
             featuremanagement.azuremonitor._send_telemetry.publish_telemetry(  # pylint: disable=protected-access
                 evaluation_event
             )
-            mock_track_event.assert_called_once()
-            assert mock_track_event.call_args[0][0] == "FeatureEvaluation"
-            assert mock_track_event.call_args[0][1]["FeatureName"] == "TestFeature"
-            assert mock_track_event.call_args[0][1]["Enabled"] == "False"
-            assert "TargetingId" not in mock_track_event.call_args[0][1]
-            assert mock_track_event.call_args[0][1]["Variant"] == "TestVariant"
-            assert mock_track_event.call_args[0][1]["VariantAssignmentReason"] == "DefaultWhenDisabled"
+            mock_logger_info.assert_called_once()
+            assert mock_logger_info.call_args[0][0] == "FeatureEvaluation"
+            event_properties = _event_properties(mock_logger_info)
+            assert event_properties["FeatureName"] == "TestFeature"
+            assert event_properties["Enabled"] == "False"
+            assert "TargetingId" not in event_properties
+            assert event_properties["Variant"] == "TestVariant"
+            assert event_properties["VariantAssignmentReason"] == "DefaultWhenDisabled"
 
     def test_send_telemetry_appinsights_no_variant(self):
         feature_flag = FeatureFlag.convert_from_json({"id": "TestFeature"})
@@ -87,30 +118,36 @@ def test_send_telemetry_appinsights_no_variant(self):
         evaluation_event.enabled = True
         evaluation_event.user = "test_user"
 
-        with patch("featuremanagement.azuremonitor._send_telemetry.azure_monitor_track_event") as mock_track_event:
-            # This is called like this so we can override the track_event function
+        with (
+            patch("featuremanagement.azuremonitor._send_telemetry._initialize_event_logger"),
+            patch("featuremanagement.azuremonitor._send_telemetry._event_logger.info") as mock_logger_info,
+        ):
+            # This is called like this so we can override the _event_logger.info function
             featuremanagement.azuremonitor._send_telemetry.publish_telemetry(  # pylint: disable=protected-access
                 evaluation_event
             )
-            mock_track_event.assert_called_once()
-            assert mock_track_event.call_args[0][0] == "FeatureEvaluation"
-            assert mock_track_event.call_args[0][1]["FeatureName"] == "TestFeature"
-            assert mock_track_event.call_args[0][1]["Enabled"] == "True"
-            assert mock_track_event.call_args[0][1]["TargetingId"] == "test_user"
-            assert "Variant" not in mock_track_event.call_args[0][1]
-            assert "Reason" not in mock_track_event.call_args[0][1]
+            mock_logger_info.assert_called_once()
+            assert mock_logger_info.call_args[0][0] == "FeatureEvaluation"
+            event_properties = _event_properties(mock_logger_info)
+            assert event_properties["FeatureName"] == "TestFeature"
+            assert event_properties["Enabled"] == "True"
+            assert "Variant" not in event_properties
+            assert "Reason" not in event_properties
 
     def test_send_telemetry_appinsights_no_feature_flag(self):
         evaluation_event = EvaluationEvent(None)
         evaluation_event.enabled = True
         evaluation_event.user = "test_user"
 
-        with patch("featuremanagement.azuremonitor._send_telemetry.azure_monitor_track_event") as mock_track_event:
-            # This is called like this so we can override the track_event function
+        with (
+            patch("featuremanagement.azuremonitor._send_telemetry._initialize_event_logger"),
+            patch("featuremanagement.azuremonitor._send_telemetry._event_logger.info") as mock_logger_info,
+        ):
+            # This is called like this so we can override the _event_logger.info function
             featuremanagement.azuremonitor._send_telemetry.publish_telemetry(  # pylint: disable=protected-access
                 evaluation_event
             )
-            mock_track_event.assert_not_called()
+            mock_logger_info.assert_not_called()
 
     def test_send_telemetry_appinsights_default_when_enabled(self):
         feature_flag = FeatureFlag.convert_from_json(
@@ -130,18 +167,21 @@ def test_send_telemetry_appinsights_default_when_enabled(self):
         evaluation_event.variant = variant
         evaluation_event.reason = VariantAssignmentReason.DEFAULT_WHEN_ENABLED
 
-        with patch("featuremanagement.azuremonitor._send_telemetry.azure_monitor_track_event") as mock_track_event:
-            # This is called like this so we can override the track_event function
+        with (
+            patch("featuremanagement.azuremonitor._send_telemetry._initialize_event_logger"),
+            patch("featuremanagement.azuremonitor._send_telemetry._event_logger.info") as mock_logger_info,
+        ):
+            # This is called like this so we can override the _event_logger.info function
             featuremanagement.azuremonitor._send_telemetry.publish_telemetry(  # pylint: disable=protected-access
                 evaluation_event
             )
-            mock_track_event.assert_called_once()
-            assert mock_track_event.call_args[0][0] == "FeatureEvaluation"
-            assert mock_track_event.call_args[0][1]["FeatureName"] == "TestFeature"
-            assert mock_track_event.call_args[0][1]["Enabled"] == "True"
-            assert mock_track_event.call_args[0][1]["TargetingId"] == "test_user"
-            assert mock_track_event.call_args[0][1]["Variant"] == "big"
-            assert mock_track_event.call_args[0][1]["VariantAssignmentReason"] == "DefaultWhenEnabled"
+            mock_logger_info.assert_called_once()
+            assert mock_logger_info.call_args[0][0] == "FeatureEvaluation"
+            event_properties = _event_properties(mock_logger_info)
+            assert event_properties["FeatureName"] == "TestFeature"
+            assert event_properties["Enabled"] == "True"
+            assert event_properties["Variant"] == "big"
+            assert event_properties["VariantAssignmentReason"] == "DefaultWhenEnabled"
 
     def test_send_telemetry_appinsights_default_when_enabled_no_percentile(self):
         feature_flag = FeatureFlag.convert_from_json(
@@ -160,18 +200,21 @@ def test_send_telemetry_appinsights_default_when_enabled_no_percentile(self):
         evaluation_event.variant = variant
         evaluation_event.reason = VariantAssignmentReason.DEFAULT_WHEN_ENABLED
 
-        with patch("featuremanagement.azuremonitor._send_telemetry.azure_monitor_track_event") as mock_track_event:
-            # This is called like this so we can override the track_event function
+        with (
+            patch("featuremanagement.azuremonitor._send_telemetry._initialize_event_logger"),
+            patch("featuremanagement.azuremonitor._send_telemetry._event_logger.info") as mock_logger_info,
+        ):
+            # This is called like this so we can override the _event_logger.info function
             featuremanagement.azuremonitor._send_telemetry.publish_telemetry(  # pylint: disable=protected-access
                 evaluation_event
             )
-            mock_track_event.assert_called_once()
-            assert mock_track_event.call_args[0][0] == "FeatureEvaluation"
-            assert mock_track_event.call_args[0][1]["FeatureName"] == "TestFeature"
-            assert mock_track_event.call_args[0][1]["Enabled"] == "True"
-            assert mock_track_event.call_args[0][1]["TargetingId"] == "test_user"
-            assert mock_track_event.call_args[0][1]["Variant"] == "big"
-            assert mock_track_event.call_args[0][1]["VariantAssignmentReason"] == "DefaultWhenEnabled"
+            mock_logger_info.assert_called_once()
+            assert mock_logger_info.call_args[0][0] == "FeatureEvaluation"
+            event_properties = _event_properties(mock_logger_info)
+            assert event_properties["FeatureName"] == "TestFeature"
+            assert event_properties["Enabled"] == "True"
+            assert event_properties["Variant"] == "big"
+            assert event_properties["VariantAssignmentReason"] == "DefaultWhenEnabled"
 
     def test_send_telemetry_appinsights_allocation(self):
         feature_flag = FeatureFlag.convert_from_json(
@@ -190,20 +233,23 @@ def test_send_telemetry_appinsights_allocation(self):
         evaluation_event.variant = variant
         evaluation_event.reason = VariantAssignmentReason.PERCENTILE
 
-        with patch("featuremanagement.azuremonitor._send_telemetry.azure_monitor_track_event") as mock_track_event:
-            # This is called like this so we can override the track_event function
+        with (
+            patch("featuremanagement.azuremonitor._send_telemetry._initialize_event_logger"),
+            patch("featuremanagement.azuremonitor._send_telemetry._event_logger.info") as mock_logger_info,
+        ):
+            # This is called like this so we can override the _event_logger.info function
             featuremanagement.azuremonitor._send_telemetry.publish_telemetry(  # pylint: disable=protected-access
                 evaluation_event
             )
-            mock_track_event.assert_called_once()
-            assert mock_track_event.call_args[0][0] == "FeatureEvaluation"
-            assert mock_track_event.call_args[0][1]["FeatureName"] == "TestFeature"
-            assert mock_track_event.call_args[0][1]["Enabled"] == "True"
-            assert mock_track_event.call_args[0][1]["TargetingId"] == "test_user"
-            assert mock_track_event.call_args[0][1]["Variant"] == "big"
-            assert mock_track_event.call_args[0][1]["VariantAssignmentReason"] == "Percentile"
-            assert mock_track_event.call_args[0][1]["VariantAssignmentPercentage"] == "25"
-            assert "DefaultWhenEnabled" not in mock_track_event.call_args[0][1]
+            mock_logger_info.assert_called_once()
+            assert mock_logger_info.call_args[0][0] == "FeatureEvaluation"
+            event_properties = _event_properties(mock_logger_info)
+            assert event_properties["FeatureName"] == "TestFeature"
+            assert event_properties["Enabled"] == "True"
+            assert event_properties["Variant"] == "big"
+            assert event_properties["VariantAssignmentReason"] == "Percentile"
+            assert event_properties["VariantAssignmentPercentage"] == "25"
+            assert "DefaultWhenEnabled" not in event_properties
 
     def test_targeting_span_processor(self, caplog):
         processor = TargetingSpanProcessor()