Repository: microsoft/botbuilder-python
Pull request #293 (2019-08-12 13:29:56)

Telemetry Middleware
Initial port of Telemetry Middleware.


axelsrz: Could you format the code to be black format compliant? 
`pip install black`

On the root of the project:
`black libraries`
daveta: Nice tool!  

Patch:
diff --git a/libraries/botbuilder-core/botbuilder/core/__init__.py b/libraries/botbuilder-core/botbuilder/core/__init__.py
index 832e9124..15b2f5f3 100644
--- a/libraries/botbuilder-core/botbuilder/core/__init__.py
+++ b/libraries/botbuilder-core/botbuilder/core/__init__.py
@@ -30,6 +30,9 @@ from .show_typing_middleware import ShowTypingMiddleware
 from .state_property_accessor import StatePropertyAccessor
 from .state_property_info import StatePropertyInfo
 from .storage import Storage, StoreItem, calculate_change_hash
+from .telemetry_constants import TelemetryConstants
+from .telemetry_logger_constants import TelemetryLoggerConstants
+from .telemetry_logger_middleware import TelemetryLoggerMiddleware
 from .turn_context import TurnContext
 from .user_state import UserState
 from .user_token_provider import UserTokenProvider
@@ -65,6 +68,9 @@ __all__ = [
     "StatePropertyInfo",
     "Storage",
     "StoreItem",
+    "TelemetryConstants",
+    "TelemetryLoggerConstants",
+    "TelemetryLoggerMiddleware",
     "TopIntent",
     "TurnContext",
     "UserState",
diff --git a/libraries/botbuilder-core/botbuilder/core/middleware_set.py b/libraries/botbuilder-core/botbuilder/core/middleware_set.py
index eae91b94..88dbf812 100644
--- a/libraries/botbuilder-core/botbuilder/core/middleware_set.py
+++ b/libraries/botbuilder-core/botbuilder/core/middleware_set.py
@@ -10,7 +10,7 @@ from .turn_context import TurnContext
 
 class Middleware(ABC):
     @abstractmethod
-    def on_process_request(
+    async def on_process_request(
         self, context: TurnContext, logic: Callable[[TurnContext], Awaitable]
     ):
         pass
diff --git a/libraries/botbuilder-core/botbuilder/core/telemetry_constants.py b/libraries/botbuilder-core/botbuilder/core/telemetry_constants.py
new file mode 100644
index 00000000..1ae0f181
--- /dev/null
+++ b/libraries/botbuilder-core/botbuilder/core/telemetry_constants.py
@@ -0,0 +1,20 @@
+# Copyright (c) Microsoft Corporation. All rights reserved.
+# Licensed under the MIT License
+
+
+class TelemetryConstants:
+    """Telemetry logger property names."""
+
+    CHANNEL_ID_PROPERTY: str = "channelId"
+    CONVERSATION_ID_PROPERTY: str = "conversationId"
+    CONVERSATION_NAME_PROPERTY: str = "conversationName"
+    DIALOG_ID_PROPERTY: str = "dialogId"
+    FROM_ID_PROPERTY: str = "fromId"
+    FROM_NAME_PROPERTY: str = "fromName"
+    LOCALE_PROPERTY: str = "locale"
+    RECIPIENT_ID_PROPERTY: str = "recipientId"
+    RECIPIENT_NAME_PROPERTY: str = "recipientName"
+    REPLY_ACTIVITY_ID_PROPERTY: str = "replyActivityId"
+    TEXT_PROPERTY: str = "text"
+    SPEAK_PROPERTY: str = "speak"
+    USER_ID_PROPERTY: str = "userId"
diff --git a/libraries/botbuilder-core/botbuilder/core/telemetry_logger_constants.py b/libraries/botbuilder-core/botbuilder/core/telemetry_logger_constants.py
new file mode 100644
index 00000000..486c502b
--- /dev/null
+++ b/libraries/botbuilder-core/botbuilder/core/telemetry_logger_constants.py
@@ -0,0 +1,18 @@
+# Copyright (c) Microsoft Corporation. All rights reserved.
+# Licensed under the MIT License
+
+
+class TelemetryLoggerConstants:
+    """The Telemetry Logger Event names."""
+
+    # The name of the event when a new message is received from the user.
+    BOT_MSG_RECEIVE_EVENT: str = "BotMessageReceived"
+
+    # The name of the event when logged when a message is sent from the bot to the user.
+    BOT_MSG_SEND_EVENT: str = "BotMessageSend"
+
+    # The name of the event when a message is updated by the bot.
+    BOT_MSG_UPDATE_EVENT: str = "BotMessageUpdate"
+
+    # The name of the event when a message is deleted by the bot.
+    BOT_MSG_DELETE_EVENT: str = "BotMessageDelete"
diff --git a/libraries/botbuilder-core/botbuilder/core/telemetry_logger_middleware.py b/libraries/botbuilder-core/botbuilder/core/telemetry_logger_middleware.py
new file mode 100644
index 00000000..cdb7fcca
--- /dev/null
+++ b/libraries/botbuilder-core/botbuilder/core/telemetry_logger_middleware.py
@@ -0,0 +1,280 @@
+# Copyright (c) Microsoft Corporation. All rights reserved.
+# Licensed under the MIT License.
+"""Middleware Component for logging Activity messages."""
+
+from typing import Awaitable, Callable, List, Dict
+from botbuilder.schema import Activity, ConversationReference, ActivityTypes
+from .bot_telemetry_client import BotTelemetryClient
+from .bot_assert import BotAssert
+from .middleware_set import Middleware
+from .null_telemetry_client import NullTelemetryClient
+from .turn_context import TurnContext
+from .telemetry_constants import TelemetryConstants
+from .telemetry_logger_constants import TelemetryLoggerConstants
+
+
+# pylint: disable=line-too-long
+class TelemetryLoggerMiddleware(Middleware):
+    """Middleware for logging incoming, outgoing, updated or deleted Activity messages."""
+
+    def __init__(
+        self, telemetry_client: BotTelemetryClient, log_personal_information: bool
+    ) -> None:
+        super(TelemetryLoggerMiddleware, self).__init__()
+        self._telemetry_client = telemetry_client or NullTelemetryClient()
+        self._log_personal_information = log_personal_information
+
+    @property
+    def telemetry_client(self) -> BotTelemetryClient:
+        """Gets the currently configured BotTelemetryClient."""
+        return self._telemetry_client
+
+    @property
+    def log_personal_information(self) -> bool:
+        """ Gets a value indicating whether determines whether to log personal
+        information that came from the user."""
+        return self._log_personal_information
+
+    # pylint: disable=arguments-differ
+    async def on_process_request(
+        self, context: TurnContext, logic_fn: Callable[[TurnContext], Awaitable]
+    ) -> None:
+        """Logs events based on incoming and outgoing activities using
+        BotTelemetryClient base class
+
+        :param turn_context: The context object for this turn.
+        :param logic: Callable to continue the bot middleware pipeline
+
+        :return:  None
+        """
+        BotAssert.context_not_none(context)
+
+        # Log incoming activity at beginning of turn
+        if context.activity:
+            activity = context.activity
+            # Log Bot Message Received
+            await self.on_receive_activity(activity)
+
+        # hook up onSend pipeline
+        # pylint: disable=unused-argument
+        async def send_activities_handler(
+            ctx: TurnContext,
+            activities: List[Activity],
+            next_send: Callable[[], Awaitable[None]],
+        ):
+            # Run full pipeline
+            responses = await next_send()
+            for activity in activities:
+                await self.on_send_activity(activity)
+            return responses
+
+        context.on_send_activities(send_activities_handler)
+
+        # hook up update activity pipeline
+        async def update_activity_handler(
+            ctx: TurnContext, activity: Activity, next_update: Callable[[], Awaitable]
+        ):
+            # Run full pipeline
+            response = await next_update()
+            await self.on_update_activity(activity)
+            return response
+
+        context.on_update_activity(update_activity_handler)
+
+        # hook up delete activity pipeline
+        async def delete_activity_handler(
+            ctx: TurnContext,
+            reference: ConversationReference,
+            next_delete: Callable[[], Awaitable],
+        ):
+            # Run full pipeline
+            await next_delete()
+
+            delete_msg = Activity(
+                type=ActivityTypes.message_delete, id=reference.activity_id
+            )
+            deleted_activity: Activity = TurnContext.apply_conversation_reference(
+                delete_msg, reference, False
+            )
+            await self.on_delete_activity(deleted_activity)
+
+        context.on_delete_activity(delete_activity_handler)
+
+        if logic_fn:
+            await logic_fn()
+
+    async def on_receive_activity(self, activity: Activity) -> None:
+        """Invoked when a message is received from the user.
+        Performs logging of telemetry data using the BotTelemetryClient.track_event() method.
+        This event name used is "BotMessageReceived".
+        :param activity: Current activity sent from user.
+        """
+        self.telemetry_client.track_event(
+            TelemetryLoggerConstants.BOT_MSG_RECEIVE_EVENT,
+            await self.fill_receive_event_properties(activity),
+        )
+
+    async def on_send_activity(self, activity: Activity) -> None:
+        """Invoked when the bot sends a message to the user.
+        Performs logging of telemetry data using the BotTelemetryClient.track_event() method.
+        This event name used is "BotMessageSend".
+        :param activity: Current activity sent from bot.
+        """
+        self.telemetry_client.track_event(
+            TelemetryLoggerConstants.BOT_MSG_SEND_EVENT,
+            await self.fill_send_event_properties(activity),
+        )
+
+    async def on_update_activity(self, activity: Activity) -> None:
+        """Invoked when the bot updates a message.
+        Performs logging of telemetry data using the BotTelemetryClient.track_event() method.
+        This event name used is "BotMessageUpdate".
+        :param activity: Current activity sent from user.
+        """
+        self.telemetry_client.track_event(
+            TelemetryLoggerConstants.BOT_MSG_UPDATE_EVENT,
+            await self.fill_update_event_properties(activity),
+        )
+
+    async def on_delete_activity(self, activity: Activity) -> None:
+        """Invoked when the bot deletes a message.
+        Performs logging of telemetry data using the BotTelemetryClient.track_event() method.
+        This event name used is "BotMessageDelete".
+        :param activity: Current activity sent from user.
+        """
+        self.telemetry_client.track_event(
+            TelemetryLoggerConstants.BOT_MSG_DELETE_EVENT,
+            await self.fill_delete_event_properties(activity),
+        )
+
+    async def fill_receive_event_properties(
+        self, activity: Activity, additional_properties: Dict[str, str] = None
+    ) -> Dict[str, str]:
+        """Fills the event properties for the BotMessageReceived.
+        Adheres to the LogPersonalInformation flag to filter Name, Text and Speak properties.
+        :param activity: activity sent from user.
+        :param additional_properties: Additional properties to add to the event.
+        Additional properties can override "stock" properties.
+
+        :return: A dictionary that is sent as "Properties" to
+        BotTelemetryClient.track_event method for the BotMessageReceived event.
+        """
+        properties = {
+            TelemetryConstants.FROM_ID_PROPERTY: activity.from_property.id,
+            TelemetryConstants.CONVERSATION_NAME_PROPERTY: activity.conversation.name,
+            TelemetryConstants.LOCALE_PROPERTY: activity.locale,
+            TelemetryConstants.RECIPIENT_ID_PROPERTY: activity.recipient.id,
+            TelemetryConstants.RECIPIENT_NAME_PROPERTY: activity.from_property.name,
+        }
+
+        if self.log_personal_information:
+            if activity.from_property.name and activity.from_property.name.strip():
+                properties[
+                    TelemetryConstants.FROM_NAME_PROPERTY
+                ] = activity.from_property.name
+            if activity.text and activity.text.strip():
+                properties[TelemetryConstants.TEXT_PROPERTY] = activity.text
+            if activity.speak and activity.speak.strip():
+                properties[TelemetryConstants.SPEAK_PROPERTY] = activity.speak
+
+        # Additional properties can override "stock" properties
+        if additional_properties:
+            for prop in additional_properties:
+                properties[prop.key] = prop.value
+
+        return properties
+
+    async def fill_send_event_properties(
+        self, activity: Activity, additional_properties: Dict[str, str] = None
+    ) -> Dict[str, str]:
+        """Fills the event properties for the BotMessageSend.
+        These properties are logged when an activity message is sent by the Bot to the user.
+        :param activity: activity sent from user.
+        :param additional_properties: Additional properties to add to the event.
+        Additional properties can override "stock" properties.
+
+        :return: A dictionary that is sent as "Properties" to the
+        BotTelemetryClient.track_event method for the BotMessageSend event.
+        """
+        properties = {
+            TelemetryConstants.REPLY_ACTIVITY_ID_PROPERTY: activity.reply_to_id,
+            TelemetryConstants.RECIPIENT_ID_PROPERTY: activity.recipient.id,
+            TelemetryConstants.CONVERSATION_NAME_PROPERTY: activity.conversation.name,
+            TelemetryConstants.LOCALE_PROPERTY: activity.locale,
+        }
+
+        # Use the LogPersonalInformation flag to toggle logging PII data, text and user name are common examples
+        if self.log_personal_information:
+            if activity.from_property.name and activity.from_property.name.strip():
+                properties[
+                    TelemetryConstants.FROM_NAME_PROPERTY
+                ] = activity.from_property.name
+            if activity.text and activity.text.strip():
+                properties[TelemetryConstants.TEXT_PROPERTY] = activity.text
+            if activity.speak and activity.speak.strip():
+                properties[TelemetryConstants.SPEAK_PROPERTY] = activity.speak
+
+        # Additional properties can override "stock" properties
+        if additional_properties:
+            for prop in additional_properties:
+                properties[prop.key] = prop.value
+
+        return properties
+
+    async def fill_update_event_properties(
+        self, activity: Activity, additional_properties: Dict[str, str] = None
+    ) -> Dict[str, str]:
+        """Fills the event properties for the BotMessageUpdate.
+        These properties are logged when an activity message is updated by the Bot.
+        For example, if a card is interacted with by the use, and the card needs
+        to be updated to reflect some interaction.
+        :param activity: activity sent from user.
+        :param additional_properties: Additional properties to add to the event.
+        Additional properties can override "stock" properties.
+
+        :return: A dictionary that is sent as "Properties" to the
+        BotTelemetryClient.track_event method for the BotMessageUpdate event.
+        """
+        properties = {
+            TelemetryConstants.RECIPIENT_ID_PROPERTY: activity.recipient.id,
+            TelemetryConstants.CONVERSATION_ID_PROPERTY: activity.conversation.id,
+            TelemetryConstants.CONVERSATION_NAME_PROPERTY: activity.conversation.name,
+            TelemetryConstants.LOCALE_PROPERTY: activity.locale,
+        }
+
+        # Use the LogPersonalInformation flag to toggle logging PII data, text is a common examples
+        if self.log_personal_information:
+            if activity.text and activity.text.strip():
+                properties[TelemetryConstants.TEXT_PROPERTY] = activity.text
+
+        # Additional properties can override "stock" properties
+        if additional_properties:
+            for prop in additional_properties:
+                properties[prop.key] = prop.value
+
+        return properties
+
+    async def fill_delete_event_properties(
+        self, activity: Activity, additional_properties: Dict[str, str] = None
+    ) -> Dict[str, str]:
+        """Fills the event properties for the BotMessageDelete.
+        These properties are logged when an activity message is deleted by the Bot.
+        :param activity: activity sent from user.
+        :param additional_properties: Additional properties to add to the event.
+        Additional properties can override "stock" properties.
+
+        :return: A dictionary that is sent as "Properties" to the
+        BotTelemetryClient.track_event method for the BotMessageUpdate event.
+        """
+        properties = {
+            TelemetryConstants.RECIPIENT_ID_PROPERTY: activity.recipient.id,
+            TelemetryConstants.CONVERSATION_ID_PROPERTY: activity.conversation.id,
+            TelemetryConstants.CONVERSATION_NAME_PROPERTY: activity.conversation.name,
+        }
+
+        # Additional properties can override "stock" properties
+        if additional_properties:
+            for prop in additional_properties:
+                properties[prop.key] = prop.value
+
+        return properties


Test patch:
diff --git a/libraries/botbuilder-core/tests/test_telemetry_middleware.py b/libraries/botbuilder-core/tests/test_telemetry_middleware.py
new file mode 100644
index 00000000..7128dab8
--- /dev/null
+++ b/libraries/botbuilder-core/tests/test_telemetry_middleware.py
@@ -0,0 +1,248 @@
+# Copyright (c) Microsoft Corporation. All rights reserved.
+# Licensed under the MIT License.
+
+# pylint: disable=line-too-long,missing-docstring,unused-variable
+import copy
+from typing import Dict
+from unittest.mock import Mock
+import aiounittest
+from botbuilder.core import (
+    NullTelemetryClient,
+    TelemetryLoggerMiddleware,
+    TelemetryLoggerConstants,
+    TurnContext,
+)
+from botbuilder.core.adapters import TestAdapter, TestFlow
+from botbuilder.schema import (
+    Activity,
+    ActivityTypes,
+    ChannelAccount,
+    ConversationAccount,
+)
+
+
+class TestTelemetryMiddleware(aiounittest.AsyncTestCase):
+    # pylint: disable=unused-argument
+    async def test_create_middleware(self):
+        telemetry = NullTelemetryClient()
+        my_logger = TelemetryLoggerMiddleware(telemetry, True)
+        assert my_logger
+
+    async def test_should_send_receive(self):
+        telemetry = Mock()
+        my_logger = TelemetryLoggerMiddleware(telemetry, True)
+
+        async def logic(context: TurnContext):
+            await context.send_activity(f"echo:{context.activity.text}")
+
+        adapter = TestAdapter(logic)
+        adapter.use(my_logger)
+        test_flow = TestFlow(None, adapter)
+        test_flow = await test_flow.send("foo")
+        test_flow = await test_flow.assert_reply("echo:foo")
+        test_flow = await test_flow.send("bar")
+        await test_flow.assert_reply("echo:bar")
+
+        # assert
+        # Note: None values just check for existence of the key, not the explicit
+        #     value (generated)
+        telemetry_calls = [
+            (
+                TelemetryLoggerConstants.BOT_MSG_RECEIVE_EVENT,
+                {
+                    "text": "foo",
+                    "fromId": "User1",
+                    "conversationName": None,
+                    "locale": None,
+                    "recipientId": "bot",
+                    "recipientName": "user",
+                },
+            ),
+            (
+                TelemetryLoggerConstants.BOT_MSG_SEND_EVENT,
+                {
+                    "text": "echo:foo",
+                    "replyActivityId": None,
+                    "recipientId": None,
+                    "conversationName": None,
+                    "locale": None,
+                },
+            ),
+            (
+                TelemetryLoggerConstants.BOT_MSG_RECEIVE_EVENT,
+                {
+                    "text": "bar",
+                    "fromId": "User1",
+                    "conversationName": None,
+                    "locale": None,
+                    "recipientId": "bot",
+                    "recipientName": "user",
+                    "fromName": "user",
+                },
+            ),
+            (
+                TelemetryLoggerConstants.BOT_MSG_SEND_EVENT,
+                {
+                    "replyActivityId": None,
+                    "recipientId": "User1",
+                    "conversationName": None,
+                    "locale": None,
+                    "fromName": "Bot",
+                    "text": "echo:bar",
+                },
+            ),
+        ]
+        self.assert_telemetry_calls(telemetry, telemetry_calls)
+
+    async def test_none_telemetry_client(self):
+        my_logger = TelemetryLoggerMiddleware(None, True)
+
+        async def logic(context: TurnContext):
+            await context.send_activity(f"echo:{context.activity.text}")
+
+        adapter = TestAdapter(logic)
+        adapter.use(my_logger)
+        test_flow = TestFlow(None, adapter)
+        test_flow = await test_flow.send("foo")
+        test_flow = await test_flow.assert_reply("echo:foo")
+        test_flow = await test_flow.send("bar")
+        await test_flow.assert_reply("echo:bar")
+
+    async def test_log_update(self):
+        telemetry = Mock()
+        my_logger = TelemetryLoggerMiddleware(telemetry, True)
+        activity_to_update = None
+
+        async def process(context: TurnContext) -> None:
+            nonlocal activity_to_update
+            if context.activity.text == "update":
+                if not activity_to_update:
+                    raise Exception("activity to update not set yet!")
+                activity_to_update.text = "new response"
+                await context.update_activity(activity_to_update)
+            else:
+                activity = self.create_reply(context.activity, "response")
+                response = await context.send_activity(activity)
+                activity.id = response.id
+                # clone the activity, so we can use it to do an update
+                activity_to_update = copy.copy(activity)
+                # await context.send_activity(f'echo:{context.activity.text}')
+
+        adapter = TestAdapter(process)
+        adapter.use(my_logger)
+        test_flow = TestFlow(None, adapter)
+        test_flow = await test_flow.send("foo")
+        test_flow = await test_flow.assert_reply("response")
+        test_flow = await test_flow.send("update")
+
+        # assert
+        # Note: None values just check for existence of the key, not the explicit
+        #     value (generated)
+        telemetry_call_expected = [
+            (
+                TelemetryLoggerConstants.BOT_MSG_RECEIVE_EVENT,
+                {
+                    "text": "foo",
+                    "fromId": "User1",
+                    "conversationName": None,
+                    "locale": None,
+                    "recipientId": "bot",
+                    "recipientName": "user",
+                },
+            ),
+            (
+                TelemetryLoggerConstants.BOT_MSG_SEND_EVENT,
+                {
+                    "replyActivityId": "1",
+                    "recipientId": "User1",
+                    "conversationName": None,
+                    "locale": None,
+                    "fromName": "Bot",
+                    "text": "response",
+                },
+            ),
+            (
+                TelemetryLoggerConstants.BOT_MSG_RECEIVE_EVENT,
+                {
+                    "text": "update",
+                    "fromId": "User1",
+                    "conversationName": None,
+                    "locale": None,
+                    "recipientId": "bot",
+                    "recipientName": "user",
+                    "fromName": "user",
+                },
+            ),
+            (
+                TelemetryLoggerConstants.BOT_MSG_UPDATE_EVENT,
+                {
+                    "recipientId": "User1",
+                    "conversationId": "Convo1",
+                    "conversationName": None,
+                    "locale": None,
+                    "text": "new response",
+                },
+            ),
+        ]
+        self.assert_telemetry_calls(telemetry, telemetry_call_expected)
+
+    def create_reply(self, activity, text, locale=None):
+        return Activity(
+            type=ActivityTypes.message,
+            from_property=ChannelAccount(
+                id=activity.recipient.id, name=activity.recipient.name
+            ),
+            recipient=ChannelAccount(
+                id=activity.from_property.id, name=activity.from_property.name
+            ),
+            reply_to_id=activity.id,
+            service_url=activity.service_url,
+            channel_id=activity.channel_id,
+            conversation=ConversationAccount(
+                is_group=activity.conversation.is_group,
+                id=activity.conversation.id,
+                name=activity.conversation.name,
+            ),
+            text=text or "",
+            locale=locale or activity.locale,
+        )
+
+    def assert_telemetry_call(
+        self, telemetry_mock, index: int, event_name: str, props: Dict[str, str]
+    ) -> None:
+        self.assertTrue(
+            index < len(telemetry_mock.track_event.call_args_list),
+            f"{len(telemetry_mock.track_event.call_args_list)} calls were made. You were asking for index {index}.",
+        )
+        args, kwargs = telemetry_mock.track_event.call_args_list[index]
+        self.assertEqual(
+            args[0],
+            event_name,
+            f"Event NAME not matching.\n   Expected: {props}\n   Generated: {args[1]}",
+        )
+
+        for key, val in props.items():
+            self.assertTrue(
+                key in args[1],
+                msg=f"Could not find value {key} in '{args[1]}' for index {index}",
+            )
+            self.assertTrue(
+                isinstance(args[1], dict),
+                f"ERROR: Second parm passed not a dictionary! {type(args[1])}",
+            )
+            if props[key]:
+                self.assertTrue(
+                    val == args[1][key],
+                    f'   ERROR: Validate failed: "{val}" expected, "{args[1][key]}" generated',
+                )
+
+    def assert_telemetry_calls(self, telemetry_mock, calls) -> None:
+        index = 0
+        for event_name, props in calls:
+            self.assert_telemetry_call(telemetry_mock, index, event_name, props)
+            index += 1
+        if index != len(telemetry_mock.track_event.call_args_list):
+            self.assertTrue(  # pylint: disable=redundant-unittest-assert
+                False,
+                f"Found {len(telemetry_mock.track_event.call_args_list)} calls, testing for {index + 1}",
+            )