diff --git a/examples/a2a-test/src/main.py b/examples/a2a-test/src/main.py index b8fe1f23..05c6ecf6 100644 --- a/examples/a2a-test/src/main.py +++ b/examples/a2a-test/src/main.py @@ -4,6 +4,7 @@ """ import asyncio +import logging import re import uuid from os import getenv @@ -24,14 +25,20 @@ from microsoft_teams.ai import ChatPrompt, Function, ModelMessage from microsoft_teams.api import MessageActivity, TypingActivityInput from microsoft_teams.apps import ActivityContext, App, PluginBase -from microsoft_teams.common import ConsoleLogger, ConsoleLoggerOptions +from microsoft_teams.common import ConsoleFormatter from microsoft_teams.devtools import DevToolsPlugin from microsoft_teams.openai.completions_model import OpenAICompletionsAIModel from pydantic import BaseModel -logger = ConsoleLogger().create_logger("a2a", ConsoleLoggerOptions(level="debug")) PORT = getenv("PORT", "4000") +# Setup logging +logging.getLogger().setLevel(logging.DEBUG) +stream_handler = logging.StreamHandler() +stream_handler.setFormatter(ConsoleFormatter()) +logging.getLogger().addHandler(stream_handler) +logger = logging.getLogger(__name__) + # Setup AI def get_required_env(key: str) -> str: @@ -146,7 +153,7 @@ class LocationParams(BaseModel): # Setup the A2A Server Plugin plugins: List[PluginBase] = [A2APlugin(A2APluginOptions(agent_card=agent_card)), DevToolsPlugin()] -app = App(logger=logger, plugins=plugins) +app = App(plugins=plugins) # A2A Server Event Handler diff --git a/examples/dialogs/src/main.py b/examples/dialogs/src/main.py index c3a10e5c..f5eafffa 100644 --- a/examples/dialogs/src/main.py +++ b/examples/dialogs/src/main.py @@ -4,8 +4,8 @@ """ import asyncio +import logging import os -from logging import Logger from typing import Any, Optional from microsoft_teams.api import ( @@ -25,10 +25,15 @@ from microsoft_teams.apps import ActivityContext, App from microsoft_teams.apps.events.types import ErrorEvent from microsoft_teams.cards import AdaptiveCard, SubmitAction, SubmitActionData, TaskFetchSubmitActionData, TextBlock -from microsoft_teams.common.logging import ConsoleLogger +from microsoft_teams.common import ConsoleFormatter + +# Setup logging +logging.getLogger().setLevel(logging.DEBUG) +stream_handler = logging.StreamHandler() +stream_handler.setFormatter(ConsoleFormatter()) +logging.getLogger().addHandler(stream_handler) +logger = logging.getLogger(__name__) -logger_instance = ConsoleLogger() -logger: Logger = logger_instance.create_logger("@apps/dialogs") if not os.getenv("BOT_ENDPOINT"): logger.warning("No remote endpoint detected. Using webpages for dialog will not work as expected") diff --git a/examples/graph/src/main.py b/examples/graph/src/main.py index af80a27c..3f77f364 100644 --- a/examples/graph/src/main.py +++ b/examples/graph/src/main.py @@ -10,11 +10,17 @@ from azure.core.exceptions import ClientAuthenticationError from microsoft_teams.api import MessageActivity from microsoft_teams.apps import ActivityContext, App, AppOptions, ErrorEvent, SignInEvent +from microsoft_teams.common import ConsoleFormatter from microsoft_teams.graph import get_graph_client from msgraph.generated.users.item.messages.messages_request_builder import ( # type: ignore MessagesRequestBuilder, ) +# Setup logging +logging.getLogger().setLevel(logging.DEBUG) +stream_handler = logging.StreamHandler() +stream_handler.setFormatter(ConsoleFormatter()) +logging.getLogger().addHandler(stream_handler) logger = logging.getLogger(__name__) app_options = AppOptions(default_connection_name=os.getenv("CONNECTION_NAME", "graph")) @@ -39,7 +45,7 @@ async def get_authenticated_graph_client(ctx: ActivityContext[MessageActivity]): return get_graph_client(ctx.user_token) except Exception as e: - ctx.logger.error(f"Failed to create Graph client: {e}") + logger.error(f"Failed to create Graph client: {e}") await ctx.send("🔐 Failed to create authenticated client. Please try signing in again.") await ctx.sign_in() return None @@ -90,12 +96,12 @@ async def handle_profile_command(ctx: ActivityContext[MessageActivity]): await ctx.send("❌ Could not retrieve your profile information.") except ClientAuthenticationError as e: - ctx.logger.error(f"Authentication error: {e}") + logger.error(f"Authentication error: {e}") await ctx.send("🔐 Authentication failed. Please try signing in again.") await ctx.sign_in() except Exception as e: - ctx.logger.error(f"Error getting profile: {e}") + logger.error(f"Error getting profile: {e}") await ctx.send(f"❌ Failed to get your profile: {str(e)}") @@ -138,11 +144,11 @@ async def handle_emails_command(ctx: ActivityContext[MessageActivity]): await ctx.send("📪 No recent emails found.") except ClientAuthenticationError as e: - ctx.logger.error(f"Authentication error: {e}") + logger.error(f"Authentication error: {e}") await ctx.send("🔐 Authentication failed. You may need additional permissions to read emails.") except Exception as e: - ctx.logger.error(f"Error getting emails: {e}") + logger.error(f"Error getting emails: {e}") await ctx.send(f"❌ Failed to get your emails: {str(e)}") diff --git a/examples/oauth/src/main.py b/examples/oauth/src/main.py index a9e343f2..9215f91d 100644 --- a/examples/oauth/src/main.py +++ b/examples/oauth/src/main.py @@ -4,11 +4,20 @@ """ import asyncio +import logging from microsoft_teams.api import MessageActivity from microsoft_teams.api.activities.invoke.sign_in import SignInFailureInvokeActivity from microsoft_teams.apps import ActivityContext, App, SignInEvent from microsoft_teams.apps.events.types import ErrorEvent +from microsoft_teams.common import ConsoleFormatter + +# Setup logging +logging.getLogger().setLevel(logging.DEBUG) +stream_handler = logging.StreamHandler() +stream_handler.setFormatter(ConsoleFormatter()) +logging.getLogger().addHandler(stream_handler) +logger = logging.getLogger(__name__) app = App() @@ -19,7 +28,7 @@ async def handle_message(ctx: ActivityContext[MessageActivity]): print(f"[GENERATED onMessage] Message received: {ctx.activity.text}") print(f"[GENERATED onMessage] From: {ctx.activity.from_}") - ctx.logger.info("User requested sign-in.") + logger.info("User requested sign-in.") if ctx.is_signed_in: await ctx.send("You are already signed in. Logging you out.") await ctx.sign_out() diff --git a/examples/tab/Web/src/App.tsx b/examples/tab/Web/src/App.tsx index 3d333487..41d8a3bd 100644 --- a/examples/tab/Web/src/App.tsx +++ b/examples/tab/Web/src/App.tsx @@ -2,7 +2,6 @@ import React from 'react'; import * as teamsJs from '@microsoft/teams-js'; import * as client from '@microsoft/teams.client'; import * as endpoints from '@microsoft/teams.graph-endpoints'; -import { ConsoleLogger } from '@microsoft/teams.common'; import './App.css'; @@ -17,7 +16,6 @@ export default function App() { try { // initialize the app and prompt for Graph scope consent, if not already granted const app = new client.App(clientId, { - logger: new ConsoleLogger('@examples/tab', { level: 'debug' }), msalOptions: { prewarmScopes: [ 'https://graph.microsoft.com/User.Read', @@ -28,7 +26,7 @@ export default function App() { }); await app.start(); - app.log.info('app started'); + console.info('app started'); setApp(app); } catch (err) { console.error(err); diff --git a/packages/a2aprotocol/src/microsoft_teams/a2a/__init__.py b/packages/a2aprotocol/src/microsoft_teams/a2a/__init__.py index 98d34b6f..be841c65 100644 --- a/packages/a2aprotocol/src/microsoft_teams/a2a/__init__.py +++ b/packages/a2aprotocol/src/microsoft_teams/a2a/__init__.py @@ -3,10 +3,14 @@ Licensed under the MIT License. """ +import logging + from . import chat_prompt, server from .chat_prompt import * # noqa: F403 from .server import * # noqa: F401, F403 +logging.getLogger(__name__).addHandler(logging.NullHandler()) + # Combine all exports from submodules __all__: list[str] = [] __all__.extend(chat_prompt.__all__) diff --git a/packages/a2aprotocol/src/microsoft_teams/a2a/chat_prompt/plugin.py b/packages/a2aprotocol/src/microsoft_teams/a2a/chat_prompt/plugin.py index 51aa4950..509b522f 100644 --- a/packages/a2aprotocol/src/microsoft_teams/a2a/chat_prompt/plugin.py +++ b/packages/a2aprotocol/src/microsoft_teams/a2a/chat_prompt/plugin.py @@ -3,18 +3,17 @@ Licensed under the MIT License. """ +import logging import re import uuid from dataclasses import asdict from functools import partial -from logging import Logger from typing import Any, Dict, List, Optional, Union, Unpack, cast from httpx import AsyncClient from microsoft_teams.ai import Function as ChatFunction from microsoft_teams.ai import SystemMessage from microsoft_teams.ai.plugin import BaseAIPlugin -from microsoft_teams.common.logging.console import ConsoleLogger from pydantic import BaseModel from a2a.client import ClientFactory @@ -39,6 +38,8 @@ InternalA2AClientPluginOptions, ) +logger = logging.getLogger(__name__) + class A2AClientMessageParams(BaseModel): message: str @@ -46,7 +47,6 @@ class A2AClientMessageParams(BaseModel): class A2AClientPlugin(BaseAIPlugin): - log: Logger _agent_configs: Dict[str, AgentConfig] = {} _clients: Dict[str, AgentClientInfo] = {} @@ -63,7 +63,6 @@ def __init__(self, **options: Unpack[A2AClientPluginOptions]): self._build_prompt = self.options.build_prompt self._build_message_for_agent = self.options.build_message_for_agent self._build_message_from_agent_response = self.options.build_message_from_agent_response - self.log = self.options.logger if self.options.logger else ConsoleLogger().create_logger(name="a2a:client") def on_use_plugin(self, args: A2APluginUseParams): # just store the config, defer client creation to on_build_functions @@ -102,7 +101,7 @@ async def _get_agent_card(self, key: str, config: AgentConfig) -> Optional[Agent self._clients.update({key: client_info}) return card except Exception as e: - self.log.error(f"Error creating client or fetching agent card for {key}: {e}") + logger.error(f"Error creating client or fetching agent card for {key}: {e}") return None def _default_function_metadata(self, card: AgentCard) -> FunctionMetadata: @@ -143,7 +142,7 @@ async def on_build_functions(self, functions: list[ChatFunction[Any]]) -> list[C try: agent_card = await self._get_agent_card(key, config) if not agent_card: - self.log.warning(f"Could not retrieve agent card for {key}, continuing to next agent.") + logger.warning(f"Could not retrieve agent card for {key}, continuing to next agent.") # skip if we couldn't get the agent card continue @@ -183,7 +182,7 @@ async def message_handler( if not client_info: raise ValueError(f"Client not found for agent {key}") - self.log.debug(f"Calling agent {agent_card.name} with {message.model_dump_json()}") + logger.debug(f"Calling agent {agent_card.name} with {message.model_dump_json()}") last_message: Optional[Message] = None async for event in client_info.client.send_message(message): @@ -194,7 +193,7 @@ async def message_handler( last_message = event if last_message is not None: - self.log.debug(f"Got response from {agent_card.name}") + logger.debug(f"Got response from {agent_card.name}") # use custom response builder if provided, otherwise use default metadata = BuildMessageFromAgentMetadata( card=agent_card, response=last_message, original_input=agent_message @@ -209,7 +208,7 @@ async def message_handler( ) ) except Exception as e: - self.log.error(e) + logger.error(e) raise e message_handler_with_args = partial(message_handler, config=config, agent_card=agent_card, key=key) @@ -222,9 +221,9 @@ async def message_handler( handler=message_handler_with_args, ) ) - self.log.debug(f"Added function in ChatPrompt to call {agent_card.name}") + logger.debug(f"Added function in ChatPrompt to call {agent_card.name}") except Exception as e: - self.log.info(f"Failed to build function for agent {key}: {e}") + logger.info(f"Failed to build function for agent {key}: {e}") # Continue with other agents even if one fails functions = functions + all_functions @@ -247,7 +246,7 @@ async def on_build_instructions(self, instructions: Optional[SystemMessage] = No ) ) except Exception as e: - self.log.info(f"Failed to get agent card for {key}: {e}") + logger.info(f"Failed to get agent card for {key}: {e}") # use custom build_prompt if provided, otherwise use default if self._build_prompt: diff --git a/packages/a2aprotocol/src/microsoft_teams/a2a/server/logging_middleware.py b/packages/a2aprotocol/src/microsoft_teams/a2a/server/logging_middleware.py index 8473b9ab..5bc6b2dd 100644 --- a/packages/a2aprotocol/src/microsoft_teams/a2a/server/logging_middleware.py +++ b/packages/a2aprotocol/src/microsoft_teams/a2a/server/logging_middleware.py @@ -3,18 +3,19 @@ Licensed under the MIT License. """ -from logging import Logger +import logging from starlette.middleware.base import BaseHTTPMiddleware, RequestResponseEndpoint from starlette.requests import Request from starlette.responses import Response from starlette.types import ASGIApp +logger = logging.getLogger(__name__) + class LoggingMiddleware(BaseHTTPMiddleware): - def __init__(self, app: ASGIApp, logger: Logger) -> None: + def __init__(self, app: ASGIApp) -> None: super().__init__(app) - self.logger = logger async def dispatch(self, request: Request, call_next: RequestResponseEndpoint) -> Response: log_message = f"A2A Request: {request.method} {request.url}" @@ -22,6 +23,6 @@ async def dispatch(self, request: Request, call_next: RequestResponseEndpoint) - if request.method == "POST": body = await request.body() log_message += f" Body: {body.decode('utf-8')}" - self.logger.debug(log_message) + logger.debug(log_message) response = await call_next(request) return response diff --git a/packages/a2aprotocol/src/microsoft_teams/a2a/server/plugin.py b/packages/a2aprotocol/src/microsoft_teams/a2a/server/plugin.py index 5c106bd1..2078e52b 100644 --- a/packages/a2aprotocol/src/microsoft_teams/a2a/server/plugin.py +++ b/packages/a2aprotocol/src/microsoft_teams/a2a/server/plugin.py @@ -3,14 +3,13 @@ Licensed under the MIT License. """ -from logging import Logger +import logging from typing import Annotated, Any, Awaitable, Callable, List, Optional from microsoft_teams.apps import ( DependencyMetadata, EventMetadata, HttpPlugin, - LoggerDependencyOptions, Plugin, PluginBase, ) @@ -26,10 +25,11 @@ from .custom_agent_executor import A2AMessageEvent, CustomAgentExecutor from .logging_middleware import LoggingMiddleware +logger = logging.getLogger(__name__) + @Plugin(name="a2a", version="0.3.7", description="A2A Server Plugin") class A2APlugin(PluginBase): - logger: Annotated[Logger, LoggerDependencyOptions()] http: Annotated[HttpPlugin, DependencyMetadata()] emit: Annotated[Callable[[str, A2AMessageEvent], Awaitable[None]], EventMetadata(name="custom")] @@ -68,13 +68,13 @@ async def on_init(self) -> None: self.app = a2a_app.build(agent_card_url=self.agent_card_path) # add the middleware - self.app.add_middleware(LoggingMiddleware, logger=self.logger) + self.app.add_middleware(LoggingMiddleware) for middleware_info in self._middlewares: middleware, kwargs = middleware_info self.app.add_middleware(middleware, **kwargs) - self.logger.info(f"A2A agent set up at {self.agent_card_path}") - self.logger.info(f"A2A agent listening at {self.path}") + logger.info(f"A2A agent set up at {self.agent_card_path}") + logger.info(f"A2A agent listening at {self.path}") self.http.app.mount(self.path, self.app) diff --git a/packages/ai/src/microsoft_teams/ai/__init__.py b/packages/ai/src/microsoft_teams/ai/__init__.py index b256d155..7e641d51 100644 --- a/packages/ai/src/microsoft_teams/ai/__init__.py +++ b/packages/ai/src/microsoft_teams/ai/__init__.py @@ -3,12 +3,16 @@ Licensed under the MIT License. """ +import logging + from .ai_model import AIModel from .chat_prompt import ChatPrompt, ChatSendResult from .function import Function, FunctionCall, FunctionHandler, FunctionHandlers, FunctionHandlerWithNoParams from .memory import ListMemory, Memory from .message import FunctionMessage, Message, ModelMessage, SystemMessage, UserMessage +logging.getLogger(__name__).addHandler(logging.NullHandler()) + __all__ = [ "ChatSendResult", "ChatPrompt", diff --git a/packages/api/src/microsoft_teams/api/__init__.py b/packages/api/src/microsoft_teams/api/__init__.py index 6e2fd5d5..59c0de16 100644 --- a/packages/api/src/microsoft_teams/api/__init__.py +++ b/packages/api/src/microsoft_teams/api/__init__.py @@ -3,12 +3,16 @@ Licensed under the MIT License. """ +import logging + from . import activities, auth, clients, models from .activities import * # noqa: F403 from .auth import * # noqa: F403 from .clients import * # noqa: F403 from .models import * # noqa: F403 +logging.getLogger(__name__).addHandler(logging.NullHandler()) + # Combine all exports from submodules __all__: list[str] = [] __all__.extend(activities.__all__) diff --git a/packages/apps/scripts/generate_handlers.py b/packages/apps/scripts/generate_handlers.py index e3286260..3a84f2cd 100644 --- a/packages/apps/scripts/generate_handlers.py +++ b/packages/apps/scripts/generate_handlers.py @@ -43,7 +43,6 @@ def generate_imports() -> str: """Generate import statements for the generated file.""" imports = { "from abc import ABC, abstractmethod", - "from logging import Logger", "from typing import Callable, Optional, overload", "from microsoft_teams.api import InvokeResponse", "from .activity_context import ActivityContext", @@ -113,14 +112,14 @@ def generate_method(config: ActivityConfig, config_key: str) -> str: return f''' @overload def {method_name}(self, handler: {handler_type}) -> {handler_type}: ... - + @overload def {method_name}(self) -> Callable[[{handler_type}], {handler_type}]: ... - + def {method_name}(self, handler: Optional[{handler_type}] = None) -> {union_type}: """Register a {activity_name} activity handler.""" def decorator(func: {handler_type}) -> {handler_type}: - validate_handler_type(self.logger, func, {input_class_name}, "{method_name}", "{input_class_name}") + validate_handler_type(func, {input_class_name}, "{method_name}", "{input_class_name}") config = ACTIVITY_ROUTES["{config_key}"] self.router.add_handler(config.selector, func) return func @@ -148,12 +147,6 @@ def router(self) -> ActivityRouter: """The activity router instance. Must be implemented by the concrete class.""" pass - @property - @abstractmethod - def logger(self) -> Logger: - """The logger instance used by the app.""" - pass - {methods_code}''' diff --git a/packages/apps/src/microsoft_teams/apps/__init__.py b/packages/apps/src/microsoft_teams/apps/__init__.py index 2aa32332..50586c24 100644 --- a/packages/apps/src/microsoft_teams/apps/__init__.py +++ b/packages/apps/src/microsoft_teams/apps/__init__.py @@ -3,6 +3,8 @@ Licensed under the MIT License. """ +import logging + from . import auth, contexts, events, plugins from .app import App from .auth import * # noqa: F403 @@ -14,6 +16,8 @@ from .plugins import * # noqa: F401, F403 from .routing import ActivityContext +logging.getLogger(__name__).addHandler(logging.NullHandler()) + # Combine all exports from submodules __all__: list[str] = ["App", "AppOptions", "HttpPlugin", "HttpStream", "ActivityContext"] __all__.extend(auth.__all__) diff --git a/packages/apps/src/microsoft_teams/apps/app.py b/packages/apps/src/microsoft_teams/apps/app.py index edcd554f..ef5530a1 100644 --- a/packages/apps/src/microsoft_teams/apps/app.py +++ b/packages/apps/src/microsoft_teams/apps/app.py @@ -5,8 +5,8 @@ import asyncio import importlib.metadata +import logging import os -from logging import Logger from typing import Any, Awaitable, Callable, List, Optional, TypeVar, Union, Unpack, cast, overload from dependency_injector import providers @@ -27,7 +27,7 @@ TokenCredentials, ) from microsoft_teams.cards import AdaptiveCard -from microsoft_teams.common import Client, ClientOptions, ConsoleLogger, EventEmitter, LocalStorage +from microsoft_teams.common import Client, ClientOptions, EventEmitter, LocalStorage from .app_events import EventManager from .app_oauth import OauthHandlers @@ -60,6 +60,8 @@ USER_AGENT = f"teams.py[apps]/{version}" +logger = logging.getLogger(__name__) + class App(ActivityHandlerMixin): """ @@ -71,7 +73,6 @@ class App(ActivityHandlerMixin): def __init__(self, **options: Unpack[AppOptions]): self.options = InternalAppOptions.from_typeddict(options) - self.log = self.options.logger or ConsoleLogger().create_logger("@teams/app") self.storage = self.options.storage or LocalStorage() self.http_client = Client( @@ -87,14 +88,12 @@ def __init__(self, **options: Unpack[AppOptions]): self._token_manager = TokenManager( credentials=self.credentials, - logger=self.log, ) self.container = Container() self.container.set_provider("id", providers.Object(self.id)) self.container.set_provider("credentials", providers.Object(self.credentials)) self.container.set_provider("bot_token", providers.Factory(lambda: self._get_bot_token)) - self.container.set_provider("logger", providers.Object(self.log)) self.container.set_provider("storage", providers.Object(self.storage)) self.container.set_provider(self.http_client.__class__.__name__, providers.Factory(lambda: self.http_client)) @@ -119,7 +118,7 @@ def __init__(self, **options: Unpack[AppOptions]): break if not http_plugin: - http_plugin = HttpPlugin(logger=self.log, skip_auth=self.options.skip_auth) + http_plugin = HttpPlugin(skip_auth=self.options.skip_auth) plugins.insert(0, http_plugin) self.http = cast(HttpPlugin, http_plugin) @@ -130,7 +129,6 @@ def __init__(self, **options: Unpack[AppOptions]): # initialize all event, activity, and plugin processors self.activity_processor = ActivityProcessor( self._router, - self.log, self.id, self.storage, self.options.default_connection_name, @@ -141,7 +139,7 @@ def __init__(self, **options: Unpack[AppOptions]): self.event_manager = EventManager(self._events) self.activity_processor.event_manager = self.event_manager self._plugin_processor = PluginProcessor( - self.container, self.event_manager, self.log, self._events, self.activity_processor + self.container, self.event_manager, self._events, self.activity_processor ) self.plugins = self._plugin_processor.initialize_plugins(plugins) @@ -157,7 +155,7 @@ def __init__(self, **options: Unpack[AppOptions]): self.entra_token_validator: Optional[TokenValidator] = None if self.credentials and hasattr(self.credentials, "client_id"): self.entra_token_validator = TokenValidator.for_entra( - self.credentials.client_id, self.credentials.tenant_id, logger=self.log + self.credentials.client_id, self.credentials.tenant_id ) @property @@ -170,11 +168,6 @@ def is_running(self) -> bool: """Whether the app is currently running.""" return self._running - @property - def logger(self) -> Logger: - """The logger instance used by the app.""" - return self.log - @property def events(self) -> EventEmitter[EventType]: """The event emitter instance used by the app.""" @@ -203,7 +196,7 @@ async def start(self, port: Optional[int] = None) -> None: port: Port to listen on (defaults to PORT env var or 3978) """ if self._running: - self.log.warning("App is already running") + logger.warning("App is already running") return self._port = port or int(os.getenv("PORT", "3978")) @@ -217,7 +210,7 @@ async def start(self, port: Optional[int] = None) -> None: # Set callback and start HTTP plugin async def on_http_ready() -> None: - self.log.info("Teams app started successfully") + logger.info("Teams app started successfully") assert self._port is not None, "Port must be set before emitting start event" self._events.emit("start", StartEvent(port=self._port)) self._running = True @@ -234,7 +227,7 @@ async def on_http_ready() -> None: except Exception as error: self._running = False - self.log.error(f"Failed to start app: {error}") + logger.error(f"Failed to start app: {error}") self._events.emit("error", ErrorEvent(error, context={"method": "start", "port": self._port})) raise @@ -253,14 +246,14 @@ async def on_http_stopped() -> None: await plugin.on_stop() self._running = False - self.log.info("Teams app stopped") + logger.info("Teams app stopped") self._events.emit("stop", StopEvent()) self.http.on_stopped_callback = on_http_stopped await self.http.on_stop() except Exception as error: - self.log.error(f"Failed to stop app: {error}") + logger.error(f"Failed to stop app: {error}") self._events.emit("error", ErrorEvent(error, context={"method": "stop"})) raise @@ -305,14 +298,14 @@ def _init_credentials(self) -> Optional[Credentials]: token = self.options.token managed_identity_client_id = self.options.managed_identity_client_id or os.getenv("MANAGED_IDENTITY_CLIENT_ID") - self.log.debug(f"Using CLIENT_ID: {client_id}") + logger.debug(f"Using CLIENT_ID: {client_id}") if not tenant_id: - self.log.warning("TENANT_ID is not set, assuming multi-tenant app") + logger.warning("TENANT_ID is not set, assuming multi-tenant app") else: - self.log.debug(f"Using TENANT_ID: {tenant_id} (assuming single-tenant app)") + logger.debug(f"Using TENANT_ID: {tenant_id} (assuming single-tenant app)") if client_id and client_secret: - self.log.debug("Using client secret for auth") + logger.debug("Using client secret for auth") return ClientCredentials(client_id=client_id, client_secret=client_secret, tenant_id=tenant_id) if client_id and token: @@ -320,7 +313,7 @@ def _init_credentials(self) -> Optional[Credentials]: if client_id: if managed_identity_client_id == "system": - self.log.debug("Using Federated Identity Credentials with system-assigned managed identity") + logger.debug("Using Federated Identity Credentials with system-assigned managed identity") return FederatedIdentityCredentials( client_id=client_id, managed_identity_type="system", @@ -329,7 +322,7 @@ def _init_credentials(self) -> Optional[Credentials]: ) if managed_identity_client_id and managed_identity_client_id != client_id: - self.log.debug("Using Federated Identity Credentials with user-assigned managed identity") + logger.debug("Using Federated Identity Credentials with user-assigned managed identity") return FederatedIdentityCredentials( client_id=client_id, managed_identity_type="user", @@ -337,7 +330,7 @@ def _init_credentials(self) -> Optional[Credentials]: tenant_id=tenant_id, ) - self.log.debug("Using user-assigned managed identity (direct)") + logger.debug("Using user-assigned managed identity (direct)") mi_client_id = managed_identity_client_id or client_id return ManagedIdentityCredentials( client_id=mi_client_id, @@ -410,7 +403,7 @@ def decorator(func: F) -> F: # Validate the detected type against registered events or custom event if not is_registered_event(detected_type): - self.logger.info(f"Event type '{detected_type}' is not a registered type.") + logger.info(f"Event type '{detected_type}' is not a registered type.") detected_type = cast(EventType, detected_type) # add it to the event emitter @@ -474,17 +467,17 @@ async def post_to_chat(ctx: FunctionContext[Any]): def decorator(func: FCtx) -> FCtx: endpoint_name = name_or_func if isinstance(name_or_func, str) else func.__name__.replace("_", "-") - self.logger.debug("Generated endpoint name for function '%s': %s", func.__name__, endpoint_name) + logger.debug("Generated endpoint name for function '%s': %s", func.__name__, endpoint_name) async def endpoint(req: Request): - middleware = remote_function_jwt_validation(self.log, self.entra_token_validator) + middleware = remote_function_jwt_validation(self.entra_token_validator) async def call_next(r: Request) -> Any: ctx = FunctionContext( id=self.id, api=self.api, http=self.http, - log=self.log, + log=logger, data=await r.json(), **r.state.context.__dict__, ) diff --git a/packages/apps/src/microsoft_teams/apps/app_oauth.py b/packages/apps/src/microsoft_teams/apps/app_oauth.py index 535eadf3..e6417478 100644 --- a/packages/apps/src/microsoft_teams/apps/app_oauth.py +++ b/packages/apps/src/microsoft_teams/apps/app_oauth.py @@ -3,6 +3,7 @@ Licensed under the MIT License. """ +import logging from typing import Optional, Union from httpx import HTTPStatusError @@ -22,6 +23,8 @@ from .events import ErrorEvent, EventType, SignInEvent from .routing import ActivityContext +logger = logging.getLogger(__name__) + class OauthHandlers: def __init__(self, default_connection_name: str, event_emitter: EventEmitter[EventType]) -> None: @@ -34,13 +37,12 @@ async def sign_in_token_exchange( """ Decorator to register a function that handles the sign-in token exchange. """ - log = ctx.logger activity = ctx.activity api = ctx.api next_handler = ctx.next try: if activity.value.connection_name != self.default_connection_name: - log.warning( + logger.warning( f"Sign-in token exchange invoked with connection name '{activity.value.connection_name}', " f"but default connection name is '{self.default_connection_name}'. " f"Token verification will likely fail." @@ -63,18 +65,18 @@ async def sign_in_token_exchange( if isinstance(e, HTTPStatusError): status = e.response.status_code if status not in (404, 400, 412): - log.error( + logger.error( f"Error exchanging token for user {activity.from_.id} in " f"conversation {activity.conversation.id}: {e}" ) self.event_emitter.emit("error", ErrorEvent(error=e, context={"activity": activity})) return InvokeResponse(status=status or 500) - log.info( + logger.info( f"Unable to exchange token for user {activity.from_.id} in " f"conversation {activity.conversation.id}: {e}" ) else: - log.error( + logger.error( f"Unable to exchange token for user {activity.from_.id} in " f"conversation {activity.conversation.id}: {e}" ) @@ -147,19 +149,18 @@ async def sign_in_verify_state( """ Decorator to register a function that handles the sign-in token exchange. """ - log = ctx.logger activity = ctx.activity api = ctx.api next_handler = ctx.next try: if not activity.value.state: - log.warning( + logger.warning( f"Auth state not present for conversation id '{activity.conversation.id}' " f"and user id '{activity.from_.id}'. " ) return InvokeResponse(status=404) - log.debug( + logger.debug( f"Verifying sign-in state for user {activity.from_.id} in conversation" f"{activity.conversation.id} with state {activity.value.state}" ) @@ -174,12 +175,12 @@ async def sign_in_verify_state( ) ) self.event_emitter.emit("sign_in", SignInEvent(activity_ctx=ctx, token_response=token)) - log.debug( + logger.debug( f"Sign-in state verified for user {activity.from_.id} in conversation {activity.conversation.id}" ) return None except Exception as e: - log.error( + logger.error( f"Error verifying sign-in state for user {activity.from_.id} in conversation" f"{activity.conversation.id}: {e}" ) diff --git a/packages/apps/src/microsoft_teams/apps/app_plugins.py b/packages/apps/src/microsoft_teams/apps/app_plugins.py index 0f3486b6..f61da1cc 100644 --- a/packages/apps/src/microsoft_teams/apps/app_plugins.py +++ b/packages/apps/src/microsoft_teams/apps/app_plugins.py @@ -3,7 +3,7 @@ Licensed under the MIT License. """ -from logging import Logger +import logging from typing import Any, List, Optional, cast, get_type_hints from dependency_injector import providers @@ -24,6 +24,8 @@ get_metadata, ) +logger = logging.getLogger(__name__) + class PluginProcessor: """ @@ -37,14 +39,12 @@ def __init__( self, container: Container, event_manager: EventManager, - logger: Logger, event_emitter: EventEmitter[EventType], activity_processor: ActivityProcessor, ): self.plugins: List[PluginBase] = [] self.container = container self.event_manager = event_manager - self.logger = logger self.event_emitter = event_emitter self.activity_processor = activity_processor @@ -56,7 +56,7 @@ def initialize_plugins(self, plugins: List[PluginBase]) -> List[PluginBase]: name = metadata.name class_name = plugin.__class__.__name__ - self.logger.debug(f"Initializing the plugin {class_name}") + logger.debug(f"Initializing the plugin {class_name}") if not name: raise ValueError(f"Plugin {class_name} missing name in metadata") @@ -70,7 +70,7 @@ def initialize_plugins(self, plugins: List[PluginBase]) -> List[PluginBase]: if class_name != name: self.container.set_provider(class_name, providers.Object(plugin)) - self.logger.debug("Successfully initialized all plugins") + logger.debug("Successfully initialized all plugins") return self.plugins def get_plugin(self, name: str) -> Optional[PluginBase]: @@ -90,7 +90,7 @@ def inject(self, plugin: PluginBase) -> None: metadata = getattr(annotated_type, "__metadata__", ()) for meta in metadata: - self.logger.debug(f"Initializing the dependency {field_name} for {plugin.__class__.__name__}") + logger.debug(f"Initializing the dependency {field_name} for {plugin.__class__.__name__}") if isinstance(meta, EventMetadata): self._inject_event(meta, plugin, field_name) @@ -100,7 +100,7 @@ def inject(self, plugin: PluginBase) -> None: def _inject_event(self, meta: EventMetadata, plugin: PluginBase, field_name: str) -> None: """Injects event handler into the plugin based on metadata info.""" if meta.name == "error": - self.logger.debug("Injecting the error event") + logger.debug("Injecting the error event") async def error_handler(event: PluginErrorEvent) -> None: activity = cast(Activity, event.activity) @@ -110,7 +110,7 @@ async def error_handler(event: PluginErrorEvent) -> None: setattr(plugin, field_name, error_handler) elif meta.name == "activity": - self.logger.debug("Injecting the activity event") + logger.debug("Injecting the activity event") async def activity_handler(event: PluginActivityEvent) -> InvokeResponse[Any]: sender = cast(Sender, plugin) @@ -120,13 +120,11 @@ async def activity_handler(event: PluginActivityEvent) -> InvokeResponse[Any]: setattr(plugin, field_name, activity_handler) elif meta.name == "custom": - self.logger.debug("Injecting the custom event") + logger.debug("Injecting the custom event") async def custom_handler(name: str, event: Any) -> None: if is_registered_event(name): - self.logger.warning( - f"event {name} is reserved by core app-events but an plugin is trying to emit it" - ) + logger.warning(f"event {name} is reserved by core app-events but an plugin is trying to emit it") return self.event_emitter.emit(name, event) @@ -149,8 +147,5 @@ def _inject_dependency(self, meta: DependencyMetadata, plugin: PluginBase, type_ else: # Calling the provider to get the actual instance dependency = dependency() - if field_name == "logger": - logger_dependency = cast(Logger, dependency) - dependency = logger_dependency.getChild(plugin.__class__.__name__) setattr(plugin, field_name, dependency) - self.logger.debug(f"Successfully injected the dependency {field_name} into {plugin.__class__.__name__}") + logger.debug(f"Successfully injected the dependency {field_name} into {plugin.__class__.__name__}") diff --git a/packages/apps/src/microsoft_teams/apps/app_process.py b/packages/apps/src/microsoft_teams/apps/app_process.py index 21d2df51..d679f854 100644 --- a/packages/apps/src/microsoft_teams/apps/app_process.py +++ b/packages/apps/src/microsoft_teams/apps/app_process.py @@ -3,7 +3,7 @@ Licensed under the MIT License. """ -from logging import Logger +import logging from typing import TYPE_CHECKING, Any, Callable, Dict, List, Optional, Union, cast from microsoft_teams.api import ( @@ -30,6 +30,8 @@ from .token_manager import TokenManager from .utils import extract_tenant_id +logger = logging.getLogger(__name__) + class ActivityProcessor: """Provides activity processing functionality with middleware chain support.""" @@ -37,7 +39,6 @@ class ActivityProcessor: def __init__( self, router: ActivityRouter, - logger: Logger, id: Optional[str], storage: Union[Storage[str, Any], LocalStorage[Any]], default_connection_name: str, @@ -46,7 +47,6 @@ def __init__( api_client_settings: Optional[ApiClientSettings], ) -> None: self.router = router - self.logger = logger self.id = id self.storage = storage self.default_connection_name = default_connection_name @@ -106,7 +106,7 @@ async def _build_context( is_signed_in = True except Exception: # User token not available - self.logger.debug("No user token available") + logger.debug("No user token available") pass tenant_id = extract_tenant_id(activity) @@ -114,7 +114,6 @@ async def _build_context( activityCtx = ActivityContext( activity, self.id or "", - self.logger, self.storage, api_client, user_token, @@ -136,7 +135,7 @@ async def updated_send( if not self.event_manager: raise ValueError("EventManager was not initialized properly") - self.logger.debug("Calling on_activity_sent for plugins") + logger.debug("Calling on_activity_sent for plugins") ref = conversation_ref or activityCtx.conversation_ref await self.event_manager.on_activity_sent( @@ -174,7 +173,7 @@ async def process_activity( ) -> InvokeResponse[Any]: activityCtx = await self._build_context(event.activity, event.token, plugins, sender) - self.logger.debug(f"Received activity: {activityCtx.activity}") + logger.debug(f"Received activity: {activityCtx.activity}") # Get registered handlers for this activity type handlers = self.router.select_handlers(activityCtx.activity) @@ -229,7 +228,7 @@ async def route(ctx: ActivityContext[ActivityBase]) -> Optional[Any]: await self.event_manager.on_error(ErrorEvent(error=error, activity=event.activity, sender=sender), plugins) raise error - self.logger.debug("Completed processing activity") + logger.debug("Completed processing activity") return response diff --git a/packages/apps/src/microsoft_teams/apps/auth/jwt_middleware.py b/packages/apps/src/microsoft_teams/apps/auth/jwt_middleware.py index 026f29fb..e56a8a14 100644 --- a/packages/apps/src/microsoft_teams/apps/auth/jwt_middleware.py +++ b/packages/apps/src/microsoft_teams/apps/auth/jwt_middleware.py @@ -3,7 +3,7 @@ Licensed under the MIT License. """ -from logging import Logger +import logging from typing import Awaitable, Callable import jwt @@ -12,10 +12,11 @@ from .token_validator import TokenValidator +logger = logging.getLogger(__name__) + def create_jwt_validation_middleware( app_id: str, - logger: Logger, paths: list[str], ): """ @@ -23,14 +24,13 @@ def create_jwt_validation_middleware( Args: app_id: Bot's Microsoft App ID for audience validation - logger: Logger instance paths: List of paths to validate Returns: Middleware function that can be added to FastAPI app """ # Create service token validator - token_validator = TokenValidator.for_service(app_id, logger) + token_validator = TokenValidator.for_service(app_id) async def middleware(request: Request, call_next: Callable[[Request], Awaitable[Response]]) -> Response: """JWT validation middleware function.""" diff --git a/packages/apps/src/microsoft_teams/apps/auth/remote_function_jwt_middleware.py b/packages/apps/src/microsoft_teams/apps/auth/remote_function_jwt_middleware.py index 5e1b87aa..920a488e 100644 --- a/packages/apps/src/microsoft_teams/apps/auth/remote_function_jwt_middleware.py +++ b/packages/apps/src/microsoft_teams/apps/auth/remote_function_jwt_middleware.py @@ -3,7 +3,7 @@ Licensed under the MIT License. """ -from logging import Logger +import logging from typing import Any, Awaitable, Callable, Dict, List, Optional from fastapi import HTTPException, Request, Response @@ -11,8 +11,10 @@ from ..contexts import ClientContext from .token_validator import TokenValidator +logger = logging.getLogger(__name__) -def require_fields(fields: Dict[str, Optional[Any]], context: str, logger: Logger) -> None: + +def require_fields(fields: Dict[str, Optional[Any]], context: str) -> None: missing: List[str] = [name for name, value in fields.items() if not value] if missing: message = f"Missing or invalid fields in {context}: {', '.join(missing)}" @@ -20,12 +22,11 @@ def require_fields(fields: Dict[str, Optional[Any]], context: str, logger: Logge raise HTTPException(status_code=401, detail=message) -def remote_function_jwt_validation(logger: Logger, entra_token_validator: Optional[TokenValidator]): +def remote_function_jwt_validation(entra_token_validator: Optional[TokenValidator]): """ Middleware to validate JWT for remote function calls. Args: entra_token_validator: TokenValidator instance for Entra ID tokens - logger: Logger instance Returns: Middleware function that can be added to FastAPI app @@ -45,7 +46,6 @@ async def middleware(request: Request, call_next: Callable[[Request], Awaitable[ "Authorization (Bearer token)": auth_token, }, "header", - logger, ) if not entra_token_validator: @@ -58,7 +58,6 @@ async def middleware(request: Request, call_next: Callable[[Request], Awaitable[ require_fields( {"oid": token_payload.get("oid"), "tid": token_payload.get("tid"), "name": token_payload.get("name")}, "token payload", - logger, ) # Build context diff --git a/packages/apps/src/microsoft_teams/apps/auth/token_validator.py b/packages/apps/src/microsoft_teams/apps/auth/token_validator.py index da70a895..0a0f1ea5 100644 --- a/packages/apps/src/microsoft_teams/apps/auth/token_validator.py +++ b/packages/apps/src/microsoft_teams/apps/auth/token_validator.py @@ -3,15 +3,16 @@ Licensed under the MIT License. """ +import logging from dataclasses import dataclass -from logging import Logger from typing import Any, Dict, List, Optional import jwt -from microsoft_teams.common.logging import ConsoleLogger JWT_LEEWAY_SECONDS = 300 # Allowable clock skew when validating JWTs +logger = logging.getLogger(__name__) + @dataclass class JwtValidationOptions: @@ -36,29 +37,25 @@ class TokenValidator: JWT token validator using PyJWKClient for simplified validation. """ - def __init__(self, jwt_validation_options: JwtValidationOptions, logger: Optional[Logger] = None): + def __init__(self, jwt_validation_options: JwtValidationOptions): """ Initialize the token validator. Args: jwt_validation_options: Configuration for JWT validation """ - self.logger = logger or ConsoleLogger().create_logger("@teams/token-validator") self.options = jwt_validation_options # ----- Factory constructors ----- @classmethod - def for_service( - cls, app_id: str, logger: Optional[Logger] = None, service_url: Optional[str] = None - ) -> "TokenValidator": + def for_service(cls, app_id: str, service_url: Optional[str] = None) -> "TokenValidator": """Create a validator for Bot Framework service tokens. Reference: https://learn.microsoft.com/en-us/azure/bot-service/rest-api/bot-framework-rest-connector-authentication Args: app_id: The bot's Microsoft App ID (used for audience validation) - service_url: Optional service URL to validate against token claims - logger: Optional logger instance""" + service_url: Optional service URL to validate against token claims""" options = JwtValidationOptions( valid_issuers=["https://api.botframework.com"], @@ -66,19 +63,16 @@ def for_service( jwks_uri="https://login.botframework.com/v1/.well-known/keys", service_url=service_url, ) - return cls(options, logger) + return cls(options) @classmethod - def for_entra( - cls, app_id: str, tenant_id: Optional[str], scope: Optional[str] = None, logger: Optional[Logger] = None - ) -> "TokenValidator": + def for_entra(cls, app_id: str, tenant_id: Optional[str], scope: Optional[str] = None) -> "TokenValidator": """Create a validator for Entra ID tokens. Args: app_id: The app's Microsoft App ID (used for audience validation) tenant_id: The Azure AD tenant ID scope: Optional scope that must be present in the token - logger: Optional logger instance """ @@ -92,7 +86,7 @@ def for_entra( jwks_uri=f"https://login.microsoftonline.com/{tenant_id}/discovery/v2.0/keys", scope=scope, ) - return cls(options, logger) + return cls(options) async def validate_token( self, raw_token: str, service_url: Optional[str] = None, scope: Optional[str] = None @@ -112,7 +106,7 @@ async def validate_token( jwt.InvalidTokenError: When token validation fails """ if not raw_token: - self.logger.error("No token provided") + logger.error("No token provided") raise jwt.InvalidTokenError("No token provided") try: @@ -146,11 +140,11 @@ async def validate_token( if required_scope: self._validate_scope(payload, required_scope) - self.logger.debug("Token validation successful") + logger.debug("Token validation successful") return payload except jwt.InvalidTokenError as e: - self.logger.error(f"Token validation failed: {e}") + logger.error(f"Token validation failed: {e}") raise def _validate_service_url(self, payload: Dict[str, Any], expected_service_url: str) -> None: @@ -163,7 +157,7 @@ def _validate_service_url(self, payload: Dict[str, Any], expected_service_url: s token_service_url = payload.get("serviceurl") if not token_service_url: - self.logger.error("Token missing serviceurl claim") + logger.error("Token missing serviceurl claim") raise jwt.InvalidTokenError("Token missing serviceurl claim") # Normalize URLs (remove trailing slashes) @@ -171,9 +165,7 @@ def _validate_service_url(self, payload: Dict[str, Any], expected_service_url: s normalized_expected_url = expected_service_url.rstrip("/") if normalized_token_url != normalized_expected_url: - self.logger.error( - f"Service URL mismatch. Token: {normalized_token_url}, Expected: {normalized_expected_url}" - ) + logger.error(f"Service URL mismatch. Token: {normalized_token_url}, Expected: {normalized_expected_url}") raise jwt.InvalidTokenError( f"Service URL mismatch. Token: {normalized_token_url}, Expected: {normalized_expected_url}" ) @@ -187,5 +179,5 @@ def _validate_scope(self, payload: Dict[str, Any], required_scope: str) -> None: """ scopes = payload.get("scp", "") or "" if required_scope not in scopes: - self.logger.error(f"Token missing required scope: {required_scope}") + logger.error(f"Token missing required scope: {required_scope}") raise jwt.InvalidTokenError(f"Token missing required scope: {required_scope}") diff --git a/packages/apps/src/microsoft_teams/apps/contexts/function_context.py b/packages/apps/src/microsoft_teams/apps/contexts/function_context.py index 8766ba2e..414f0e50 100644 --- a/packages/apps/src/microsoft_teams/apps/contexts/function_context.py +++ b/packages/apps/src/microsoft_teams/apps/contexts/function_context.py @@ -5,6 +5,8 @@ from __future__ import annotations +import logging +import warnings from dataclasses import dataclass from logging import Logger from typing import Generic, Optional, TypeVar @@ -26,6 +28,8 @@ T = TypeVar("T") +logger = logging.getLogger(__name__) + @dataclass(kw_only=True) class FunctionContext(ClientContext, Generic[T]): @@ -46,11 +50,27 @@ class FunctionContext(ClientContext, Generic[T]): """The HTTP plugin instance for sending messages.""" log: Logger - """The app logger instance.""" + """ + The app logger instance. + + DEPRECATED: + This method of setting the logger is deprecated and will be removed in version 2.0.0 GA. + Please update your imports to use the standard Python logging library instead. + """ data: T """The function payload.""" + def __getattribute__(self, name: str) -> object: + if name == "log": + warnings.warn( + "FunctionContext.log is deprecated and will be removed in version 2.0.0 GA. " + "Use standard Python logging (logging.getLogger(__name__)) instead.", + DeprecationWarning, + stacklevel=2, + ) + return super().__getattribute__(name) + async def send(self, activity: str | ActivityParams | AdaptiveCard) -> Optional[SentActivity]: """ Send an activity to the current conversation. @@ -63,7 +83,7 @@ async def send(self, activity: str | ActivityParams | AdaptiveCard) -> Optional[ conversation_id = await self._resolve_conversation_id(activity) if not conversation_id: - self.log.warning("Cannot send activity: conversation ID could not be resolved") + logger.warning("Cannot send activity: conversation ID could not be resolved") return None conversation_ref = ConversationReference( @@ -107,12 +127,12 @@ async def _resolve_conversation_id(self, activity: str | ActivityParams | Adapti self._resolved_conversation_id, self.user_id ) if not member: - self.log.warning( + logger.warning( f"User {self.user_id} is not a member of conversation {self._resolved_conversation_id}" ) self._resolved_conversation_id = None except Exception as e: - self.log.error(f"Failed to get conversation member: {e}") + logger.error(f"Failed to get conversation member: {e}") self._resolved_conversation_id = None else: @@ -129,7 +149,7 @@ async def _resolve_conversation_id(self, activity: str | ActivityParams | Adapti conversation = await self.api.conversations.create(conversation_params) self._resolved_conversation_id = conversation.id except Exception as e: - self.log.error(f"Failed to create conversation: {e}") + logger.error(f"Failed to create conversation: {e}") self._resolved_conversation_id = None return self._resolved_conversation_id diff --git a/packages/apps/src/microsoft_teams/apps/http_plugin.py b/packages/apps/src/microsoft_teams/apps/http_plugin.py index a0be6501..c4accc9e 100644 --- a/packages/apps/src/microsoft_teams/apps/http_plugin.py +++ b/packages/apps/src/microsoft_teams/apps/http_plugin.py @@ -5,8 +5,8 @@ import importlib.metadata import inspect +import logging from contextlib import AsyncExitStack, asynccontextmanager -from logging import Logger from pathlib import Path from types import SimpleNamespace from typing import ( @@ -39,7 +39,7 @@ TokenProtocol, ) from microsoft_teams.apps.http_stream import HttpStream -from microsoft_teams.common import Client, ClientOptions, ConsoleLogger, Token +from microsoft_teams.common import Client, ClientOptions, Token from pydantic import BaseModel, ValidationError from starlette.applications import Starlette from starlette.types import Lifespan @@ -49,7 +49,6 @@ from .plugins import ( DependencyMetadata, EventMetadata, - LoggerDependencyOptions, PluginActivityResponseEvent, PluginStartEvent, Sender, @@ -59,11 +58,12 @@ version = importlib.metadata.version("microsoft-teams-apps") +logger = logging.getLogger(__name__) + class HttpPluginOptions(TypedDict, total=False): """Options for configuring the HTTP plugin.""" - logger: Logger skip_auth: bool server_factory: Callable[[FastAPI], uvicorn.Server] @@ -74,7 +74,6 @@ class HttpPlugin(Sender): Basic HTTP plugin that provides a FastAPI server for Teams activities. """ - logger: Annotated[Logger, LoggerDependencyOptions()] credentials: Annotated[Optional[Credentials], DependencyMetadata(optional=True)] on_error_event: Annotated[Callable[[ErrorEvent], None], EventMetadata(name="error")] @@ -89,7 +88,6 @@ class HttpPlugin(Sender): def __init__(self, **options: Unpack[HttpPluginOptions]): """ Args: - logger: Optional logger. skip_auth: Whether to skip JWT validation. server_factory: Optional function that takes an ASGI app and returns a configured `uvicorn.Server`. @@ -103,7 +101,6 @@ def custom_server_factory(app: FastAPI) -> uvicorn.Server: ``` """ super().__init__() - self.logger = options.get("logger") or ConsoleLogger().create_logger("@teams/http-plugin") self._port: Optional[int] = None self._skip_auth: bool = options.get("skip_auth", False) self._server: Optional[uvicorn.Server] = None @@ -114,12 +111,12 @@ def custom_server_factory(app: FastAPI) -> uvicorn.Server: @asynccontextmanager async def default_lifespan(_app: Starlette) -> AsyncGenerator[None, None]: # Startup - self.logger.info(f"listening on port {self._port} 🚀") + logger.info(f"listening on port {self._port} 🚀") if self._on_ready_callback: await self._on_ready_callback() yield # Shutdown - self.logger.info("Server shutting down") + logger.info("Server shutting down") if self._on_stopped_callback: await self._on_stopped_callback() @@ -183,9 +180,7 @@ async def on_init(self) -> None: # Add JWT validation middleware app_id = getattr(self.credentials, "client_id", None) if app_id and not self._skip_auth: - jwt_middleware = create_jwt_validation_middleware( - app_id=app_id, logger=self.logger, paths=["/api/messages"] - ) + jwt_middleware = create_jwt_validation_middleware(app_id=app_id, paths=["/api/messages"]) self.app.middleware("http")(jwt_middleware) async def on_start(self, event: PluginStartEvent) -> None: @@ -194,7 +189,7 @@ async def on_start(self, event: PluginStartEvent) -> None: try: if self._server and self._server.config.port != self._port: - self.logger.warning( + logger.warning( "Using port configured by server factory: %d, but plugin start event has port %d.", self._server.config.port, self._port, @@ -204,23 +199,23 @@ async def on_start(self, event: PluginStartEvent) -> None: config = uvicorn.Config(app=self.app, host="0.0.0.0", port=self._port, log_level="info") self._server = uvicorn.Server(config) - self.logger.info("Starting HTTP server on port %d", self._port) + logger.info("Starting HTTP server on port %d", self._port) # The lifespan handler will call the callback when the server is ready await self._server.serve() except OSError as error: # Handle port in use, permission errors, etc. - self.logger.error("Server startup failed: %s", error) + logger.error("Server startup failed: %s", error) raise except Exception as error: - self.logger.error("Failed to start server: %s", error) + logger.error("Failed to start server: %s", error) raise async def on_stop(self) -> None: """Stop the HTTP server.""" if self._server: - self.logger.info("Stopping HTTP server") + logger.info("Stopping HTTP server") self._server.should_exit = True async def on_activity_response(self, event: PluginActivityResponseEvent) -> None: @@ -235,7 +230,7 @@ async def on_activity_response(self, event: PluginActivityResponseEvent) -> None response_data: The response data to send back plugin: The plugin that sent the response """ - self.logger.debug(f"Completing activity response for {event.activity.id}") + logger.debug(f"Completing activity response for {event.activity.id}") async def send(self, activity: ActivityParams, ref: ConversationReference) -> SentActivity: api = ApiClient(service_url=ref.service_url, options=self.client.clone(ClientOptions(token=self.bot_token))) @@ -279,7 +274,7 @@ async def _process_activity( result = self.on_activity_event(event) except Exception as error: # Log with full traceback - self.logger.exception(str(error)) + logger.exception(str(error)) result = InvokeResponse(status=500) return result @@ -317,15 +312,15 @@ async def _handle_activity_request(self, request: Request) -> Any: activity_type = body.get("type", "unknown") activity_id = body.get("id", "unknown") - self.logger.debug(f"Received activity: {activity_type} (ID: {activity_id})") + logger.debug(f"Received activity: {activity_type} (ID: {activity_id})") try: activity = ActivityTypeAdapter.validate_python(body) except ValidationError as e: - self.logger.error(e.errors()) + logger.error(e.errors()) raise - self.logger.debug(f"Processing activity {activity_id} via handler...") + logger.debug(f"Processing activity {activity_id} via handler...") return await self._process_activity(activity, activity_id, token) def _handle_activity_response(self, response: Response, result: Any) -> Union[Response, Dict[str, object]]: @@ -358,9 +353,9 @@ def _handle_activity_response(self, response: Response, result: Any) -> Union[Re response.status_code = status_code if body is not None: - self.logger.debug(f"Returning body {body}") + logger.debug(f"Returning body {body}") return body - self.logger.debug("Returning empty body") + logger.debug("Returning empty body") return response async def on_activity_request(self, request: Request, response: Response) -> Any: @@ -385,7 +380,7 @@ def create_stream(self, ref: ConversationReference) -> StreamerProtocol: api = ApiClient(ref.service_url, self.client.clone(ClientOptions(token=self.bot_token))) - return HttpStream(api, ref, self.logger) + return HttpStream(api, ref) def mount(self, name: str, dir_path: Path | str, page_path: Optional[str] = None) -> None: """ diff --git a/packages/apps/src/microsoft_teams/apps/http_stream.py b/packages/apps/src/microsoft_teams/apps/http_stream.py index 47383b6c..645025c8 100644 --- a/packages/apps/src/microsoft_teams/apps/http_stream.py +++ b/packages/apps/src/microsoft_teams/apps/http_stream.py @@ -4,8 +4,8 @@ """ import asyncio +import logging from collections import deque -from logging import Logger from typing import Awaitable, Callable, List, Optional, Union from microsoft_teams.api import ( @@ -18,11 +18,13 @@ SentActivity, TypingActivityInput, ) -from microsoft_teams.common import ConsoleLogger, EventEmitter +from microsoft_teams.common import EventEmitter from .plugins.streamer import StreamerEvent, StreamerProtocol from .utils import RetryOptions, retry +logger = logging.getLogger(__name__) + class HttpStream(StreamerProtocol): """ @@ -40,21 +42,17 @@ class HttpStream(StreamerProtocol): The delays between flushes is to ensure we dont hit API rate limits with Microsoft Teams. """ - def __init__(self, client: ApiClient, ref: ConversationReference, logger: Optional[Logger] = None): + def __init__(self, client: ApiClient, ref: ConversationReference): """ Initialize a new HttpStream instance. Args: client (ApiClient): The API client used to send activities to Microsoft Teams. ref (ConversationReference): Reference to the Teams conversation. - logger (Optional[Logger]): Custom logger instance for debugging and monitoring.. """ super().__init__() self._client = client self._ref = ref - self._logger = ( - logger.getChild("@teams/http-stream") if logger else ConsoleLogger().create_logger("@teams/http-stream") - ) self._events = EventEmitter[StreamerEvent]() self._result: Optional[SentActivity] = None @@ -139,21 +137,21 @@ async def _poll(): async def close(self) -> Optional[SentActivity]: # wait for lock to be free if self._result is not None: - self._logger.debug("stream already closed with result") + logger.debug("stream already closed with result") return self._result if self._index == 1 and not self._queue and not self._lock.locked(): - self._logger.debug("stream has no content to send, returning None") + logger.debug("stream has no content to send, returning None") return None # Wait until _id is set and queue is empty result = await self._wait_for_id_and_queue() if not result: - self._logger.warning("Timeout while waiting for _id to be set and queue to be empty, cannot close stream") + logger.warning("Timeout while waiting for _id to be set and queue to be empty, cannot close stream") return None if self._text == "" and self._attachments == []: - self._logger.warning("no text or attachments to send, cannot close stream") + logger.warning("no text or attachments to send, cannot close stream") return None # Build final message @@ -161,7 +159,7 @@ async def close(self) -> Optional[SentActivity]: activity = MessageActivityInput(text=self._text).with_id(self._id).with_channel_data(self._channel_data) activity.add_attachments(*self._attachments).add_entities(*self._entities).add_stream_final() - res = await retry(lambda: self._send(activity), options=RetryOptions(logger=self._logger)) + res = await retry(lambda: self._send(activity), options=RetryOptions()) # Emit close event self._events.emit("close", res) @@ -169,7 +167,7 @@ async def close(self) -> Optional[SentActivity]: # Reset state self._reset_state() self._result = res - self._logger.debug("stream closed with result: %s", res) + logger.debug("stream closed with result: %s", res) return res @@ -215,7 +213,7 @@ async def _flush(self) -> None: i += 1 if i == 0: - self._logger.debug("No activities to flush") + logger.debug("No activities to flush") return # Send informative updates immediately @@ -252,7 +250,7 @@ async def _send_activity(self, to_send: TypingActivityInput): res = await retry( lambda: self._send(to_send), - options=RetryOptions(logger=self._logger, max_delay=4.0, jitter_type="none", max_attempts=8), + options=RetryOptions(max_delay=4.0, jitter_type="none", max_attempts=8), ) self._events.emit("chunk", res) self._index += 1 diff --git a/packages/apps/src/microsoft_teams/apps/options.py b/packages/apps/src/microsoft_teams/apps/options.py index 6bd5846c..9bd6ff55 100644 --- a/packages/apps/src/microsoft_teams/apps/options.py +++ b/packages/apps/src/microsoft_teams/apps/options.py @@ -3,6 +3,7 @@ Licensed under the MIT License. """ +import warnings from dataclasses import dataclass, field from logging import Logger from typing import Any, Awaitable, Callable, List, Optional, TypedDict, Union, cast @@ -108,6 +109,13 @@ def from_typeddict(cls, options: AppOptions) -> "InternalAppOptions": InternalAppOptions with proper defaults and non-nullable required fields """ kwargs: dict[str, Any] = {k: v for k, v in options.items() if v is not None} + if "logger" in kwargs: + warnings.warn( + "The 'logger' option is deprecated and will be removed in version 2.0.0 GA. " + "Use standard Python logging (logging.getLogger(__name__)) instead.", + DeprecationWarning, + stacklevel=3, + ) return cls(**kwargs) diff --git a/packages/apps/src/microsoft_teams/apps/plugins/metadata.py b/packages/apps/src/microsoft_teams/apps/plugins/metadata.py index 98b34a9f..bc0c752c 100644 --- a/packages/apps/src/microsoft_teams/apps/plugins/metadata.py +++ b/packages/apps/src/microsoft_teams/apps/plugins/metadata.py @@ -101,6 +101,11 @@ class BotTokenDependencyOptions(DependencyMetadata): @dataclass class LoggerDependencyOptions(DependencyMetadata): + """ + DEPRECATED: This dataclass is deprecated and will be removed in version 2.0.0 GA. + please update your imports to use the standard Python logging library instead. + """ + name = "logger" optional = False diff --git a/packages/apps/src/microsoft_teams/apps/routing/activity_context.py b/packages/apps/src/microsoft_teams/apps/routing/activity_context.py index ce6de9bf..086aa274 100644 --- a/packages/apps/src/microsoft_teams/apps/routing/activity_context.py +++ b/packages/apps/src/microsoft_teams/apps/routing/activity_context.py @@ -5,8 +5,8 @@ import base64 import json +import logging from dataclasses import dataclass -from logging import Logger from typing import TYPE_CHECKING, Any, Awaitable, Callable, Generic, Optional, TypeVar, cast from microsoft_teams.api import ( @@ -45,6 +45,8 @@ SendCallable = Callable[[str | ActivityParams | AdaptiveCard], Awaitable[SentActivity]] +logger = logging.getLogger(__name__) + def _get_graph_client(token: Token): """Lazy import and call get_graph_client when needed.""" @@ -87,7 +89,6 @@ def __init__( self, activity: T, app_id: str, - logger: Logger, storage: Storage[str, Any], api: ApiClient, user_token: Optional[str], diff --git a/packages/apps/src/microsoft_teams/apps/routing/activity_handlers.py b/packages/apps/src/microsoft_teams/apps/routing/activity_handlers.py index 280ff949..d44cc87d 100644 --- a/packages/apps/src/microsoft_teams/apps/routing/activity_handlers.py +++ b/packages/apps/src/microsoft_teams/apps/routing/activity_handlers.py @@ -4,7 +4,6 @@ """ from abc import ABC, abstractmethod -from logging import Logger from typing import Awaitable, Callable, Optional, Pattern, Union, overload from microsoft_teams.api import ( @@ -27,12 +26,6 @@ def router(self) -> ActivityRouter: """The activity router instance. Must be implemented by the concrete class.""" pass - @property - @abstractmethod - def logger(self) -> Logger: - """The logger instance used by the app.""" - pass - @overload def on_message_pattern( self, pattern: str | Pattern[str] @@ -102,7 +95,7 @@ def on_message_pattern( def decorator( func: Callable[[ActivityContext[MessageActivity]], Awaitable[None]], ) -> Callable[[ActivityContext[MessageActivity]], Awaitable[None]]: - validate_handler_type(self.logger, func, MessageActivity, "on_message", "MessageActivity") + validate_handler_type(func, MessageActivity, "on_message", "MessageActivity") def selector(ctx: ActivityBase) -> bool: if not isinstance(ctx, MessageActivity): diff --git a/packages/apps/src/microsoft_teams/apps/routing/generated_handlers.py b/packages/apps/src/microsoft_teams/apps/routing/generated_handlers.py index ba4a63a2..c1a8b710 100644 --- a/packages/apps/src/microsoft_teams/apps/routing/generated_handlers.py +++ b/packages/apps/src/microsoft_teams/apps/routing/generated_handlers.py @@ -10,7 +10,6 @@ """ from abc import ABC, abstractmethod -from logging import Logger from typing import Callable, Optional, overload from microsoft_teams.api.activities import ( @@ -92,12 +91,6 @@ def router(self) -> ActivityRouter: """The activity router instance. Must be implemented by the concrete class.""" pass - @property - @abstractmethod - def logger(self) -> Logger: - """The logger instance used by the app.""" - pass - @overload def on_message(self, handler: BasicHandler[MessageActivity]) -> BasicHandler[MessageActivity]: ... @@ -108,7 +101,7 @@ def on_message(self, handler: Optional[BasicHandler[MessageActivity]] = None) -> """Register a message activity handler.""" def decorator(func: BasicHandler[MessageActivity]) -> BasicHandler[MessageActivity]: - validate_handler_type(self.logger, func, MessageActivity, "on_message", "MessageActivity") + validate_handler_type(func, MessageActivity, "on_message", "MessageActivity") config = ACTIVITY_ROUTES["message"] self.router.add_handler(config.selector, func) return func @@ -133,9 +126,7 @@ def on_message_delete( """Register a message_delete activity handler.""" def decorator(func: BasicHandler[MessageDeleteActivity]) -> BasicHandler[MessageDeleteActivity]: - validate_handler_type( - self.logger, func, MessageDeleteActivity, "on_message_delete", "MessageDeleteActivity" - ) + validate_handler_type(func, MessageDeleteActivity, "on_message_delete", "MessageDeleteActivity") config = ACTIVITY_ROUTES["message_delete"] self.router.add_handler(config.selector, func) return func @@ -160,9 +151,7 @@ def on_soft_delete_message( """Register a soft_delete_message activity handler.""" def decorator(func: BasicHandler[MessageDeleteActivity]) -> BasicHandler[MessageDeleteActivity]: - validate_handler_type( - self.logger, func, MessageDeleteActivity, "on_soft_delete_message", "MessageDeleteActivity" - ) + validate_handler_type(func, MessageDeleteActivity, "on_soft_delete_message", "MessageDeleteActivity") config = ACTIVITY_ROUTES["soft_delete_message"] self.router.add_handler(config.selector, func) return func @@ -187,9 +176,7 @@ def on_message_reaction( """Register a message_reaction activity handler.""" def decorator(func: BasicHandler[MessageReactionActivity]) -> BasicHandler[MessageReactionActivity]: - validate_handler_type( - self.logger, func, MessageReactionActivity, "on_message_reaction", "MessageReactionActivity" - ) + validate_handler_type(func, MessageReactionActivity, "on_message_reaction", "MessageReactionActivity") config = ACTIVITY_ROUTES["message_reaction"] self.router.add_handler(config.selector, func) return func @@ -214,9 +201,7 @@ def on_message_update( """Register a message_update activity handler.""" def decorator(func: BasicHandler[MessageUpdateActivity]) -> BasicHandler[MessageUpdateActivity]: - validate_handler_type( - self.logger, func, MessageUpdateActivity, "on_message_update", "MessageUpdateActivity" - ) + validate_handler_type(func, MessageUpdateActivity, "on_message_update", "MessageUpdateActivity") config = ACTIVITY_ROUTES["message_update"] self.router.add_handler(config.selector, func) return func @@ -241,9 +226,7 @@ def on_undelete_message( """Register a undelete_message activity handler.""" def decorator(func: BasicHandler[MessageUpdateActivity]) -> BasicHandler[MessageUpdateActivity]: - validate_handler_type( - self.logger, func, MessageUpdateActivity, "on_undelete_message", "MessageUpdateActivity" - ) + validate_handler_type(func, MessageUpdateActivity, "on_undelete_message", "MessageUpdateActivity") config = ACTIVITY_ROUTES["undelete_message"] self.router.add_handler(config.selector, func) return func @@ -266,7 +249,7 @@ def on_edit_message( """Register a edit_message activity handler.""" def decorator(func: BasicHandler[MessageUpdateActivity]) -> BasicHandler[MessageUpdateActivity]: - validate_handler_type(self.logger, func, MessageUpdateActivity, "on_edit_message", "MessageUpdateActivity") + validate_handler_type(func, MessageUpdateActivity, "on_edit_message", "MessageUpdateActivity") config = ACTIVITY_ROUTES["edit_message"] self.router.add_handler(config.selector, func) return func @@ -287,7 +270,7 @@ def on_command( """Register a command activity handler.""" def decorator(func: BasicHandler[CommandSendActivity]) -> BasicHandler[CommandSendActivity]: - validate_handler_type(self.logger, func, CommandSendActivity, "on_command", "CommandSendActivity") + validate_handler_type(func, CommandSendActivity, "on_command", "CommandSendActivity") config = ACTIVITY_ROUTES["command"] self.router.add_handler(config.selector, func) return func @@ -312,9 +295,7 @@ def on_command_result( """Register a command_result activity handler.""" def decorator(func: BasicHandler[CommandResultActivity]) -> BasicHandler[CommandResultActivity]: - validate_handler_type( - self.logger, func, CommandResultActivity, "on_command_result", "CommandResultActivity" - ) + validate_handler_type(func, CommandResultActivity, "on_command_result", "CommandResultActivity") config = ACTIVITY_ROUTES["command_result"] self.router.add_handler(config.selector, func) return func @@ -340,7 +321,7 @@ def on_conversation_update( def decorator(func: BasicHandler[ConversationUpdateActivity]) -> BasicHandler[ConversationUpdateActivity]: validate_handler_type( - self.logger, func, ConversationUpdateActivity, "on_conversation_update", "ConversationUpdateActivity" + func, ConversationUpdateActivity, "on_conversation_update", "ConversationUpdateActivity" ) config = ACTIVITY_ROUTES["conversation_update"] self.router.add_handler(config.selector, func) @@ -366,9 +347,7 @@ def on_channel_created( """Register a channel_created activity handler.""" def decorator(func: BasicHandler[ConversationUpdateActivity]) -> BasicHandler[ConversationUpdateActivity]: - validate_handler_type( - self.logger, func, ConversationUpdateActivity, "on_channel_created", "ConversationUpdateActivity" - ) + validate_handler_type(func, ConversationUpdateActivity, "on_channel_created", "ConversationUpdateActivity") config = ACTIVITY_ROUTES["channel_created"] self.router.add_handler(config.selector, func) return func @@ -393,9 +372,7 @@ def on_channel_deleted( """Register a channel_deleted activity handler.""" def decorator(func: BasicHandler[ConversationUpdateActivity]) -> BasicHandler[ConversationUpdateActivity]: - validate_handler_type( - self.logger, func, ConversationUpdateActivity, "on_channel_deleted", "ConversationUpdateActivity" - ) + validate_handler_type(func, ConversationUpdateActivity, "on_channel_deleted", "ConversationUpdateActivity") config = ACTIVITY_ROUTES["channel_deleted"] self.router.add_handler(config.selector, func) return func @@ -420,9 +397,7 @@ def on_channel_renamed( """Register a channel_renamed activity handler.""" def decorator(func: BasicHandler[ConversationUpdateActivity]) -> BasicHandler[ConversationUpdateActivity]: - validate_handler_type( - self.logger, func, ConversationUpdateActivity, "on_channel_renamed", "ConversationUpdateActivity" - ) + validate_handler_type(func, ConversationUpdateActivity, "on_channel_renamed", "ConversationUpdateActivity") config = ACTIVITY_ROUTES["channel_renamed"] self.router.add_handler(config.selector, func) return func @@ -447,9 +422,7 @@ def on_channel_restored( """Register a channel_restored activity handler.""" def decorator(func: BasicHandler[ConversationUpdateActivity]) -> BasicHandler[ConversationUpdateActivity]: - validate_handler_type( - self.logger, func, ConversationUpdateActivity, "on_channel_restored", "ConversationUpdateActivity" - ) + validate_handler_type(func, ConversationUpdateActivity, "on_channel_restored", "ConversationUpdateActivity") config = ACTIVITY_ROUTES["channel_restored"] self.router.add_handler(config.selector, func) return func @@ -474,9 +447,7 @@ def on_team_archived( """Register a team_archived activity handler.""" def decorator(func: BasicHandler[ConversationUpdateActivity]) -> BasicHandler[ConversationUpdateActivity]: - validate_handler_type( - self.logger, func, ConversationUpdateActivity, "on_team_archived", "ConversationUpdateActivity" - ) + validate_handler_type(func, ConversationUpdateActivity, "on_team_archived", "ConversationUpdateActivity") config = ACTIVITY_ROUTES["team_archived"] self.router.add_handler(config.selector, func) return func @@ -501,9 +472,7 @@ def on_team_deleted( """Register a team_deleted activity handler.""" def decorator(func: BasicHandler[ConversationUpdateActivity]) -> BasicHandler[ConversationUpdateActivity]: - validate_handler_type( - self.logger, func, ConversationUpdateActivity, "on_team_deleted", "ConversationUpdateActivity" - ) + validate_handler_type(func, ConversationUpdateActivity, "on_team_deleted", "ConversationUpdateActivity") config = ACTIVITY_ROUTES["team_deleted"] self.router.add_handler(config.selector, func) return func @@ -529,7 +498,7 @@ def on_team_hard_deleted( def decorator(func: BasicHandler[ConversationUpdateActivity]) -> BasicHandler[ConversationUpdateActivity]: validate_handler_type( - self.logger, func, ConversationUpdateActivity, "on_team_hard_deleted", "ConversationUpdateActivity" + func, ConversationUpdateActivity, "on_team_hard_deleted", "ConversationUpdateActivity" ) config = ACTIVITY_ROUTES["team_hard_deleted"] self.router.add_handler(config.selector, func) @@ -555,9 +524,7 @@ def on_team_renamed( """Register a team_renamed activity handler.""" def decorator(func: BasicHandler[ConversationUpdateActivity]) -> BasicHandler[ConversationUpdateActivity]: - validate_handler_type( - self.logger, func, ConversationUpdateActivity, "on_team_renamed", "ConversationUpdateActivity" - ) + validate_handler_type(func, ConversationUpdateActivity, "on_team_renamed", "ConversationUpdateActivity") config = ACTIVITY_ROUTES["team_renamed"] self.router.add_handler(config.selector, func) return func @@ -582,9 +549,7 @@ def on_team_restored( """Register a team_restored activity handler.""" def decorator(func: BasicHandler[ConversationUpdateActivity]) -> BasicHandler[ConversationUpdateActivity]: - validate_handler_type( - self.logger, func, ConversationUpdateActivity, "on_team_restored", "ConversationUpdateActivity" - ) + validate_handler_type(func, ConversationUpdateActivity, "on_team_restored", "ConversationUpdateActivity") config = ACTIVITY_ROUTES["team_restored"] self.router.add_handler(config.selector, func) return func @@ -609,9 +574,7 @@ def on_team_unarchived( """Register a team_unarchived activity handler.""" def decorator(func: BasicHandler[ConversationUpdateActivity]) -> BasicHandler[ConversationUpdateActivity]: - validate_handler_type( - self.logger, func, ConversationUpdateActivity, "on_team_unarchived", "ConversationUpdateActivity" - ) + validate_handler_type(func, ConversationUpdateActivity, "on_team_unarchived", "ConversationUpdateActivity") config = ACTIVITY_ROUTES["team_unarchived"] self.router.add_handler(config.selector, func) return func @@ -637,7 +600,7 @@ def on_end_of_conversation( def decorator(func: BasicHandler[EndOfConversationActivity]) -> BasicHandler[EndOfConversationActivity]: validate_handler_type( - self.logger, func, EndOfConversationActivity, "on_end_of_conversation", "EndOfConversationActivity" + func, EndOfConversationActivity, "on_end_of_conversation", "EndOfConversationActivity" ) config = ACTIVITY_ROUTES["end_of_conversation"] self.router.add_handler(config.selector, func) @@ -657,7 +620,7 @@ def on_event(self, handler: Optional[BasicHandler[EventActivity]] = None) -> Bas """Register a event activity handler.""" def decorator(func: BasicHandler[EventActivity]) -> BasicHandler[EventActivity]: - validate_handler_type(self.logger, func, EventActivity, "on_event", "EventActivity") + validate_handler_type(func, EventActivity, "on_event", "EventActivity") config = ACTIVITY_ROUTES["event"] self.router.add_handler(config.selector, func) return func @@ -682,9 +645,7 @@ def on_read_receipt( """Register a read_receipt activity handler.""" def decorator(func: BasicHandler[ReadReceiptEventActivity]) -> BasicHandler[ReadReceiptEventActivity]: - validate_handler_type( - self.logger, func, ReadReceiptEventActivity, "on_read_receipt", "ReadReceiptEventActivity" - ) + validate_handler_type(func, ReadReceiptEventActivity, "on_read_receipt", "ReadReceiptEventActivity") config = ACTIVITY_ROUTES["read_receipt"] self.router.add_handler(config.selector, func) return func @@ -709,9 +670,7 @@ def on_meeting_start( """Register a meeting_start activity handler.""" def decorator(func: BasicHandler[MeetingStartEventActivity]) -> BasicHandler[MeetingStartEventActivity]: - validate_handler_type( - self.logger, func, MeetingStartEventActivity, "on_meeting_start", "MeetingStartEventActivity" - ) + validate_handler_type(func, MeetingStartEventActivity, "on_meeting_start", "MeetingStartEventActivity") config = ACTIVITY_ROUTES["meeting_start"] self.router.add_handler(config.selector, func) return func @@ -736,9 +695,7 @@ def on_meeting_end( """Register a meeting_end activity handler.""" def decorator(func: BasicHandler[MeetingEndEventActivity]) -> BasicHandler[MeetingEndEventActivity]: - validate_handler_type( - self.logger, func, MeetingEndEventActivity, "on_meeting_end", "MeetingEndEventActivity" - ) + validate_handler_type(func, MeetingEndEventActivity, "on_meeting_end", "MeetingEndEventActivity") config = ACTIVITY_ROUTES["meeting_end"] self.router.add_handler(config.selector, func) return func @@ -768,7 +725,6 @@ def decorator( func: BasicHandler[MeetingParticipantJoinEventActivity], ) -> BasicHandler[MeetingParticipantJoinEventActivity]: validate_handler_type( - self.logger, func, MeetingParticipantJoinEventActivity, "on_meeting_participant_join", @@ -803,7 +759,6 @@ def decorator( func: BasicHandler[MeetingParticipantLeaveEventActivity], ) -> BasicHandler[MeetingParticipantLeaveEventActivity]: validate_handler_type( - self.logger, func, MeetingParticipantLeaveEventActivity, "on_meeting_participant_leave", @@ -838,9 +793,7 @@ def on_config_open( def decorator( func: InvokeHandler[ConfigFetchInvokeActivity, ConfigInvokeResponse], ) -> InvokeHandler[ConfigFetchInvokeActivity, ConfigInvokeResponse]: - validate_handler_type( - self.logger, func, ConfigFetchInvokeActivity, "on_config_open", "ConfigFetchInvokeActivity" - ) + validate_handler_type(func, ConfigFetchInvokeActivity, "on_config_open", "ConfigFetchInvokeActivity") config = ACTIVITY_ROUTES["config.open"] self.router.add_handler(config.selector, func) return func @@ -870,9 +823,7 @@ def on_config_submit( def decorator( func: InvokeHandler[ConfigSubmitInvokeActivity, ConfigInvokeResponse], ) -> InvokeHandler[ConfigSubmitInvokeActivity, ConfigInvokeResponse]: - validate_handler_type( - self.logger, func, ConfigSubmitInvokeActivity, "on_config_submit", "ConfigSubmitInvokeActivity" - ) + validate_handler_type(func, ConfigSubmitInvokeActivity, "on_config_submit", "ConfigSubmitInvokeActivity") config = ACTIVITY_ROUTES["config.submit"] self.router.add_handler(config.selector, func) return func @@ -899,9 +850,7 @@ def on_file_consent( def decorator( func: VoidInvokeHandler[FileConsentInvokeActivity], ) -> VoidInvokeHandler[FileConsentInvokeActivity]: - validate_handler_type( - self.logger, func, FileConsentInvokeActivity, "on_file_consent", "FileConsentInvokeActivity" - ) + validate_handler_type(func, FileConsentInvokeActivity, "on_file_consent", "FileConsentInvokeActivity") config = ACTIVITY_ROUTES["file.consent"] self.router.add_handler(config.selector, func) return func @@ -929,7 +878,7 @@ def decorator( func: VoidInvokeHandler[ExecuteActionInvokeActivity], ) -> VoidInvokeHandler[ExecuteActionInvokeActivity]: validate_handler_type( - self.logger, func, ExecuteActionInvokeActivity, "on_message_execute", "ExecuteActionInvokeActivity" + func, ExecuteActionInvokeActivity, "on_message_execute", "ExecuteActionInvokeActivity" ) config = ACTIVITY_ROUTES["message.execute"] self.router.add_handler(config.selector, func) @@ -964,7 +913,6 @@ def decorator( func: InvokeHandler[MessageExtensionQueryLinkInvokeActivity, MessagingExtensionInvokeResponse], ) -> InvokeHandler[MessageExtensionQueryLinkInvokeActivity, MessagingExtensionInvokeResponse]: validate_handler_type( - self.logger, func, MessageExtensionQueryLinkInvokeActivity, "on_message_ext_query_link", @@ -1003,7 +951,6 @@ def decorator( func: InvokeHandler[MessageExtensionAnonQueryLinkInvokeActivity, MessagingExtensionInvokeResponse], ) -> InvokeHandler[MessageExtensionAnonQueryLinkInvokeActivity, MessagingExtensionInvokeResponse]: validate_handler_type( - self.logger, func, MessageExtensionAnonQueryLinkInvokeActivity, "on_message_ext_anon_query_link", @@ -1040,11 +987,7 @@ def decorator( func: InvokeHandler[MessageExtensionQueryInvokeActivity, MessagingExtensionInvokeResponse], ) -> InvokeHandler[MessageExtensionQueryInvokeActivity, MessagingExtensionInvokeResponse]: validate_handler_type( - self.logger, - func, - MessageExtensionQueryInvokeActivity, - "on_message_ext_query", - "MessageExtensionQueryInvokeActivity", + func, MessageExtensionQueryInvokeActivity, "on_message_ext_query", "MessageExtensionQueryInvokeActivity" ) config = ACTIVITY_ROUTES["message.ext.query"] self.router.add_handler(config.selector, func) @@ -1079,7 +1022,6 @@ def decorator( func: InvokeHandler[MessageExtensionSelectItemInvokeActivity, MessagingExtensionInvokeResponse], ) -> InvokeHandler[MessageExtensionSelectItemInvokeActivity, MessagingExtensionInvokeResponse]: validate_handler_type( - self.logger, func, MessageExtensionSelectItemInvokeActivity, "on_message_ext_select_item", @@ -1118,7 +1060,6 @@ def decorator( func: InvokeHandler[MessageExtensionSubmitActionInvokeActivity, MessagingExtensionActionInvokeResponse], ) -> InvokeHandler[MessageExtensionSubmitActionInvokeActivity, MessagingExtensionActionInvokeResponse]: validate_handler_type( - self.logger, func, MessageExtensionSubmitActionInvokeActivity, "on_message_ext_submit", @@ -1157,7 +1098,6 @@ def decorator( func: InvokeHandler[MessageExtensionFetchTaskInvokeActivity, MessagingExtensionActionInvokeResponse], ) -> InvokeHandler[MessageExtensionFetchTaskInvokeActivity, MessagingExtensionActionInvokeResponse]: validate_handler_type( - self.logger, func, MessageExtensionFetchTaskInvokeActivity, "on_message_ext_open", @@ -1196,7 +1136,6 @@ def decorator( func: InvokeHandler[MessageExtensionQuerySettingUrlInvokeActivity, MessagingExtensionInvokeResponse], ) -> InvokeHandler[MessageExtensionQuerySettingUrlInvokeActivity, MessagingExtensionInvokeResponse]: validate_handler_type( - self.logger, func, MessageExtensionQuerySettingUrlInvokeActivity, "on_message_ext_query_settings_url", @@ -1235,7 +1174,6 @@ def decorator( func: InvokeHandler[MessageExtensionSettingInvokeActivity, MessagingExtensionInvokeResponse], ) -> InvokeHandler[MessageExtensionSettingInvokeActivity, MessagingExtensionInvokeResponse]: validate_handler_type( - self.logger, func, MessageExtensionSettingInvokeActivity, "on_message_ext_setting", @@ -1271,7 +1209,6 @@ def decorator( func: VoidInvokeHandler[MessageExtensionCardButtonClickedInvokeActivity], ) -> VoidInvokeHandler[MessageExtensionCardButtonClickedInvokeActivity]: validate_handler_type( - self.logger, func, MessageExtensionCardButtonClickedInvokeActivity, "on_message_ext_card_button_clicked", @@ -1306,9 +1243,7 @@ def on_dialog_open( def decorator( func: InvokeHandler[TaskFetchInvokeActivity, TaskModuleInvokeResponse], ) -> InvokeHandler[TaskFetchInvokeActivity, TaskModuleInvokeResponse]: - validate_handler_type( - self.logger, func, TaskFetchInvokeActivity, "on_dialog_open", "TaskFetchInvokeActivity" - ) + validate_handler_type(func, TaskFetchInvokeActivity, "on_dialog_open", "TaskFetchInvokeActivity") config = ACTIVITY_ROUTES["dialog.open"] self.router.add_handler(config.selector, func) return func @@ -1338,9 +1273,7 @@ def on_dialog_submit( def decorator( func: InvokeHandler[TaskSubmitInvokeActivity, TaskModuleInvokeResponse], ) -> InvokeHandler[TaskSubmitInvokeActivity, TaskModuleInvokeResponse]: - validate_handler_type( - self.logger, func, TaskSubmitInvokeActivity, "on_dialog_submit", "TaskSubmitInvokeActivity" - ) + validate_handler_type(func, TaskSubmitInvokeActivity, "on_dialog_submit", "TaskSubmitInvokeActivity") config = ACTIVITY_ROUTES["dialog.submit"] self.router.add_handler(config.selector, func) return func @@ -1370,7 +1303,7 @@ def on_tab_open( def decorator( func: InvokeHandler[TabFetchInvokeActivity, TabInvokeResponse], ) -> InvokeHandler[TabFetchInvokeActivity, TabInvokeResponse]: - validate_handler_type(self.logger, func, TabFetchInvokeActivity, "on_tab_open", "TabFetchInvokeActivity") + validate_handler_type(func, TabFetchInvokeActivity, "on_tab_open", "TabFetchInvokeActivity") config = ACTIVITY_ROUTES["tab.open"] self.router.add_handler(config.selector, func) return func @@ -1400,9 +1333,7 @@ def on_tab_submit( def decorator( func: InvokeHandler[TabSubmitInvokeActivity, TabInvokeResponse], ) -> InvokeHandler[TabSubmitInvokeActivity, TabInvokeResponse]: - validate_handler_type( - self.logger, func, TabSubmitInvokeActivity, "on_tab_submit", "TabSubmitInvokeActivity" - ) + validate_handler_type(func, TabSubmitInvokeActivity, "on_tab_submit", "TabSubmitInvokeActivity") config = ACTIVITY_ROUTES["tab.submit"] self.router.add_handler(config.selector, func) return func @@ -1432,11 +1363,7 @@ def decorator( func: VoidInvokeHandler[MessageSubmitActionInvokeActivity], ) -> VoidInvokeHandler[MessageSubmitActionInvokeActivity]: validate_handler_type( - self.logger, - func, - MessageSubmitActionInvokeActivity, - "on_message_submit", - "MessageSubmitActionInvokeActivity", + func, MessageSubmitActionInvokeActivity, "on_message_submit", "MessageSubmitActionInvokeActivity" ) config = ACTIVITY_ROUTES["message.submit"] self.router.add_handler(config.selector, func) @@ -1467,7 +1394,6 @@ def decorator( func: VoidInvokeHandler[MessageSubmitActionInvokeActivity], ) -> VoidInvokeHandler[MessageSubmitActionInvokeActivity]: validate_handler_type( - self.logger, func, MessageSubmitActionInvokeActivity, "on_message_submit_feedback", @@ -1499,9 +1425,7 @@ def on_handoff_action( def decorator( func: VoidInvokeHandler[HandoffActionInvokeActivity], ) -> VoidInvokeHandler[HandoffActionInvokeActivity]: - validate_handler_type( - self.logger, func, HandoffActionInvokeActivity, "on_handoff_action", "HandoffActionInvokeActivity" - ) + validate_handler_type(func, HandoffActionInvokeActivity, "on_handoff_action", "HandoffActionInvokeActivity") config = ACTIVITY_ROUTES["handoff.action"] self.router.add_handler(config.selector, func) return func @@ -1533,11 +1457,7 @@ def decorator( func: InvokeHandler[SignInTokenExchangeInvokeActivity, TokenExchangeInvokeResponseType], ) -> InvokeHandler[SignInTokenExchangeInvokeActivity, TokenExchangeInvokeResponseType]: validate_handler_type( - self.logger, - func, - SignInTokenExchangeInvokeActivity, - "on_signin_token_exchange", - "SignInTokenExchangeInvokeActivity", + func, SignInTokenExchangeInvokeActivity, "on_signin_token_exchange", "SignInTokenExchangeInvokeActivity" ) config = ACTIVITY_ROUTES["signin.token-exchange"] self.router.add_handler(config.selector, func) @@ -1568,11 +1488,7 @@ def decorator( func: VoidInvokeHandler[SignInVerifyStateInvokeActivity], ) -> VoidInvokeHandler[SignInVerifyStateInvokeActivity]: validate_handler_type( - self.logger, - func, - SignInVerifyStateInvokeActivity, - "on_signin_verify_state", - "SignInVerifyStateInvokeActivity", + func, SignInVerifyStateInvokeActivity, "on_signin_verify_state", "SignInVerifyStateInvokeActivity" ) config = ACTIVITY_ROUTES["signin.verify-state"] self.router.add_handler(config.selector, func) @@ -1595,22 +1511,12 @@ def on_signin_failure( def on_signin_failure( self, handler: Optional[VoidInvokeHandler[SignInFailureInvokeActivity]] = None ) -> VoidInvokeHandlerUnion[SignInFailureInvokeActivity]: - """Register a signin.failure activity handler. - - Handles signin/failure invoke activities sent by Teams when a sign-in - operation fails (e.g., SSO token exchange resource mismatch). - """ + """Register a signin.failure activity handler.""" def decorator( func: VoidInvokeHandler[SignInFailureInvokeActivity], ) -> VoidInvokeHandler[SignInFailureInvokeActivity]: - validate_handler_type( - self.logger, - func, - SignInFailureInvokeActivity, - "on_signin_failure", - "SignInFailureInvokeActivity", - ) + validate_handler_type(func, SignInFailureInvokeActivity, "on_signin_failure", "SignInFailureInvokeActivity") config = ACTIVITY_ROUTES["signin.failure"] self.router.add_handler(config.selector, func) return func @@ -1640,9 +1546,7 @@ def on_card_action( def decorator( func: InvokeHandler[AdaptiveCardInvokeActivity, AdaptiveCardInvokeResponse], ) -> InvokeHandler[AdaptiveCardInvokeActivity, AdaptiveCardInvokeResponse]: - validate_handler_type( - self.logger, func, AdaptiveCardInvokeActivity, "on_card_action", "AdaptiveCardInvokeActivity" - ) + validate_handler_type(func, AdaptiveCardInvokeActivity, "on_card_action", "AdaptiveCardInvokeActivity") config = ACTIVITY_ROUTES["card.action"] self.router.add_handler(config.selector, func) return func @@ -1661,7 +1565,7 @@ def on_invoke(self, handler: Optional[BasicHandler[InvokeActivity]] = None) -> B """Register a invoke activity handler.""" def decorator(func: BasicHandler[InvokeActivity]) -> BasicHandler[InvokeActivity]: - validate_handler_type(self.logger, func, InvokeActivity, "on_invoke", "InvokeActivity") + validate_handler_type(func, InvokeActivity, "on_invoke", "InvokeActivity") config = ACTIVITY_ROUTES["invoke"] self.router.add_handler(config.selector, func) return func @@ -1686,9 +1590,7 @@ def on_installation_update( """Register a installation_update activity handler.""" def decorator(func: BasicHandler[InstallUpdateActivity]) -> BasicHandler[InstallUpdateActivity]: - validate_handler_type( - self.logger, func, InstallUpdateActivity, "on_installation_update", "InstallUpdateActivity" - ) + validate_handler_type(func, InstallUpdateActivity, "on_installation_update", "InstallUpdateActivity") config = ACTIVITY_ROUTES["installation_update"] self.router.add_handler(config.selector, func) return func @@ -1709,7 +1611,7 @@ def on_install_add( """Register a install.add activity handler.""" def decorator(func: BasicHandler[InstalledActivity]) -> BasicHandler[InstalledActivity]: - validate_handler_type(self.logger, func, InstalledActivity, "on_install_add", "InstalledActivity") + validate_handler_type(func, InstalledActivity, "on_install_add", "InstalledActivity") config = ACTIVITY_ROUTES["install.add"] self.router.add_handler(config.selector, func) return func @@ -1730,7 +1632,7 @@ def on_install_remove( """Register a install.remove activity handler.""" def decorator(func: BasicHandler[UninstalledActivity]) -> BasicHandler[UninstalledActivity]: - validate_handler_type(self.logger, func, UninstalledActivity, "on_install_remove", "UninstalledActivity") + validate_handler_type(func, UninstalledActivity, "on_install_remove", "UninstalledActivity") config = ACTIVITY_ROUTES["install.remove"] self.router.add_handler(config.selector, func) return func @@ -1749,7 +1651,7 @@ def on_typing(self, handler: Optional[BasicHandler[TypingActivity]] = None) -> B """Register a typing activity handler.""" def decorator(func: BasicHandler[TypingActivity]) -> BasicHandler[TypingActivity]: - validate_handler_type(self.logger, func, TypingActivity, "on_typing", "TypingActivity") + validate_handler_type(func, TypingActivity, "on_typing", "TypingActivity") config = ACTIVITY_ROUTES["typing"] self.router.add_handler(config.selector, func) return func @@ -1768,7 +1670,7 @@ def on_trace(self, handler: Optional[BasicHandler[TraceActivity]] = None) -> Bas """Register a trace activity handler.""" def decorator(func: BasicHandler[TraceActivity]) -> BasicHandler[TraceActivity]: - validate_handler_type(self.logger, func, TraceActivity, "on_trace", "TraceActivity") + validate_handler_type(func, TraceActivity, "on_trace", "TraceActivity") config = ACTIVITY_ROUTES["trace"] self.router.add_handler(config.selector, func) return func @@ -1787,7 +1689,7 @@ def on_handoff(self, handler: Optional[BasicHandler[HandoffActivity]] = None) -> """Register a handoff activity handler.""" def decorator(func: BasicHandler[HandoffActivity]) -> BasicHandler[HandoffActivity]: - validate_handler_type(self.logger, func, HandoffActivity, "on_handoff", "HandoffActivity") + validate_handler_type(func, HandoffActivity, "on_handoff", "HandoffActivity") config = ACTIVITY_ROUTES["handoff"] self.router.add_handler(config.selector, func) return func @@ -1806,7 +1708,7 @@ def on_activity(self, handler: Optional[BasicHandler[Activity]] = None) -> Basic """Register a activity activity handler.""" def decorator(func: BasicHandler[Activity]) -> BasicHandler[Activity]: - validate_handler_type(self.logger, func, Activity, "on_activity", "Activity") + validate_handler_type(func, Activity, "on_activity", "Activity") config = ACTIVITY_ROUTES["activity"] self.router.add_handler(config.selector, func) return func diff --git a/packages/apps/src/microsoft_teams/apps/routing/type_validation.py b/packages/apps/src/microsoft_teams/apps/routing/type_validation.py index ccc92c33..26cc9a80 100644 --- a/packages/apps/src/microsoft_teams/apps/routing/type_validation.py +++ b/packages/apps/src/microsoft_teams/apps/routing/type_validation.py @@ -4,14 +4,15 @@ """ import inspect -from logging import Logger +import logging from typing import Any, Callable, Optional from .activity_context import ActivityContext +logger = logging.getLogger(__name__) + def validate_handler_type( - logger: Logger, func: Callable[[Any], Any], expected_activity_type: Any, method_name: str, diff --git a/packages/apps/src/microsoft_teams/apps/token_manager.py b/packages/apps/src/microsoft_teams/apps/token_manager.py index 6053f776..9dc84718 100644 --- a/packages/apps/src/microsoft_teams/apps/token_manager.py +++ b/packages/apps/src/microsoft_teams/apps/token_manager.py @@ -20,7 +20,6 @@ ManagedIdentityCredentials, TokenCredentials, ) -from microsoft_teams.common import ConsoleLogger from msal import ( ConfidentialClientApplication, ManagedIdentityClient, @@ -34,6 +33,8 @@ DEFAULT_TENANT_FOR_GRAPH_TOKEN = "common" DEFAULT_TOKEN_AUTHORITY = "https://login.microsoftonline.com/{tenant_id}" +logger = logging.getLogger(__name__) + class TokenManager: """Manages authentication tokens for the Teams application.""" @@ -41,15 +42,8 @@ class TokenManager: def __init__( self, credentials: Optional[Credentials], - logger: Optional[logging.Logger] = None, ): self._credentials = credentials - - if not logger: - self._logger = ConsoleLogger().create_logger("TokenManager") - else: - self._logger = logger.getChild("TokenManager") - self._confidential_clients_by_tenant: dict[str, ConfidentialClientApplication] = {} self._managed_identity_client: Optional[ManagedIdentityClient] = None @@ -80,7 +74,7 @@ async def _get_token( credentials = self._credentials if self._credentials is None: if caller_name: - self._logger.debug(f"No credentials provided for {caller_name}") + logger.debug(f"No credentials provided for {caller_name}") return None if isinstance(credentials, ClientCredentials): return await self._get_token_with_client_credentials(credentials, scope, tenant_id) @@ -159,7 +153,7 @@ async def _acquire_managed_identity_token(self, credentials: FederatedIdentityCr ) if not mi_token_res.get("access_token"): - self._logger.error("FIC Step 1 failed: Could not acquire MI token") + logger.error("FIC Step 1 failed: Could not acquire MI token") error = mi_token_res.get("error", ValueError("Error retrieving MI token")) if not isinstance(error, BaseException): error = ValueError(error) @@ -190,15 +184,15 @@ def _handle_token_response(self, token_res: dict[str, Any], error_prefix: str = return JsonWebToken(access_token) else: error_msg = f"{error_prefix}: " if error_prefix else "" - self._logger.error(f"{error_msg}Could not acquire access token") - self._logger.debug(f"TokenRes: {token_res}") + logger.error(f"{error_msg}Could not acquire access token") + logger.debug(f"TokenRes: {token_res}") error = token_res.get("error", "Error retrieving token") if not isinstance(error, BaseException): error = ValueError(error) error_description = token_res.get("error_description", "Error retrieving token from MSAL") - self._logger.error(error_description) + logger.error(error_description) raise error def _get_confidential_client(self, credentials: ClientCredentials, tenant_id: str) -> ConfidentialClientApplication: diff --git a/packages/apps/src/microsoft_teams/apps/utils/retry.py b/packages/apps/src/microsoft_teams/apps/utils/retry.py index dc7ebb76..99c0e25b 100644 --- a/packages/apps/src/microsoft_teams/apps/utils/retry.py +++ b/packages/apps/src/microsoft_teams/apps/utils/retry.py @@ -4,14 +4,14 @@ """ import asyncio +import logging import random -from logging import Logger from typing import Awaitable, Callable, Literal, Optional, TypeVar -from microsoft_teams.common import ConsoleLogger - T = TypeVar("T") +logger = logging.getLogger(__name__) + # Type alias for jitter types using string literals JitterType = Literal["none", "full", "equal", "decorrelated"] @@ -23,21 +23,13 @@ def __init__( delay: float = 0.5, # in seconds max_delay: float = 30.0, # maximum delay cap jitter_type: JitterType = "full", - logger: Optional[Logger] = None, previous_delay: Optional[float] = None, # Internal use for decorrelated jitter attempt_number: int = 1, # Internal use to track current attempt number - _internal_logger: Optional[Logger] = None, # Internal use to pass existing child logger ): self.max_attempts = max_attempts self.delay = delay self.max_delay = max_delay self.jitter_type: JitterType = jitter_type - # Use existing internal logger if provided, otherwise create child logger - self.logger = ( - _internal_logger - if _internal_logger - else (logger.getChild("@teams/retry") if logger else ConsoleLogger().create_logger("@teams/retry")) - ) self.previous_delay = previous_delay self.attempt_number = attempt_number @@ -68,7 +60,6 @@ async def retry(factory: Callable[[], Awaitable[T]], options: Optional[RetryOpti base_delay = options.delay max_delay = options.max_delay jitter_type: JitterType = options.jitter_type - logger = options.logger previous_delay = options.previous_delay attempt_number = options.attempt_number @@ -102,7 +93,6 @@ async def retry(factory: Callable[[], Awaitable[T]], options: Optional[RetryOpti jitter_type=jitter_type, previous_delay=jittered_delay, # Pass current delay for decorrelated jitter attempt_number=attempt_number + 1, # Increment attempt number - _internal_logger=logger, # Pass the existing logger to avoid nested children ), ) logger.error("Final attempt failed.", exc_info=err) diff --git a/packages/apps/tests/conftest.py b/packages/apps/tests/conftest.py index 13e206a4..435b83d5 100644 --- a/packages/apps/tests/conftest.py +++ b/packages/apps/tests/conftest.py @@ -3,6 +3,8 @@ Licensed under the MIT License. """ +import logging + import pytest from microsoft_teams.api import ( Account, @@ -32,6 +34,18 @@ def reset_environment(): os.environ.update(original_env) +@pytest.fixture(autouse=True) +def configure_logging(): + """Configure logging for tests to ensure DEBUG logs are captured.""" + # Set the microsoft_teams logger to DEBUG level so caplog can capture DEBUG logs + logger = logging.getLogger("microsoft_teams") + original_level = logger.level + logger.setLevel(logging.DEBUG) + yield + # Restore original level after test + logger.setLevel(original_level) + + @pytest.fixture def mock_account(): """Create a mock account for testing.""" diff --git a/packages/apps/tests/test_activity_context.py b/packages/apps/tests/test_activity_context.py index 9cb6048b..e12fa65d 100644 --- a/packages/apps/tests/test_activity_context.py +++ b/packages/apps/tests/test_activity_context.py @@ -36,7 +36,6 @@ def _create_activity_context( return ActivityContext( activity=mock_activity, app_id="test-app-id", - logger=MagicMock(), storage=MagicMock(), api=MagicMock(), user_token=None, diff --git a/packages/apps/tests/test_app.py b/packages/apps/tests/test_app.py index a27f4188..088a0e4a 100644 --- a/packages/apps/tests/test_app.py +++ b/packages/apps/tests/test_app.py @@ -65,11 +65,6 @@ def __str__(self) -> str: class TestApp: """Test cases for App class public interface.""" - @pytest.fixture - def mock_logger(self): - """Create a mock logger.""" - return MagicMock() - @pytest.fixture def mock_storage(self): """Create a mock storage.""" @@ -85,10 +80,9 @@ async def handler(ctx) -> None: return handler @pytest.fixture(scope="function") - def basic_options(self, mock_logger, mock_storage): + def basic_options(self, mock_storage): """Create basic app options.""" return AppOptions( - logger=mock_logger, storage=mock_storage, client_id="test-client-id", client_secret="test-secret", @@ -110,10 +104,9 @@ def app_with_options(self, basic_options): return self._mock_http_plugin(app) @pytest.fixture(scope="function") - def app_with_activity_handler(self, mock_logger, mock_storage, mock_activity_handler): + def app_with_activity_handler(self, mock_storage, mock_activity_handler): """Create App with activity handler.""" options = AppOptions( - logger=mock_logger, storage=mock_storage, client_id="test-client-id", client_secret="test-secret", @@ -586,7 +579,6 @@ def test_user_agent_format(self, app_with_options: App): ) def test_app_init_with_managed_identity( self, - mock_logger, mock_storage, options_dict: dict, env_vars: dict, @@ -595,7 +587,7 @@ def test_app_init_with_managed_identity( description: str, ): """Test app initialization with managed identity credentials.""" - options = AppOptions(logger=mock_logger, storage=mock_storage, **options_dict) + options = AppOptions(storage=mock_storage, **options_dict) with patch.dict("os.environ", env_vars, clear=False): app = App(**options) @@ -621,7 +613,6 @@ def test_app_init_with_managed_identity( ) def test_app_init_with_federated_identity( self, - mock_logger, mock_storage, managed_identity_client_id: str, expected_mi_type: str, @@ -630,7 +621,6 @@ def test_app_init_with_federated_identity( ): """Test app initialization with FederatedIdentityCredentials.""" options = AppOptions( - logger=mock_logger, storage=mock_storage, client_id="app-client-id", managed_identity_client_id=managed_identity_client_id, @@ -646,11 +636,10 @@ def test_app_init_with_federated_identity( assert app.credentials.managed_identity_client_id == expected_mi_client_id, f"Failed for: {description}" assert app.credentials.tenant_id == "test-tenant-id", f"Failed for: {description}" - def test_app_init_with_client_secret_takes_precedence(self, mock_logger, mock_storage): + def test_app_init_with_client_secret_takes_precedence(self, mock_storage): """Test that ClientCredentials is used when both client_secret and managed_identity_client_id are provided.""" # When client_secret is provided, it should take precedence over managed identity options = AppOptions( - logger=mock_logger, storage=mock_storage, client_id="test-client-id", client_secret="test-client-secret", @@ -665,10 +654,9 @@ def test_app_init_with_client_secret_takes_precedence(self, mock_logger, mock_st assert type(app.credentials).__name__ == "ClientCredentials" assert app.credentials.client_id == "test-client-id" - def test_service_url_default(self, mock_logger, mock_storage): + def test_service_url_default(self, mock_storage): """Test that app uses default service URL when no configuration provided.""" options = AppOptions( - logger=mock_logger, storage=mock_storage, client_id="test-client-id", client_secret="test-client-secret", @@ -682,10 +670,9 @@ def test_service_url_default(self, mock_logger, mock_storage): app = App(**options) assert app.api.service_url == "https://smba.trafficmanager.net/teams" - def test_service_url_from_environment(self, mock_logger, mock_storage): + def test_service_url_from_environment(self, mock_storage): """Test that app uses service URL from environment variable.""" options = AppOptions( - logger=mock_logger, storage=mock_storage, client_id="test-client-id", client_secret="test-client-secret", @@ -695,10 +682,9 @@ def test_service_url_from_environment(self, mock_logger, mock_storage): app = App(**options) assert app.api.service_url == "https://custom.service.url/teams" - def test_service_url_from_options(self, mock_logger, mock_storage): + def test_service_url_from_options(self, mock_storage): """Test that app uses service URL from options when provided.""" options = AppOptions( - logger=mock_logger, storage=mock_storage, client_id="test-client-id", client_secret="test-client-secret", @@ -710,11 +696,10 @@ def test_service_url_from_options(self, mock_logger, mock_storage): # Options should take precedence over environment assert app.api.service_url == "https://options.service.url/teams" - def test_service_url_priority(self, mock_logger, mock_storage): + def test_service_url_priority(self, mock_storage): """Test that service URL prioritizes options > env > default.""" # Test 1: Default when neither option nor env provided options1 = AppOptions( - logger=mock_logger, storage=mock_storage, client_id="test-client-id", client_secret="test-client-secret", @@ -728,7 +713,6 @@ def test_service_url_priority(self, mock_logger, mock_storage): # Test 2: Environment when provided but option not set options2 = AppOptions( - logger=mock_logger, storage=mock_storage, client_id="test-client-id", client_secret="test-client-secret", @@ -740,7 +724,6 @@ def test_service_url_priority(self, mock_logger, mock_storage): # Test 3: Options when both option and env provided options3 = AppOptions( - logger=mock_logger, storage=mock_storage, client_id="test-client-id", client_secret="test-client-secret", @@ -754,7 +737,7 @@ def test_service_url_priority(self, mock_logger, mock_storage): # Tests for App.send() proactive targeted message validation @pytest.mark.asyncio - async def test_proactive_targeted_without_recipient_raises_error(self, mock_logger, mock_storage) -> None: + async def test_proactive_targeted_without_recipient_raises_error(self, mock_storage) -> None: """ Test that sending a targeted message proactively without an explicit recipient raises a ValueError. @@ -762,7 +745,6 @@ async def test_proactive_targeted_without_recipient_raises_error(self, mock_logg from microsoft_teams.api import MessageActivityInput, SentActivity options = AppOptions( - logger=mock_logger, storage=mock_storage, client_id="test-client-id", client_secret="test-secret", @@ -783,7 +765,7 @@ async def test_proactive_targeted_without_recipient_raises_error(self, mock_logg await app.send("conv-123", activity) @pytest.mark.asyncio - async def test_proactive_targeted_with_explicit_recipient_succeeds(self, mock_logger, mock_storage) -> None: + async def test_proactive_targeted_with_explicit_recipient_succeeds(self, mock_storage) -> None: """ Test that sending a targeted message proactively with an explicit recipient account succeeds. @@ -791,7 +773,6 @@ async def test_proactive_targeted_with_explicit_recipient_succeeds(self, mock_lo from microsoft_teams.api import Account, MessageActivityInput, SentActivity options = AppOptions( - logger=mock_logger, storage=mock_storage, client_id="test-client-id", client_secret="test-secret", diff --git a/packages/apps/tests/test_app_oauth.py b/packages/apps/tests/test_app_oauth.py index 62ef79e5..2eeacbe9 100644 --- a/packages/apps/tests/test_app_oauth.py +++ b/packages/apps/tests/test_app_oauth.py @@ -137,18 +137,15 @@ async def test_sign_in_token_exchange_success( async def test_sign_in_token_exchange_connection_name_warning( self, oauth_handlers, mock_context, token_exchange_activity, mock_token_response ): - """Test token exchange with different connection name logs warning.""" + """Test token exchange with different connection name.""" token_exchange_activity.value.connection_name = "different-connection" mock_context.activity = token_exchange_activity mock_context.api.users.token.exchange.return_value = mock_token_response await oauth_handlers.sign_in_token_exchange(mock_context) - # Verify warning was logged - mock_context.logger.warning.assert_called_once() - warning_msg = mock_context.logger.warning.call_args[0][0] - assert "different-connection" in warning_msg - assert "test-connection" in warning_msg + # Exchange still succeeds despite connection name mismatch + mock_context.api.users.token.exchange.assert_called_once() @pytest.mark.asyncio async def test_sign_in_token_exchange_http_error_404(self, oauth_handlers, mock_context, token_exchange_activity): @@ -194,9 +191,6 @@ async def test_sign_in_token_exchange_http_error_500(self, oauth_handlers, mock_ "error", ErrorEvent(error=http_error, context={"activity": token_exchange_activity}) ) - # Verify error logged - mock_context.logger.error.assert_called_once() - # Verify error response assert isinstance(result, InvokeResponse) assert result.status == 500 @@ -246,9 +240,6 @@ async def test_sign_in_verify_state_success( "sign_in", SignInEvent(activity_ctx=mock_context, token_response=mock_token_response) ) - # Verify debug logs - assert mock_context.logger.debug.call_count == 2 - # Verify response assert result is None @@ -263,11 +254,6 @@ async def test_sign_in_verify_state_no_state(self, oauth_handlers, mock_context, result = await oauth_handlers.sign_in_verify_state(mock_context) - # Verify warning logged - mock_context.logger.warning.assert_called_once() - warning_msg = mock_context.logger.warning.call_args[0][0] - assert "Auth state not present" in warning_msg - # Verify no API call mock_context.api.users.token.get.assert_not_called() @@ -298,9 +284,6 @@ async def test_sign_in_verify_state_http_error_500(self, oauth_handlers, mock_co "error", ErrorEvent(error=http_error, context={"activity": verify_state_activity}) ) - # Verify error logged - mock_context.logger.error.assert_called_once() - # Verify error response assert isinstance(result, InvokeResponse) and result.body is None assert result.status == 500 @@ -320,9 +303,6 @@ async def test_sign_in_verify_state_http_error_404(self, oauth_handlers, mock_co result = await oauth_handlers.sign_in_verify_state(mock_context) - # Verify error logged - mock_context.logger.error.assert_called_once() - # Verify 412 response assert isinstance(result, InvokeResponse) and result.body is None assert result.status == 412 @@ -336,9 +316,6 @@ async def test_sign_in_verify_state_generic_exception(self, oauth_handlers, mock result = await oauth_handlers.sign_in_verify_state(mock_context) - # Verify error logged - mock_context.logger.error.assert_called_once() - # Verify 412 response assert isinstance(result, InvokeResponse) and result.body is None assert result.status == 412 @@ -464,7 +441,6 @@ def processor(self, router): return ActivityProcessor( router=router, - logger=MagicMock(), id="bot-456", storage=LocalStorage(), default_connection_name="graph", @@ -479,7 +455,6 @@ def _make_ctx(activity): return ActivityContext( activity=activity, app_id="bot-456", - logger=MagicMock(), storage=MagicMock(), api=MagicMock(), user_token=None, diff --git a/packages/apps/tests/test_app_plugins.py b/packages/apps/tests/test_app_plugins.py index 5fc33123..2b31462c 100644 --- a/packages/apps/tests/test_app_plugins.py +++ b/packages/apps/tests/test_app_plugins.py @@ -15,7 +15,6 @@ DependencyMetadata, ErrorEvent, EventMetadata, - LoggerDependencyOptions, Plugin, PluginBase, ) @@ -56,13 +55,12 @@ def mock_activity_processor(self): return MagicMock(spec=ActivityProcessor) @pytest.fixture - def plugin_processor(self, container, mock_event_emitter, mock_logger, mock_event_manager, mock_activity_processor): + def plugin_processor(self, container, mock_event_emitter, mock_event_manager, mock_activity_processor): """Create a PluginProcessor instance.""" return PluginProcessor( container=container, event_manager=mock_event_manager, event_emitter=mock_event_emitter, - logger=mock_logger, activity_processor=mock_activity_processor, ) @@ -72,7 +70,6 @@ def mock_plugin(self): @Plugin(name="MockPlugin", version="1.0", description="A mock plugin for testing") class MockPlugin(PluginBase): - logger: Annotated[Logger, LoggerDependencyOptions()] on_error_event: Annotated[Callable[[ErrorEvent], None], EventMetadata(name="error")] client: Annotated[Client, DependencyMetadata()] on_activity_event: Annotated[Callable[[ActivityEvent], InvokeResponse[Any]], EventMetadata(name="activity")] @@ -114,10 +111,9 @@ async def test_get_plugin(self, plugin_processor, mock_plugin): assert plugin_none is None @pytest.mark.asyncio - async def test_inject(self, plugin_processor, mock_plugin, mock_logger, mock_client): + async def test_inject(self, plugin_processor, mock_plugin, mock_client): """Test the inject method.""" - plugin_processor.container.set_provider("logger", mock_logger) plugin_processor.container.set_provider("client", mock_client) invoke_response = InvokeResponse[Any](status=200, body=None) @@ -128,7 +124,6 @@ async def test_inject(self, plugin_processor, mock_plugin, mock_logger, mock_cli result = await mock_plugin.on_activity_event(MagicMock(spec=PluginActivityEvent)) - assert mock_plugin.logger._extract_mock_name() == "mock().getChild()" assert hasattr(mock_plugin, "on_error_event") assert mock_plugin.client._extract_mock_name() == "mock()" diff --git a/packages/apps/tests/test_app_process.py b/packages/apps/tests/test_app_process.py index eab61cb8..39808085 100644 --- a/packages/apps/tests/test_app_process.py +++ b/packages/apps/tests/test_app_process.py @@ -38,14 +38,13 @@ def mock_http_client(self): return http_client @pytest.fixture - def activity_processor(self, mock_logger, mock_http_client): + def activity_processor(self, mock_http_client): """Create an ActivityProcessor instance.""" mock_storage = MagicMock(spec=LocalStorage) mock_activity_router = MagicMock(spec=ActivityRouter) mock_token_manager = MagicMock(spec=TokenManager) return ActivityProcessor( mock_activity_router, - mock_logger, "id", mock_storage, "default_connection", @@ -64,12 +63,11 @@ async def test_execute_middleware_chain_with_no_handlers(self, activity_processo assert response is None @pytest.mark.asyncio - async def test_execute_middleware_chain_with_two_handlers(self, activity_processor, mock_http_client, mock_logger): + async def test_execute_middleware_chain_with_two_handlers(self, activity_processor, mock_http_client): """Test the execute_middleware_chain method with two handlers.""" context = ActivityContext( activity=MagicMock(spec=ActivityBase), app_id="app_id", - logger=mock_logger, storage=MagicMock(spec=LocalStorage), api=mock_http_client, user_token=None, diff --git a/packages/apps/tests/test_http_plugin.py b/packages/apps/tests/test_http_plugin.py index 1371587f..93f11ff3 100644 --- a/packages/apps/tests/test_http_plugin.py +++ b/packages/apps/tests/test_http_plugin.py @@ -26,25 +26,14 @@ class TestHttpPlugin: """Test cases for HttpPlugin public interface.""" @pytest.fixture - def mock_logger(self): - """Create a mock logger.""" - return MagicMock() - - @pytest.fixture - def plugin_with_validator(self, mock_logger): + def plugin_with_validator(self): """Create HttpPlugin with token validator.""" - return HttpPlugin(logger=mock_logger) + return HttpPlugin() @pytest.fixture - def plugin_without_validator(self, mock_logger): + def plugin_without_validator(self): """Create HttpPlugin without token validator.""" - return HttpPlugin(logger=mock_logger) - - def test_init_with_default_logger(self): - """Test HttpPlugin initialization with default logger.""" - plugin = HttpPlugin() - - assert plugin.logger is not None + return HttpPlugin() def test_fastapi_methods_exposed(self, plugin_with_validator): """Test that FastAPI methods are properly exposed.""" @@ -60,7 +49,7 @@ def test_fastapi_methods_exposed(self, plugin_with_validator): assert plugin_with_validator.post == plugin_with_validator.app.post @pytest.mark.asyncio - async def test_on_activity_response(self, plugin_without_validator, mock_account, mock_logger): + async def test_on_activity_response(self, plugin_without_validator, mock_account): """Test successful activity response completion.""" mock_activity = cast( MessageActivity, @@ -84,11 +73,8 @@ async def test_on_activity_response(self, plugin_without_validator, mock_account ) ) - mock_logger.debug.assert_called_once() - mock_logger.debug.assert_called_with(f"Completing activity response for {mock_activity.id}") - @pytest.mark.asyncio - async def test_on_error(self, plugin_with_validator, mock_account, mock_logger): + async def test_on_error(self, plugin_with_validator, mock_account): """Test error handling with activity ID.""" mock_activity = cast( MessageActivity, @@ -172,11 +158,6 @@ def test_middleware_setup(self, plugin_with_validator, plugin_without_validator) # Without app_id, no middleware but app still exists assert plugin_without_validator.app is not None - def test_logger_property(self, mock_logger): - """Test logger property assignment.""" - plugin = HttpPlugin(logger=mock_logger) - assert plugin.logger == mock_logger - def test_app_property(self, plugin_with_validator): """Test FastAPI app property.""" from fastapi import FastAPI @@ -252,8 +233,6 @@ async def test_on_activity_request_exception(self, plugin_without_validator, moc result = await plugin_without_validator.on_activity_request(mock_request, mock_response) mock_handler.assert_called_once() - # Exception is logged directly at exception site - plugin_without_validator.logger.exception.assert_called_once_with(str(test_error)) assert isinstance(result, Response) assert result.status_code == 500 @@ -263,7 +242,7 @@ async def test_on_activity_request_exception(self, plugin_without_validator, moc @pytest.fixture def plugin_for_send(self): """Create HttpPlugin for send testing.""" - plugin = HttpPlugin(logger=MagicMock()) + plugin = HttpPlugin() plugin.client = MagicMock() plugin.client.clone = MagicMock(return_value=MagicMock()) plugin.bot_token = MagicMock() diff --git a/packages/apps/tests/test_http_stream.py b/packages/apps/tests/test_http_stream.py index d1826d78..f6c9905a 100644 --- a/packages/apps/tests/test_http_stream.py +++ b/packages/apps/tests/test_http_stream.py @@ -56,8 +56,8 @@ def conversation_reference(self): ) @pytest.fixture - def http_stream(self, mock_api_client, conversation_reference, mock_logger): - return HttpStream(mock_api_client, conversation_reference, mock_logger) + def http_stream(self, mock_api_client, conversation_reference): + return HttpStream(mock_api_client, conversation_reference) @pytest.fixture def patch_loop_call_later(self): @@ -96,7 +96,7 @@ async def test_stream_multiple_emits_with_timer(self, http_stream, patch_loop_ca @pytest.mark.asyncio async def test_stream_error_handled_gracefully( - self, mock_api_client, conversation_reference, mock_logger, patch_loop_call_later + self, mock_api_client, conversation_reference, patch_loop_call_later ): call_count = 0 loop = asyncio.get_running_loop() @@ -111,7 +111,7 @@ async def mock_send_with_timeout(activity): return SentActivity(id=f"success-after-timeout-{call_count}", activity_params=activity) mock_api_client.conversations.activities().create = mock_send_with_timeout - stream = HttpStream(mock_api_client, conversation_reference, mock_logger) + stream = HttpStream(mock_api_client, conversation_reference) stream.emit("Test message with timeout") await asyncio.sleep(0) @@ -123,7 +123,7 @@ async def mock_send_with_timeout(activity): @pytest.mark.asyncio async def test_stream_all_timeouts_fail_handled_gracefully( - self, mock_api_client, conversation_reference, mock_logger, patch_loop_call_later + self, mock_api_client, conversation_reference, patch_loop_call_later ): call_count = 0 loop = asyncio.get_running_loop() @@ -136,7 +136,7 @@ async def mock_send_all_timeout(activity): raise TimeoutError("All operations timed out") mock_api_client.conversations.activities().create = mock_send_all_timeout - stream = HttpStream(mock_api_client, conversation_reference, mock_logger) + stream = HttpStream(mock_api_client, conversation_reference) stream.emit("Test message with all timeouts") await asyncio.sleep(0) @@ -146,12 +146,12 @@ async def mock_send_all_timeout(activity): @pytest.mark.asyncio async def test_stream_update_status_sends_typing_activity( - self, mock_api_client, conversation_reference, mock_logger, patch_loop_call_later + self, mock_api_client, conversation_reference, patch_loop_call_later ): loop = asyncio.get_running_loop() patcher, scheduled = patch_loop_call_later(loop) with patcher: - stream = HttpStream(mock_api_client, conversation_reference, mock_logger) + stream = HttpStream(mock_api_client, conversation_reference) stream.update("Thinking...") await asyncio.sleep(0) await self._run_scheduled_flushes(scheduled) @@ -166,12 +166,12 @@ async def test_stream_update_status_sends_typing_activity( @pytest.mark.asyncio async def test_stream_sequence_of_update_and_emit( - self, mock_api_client, conversation_reference, mock_logger, patch_loop_call_later + self, mock_api_client, conversation_reference, patch_loop_call_later ): loop = asyncio.get_running_loop() patcher, scheduled = patch_loop_call_later(loop) with patcher: - stream = HttpStream(mock_api_client, conversation_reference, mock_logger) + stream = HttpStream(mock_api_client, conversation_reference) stream.update("Preparing response...") stream.emit("Final response message") await asyncio.sleep(0) @@ -188,7 +188,7 @@ async def test_stream_sequence_of_update_and_emit( @pytest.mark.asyncio async def test_stream_concurrent_emits_do_not_flush_simultaneously( - self, mock_api_client, conversation_reference, mock_logger, patch_loop_call_later + self, mock_api_client, conversation_reference, patch_loop_call_later ): concurrent_entries = 0 max_concurrent_entries = 0 @@ -209,7 +209,7 @@ async def mock_send(activity): mock_api_client.conversations.activities().create = mock_send with patcher: - stream = HttpStream(mock_api_client, conversation_reference, mock_logger) + stream = HttpStream(mock_api_client, conversation_reference) async def emit_task(): stream.emit("Concurrent message") diff --git a/packages/apps/tests/test_optional_graph_dependencies.py b/packages/apps/tests/test_optional_graph_dependencies.py index aa52e33c..fde8c97b 100644 --- a/packages/apps/tests/test_optional_graph_dependencies.py +++ b/packages/apps/tests/test_optional_graph_dependencies.py @@ -18,7 +18,6 @@ def _create_activity_context(self) -> ActivityContext[Any]: """Create a minimal ActivityContext for testing.""" # Create mock objects for all required parameters mock_activity = MagicMock() - mock_logger = MagicMock() mock_storage = MagicMock() mock_api = MagicMock() mock_conversation_ref = MagicMock() @@ -28,7 +27,6 @@ def _create_activity_context(self) -> ActivityContext[Any]: return ActivityContext( activity=mock_activity, app_id="test-app-id", - logger=mock_logger, storage=mock_storage, api=mock_api, user_token=None, @@ -76,7 +74,6 @@ def test_user_graph_property_not_signed_in(self) -> None: activity_context = ActivityContext( activity=MagicMock(), app_id="test-app-id", - logger=MagicMock(), storage=MagicMock(), api=MagicMock(), user_token=MagicMock(), # Has token but not signed in @@ -96,7 +93,6 @@ def test_user_graph_property_no_token(self) -> None: activity_context = ActivityContext( activity=MagicMock(), app_id="test-app-id", - logger=MagicMock(), storage=MagicMock(), api=MagicMock(), user_token=None, # No token @@ -116,7 +112,6 @@ def test_app_graph_property_no_token(self) -> None: activity_context = ActivityContext( activity=MagicMock(), app_id="test-app-id", - logger=MagicMock(), storage=MagicMock(), api=MagicMock(), user_token=None, diff --git a/packages/apps/tests/test_retry.py b/packages/apps/tests/test_retry.py index 15d45ba6..6ea5b4e3 100644 --- a/packages/apps/tests/test_retry.py +++ b/packages/apps/tests/test_retry.py @@ -3,8 +3,6 @@ Licensed under the MIT License. """ -from unittest.mock import MagicMock - import pytest from microsoft_teams.apps.utils import RetryOptions, retry @@ -22,17 +20,14 @@ def test_default_initialization(self): assert options.max_delay == 30.0 assert options.jitter_type == "full" assert options.attempt_number == 1 - assert options.logger is not None def test_custom_initialization(self): """Test that RetryOptions can be initialized with custom values.""" - mock_logger = MagicMock() options = RetryOptions( max_attempts=3, delay=1.0, max_delay=60.0, jitter_type="none", - logger=mock_logger, attempt_number=2, ) assert options.max_attempts == 3 @@ -40,8 +35,6 @@ def test_custom_initialization(self): assert options.max_delay == 60.0 assert options.jitter_type == "none" assert options.attempt_number == 2 - # Logger should be a child of the provided logger - mock_logger.getChild.assert_called_once_with("@teams/retry") class TestRetry: @@ -62,18 +55,9 @@ async def success_factory(): assert call_count == 1 @pytest.mark.asyncio - async def test_attempt_number_increments_correctly(self): + async def test_attempt_number_increments_correctly(self, caplog): """Test that attempt numbers increment correctly in log messages.""" call_count = 0 - mock_logger = MagicMock() - logged_messages = [] - - def capture_debug(msg): - logged_messages.append(msg) - - mock_child_logger = MagicMock() - mock_child_logger.debug.side_effect = capture_debug - mock_logger.getChild.return_value = mock_child_logger async def failing_factory(): nonlocal call_count @@ -82,34 +66,24 @@ async def failing_factory(): raise ValueError(f"Attempt {call_count} failed") return "success" - options = RetryOptions(max_attempts=3, delay=0.01, jitter_type="none", logger=mock_logger) - result = await retry(failing_factory, options) + options = RetryOptions(max_attempts=3, delay=0.01, jitter_type="none") + + with caplog.at_level("DEBUG"): + result = await retry(failing_factory, options) assert result == "success" assert call_count == 3 # Check that attempt numbers are logged correctly - delay_messages = [msg for msg in logged_messages if "before retry (attempt" in msg] + delay_messages = [rec.message for rec in caplog.records if "before retry (attempt" in rec.message] assert len(delay_messages) == 2 # Two retries (attempts 1 and 2 failed) assert "(attempt 1)" in delay_messages[0] # First retry shows attempt 1 (which failed) assert "(attempt 2)" in delay_messages[1] # Second retry shows attempt 2 (which failed) @pytest.mark.asyncio - async def test_exponential_backoff_increases(self): + async def test_exponential_backoff_increases(self, caplog): """Test that exponential backoff delays increase exponentially.""" call_count = 0 - mock_logger = MagicMock() - logged_delays = [] - - def capture_debug(msg): - if "Delaying" in msg and "before retry" in msg: - # Extract delay value from message like "Delaying 1.00s before retry..." - delay_str = msg.split("Delaying ")[1].split("s")[0] - logged_delays.append(float(delay_str)) - - mock_child_logger = MagicMock() - mock_child_logger.debug.side_effect = capture_debug - mock_logger.getChild.return_value = mock_child_logger async def failing_factory(): nonlocal call_count @@ -119,11 +93,23 @@ async def failing_factory(): return "success" # Use no jitter to test pure exponential backoff - options = RetryOptions(max_attempts=4, delay=1.0, jitter_type="none", logger=mock_logger) - result = await retry(failing_factory, options) + options = RetryOptions(max_attempts=4, delay=1.0, jitter_type="none") + + with caplog.at_level("DEBUG"): + result = await retry(failing_factory, options) assert result == "success" assert call_count == 4 + + # Extract delay values from log messages + logged_delays = [] + for rec in caplog.records: + msg = rec.message + if "Delaying" in msg and "before retry" in msg: + # Extract delay value from message like "Delaying 1.00s before retry..." + delay_str = msg.split("Delaying ")[1].split("s")[0] + logged_delays.append(float(delay_str)) + assert len(logged_delays) == 3 # Three retries # Check exponential increase: base_delay * (2^(attempt_number - 1)) @@ -135,23 +121,9 @@ async def failing_factory(): assert logged_delays[2] == 4.0 # Third retry (after attempt 3 failed) @pytest.mark.asyncio - async def test_logger_name_consistent(self): - """Test that logger name doesn't keep growing with recursive calls.""" + async def test_logger_name_consistent(self, caplog): + """Test that logger uses consistent name across retry attempts.""" call_count = 0 - mock_logger = MagicMock() - mock_logger.name = "test_logger" - - # Track how many times getChild is called - child_call_count = 0 - - def track_get_child(child_name): - nonlocal child_call_count - child_call_count += 1 - child_mock = MagicMock() - child_mock.name = f"{mock_logger.name}.{child_name}" - return child_mock - - mock_logger.getChild.side_effect = track_get_child async def failing_factory(): nonlocal call_count @@ -160,16 +132,20 @@ async def failing_factory(): raise ValueError(f"Attempt {call_count} failed") return "success" - options = RetryOptions(max_attempts=3, delay=0.01, logger=mock_logger) - result = await retry(failing_factory, options) + options = RetryOptions(max_attempts=3, delay=0.01) + + with caplog.at_level("DEBUG"): + result = await retry(failing_factory, options) assert result == "success" assert call_count == 3 - # getChild should only be called once (for the initial RetryOptions) - # Recursive calls should reuse the existing child logger - assert child_call_count == 1 - mock_logger.getChild.assert_called_once_with("@teams/retry") + # Check that all retry log messages use the same logger name + logger_names = [rec.name for rec in caplog.records] + # All messages should come from the same logger + assert len(set(logger_names)) == 1 + # Logger name should be the module name + assert logger_names[0] == "microsoft_teams.apps.utils.retry" @pytest.mark.asyncio async def test_final_attempt_failure_raises(self): diff --git a/packages/apps/tests/test_token_validator.py b/packages/apps/tests/test_token_validator.py index 24101f15..54a84ad3 100644 --- a/packages/apps/tests/test_token_validator.py +++ b/packages/apps/tests/test_token_validator.py @@ -58,21 +58,10 @@ def test_init(self): """Test TokenValidator initialization.""" validator = TokenValidator.for_service("test-app-id") - assert validator.logger is not None assert validator.options.valid_issuers == ["https://api.botframework.com"] assert validator.options.valid_audiences == ["test-app-id", "api://test-app-id"] assert validator.options.jwks_uri == "https://login.botframework.com/v1/.well-known/keys" - def test_init_with_custom_logger(self): - """Test TokenValidator initialization with custom logger.""" - mock_logger = MagicMock() - validator = TokenValidator.for_service("test-app-id", mock_logger) - - assert validator.options.valid_issuers == ["https://api.botframework.com"] - assert validator.options.valid_audiences == ["test-app-id", "api://test-app-id"] - assert validator.options.jwks_uri == "https://login.botframework.com/v1/.well-known/keys" - assert validator.logger == mock_logger - @pytest.mark.asyncio async def test_validate_token_success(self, validator, mock_signing_key, valid_payload): """Test successful token validation.""" diff --git a/packages/botbuilder/src/microsoft_teams/botbuilder/__init__.py b/packages/botbuilder/src/microsoft_teams/botbuilder/__init__.py index 73a28a2d..6702d6c6 100644 --- a/packages/botbuilder/src/microsoft_teams/botbuilder/__init__.py +++ b/packages/botbuilder/src/microsoft_teams/botbuilder/__init__.py @@ -3,6 +3,10 @@ Licensed under the MIT License. """ +import logging + from .botbuilder_plugin import BotBuilderPlugin, BotBuilderPluginOptions +logging.getLogger(__name__).addHandler(logging.NullHandler()) + __all__ = ["BotBuilderPlugin", "BotBuilderPluginOptions"] diff --git a/packages/botbuilder/src/microsoft_teams/botbuilder/botbuilder_plugin.py b/packages/botbuilder/src/microsoft_teams/botbuilder/botbuilder_plugin.py index ddc79f1f..09cd5b29 100644 --- a/packages/botbuilder/src/microsoft_teams/botbuilder/botbuilder_plugin.py +++ b/packages/botbuilder/src/microsoft_teams/botbuilder/botbuilder_plugin.py @@ -4,7 +4,7 @@ """ import importlib.metadata -from logging import Logger +import logging from types import SimpleNamespace from typing import Annotated, Any, Optional, Unpack, cast @@ -13,7 +13,6 @@ from microsoft_teams.apps import ( DependencyMetadata, HttpPlugin, - LoggerDependencyOptions, Plugin, ) from microsoft_teams.apps.http_plugin import HttpPluginOptions @@ -30,6 +29,8 @@ version = importlib.metadata.version("microsoft-teams-botbuilder") +logger = logging.getLogger(__name__) + # Constants for app types SINGLE_TENANT = "singletenant" MULTI_TENANT = "multitenant" @@ -49,7 +50,6 @@ class BotBuilderPlugin(HttpPlugin): """ # Dependency injections - logger: Annotated[Logger, LoggerDependencyOptions()] credentials: Annotated[Optional[Credentials], DependencyMetadata(optional=True)] def __init__(self, **options: Unpack[BotBuilderPluginOptions]): @@ -90,7 +90,7 @@ async def on_init(self) -> None: bot_framework_auth = ConfigurationBotFrameworkAuthentication(configuration=config) self.adapter = CloudAdapter(bot_framework_auth) - self.logger.debug("BotBuilder plugin initialized successfully") + logger.debug("BotBuilder plugin initialized successfully") async def on_activity_request(self, request: Request, response: Response) -> Any: """ @@ -131,8 +131,8 @@ async def logic(turn_context: TurnContext): return self._handle_activity_response(response, result) except HTTPException as http_err: - self.logger.error(f"HTTP error processing activity: {http_err}", exc_info=True) + logger.error(f"HTTP error processing activity: {http_err}", exc_info=True) raise except Exception as err: - self.logger.error(f"Error processing activity: {err}", exc_info=True) + logger.error(f"Error processing activity: {err}", exc_info=True) raise HTTPException(status_code=500, detail=str(err)) from err diff --git a/packages/cards/src/microsoft_teams/cards/__init__.py b/packages/cards/src/microsoft_teams/cards/__init__.py index c357ff22..98a1850b 100644 --- a/packages/cards/src/microsoft_teams/cards/__init__.py +++ b/packages/cards/src/microsoft_teams/cards/__init__.py @@ -3,10 +3,14 @@ Licensed under the MIT License. """ +import logging + from . import actions from .actions import * # noqa: F403 from .core import * +logging.getLogger(__name__).addHandler(logging.NullHandler()) + # Combine all exports from submodules __all__: list[str] = [] __all__.extend(actions.__all__) diff --git a/packages/common/README.md b/packages/common/README.md index 8bb26557..1f733782 100644 --- a/packages/common/README.md +++ b/packages/common/README.md @@ -85,9 +85,26 @@ items = list_storage.items() ## Logging +The SDK uses Python's standard `logging` module. The library doesn't configure logging - your application should. + ```python -from microsoft_teams.common import ConsoleLogger +import logging + +# Configure logging once at application startup +logging.getLogger().setLevel(logging.DEBUG) +stream_handler = logging.StreamHandler() +stream_handler.setFormatter(ConsoleFormatter()) +logging.getLogger().addHandler(stream_handler) -# Create console logger -logger = ConsoleLogger().create_logger("my-app") +# Use module-level loggers in your code +logger = logging.getLogger(__name__) +logger.info("Application started") ``` + +**Custom Filtering** + +The SDK provides optional filtering as well: + +```python +stream_handler.addFilter(ConsoleFilter("microsoft_teams.*")) +``` \ No newline at end of file diff --git a/packages/common/src/microsoft_teams/common/__init__.py b/packages/common/src/microsoft_teams/common/__init__.py index 17d17ab9..c3c21ead 100644 --- a/packages/common/src/microsoft_teams/common/__init__.py +++ b/packages/common/src/microsoft_teams/common/__init__.py @@ -3,12 +3,16 @@ Licensed under the MIT License. """ +import logging as _logging + from . import events, http, logging, storage # noqa: E402 from .events import * # noqa: F401, F402, F403 from .http import * # noqa: F401, F402, F403 from .logging import * # noqa: F401, F402, F403 from .storage import * # noqa: F401, F402, F403 +_logging.getLogger(__name__).addHandler(_logging.NullHandler()) + # Combine all exports from submodules __all__: list[str] = [] __all__.extend(events.__all__) diff --git a/packages/common/src/microsoft_teams/common/events/event_emitter.py b/packages/common/src/microsoft_teams/common/events/event_emitter.py index f83234e6..047e5497 100644 --- a/packages/common/src/microsoft_teams/common/events/event_emitter.py +++ b/packages/common/src/microsoft_teams/common/events/event_emitter.py @@ -8,10 +8,10 @@ import logging from typing import Any, Awaitable, Callable, Dict, Generic, List, Optional, Protocol, TypedDict, TypeVar, Union -from ..logging import ConsoleLogger - EventTypeT = TypeVar("EventTypeT", bound=str, contravariant=True) +logger = logging.getLogger(__name__) + EventHandler = Union[ Callable[[Any], None], # Sync handler Callable[[Any], Awaitable[Any]], # Async handler @@ -46,7 +46,6 @@ def emit(self, event: EventTypeT, value: Any = None) -> None: class EventEmitterOptions(TypedDict, total=False): """ Options for EventEmitter configuration. - :param logger: Custom logger instance to use for logging events """ @@ -61,17 +60,10 @@ class EventEmitter(EventEmitterProtocol[EventTypeT]): Thread-safe for single-threaded use cases. """ - def __init__(self, options: Optional[EventEmitterOptions] = None) -> None: + def __init__(self) -> None: self._index = -1 self._subscriptions: Dict[str, List[Subscription]] = {} - # Use provided logger or create default console logger - logger = options.get("logger") if options else None - if logger: - self._logger = logger.getChild("microsoft_teams.common.events.EventEmitter") - else: - self._logger = ConsoleLogger().create_logger("microsoft_teams.common.events.EventEmitter") - def on(self, event: EventTypeT, handler: EventHandler) -> int: """ Register an event handler. @@ -90,7 +82,7 @@ def on(self, event: EventTypeT, handler: EventHandler) -> int: self._subscriptions[event].append({"id": subscription_id, "handler": handler}) - self._logger.debug("Registered handler for event '%s' with id %d", event, subscription_id) + logger.debug("Registered handler for event '%s' with id %d", event, subscription_id) return subscription_id def once(self, event: EventTypeT, handler: EventHandler) -> int: @@ -123,7 +115,7 @@ def once_wrapper(value: Any) -> None: self._subscriptions[event].append({"id": subscription_id, "handler": once_wrapper}) - self._logger.debug("Registered one-time handler for event '%s' with id %d", event, subscription_id) + logger.debug("Registered one-time handler for event '%s' with id %d", event, subscription_id) return subscription_id def off(self, subscription_id: int) -> None: @@ -137,7 +129,7 @@ def off(self, subscription_id: int) -> None: for i, subscription in enumerate(subscriptions): if subscription["id"] == subscription_id: subscriptions.pop(i) - self._logger.debug("Removed handler with id %d from event '%s'", subscription_id, event_name) + logger.debug("Removed handler with id %d from event '%s'", subscription_id, event_name) if not subscriptions: del self._subscriptions[event_name] return @@ -156,7 +148,7 @@ def emit(self, event: EventTypeT, value: Any = None) -> None: return handler_count = len(self._subscriptions[event]) - self._logger.debug("Emitting event '%s' to %d handler(s)", event, handler_count) + logger.debug("Emitting event '%s' to %d handler(s)", event, handler_count) awaitables: list[Awaitable[None]] = [] @@ -170,17 +162,17 @@ def emit(self, event: EventTypeT, value: Any = None) -> None: handler(value) except Exception as e: # Continue executing other handlers even if one fails - self._logger.error("Handler failed for event '%s': %s", event, e) + logger.error("Handler failed for event '%s': %s", event, e) # Handle awaitables if any exist if awaitables: - self._logger.debug("Running %d async handler(s) for event '%s'", len(awaitables), event) + logger.debug("Running %d async handler(s) for event '%s'", len(awaitables), event) async def run_async_handlers() -> None: results = await asyncio.gather(*awaitables, return_exceptions=True) for i, result in enumerate(results): if isinstance(result, Exception): - self._logger.error("Async handler %d failed for event '%s': %s", i, event, result) + logger.error("Async handler %d failed for event '%s': %s", i, event, result) try: # Try to get the current event loop @@ -223,11 +215,11 @@ def remove_all_listeners(self, event: Optional[str] = None) -> None: if event is None: total_handlers = sum(len(handlers) for handlers in self._subscriptions.values()) self._subscriptions.clear() - self._logger.debug("Removed all %d handler(s) from all events", total_handlers) + logger.debug("Removed all %d handler(s) from all events", total_handlers) elif event in self._subscriptions: handler_count = len(self._subscriptions[event]) del self._subscriptions[event] - self._logger.debug("Removed all %d handler(s) from event '%s'", handler_count, event) + logger.debug("Removed all %d handler(s) from event '%s'", handler_count, event) def _get_next_id(self) -> int: """Get next unique subscription ID.""" diff --git a/packages/common/src/microsoft_teams/common/http/client.py b/packages/common/src/microsoft_teams/common/http/client.py index 9d0b53fc..0e29cb4e 100644 --- a/packages/common/src/microsoft_teams/common/http/client.py +++ b/packages/common/src/microsoft_teams/common/http/client.py @@ -13,14 +13,13 @@ from httpx._models import Request, Response from httpx._types import QueryParamTypes, RequestContent, RequestData, RequestFiles -from ..logging import ConsoleLogger from .client_token import Token, resolve_token from .interceptor import Interceptor, InterceptorRequestContext, InterceptorResponseContext -console_logger = ConsoleLogger() +logger = logging.getLogger(__name__) -def _wrap_response_json(response: httpx.Response, logger: logging.Logger) -> None: +def _wrap_response_json(response: httpx.Response) -> None: """ Wrap the response.json method to handle JSONDecodeError gracefully. @@ -52,7 +51,6 @@ class ClientOptions: base_url: The base URL for all requests. headers: Default headers to include with every request. timeout: Default request timeout in seconds. - logger: Logger instance for request/response/error logging. token: Default authorization token (string, string-like, or callable). interceptors: List of interceptors for request/response middleware. """ @@ -60,7 +58,6 @@ class ClientOptions: base_url: Optional[str] = None headers: Dict[str, str] = field(default_factory=dict[str, str]) timeout: Optional[float] = None - logger: Optional[logging.Logger] = None token: Optional[Token] = None interceptors: Optional[List[Interceptor]] = field(default_factory=list[Interceptor]) @@ -84,12 +81,9 @@ def __init__(self, options: Optional[ClientOptions] = None): options = ClientOptions() self._options = options - self._logger = options.logger or console_logger.create_logger("http-client") self._token = options.token - - # Configure httpx logging to match our logger's level httpx_logger = logging.getLogger("httpx") - httpx_logger.setLevel(self._logger.level) + httpx_logger.setLevel(logger.level) # Maintain interceptors as a separate instance attribute (do not mutate options) self._interceptors = list(options.interceptors or []) @@ -143,7 +137,7 @@ async def get( req_headers = await self._prepare_headers(headers, token) response = await self.http.get(url, headers=req_headers, params=params, **kwargs) response.raise_for_status() - _wrap_response_json(response, self._logger) + _wrap_response_json(response) return response async def post( @@ -188,7 +182,7 @@ async def post( **kwargs, ) response.raise_for_status() - _wrap_response_json(response, self._logger) + _wrap_response_json(response) return response async def put( @@ -233,7 +227,7 @@ async def put( **kwargs, ) response.raise_for_status() - _wrap_response_json(response, self._logger) + _wrap_response_json(response) return response async def patch( @@ -278,7 +272,7 @@ async def patch( **kwargs, ) response.raise_for_status() - _wrap_response_json(response, self._logger) + _wrap_response_json(response) return response async def delete( @@ -306,7 +300,7 @@ async def delete( req_headers = await self._prepare_headers(headers, token) response = await self.http.delete(url, headers=req_headers, params=params, **kwargs) response.raise_for_status() - _wrap_response_json(response, self._logger) + _wrap_response_json(response) return response async def request( @@ -354,7 +348,7 @@ async def request( **kwargs, ) response.raise_for_status() - _wrap_response_json(response, self._logger) + _wrap_response_json(response) return response async def _resolve_token(self, token: Optional[Token]) -> Optional[str]: @@ -392,7 +386,7 @@ def _update_event_hooks(self) -> None: def _make_request_wrapper(h: Interceptor) -> Callable[[Request], Awaitable[None]]: async def wrapper(request: Request) -> None: - ctx = InterceptorRequestContext(request, self._logger) + ctx = InterceptorRequestContext(request, logger) result = h.request(ctx) if inspect.isawaitable(result): await result @@ -404,7 +398,7 @@ async def wrapper(request: Request) -> None: def _make_response_wrapper(h: Interceptor) -> Callable[[Response], Awaitable[None]]: async def wrapper(response: Response) -> None: - ctx = InterceptorResponseContext(response, self._logger) + ctx = InterceptorResponseContext(response, logger) result = h.response(ctx) if inspect.isawaitable(result): await result @@ -429,7 +423,6 @@ def clone(self, overrides: Optional[ClientOptions] = None) -> "Client": base_url=overrides.base_url if overrides.base_url is not None else self._options.base_url, headers={**self._options.headers, **(overrides.headers or {})}, timeout=overrides.timeout if overrides.timeout is not None else self._options.timeout, - logger=overrides.logger if overrides.logger is not None else self._options.logger, token=overrides.token if overrides.token is not None else self._options.token, interceptors=list(overrides.interceptors) if overrides.interceptors is not None diff --git a/packages/common/src/microsoft_teams/common/logging/__init__.py b/packages/common/src/microsoft_teams/common/logging/__init__.py index 8b854c6f..b9e0410c 100644 --- a/packages/common/src/microsoft_teams/common/logging/__init__.py +++ b/packages/common/src/microsoft_teams/common/logging/__init__.py @@ -8,4 +8,4 @@ from .filter import ConsoleFilter from .formatter import ConsoleFormatter -__all__ = ["ANSI", "ConsoleLogger", "ConsoleFormatter", "ConsoleFilter", "ConsoleLoggerOptions"] +__all__ = ["ANSI", "ConsoleFormatter", "ConsoleFilter", "ConsoleLogger", "ConsoleLoggerOptions"] diff --git a/packages/common/src/microsoft_teams/common/logging/console.py b/packages/common/src/microsoft_teams/common/logging/console.py index 7a99e8a5..0d0a893c 100644 --- a/packages/common/src/microsoft_teams/common/logging/console.py +++ b/packages/common/src/microsoft_teams/common/logging/console.py @@ -5,6 +5,7 @@ import logging import os +import warnings from typing import Optional, TypedDict from .filter import ConsoleFilter @@ -15,6 +16,9 @@ class ConsoleLoggerOptions(TypedDict, total=False): """ ConsoleLoggerOptions is a dictionary that contains the options for the ConsoleLogger. + DEPRECATED: This class is deprecated and will be removed in version 2.0.0 GA. + please update your imports to use the standard Python logging library instead. + :param level: The level of the logger (error, warn, info, debug) :param pattern: The pattern of the logger (e.g. "my_module.*") """ @@ -26,10 +30,21 @@ class ConsoleLoggerOptions(TypedDict, total=False): class ConsoleLogger: """ ConsoleLogger is a class that creates a logger for the console. + + DEPRECATED: This class is deprecated and will be removed in version 2.0.0 GA. + please update your imports to use the standard Python logging library instead. """ _levels = {"error": logging.ERROR, "warn": logging.WARNING, "info": logging.INFO, "debug": logging.DEBUG} + def __init__(self) -> None: + warnings.warn( + "ConsoleLogger is deprecated and will be removed in version 2.0.0 GA. " + "Use standard Python logging (logging.getLogger(__name__)) instead.", + DeprecationWarning, + stacklevel=2, + ) + def create_logger(self, name: str, options: Optional[ConsoleLoggerOptions] = None) -> logging.Logger: """ Create a logger for the console. diff --git a/packages/common/tests/test_backward_compat.py b/packages/common/tests/test_backward_compat.py index a621439f..fdad9c9a 100644 --- a/packages/common/tests/test_backward_compat.py +++ b/packages/common/tests/test_backward_compat.py @@ -11,12 +11,12 @@ def test_old_import_shows_deprecation_warning(): with warnings.catch_warnings(record=True) as w: warnings.simplefilter("always") - from microsoft.teams.common import ConsoleLogger + from microsoft.teams.common import Client assert len(w) >= 1 assert any(issubclass(warning.category, DeprecationWarning) for warning in w) assert "deprecated" in str(w[0].message).lower() - assert ConsoleLogger is not None + assert Client is not None def test_new_import_no_warning(): @@ -24,20 +24,23 @@ def test_new_import_no_warning(): with warnings.catch_warnings(record=True) as w: warnings.simplefilter("always") - from microsoft_teams.common import ConsoleLogger + from microsoft_teams.common import Client # No warnings expected assert len(w) == 0 - assert ConsoleLogger is not None + assert Client is not None def test_both_namespaces_same_class(): """Old and new imports reference the same class""" - from microsoft.teams.common import ConsoleLogger as OldLogger - from microsoft_teams.common import ConsoleLogger as NewLogger + with warnings.catch_warnings(record=True): + warnings.simplefilter("always") + + from microsoft.teams.common import Client as OldClient + from microsoft_teams.common import Client as NewClient - assert OldLogger is NewLogger - assert id(OldLogger) == id(NewLogger) + assert OldClient is NewClient + assert id(OldClient) == id(NewClient) def test_new_import_from_submodule(): diff --git a/packages/devtools/src/microsoft_teams/devtools/__init__.py b/packages/devtools/src/microsoft_teams/devtools/__init__.py index 4198a0f2..e41d9d78 100644 --- a/packages/devtools/src/microsoft_teams/devtools/__init__.py +++ b/packages/devtools/src/microsoft_teams/devtools/__init__.py @@ -3,7 +3,11 @@ Licensed under the MIT License. """ +import logging + from .devtools_plugin import DevToolsPlugin from .page import Page +logging.getLogger(__name__).addHandler(logging.NullHandler()) + __all__: list[str] = ["DevToolsPlugin", "Page"] diff --git a/packages/devtools/src/microsoft_teams/devtools/devtools_plugin.py b/packages/devtools/src/microsoft_teams/devtools/devtools_plugin.py index 51b4e947..97be657d 100644 --- a/packages/devtools/src/microsoft_teams/devtools/devtools_plugin.py +++ b/packages/devtools/src/microsoft_teams/devtools/devtools_plugin.py @@ -5,10 +5,10 @@ import asyncio import importlib.metadata +import logging import os from contextlib import asynccontextmanager from datetime import datetime -from logging import Logger from typing import Annotated, Any, AsyncGenerator, Awaitable, Callable, Dict, List, Optional from uuid import uuid4 @@ -23,7 +23,6 @@ ErrorEvent, EventMetadata, HttpPlugin, - LoggerDependencyOptions, Plugin, PluginActivityEvent, PluginActivityResponseEvent, @@ -40,6 +39,8 @@ version = importlib.metadata.version("microsoft-teams-devtools") +logger = logging.getLogger(__name__) + @Plugin( name="devtools", @@ -47,7 +48,6 @@ description="set of tools to make development of Teams apps faster and simpler", ) class DevToolsPlugin(Sender): - logger: Annotated[Logger, LoggerDependencyOptions()] id: Annotated[Optional[TokenProtocol], DependencyMetadata(optional=True)] http: Annotated[HttpPlugin, DependencyMetadata()] @@ -65,12 +65,12 @@ def __init__(self): @asynccontextmanager async def lifespan(_app: FastAPI) -> AsyncGenerator[None, None]: # Startup - self.logger.info(f"listening on port {self._port} 🚀") + logger.info(f"listening on port {self._port} 🚀") if self._on_ready_callback: await self._on_ready_callback() yield # Shutdown - self.logger.info("Server shutting down") + logger.info("Server shutting down") if self._on_stopped_callback: await self._on_stopped_callback() @@ -83,7 +83,7 @@ async def lifespan(_app: FastAPI) -> AsyncGenerator[None, None]: @self.app.websocket("/devtools/sockets") async def websocket_endpoint(websocket: WebSocket): # type: ignore - self.logger.info(f"WebSocket connection initiated with scope type: {websocket.scope['type']}") + logger.info(f"WebSocket connection initiated with scope type: {websocket.scope['type']}") await self.on_socket_connection(websocket) dist = os.path.join(os.path.dirname(__file__), "web") @@ -116,7 +116,7 @@ def on_stopped_callback(self, callback: Optional[Callable[[], Awaitable[None]]]) self._on_stopped_callback = callback async def on_init(self) -> None: - self.logger.warning("⚠️ Devtools is not secure and should not be used in production environments ⚠️") + logger.warning("⚠️ Devtools is not secure and should not be used in production environments ⚠️") async def on_start(self, event: PluginStartEvent) -> None: self._port = event.port + 1 @@ -141,13 +141,13 @@ async def process(token: TokenProtocol, activity: Activity): del self.pending[activity.id] return result - router.include_router(get_router(RouteContext(port=self._port, log=self.logger, process=process))) + router.include_router(get_router(RouteContext(port=self._port, log=logger, process=process))) self.app.include_router(router) config = uvicorn.Config(app=self.app, host="0.0.0.0", port=self._port, log_level="info") self._server = uvicorn.Server(config) - self.logger.info(f"available at http://localhost:{self._port}/devtools") + logger.info(f"available at http://localhost:{self._port}/devtools") # The lifespan handler will call the callback when the server is ready await self._server.serve() @@ -155,11 +155,11 @@ async def process(token: TokenProtocol, activity: Activity): except OSError as error: # Handle port in use, permission errors, etc. await self.on_error(PluginErrorEvent(error=error)) - self.logger.error("Server startup failed: %s", error) + logger.error("Server startup failed: %s", error) raise except Exception as error: await self.on_error(PluginErrorEvent(error=error)) - self.logger.error("Failed to start server: %s", error) + logger.error("Failed to start server: %s", error) raise async def on_socket_connection(self, websocket: WebSocket): @@ -185,16 +185,16 @@ async def on_socket_connection(self, websocket: WebSocket): while True: try: data = await websocket.receive_text() - self.logger.debug(f"Received WebSocket message: {data}") + logger.debug(f"Received WebSocket message: {data}") except WebSocketDisconnect: - self.logger.debug(f"WebSocket {socket_id} disconnected") + logger.debug(f"WebSocket {socket_id} disconnected") break finally: del self.sockets[socket_id] async def on_activity(self, event: PluginActivityEvent): """Handle incoming activities.""" - self.logger.debug("Activity received in on_activity") + logger.debug("Activity received in on_activity") activity = DevToolsActivityReceivedEvent( id=str(uuid4()), @@ -208,7 +208,7 @@ async def on_activity(self, event: PluginActivityEvent): async def on_activity_sent(self, event: PluginActivitySentEvent): """Handle sent activities.""" - self.logger.debug(f"Activity sent: {event.activity}") + logger.debug(f"Activity sent: {event.activity}") activity = DevToolsActivitySentEvent( id=str(uuid4()), @@ -239,7 +239,7 @@ async def emit_activity_to_sockets(self, event: DevToolsActivityEvent): try: await websocket.send_json(data) except WebSocketDisconnect: - self.logger.debug(f"WebSocket {socket_id} disconnected") + logger.debug(f"WebSocket {socket_id} disconnected") del self.sockets[socket_id] def add_page(self, page: Page) -> "DevToolsPlugin": diff --git a/packages/graph/src/microsoft_teams/graph/__init__.py b/packages/graph/src/microsoft_teams/graph/__init__.py index 48e5b47b..16bf47cf 100644 --- a/packages/graph/src/microsoft_teams/graph/__init__.py +++ b/packages/graph/src/microsoft_teams/graph/__init__.py @@ -3,9 +3,13 @@ Licensed under the MIT License. """ +import logging + from .auth_provider import AuthProvider from .graph import get_graph_client +logging.getLogger(__name__).addHandler(logging.NullHandler()) + __all__ = [ "AuthProvider", "get_graph_client", diff --git a/packages/mcpplugin/src/microsoft_teams/mcpplugin/__init__.py b/packages/mcpplugin/src/microsoft_teams/mcpplugin/__init__.py index fc61cbdc..378035b2 100644 --- a/packages/mcpplugin/src/microsoft_teams/mcpplugin/__init__.py +++ b/packages/mcpplugin/src/microsoft_teams/mcpplugin/__init__.py @@ -3,10 +3,14 @@ Licensed under the MIT License. """ +import logging + from . import models from .ai_plugin import McpClientPlugin, McpClientPluginParams, McpToolDetails from .models import * # noqa: F403 from .server_plugin import McpServerPlugin +logging.getLogger(__name__).addHandler(logging.NullHandler()) + __all__: list[str] = ["McpClientPlugin", "McpClientPluginParams", "McpToolDetails", "McpServerPlugin"] __all__.extend(models.__all__) diff --git a/packages/mcpplugin/src/microsoft_teams/mcpplugin/ai_plugin.py b/packages/mcpplugin/src/microsoft_teams/mcpplugin/ai_plugin.py index 552db972..b2b76fad 100644 --- a/packages/mcpplugin/src/microsoft_teams/mcpplugin/ai_plugin.py +++ b/packages/mcpplugin/src/microsoft_teams/mcpplugin/ai_plugin.py @@ -13,7 +13,6 @@ from mcp.types import TextContent from microsoft_teams.ai.function import Function from microsoft_teams.ai.plugin import BaseAIPlugin -from microsoft_teams.common.logging import ConsoleLogger from pydantic import BaseModel from .models import McpCachedValue, McpClientPluginParams, McpToolDetails @@ -21,6 +20,8 @@ REFETCH_TIMEOUT_MS = 24 * 60 * 60 * 1000 # 1 day +logger = logging.getLogger(__name__) + class McpClientPlugin(BaseAIPlugin): """ @@ -36,7 +37,6 @@ def __init__( name: str = "mcp_client", version: str = "0.0.0", cache: Optional[Dict[str, McpCachedValue]] = None, - logger: Optional[logging.Logger] = None, refetch_timeout_ms: int = REFETCH_TIMEOUT_MS, # 1 day ): """ @@ -46,14 +46,12 @@ def __init__( name: Plugin identifier version: Plugin version cache: Optional cache for storing fetched tools - logger: Optional logger instance refetch_timeout_ms: How long to cache tools before refetching (default: 1 day) """ super().__init__(name) self._version = version self._cache: Dict[str, McpCachedValue] = cache or {} - self._logger = logger.getChild(self.name) if logger else ConsoleLogger().create_logger(self.name) self._refetch_timeout_ms = refetch_timeout_ms # If cache is provided, update last_fetched for entries with tools @@ -180,7 +178,7 @@ async def _fetch_tools_if_needed(self) -> None: for i, (url, params) in enumerate(fetch_needed): result = results[i] if isinstance(result, Exception): - self._logger.error(f"Failed to fetch tools from {url}: {result}") + logger.error(f"Failed to fetch tools from {url}: {result}") if not params.skip_if_unavailable: raise result elif isinstance(result, list): @@ -191,7 +189,7 @@ async def _fetch_tools_if_needed(self) -> None: self._cache[url].last_fetched = current_time self._cache[url].transport = params.transport - self._logger.debug(f"Cached {len(result)} tools for {url}") + logger.debug(f"Cached {len(result)} tools for {url}") def _create_function_from_tool( self, url: str, tool: McpToolDetails, plugin_params: McpClientPluginParams @@ -224,12 +222,12 @@ async def handler(params: BaseModel) -> str: Exception: If tool execution fails """ try: - self._logger.debug(f"Making call to {url} tool-name={tool_name}") + logger.debug(f"Making call to {url} tool-name={tool_name}") result = await self._call_mcp_tool(url, tool_name, params.model_dump(), plugin_params) - self._logger.debug(f"Successfully received result for mcp call {result}") + logger.debug(f"Successfully received result for mcp call {result}") return str(result) except Exception as e: - self._logger.error(f"Error calling tool {tool_name} on {url}: {e}") + logger.error(f"Error calling tool {tool_name} on {url}: {e}") raise return Function( @@ -269,7 +267,7 @@ async def _fetch_tools_from_server(self, url: str, params: McpClientPluginParams ) ) - self._logger.debug(f"Got {len(tools)} tools for {url}") + logger.debug(f"Got {len(tools)} tools for {url}") return tools async def _call_mcp_tool( @@ -314,7 +312,7 @@ async def _call_mcp_tool( try: contents.append(json.dumps(item, default=str, ensure_ascii=False)) except (TypeError, ValueError) as e: - self._logger.warning(f"Failed to serialize content item: {e}") + logger.warning(f"Failed to serialize content item: {e}") contents.append(str(item)) return contents diff --git a/packages/mcpplugin/src/microsoft_teams/mcpplugin/server_plugin.py b/packages/mcpplugin/src/microsoft_teams/mcpplugin/server_plugin.py index f56bdf13..1f8b436c 100644 --- a/packages/mcpplugin/src/microsoft_teams/mcpplugin/server_plugin.py +++ b/packages/mcpplugin/src/microsoft_teams/mcpplugin/server_plugin.py @@ -18,7 +18,6 @@ PluginBase, PluginStartEvent, ) -from microsoft_teams.common.logging import ConsoleLogger from pydantic import BaseModel try: @@ -26,6 +25,8 @@ except importlib.metadata.PackageNotFoundError: version = "0.0.1-alpha.1" +logger = logging.getLogger(__name__) + P = TypeVar("P", bound=BaseModel) @@ -42,19 +43,17 @@ class McpServerPlugin(PluginBase): # Dependency injection http: Annotated[HttpPlugin, DependencyMetadata()] - def __init__(self, name: str = "teams-mcp-server", path: str = "/mcp", logger: logging.Logger | None = None): + def __init__(self, name: str = "teams-mcp-server", path: str = "/mcp"): """ Initialize the MCP server plugin. Args: name: The name of the MCP server for identification path: The HTTP path to mount the MCP server on (default: /mcp) - logger: Optional logger instance for debugging """ self.mcp_server = FastMCP(name) self.path = path self._mounted = False - self.logger = logger or ConsoleLogger().create_logger("mcp-server") @property def server(self) -> FastMCP: @@ -127,7 +126,7 @@ async def wrapped_handler(**kwargs: Any) -> Any: return await result return result except Exception as e: - self.logger.error(f"Function execution failed for '{function.name}': {e}") + logger.error(f"Function execution failed for '{function.name}': {e}") raise function_tool = FunctionTool( @@ -135,11 +134,11 @@ async def wrapped_handler(**kwargs: Any) -> Any: ) self.mcp_server.add_tool(function_tool) - self.logger.debug(f"Registered AI function '{function.name}' as MCP tool") + logger.debug(f"Registered AI function '{function.name}' as MCP tool") return self except Exception as e: - self.logger.error(f"Failed to register function '{function.name}' as MCP tool: {e}") + logger.error(f"Failed to register function '{function.name}' as MCP tool: {e}") raise async def on_start(self, event: PluginStartEvent) -> None: @@ -154,7 +153,7 @@ async def on_start(self, event: PluginStartEvent) -> None: """ if self._mounted: - self.logger.warning("MCP server already mounted") + logger.warning("MCP server already mounted") return try: @@ -165,9 +164,9 @@ async def on_start(self, event: PluginStartEvent) -> None: self._mounted = True - self.logger.info(f"MCP server mounted at {self.path}") + logger.info(f"MCP server mounted at {self.path}") except Exception as e: - self.logger.error(f"Failed to mount MCP server: {e}") + logger.error(f"Failed to mount MCP server: {e}") raise async def on_stop(self) -> None: @@ -177,5 +176,5 @@ async def on_stop(self) -> None: Performs graceful shutdown of the MCP server and cleans up resources. """ if self._mounted: - self.logger.info("MCP server shutting down") + logger.info("MCP server shutting down") self._mounted = False diff --git a/packages/openai/src/microsoft_teams/openai/__init__.py b/packages/openai/src/microsoft_teams/openai/__init__.py index 85052037..da6e7607 100644 --- a/packages/openai/src/microsoft_teams/openai/__init__.py +++ b/packages/openai/src/microsoft_teams/openai/__init__.py @@ -3,7 +3,11 @@ Licensed under the MIT License. """ +import logging + from .completions_model import OpenAICompletionsAIModel from .responses_chat_model import OpenAIResponsesAIModel +logging.getLogger(__name__).addHandler(logging.NullHandler()) + __all__ = ["OpenAICompletionsAIModel", "OpenAIResponsesAIModel"] diff --git a/packages/openai/src/microsoft_teams/openai/common.py b/packages/openai/src/microsoft_teams/openai/common.py index f36c8546..9339cd6a 100644 --- a/packages/openai/src/microsoft_teams/openai/common.py +++ b/packages/openai/src/microsoft_teams/openai/common.py @@ -3,18 +3,19 @@ Licensed under the MIT License. """ +import logging from dataclasses import dataclass, field -from logging import Logger from os import getenv from typing import Literal from dotenv import find_dotenv, load_dotenv -from microsoft_teams.common.logging import ConsoleLogger from openai import AsyncAzureOpenAI, AsyncOpenAI load_dotenv(find_dotenv(usecwd=True)) +logger = logging.getLogger(__name__) + @dataclass class OpenAIBaseModel: @@ -45,9 +46,6 @@ class OpenAIBaseModel: # Azure OpenAI options azure_endpoint: str | None = None # Azure OpenAI endpoint URL api_version: str | None = None # Azure OpenAI API version - logger: Logger = field( - default_factory=lambda: ConsoleLogger().create_logger(name="OpenAI-Model") - ) # Logger instance _client: AsyncOpenAI = field(init=False) # Internal client instance _model: str = field(init=False) # Resolved model name diff --git a/packages/openai/src/microsoft_teams/openai/completions_model.py b/packages/openai/src/microsoft_teams/openai/completions_model.py index 9ffc7f45..f70b2604 100644 --- a/packages/openai/src/microsoft_teams/openai/completions_model.py +++ b/packages/openai/src/microsoft_teams/openai/completions_model.py @@ -5,6 +5,7 @@ import inspect import json +import logging from dataclasses import dataclass from typing import Any, Awaitable, Callable, TypedDict, cast @@ -41,6 +42,8 @@ from .function_utils import get_function_schema, parse_function_arguments +logger = logging.getLogger(__name__) + class _ToolCallData(TypedDict): """ @@ -102,7 +105,7 @@ async def generate_text( # Get conversation history from memory (make a copy to avoid modifying memory's internal state) messages = list(await memory.get_all()) - self.logger.debug(f"Retrieved {len(messages)} messages from memory, {len(function_results)} function results") + logger.debug(f"Retrieved {len(messages)} messages from memory, {len(function_results)} function results") # Push current input to memory await memory.push(input) @@ -121,12 +124,12 @@ async def generate_text( # Convert messages to OpenAI format openai_messages = self._convert_messages(input_to_send, system, messages) - self.logger.debug(f"Converted to {len(openai_messages)} OpenAI messages") + logger.debug(f"Converted to {len(openai_messages)} OpenAI messages") # Convert functions to OpenAI tools format if provided tools = self._convert_functions(functions) if functions else omit - self.logger.debug(f"Making Chat Completions API call (streaming: {bool(on_chunk)})") + logger.debug(f"Making Chat Completions API call (streaming: {bool(on_chunk)})") # Make OpenAI API call (with streaming if on_chunk provided) response = await self._client.chat.completions.create( @@ -141,14 +144,12 @@ async def generate_text( # If response has function calls, recursively execute them if model_response.function_calls: - self.logger.debug( - f"Response has {len(model_response.function_calls)} function calls, executing recursively" - ) + logger.debug(f"Response has {len(model_response.function_calls)} function calls, executing recursively") return await self.generate_text(model_response, system=system, memory=memory, functions=functions) # Push response to memory (only if not recursing) await memory.push(model_response) - self.logger.debug("Chat Completions conversation completed, returning response") + logger.debug("Chat Completions conversation completed, returning response") return model_response @@ -160,7 +161,7 @@ async def _execute_functions( if isinstance(input, ModelMessage) and input.function_calls: # Execute any pending function calls - self.logger.debug(f"Executing {len(input.function_calls)} function calls") + logger.debug(f"Executing {len(input.function_calls)} function calls") for call in input.function_calls: if functions and call.name in functions: function = functions[call.name] @@ -183,7 +184,7 @@ async def _execute_functions( # Create function result message function_results.append(FunctionMessage(content=fn_res, function_id=call.id)) except Exception as e: - self.logger.error(e) + logger.error(e) # Handle function execution errors function_results.append( FunctionMessage(content=f"Function execution failed: {str(e)}", function_id=call.id) diff --git a/packages/openai/src/microsoft_teams/openai/responses_chat_model.py b/packages/openai/src/microsoft_teams/openai/responses_chat_model.py index 9a437d53..fb7874ec 100644 --- a/packages/openai/src/microsoft_teams/openai/responses_chat_model.py +++ b/packages/openai/src/microsoft_teams/openai/responses_chat_model.py @@ -5,6 +5,7 @@ import inspect import json +import logging from dataclasses import dataclass from typing import Awaitable, Callable, cast @@ -42,6 +43,8 @@ from .common import OpenAIBaseModel from .function_utils import get_function_schema, parse_function_arguments +logger = logging.getLogger(__name__) + @dataclass class OpenAIResponsesAIModel(OpenAIBaseModel, AIModel): @@ -112,7 +115,7 @@ async def _send_stateful( if isinstance(msg, ModelMessage) and msg.id: previous_response_id = msg.id break - self.logger.debug(f"Found previous response ID: {previous_response_id}") + logger.debug(f"Found previous response ID: {previous_response_id}") if function_results: for result in function_results: await memory.push(result) @@ -123,7 +126,7 @@ async def _send_stateful( # Convert functions to tools format tools = self._convert_functions_to_tools(functions) if functions else omit - self.logger.debug(f"Making Responses API call with input type: {type(input).__name__}") + logger.debug(f"Making Responses API call with input type: {type(input).__name__}") # Make OpenAI Responses API call response = await self._client.responses.create( @@ -134,9 +137,9 @@ async def _send_stateful( previous_response_id=previous_response_id, ) - self.logger.debug(f"Response API returned: {type(response)}") - self.logger.debug(f"Response has content: {hasattr(response, 'content')}") - self.logger.debug(f"Response attributes: {[attr for attr in dir(response) if not attr.startswith('_')]}") + logger.debug(f"Response API returned: {type(response)}") + logger.debug(f"Response has content: {hasattr(response, 'content')}") + logger.debug(f"Response attributes: {[attr for attr in dir(response) if not attr.startswith('_')]}") # Convert response to ModelMessage format model_response = self._convert_from_responses_format(response) @@ -150,15 +153,13 @@ async def _send_stateful( # If response has function calls, recursively execute them if model_response.function_calls: - self.logger.debug( - f"Response has {len(model_response.function_calls)} function calls, executing recursively" - ) + logger.debug(f"Response has {len(model_response.function_calls)} function calls, executing recursively") return await self.generate_text( model_response, system=system, memory=memory, functions=functions, on_chunk=on_chunk ) - self.logger.debug("Stateful Responses API conversation completed") - self.logger.debug(model_response) + logger.debug("Stateful Responses API conversation completed") + logger.debug(model_response) return model_response async def _send_stateless( @@ -173,7 +174,7 @@ async def _send_stateless( """Handle stateless conversation using standard OpenAI API pattern.""" # Get conversation history from memory (make a copy to avoid modifying memory's internal state) messages = list(await memory.get_all()) - self.logger.debug(f"Retrieved {len(messages)} messages from memory") + logger.debug(f"Retrieved {len(messages)} messages from memory") # Push current input to memory await memory.push(input) @@ -191,7 +192,7 @@ async def _send_stateless( # Convert functions to tools format tools = self._convert_functions_to_tools(functions) if functions else omit - self.logger.debug(f"Making Responses API call with input type: {type(input).__name__}") + logger.debug(f"Making Responses API call with input type: {type(input).__name__}") # Make OpenAI Responses API call (stateless) response = await self._client.responses.create( @@ -201,20 +202,18 @@ async def _send_stateless( tools=tools, ) - self.logger.debug(f"Response API returned: {type(response)}") - self.logger.debug(f"Response has content: {hasattr(response, 'content')}") + logger.debug(f"Response API returned: {type(response)}") + logger.debug(f"Response has content: {hasattr(response, 'content')}") if hasattr(response, "output"): - self.logger.debug(f"Response content: {response.output}") - self.logger.debug(f"Response attributes: {[attr for attr in dir(response) if not attr.startswith('_')]}") + logger.debug(f"Response content: {response.output}") + logger.debug(f"Response attributes: {[attr for attr in dir(response) if not attr.startswith('_')]}") # Convert response to ModelMessage format model_response = self._convert_from_responses_format(response) # If response has function calls, recursively execute them if model_response.function_calls: - self.logger.debug( - f"Response has {len(model_response.function_calls)} function calls, executing recursively" - ) + logger.debug(f"Response has {len(model_response.function_calls)} function calls, executing recursively") return await self.generate_text(model_response, system=system, memory=memory, functions=functions) # Push response to memory (only if not recursing) @@ -225,7 +224,7 @@ async def _send_stateless( if model_response.content: await on_chunk(model_response.content) - self.logger.debug("Stateless Responses API conversation completed") + logger.debug("Stateless Responses API conversation completed") return model_response async def _execute_functions( @@ -314,7 +313,7 @@ def _convert_to_responses_format( } ) else: - self.logger.warning(f"No associated result found for call id ({call.name} - {call.id})") + logger.warning(f"No associated result found for call id ({call.name} - {call.id})") else: # ModelMessage with content but no function calls content = message.content or ""