diff --git a/libraries/botbuilder-core/botbuilder/core/__init__.py b/libraries/botbuilder-core/botbuilder/core/__init__.py index 832e91242..15b2f5f37 100644 --- a/libraries/botbuilder-core/botbuilder/core/__init__.py +++ b/libraries/botbuilder-core/botbuilder/core/__init__.py @@ -30,6 +30,9 @@ 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 @@ "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 eae91b94b..88dbf812a 100644 --- a/libraries/botbuilder-core/botbuilder/core/middleware_set.py +++ b/libraries/botbuilder-core/botbuilder/core/middleware_set.py @@ -10,7 +10,7 @@ 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 000000000..1ae0f1816 --- /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 000000000..486c502b5 --- /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 000000000..cdb7fcca5 --- /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 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 000000000..7128dab8d --- /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}", + )