diff --git a/sdk/ai/azure-ai-projects/README.md b/sdk/ai/azure-ai-projects/README.md index da4f812a1b7e..17a3fe812af0 100644 --- a/sdk/ai/azure-ai-projects/README.md +++ b/sdk/ai/azure-ai-projects/README.md @@ -127,6 +127,7 @@ async with ( ) as project_client, ): ``` + ### Performing Responses operations using OpenAI client Use the `.get_openai_client()` method to obtain an authenticated [OpenAI](https://github.com/openai/openai-python) client and run Responses, Conversations, Evaluations, Files, and Fine-Tuning operations. See the **responses**, **agents**, **evaluations**, **files**, and **finetuning** folders in the [samples][samples] for complete working examples. @@ -158,6 +159,7 @@ See the **responses** folder in the [samples][samples] for additional samples in ### Agents See Foundry documentation: + * **[Microsoft Foundry Agents overview](https://learn.microsoft.com/azure/foundry/agents/overview)** — concepts, setup, and quick-starts. * **[Runtime components](https://learn.microsoft.com/azure/foundry/agents/concepts/runtime-components?tabs=python)** — deep-dive into agent architecture. * **[Tool catalog](https://learn.microsoft.com/azure/foundry/agents/concepts/tool-catalog)** — all available tools and agent capabilities. @@ -234,25 +236,29 @@ To turn on client console logging define the environment variable `AZURE_AI_PROJ #### Customizing your log -Instead of using the above-mentioned environment variable, you can configure logging yourself and control the log level, format and destination. To log to `stdout`, add the following at the top of your Python script: +Instead of using the above-mentioned environment variable, you can configure logging yourself and control the log level, format, and destination. You can optionally attach the same handler to the Azure SDK logger and, for `.get_openai_client()` scenarios, optionally attach it to the dedicated OpenAI transport logger as well: ```python import sys import logging -# Acquire the logger for this client library. Use 'azure' to affect both -# `azure.core` and `azure.ai.projects' libraries. -logger = logging.getLogger("azure") - -# Set the desired logging level. logging.INFO or logging.DEBUG are good options. -logger.setLevel(logging.DEBUG) - # Direct logging output to stdout: handler = logging.StreamHandler(stream=sys.stdout) # Or direct logging output to a file: # handler = logging.FileHandler(filename="sample.log") + +# Optional: logger for azure-ai-projects and azure-core. +logger = logging.getLogger("azure") +logger.setLevel(logging.DEBUG) logger.addHandler(handler) +# Optional: additional logger for an openai client generated from `.get_openai_client()`. +openai_logger = logging.getLogger("azure.ai.projects.openai_transport") +openai_logger.setLevel(logging.DEBUG) +openai_logger.propagate = False +openai_logger.addHandler(handler) + + # Optional: change the default logging format. Here we add a timestamp. #formatter = logging.Formatter("%(asctime)s:%(levelname)s:%(name)s:%(message)s") #handler.setFormatter(formatter) @@ -270,6 +276,8 @@ project_client = AIProjectClient( Note that the log level must be set to `logging.DEBUG` (see above code). Logs will be redacted with any other log level. +See the logging samples in the `samples/logs/` folder for complete end-to-end examples, including console logging, file logging, and OpenAI transport logging. + Be sure to protect non-redacted logs to avoid compromising security. For more information, see [Configure logging in the Azure libraries for Python](https://aka.ms/azsdk/python/logging) diff --git a/sdk/ai/azure-ai-projects/azure/ai/projects/_patch.py b/sdk/ai/azure-ai-projects/azure/ai/projects/_patch.py index 9796a5679697..6e07cc919b74 100644 --- a/sdk/ai/azure-ai-projects/azure/ai/projects/_patch.py +++ b/sdk/ai/azure-ai-projects/azure/ai/projects/_patch.py @@ -11,9 +11,9 @@ import os import re import logging -from typing import List, Any, Optional +from typing import List, Any, Optional, cast import httpx # pylint: disable=networking-import-outside-azure-core-transport -from openai import OpenAI +from openai import OpenAI, DefaultHttpxClient from azure.core.tracing.decorator import distributed_trace from azure.core.credentials import TokenCredential from azure.identity import get_bearer_token_provider @@ -21,7 +21,9 @@ from .operations import TelemetryOperations from .models._patch import _BETA_OPERATION_FEATURE_HEADERS, _FOUNDRY_FEATURES_HEADER_NAME, _has_header_case_insensitive +_OPENAI_TRANSPORT_LOGGER_NAME = "azure.ai.projects.openai_transport" logger = logging.getLogger(__name__) +_openai_transport_logger = logging.getLogger(_OPENAI_TRANSPORT_LOGGER_NAME) # --------------------------------------------------------------------------- @@ -97,6 +99,61 @@ def _build_openai_user_agent(custom_user_agent: Optional[str], openai_default_us return "-".join(ua for ua in [custom_user_agent, "AIProjectClient"] if ua) + " " + openai_default_user_agent +def _log_streaming_response_notice(logging_enabled: bool) -> bool: + if logging_enabled: + _openai_transport_logger.debug("Body: [Streaming response will be logged as consumed]") + return True + + _openai_transport_logger.debug("Body: [Streaming content exists]") + return False + + +def _log_streaming_response_chunk(chunk: bytes) -> None: + if not chunk: + return + + try: + _openai_transport_logger.debug("Body chunk:\n %s", chunk.decode("utf-8")) + except Exception: # pylint: disable=broad-exception-caught + _openai_transport_logger.debug("Body chunk (raw):\n %r", chunk) + + +class _LoggingSyncByteStream(httpx.SyncByteStream): + def __init__(self, stream: httpx.SyncByteStream) -> None: + self._stream = stream + + def __iter__(self): + try: + for chunk in self._stream: + _log_streaming_response_chunk(chunk) + yield chunk + finally: + _openai_transport_logger.debug("Body: [Streaming response completed]") + + def close(self) -> None: + close = getattr(self._stream, "close", None) + if close: + close() + + +class _LoggingAsyncByteStream(httpx.AsyncByteStream): + def __init__(self, stream: httpx.AsyncByteStream) -> None: + self._stream = stream + + async def __aiter__(self): + try: + async for chunk in self._stream: + _log_streaming_response_chunk(chunk) + yield chunk + finally: + _openai_transport_logger.debug("Body: [Streaming response completed]") + + async def aclose(self) -> None: + aclose = getattr(self._stream, "aclose", None) + if aclose: + await aclose() + + class AIProjectClient(AIProjectClientGenerated): # pylint: disable=too-many-instance-attributes """AIProjectClient. @@ -161,6 +218,7 @@ def __init__( azure_logger.setLevel(logging.DEBUG) console_handler = logging.StreamHandler(stream=sys.stdout) console_handler.addFilter(_AuthSecretsFilter()) + console_handler.addFilter(_OpenAIAuthSecretsFilter()) azure_logger.addHandler(console_handler) # Exclude detailed logs for network calls associated with getting Entra ID token. logging.getLogger("azure.identity").setLevel(logging.ERROR) @@ -169,6 +227,10 @@ def __init__( # (which are implemented as a separate logging policy) logging.getLogger("azure.core.pipeline.policies.http_logging_policy").setLevel(logging.ERROR) + openai_transport_logger = logging.getLogger(_OPENAI_TRANSPORT_LOGGER_NAME) + openai_transport_logger.setLevel(logging.DEBUG) + openai_transport_logger.propagate = False + openai_transport_logger.addHandler(console_handler) kwargs.setdefault("logging_enable", self._console_logging_enabled) self._kwargs = kwargs.copy() @@ -203,9 +265,10 @@ def _get_openai_http_client(self, kwargs: dict): """ if "http_client" in kwargs: return kwargs.pop("http_client") - if self._console_logging_enabled: - return httpx.Client(transport=_OpenAILoggingTransport()) - return None + + logging_kwargs = getattr(self, "_kwargs", {}) + logging_enabled = bool(logging_kwargs.get("logging_enable", False)) + return DefaultHttpxClient(transport=_OpenAILoggingTransport(logging_enabled=logging_enabled)) @distributed_trace def get_openai_client( @@ -242,7 +305,7 @@ def get_openai_client( base_url = _resolve_openai_base_url(self._config, agent_name, kwargs) default_query = _resolve_openai_query_params(self._config, agent_name, kwargs) - logger.debug( # pylint: disable=specify-parameter-names-in-call + _openai_transport_logger.debug( # pylint: disable=specify-parameter-names-in-call "[get_openai_client] Creating OpenAI client using Entra ID authentication, base_url = `%s`", # pylint: disable=line-too-long base_url, ) @@ -300,11 +363,25 @@ def filter(self, record: logging.LogRecord) -> bool: return True +class _OpenAIAuthSecretsFilter(logging.Filter): + """Redact bearer tokens in OpenAI transport log messages before console emission.""" + + _AUTH_HEADER_LINE_PATTERN = re.compile(r"(?im)^(\s*authorization:\s*bearer\s+).+$") + + def filter(self, record: logging.LogRecord) -> bool: + rendered = record.getMessage() + redacted = self._AUTH_HEADER_LINE_PATTERN.sub(r"\1", rendered) + if redacted != rendered: + record.msg = redacted + record.args = () + return True + + class _OpenAILoggingTransport(httpx.HTTPTransport): - """Custom HTTP transport that logs OpenAI API requests and responses to the console. + """Custom HTTP transport that logs OpenAI API requests and responses. - This transport wraps httpx.HTTPTransport to intercept all HTTP traffic and print - detailed request/response information for debugging purposes. It automatically + This transport wraps httpx.HTTPTransport to intercept all HTTP traffic and emit + detailed request/response information through a dedicated logger. It automatically redacts sensitive authorization headers and handles various content types including multipart form data (file uploads). @@ -312,12 +389,18 @@ class _OpenAILoggingTransport(httpx.HTTPTransport): AZURE_AI_PROJECTS_CONSOLE_LOGGING environment variable. """ + def __init__(self, *, logging_enabled: bool) -> None: + super().__init__() + self._logging_enabled = logging_enabled + def _sanitize_auth_header(self, headers) -> None: """Sanitize authorization and api-key headers by redacting sensitive information. :param headers: Dictionary of HTTP headers to sanitize :type headers: dict """ + if self._logging_enabled: + return if "authorization" in headers: auth_value = headers["authorization"] @@ -326,9 +409,14 @@ def _sanitize_auth_header(self, headers) -> None: else: headers["authorization"] = "" + @staticmethod + def _is_streaming_response(response: httpx.Response) -> bool: + content_type = response.headers.get("content-type", "").lower() + return "text/event-stream" in content_type + def handle_request(self, request: httpx.Request) -> httpx.Response: """ - Log HTTP request and response details to console, in a nicely formatted way, + Log HTTP request and response details using the dedicated transport logger, for OpenAI / Azure OpenAI clients. :param request: The HTTP request to handle and log @@ -338,31 +426,38 @@ def handle_request(self, request: httpx.Request) -> httpx.Response: :rtype: httpx.Response """ - print(f"\n==> Request:\n{request.method} {request.url}") + _openai_transport_logger.debug("\n==> Request:\n%s %s", request.method, request.url) headers = dict(request.headers) self._sanitize_auth_header(headers) - print("Headers:") + _openai_transport_logger.debug("Headers:") for key, value in sorted(headers.items()): - print(f" {key}: {value}") + _openai_transport_logger.debug(" %s: %s", key, value) self._log_request_body(request) response = super().handle_request(request) - print(f"\n<== Response:\n{response.status_code} {response.reason_phrase}") - print("Headers:") + _openai_transport_logger.debug("\n<== Response:\n%s %s", response.status_code, response.reason_phrase) + _openai_transport_logger.debug("Headers:") for key, value in sorted(dict(response.headers).items()): - print(f" {key}: {value}") + _openai_transport_logger.debug(" %s: %s", key, value) - content = response.read() - if content is None or content == b"": - print("Body: [No content]") + if self._is_streaming_response(response): + if _log_streaming_response_notice(self._logging_enabled): + response.stream = _LoggingSyncByteStream(cast(httpx.SyncByteStream, response.stream)) else: - try: - print(f"Body:\n {content.decode('utf-8')}") - except Exception: # pylint: disable=broad-exception-caught - print(f"Body (raw):\n {content!r}") - print("\n") + content = response.read() + if content is None or content == b"": + _openai_transport_logger.debug("Body: [No content]") + else: + if self._logging_enabled: + try: + _openai_transport_logger.debug("Body:\n %s", content.decode("utf-8")) + except Exception: # pylint: disable=broad-exception-caught + _openai_transport_logger.debug("Body (raw):\n %r", content) + else: + _openai_transport_logger.debug("Body: [Content exists]") + _openai_transport_logger.debug("\n") return response @@ -376,29 +471,32 @@ def _log_request_body(self, request: httpx.Request) -> None: # Check content-type header to identify file uploads content_type = request.headers.get("content-type", "").lower() if "multipart/form-data" in content_type: - print("Body: [Multipart form data - file upload, not logged]") + _openai_transport_logger.debug("Body: [Multipart form data - file upload, not logged]") return # Safely check if content exists without accessing it if not hasattr(request, "content"): - print("Body: [No content attribute]") + _openai_transport_logger.debug("Body: [No content attribute]") return # Very careful content access - wrap in try-catch immediately try: content = request.content except Exception as access_error: # pylint: disable=broad-exception-caught - print(f"Body: [Cannot access content: {access_error}]") + _openai_transport_logger.debug("Body: [Cannot access content: %s]", access_error) return if content is None or content == b"": - print("Body: [No content]") + _openai_transport_logger.debug("Body: [No content]") return - try: - print(f"Body:\n {content.decode('utf-8')}") - except Exception: # pylint: disable=broad-exception-caught - print(f"Body (raw):\n {content!r}") + if self._logging_enabled: + try: + _openai_transport_logger.debug("Body:\n %s", content.decode("utf-8")) + except Exception: # pylint: disable=broad-exception-caught + _openai_transport_logger.debug("Body (raw):\n %r", content) + else: + _openai_transport_logger.debug("Body: [Content exists]") __all__: List[str] = [ diff --git a/sdk/ai/azure-ai-projects/azure/ai/projects/_patch.pyi b/sdk/ai/azure-ai-projects/azure/ai/projects/_patch.pyi index 42009c1c227e..4fad0e185af6 100644 --- a/sdk/ai/azure-ai-projects/azure/ai/projects/_patch.pyi +++ b/sdk/ai/azure-ai-projects/azure/ai/projects/_patch.pyi @@ -10,6 +10,7 @@ Azure-specific grader types in addition to the standard OpenAI graders. import logging from typing import Any, Iterable, List, Union, Optional +import httpx from httpx import Timeout from openai import NotGiven, Omit, OpenAI as OpenAIClient from openai._types import Body, Query, Headers @@ -107,11 +108,23 @@ class AIProjectClient(AIProjectClientGenerated): # To make mypy happy... otherwise imports of the below result in mypy "attr-defined" error class _AuthSecretsFilter(logging.Filter): ... +class _OpenAIAuthSecretsFilter(logging.Filter): ... + +class _OpenAILoggingTransport: + def __init__(self, *, logging_enabled: bool) -> None: ... + def handle_request(self, request: httpx.Request) -> httpx.Response: ... + +class _LoggingSyncByteStream(httpx.SyncByteStream): + def __init__(self, stream: httpx.SyncByteStream) -> None: ... + +class _LoggingAsyncByteStream(httpx.AsyncByteStream): + def __init__(self, stream: httpx.AsyncByteStream) -> None: ... def _resolve_openai_base_url(config: Any, agent_name: Optional[str], kwargs: dict) -> str: ... def _resolve_openai_query_params(config: Any, agent_name: Optional[str], kwargs: dict) -> dict: ... def _resolve_openai_default_headers(agent_name: Optional[str], kwargs: dict) -> dict: ... def _build_openai_user_agent(custom_user_agent: Optional[str], openai_default_user_agent: str) -> str: ... +def _log_streaming_response_notice(logging_enabled: bool) -> bool: ... __all__: List[str] = ["AIProjectClient"] diff --git a/sdk/ai/azure-ai-projects/azure/ai/projects/aio/_patch.py b/sdk/ai/azure-ai-projects/azure/ai/projects/aio/_patch.py index ce80d545efa5..a9b0aa007166 100644 --- a/sdk/ai/azure-ai-projects/azure/ai/projects/aio/_patch.py +++ b/sdk/ai/azure-ai-projects/azure/ai/projects/aio/_patch.py @@ -10,15 +10,18 @@ import os import logging -from typing import List, Any, Optional +from typing import List, Any, Optional, cast import httpx # pylint: disable=networking-import-outside-azure-core-transport -from openai import AsyncOpenAI +from openai import AsyncOpenAI, DefaultAsyncHttpxClient from azure.core.tracing.decorator import distributed_trace from azure.core.credentials_async import AsyncTokenCredential from azure.identity.aio import get_bearer_token_provider from .._patch import ( _AuthSecretsFilter, + _OpenAIAuthSecretsFilter, + _LoggingAsyncByteStream, _build_openai_user_agent, + _log_streaming_response_notice, _resolve_openai_base_url, _resolve_openai_default_headers, _resolve_openai_query_params, @@ -26,7 +29,9 @@ from ._client import AIProjectClient as AIProjectClientGenerated from .operations import TelemetryOperations +_OPENAI_TRANSPORT_LOGGER_NAME = "azure.ai.projects.openai_transport" logger = logging.getLogger(__name__) +_openai_transport_logger = logging.getLogger(_OPENAI_TRANSPORT_LOGGER_NAME) class AIProjectClient(AIProjectClientGenerated): # pylint: disable=too-many-instance-attributes @@ -93,6 +98,7 @@ def __init__( azure_logger.setLevel(logging.DEBUG) console_handler = logging.StreamHandler(stream=sys.stdout) console_handler.addFilter(_AuthSecretsFilter()) + console_handler.addFilter(_OpenAIAuthSecretsFilter()) azure_logger.addHandler(console_handler) # Exclude detailed logs for network calls associated with getting Entra ID token. logging.getLogger("azure.identity").setLevel(logging.ERROR) @@ -101,6 +107,11 @@ def __init__( # (which are implemented as a separate logging policy) logging.getLogger("azure.core.pipeline.policies.http_logging_policy").setLevel(logging.ERROR) + openai_transport_logger = logging.getLogger(_OPENAI_TRANSPORT_LOGGER_NAME) + openai_transport_logger.setLevel(logging.DEBUG) + openai_transport_logger.propagate = False + openai_transport_logger.addHandler(console_handler) + kwargs.setdefault("logging_enable", self._console_logging_enabled) self._kwargs = kwargs.copy() @@ -135,9 +146,10 @@ def _get_openai_http_client(self, kwargs: dict): """ if "http_client" in kwargs: return kwargs.pop("http_client") - if self._console_logging_enabled: - return httpx.AsyncClient(transport=_OpenAILoggingTransport()) - return None + + logging_kwargs = getattr(self, "_kwargs", {}) + logging_enabled = bool(logging_kwargs.get("logging_enable", False)) + return DefaultAsyncHttpxClient(transport=_OpenAILoggingTransport(logging_enabled=logging_enabled)) @distributed_trace def get_openai_client( @@ -222,12 +234,18 @@ class _OpenAILoggingTransport(httpx.AsyncHTTPTransport): AZURE_AI_PROJECTS_CONSOLE_LOGGING environment variable. """ + def __init__(self, *, logging_enabled: bool) -> None: + super().__init__() + self._logging_enabled = logging_enabled + def _sanitize_auth_header(self, headers): """Sanitize authorization and api-key headers by redacting sensitive information. :param headers: Dictionary of HTTP headers to sanitize :type headers: dict """ + if self._logging_enabled: + return if "authorization" in headers: auth_value = headers["authorization"] @@ -236,6 +254,11 @@ def _sanitize_auth_header(self, headers): else: headers["authorization"] = "" + @staticmethod + def _is_streaming_response(response: httpx.Response) -> bool: + content_type = response.headers.get("content-type", "").lower() + return "text/event-stream" in content_type + async def handle_async_request(self, request: httpx.Request) -> httpx.Response: """ Log HTTP request and response details to console, in a nicely formatted way, @@ -248,31 +271,40 @@ async def handle_async_request(self, request: httpx.Request) -> httpx.Response: :rtype: httpx.Response """ - print(f"\n==> Request:\n{request.method} {request.url}") + _openai_transport_logger.debug("\n==> Request:\n%s %s", request.method, request.url) headers = dict(request.headers) self._sanitize_auth_header(headers) - print("Headers:") + _openai_transport_logger.debug("Headers:") for key, value in sorted(headers.items()): - print(f" {key}: {value}") + if not self._logging_enabled and key.lower() == "api-key": + value = "" + _openai_transport_logger.debug(" %s: %s", key, value) self._log_request_body(request) response = await super().handle_async_request(request) - print(f"\n<== Response:\n{response.status_code} {response.reason_phrase}") - print("Headers:") + _openai_transport_logger.debug("\n<== Response:\n%s %s", response.status_code, response.reason_phrase) + _openai_transport_logger.debug("Headers:") for key, value in sorted(dict(response.headers).items()): - print(f" {key}: {value}") + _openai_transport_logger.debug(" %s: %s", key, value) - content = await response.aread() - if content is None or content == b"": - print("Body: [No content]") + if self._is_streaming_response(response): + if _log_streaming_response_notice(self._logging_enabled): + response.stream = _LoggingAsyncByteStream(cast(httpx.AsyncByteStream, response.stream)) else: - try: - print(f"Body:\n {content.decode('utf-8')}") - except Exception: # pylint: disable=broad-exception-caught - print(f"Body (raw):\n {content!r}") - print("\n") + content = await response.aread() + if content is None or content == b"": + _openai_transport_logger.debug("Body: [No content]") + else: + if self._logging_enabled: + try: + _openai_transport_logger.debug("Body:\n %s", content.decode("utf-8")) + except Exception: # pylint: disable=broad-exception-caught + _openai_transport_logger.debug("Body (raw):\n %r", content) + else: + _openai_transport_logger.debug("Body: [Content exists]") + _openai_transport_logger.debug("\n") return response @@ -286,29 +318,32 @@ def _log_request_body(self, request: httpx.Request) -> None: # Check content-type header to identify file uploads content_type = request.headers.get("content-type", "").lower() if "multipart/form-data" in content_type: - print("Body: [Multipart form data - file upload, not logged]") + _openai_transport_logger.debug("Body: [Multipart form data - file upload, not logged]") return # Safely check if content exists without accessing it if not hasattr(request, "content"): - print("Body: [No content attribute]") + _openai_transport_logger.debug("Body: [No content attribute]") return # Very careful content access - wrap in try-catch immediately try: content = request.content except Exception as access_error: # pylint: disable=broad-exception-caught - print(f"Body: [Cannot access content: {access_error}]") + _openai_transport_logger.debug("Body: [Cannot access content: %s]", access_error) return if content is None or content == b"": - print("Body: [No content]") + _openai_transport_logger.debug("Body: [No content]") return - try: - print(f"Body:\n {content.decode('utf-8')}") - except Exception: # pylint: disable=broad-exception-caught - print(f"Body (raw):\n {content!r}") + if self._logging_enabled: + try: + _openai_transport_logger.debug("Body:\n %s", content.decode("utf-8")) + except Exception: # pylint: disable=broad-exception-caught + _openai_transport_logger.debug("Body (raw):\n %r", content) + else: + _openai_transport_logger.debug("Body: [Content exists]") __all__: List[str] = ["AIProjectClient"] # Add all objects you want publicly available to users at this package level diff --git a/sdk/ai/azure-ai-projects/azure/ai/projects/aio/_patch.pyi b/sdk/ai/azure-ai-projects/azure/ai/projects/aio/_patch.pyi index b23e4a17b334..95983692257c 100644 --- a/sdk/ai/azure-ai-projects/azure/ai/projects/aio/_patch.pyi +++ b/sdk/ai/azure-ai-projects/azure/ai/projects/aio/_patch.pyi @@ -9,6 +9,7 @@ Azure-specific grader types in addition to the standard OpenAI graders. """ from typing import Any, Iterable, List, Union, Optional +import httpx from httpx import Timeout from openai import NotGiven, Omit, AsyncOpenAI as AsyncOpenAIClient from openai._types import Body, Query, Headers @@ -104,6 +105,14 @@ class AIProjectClient(AIProjectClientGenerated): self, agent_name: Optional[str] = None, **kwargs: Any # pylint: disable=unused-argument ) -> AsyncOpenAI: ... +class _OpenAILoggingTransport: + def __init__(self, *, logging_enabled: bool) -> None: ... + async def handle_async_request(self, request: Any) -> Any: ... + +class _LoggingAsyncByteStream(httpx.AsyncByteStream): ... + +def _log_streaming_response_notice(logging_enabled: bool) -> bool: ... + # To make mypy happy... otherwise imports of the below result in mypy "attr-defined" error __all__: List[str] = ["AIProjectClient"] diff --git a/sdk/ai/azure-ai-projects/samples/logs/log_utils.py b/sdk/ai/azure-ai-projects/samples/logs/log_utils.py new file mode 100644 index 000000000000..e0dac50a2965 --- /dev/null +++ b/sdk/ai/azure-ai-projects/samples/logs/log_utils.py @@ -0,0 +1,15 @@ +# ------------------------------------ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT License. +# ------------------------------------ + +from datetime import datetime +from pathlib import Path +from tempfile import gettempdir +from typing import Union + + +def create_timestamped_temp_log_file(script_path: Union[str, Path]) -> Path: + script_path = Path(script_path) + timestamp = datetime.now().strftime("%Y%m%d_%H%M%S") + return Path(gettempdir()) / f"{script_path.stem}_{timestamp}.log" diff --git a/sdk/ai/azure-ai-projects/samples/logs/sample_log_all.py b/sdk/ai/azure-ai-projects/samples/logs/sample_log_all.py new file mode 100644 index 000000000000..f842d06a804d --- /dev/null +++ b/sdk/ai/azure-ai-projects/samples/logs/sample_log_all.py @@ -0,0 +1,82 @@ +# ------------------------------------ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT License. +# ------------------------------------ + +""" +DESCRIPTION: + This sample demonstrates how to capture both Azure-core HTTP logs and + OpenAI transport logs into a single file while running a Prompt Agent operation. + With logging_enable=True, all logs will include request bodies, response body, and token. + +USAGE: + python samples/logs/sample_log_all.py + + Before running the sample: + + pip install "azure-ai-projects>=2.5.0" python-dotenv + + Set these environment variables with your own values: + 1) FOUNDRY_PROJECT_ENDPOINT - The Azure AI Project endpoint. + 2) FOUNDRY_MODEL_NAME - The deployment name of the AI model. + 3) FOUNDRY_AGENT_NAME - Optional. Defaults to "MyAgent". + + This sample writes Azure-core and OpenAI transport logs to a timestamped temp log file. +""" + +import logging +import os + +from dotenv import load_dotenv +from azure.identity import DefaultAzureCredential +from azure.ai.projects import AIProjectClient +from azure.ai.projects.models import PromptAgentDefinition +from log_utils import create_timestamped_temp_log_file +from util import create_version_with_endpoint + +load_dotenv() + +LOG_FILE = create_timestamped_temp_log_file(__file__) + +file_handler = logging.FileHandler(filename=LOG_FILE, encoding="utf-8") + +# Logger for logs from azure-ai-projects SDK through Azure-core. +logger = logging.getLogger("azure") +logger.setLevel(logging.DEBUG) +logger.addHandler(file_handler) + +# Logger for logs from the OpenAI client. +openai_logger = logging.getLogger("azure.ai.projects.openai_transport") +openai_logger.setLevel(logging.DEBUG) +openai_logger.propagate = False +openai_logger.addHandler(file_handler) + +endpoint = os.environ["FOUNDRY_PROJECT_ENDPOINT"] +model = os.environ["FOUNDRY_MODEL_NAME"] +agent_name = os.environ.get("FOUNDRY_AGENT_NAME") or "MyAgent" +with ( + DefaultAzureCredential() as credential, + AIProjectClient(endpoint=endpoint, credential=credential, logging_enable=True) as project_client, +): + with ( + create_version_with_endpoint( + project_client=project_client, + agent_name=agent_name, + definition=PromptAgentDefinition( + model=model, + instructions="You are a helpful assistant.", + ), + ), + project_client.get_openai_client(agent_name=agent_name) as openai_client, + ): + conversation = openai_client.conversations.create( + items=[{"type": "message", "role": "user", "content": "How many feet are in a mile?"}], + ) + print(f"Conversation created (id: {conversation.id})") + + response = openai_client.responses.create(conversation=conversation.id) + print(f"Response output: {response.output_text}") + + openai_client.conversations.delete(conversation_id=conversation.id) + print("Conversation deleted") + print(f"Azure-core and OpenAI transport logs written to {LOG_FILE}") diff --git a/sdk/ai/azure-ai-projects/samples/logs/sample_log_from_openai_client.py b/sdk/ai/azure-ai-projects/samples/logs/sample_log_from_openai_client.py new file mode 100644 index 000000000000..f9c1458a0264 --- /dev/null +++ b/sdk/ai/azure-ai-projects/samples/logs/sample_log_from_openai_client.py @@ -0,0 +1,78 @@ +# ------------------------------------ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT License. +# ------------------------------------ + +""" +DESCRIPTION: + This sample demonstrates how to capture OpenAI transport logs from the + SDK-authenticated OpenAI client into a file while suppressing terminal output. + With logging_enable=True, all logs will include request bodies, response body, and token. + +USAGE: + python samples/logs/sample_log_from_openai_client.py + + Before running the sample: + + pip install "azure-ai-projects>=2.5.0" python-dotenv + + Set these environment variables with your own values: + 1) FOUNDRY_PROJECT_ENDPOINT - The Azure AI Project endpoint. + 2) FOUNDRY_MODEL_NAME - The deployment name of the AI model. + 3) FOUNDRY_AGENT_NAME - Optional. Defaults to "MyAgent". + + This sample writes OpenAI transport logs to a timestamped temp log file. +""" + +import logging +import os + +from dotenv import load_dotenv +from azure.identity import DefaultAzureCredential +from azure.ai.projects import AIProjectClient +from azure.ai.projects.models import PromptAgentDefinition +from log_utils import create_timestamped_temp_log_file +from util import create_version_with_endpoint + +load_dotenv() + +LOG_FILE = create_timestamped_temp_log_file(__file__) + +file_handler = logging.FileHandler(filename=LOG_FILE, encoding="utf-8") + +transport_logger = logging.getLogger("azure.ai.projects.openai_transport") +transport_logger.setLevel(logging.DEBUG) +transport_logger.propagate = False +transport_logger.addHandler(file_handler) + +endpoint = os.environ["FOUNDRY_PROJECT_ENDPOINT"] +model = os.environ["FOUNDRY_MODEL_NAME"] +agent_name = os.environ.get("FOUNDRY_AGENT_NAME") or "MyAgent" + +with ( + DefaultAzureCredential() as credential, + AIProjectClient(endpoint=endpoint, credential=credential, logging_enable=True) as project_client, +): + + with ( + create_version_with_endpoint( + project_client=project_client, + agent_name=agent_name, + definition=PromptAgentDefinition( + model=model, + instructions="You are a helpful assistant.", + ), + ), + project_client.get_openai_client(agent_name=agent_name) as openai_client, + ): + conversation = openai_client.conversations.create( + items=[{"type": "message", "role": "user", "content": "How many feet are in a mile?"}], + ) + print(f"Conversation created (id: {conversation.id})") + + response = openai_client.responses.create(conversation=conversation.id) + print(f"Response output: {response.output_text}") + + openai_client.conversations.delete(conversation_id=conversation.id) + print("Conversation deleted") + print(f"OpenAI transport logs written to {LOG_FILE}") diff --git a/sdk/ai/azure-ai-projects/samples/logs/sample_log_from_sdk.py b/sdk/ai/azure-ai-projects/samples/logs/sample_log_from_sdk.py new file mode 100644 index 000000000000..7d6a6b9d33d2 --- /dev/null +++ b/sdk/ai/azure-ai-projects/samples/logs/sample_log_from_sdk.py @@ -0,0 +1,78 @@ +# ------------------------------------ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT License. +# ------------------------------------ + +""" +DESCRIPTION: + This sample demonstrates how to capture Azure-core HTTP logs from the SDK + into a file while running a Prompt Agent operation. + With logging_enable=True, the Azure-core network trace logs include request bodies, response body, and token. + +USAGE: + python samples/logs/sample_log_from_sdk.py + + Before running the sample: + + pip install "azure-ai-projects>=2.5.0" python-dotenv + + Set these environment variables with your own values: + 1) FOUNDRY_PROJECT_ENDPOINT - The Azure AI Project endpoint. + 2) FOUNDRY_MODEL_NAME - The deployment name of the AI model. + 3) FOUNDRY_AGENT_NAME - Optional. Defaults to "MyAgent". + + This sample writes Azure-core logs to a timestamped temp log file. +""" + +import logging +import os + +from dotenv import load_dotenv +from azure.identity import DefaultAzureCredential +from azure.ai.projects import AIProjectClient +from azure.ai.projects.models import PromptAgentDefinition +from log_utils import create_timestamped_temp_log_file +from util import create_version_with_endpoint + +load_dotenv() + +LOG_FILE = create_timestamped_temp_log_file(__file__) + +logger = logging.getLogger("azure") +logger.setLevel(logging.DEBUG) + +transport_logger = logging.getLogger("azure.ai.projects.openai_transport") +transport_logger.propagate = False + +# Keep stdout available for sample prints while also writing SDK logs to a file. +file_handler = logging.FileHandler(filename=LOG_FILE, encoding="utf-8") +logger.addHandler(file_handler) + +endpoint = os.environ["FOUNDRY_PROJECT_ENDPOINT"] +model = os.environ["FOUNDRY_MODEL_NAME"] +agent_name = os.environ.get("FOUNDRY_AGENT_NAME") or "MyAgent" + +with ( + DefaultAzureCredential() as credential, + AIProjectClient(endpoint=endpoint, credential=credential, logging_enable=True) as project_client, + create_version_with_endpoint( + project_client=project_client, + agent_name=agent_name, + definition=PromptAgentDefinition( + model=model, + instructions="You are a helpful assistant.", + ), + ), + project_client.get_openai_client(agent_name=agent_name) as openai_client, +): + conversation = openai_client.conversations.create( + items=[{"type": "message", "role": "user", "content": "How many feet are in a mile?"}], + ) + print(f"Conversation created (id: {conversation.id})") + + response = openai_client.responses.create(conversation=conversation.id) + print(f"Response output: {response.output_text}") + + openai_client.conversations.delete(conversation_id=conversation.id) + print("Conversation deleted") + print(f"Azure-core logs written to {LOG_FILE}") diff --git a/sdk/ai/azure-ai-projects/samples/logs/sample_log_stream_events.py b/sdk/ai/azure-ai-projects/samples/logs/sample_log_stream_events.py new file mode 100644 index 000000000000..be364db74f49 --- /dev/null +++ b/sdk/ai/azure-ai-projects/samples/logs/sample_log_stream_events.py @@ -0,0 +1,82 @@ +# ------------------------------------ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT License. +# ------------------------------------ + +""" +DESCRIPTION: + This sample demonstrates how to capture Azure-core HTTP logs and OpenAI + transport logs into a file while running a streaming responses operation. + With logging_enable=True, request bodies, response metadata, and token are + included in the log file. Streamed response events are printed to the + console and are not automatically written to SDK logs. + + See also https://platform.openai.com/docs/guides/streaming-responses?api-mode=responses&lang=python + +USAGE: + python samples/logs/sample_log_stream_events.py + + Before running the sample: + + pip install "azure-ai-projects>=2.5.0" python-dotenv + + Set these environment variables with your own values: + 1) FOUNDRY_PROJECT_ENDPOINT - The Azure AI Project endpoint. + 2) FOUNDRY_MODEL_NAME - The deployment name of the AI model. + + This sample writes Azure-core and OpenAI transport logs to a timestamped temp log file. +""" + +import logging +import os + +from dotenv import load_dotenv + +from azure.ai.projects import AIProjectClient +from azure.identity import DefaultAzureCredential + +from log_utils import create_timestamped_temp_log_file + +load_dotenv() + +LOG_FILE = create_timestamped_temp_log_file(__file__) + +logger = logging.getLogger("azure") +logger.setLevel(logging.DEBUG) +logger.handlers.clear() + +# Keep stdout available for streamed sample output while also writing SDK logs to a file. +file_handler = logging.FileHandler(filename=LOG_FILE, encoding="utf-8") +logger.addHandler(file_handler) + +transport_logger = logging.getLogger("azure.ai.projects.openai_transport") +transport_logger.setLevel(logging.DEBUG) +transport_logger.propagate = False +transport_logger.addHandler(file_handler) + +endpoint = os.environ["FOUNDRY_PROJECT_ENDPOINT"] +model = os.environ["FOUNDRY_MODEL_NAME"] + +with ( + DefaultAzureCredential() as credential, + AIProjectClient(endpoint=endpoint, credential=credential, logging_enable=True) as project_client, + project_client.get_openai_client() as openai_client, +): + with openai_client.responses.create( + model=model, + input=[ + {"role": "user", "content": "Tell me about the capital city of France"}, + ], + stream=True, + ) as response_stream_events: + for event in response_stream_events: + if event.type == "response.created": + print(f"Stream response created with ID: {event.response.id}\n") + elif event.type == "response.output_text.delta": + print(event.delta, end="", flush=True) + elif event.type == "response.text.done": + print("\n\nResponse text done. Access final text in 'event.text'") + elif event.type == "response.completed": + print("\n\nResponse completed. Access final text in 'event.response.output_text'") + +print(f"Azure-core and OpenAI transport logs written to {LOG_FILE}") diff --git a/sdk/ai/azure-ai-projects/samples/logs/sample_log_stream_events_async.py b/sdk/ai/azure-ai-projects/samples/logs/sample_log_stream_events_async.py new file mode 100644 index 000000000000..112ef2a737ba --- /dev/null +++ b/sdk/ai/azure-ai-projects/samples/logs/sample_log_stream_events_async.py @@ -0,0 +1,90 @@ +# ------------------------------------ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT License. +# ------------------------------------ + +""" +DESCRIPTION: + This sample demonstrates how to capture Azure-core HTTP logs and OpenAI + transport logs into a file while running an asynchronous streaming responses + operation. With logging_enable=True, request bodies, response metadata, and + token are included in the log file. Streamed response events are printed to + the console and are not automatically written to SDK logs as parsed events. + + See also https://platform.openai.com/docs/guides/streaming-responses?api-mode=responses&lang=python + +USAGE: + python samples/logs/sample_log_stream_events_async.py + + Before running the sample: + + pip install "azure-ai-projects>=2.5.0" python-dotenv aiohttp + + Set these environment variables with your own values: + 1) FOUNDRY_PROJECT_ENDPOINT - The Azure AI Project endpoint. + 2) FOUNDRY_MODEL_NAME - The deployment name of the AI model. + + This sample writes Azure-core and OpenAI transport logs to a timestamped temp log file. +""" + +import asyncio +import logging +import os + +from dotenv import load_dotenv + +from azure.ai.projects.aio import AIProjectClient +from azure.identity.aio import DefaultAzureCredential + +from log_utils import create_timestamped_temp_log_file + +load_dotenv() + +LOG_FILE = create_timestamped_temp_log_file(__file__) + +logger = logging.getLogger("azure") +logger.setLevel(logging.DEBUG) +logger.handlers.clear() + +# Keep stdout available for streamed sample output while also writing SDK logs to a file. +file_handler = logging.FileHandler(filename=LOG_FILE, encoding="utf-8") +logger.addHandler(file_handler) + +transport_logger = logging.getLogger("azure.ai.projects.openai_transport") +transport_logger.setLevel(logging.DEBUG) +transport_logger.propagate = False +transport_logger.addHandler(file_handler) + +endpoint = os.environ["FOUNDRY_PROJECT_ENDPOINT"] +model = os.environ["FOUNDRY_MODEL_NAME"] + + +async def main() -> None: + async with ( + DefaultAzureCredential() as credential, + AIProjectClient(endpoint=endpoint, credential=credential, logging_enable=True) as project_client, + project_client.get_openai_client() as openai_client, + ): + stream_response = await openai_client.responses.create( + model=model, + input=[ + {"role": "user", "content": "Tell me about the capital city of France"}, + ], + stream=True, + ) + + async for event in stream_response: + if event.type == "response.created": + print(f"Stream response created with ID: {event.response.id}\n") + elif event.type == "response.output_text.delta": + print(event.delta, end="", flush=True) + elif event.type == "response.text.done": + print("\n\nResponse text done. Access final text in 'event.text'") + elif event.type == "response.completed": + print("\n\nResponse completed. Access final text in 'event.response.output_text'") + + print(f"Azure-core and OpenAI transport logs written to {LOG_FILE}") + + +if __name__ == "__main__": + asyncio.run(main()) diff --git a/sdk/ai/azure-ai-projects/samples/logs/sample_log_to_console.py b/sdk/ai/azure-ai-projects/samples/logs/sample_log_to_console.py new file mode 100644 index 000000000000..8cc2b82fba80 --- /dev/null +++ b/sdk/ai/azure-ai-projects/samples/logs/sample_log_to_console.py @@ -0,0 +1,67 @@ +# ------------------------------------ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT License. +# ------------------------------------ + +""" +DESCRIPTION: + This sample demonstrates how to capture both Azure-core HTTP logs and + OpenAI transport logs into a single file while running a Prompt Agent operation. + With logging_enable=False, the transport still logs request and response metadata, + but excludes request bodies and response bodies while keeping sensitive headers redacted. + +USAGE: + python samples/logs/sample_log_to_console.py + + Before running the sample: + + pip install "azure-ai-projects>=2.5.0" python-dotenv + + Set these environment variables with your own values: + 1) FOUNDRY_PROJECT_ENDPOINT - The Azure AI Project endpoint. + 2) FOUNDRY_MODEL_NAME - The deployment name of the AI model. + 3) FOUNDRY_AGENT_NAME - Optional. Defaults to "MyAgent". + + This sample writes Azure-core and OpenAI transport logs to the console. +""" + +import os + +from dotenv import load_dotenv +from azure.identity import DefaultAzureCredential +from azure.ai.projects import AIProjectClient +from azure.ai.projects.models import PromptAgentDefinition + +from util import create_version_with_endpoint + +load_dotenv() + +os.environ["AZURE_AI_PROJECTS_CONSOLE_LOGGING"] = "true" +endpoint = os.environ["FOUNDRY_PROJECT_ENDPOINT"] +model = os.environ["FOUNDRY_MODEL_NAME"] +agent_name = os.environ.get("FOUNDRY_AGENT_NAME") or "MyAgent" +with ( + DefaultAzureCredential() as credential, + AIProjectClient(endpoint=endpoint, credential=credential) as project_client, +): + with ( + create_version_with_endpoint( + project_client=project_client, + agent_name=agent_name, + definition=PromptAgentDefinition( + model=model, + instructions="You are a helpful assistant.", + ), + ), + project_client.get_openai_client(agent_name=agent_name) as openai_client, + ): + conversation = openai_client.conversations.create( + items=[{"type": "message", "role": "user", "content": "How many feet are in a mile?"}], + ) + print(f"Conversation created (id: {conversation.id})") + + response = openai_client.responses.create(conversation=conversation.id) + print(f"Response output: {response.output_text}") + + openai_client.conversations.delete(conversation_id=conversation.id) + print("Conversation deleted") diff --git a/sdk/ai/azure-ai-projects/samples/logs/sample_log_with_logging_disabled.py b/sdk/ai/azure-ai-projects/samples/logs/sample_log_with_logging_disabled.py new file mode 100644 index 000000000000..b0da20906e6f --- /dev/null +++ b/sdk/ai/azure-ai-projects/samples/logs/sample_log_with_logging_disabled.py @@ -0,0 +1,82 @@ +# ------------------------------------ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT License. +# ------------------------------------ + +""" +DESCRIPTION: + This sample demonstrates how to capture both Azure-core HTTP logs and + OpenAI transport logs into a single file while running a Prompt Agent operation. + With logging_enable=False, the transport still logs request and response metadata, + but excludes request bodies and response bodies while keeping sensitive headers redacted. + +USAGE: + python samples/logs/sample_log_with_logging_disabled.py + + Before running the sample: + + pip install "azure-ai-projects>=2.5.0" python-dotenv + + Set these environment variables with your own values: + 1) FOUNDRY_PROJECT_ENDPOINT - The Azure AI Project endpoint. + 2) FOUNDRY_MODEL_NAME - The deployment name of the AI model. + 3) FOUNDRY_AGENT_NAME - Optional. Defaults to "MyAgent". + + This sample writes Azure-core and OpenAI transport logs to a timestamped temp log file. +""" + +import logging +import os + +from dotenv import load_dotenv +from azure.identity import DefaultAzureCredential +from azure.ai.projects import AIProjectClient +from azure.ai.projects.models import PromptAgentDefinition +from log_utils import create_timestamped_temp_log_file +from util import create_version_with_endpoint + +load_dotenv() + +LOG_FILE = create_timestamped_temp_log_file(__file__) + +logger = logging.getLogger("azure") +logger.setLevel(logging.DEBUG) + +# Keep stdout available for sample prints while also writing SDK logs to a file. +file_handler = logging.FileHandler(filename=LOG_FILE, encoding="utf-8") +logger.addHandler(file_handler) + +transport_logger = logging.getLogger("azure.ai.projects.openai_transport") +transport_logger.setLevel(logging.DEBUG) +transport_logger.propagate = False +transport_logger.addHandler(file_handler) + +endpoint = os.environ["FOUNDRY_PROJECT_ENDPOINT"] +model = os.environ["FOUNDRY_MODEL_NAME"] +agent_name = os.environ.get("FOUNDRY_AGENT_NAME") or "MyAgent" +with ( + DefaultAzureCredential() as credential, + AIProjectClient(endpoint=endpoint, credential=credential, logging_enable=False) as project_client, +): + with ( + create_version_with_endpoint( + project_client=project_client, + agent_name=agent_name, + definition=PromptAgentDefinition( + model=model, + instructions="You are a helpful assistant.", + ), + ), + project_client.get_openai_client(agent_name=agent_name) as openai_client, + ): + conversation = openai_client.conversations.create( + items=[{"type": "message", "role": "user", "content": "How many feet are in a mile?"}], + ) + print(f"Conversation created (id: {conversation.id})") + + response = openai_client.responses.create(conversation=conversation.id) + print(f"Response output: {response.output_text}") + + openai_client.conversations.delete(conversation_id=conversation.id) + print("Conversation deleted") + print(f"Azure-core and OpenAI transport logs written to {LOG_FILE}") diff --git a/sdk/ai/azure-ai-projects/samples/logs/util.py b/sdk/ai/azure-ai-projects/samples/logs/util.py new file mode 100644 index 000000000000..133a25b840ec --- /dev/null +++ b/sdk/ai/azure-ai-projects/samples/logs/util.py @@ -0,0 +1,21 @@ +# ------------------------------------ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT License. +# ------------------------------------ + +"""Helpers shared by the direct-execution logging samples in this folder.""" + +from importlib.util import module_from_spec, spec_from_file_location +from pathlib import Path + +_SAMPLES_UTIL_PATH = Path(__file__).resolve().parents[1] / "util.py" + +_SPEC = spec_from_file_location("samples_shared_util", _SAMPLES_UTIL_PATH) +if _SPEC is None or _SPEC.loader is None: + raise ImportError(f"Unable to load shared samples util from {_SAMPLES_UTIL_PATH}") + +_MODULE = module_from_spec(_SPEC) +_SPEC.loader.exec_module(_MODULE) + +create_version_with_endpoint = _MODULE.create_version_with_endpoint +create_version_with_endpoint_async = _MODULE.create_version_with_endpoint_async diff --git a/sdk/ai/azure-ai-projects/tests/responses/openai_test_helpers.py b/sdk/ai/azure-ai-projects/tests/responses/openai_test_helpers.py index fbf3637291ea..10ad9a0b2fea 100644 --- a/sdk/ai/azure-ai-projects/tests/responses/openai_test_helpers.py +++ b/sdk/ai/azure-ai-projects/tests/responses/openai_test_helpers.py @@ -30,6 +30,7 @@ def make_sync_client( allow_preview: bool = True, console_logging: bool = False, + logging_enable: bool = False, custom_user_agent: Optional[str] = None, ) -> AIProjectClient: """Return a minimal sync AIProjectClient stub suitable for unit-testing get_openai_client.""" @@ -40,6 +41,7 @@ def make_sync_client( client._config.api_version = API_VERSION client._config.credential = MagicMock() client._console_logging_enabled = console_logging + client._kwargs = {"logging_enable": logging_enable} client._custom_user_agent = custom_user_agent return client @@ -47,6 +49,7 @@ def make_sync_client( def make_async_client( allow_preview: bool = True, console_logging: bool = False, + logging_enable: bool = False, custom_user_agent: Optional[str] = None, ) -> AsyncAIProjectClient: """Return a minimal async AIProjectClient stub suitable for unit-testing get_openai_client.""" @@ -57,6 +60,7 @@ def make_async_client( client._config.api_version = API_VERSION client._config.credential = MagicMock() client._console_logging_enabled = console_logging + client._kwargs = {"logging_enable": logging_enable} client._custom_user_agent = custom_user_agent return client diff --git a/sdk/ai/azure-ai-projects/tests/responses/test_client_logging.py b/sdk/ai/azure-ai-projects/tests/responses/test_client_logging.py new file mode 100644 index 000000000000..b23c38cbfd57 --- /dev/null +++ b/sdk/ai/azure-ai-projects/tests/responses/test_client_logging.py @@ -0,0 +1,311 @@ +# pylint: disable=line-too-long,useless-suppression +# ------------------------------------ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT License. +# ------------------------------------ +"""Unit tests for logger wiring and transport logging behavior.""" + +import logging +from pathlib import Path +from typing import Any +from unittest.mock import MagicMock, patch + +import httpx +import pytest +from azure.core.credentials import TokenCredential +from azure.ai.projects import AIProjectClient +from azure.ai.projects._patch import _OpenAIAuthSecretsFilter, _OpenAILoggingTransport + +from openai_test_helpers import SYNC_OPENAI_PATCH, SYNC_TOKEN_PROVIDER_PATCH, make_sync_client, mock_openai + + +class DummyTokenCredential(TokenCredential): + """A dummy credential that returns None for testing purposes.""" + + def get_token(self, *scopes: str, **kwargs: Any): # type: ignore[override] + return None + + +class _TestSyncByteStream(httpx.SyncByteStream): + def __init__(self, chunks): + self._chunks = chunks + + def __iter__(self): + yield from self._chunks + + +def _attach_file_handler(logger_name: str, log_file: Path) -> logging.FileHandler: + handler = logging.FileHandler(log_file, encoding="utf-8") + handler.setLevel(logging.DEBUG) + logger = logging.getLogger(logger_name) + logger.addHandler(handler) + logger.setLevel(logging.DEBUG) + return handler + + +def _read_log_file(handler: logging.FileHandler, log_file: Path) -> str: + handler.flush() + return log_file.read_text(encoding="utf-8") + + +def _assert_json_request_body(log_text: str, expected: bool) -> None: + marker = 'Body:\n {"message":"hello"}' + assert (marker in log_text) is expected + + +def _assert_json_response_body(log_text: str, expected: bool) -> None: + marker = 'Body:\n {"result":"ok"}' + assert (marker in log_text) is expected + + +def _assert_bearer_token_logging(log_text: str, logging_enabled: bool) -> None: + raw_token = "authorization: Bearer secret-token" + redacted_token = "authorization: Bearer " + assert (raw_token in log_text) is logging_enabled + assert (redacted_token in log_text) is (not logging_enabled) + + +@pytest.fixture +def restore_logger_state(): + logger_names = [ + "azure", + "azure.identity", + "azure.core.pipeline.policies.http_logging_policy", + "azure.ai.projects.openai_transport", + ] + original_state = {} + for logger_name in logger_names: + logger = logging.getLogger(logger_name) + original_state[logger_name] = { + "handlers": list(logger.handlers), + "level": logger.level, + "propagate": logger.propagate, + } + logger.handlers = [] + + yield + + for logger_name, state in original_state.items(): + logger = logging.getLogger(logger_name) + for handler in list(logger.handlers): + logger.removeHandler(handler) + try: + handler.close() + except Exception: # pylint: disable=broad-exception-caught + pass + logger.handlers = list(state["handlers"]) + logger.setLevel(state["level"]) + logger.propagate = state["propagate"] + + +def test_project_client_console_logging_configures_loggers(monkeypatch, restore_logger_state): + """Console logging should attach a shared stream handler and enable verbose logging.""" + monkeypatch.setenv("AZURE_AI_PROJECTS_CONSOLE_LOGGING", "true") + + with ( + patch("azure.ai.projects._patch.AIProjectClientGenerated.__init__", return_value=None), + patch("azure.ai.projects._patch.TelemetryOperations", return_value=MagicMock()), + ): + client = AIProjectClient(endpoint="https://example.com/api/projects/test", credential=DummyTokenCredential()) + + azure_logger = logging.getLogger("azure") + identity_logger = logging.getLogger("azure.identity") + http_logging_logger = logging.getLogger("azure.core.pipeline.policies.http_logging_policy") + transport_logger = logging.getLogger("azure.ai.projects.openai_transport") + + assert client._console_logging_enabled is True + assert client._kwargs["logging_enable"] is True + assert azure_logger.level == logging.DEBUG + assert identity_logger.level == logging.ERROR + assert http_logging_logger.level == logging.ERROR + assert transport_logger.level == logging.DEBUG + assert transport_logger.propagate is False + assert len(azure_logger.handlers) == 1 + assert len(transport_logger.handlers) == 1 + assert isinstance(azure_logger.handlers[0], logging.StreamHandler) + assert azure_logger.handlers[0] is transport_logger.handlers[0] + + +def test_openai_auth_secrets_filter_redacts_transport_headers() -> None: + filter_instance = _OpenAIAuthSecretsFilter() + record = logging.LogRecord( + name="azure.ai.projects.openai_transport", + level=logging.DEBUG, + pathname=__file__, + lineno=1, + msg="authorization: Bearer secret-token", + args=(), + exc_info=None, + ) + + assert filter_instance.filter(record) is True + assert record.getMessage() == "authorization: Bearer " + + +def test_project_client_without_console_logging_leaves_loggers_unwired(monkeypatch, restore_logger_state): + """Without the env flag, the constructor should not attach handlers or override logging_enable.""" + monkeypatch.delenv("AZURE_AI_PROJECTS_CONSOLE_LOGGING", raising=False) + + with ( + patch("azure.ai.projects._patch.AIProjectClientGenerated.__init__", return_value=None), + patch("azure.ai.projects._patch.TelemetryOperations", return_value=MagicMock()), + ): + client = AIProjectClient( + endpoint="https://example.com/api/projects/test", + credential=DummyTokenCredential(), + logging_enable=False, + ) + + assert client._console_logging_enabled is False + assert client._kwargs["logging_enable"] is False + assert logging.getLogger("azure").handlers == [] + assert logging.getLogger("azure.ai.projects.openai_transport").handlers == [] + + +def test_get_openai_client_logs_creation_message(tmp_path, restore_logger_state): + """Creating the OpenAI client should write the creation log message to the log file.""" + client = make_sync_client(logging_enable=False) + mock_cls, _ = mock_openai() + log_file = tmp_path / "openai_client.log" + handler = _attach_file_handler("azure.ai.projects.openai_transport", log_file) + + with ( + patch(SYNC_OPENAI_PATCH, mock_cls), + patch(SYNC_TOKEN_PROVIDER_PATCH, return_value="provider"), + ): + client.get_openai_client(agent_name="my-agent") + + log_text = _read_log_file(handler, log_file) + + assert log_file.exists() + assert "[get_openai_client] Creating OpenAI client using Entra ID authentication" in log_text + assert "/agents/my-agent/endpoint/protocols/openai" in log_text + + +def test_openai_transport_full_logging_writes_request_response_and_raw_token_to_file(tmp_path, restore_logger_state): + """With logging_enable=True, the log file should include request, response, JSON bodies, and the raw bearer token.""" + request = httpx.Request( + "POST", + "https://example.com/openai/v1/responses", + headers={"authorization": "Bearer secret-token", "content-type": "application/json"}, + content=b'{"message":"hello"}', + ) + response = httpx.Response( + 200, + request=request, + headers={"content-type": "application/json"}, + content=b'{"result":"ok"}', + ) + log_file = tmp_path / "transport_full.log" + handler = _attach_file_handler("azure.ai.projects.openai_transport", log_file) + + with patch.object(httpx.HTTPTransport, "handle_request", return_value=response): + result = _OpenAILoggingTransport(logging_enabled=True).handle_request(request) + + log_text = _read_log_file(handler, log_file) + + assert result is response + assert log_file.exists() + assert "==> Request:" in log_text + assert "<== Response:" in log_text + _assert_bearer_token_logging(log_text, logging_enabled=True) + _assert_json_request_body(log_text, expected=True) + _assert_json_response_body(log_text, expected=True) + assert "Body: [Content exists]" not in log_text + + +def test_openai_transport_reduced_logging_writes_metadata_only_to_file(tmp_path, restore_logger_state): + """With logging_enable=False, the log file should include metadata but not the raw bearer token or JSON bodies.""" + request = httpx.Request( + "POST", + "https://example.com/openai/v1/responses", + headers={"authorization": "Bearer secret-token", "content-type": "application/json"}, + content=b'{"message":"hello"}', + ) + response = httpx.Response( + 200, + request=request, + headers={"content-type": "application/json"}, + content=b'{"result":"ok"}', + ) + log_file = tmp_path / "transport_reduced.log" + handler = _attach_file_handler("azure.ai.projects.openai_transport", log_file) + + with patch.object(httpx.HTTPTransport, "handle_request", return_value=response): + result = _OpenAILoggingTransport(logging_enabled=False).handle_request(request) + + log_text = _read_log_file(handler, log_file) + + assert result is response + assert log_file.exists() + assert "==> Request:" in log_text + assert "<== Response:" in log_text + _assert_bearer_token_logging(log_text, logging_enabled=False) + _assert_json_request_body(log_text, expected=False) + _assert_json_response_body(log_text, expected=False) + assert log_text.count("Body: [Content exists]") == 2 + + +def test_openai_transport_streaming_response_skips_body_read_and_keeps_metadata(tmp_path, restore_logger_state): + """Streaming responses should keep metadata logging without buffering the response body.""" + request = httpx.Request( + "POST", + "https://example.com/openai/v1/responses", + headers={"authorization": "Bearer secret-token", "content-type": "application/json"}, + content=b'{"message":"hello"}', + ) + response = httpx.Response( + 200, + request=request, + headers={"content-type": "text/event-stream"}, + ) + log_file = tmp_path / "transport_streaming.log" + handler = _attach_file_handler("azure.ai.projects.openai_transport", log_file) + + with ( + patch.object(httpx.HTTPTransport, "handle_request", return_value=response), + patch.object(response, "read", side_effect=AssertionError("streaming response should not be read")), + ): + result = _OpenAILoggingTransport(logging_enabled=False).handle_request(request) + + log_text = _read_log_file(handler, log_file) + + assert result is response + assert "==> Request:" in log_text + assert "<== Response:" in log_text + _assert_bearer_token_logging(log_text, logging_enabled=False) + _assert_json_request_body(log_text, expected=False) + _assert_json_response_body(log_text, expected=False) + assert "Body: [Streaming content exists]" in log_text + + +def test_openai_transport_streaming_response_logs_chunks_lazily(tmp_path, restore_logger_state): + request = httpx.Request( + "POST", + "https://example.com/openai/v1/responses", + headers={"authorization": "Bearer secret-token", "content-type": "application/json"}, + content=b'{"message":"hello"}', + ) + response = httpx.Response( + 200, + request=request, + headers={"content-type": "text/event-stream"}, + stream=_TestSyncByteStream([b"data: first\n\n", b"data: second\n\n"]), + ) + log_file = tmp_path / "transport_streaming_lazy.log" + handler = _attach_file_handler("azure.ai.projects.openai_transport", log_file) + + with patch.object(httpx.HTTPTransport, "handle_request", return_value=response): + result = _OpenAILoggingTransport(logging_enabled=True).handle_request(request) + + log_text = _read_log_file(handler, log_file) + assert "Body: [Streaming response will be logged as consumed]" in log_text + assert "data: first" not in log_text + + consumed = b"".join(result.iter_bytes()) + log_text = _read_log_file(handler, log_file) + + assert consumed == b"data: first\n\ndata: second\n\n" + assert "Body chunk:\n data: first\n\n" in log_text + assert "Body chunk:\n data: second\n\n" in log_text + assert "Body: [Streaming response completed]" in log_text diff --git a/sdk/ai/azure-ai-projects/tests/responses/test_client_logging_async.py b/sdk/ai/azure-ai-projects/tests/responses/test_client_logging_async.py new file mode 100644 index 000000000000..fc232eacea29 --- /dev/null +++ b/sdk/ai/azure-ai-projects/tests/responses/test_client_logging_async.py @@ -0,0 +1,311 @@ +# pylint: disable=line-too-long,useless-suppression +# ------------------------------------ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT License. +# ------------------------------------ +"""Async unit tests for logger wiring and transport logging behavior.""" + +import logging +from pathlib import Path +from typing import Any +from unittest.mock import AsyncMock, MagicMock, patch + +import httpx +import pytest +from azure.core.credentials_async import AsyncTokenCredential +from azure.ai.projects.aio import AIProjectClient +from azure.ai.projects.aio._patch import _OpenAILoggingTransport + +from openai_test_helpers import ASYNC_OPENAI_PATCH, ASYNC_TOKEN_PROVIDER_PATCH, make_async_client, mock_openai + + +class DummyAsyncTokenCredential(AsyncTokenCredential): + """A dummy async credential that returns None for testing purposes.""" + + async def get_token(self, *scopes: str, **kwargs: Any): # type: ignore[override] + return None + + async def close(self) -> None: + pass + + +class _TestAsyncByteStream(httpx.AsyncByteStream): + def __init__(self, chunks): + self._chunks = chunks + + async def __aiter__(self): + for chunk in self._chunks: + yield chunk + + +def _attach_file_handler(logger_name: str, log_file: Path) -> logging.FileHandler: + handler = logging.FileHandler(log_file, encoding="utf-8") + handler.setLevel(logging.DEBUG) + logger = logging.getLogger(logger_name) + logger.addHandler(handler) + logger.setLevel(logging.DEBUG) + return handler + + +def _read_log_file(handler: logging.FileHandler, log_file: Path) -> str: + handler.flush() + return log_file.read_text(encoding="utf-8") + + +def _assert_json_request_body(log_text: str, expected: bool) -> None: + marker = 'Body:\n {"message":"hello"}' + assert (marker in log_text) is expected + + +def _assert_json_response_body(log_text: str, expected: bool) -> None: + marker = 'Body:\n {"result":"ok"}' + assert (marker in log_text) is expected + + +def _assert_bearer_token_logging(log_text: str, logging_enabled: bool) -> None: + raw_token = "authorization: Bearer secret-token" + redacted_token = "authorization: Bearer " + assert (raw_token in log_text) is logging_enabled + assert (redacted_token in log_text) is (not logging_enabled) + + +@pytest.fixture +def restore_logger_state(): + logger_names = [ + "azure", + "azure.identity", + "azure.core.pipeline.policies.http_logging_policy", + "azure.ai.projects.openai_transport", + ] + original_state = {} + for logger_name in logger_names: + logger = logging.getLogger(logger_name) + original_state[logger_name] = { + "handlers": list(logger.handlers), + "level": logger.level, + "propagate": logger.propagate, + } + logger.handlers = [] + + yield + + for logger_name, state in original_state.items(): + logger = logging.getLogger(logger_name) + for handler in list(logger.handlers): + logger.removeHandler(handler) + try: + handler.close() + except Exception: # pylint: disable=broad-exception-caught + pass + logger.handlers = list(state["handlers"]) + logger.setLevel(state["level"]) + logger.propagate = state["propagate"] + + +def test_project_client_console_logging_configures_loggers_async(monkeypatch, restore_logger_state): + """Console logging should attach a shared stream handler and enable verbose logging.""" + monkeypatch.setenv("AZURE_AI_PROJECTS_CONSOLE_LOGGING", "true") + + with ( + patch("azure.ai.projects.aio._patch.AIProjectClientGenerated.__init__", return_value=None), + patch("azure.ai.projects.aio._patch.TelemetryOperations", return_value=MagicMock()), + ): + client = AIProjectClient( + endpoint="https://example.com/api/projects/test", credential=DummyAsyncTokenCredential() + ) + + azure_logger = logging.getLogger("azure") + identity_logger = logging.getLogger("azure.identity") + http_logging_logger = logging.getLogger("azure.core.pipeline.policies.http_logging_policy") + transport_logger = logging.getLogger("azure.ai.projects.openai_transport") + + assert client._console_logging_enabled is True + assert client._kwargs["logging_enable"] is True + assert azure_logger.level == logging.DEBUG + assert identity_logger.level == logging.ERROR + assert http_logging_logger.level == logging.ERROR + assert transport_logger.level == logging.DEBUG + assert transport_logger.propagate is False + assert len(azure_logger.handlers) == 1 + assert len(transport_logger.handlers) == 1 + assert isinstance(azure_logger.handlers[0], logging.StreamHandler) + assert azure_logger.handlers[0] is transport_logger.handlers[0] + + +def test_project_client_without_console_logging_leaves_loggers_unwired_async(monkeypatch, restore_logger_state): + """Without the env flag, the constructor should not attach handlers or override logging_enable.""" + monkeypatch.delenv("AZURE_AI_PROJECTS_CONSOLE_LOGGING", raising=False) + + with ( + patch("azure.ai.projects.aio._patch.AIProjectClientGenerated.__init__", return_value=None), + patch("azure.ai.projects.aio._patch.TelemetryOperations", return_value=MagicMock()), + ): + client = AIProjectClient( + endpoint="https://example.com/api/projects/test", + credential=DummyAsyncTokenCredential(), + logging_enable=False, + ) + + assert client._console_logging_enabled is False + assert client._kwargs["logging_enable"] is False + assert logging.getLogger("azure").handlers == [] + assert logging.getLogger("azure.ai.projects.openai_transport").handlers == [] + + +def test_get_openai_client_logs_creation_message_async(tmp_path, restore_logger_state): + """Creating the AsyncOpenAI client should write the creation log message to the log file.""" + client = make_async_client(logging_enable=False) + mock_cls, _ = mock_openai() + log_file = tmp_path / "openai_client_async.log" + handler = _attach_file_handler("azure.ai.projects.aio._patch", log_file) + + with ( + patch(ASYNC_OPENAI_PATCH, mock_cls), + patch(ASYNC_TOKEN_PROVIDER_PATCH, return_value="provider"), + ): + client.get_openai_client(agent_name="my-agent") + + log_text = _read_log_file(handler, log_file) + + assert log_file.exists() + assert "[get_openai_client] Creating OpenAI client using Entra ID authentication" in log_text + assert "/agents/my-agent/endpoint/protocols/openai" in log_text + + +@pytest.mark.asyncio +async def test_openai_transport_full_logging_writes_request_response_and_raw_token_to_file_async( + tmp_path, restore_logger_state +): + """With logging_enable=True, the log file should include request, response, JSON bodies, and the raw bearer token.""" + request = httpx.Request( + "POST", + "https://example.com/openai/v1/responses", + headers={"authorization": "Bearer secret-token", "content-type": "application/json"}, + content=b'{"message":"hello"}', + ) + response = httpx.Response( + 200, + request=request, + headers={"content-type": "application/json"}, + content=b'{"result":"ok"}', + ) + log_file = tmp_path / "transport_full_async.log" + handler = _attach_file_handler("azure.ai.projects.openai_transport", log_file) + + with patch.object(httpx.AsyncHTTPTransport, "handle_async_request", new=AsyncMock(return_value=response)): + result = await _OpenAILoggingTransport(logging_enabled=True).handle_async_request(request) + + log_text = _read_log_file(handler, log_file) + + assert result is response + assert log_file.exists() + assert "==> Request:" in log_text + assert "<== Response:" in log_text + _assert_bearer_token_logging(log_text, logging_enabled=True) + _assert_json_request_body(log_text, expected=True) + _assert_json_response_body(log_text, expected=True) + assert "Body: [Content exists]" not in log_text + + +@pytest.mark.asyncio +async def test_openai_transport_reduced_logging_writes_metadata_only_to_file_async(tmp_path, restore_logger_state): + """With logging_enable=False, the log file should include metadata but not the raw bearer token or JSON bodies.""" + request = httpx.Request( + "POST", + "https://example.com/openai/v1/responses", + headers={"authorization": "Bearer secret-token", "content-type": "application/json"}, + content=b'{"message":"hello"}', + ) + response = httpx.Response( + 200, + request=request, + headers={"content-type": "application/json"}, + content=b'{"result":"ok"}', + ) + log_file = tmp_path / "transport_reduced_async.log" + handler = _attach_file_handler("azure.ai.projects.openai_transport", log_file) + + with patch.object(httpx.AsyncHTTPTransport, "handle_async_request", new=AsyncMock(return_value=response)): + result = await _OpenAILoggingTransport(logging_enabled=False).handle_async_request(request) + + log_text = _read_log_file(handler, log_file) + + assert result is response + assert log_file.exists() + assert "==> Request:" in log_text + assert "<== Response:" in log_text + _assert_bearer_token_logging(log_text, logging_enabled=False) + _assert_json_request_body(log_text, expected=False) + _assert_json_response_body(log_text, expected=False) + assert log_text.count("Body: [Content exists]") == 2 + + +@pytest.mark.asyncio +async def test_openai_transport_streaming_response_skips_body_read_and_keeps_metadata_async( + tmp_path, restore_logger_state +): + """Streaming responses should keep metadata logging without buffering the response body.""" + request = httpx.Request( + "POST", + "https://example.com/openai/v1/responses", + headers={"authorization": "Bearer secret-token", "content-type": "application/json"}, + content=b'{"message":"hello"}', + ) + response = httpx.Response( + 200, + request=request, + headers={"content-type": "text/event-stream"}, + ) + log_file = tmp_path / "transport_streaming_async.log" + handler = _attach_file_handler("azure.ai.projects.openai_transport", log_file) + + with ( + patch.object(httpx.AsyncHTTPTransport, "handle_async_request", new=AsyncMock(return_value=response)), + patch.object( + response, "aread", new=AsyncMock(side_effect=AssertionError("streaming response should not be read")) + ), + ): + result = await _OpenAILoggingTransport(logging_enabled=False).handle_async_request(request) + + log_text = _read_log_file(handler, log_file) + + assert result is response + assert "==> Request:" in log_text + assert "<== Response:" in log_text + _assert_bearer_token_logging(log_text, logging_enabled=False) + _assert_json_request_body(log_text, expected=False) + _assert_json_response_body(log_text, expected=False) + assert "Body: [Streaming content exists]" in log_text + + +@pytest.mark.asyncio +async def test_openai_transport_streaming_response_logs_chunks_lazily_async(tmp_path, restore_logger_state): + request = httpx.Request( + "POST", + "https://example.com/openai/v1/responses", + headers={"authorization": "Bearer secret-token", "content-type": "application/json"}, + content=b'{"message":"hello"}', + ) + response = httpx.Response( + 200, + request=request, + headers={"content-type": "text/event-stream"}, + stream=_TestAsyncByteStream([b"data: first\n\n", b"data: second\n\n"]), + ) + log_file = tmp_path / "transport_streaming_lazy_async.log" + handler = _attach_file_handler("azure.ai.projects.openai_transport", log_file) + + with patch.object(httpx.AsyncHTTPTransport, "handle_async_request", new=AsyncMock(return_value=response)): + result = await _OpenAILoggingTransport(logging_enabled=True).handle_async_request(request) + + log_text = _read_log_file(handler, log_file) + assert "Body: [Streaming response will be logged as consumed]" in log_text + assert "data: first" not in log_text + + consumed_parts = [chunk async for chunk in result.aiter_bytes()] + log_text = _read_log_file(handler, log_file) + + assert b"".join(consumed_parts) == b"data: first\n\ndata: second\n\n" + assert "Body chunk:\n data: first\n\n" in log_text + assert "Body chunk:\n data: second\n\n" in log_text + assert "Body: [Streaming response completed]" in log_text diff --git a/sdk/ai/azure-ai-projects/tests/responses/test_openai_client_overrides.py b/sdk/ai/azure-ai-projects/tests/responses/test_openai_client_overrides.py index e0895ae552ca..912fcc4520e5 100644 --- a/sdk/ai/azure-ai-projects/tests/responses/test_openai_client_overrides.py +++ b/sdk/ai/azure-ai-projects/tests/responses/test_openai_client_overrides.py @@ -179,25 +179,34 @@ def test_caller_api_key_skips_token_provider(self): class TestHttpClientBranches: - def test_http_client_is_none_by_default(self): - """Branch: no override + console logging off -> http_client is None.""" - client = make_sync_client(console_logging=False) + def test_logging_disabled_still_creates_logging_transport(self): + """Branch: no override + logging disabled -> OpenAI default sync client with reduced logging transport.""" + client = make_sync_client(console_logging=False, logging_enable=False) mock_cls, _ = mock_openai() - with patch(SYNC_OPENAI_PATCH, mock_cls), patch(SYNC_TOKEN_PROVIDER_PATCH, return_value="tok"): + with ( + patch(SYNC_OPENAI_PATCH, mock_cls), + patch(SYNC_TOKEN_PROVIDER_PATCH, return_value="tok"), + patch("azure.ai.projects._patch.DefaultHttpxClient") as mock_default_http_client, + patch("azure.ai.projects._patch._OpenAILoggingTransport") as mock_transport, + ): + mock_transport.return_value = object() + mock_default_http_client.return_value = object() client.get_openai_client() - for c in mock_cls.call_args_list: - assert c.kwargs["http_client"] is None + mock_default_http_client.assert_called_once_with(transport=mock_transport.return_value) + mock_transport.assert_called_once_with(logging_enabled=False) - def test_console_logging_creates_logging_transport(self): - """Branch: no override + _console_logging_enabled=True -> httpx.Client with logging transport.""" - client = make_sync_client(console_logging=True) + def test_logging_enable_creates_logging_transport_without_console_logging(self): + """Branch: constructor logging_enable=True -> OpenAI default sync client with logging transport.""" + client = make_sync_client(console_logging=False, logging_enable=True) mock_cls, _ = mock_openai() with ( patch(SYNC_OPENAI_PATCH, mock_cls), patch(SYNC_TOKEN_PROVIDER_PATCH, return_value="tok"), - patch("azure.ai.projects._patch.httpx") as mock_httpx, - patch("azure.ai.projects._patch._OpenAILoggingTransport"), + patch("azure.ai.projects._patch.DefaultHttpxClient") as mock_default_http_client, + patch("azure.ai.projects._patch._OpenAILoggingTransport") as mock_transport, ): - mock_httpx.Client.return_value = object() + mock_transport.return_value = object() + mock_default_http_client.return_value = object() client.get_openai_client() - mock_httpx.Client.assert_called_once() + mock_default_http_client.assert_called_once_with(transport=mock_transport.return_value) + mock_transport.assert_called_once_with(logging_enabled=True) diff --git a/sdk/ai/azure-ai-projects/tests/responses/test_openai_client_overrides_async.py b/sdk/ai/azure-ai-projects/tests/responses/test_openai_client_overrides_async.py index 220dc961d22a..f13198441b9c 100644 --- a/sdk/ai/azure-ai-projects/tests/responses/test_openai_client_overrides_async.py +++ b/sdk/ai/azure-ai-projects/tests/responses/test_openai_client_overrides_async.py @@ -189,26 +189,35 @@ async def test_caller_api_key_skips_token_provider(self): class TestHttpClientBranchesAsync: @pytest.mark.asyncio - async def test_http_client_is_none_by_default(self): - """Branch: no override + console logging off -> http_client is None.""" - client = make_async_client(console_logging=False) + async def test_logging_disabled_still_creates_async_logging_transport(self): + """Branch: no override + logging disabled -> OpenAI default async client with reduced logging transport.""" + client = make_async_client(console_logging=False, logging_enable=False) mock_cls, _ = mock_openai() - with patch(ASYNC_OPENAI_PATCH, mock_cls), patch(ASYNC_TOKEN_PROVIDER_PATCH, return_value="tok"): + with ( + patch(ASYNC_OPENAI_PATCH, mock_cls), + patch(ASYNC_TOKEN_PROVIDER_PATCH, return_value="tok"), + patch("azure.ai.projects.aio._patch.DefaultAsyncHttpxClient") as mock_default_http_client, + patch("azure.ai.projects.aio._patch._OpenAILoggingTransport") as mock_transport, + ): + mock_transport.return_value = object() + mock_default_http_client.return_value = object() client.get_openai_client() - for c in mock_cls.call_args_list: - assert c.kwargs["http_client"] is None + mock_default_http_client.assert_called_once_with(transport=mock_transport.return_value) + mock_transport.assert_called_once_with(logging_enabled=False) @pytest.mark.asyncio - async def test_console_logging_creates_async_logging_transport(self): - """Branch: no override + _console_logging_enabled=True -> httpx.AsyncClient with logging transport.""" - client = make_async_client(console_logging=True) + async def test_logging_enable_creates_async_logging_transport_without_console_logging(self): + """Branch: constructor logging_enable=True -> OpenAI default async client with logging transport.""" + client = make_async_client(console_logging=False, logging_enable=True) mock_cls, _ = mock_openai() with ( patch(ASYNC_OPENAI_PATCH, mock_cls), patch(ASYNC_TOKEN_PROVIDER_PATCH, return_value="tok"), - patch("azure.ai.projects.aio._patch.httpx") as mock_httpx, - patch("azure.ai.projects.aio._patch._OpenAILoggingTransport"), + patch("azure.ai.projects.aio._patch.DefaultAsyncHttpxClient") as mock_default_http_client, + patch("azure.ai.projects.aio._patch._OpenAILoggingTransport") as mock_transport, ): - mock_httpx.AsyncClient.return_value = object() + mock_transport.return_value = object() + mock_default_http_client.return_value = object() client.get_openai_client() - mock_httpx.AsyncClient.assert_called_once() + mock_default_http_client.assert_called_once_with(transport=mock_transport.return_value) + mock_transport.assert_called_once_with(logging_enabled=True) diff --git a/sdk/ai/azure-ai-projects/tests/samples/README.md b/sdk/ai/azure-ai-projects/tests/samples/README.md index a8c2ba7916cd..610e9b4f5b17 100644 --- a/sdk/ai/azure-ai-projects/tests/samples/README.md +++ b/sdk/ai/azure-ai-projects/tests/samples/README.md @@ -11,22 +11,16 @@ Use recorded tests to validate samples with `SyncSampleExecutor` and `AsyncSampl ## Sample test logging -Optionally enable logging to capture sample execution results in log files (useful for monitoring and alerting): - -```bash -# In .env - uncomment to enable logging -SAMPLE_TEST_ERROR_LOG=_errors_.log -SAMPLE_TEST_FAILED_LOG=_failed_.log -SAMPLE_TEST_PASSED_LOG=_success_.log -``` +In live mode, sample execution always writes a log file to the system temp directory. Log types: -- **`SAMPLE_TEST_ERROR_LOG`**: Sample crashed with an exception during execution -- **`SAMPLE_TEST_FAILED_LOG`**: Sample ran successfully but LLM validation failed (incorrect output) -- **`SAMPLE_TEST_PASSED_LOG`**: Sample ran successfully and LLM validation passed (correct output) +- `*_errors_.log`: Sample crashed with an exception during execution +- `*_failed_.log`: Sample ran successfully but LLM validation failed (incorrect output) +- `*_success_.log`: Sample ran successfully and LLM validation passed (correct output) +- `*_output_.log`: Captured `print()` output only, without SDK debug log entries -Logs are written to the system's temp directory with the specified filename format. Each log includes the sample path, status/error details, exception traceback (for errors), and all captured print statements. +Logs are written to the system's temp directory with those fixed filename templates. The `*_errors_*`, `*_failed_*`, and `*_success_*` logs include the sample path, status/error details, exception traceback (for errors), and all captured print/debug statements. The `*_output_*` log contains only captured `print()` output. ## Sync example @@ -231,7 +225,7 @@ executor = SyncSampleExecutor( Behavior: -- **Samples in the allowlist:** Pass the test even when LLM validation fails. A warning message is printed to the console, and a failed report is still generated (if `SAMPLE_TEST_FAILED_LOG` is configured in `.env`). +- **Samples in the allowlist:** Pass the test even when LLM validation fails. A warning message is printed to the console, and a failed report is still generated. - **Samples not in the allowlist:** Fail the test when LLM validation fails (existing behavior). - **All samples:** Execution errors (exceptions) always fail the test, regardless of the allowlist. diff --git a/sdk/ai/azure-ai-projects/tests/samples/llm-analyze.py b/sdk/ai/azure-ai-projects/tests/samples/llm-analyze.py index aee1c9b7c86b..d1d29ae03eee 100644 --- a/sdk/ai/azure-ai-projects/tests/samples/llm-analyze.py +++ b/sdk/ai/azure-ai-projects/tests/samples/llm-analyze.py @@ -7,16 +7,17 @@ Example: python .\\tests\\samples\\llm-analyze.py --sample-path="samples\\agents\\tools\\sample_agent_file_search.py" \ - --foundry_project_endpoint="https://foundy6maq.services.ai.azure.com/api/projects/project6maq" \ - --foundry_model_name="gpt-5" \ - --llm_endpoint="https://foundy6maq.services.ai.azure.com/api/projects/project6maq", \ - --llm_model_name="gpt-5" + --foundry_project_endpoint="https://.services.ai.azure.com/api/projects/" \ + --foundry_model_name="gpt-5.2" \ + --llm_endpoint="https://.services.ai.azure.com/api/projects/" \ + --llm_model_name="gpt-5.2" Example JSON output: { "correct": true, "llm_comment": "Execution completed successfully with substantive output.", "log_file": "C:\\Users\\\\AppData\\Local\\Temp\\sample_agent_file_search_success_.log", + "print_output_file": "C:\\Users\\\\AppData\\Local\\Temp\\sample_agent_file_search_output_.log", "duration": 117.912 } @@ -60,12 +61,7 @@ from sample_executor import AsyncSampleExecutor, SyncSampleExecutor # pylint: disable=wrong-import-position from test_base import patched_open_crlf_to_lf # pylint: disable=wrong-import-position -LOG_FILE_PATTERNS = { - "AZURE_TEST_RUN_LIVE": "true", - "SAMPLE_TEST_PASSED_LOG": "_success_.log", - "SAMPLE_TEST_FAILED_LOG": "_failed_.log", - "SAMPLE_TEST_ERROR_LOG": "_errors_.log", -} +LIVE_MODE_ENV = {"AZURE_TEST_RUN_LIVE": "true"} class _CredentialProvider: @@ -88,9 +84,12 @@ class _CliSampleExecutor(SyncSampleExecutor): def __init__(self, *args, **kwargs): super().__init__(*args, **kwargs) self.log_file_path: str | None = None + self.print_output_file_path: str | None = None def _capture_print(self, *args, **_kwargs): - self.print_calls.append(" ".join(str(arg) for arg in args)) + text = " ".join(str(arg) for arg in args) + self.print_calls.append(text) + self.print_output_calls.append(text) def _write_error_log(self, reason: str, exception_info: str) -> str | None: self.log_file_path = super()._write_error_log(reason, exception_info) @@ -104,6 +103,10 @@ def _write_passed_log(self, reason: str = "Validation passed") -> str | None: self.log_file_path = super()._write_passed_log(reason) return self.log_file_path + def _write_output_log(self) -> str | None: + self.print_output_file_path = super()._write_output_log() + return self.print_output_file_path + def validate_print_calls_by_llm(self, *, endpoint: str, model: str, instructions: str | None = None) -> dict: instructions = self._resolve_validation_instructions(instructions) response = None @@ -159,9 +162,12 @@ class _CliAsyncSampleExecutor(AsyncSampleExecutor): def __init__(self, *args, **kwargs): super().__init__(*args, **kwargs) self.log_file_path: str | None = None + self.print_output_file_path: str | None = None def _capture_print(self, *args, **_kwargs): - self.print_calls.append(" ".join(str(arg) for arg in args)) + text = " ".join(str(arg) for arg in args) + self.print_calls.append(text) + self.print_output_calls.append(text) def _write_error_log(self, reason: str, exception_info: str) -> str | None: self.log_file_path = super()._write_error_log(reason, exception_info) @@ -175,6 +181,10 @@ def _write_passed_log(self, reason: str = "Validation passed") -> str | None: self.log_file_path = super()._write_passed_log(reason) return self.log_file_path + def _write_output_log(self) -> str | None: + self.print_output_file_path = super()._write_output_log() + return self.print_output_file_path + async def validate_print_calls_by_llm_async( self, *, endpoint: str, model: str, instructions: str | None = None ) -> dict: @@ -288,11 +298,12 @@ def _clean_cli_value(value: str) -> str: return args, env_vars -def _build_result(report: dict, *, log_file: str | None, start_time: float) -> dict: +def _build_result(report: dict, *, log_file: str | None, print_output_file: str | None, start_time: float) -> dict: return { "correct": report.get("correct", False), "llm_comment": report.get("reason"), "log_file": log_file, + "print_output_file": print_output_file, "duration": round(time.perf_counter() - start_time, 3), } @@ -302,7 +313,7 @@ def _run_sync_sample(sample_path: str, args: argparse.Namespace, env_vars: dict[ executor = _CliSampleExecutor( _CredentialProvider(credential), sample_path, - env_vars={**LOG_FILE_PATTERNS, **env_vars}, + env_vars={**LIVE_MODE_ENV, **env_vars}, ) try: with _suppress_terminal_output(): @@ -310,7 +321,13 @@ def _run_sync_sample(sample_path: str, args: argparse.Namespace, env_vars: dict[ report = executor.validate_print_calls_by_llm(endpoint=args.llm_endpoint, model=args.llm_model_name) except Exception as ex: # pylint: disable=broad-exception-caught report = {"correct": False, "reason": f"Sample execution failed: {type(ex).__name__}: {ex}"} - return _build_result(report, log_file=executor.log_file_path, start_time=start_time) + print_output_file = executor.print_output_file_path + return _build_result( + report, + log_file=executor.log_file_path, + print_output_file=print_output_file, + start_time=start_time, + ) async def _run_async_sample( @@ -320,7 +337,7 @@ async def _run_async_sample( executor = _CliAsyncSampleExecutor( _AsyncCredentialProvider(credential), sample_path, - env_vars={**LOG_FILE_PATTERNS, **env_vars}, + env_vars={**LIVE_MODE_ENV, **env_vars}, ) try: with _suppress_terminal_output(): @@ -331,7 +348,13 @@ async def _run_async_sample( ) except Exception as ex: # pylint: disable=broad-exception-caught report = {"correct": False, "reason": f"Sample execution failed: {type(ex).__name__}: {ex}"} - return _build_result(report, log_file=executor.log_file_path, start_time=start_time) + print_output_file = executor.print_output_file_path + return _build_result( + report, + log_file=executor.log_file_path, + print_output_file=print_output_file, + start_time=start_time, + ) def main() -> int: @@ -340,7 +363,7 @@ def main() -> int: str((PROJECT_ROOT / args.sample_path).resolve()) if not os.path.isabs(args.sample_path) else args.sample_path ) start_time = time.perf_counter() - with _temporary_env(LOG_FILE_PATTERNS): + with _temporary_env(LIVE_MODE_ENV): result = ( asyncio.run(_run_async_sample(sample_path, args, env_vars, start_time)) if sample_path.endswith("_async.py") diff --git a/sdk/ai/azure-ai-projects/tests/samples/sample_executor.py b/sdk/ai/azure-ai-projects/tests/samples/sample_executor.py index ccc291443da7..6e1ae8af78c2 100644 --- a/sdk/ai/azure-ai-projects/tests/samples/sample_executor.py +++ b/sdk/ai/azure-ai-projects/tests/samples/sample_executor.py @@ -197,6 +197,7 @@ def __init__( self.test_instance = test_instance self.sample_path = sample_path self.print_calls: list[str] = [] + self.print_output_calls: list[str] = [] self._original_print = print self.allowed_llm_validation_failures = allowed_llm_validation_failures or set() self._validation_text_preprocessor = validation_text_preprocessor @@ -235,6 +236,7 @@ def _capture_print(self, *args, **kwargs): """Capture print calls while still outputting to console.""" text = " ".join(str(arg) for arg in args) self.print_calls.append(text) + self.print_output_calls.append(text) self._original_print(*args, **kwargs) @contextmanager @@ -259,8 +261,6 @@ def __init__(self, sink: list[str]): self._included_logger_prefixes = ( "azure", "msrest", - "openai", - "httpx", ) def emit(self, record: logging.LogRecord) -> None: @@ -279,10 +279,9 @@ def emit(self, record: logging.LogRecord) -> None: "azure", "azure.core", "azure.core.pipeline.policies.http_logging_policy", + "azure.ai.projects.openai_transport", "msrest", "msrest.http_logger", - "httpx", - "openai", ] previous_logger_levels: dict[str, int] = {} @@ -308,14 +307,22 @@ def _always_true(_level, _logger=module_logger): continue capture_handler = _PrintCaptureLogHandler(self.print_calls) - capture_handler.setFormatter(logging.Formatter("[%(name)s] %(message)s")) + capture_handler.setFormatter(logging.Formatter("%(message)s")) root_logger.setLevel(logging.DEBUG) root_logger.addHandler(capture_handler) + directly_attached_loggers = [] + for logger_name in ("azure.ai.projects.openai_transport",): + logger_instance = logging.getLogger(logger_name) + logger_instance.addHandler(capture_handler) + directly_attached_loggers.append(logger_instance) + try: yield finally: + for logger_instance in directly_attached_loggers: + logger_instance.removeHandler(capture_handler) root_logger.removeHandler(capture_handler) root_logger.setLevel(previous_root_level) @@ -325,29 +332,17 @@ def _always_true(_level, _logger=module_logger): for module_logger, original_is_enabled_for in patched_is_enabled_for: module_logger.isEnabledFor = original_is_enabled_for - def _get_log_file_path(self, log_env_var: str) -> Optional[str]: - """Get and prepare log file path based on environment variable. + def _build_live_log_file_path(self, suffix: str) -> Optional[str]: + """Build a live-mode sample log path in the system temp directory.""" - Args: - log_env_var: Environment variable name to check for log format - - Returns: - Path to the log file (cleaned up and ready to write), or None if logging is disabled - """ # Only create logs in live mode if not _is_live_mode(): return None - # Only log if environment variable is set - log_format = os.environ.get(log_env_var) - if not log_format: - return None - timestamp = datetime.now().strftime("%Y%m%d_%H%M%S") sample_filename = os.path.basename(self.sample_path).replace(".py", "") - # Replace placeholders in the format template - log_filename = log_format.replace("", sample_filename).replace("", timestamp) + log_filename = f"{sample_filename}_{suffix}_{timestamp}.log" log_file = os.path.join(tempfile.gettempdir(), log_filename) # Remove existing file if present to ensure clean overwrite @@ -356,6 +351,17 @@ def _get_log_file_path(self, log_env_var: str) -> Optional[str]: return log_file + def _get_sample_display_path(self) -> str: + """Get the sample path relative to the package root when possible.""" + + current_dir = os.path.dirname(os.path.abspath(__file__)) + package_root = os.path.normpath(os.path.join(current_dir, os.pardir, os.pardir)) + + try: + return os.path.relpath(self.sample_path, package_root) + except ValueError: + return self.sample_path + def _write_error_log(self, reason: str, exception_info: str) -> Optional[str]: """Write captured print statements to a log file for execution errors. @@ -366,21 +372,23 @@ def _write_error_log(self, reason: str, exception_info: str) -> Optional[str]: Returns: Path to the created log file, or None if logging is disabled """ - log_file = self._get_log_file_path("SAMPLE_TEST_ERROR_LOG") + log_file = self._build_live_log_file_path("errors") if not log_file: return None + self._write_output_log() + sample_display_path = self._get_sample_display_path() + with open(log_file, "w", encoding="utf-8") as f: - f.write(f"Sample: {self.sample_path}\n") + f.write(f"Sample: {sample_display_path}\n") f.write(f"Execution Error:\n{reason}\n\n") f.write("Exception Details:\n") f.write("=" * 80 + "\n") f.write(exception_info) f.write("\n" + "=" * 80 + "\n\n") - f.write("Print Statements:\n") + f.write("API Logs and Print Statements:\n") f.write("=" * 80 + "\n") - for i, print_call in enumerate(self.print_calls, 1): - f.write(f"{i}. {print_call}\n") + self._write_numbered_print_calls(f) return log_file def _write_failed_log(self, reason: str) -> Optional[str]: @@ -392,17 +400,19 @@ def _write_failed_log(self, reason: str) -> Optional[str]: Returns: Path to the created log file, or None if logging is disabled """ - log_file = self._get_log_file_path("SAMPLE_TEST_FAILED_LOG") + log_file = self._build_live_log_file_path("failed") if not log_file: return None + self._write_output_log() + sample_display_path = self._get_sample_display_path() + with open(log_file, "w", encoding="utf-8") as f: - f.write(f"Sample: {self.sample_path}\n") + f.write(f"Sample: {sample_display_path}\n") f.write(f"Validation Failed: {reason}\n\n") - f.write("Print Statements:\n") + f.write("API Logs and Print Statements:\n") f.write("=" * 80 + "\n") - for i, print_call in enumerate(self.print_calls, 1): - f.write(f"{i}. {print_call}\n") + self._write_numbered_print_calls(f) return log_file def _write_passed_log(self, reason: str = "Validation passed") -> Optional[str]: @@ -414,19 +424,99 @@ def _write_passed_log(self, reason: str = "Validation passed") -> Optional[str]: Returns: Path to the created log file, or None if logging is disabled """ - log_file = self._get_log_file_path("SAMPLE_TEST_PASSED_LOG") + log_file = self._build_live_log_file_path("success") if not log_file: return None + self._write_output_log() + sample_display_path = self._get_sample_display_path() + with open(log_file, "w", encoding="utf-8") as f: - f.write(f"Sample: {self.sample_path}\n") + f.write(f"Sample: {sample_display_path}\n") f.write(f"Validation Passed: {reason}\n\n") - f.write("Print Statements:\n") + f.write("API Logs and Print Statements:\n") f.write("=" * 80 + "\n") - for i, print_call in enumerate(self.print_calls, 1): - f.write(f"{i}. {print_call}\n") + self._write_numbered_print_calls(f) return log_file + def _write_output_log(self) -> Optional[str]: + """Write captured print-only output to a live-mode temp log file.""" + log_file = self._build_live_log_file_path("output") + if not log_file: + return None + + sample_display_path = self._get_sample_display_path() + + with open(log_file, "w", encoding="utf-8") as file_handle: + file_handle.write(f"Sample: {sample_display_path}\n") + file_handle.write("Print Output:\n") + file_handle.write("=" * 80 + "\n") + if self.print_output_calls: + for print_call in self.print_output_calls: + file_handle.write(f"{print_call}\n") + else: + file_handle.write("(No print() output was captured before the sample stopped.)\n") + return log_file + + def _write_numbered_print_calls(self, file_handle) -> None: + """Write captured entries with numbering anchored to the first meaningful line.""" + + numbered_index = 0 + current_block: list[str] = [] + + labeled_block_prefixes = ( + "Request URL:", + "Request method:", + "Request headers:", + "Request body:", + "Response status:", + "Response headers:", + "Response content:", + ) + + def _starts_labeled_block(line: str) -> bool: + stripped = line.strip() + return any(stripped.startswith(prefix) for prefix in labeled_block_prefixes) + + def _current_block_is_labeled() -> bool: + return bool(current_block) and _starts_labeled_block(current_block[0]) + + def _flush_current_block() -> None: + nonlocal numbered_index, current_block + if not current_block: + return + numbered_index += 1 + file_handle.write(f"{numbered_index}. {current_block[0]}\n") + for line in current_block[1:]: + file_handle.write(f"{line}\n") + current_block = [] + + for print_call in self.print_calls: + lines = print_call.splitlines() + while lines and not lines[0].strip(): + lines.pop(0) + + if not lines: + _flush_current_block() + numbered_index += 1 + file_handle.write(f"{numbered_index}.\n") + continue + + for line_index, line in enumerate(lines): + if _starts_labeled_block(line): + _flush_current_block() + current_block = [line] + continue + + if current_block and (line[:1].isspace() or (_current_block_is_labeled() and line_index > 0)): + current_block.append(line) + continue + + _flush_current_block() + current_block = [line] + + _flush_current_block() + def _get_validation_request_params( self, instructions: str,