diff --git a/featuremanagement/azuremonitor/_send_telemetry.py b/featuremanagement/azuremonitor/_send_telemetry.py index 48c33d3..f026214 100644 --- a/featuremanagement/azuremonitor/_send_telemetry.py +++ b/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): diff --git a/pyproject.toml b/pyproject.toml index da3aa6c..f50d406 100644 --- a/pyproject.toml +++ b/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", ] diff --git a/samples/requirements.txt b/samples/requirements.txt index 1c84dca..cba21c9 100644 --- a/samples/requirements.txt +++ b/samples/requirements.txt @@ -1,6 +1,5 @@ featuremanagement azure-appconfiguration-provider azure-monitor-opentelemetry -azure-monitor-events-extension quart azure-identity diff --git a/tests/test_send_telemetry_appinsights.py b/tests/test_send_telemetry_appinsights.py index 4922070..9350bbf 100644 --- a/tests/test_send_telemetry_appinsights.py +++ b/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()