diff --git a/README.md b/README.md index ccec0686..09e8dee9 100644 --- a/README.md +++ b/README.md @@ -190,6 +190,17 @@ client.get_boolean_flag("my-flag", False, flag_evaluation_options=options) The OpenFeature SDK logs to the `openfeature` logger using the `logging` package from the Python Standard Library. +#### Logging Hook + +The Python SDK includes a `LoggingHook`, which logs detailed information at key points during flag evaluation, using the `logging` package. This hook can be particularly helpful for troubleshooting and debugging; simply attach it at the global, client or invocation level and ensure your log level is set to "debug". + +```python +from openfeature import api +from openfeature.hook.logging_hook import LoggingHook + +api.add_hooks([LoggingHook()]) +``` + ### Domains Clients can be assigned to a domain. diff --git a/openfeature/hook/logging_hook.py b/openfeature/hook/logging_hook.py new file mode 100644 index 00000000..00294b76 --- /dev/null +++ b/openfeature/hook/logging_hook.py @@ -0,0 +1,68 @@ +import json +import logging +from dataclasses import asdict + +from openfeature.evaluation_context import EvaluationContext +from openfeature.exception import ErrorCode, OpenFeatureError +from openfeature.flag_evaluation import FlagEvaluationDetails, FlagValueType +from openfeature.hook import Hook, HookContext, HookHints + + +class LoggingHook(Hook): + def __init__( + self, + include_evaluation_context: bool = False, + logger: logging.Logger | None = None, + ): + self.logger = logger or logging.getLogger("openfeature") + self.include_evaluation_context = include_evaluation_context + + def _build_args(self, hook_context: HookContext, stage: str) -> dict: + args = { + "domain": hook_context.client_metadata.domain + if hook_context.client_metadata + else None, + "provider_name": hook_context.provider_metadata.name + if hook_context.provider_metadata + else None, + "flag_key": hook_context.flag_key, + "default_value": hook_context.default_value, + "stage": stage, + } + if self.include_evaluation_context: + args["evaluation_context"] = json.dumps( + asdict(hook_context.evaluation_context), + default=str, + ) + return args + + def before( + self, hook_context: HookContext, hints: HookHints + ) -> EvaluationContext | None: + args = self._build_args(hook_context, "before") + self.logger.debug("Flag evaluation %s", args) + return None + + def after( + self, + hook_context: HookContext, + details: FlagEvaluationDetails[FlagValueType], + hints: HookHints, + ) -> None: + args = self._build_args(hook_context, "after") + args["reason"] = details.reason + args["variant"] = details.variant + args["value"] = details.value + self.logger.debug("Flag evaluation %s", args) + + def error( + self, hook_context: HookContext, exception: Exception, hints: HookHints + ) -> None: + args = self._build_args(hook_context, "error") + if isinstance(exception, OpenFeatureError): + args["error_code"] = exception.error_code + args["error_message"] = exception.error_message + else: + args["error_code"] = ErrorCode.GENERAL + args["error_message"] = str(exception) + self.logger.error("Flag evaluation %s", args) diff --git a/tests/hook/test_logging_hook.py b/tests/hook/test_logging_hook.py new file mode 100644 index 00000000..c3cd09a0 --- /dev/null +++ b/tests/hook/test_logging_hook.py @@ -0,0 +1,197 @@ +from unittest.mock import MagicMock + +import pytest + +from openfeature.client import ClientMetadata +from openfeature.evaluation_context import EvaluationContext +from openfeature.exception import ErrorCode, FlagNotFoundError +from openfeature.flag_evaluation import FlagEvaluationDetails, FlagType +from openfeature.hook.logging_hook import HookContext, LoggingHook +from openfeature.provider.metadata import Metadata + + +@pytest.fixture() +def hook_context(): + return HookContext( + flag_key="my-flag", + flag_type=FlagType.BOOLEAN, + default_value=False, + evaluation_context=EvaluationContext("user-1", {"env": "prod"}), + client_metadata=ClientMetadata(domain="my-domain"), + provider_metadata=Metadata(name="my-provider"), + ) + + +def test_before_calls_debug_with_stage(hook_context): + mock_logger = MagicMock() + hook = LoggingHook(logger=mock_logger) + hook.before(hook_context, hints={}) + mock_logger.debug.assert_called_with( + "Flag evaluation %s", + { + "stage": "before", + "flag_key": "my-flag", + "default_value": False, + "domain": "my-domain", + "provider_name": "my-provider", + }, + ) + + +def test_after_calls_debug_with_stage(hook_context): + mock_logger = MagicMock() + hook = LoggingHook(logger=mock_logger) + details = FlagEvaluationDetails( + flag_key="my-flag", + value=True, + variant="on", + reason="STATIC", + ) + hook.after(hook_context, details, hints={}) + + mock_logger.debug.assert_called_with( + "Flag evaluation %s", + { + "stage": "after", + "flag_key": "my-flag", + "default_value": False, + "domain": "my-domain", + "provider_name": "my-provider", + "reason": "STATIC", + "variant": "on", + "value": True, + }, + ) + + +def test_after_calls_debug_with_evaluation_context(hook_context): + mock_logger = MagicMock() + hook = LoggingHook(logger=mock_logger, include_evaluation_context=True) + details = FlagEvaluationDetails( + flag_key="my-flag", + value=True, + variant="on", + reason="STATIC", + ) + hook.after(hook_context, details, hints={}) + + mock_logger.debug.assert_called_with( + "Flag evaluation %s", + { + "stage": "after", + "flag_key": "my-flag", + "default_value": False, + "domain": "my-domain", + "provider_name": "my-provider", + "reason": "STATIC", + "variant": "on", + "value": True, + "evaluation_context": '{"targeting_key": "user-1", "attributes": {"env": "prod"}}', + }, + ) + + +def test_error_calls_error_log(hook_context): + mock_logger = MagicMock() + hook = LoggingHook(logger=mock_logger) + exception = Exception("something went wrong") + hook.error(hook_context, exception, hints={}) + + mock_logger.error.assert_called_with( + "Flag evaluation %s", + { + "stage": "error", + "flag_key": "my-flag", + "default_value": False, + "domain": "my-domain", + "provider_name": "my-provider", + "error_code": ErrorCode.GENERAL, + "error_message": "something went wrong", + }, + ) + + +def test_error_extracts_error_code_from_open_feature_error(hook_context): + mock_logger = MagicMock() + hook = LoggingHook(logger=mock_logger) + exception = FlagNotFoundError("flag not found") + hook.error(hook_context, exception, hints={}) + + mock_logger.error.assert_called_with( + "Flag evaluation %s", + { + "stage": "error", + "flag_key": "my-flag", + "default_value": False, + "domain": "my-domain", + "provider_name": "my-provider", + "error_code": ErrorCode.FLAG_NOT_FOUND, + "error_message": "flag not found", + }, + ) + + +def test_build_args_without_metadata(): + hook = LoggingHook() + ctx = HookContext( + flag_key="flag", + flag_type=FlagType.STRING, + default_value="default", + evaluation_context=EvaluationContext(None, {}), + client_metadata=None, + provider_metadata=None, + ) + result = hook._build_args(ctx, "before") + assert result == { + "flag_key": "flag", + "default_value": "default", + "domain": None, + "provider_name": None, + "stage": "before", + } + + +def test_build_args_excludes_evaluation_context_by_default(hook_context): + hook = LoggingHook() + result = hook._build_args(hook_context, "before") + assert result == { + "flag_key": "my-flag", + "default_value": False, + "domain": "my-domain", + "provider_name": "my-provider", + "stage": "before", + } + + +def test_build_args_includes_evaluation_context_when_enabled(hook_context): + hook = LoggingHook(include_evaluation_context=True) + result = hook._build_args(hook_context, "after") + assert result == { + "flag_key": "my-flag", + "default_value": False, + "domain": "my-domain", + "provider_name": "my-provider", + "evaluation_context": '{"targeting_key": "user-1", "attributes": {"env": "prod"}}', + "stage": "after", + } + + +def test_error_calls_error_log_with_evaluation_context(hook_context): + mock_logger = MagicMock() + hook = LoggingHook(logger=mock_logger, include_evaluation_context=True) + exception = Exception("something went wrong") + hook.error(hook_context, exception, hints={}) + + mock_logger.error.assert_called_with( + "Flag evaluation %s", + { + "stage": "error", + "flag_key": "my-flag", + "default_value": False, + "domain": "my-domain", + "provider_name": "my-provider", + "evaluation_context": '{"targeting_key": "user-1", "attributes": {"env": "prod"}}', + "error_code": ErrorCode.GENERAL, + "error_message": "something went wrong", + }, + )