Internal logging utility: _DeferredString

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"]

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"

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
 

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)

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