diff --git a/libraries/microsoft-agents-activity/microsoft_agents/activity/_utils/__init__.py b/libraries/microsoft-agents-activity/microsoft_agents/activity/_utils/__init__.py new file mode 100644 index 00000000..bedb475d --- /dev/null +++ b/libraries/microsoft-agents-activity/microsoft_agents/activity/_utils/__init__.py @@ -0,0 +1,6 @@ +# Copyright (c) Microsoft Corporation. All rights reserved. +# Licensed under the MIT License. + +from ._deferred_string import _DeferredString + +__all__ = ["_DeferredString"] diff --git a/libraries/microsoft-agents-activity/microsoft_agents/activity/_utils/_deferred_string.py b/libraries/microsoft-agents-activity/microsoft_agents/activity/_utils/_deferred_string.py new file mode 100644 index 00000000..39eb10ad --- /dev/null +++ b/libraries/microsoft-agents-activity/microsoft_agents/activity/_utils/_deferred_string.py @@ -0,0 +1,20 @@ +# Copyright (c) Microsoft Corporation. All rights reserved. +# Licensed under the MIT License. + +import logging + +logger = logging.getLogger(__name__) + + +class _DeferredString: + def __init__(self, func, *args, **kwargs): + self.func = func + self.args = args + self.kwargs = kwargs + + def __str__(self): + try: + return str(self.func(*self.args, **self.kwargs)) + except Exception as e: + logger.error("Error evaluating deferred string", exc_info=e) + return "_DeferredString: error evaluating deferred string" diff --git a/libraries/microsoft-agents-authentication-msal/microsoft_agents/authentication/msal/msal_auth.py b/libraries/microsoft-agents-authentication-msal/microsoft_agents/authentication/msal/msal_auth.py index f9486cc4..073c3a6a 100644 --- a/libraries/microsoft-agents-authentication-msal/microsoft_agents/authentication/msal/msal_auth.py +++ b/libraries/microsoft-agents-authentication-msal/microsoft_agents/authentication/msal/msal_auth.py @@ -19,6 +19,8 @@ from cryptography.hazmat.backends import default_backend from cryptography.hazmat.primitives import hashes +from microsoft_agents.activity._utils import _DeferredString + from microsoft_agents.hosting.core import ( AuthTypes, AccessTokenProviderBase, @@ -28,18 +30,6 @@ logger = logging.getLogger(__name__) -# this is deferred because jwt.decode is expensive and we don't want to do it unless we -# have logging.DEBUG enabled -class _DeferredLogOfBlueprintId: - def __init__(self, jwt_token: str): - self.jwt_token = jwt_token - - def __str__(self): - payload = jwt.decode(self.jwt_token, options={"verify_signature": False}) - agentic_blueprint_id = payload.get("xms_par_app_azp") - return f"Agentic blueprint id: {agentic_blueprint_id}" - - async def _async_acquire_token_for_client(msal_auth_client, *args, **kwargs): """MSAL in Python does not support async, so we use asyncio.to_thread to run it in a separate thread and avoid blocking the event loop @@ -328,7 +318,14 @@ async def get_agentic_instance_token( ) raise ValueError(f"Failed to acquire token. {str(agentic_instance_token)}") - logger.debug(_DeferredLogOfBlueprintId(token)) + logger.debug( + "Agentic blueprint id: %s", + _DeferredString( + lambda: jwt.decode(token, options={"verify_signature": False}).get( + "xms_par_app_azp" + ) + ), + ) return agentic_instance_token["access_token"], agent_token_result diff --git a/tests/activity/utils/__init__.py b/tests/activity/utils/__init__.py new file mode 100644 index 00000000..e69de29b diff --git a/tests/activity/utils/test_deferred_string.py b/tests/activity/utils/test_deferred_string.py new file mode 100644 index 00000000..75ac24b7 --- /dev/null +++ b/tests/activity/utils/test_deferred_string.py @@ -0,0 +1,168 @@ +import logging +from unittest.mock import patch +from io import StringIO + +from microsoft_agents.activity._utils import _DeferredString + + +class TestDeferredString: + """Test suite for _DeferredString class.""" + + def test_deferred_string_evaluation_basic(self): + """Test basic string evaluation with function and args.""" + + def sample_func(x, y): + return f"Result is {x + y}" + + deferred = _DeferredString(sample_func, 2, 3) + assert str(deferred) == "Result is 5" + + def test_deferred_string_evaluation_with_kwargs(self): + """Test string evaluation with keyword arguments.""" + + def sample_func(a, b=0, c=1): + return f"Sum is {a + b + c}" + + deferred = _DeferredString(sample_func, 5, b=10, c=15) + assert str(deferred) == "Sum is 30" + + def test_deferred_string_evaluation_mixed_args(self): + """Test string evaluation with both positional and keyword arguments.""" + + def sample_func(prefix, value, suffix="end"): + return f"{prefix}-{value}-{suffix}" + + deferred = _DeferredString(sample_func, "start", 42, suffix="finish") + assert str(deferred) == "start-42-finish" + + def test_deferred_string_no_args(self): + """Test string evaluation with no arguments.""" + + def simple_func(): + return "No args here" + + deferred = _DeferredString(simple_func) + assert str(deferred) == "No args here" + + def test_deferred_string_complex_return_type(self): + """Test that non-string return values are converted to strings.""" + + def return_number(): + return 42 + + deferred = _DeferredString(return_number) + assert str(deferred) == "42" + + def test_deferred_string_none_return(self): + """Test handling of None return value.""" + + def return_none(): + return None + + deferred = _DeferredString(return_none) + assert str(deferred) == "None" + + def test_deferred_string_exception_handling(self, caplog): + """Test exception handling during function evaluation.""" + + def faulty_func(): + raise ValueError("Intentional error") + + deferred = _DeferredString(faulty_func) + + with caplog.at_level(logging.ERROR): + result = str(deferred) + + assert result == "_DeferredString: error evaluating deferred string" + assert any( + "Error evaluating deferred string" in message for message in caplog.messages + ) + + def test_deferred_string_exception_with_args(self, caplog): + """Test exception handling when function is called with arguments.""" + + def faulty_func(x, y): + raise RuntimeError("Something went wrong") + + deferred = _DeferredString(faulty_func, 1, 2) + + with caplog.at_level(logging.ERROR): + result = str(deferred) + + assert result == "_DeferredString: error evaluating deferred string" + assert "Error evaluating deferred string" in caplog.text + + def test_deferred_string_logging_integration(self): + """Test integration with logging module using deferred string in log messages.""" + # Create a string buffer to capture log output + log_capture_string = StringIO() + ch = logging.StreamHandler(log_capture_string) + ch.setLevel(logging.INFO) + + # Create a logger and add the handler + test_logger = logging.getLogger("test_deferred_logger") + test_logger.setLevel(logging.INFO) + test_logger.addHandler(ch) + + def expensive_operation(): + return "Expensive computation result" + + deferred = _DeferredString(expensive_operation) + + # Log a message with the deferred string + test_logger.info("Processing complete: %s", deferred) + + # Get the log output and verify the deferred string was evaluated + log_contents = log_capture_string.getvalue() + assert "Processing complete: Expensive computation result" in log_contents + + # Clean up + test_logger.removeHandler(ch) + + def test_deferred_string_lazy_evaluation(self): + """Test that the function is only called when string conversion occurs.""" + call_count = 0 + + def counting_func(): + nonlocal call_count + call_count += 1 + return f"Called {call_count} times" + + deferred = _DeferredString(counting_func) + + # Function should not be called yet + assert call_count == 0 + + # First string conversion should call the function + result1 = str(deferred) + assert call_count == 1 + assert result1 == "Called 1 times" + + # Second string conversion should call the function again + result2 = str(deferred) + assert call_count == 2 + assert result2 == "Called 2 times" + + def test_deferred_string_with_logger_level_filtering(self): + """Test that deferred strings are only evaluated when log level allows it.""" + + log_capture_string = StringIO() + ch = logging.StreamHandler(log_capture_string) + test_logger = logging.getLogger("multi_deferred_logger") + test_logger.setLevel(logging.INFO) + test_logger.addHandler(ch) + + def expensive_func(): + return "test" + + deferred = _DeferredString(expensive_func) + + # Log at DEBUG level - should not evaluate deferred string due to level filtering + test_logger.debug("Debug message: %s", deferred) + assert log_capture_string.getvalue() == "" + + # Log at ERROR level - should evaluate deferred string + test_logger.error("Error message: %s", deferred) + assert log_capture_string.getvalue() == "Error message: test\n" + + test_logger.removeHandler(ch) diff --git a/tests/hosting_core/app/test_typing_indicator.py b/tests/hosting_core/app/test_typing_indicator.py index 22a09c8f..c58c4ed4 100644 --- a/tests/hosting_core/app/test_typing_indicator.py +++ b/tests/hosting_core/app/test_typing_indicator.py @@ -30,7 +30,9 @@ async def test_start_sends_typing_activity(): await indicator.stop() assert len(context.sent_activities) >= 1 - assert all(activity.type == ActivityTypes.typing for activity in context.sent_activities) + assert all( + activity.type == ActivityTypes.typing for activity in context.sent_activities + ) @pytest.mark.asyncio