From e31988795f9e318e28ff46412823498d47251bc4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rodrigo=20Brand=C3=A3o?= Date: Thu, 24 Jul 2025 08:39:33 -0700 Subject: [PATCH 1/8] Added logging to auth library --- .../agents/authentication/msal/msal_auth.py | 28 +++++++++++++++++++ 1 file changed, 28 insertions(+) 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 c6086a77..985d0644 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 @@ -1,5 +1,6 @@ from __future__ import annotations +import logging from typing import Optional from urllib.parse import urlparse, ParseResult as URI from msal import ( @@ -19,6 +20,8 @@ AgentAuthConfiguration, ) +logger = logging.getLogger(__name__) + class MsalAuth(AccessTokenProviderBase): @@ -26,10 +29,16 @@ class MsalAuth(AccessTokenProviderBase): def __init__(self, msal_configuration: AgentAuthConfiguration): self._msal_configuration = msal_configuration + logger.debug( + f"Initializing MsalAuth with configuration: {self._msal_configuration}" + ) async def get_access_token( self, resource_url: str, scopes: list[str], force_refresh: bool = False ) -> str: + logger.debug( + f"Requesting access token for resource: {resource_url}, scopes: {scopes}" + ) valid_uri, instance_uri = self._uri_validator(resource_url) if not valid_uri: raise ValueError("Invalid instance URL") @@ -38,10 +47,12 @@ async def get_access_token( msal_auth_client = self._create_client_application() if isinstance(msal_auth_client, ManagedIdentityClient): + logger.info("Acquiring token using Managed Identity Client.") auth_result_payload = msal_auth_client.acquire_token_for_client( resource=resource_url ) elif isinstance(msal_auth_client, ConfidentialClientApplication): + logger.info("Acquiring token using Confidential Client Application.") auth_result_payload = msal_auth_client.acquire_token_for_client( scopes=local_scopes ) @@ -61,6 +72,9 @@ async def aquire_token_on_behalf_of( msal_auth_client = self._create_client_application() if isinstance(msal_auth_client, ManagedIdentityClient): + logger.error( + "Attempted on-behalf-of flow with Managed Identity authentication." + ) raise NotImplementedError( "On-behalf-of flow is not supported with Managed Identity authentication." ) @@ -70,6 +84,9 @@ async def aquire_token_on_behalf_of( user_assertion=user_assertion, scopes=scopes )["access_token"] + logger.error( + f"On-behalf-of flow is not supported with the current authentication type: {msal_auth_client.__class__.__name__}" + ) raise NotImplementedError( f"On-behalf-of flow is not supported with the current authentication type: {msal_auth_client.__class__.__name__}" ) @@ -97,17 +114,23 @@ def _create_client_application( authority = f"https://login.microsoftonline.com/{authority_path}" if self._client_credential_cache: + logger.info("Using cached client credentials for MSAL authentication.") pass elif self._msal_configuration.AUTH_TYPE == AuthTypes.client_secret: self._client_credential_cache = self._msal_configuration.CLIENT_SECRET elif self._msal_configuration.AUTH_TYPE == AuthTypes.certificate: with open(self._msal_configuration.CERT_KEY_FILE) as file: + logger.info( + "Loading certificate private key for MSAL authentication." + ) private_key = file.read() with open(self._msal_configuration.CERT_PEM_FILE) as file: + logger.info("Loading public certificate for MSAL authentication.") public_certificate = file.read() # Create an X509 object and calculate the thumbprint + logger.info("Calculating thumbprint for the public certificate.") cert = load_pem_x509_certificate( data=bytes(public_certificate, "UTF-8"), backend=default_backend() ) @@ -118,6 +141,9 @@ def _create_client_application( "private_key": private_key, } else: + logger.error( + f"Unsupported authentication type: {self._msal_configuration.AUTH_TYPE}" + ) raise NotImplementedError("Authentication type not supported") msal_auth_client = ConfidentialClientApplication( @@ -134,6 +160,7 @@ def _uri_validator(url_str: str) -> tuple[bool, Optional[URI]]: result = urlparse(url_str) return all([result.scheme, result.netloc]), result except AttributeError: + logger.error(f"URI parsing error for {url_str}") return False, None def _resolve_scopes_list(self, instance_url: URI, scopes=None) -> list[str]: @@ -148,4 +175,5 @@ def _resolve_scopes_list(self, instance_url: URI, scopes=None) -> list[str]: "{instance}", f"{instance_url.scheme}://{instance_url.hostname}" ) temp_list.append(scope_placeholder) + logger.debug(f"Resolved scopes: {temp_list}") return temp_list From f6b4873fd96dc573a2537ef5fa0d44a1b9844b1d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rodrigo=20Brand=C3=A3o?= Date: Thu, 24 Jul 2025 10:58:34 -0700 Subject: [PATCH 2/8] Added prelim logging to authorization and jwt token validator code --- .../hosting/core/app/oauth/authorization.py | 28 +++++++++++++++++++ .../core/authorization/jwt_token_validator.py | 7 +++++ 2 files changed, 35 insertions(+) diff --git a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/oauth/authorization.py b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/oauth/authorization.py index a63a649e..a6ae16b7 100644 --- a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/oauth/authorization.py +++ b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/oauth/authorization.py @@ -2,6 +2,7 @@ # Licensed under the MIT License. from __future__ import annotations +import logging import jwt from typing import Dict, Optional, Callable, Awaitable @@ -19,6 +20,8 @@ from ...oauth_flow import OAuthFlow, FlowState from ...state.user_state import UserState +logger = logging.getLogger(__name__) + class SignInState(StoreItem, BaseModel): """ @@ -70,6 +73,9 @@ def __init__( "OBOCONNECTIONNAME" ) self.flow: OAuthFlow = None + logger.debug( + f"AuthHandler initialized: name={self.name}, title={self.title}, text={self.text} abs_connection_name={self.abs_oauth_connection_name} obo_connection_name={self.obo_connection_name}" + ) # Type alias for authorization handlers dictionary @@ -102,6 +108,7 @@ def __init__( ValueError: If storage is None or no auth handlers are provided. """ if storage is None: + logger.error("Storage is required for Authorization") raise ValueError("Storage is required for Authorization") user_state = UserState(storage) @@ -120,6 +127,7 @@ def __init__( if not auth_handlers: handlers_congif: Dict[str, Dict] = auth_configuration.get("HANDLERS") if not handlers_congif: + logger.error("No auth handlers provided in configuration") raise ValueError("The authorization does not have any auth handlers") auth_handlers = { handler_name: AuthHandler( @@ -145,6 +153,7 @@ def __init__( if auth_handler.text: messages_config["button_text"] = auth_handler.text + logger.debug(f"Configuring OAuth flow for handler: {auth_handler.name}") auth_handler.flow = OAuthFlow( storage=storage, abs_oauth_connection_name=auth_handler.abs_oauth_connection_name, @@ -166,6 +175,7 @@ async def get_token( """ auth_handler = self.resolver_handler(auth_handler_id) if auth_handler.flow is None: + logger.error("OAuth flow is not configured for the auth handler") raise ValueError("OAuth flow is not configured for the auth handler") return await auth_handler.flow.get_user_token(context) @@ -189,6 +199,7 @@ async def exchange_token( """ auth_handler = self.resolver_handler(auth_handler_id) if not auth_handler.flow: + logger.error("OAuth flow is not configured for the auth handler") raise ValueError("OAuth flow is not configured for the auth handler") token_response = await auth_handler.flow.get_user_token(context) @@ -217,6 +228,7 @@ def _is_exchangeable(self, token: Optional[str]) -> bool: aud = payload.get("aud") return isinstance(aud, str) and aud.startswith("api://") except Exception: + logger.exception("Failed to decode token to check audience") return False async def _handle_obo( @@ -235,12 +247,14 @@ async def _handle_obo( """ auth_handler = self.resolver_handler(handler_id) if auth_handler.flow is None: + logger.error("OAuth flow is not configured for the auth handler") raise ValueError("OAuth flow is not configured for the auth handler") # Use the flow's OBO method to exchange the token token_provider: AccessTokenProviderBase = ( self._connection_manager.get_connection(auth_handler.obo_connection_name) ) + logger.info("Attempting to exchange token on behalf of user") token = await token_provider.aquire_token_on_behalf_of( scopes=scopes, user_assertion=token, @@ -298,31 +312,42 @@ async def begin_or_continue_flow( flow = auth_handler.flow if flow is None: + logger.error("OAuth flow is not configured for the auth handler") raise ValueError("OAuth flow is not configured for the auth handler") + logger.info( + "Beginning or continuing OAuth flow for handler: %s", auth_handler_id + ) token_response = await flow.get_user_token(context) if token_response and token_response.token: + logger.debug("Token obtained successfully") return token_response # Get the current flow state flow_state = await flow._get_flow_state(context) if not flow_state.flow_started: + logger.info("Starting new OAuth flow for handler: %s", auth_handler_id) token_response = await flow.begin_flow(context) if sec_route: sign_in_state.continuation_activity = context.activity sign_in_state.handler_id = auth_handler_id turn_state.set_value(self.SIGN_IN_STATE_KEY, sign_in_state) else: + logger.info( + "Continuing existing OAuth flow for handler: %s", auth_handler_id + ) token_response = await flow.continue_flow(context) # Check if sign-in was successful and call handler if configured if token_response and token_response.token: if self._sign_in_handler: + logger.info("Sign-in successful, calling sign-in handler") await self._sign_in_handler(context, turn_state, auth_handler_id) if sec_route: turn_state.delete_value(self.SIGN_IN_STATE_KEY) else: if self._sign_in_failed_handler: + logger.warning("Sign-in failed, calling sign-in failed handler") await self._sign_in_failed_handler( context, turn_state, auth_handler_id ) @@ -342,6 +367,7 @@ def resolver_handler(self, auth_handler_id: Optional[str] = None) -> AuthHandler """ if auth_handler_id: if auth_handler_id not in self._auth_handlers: + logger.error(f"Auth handler '{auth_handler_id}' not found") raise ValueError(f"Auth handler '{auth_handler_id}' not found") return self._auth_handlers[auth_handler_id] @@ -368,11 +394,13 @@ async def sign_out( # Sign out from all handlers for handler_key, auth_handler in self._auth_handlers.items(): if auth_handler.flow: + logger.info(f"Signing out from handler: {handler_key}") await auth_handler.flow.sign_out(context) else: # Sign out from specific handler auth_handler = self.resolver_handler(auth_handler_id) if auth_handler.flow: + logger.info(f"Signing out from handler: {auth_handler_id}") await auth_handler.flow.sign_out(context) def on_sign_in_success( diff --git a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/authorization/jwt_token_validator.py b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/authorization/jwt_token_validator.py index 1c0811f6..c79ea013 100644 --- a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/authorization/jwt_token_validator.py +++ b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/authorization/jwt_token_validator.py @@ -1,3 +1,4 @@ +import logging import jwt from jwt import PyJWKClient, PyJWK, decode, get_unverified_header @@ -5,12 +6,16 @@ from .agent_auth_configuration import AgentAuthConfiguration from .claims_identity import ClaimsIdentity +logger = logging.getLogger(__name__) + class JwtTokenValidator: def __init__(self, configuration: AgentAuthConfiguration): self.configuration = configuration def validate_token(self, token: str) -> ClaimsIdentity: + + logger.debug("Validating JWT token.") key = self._get_public_key_or_secret(token) decoded_token = jwt.decode( token, @@ -20,9 +25,11 @@ def validate_token(self, token: str) -> ClaimsIdentity: options={"verify_aud": False}, ) if decoded_token["aud"] != self.configuration.CLIENT_ID: + logger.error(f"Invalid audience: {decoded_token['aud']}") raise ValueError("Invalid audience.") # This probably should return a ClaimsIdentity + logger.debug("JWT token validated successfully.") return ClaimsIdentity(decoded_token, True) def get_anonymous_claims(self) -> ClaimsIdentity: From 0d720a8d0b428aa6e4416afdeec1c5de89ecc72b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rodrigo=20Brand=C3=A3o?= Date: Thu, 24 Jul 2025 14:25:14 -0700 Subject: [PATCH 3/8] Added logging to core modules --- .../hosting/core/app/agent_application.py | 75 ++++++++- .../agents/hosting/core/app/app_options.py | 2 +- .../hosting/core/app/oauth/authorization.py | 5 +- .../core/app/state/conversation_state.py | 5 + .../agents/hosting/core/app/state/state.py | 5 +- .../hosting/core/app/state/turn_state.py | 4 + .../hosting/core/app/typing_indicator.py | 8 +- .../core/authorization/jwt_token_validator.py | 3 +- .../core/connector/client/connector_client.py | 158 ++++++++++++++++-- .../connector/client/user_token_client.py | 17 +- 10 files changed, 259 insertions(+), 23 deletions(-) diff --git a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py index 4d4e209f..29129da9 100644 --- a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py +++ b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py @@ -4,6 +4,7 @@ """ from __future__ import annotations +import logging from copy import copy from functools import partial @@ -44,6 +45,8 @@ from .oauth import Authorization, SignInState from .typing_indicator import TypingIndicator +logger = logging.getLogger(__name__) + StateT = TypeVar("StateT", bound=TurnState) IN_SIGN_IN_KEY = "__InSignInFlow__" @@ -88,6 +91,11 @@ def __init__( configuration = kwargs + logger.debug(f"Initializing AgentApplication with options: {options}") + logger.debug( + f"Initializing AgentApplication with configuration: {configuration}" + ) + if not options: # TODO: consolidate configuration story # Take the options from the kwargs and create an ApplicationOptions instance @@ -102,6 +110,10 @@ def __init__( self._options = options if not self._options.storage: + logger.error( + "ApplicationOptions.storage is required and was not configured.", + stack_info=True, + ) raise ApplicationError( """ The `ApplicationOptions.storage` property is required and was not configured. @@ -111,6 +123,10 @@ def __init__( if options.long_running_messages and ( not options.adapter or not options.bot_app_id ): + logger.error( + "ApplicationOptions.long_running_messages requires an adapter and bot_app_id.", + stack_info=True, + ) raise ApplicationError( """ The `ApplicationOptions.long_running_messages` property is unavailable because @@ -132,6 +148,10 @@ def __init__( self._auth = authorization else: if not connection_manager: + logger.error( + "ApplicationOptions.authorization requires a Connections instance.", + stack_info=True, + ) raise ApplicationError( """ The `AgentApplication` requires a `Connections` instance to be passed as the @@ -153,6 +173,10 @@ def adapter(self) -> ChannelServiceAdapter: """ if not self._adapter: + logger.error( + "AgentApplication.adapter(): self._adapter is not configured.", + stack_info=True, + ) raise ApplicationError( """ The AgentApplication.adapter property is unavailable because it was @@ -168,6 +192,10 @@ def auth(self): The application's authentication manager """ if not self._auth: + logger.error( + "AgentApplication.auth(): self._auth is not configured.", + stack_info=True, + ) raise ApplicationError( """ The `AgentApplication.auth` property is unavailable because @@ -210,6 +238,9 @@ def __selector(context: TurnContext): return activity_type == context.activity.type def __call(func: RouteHandler[StateT]) -> RouteHandler[StateT]: + logger.debug( + f"Registering activity handler for route handler {func.__name__} with type: {activity_type} with auth handlers: {auth_handlers}" + ) self._routes.append( Route[StateT](__selector, func, auth_handlers=auth_handlers) ) @@ -250,6 +281,9 @@ def __selector(context: TurnContext): return text == select def __call(func: RouteHandler[StateT]) -> RouteHandler[StateT]: + logger.debug( + f"Registering message handler for route handler {func.__name__} with select: {select} with auth handlers: {auth_handlers}" + ) self._routes.append( Route[StateT](__selector, func, auth_handlers=auth_handlers) ) @@ -301,6 +335,9 @@ def __selector(context: TurnContext): return False def __call(func: RouteHandler[StateT]) -> RouteHandler[StateT]: + logger.debug( + f"Registering conversation update handler for route handler {func.__name__} with type: {type} with auth handlers: {auth_handlers}" + ) self._routes.append( Route[StateT](__selector, func, auth_handlers=auth_handlers) ) @@ -344,6 +381,9 @@ def __selector(context: TurnContext): return False def __call(func: RouteHandler[StateT]) -> RouteHandler[StateT]: + logger.debug( + f"Registering message reaction handler for route handler {func.__name__} with type: {type} with auth handlers: {auth_handlers}" + ) self._routes.append( Route[StateT](__selector, func, auth_handlers=auth_handlers) ) @@ -400,6 +440,9 @@ def __selector(context: TurnContext): return False def __call(func: RouteHandler[StateT]) -> RouteHandler[StateT]: + logger.debug( + f"Registering message update handler for route handler {func.__name__} with type: {type} with auth handlers: {auth_handlers}" + ) self._routes.append( Route[StateT](__selector, func, auth_handlers=auth_handlers) ) @@ -444,6 +487,10 @@ async def __handler(context: TurnContext, state: StateT): ) return True + logger.debug( + f"Registering handoff handler for route handler {func.__name__} with auth handlers: {auth_handlers}" + ) + self._routes.append( Route[StateT](__selector, __handler, True, auth_handlers) ) @@ -468,8 +515,15 @@ async def sign_in_success(context: TurnContext, state: TurnState): """ if self._auth: + logger.debug( + f"Registering sign-in success handler for route handler {func.__name__}" + ) self._auth.on_sign_in_success(func) else: + logger.error( + f"Failed to register sign-in success handler for route handler {func.__name__}", + stack_info=True, + ) raise ApplicationError( """ The `AgentApplication.on_sign_in_success` method is unavailable because @@ -494,8 +548,15 @@ async def sign_in_failure(context: TurnContext, state: TurnState): """ if self._auth: + logger.debug( + f"Registering sign-in failure handler for route handler {func.__name__}" + ) self._auth.on_sign_in_failure(func) else: + logger.error( + f"Failed to register sign-in failure handler for route handler {func.__name__}", + stack_info=True, + ) raise ApplicationError( """ The `AgentApplication.on_sign_in_failure` method is unavailable because @@ -519,9 +580,13 @@ async def on_error(context: TurnContext, err: Exception): ``` """ + logger.debug(f"Registering the error handler {func.__name__} ") self._error = func if self._adapter: + logger.debug( + f"Registering for adapter {self._adapter.__class__.__name__} the error handler {func.__name__} " + ) self._adapter.on_turn_error = func return func @@ -530,10 +595,11 @@ def turn_state_factory(self, func: Callable[[TurnContext], Awaitable[StateT]]): """ Custom Turn State Factory """ - + logger.debug(f"Setting custom turn state factory: {func.__name__}") self._turn_state_factory = func return func + # robrandao async def on_turn(self, context: TurnContext): await self._start_long_running_call(context, self._on_turn) @@ -695,7 +761,14 @@ async def _start_long_running_call( async def _on_error(self, context: TurnContext, err: ApplicationError) -> None: if self._error: + self._options.logger.info( + f"Calling error handler {self._error.__name__} for error: {err}" + ) return await self._error(context, err) + self._options.logger.error( + f"An error occurred in the AgentApplication: {err}", + exc_info=True, + ) self._options.logger.error(err) raise err diff --git a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/app_options.py b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/app_options.py index dcb696ec..c8d125cb 100644 --- a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/app_options.py +++ b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/app_options.py @@ -43,7 +43,7 @@ class ApplicationOptions: Optional. `Storage` provider to use for the application. """ - logger: Logger = Logger("teams.ai") + logger: Logger = Logger(__name__) """ Optional. `Logger` that will be used in this application. """ diff --git a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/oauth/authorization.py b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/oauth/authorization.py index a6ae16b7..bd90ba84 100644 --- a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/oauth/authorization.py +++ b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/oauth/authorization.py @@ -347,7 +347,10 @@ async def begin_or_continue_flow( turn_state.delete_value(self.SIGN_IN_STATE_KEY) else: if self._sign_in_failed_handler: - logger.warning("Sign-in failed, calling sign-in failed handler") + logger.warning( + "Sign-in failed, calling sign-in failed handler", + stack_info=True, + ) await self._sign_in_failed_handler( context, turn_state, auth_handler_id ) diff --git a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/state/conversation_state.py b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/state/conversation_state.py index 6c44b1bd..9e18e915 100644 --- a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/state/conversation_state.py +++ b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/state/conversation_state.py @@ -4,6 +4,7 @@ """ from __future__ import annotations +import logging from typing import Type @@ -12,6 +13,8 @@ from microsoft.agents.hosting.core.turn_context import TurnContext from microsoft.agents.hosting.core.state import AgentState +logger = logging.getLogger(__name__) + class ConversationState(AgentState): """ @@ -34,10 +37,12 @@ def get_storage_key( ): channel_id = turn_context.activity.channel_id if not channel_id: + logger.error("Invalid activity: missing channel_id.") raise ValueError("Invalid activity: missing channel_id.") conversation_id = turn_context.activity.conversation.id if not conversation_id: + logger.error("Invalid activity: missing conversation_id.") raise ValueError("Invalid activity: missing conversation_id.") return f"{channel_id}/conversations/{conversation_id}" diff --git a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/state/state.py b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/state/state.py index b890f23d..dd72a46e 100644 --- a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/state/state.py +++ b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/state/state.py @@ -4,6 +4,7 @@ """ from __future__ import annotations +import logging import json from abc import ABC, abstractmethod @@ -14,9 +15,10 @@ StatePropertyAccessor as _StatePropertyAccessor, ) from microsoft.agents.hosting.core.storage import Storage, StoreItem - from microsoft.agents.hosting.core.turn_context import TurnContext +logger = logging.getLogger(__name__) + T = TypeVar("T") @@ -106,6 +108,7 @@ async def save( data = self.copy() del data["__key__"] + logger.info(f"Saving state {self.__key__}") await storage.delete(self.__deleted__) await storage.write( { diff --git a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/state/turn_state.py b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/state/turn_state.py index bff8a5c2..1393a005 100644 --- a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/state/turn_state.py +++ b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/state/turn_state.py @@ -4,6 +4,7 @@ """ from __future__ import annotations +import logging from typing import Any, Dict, Optional, Type, TypeVar, cast, Callable, Awaitable import asyncio @@ -16,6 +17,8 @@ from microsoft.agents.hosting.core.app.state.temp_state import TempState from microsoft.agents.hosting.core.state.user_state import UserState +logging = logging.getLogger(__name__) + ConversationStateT = TypeVar("ConversationStateT", bound=ConversationState) UserStateT = TypeVar("UserStateT", bound=UserState) TempStateT = TypeVar("TempStateT", bound=TempState) @@ -60,6 +63,7 @@ def with_storage(cls, storage: Storage, *agent_states: AgentState) -> "TurnState Returns: A new TurnState instance with the default states. """ + logger.debug("Creating TurnState with storage: %s", storage) turn_state = cls() # Add default states diff --git a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/typing_indicator.py b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/typing_indicator.py index 82f8bc78..308ef747 100644 --- a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/typing_indicator.py +++ b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/typing_indicator.py @@ -4,6 +4,7 @@ """ from __future__ import annotations +import logging from threading import Timer from typing import Optional @@ -11,6 +12,8 @@ from microsoft.agents.hosting.core import TurnContext from microsoft.agents.activity import Activity, ActivityTypes +logger = logging.getLogger(__name__) + class TypingIndicator: """ @@ -27,6 +30,7 @@ async def start(self, context: TurnContext) -> None: if self._timer is not None: return + logger.debug(f"Starting typing indicator with interval: {self._interval} ms") func = self._on_timer(context) self._timer = Timer(self._interval, func) self._timer.start() @@ -34,16 +38,18 @@ async def start(self, context: TurnContext) -> None: def stop(self) -> None: if self._timer: + logger.debug("Stopping typing indicator") self._timer.cancel() self._timer = None def _on_timer(self, context: TurnContext): async def __call__(): try: + logger.debug("Sending typing activity") await context.send_activity(Activity(type=ActivityTypes.typing)) except Exception as e: # TODO: Improve when adding logging - print(f"Error sending typing activity: {e}") + logger.error(f"Error sending typing activity: {e}") self.stop() return __call__ diff --git a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/authorization/jwt_token_validator.py b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/authorization/jwt_token_validator.py index c79ea013..26bfc7ee 100644 --- a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/authorization/jwt_token_validator.py +++ b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/authorization/jwt_token_validator.py @@ -25,7 +25,7 @@ def validate_token(self, token: str) -> ClaimsIdentity: options={"verify_aud": False}, ) if decoded_token["aud"] != self.configuration.CLIENT_ID: - logger.error(f"Invalid audience: {decoded_token['aud']}") + logger.error(f"Invalid audience: {decoded_token['aud']}", stack_info=True) raise ValueError("Invalid audience.") # This probably should return a ClaimsIdentity @@ -33,6 +33,7 @@ def validate_token(self, token: str) -> ClaimsIdentity: return ClaimsIdentity(decoded_token, True) def get_anonymous_claims(self) -> ClaimsIdentity: + logger.debug("Returning anonymous claims identity.") return ClaimsIdentity({}, False, authentication_type="Anonymous") def _get_public_key_or_secret(self, token: str) -> PyJWK: diff --git a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/connector/client/connector_client.py b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/connector/client/connector_client.py index d3f976a6..add7d18a 100644 --- a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/connector/client/connector_client.py +++ b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/connector/client/connector_client.py @@ -23,7 +23,7 @@ from ..get_product_info import get_product_info -logger = logging.getLogger("microsoft.agents.connector.client") +logger = logging.getLogger(__name__) class AttachmentInfo: @@ -74,9 +74,12 @@ async def get_attachment_info(self, attachment_id: str) -> AttachmentInfo: url = f"v3/attachments/{attachment_id}" + logger.info(f"Getting attachment info for ID: {attachment_id}") async with self.client.get(url) as response: if response.status >= 400: - logger.error(f"Error getting attachment info: {response.status}") + logger.error( + f"Error getting attachment info: {response.status}", stack_info=True + ) response.raise_for_status() data = await response.json() @@ -91,15 +94,26 @@ async def get_attachment(self, attachment_id: str, view_id: str) -> BytesIO: :return: The attachment as a readable stream. """ if attachment_id is None: + logger.error( + "AttachmentsOperations.get_attachment(): attachmentId is required", + stack_info=True, + ) raise ValueError("attachmentId is required") if view_id is None: + logger.error( + "AttachmentsOperations.get_attachment(): viewId is required", + stack_info=True, + ) raise ValueError("viewId is required") url = f"v3/attachments/{attachment_id}/views/{view_id}" + logger.info(f"Getting attachment for ID: {attachment_id}, View ID: {view_id}") async with self.client.get(url) as response: if response.status >= 400: - logger.error(f"Error getting attachment: {response.status}") + logger.error( + f"Error getting attachment: {response.status}", stack_info=True + ) response.raise_for_status() data = await response.read() @@ -124,9 +138,14 @@ async def get_conversations( {"continuationToken": continuation_token} if continuation_token else None ) + logger.info( + f"Getting conversations with continuation token: {continuation_token}" + ) async with self.client.get("v3/conversations", params=params) as response: if response.status >= 400: - logger.error(f"Error getting conversations: {response.status}") + logger.error( + f"Error getting conversations: {response.status}", stack_info=True + ) response.raise_for_status() data = await response.json() @@ -142,12 +161,15 @@ async def create_conversation( :return: The conversation resource response. """ + logger.info("Creating a new conversation") async with self.client.post( "v3/conversations", json=body.model_dump(by_alias=True, exclude_unset=True, mode="json"), ) as response: if response.status >= 400: - logger.error(f"Error creating conversation: {response.status}") + logger.error( + f"Error creating conversation: {response.status}", stack_info=True + ) response.raise_for_status() data = await response.json() @@ -165,10 +187,17 @@ async def reply_to_activity( :return: The resource response. """ if not conversation_id or not activity_id: + logger.error( + "ConversationsOperations.reply_to_activity(): conversationId and activityId are required", + stack_info=True, + ) raise ValueError("conversationId and activityId are required") url = f"v3/conversations/{conversation_id}/activities/{activity_id}" + logger.info( + f"Replying to activity: {activity_id} in conversation: {conversation_id}. Activity type is {body.type}" + ) async with self.client.post( url, json=body.model_dump( @@ -178,7 +207,10 @@ async def reply_to_activity( result = await response.json() if response.content_length else {} if response.status >= 400: - logger.error(f"Error replying to activity: {result or response.status}") + logger.error( + f"Error replying to activity: {result or response.status}", + stack_info=True, + ) response.raise_for_status() logger.info( @@ -197,16 +229,25 @@ async def send_to_conversation( :return: The resource response. """ if not conversation_id: + logger.error( + "ConversationsOperations.sent_to_conversation(): conversationId is required", + stack_info=True, + ) raise ValueError("conversationId is required") url = f"v3/conversations/{conversation_id}/activities" + logger.info( + f"Sending to conversation: {conversation_id}. Activity type is {body.type}" + ) async with self.client.post( url, json=body.model_dump(by_alias=True, exclude_unset=True, mode="json"), ) as response: if response.status >= 400: - logger.error(f"Error sending to conversation: {response.status}") + logger.error( + f"Error sending to conversation: {response.status}", stack_info=True + ) response.raise_for_status() data = await response.json() @@ -224,16 +265,25 @@ async def update_activity( :return: The resource response. """ if not conversation_id or not activity_id: + logger.error( + "ConversationsOperations.update_activity(): conversationId and activityId are required", + stack_info=True, + ) raise ValueError("conversationId and activityId are required") url = f"v3/conversations/{conversation_id}/activities/{activity_id}" + logger.info( + f"Updating activity: {activity_id} in conversation: {conversation_id}. Activity type is {body.type}" + ) async with self.client.put( url, json=body.model_dump(by_alias=True, exclude_unset=True), ) as response: if response.status >= 400: - logger.error(f"Error updating activity: {response.status}") + logger.error( + f"Error updating activity: {response.status}", stack_info=True + ) response.raise_for_status() data = await response.json() @@ -247,13 +297,22 @@ async def delete_activity(self, conversation_id: str, activity_id: str) -> None: :param activity_id: The ID of the activity. """ if not conversation_id or not activity_id: + logger.error( + "ConversationsOperations.delete_activity(): conversationId and activityId are required", + stack_info=True, + ) raise ValueError("conversationId and activityId are required") url = f"v3/conversations/{conversation_id}/activities/{activity_id}" + logger.info( + f"Deleting activity: {activity_id} from conversation: {conversation_id}" + ) async with self.client.delete(url) as response: if response.status >= 400: - logger.error(f"Error deleting activity: {response.status}") + logger.error( + f"Error deleting activity: {response.status}", stack_info=True + ) response.raise_for_status() async def upload_attachment( @@ -267,6 +326,10 @@ async def upload_attachment( :return: The resource response. """ if conversation_id is None: + logger.error( + "ConversationsOperations.upload_attachment(): conversationId is required", + stack_info=True, + ) raise ValueError("conversationId is required") url = f"v3/conversations/{conversation_id}/attachments" @@ -279,9 +342,14 @@ async def upload_attachment( "thumbnailBase64": body.thumbnail_base64, } + logger.info( + f"Uploading attachment to conversation: {conversation_id}, Attachment name: {body.name}" + ) async with self.client.post(url, json=attachment_dict) as response: if response.status >= 400: - logger.error(f"Error uploading attachment: {response.status}") + logger.error( + f"Error uploading attachment: {response.status}", stack_info=True + ) response.raise_for_status() data = await response.json() @@ -297,13 +365,21 @@ async def get_conversation_members( :return: A list of members. """ if not conversation_id: + logger.error( + "ConversationsOperations.get_conversation_members(): conversationId is required", + stack_info=True, + ) raise ValueError("conversationId is required") url = f"v3/conversations/{conversation_id}/members" + logger.info(f"Getting conversation members for conversation: {conversation_id}") async with self.client.get(url) as response: if response.status >= 400: - logger.error(f"Error getting conversation members: {response.status}") + logger.error( + f"Error getting conversation members: {response.status}", + stack_info=True, + ) response.raise_for_status() data = await response.json() @@ -320,13 +396,23 @@ async def get_conversation_member( :return: The member. """ if not conversation_id or not member_id: + logger.error( + "ConversationsOperations.get_conversation_member(): conversationId and memberId are required", + stack_info=True, + ) raise ValueError("conversationId and memberId are required") url = f"v3/conversations/{conversation_id}/members/{member_id}" + logger.info( + f"Getting conversation member: {member_id} from conversation: {conversation_id}" + ) async with self.client.get(url) as response: if response.status >= 400: - logger.error(f"Error getting conversation member: {response.status}") + logger.error( + f"Error getting conversation member: {response.status}", + stack_info=True, + ) response.raise_for_status() data = await response.json() @@ -342,13 +428,23 @@ async def delete_conversation_member( :param member_id: The ID of the member. """ if not conversation_id or not member_id: + logger.error( + "ConversationsOperations.delete_conversation_member(): conversationId and memberId are required", + stack_info=True, + ) raise ValueError("conversationId and memberId are required") url = f"v3/conversations/{conversation_id}/members/{member_id}" + logger.info( + f"Deleting conversation member: {member_id} from conversation: {conversation_id}" + ) async with self.client.delete(url) as response: if response.status >= 400 and response.status != 204: - logger.error(f"Error deleting conversation member: {response.status}") + logger.error( + f"Error deleting conversation member: {response.status}", + stack_info=True, + ) response.raise_for_status() async def get_activity_members( @@ -362,13 +458,23 @@ async def get_activity_members( :return: A list of members. """ if not conversation_id or not activity_id: + logger.error( + "ConversationsOperations.get_activity_members(): conversationId and activityId are required", + stack_info=True, + ) raise ValueError("conversationId and activityId are required") url = f"v3/conversations/{conversation_id}/activities/{activity_id}/members" + logger.info( + f"Getting activity members for conversation: {conversation_id}, Activity ID: {activity_id}" + ) async with self.client.get(url) as response: if response.status >= 400: - logger.error(f"Error getting activity members: {response.status}") + logger.error( + f"Error getting activity members: {response.status}", + stack_info=True, + ) response.raise_for_status() data = await response.json() @@ -389,6 +495,10 @@ async def get_conversation_paged_members( :return: A paged list of members. """ if not conversation_id: + logger.error( + "ConversationsOperations.get_conversation_paged_members(): conversationId is required", + stack_info=True, + ) raise ValueError("conversationId is required") params = {} @@ -399,10 +509,14 @@ async def get_conversation_paged_members( url = f"v3/conversations/{conversation_id}/pagedmembers" + logger.info( + f"Getting paged members for conversation: {conversation_id}, Page Size: {page_size}, Continuation Token: {continuation_token}" + ) async with self.client.get(url, params=params) as response: if response.status >= 400: logger.error( - f"Error getting conversation paged members: {response.status}" + f"Error getting conversation paged members: {response.status}", + stack_info=True, ) response.raise_for_status() @@ -420,17 +534,25 @@ async def send_conversation_history( :return: The resource response. """ if not conversation_id: + logger.error( + "ConversationsOperations.send_conversation_history(): conversationId is required", + stack_info=True, + ) raise ValueError("conversationId is required") url = f"v3/conversations/{conversation_id}/activities/history" + logger.info(f"Sending conversation history to conversation: {conversation_id}") async with self.client.post(url, json=body) as response: if ( response.status >= 400 and response.status != 201 and response.status != 202 ): - logger.error(f"Error sending conversation history: {response.status}") + logger.error( + f"Error sending conversation history: {response.status}", + stack_info=True, + ) response.raise_for_status() data = await response.json() @@ -462,6 +584,9 @@ def __init__(self, endpoint: str, token: str, *, session: ClientSession = None): base_url=endpoint, headers=headers, ) + logger.debug( + f"ConnectorClient initialized with endpoint: {endpoint} and headers: {headers}" + ) if len(token) > 1: session.headers.update({"Authorization": f"Bearer {token}"}) @@ -504,4 +629,5 @@ def conversations(self) -> ConversationsBase: async def close(self) -> None: """Close the HTTP session.""" if self.client: + logger.debug("Closing ConnectorClient session") await self.client.close() diff --git a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/connector/client/user_token_client.py b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/connector/client/user_token_client.py index ae5b003a..9f324c5c 100644 --- a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/connector/client/user_token_client.py +++ b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/connector/client/user_token_client.py @@ -14,7 +14,7 @@ from ..agent_sign_in_base import AgentSignInBase -logger = logging.getLogger("microsoft.agents.connector.client.user_token_client") +logger = logging.getLogger(__name__) class AgentSignIn(AgentSignInBase): @@ -47,6 +47,9 @@ async def get_sign_in_url( if final_redirect: params["finalRedirect"] = final_redirect + logger.info( + f"AgentSignIn.get_sign_in_url(): Getting sign-in URL with params: {params}" + ) async with self.client.get( "api/agentsignin/getSignInUrl", params=params ) as response: @@ -80,6 +83,9 @@ async def get_sign_in_resource( if final_redirect: params["finalRedirect"] = final_redirect + logger.info( + f"AgentSignIn.get_sign_in_resource(): Getting sign-in resource with params: {params}" + ) async with self.client.get( "api/botsignin/getSignInResource", params=params ) as response: @@ -120,6 +126,7 @@ async def get_token( if code: params["code"] = code + logger.info(f"User_token.get_token(): Getting token with params: {params}") async with self.client.get("api/usertoken/GetToken", params=params) as response: if response.status == 404: return TokenResponse(model_validate={}) @@ -151,6 +158,7 @@ async def get_aad_tokens( if channel_id: params["channelId"] = channel_id + logger.info(f"Getting AAD tokens with params: {params} and body: {body}") async with self.client.post( "api/usertoken/GetAadTokens", params=params, json=body ) as response: @@ -181,6 +189,7 @@ async def sign_out( if channel_id: params["channelId"] = channel_id + logger.info(f"Signing out user {user_id} with params: {params}") async with self.client.delete( "api/usertoken/SignOut", params=params ) as response: @@ -209,6 +218,7 @@ async def get_token_status( if include: params["include"] = include + logger.info(f"Getting token status for user {user_id} with params: {params}") async with self.client.get( "api/usertoken/GetTokenStatus", params=params ) as response: @@ -241,6 +251,7 @@ async def exchange_token( "channelId": channel_id, } + logger.info(f"Exchanging token with params: {params} and body: {body}") async with self.client.post( "api/usertoken/exchange", params=params, json=body ) as response: @@ -280,6 +291,9 @@ def __init__(self, endpoint: str, token: str, *, session: ClientSession = None): base_url=endpoint, headers=headers, ) + logger.debug( + f"Creating UserTokenClient with endpoint: {endpoint} and headers: {headers}" + ) if len(token) > 1: session.headers.update({"Authorization": f"Bearer {token}"}) @@ -309,4 +323,5 @@ def user_token(self) -> UserTokenBase: async def close(self) -> None: """Close the HTTP session.""" if self.client: + logger.debug("Closing UserTokenClient session") await self.client.close() From 8dd8161ef6f25d401e03b0403bb72791b91813b1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rodrigo=20Brand=C3=A3o?= Date: Thu, 24 Jul 2025 14:43:47 -0700 Subject: [PATCH 4/8] Add logging to AgentApplication --- .../agents/hosting/core/app/agent_application.py | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py index 29129da9..40db187c 100644 --- a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py +++ b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py @@ -742,6 +742,9 @@ async def _on_activity(self, context: TurnContext, state: StateT): if sign_in_complete: await route.handler(context, state) return + logger.warning( + f"No route found for activity type: {context.activity.type} with text: {context.activity.text}" + ) async def _start_long_running_call( self, context: TurnContext, func: Callable[[TurnContext], Awaitable] @@ -751,6 +754,9 @@ async def _start_long_running_call( and ActivityTypes.message == context.activity.type and self._options.long_running_messages ): + logger.debug( + f"Starting long running call for context: {context.activity.id} with function: {func.__name__}" + ) return await self._adapter.continue_conversation( reference=context.get_conversation_reference(context.activity), callback=func, @@ -761,14 +767,14 @@ async def _start_long_running_call( async def _on_error(self, context: TurnContext, err: ApplicationError) -> None: if self._error: - self._options.logger.info( + logger.info( f"Calling error handler {self._error.__name__} for error: {err}" ) return await self._error(context, err) - self._options.logger.error( + ogger.error( f"An error occurred in the AgentApplication: {err}", exc_info=True, ) - self._options.logger.error(err) + logger.error(err) raise err From 2ce1d6480d7f94e11c9346cb3f5d6ee22b7f908d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rodrigo=20Brand=C3=A3o?= Date: Thu, 24 Jul 2025 14:52:21 -0700 Subject: [PATCH 5/8] Add more logging to AgentApplication --- .../hosting/core/app/agent_application.py | 26 ++++++++++++++++--- 1 file changed, 23 insertions(+), 3 deletions(-) diff --git a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py index 40db187c..90203e02 100644 --- a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py +++ b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py @@ -599,8 +599,10 @@ def turn_state_factory(self, func: Callable[[TurnContext], Awaitable[StateT]]): self._turn_state_factory = func return func - # robrandao async def on_turn(self, context: TurnContext): + logger.debug( + f"AgentApplication.on_turn(): Processing turn for context: {context.activity.id}" + ) await self._start_long_running_call(context, self._on_turn) async def _on_turn(self, context: TurnContext): @@ -609,6 +611,7 @@ async def _on_turn(self, context: TurnContext): self._remove_mentions(context) + logger.debug("Initializing turn state") turn_state = await self._initialize_state(context) sign_in_state = turn_state.get_value( @@ -618,6 +621,7 @@ async def _on_turn(self, context: TurnContext): if self._auth and sign_in_state and not sign_in_state.completed: flow_state = self._auth.get_flow_state(sign_in_state.handler_id) if flow_state.flow_started: + logger.debug("Continuing sign-in flow") token_response = await self._auth.begin_or_continue_flow( context, turn_state, sign_in_state.handler_id ) @@ -625,29 +629,39 @@ async def _on_turn(self, context: TurnContext): if token_response and token_response.token: new_context = copy(context) new_context.activity = saved_activity + logger.debug("Continuing sign-in flow with token response") await self.on_turn(new_context) turn_state.delete_value(Authorization.SIGN_IN_STATE_KEY) await turn_state.save(context) return + logger.debug("Running before turn middleware") if not await self._run_before_turn_middleware(context, turn_state): return + logger.debug("Running file downloads") await self._handle_file_downloads(context, turn_state) + loggeer.debug("Running activity handlers") await self._on_activity(context, turn_state) + logger.debug("Running after turn middleware") if not await self._run_after_turn_middleware(context, turn_state): await turn_state.save(context) - return except ApplicationError as err: + logger.error( + f"An application error occurred in the AgentApplication: {err}", + exc_info=True, + ) await self._on_error(context, err) finally: + logger.debug("Stopping typing indicator") self.typing.stop() async def _start_typing(self, context: TurnContext): if self._options.start_typing_timer: + logger.debug("Starting typing indicator for context") await self.typing.start(context) def _remove_mentions(self, context: TurnContext): @@ -672,6 +686,7 @@ def parse_env_vars_configuration(vars: Dict[str, Any]) -> dict: current_level[next_level] = {} last_level = current_level current_level = current_level[next_level] + logger.debug(f"Using environment variable '{key}'") last_level[levels[-1]] = value return { @@ -683,13 +698,15 @@ def parse_env_vars_configuration(vars: Dict[str, Any]) -> dict: async def _initialize_state(self, context: TurnContext) -> StateT: if self._turn_state_factory: + logger.debug("Using custom turn state factory") turn_state = self._turn_state_factory() else: + logger.debug("Using default turn state factory") turn_state = TurnState.with_storage(self._options.storage) - await turn_state.load(context, self._options.storage) turn_state = cast(StateT, turn_state) + logger.debug("Loading turn state from storage") await turn_state.load(context, self._options.storage) turn_state.temp.input = context.activity.text return turn_state @@ -706,6 +723,9 @@ async def _handle_file_downloads(self, context: TurnContext, state: StateT): if self._options.file_downloaders and len(self._options.file_downloaders) > 0: input_files = state.temp.input_files if state.temp.input_files else [] for file_downloader in self._options.file_downloaders: + logger.info( + f"Using file downloader: {file_downloader.__class__.__name__}" + ) files = await file_downloader.download_files(context) input_files.extend(files) state.temp.input_files = input_files From 2a4bb95fe8aab7667f017e29d70eee7a8631a6ad Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rodrigo=20Brand=C3=A3o?= Date: Thu, 24 Jul 2025 15:05:37 -0700 Subject: [PATCH 6/8] Logging tweaks based on JS version --- .../agents/hosting/core/app/agent_application.py | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py index 90203e02..9be11cdb 100644 --- a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py +++ b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py @@ -617,9 +617,13 @@ async def _on_turn(self, context: TurnContext): sign_in_state = turn_state.get_value( Authorization.SIGN_IN_STATE_KEY, target_cls=SignInState ) + logger.debug( + f"Sign-in state: {sign_in_state} for context: {context.activity.id}" + ) if self._auth and sign_in_state and not sign_in_state.completed: flow_state = self._auth.get_flow_state(sign_in_state.handler_id) + logger.debug("Flow state: %s", flow_state) if flow_state.flow_started: logger.debug("Continuing sign-in flow") token_response = await self._auth.begin_or_continue_flow( @@ -629,7 +633,9 @@ async def _on_turn(self, context: TurnContext): if token_response and token_response.token: new_context = copy(context) new_context.activity = saved_activity - logger.debug("Continuing sign-in flow with token response") + logger.info( + "Resending continuation activity %s", saved_activity.text + ) await self.on_turn(new_context) turn_state.delete_value(Authorization.SIGN_IN_STATE_KEY) await turn_state.save(context) @@ -642,7 +648,7 @@ async def _on_turn(self, context: TurnContext): logger.debug("Running file downloads") await self._handle_file_downloads(context, turn_state) - loggeer.debug("Running activity handlers") + logger.debug("Running activity handlers") await self._on_activity(context, turn_state) logger.debug("Running after turn middleware") From 63dc1edc440f0f001269821299a0bb0118159276 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rodrigo=20Brand=C3=A3o?= Date: Thu, 24 Jul 2025 15:13:38 -0700 Subject: [PATCH 7/8] Added back in possibly redundant configuration load line --- .../microsoft/agents/hosting/core/app/agent_application.py | 1 + 1 file changed, 1 insertion(+) diff --git a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py index 9be11cdb..99cf6b10 100644 --- a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py +++ b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/agent_application.py @@ -709,6 +709,7 @@ async def _initialize_state(self, context: TurnContext) -> StateT: else: logger.debug("Using default turn state factory") turn_state = TurnState.with_storage(self._options.storage) + await turn_state.load(context, self._options.storage) turn_state = cast(StateT, turn_state) From 612fdb4d056efce8828fe42729806f85ca92b887 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rodrigo=20Brand=C3=A3o?= Date: Thu, 24 Jul 2025 15:36:43 -0700 Subject: [PATCH 8/8] Fixed logger definition --- .../microsoft/agents/hosting/core/app/state/turn_state.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/state/turn_state.py b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/state/turn_state.py index 1393a005..7146a085 100644 --- a/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/state/turn_state.py +++ b/libraries/microsoft-agents-hosting-core/microsoft/agents/hosting/core/app/state/turn_state.py @@ -17,7 +17,7 @@ from microsoft.agents.hosting.core.app.state.temp_state import TempState from microsoft.agents.hosting.core.state.user_state import UserState -logging = logging.getLogger(__name__) +logger = logging.getLogger(__name__) ConversationStateT = TypeVar("ConversationStateT", bound=ConversationState) UserStateT = TypeVar("UserStateT", bound=UserState)