diff --git a/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/AgentFrameworkResponseHandler.cs b/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/AgentFrameworkResponseHandler.cs index c294baaf00e..69a05053a1f 100644 --- a/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/AgentFrameworkResponseHandler.cs +++ b/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/AgentFrameworkResponseHandler.cs @@ -27,6 +27,7 @@ using ResponseOutputItemDoneEvent = Azure.AI.AgentServer.Responses.Models.ResponseOutputItemDoneEvent; namespace Microsoft.Agents.AI.Foundry.Hosting; +#pragma warning disable SYSLIB1006 // Preserve the legacy EventId 0 for every migrated log message. /// /// A implementation that bridges the Azure AI Responses Server SDK @@ -34,7 +35,7 @@ namespace Microsoft.Agents.AI.Foundry.Hosting; /// to be hosted as Azure Foundry Hosted Agents. /// [Experimental(DiagnosticIds.Experiments.AgentsAIExperiments)] -public class AgentFrameworkResponseHandler : ResponseHandler +public partial class AgentFrameworkResponseHandler : ResponseHandler { private const string LatestWorkflowCheckpointIdMetadataKey = "_last_checkpoint_id"; private const string UserPartitionName = "user"; @@ -484,10 +485,7 @@ await PersistWorkflowCheckpointAsync( // Catch agent execution errors and emit a proper failed event // with the real error message instead of letting the SDK emit // a generic "An internal server error occurred." - if (this._logger.IsEnabled(LogLevel.Error)) - { - this._logger.LogError(ex, "Agent execution failed for response {ResponseId}.", context.ResponseId); - } + LogAgentExecutionFailed(this._logger, context.ResponseId, ex); failedEvent = stream.EmitFailed( ResponseErrorCode.ServerError, @@ -549,13 +547,13 @@ await PersistWorkflowCheckpointAsync( // preserve the existing behavior and emit incomplete. if (isResilientTurn) { - this._logger.LogInformation("Shutdown detected on a resilient turn; deferring for recovery."); + LogShutdownDeferredForRecovery(this._logger); deferredForRecovery = true; await context.ExitForRecoveryAsync(cancellationToken).ConfigureAwait(false); yield break; } - this._logger.LogInformation("Shutdown detected, emitting incomplete response."); + LogShutdownEmittingIncomplete(this._logger); yield return stream.EmitIncomplete(); yield break; } @@ -566,12 +564,7 @@ await PersistWorkflowCheckpointAsync( // same conversation. Finish the current response cleanly so Core can drain the // queued input as a new handler invocation. The MAF AgentSession is saved in the // outer finally block and becomes the starting state for that invocation. - if (this._logger.IsEnabled(LogLevel.Information)) - { - this._logger.LogInformation( - "Steering input detected for response {ResponseId}; completing the active turn.", - context.ResponseId); - } + LogSteeringInputDetected(this._logger, context.ResponseId); emittedTerminal = true; yield return stream.EmitCompleted(); yield break; @@ -613,13 +606,7 @@ await PersistWorkflowCheckpointAsync( } catch (Exception ex) when (ex is not OperationCanceledException) { - if (this._logger.IsEnabled(LogLevel.Debug)) - { - this._logger.LogDebug( - ex, - "Incremental session save was skipped for response {ResponseId}; the end-of-turn save will persist the final state.", - context.ResponseId); - } + LogIncrementalSessionSaveSkipped(this._logger, context.ResponseId, ex); } } @@ -663,12 +650,7 @@ await sessionStore.SaveSessionAsync( if (notAllowedStoreUsageDetected) { - if (this._logger.IsEnabled(LogLevel.Error)) - { - this._logger.LogError( - "Agent '{AgentName}' should not have server side storage enabled. This produced a new untracked conversation/response in the server while the hosted agent also generated a conversation for the request of the agent.", - agent.Name); - } + LogServerSideStorageNotAllowed(this._logger, agent.Name); throw HostedStoredOutputCompatibility.CreateMisconfiguredAgentError(); } @@ -702,14 +684,11 @@ await sessionStore.SaveSessionAsync( } catch (Exception ex) when (ex is not OperationCanceledException) { - if (this._logger.IsEnabled(LogLevel.Debug)) - { - this._logger.LogDebug( - ex, - "Workflow checkpoint {CheckpointId} was not paired with response {ResponseId} because its AgentSession could not be saved.", - checkpoint.CheckpointId, - context.ResponseId); - } + LogWorkflowCheckpointNotPaired( + this._logger, + checkpoint.CheckpointId, + context.ResponseId, + ex); return null; } @@ -832,14 +811,7 @@ await toolboxService } catch (InvalidOperationException ex) { - if (this._logger.IsEnabled(LogLevel.Warning)) - { - this._logger.LogWarning( - ex, - "Foundry toolbox '{ToolboxName}' could not be resolved for response {ResponseId}.", - name, - responseId); - } + LogToolboxResolutionFailed(this._logger, name, responseId, ex); // A resolution error fails the request even when earlier markers collected consents. return new(Tools: [], Consents: [], Error: ex.Message); @@ -960,14 +932,11 @@ private bool AreConsentLinksAllowed(IEnumerable consents, string { if (!policy.IsAllowed(consent.ConsentUrl)) { - if (this._logger.IsEnabled(LogLevel.Warning)) - { - this._logger.LogWarning( - "OAuth consent request for tool '{ToolName}' in toolbox '{ToolboxName}' was rejected by the consent link policy for response {ResponseId}.", - consent.ToolName, - consent.ToolboxName, - responseId); - } + LogConsentLinkRejected( + this._logger, + consent.ToolName, + consent.ToolboxName, + responseId); return false; } @@ -1019,10 +988,7 @@ private AIAgent ResolveAgent(CreateResponse request) return this.PrepareResolvedAgent(agent, storageIdentity); } - if (this._logger.IsEnabled(LogLevel.Warning)) - { - this._logger.LogWarning("Agent '{AgentName}' not found in keyed services. Attempting default resolution.", agentName); - } + LogKeyedAgentNotFound(this._logger, agentName); } // Try non-keyed default @@ -1072,10 +1038,7 @@ private AgentSessionStore ResolveSessionStore(CreateResponse request) return sessionStore; } - if (this._logger.IsEnabled(LogLevel.Warning)) - { - this._logger.LogWarning("SessionStore for agent '{AgentName}' not found in keyed services. Attempting default resolution.", agentName); - } + LogKeyedSessionStoreNotFound(this._logger, agentName); } // Try non-keyed default @@ -1121,4 +1084,58 @@ private readonly record struct ToolboxRequestResolution( IReadOnlyList Tools, IReadOnlyList Consents, string? Error); + + [LoggerMessage( + EventId = 0, + Level = LogLevel.Error, + Message = "Agent execution failed for response {ResponseId}.")] + private static partial void LogAgentExecutionFailed( + ILogger logger, + string responseId, + Exception exception); + + [LoggerMessage(LogLevel.Information, "Shutdown detected on a resilient turn; deferring for recovery.", EventId = 0)] + private static partial void LogShutdownDeferredForRecovery(ILogger logger); + + [LoggerMessage(LogLevel.Information, "Shutdown detected, emitting incomplete response.", EventId = 0)] + private static partial void LogShutdownEmittingIncomplete(ILogger logger); + + [LoggerMessage(LogLevel.Information, "Steering input detected for response {ResponseId}; completing the active turn.", EventId = 0)] + private static partial void LogSteeringInputDetected(ILogger logger, string responseId); + + [LoggerMessage(LogLevel.Debug, "Incremental session save was skipped for response {ResponseId}; the end-of-turn save will persist the final state.", EventId = 0)] + private static partial void LogIncrementalSessionSaveSkipped( + ILogger logger, + string responseId, + Exception exception); + + [LoggerMessage(LogLevel.Error, "Agent '{AgentName}' should not have server side storage enabled. This produced a new untracked conversation/response in the server while the hosted agent also generated a conversation for the request of the agent.", EventId = 0)] + private static partial void LogServerSideStorageNotAllowed(ILogger logger, string? agentName); + + [LoggerMessage(LogLevel.Debug, "Workflow checkpoint {CheckpointId} was not paired with response {ResponseId} because its AgentSession could not be saved.", EventId = 0)] + private static partial void LogWorkflowCheckpointNotPaired( + ILogger logger, + string checkpointId, + string responseId, + Exception exception); + + [LoggerMessage(LogLevel.Warning, "Foundry toolbox '{ToolboxName}' could not be resolved for response {ResponseId}.", EventId = 0)] + private static partial void LogToolboxResolutionFailed( + ILogger logger, + string toolboxName, + string responseId, + Exception exception); + + [LoggerMessage(LogLevel.Warning, "OAuth consent request for tool '{ToolName}' in toolbox '{ToolboxName}' was rejected by the consent link policy for response {ResponseId}.", EventId = 0)] + private static partial void LogConsentLinkRejected( + ILogger logger, + string toolName, + string toolboxName, + string responseId); + + [LoggerMessage(LogLevel.Warning, "Agent '{AgentName}' not found in keyed services. Attempting default resolution.", EventId = 0)] + private static partial void LogKeyedAgentNotFound(ILogger logger, string agentName); + + [LoggerMessage(LogLevel.Warning, "SessionStore for agent '{AgentName}' not found in keyed services. Attempting default resolution.", EventId = 0)] + private static partial void LogKeyedSessionStoreNotFound(ILogger logger, string agentName); } diff --git a/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/FoundryAgentSessionStore.cs b/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/FoundryAgentSessionStore.cs index 77e04a9bf5a..667f8947c1d 100644 --- a/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/FoundryAgentSessionStore.cs +++ b/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/FoundryAgentSessionStore.cs @@ -51,7 +51,7 @@ namespace Microsoft.Agents.AI.Foundry.Hosting; /// /// [Experimental(DiagnosticIds.Experiments.AgentsAIExperiments)] -public sealed class FoundryAgentSessionStore : AgentSessionStore +public sealed partial class FoundryAgentSessionStore : AgentSessionStore { /// /// The default state-store name used to hold every agent session persisted by this store. @@ -211,14 +211,7 @@ await store.DeleteItemAsync( catch (FoundryStorageNotFoundException ex) { // Nothing stored for this key, so deletion remains idempotent. - if (this._logger.IsEnabled(LogLevel.Debug)) - { - this._logger.LogDebug( - ex, - "Session '{SessionId}' was not found in the Foundry state store '{StoreName}'. Nothing to delete.", - key.SessionId, - this.StoreName); - } + LogSessionNotFound(this._logger, key.SessionId, this.StoreName, ex); } } @@ -232,4 +225,11 @@ private ValueTask GetStoreAsync(CancellationToken cancellatio private static BinaryData ToBinaryData(JsonElement element) => FoundryStateStoreJson.ToBinaryData(element); private static BinaryData ToJsonString(string value) => FoundryStateStoreJson.ToJsonString(value); + + [LoggerMessage(LogLevel.Debug, "Session '{SessionId}' was not found in the Foundry state store '{StoreName}'. Nothing to delete.", EventId = 0)] + private static partial void LogSessionNotFound( + ILogger logger, + string sessionId, + string storeName, + Exception exception); } diff --git a/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/FoundryJsonCheckpointStore.cs b/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/FoundryJsonCheckpointStore.cs index ab45d07010b..3563dee0364 100644 --- a/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/FoundryJsonCheckpointStore.cs +++ b/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/FoundryJsonCheckpointStore.cs @@ -18,6 +18,7 @@ using Microsoft.Shared.Diagnostics; namespace Microsoft.Agents.AI.Foundry.Hosting; +#pragma warning disable SYSLIB1006 // Preserve the legacy EventId 0 for every migrated log message. /// /// Provides a that persists workflow checkpoints through @@ -56,7 +57,7 @@ namespace Microsoft.Agents.AI.Foundry.Hosting; /// /// [Experimental(DiagnosticIds.Experiments.AgentsAIExperiments)] -public sealed class FoundryJsonCheckpointStore : JsonCheckpointStore +public sealed partial class FoundryJsonCheckpointStore : JsonCheckpointStore { /// /// The default state-store name used to hold every workflow checkpoint persisted by this store. @@ -243,15 +244,15 @@ await store.SetItemAsync( // Another writer added a checkpoint to the same session between the read and the // write. The checkpoint item is already stored under its own key, so the next // attempt simply re-reads the index and appends to the newer list. - if (this._logger?.IsEnabled(LogLevel.Debug) is true) + if (this._logger is { } logger) { - this._logger.LogDebug( - ex, - "Attempt {Attempt} of {MaxAttempts} to index checkpoint '{CheckpointId}' for session '{SessionId}' lost to another writer. Retrying.", + LogCheckpointIndexRaceRetry( + logger, attempt + 1, this._maxIndexUpdateAttempts, checkpointInfo.CheckpointId, - sessionId); + sessionId, + ex); } continue; @@ -384,13 +385,13 @@ entry.ParentCheckpointId is null || catch (FoundryStorageNotFoundException ex) { // Already deleted, by an earlier attempt or another instance. - if (this._logger?.IsEnabled(LogLevel.Debug) is true) + if (this._logger is { } logger) { - this._logger.LogDebug( - ex, - "Obsolete checkpoint '{CheckpointId}' of session '{SessionId}' was already gone.", + LogObsoleteCheckpointAlreadyGone( + logger, entry.CheckpointId, - sessionId); + sessionId, + ex); } } } @@ -399,12 +400,9 @@ entry.ParentCheckpointId is null || { // Another instance updated the same session index first. Leaving the old items in place // is safer than deleting against a stale index; a later resume can prune them. - if (this._logger?.IsEnabled(LogLevel.Debug) is true) + if (this._logger is { } logger) { - this._logger.LogDebug( - ex, - "Pruning obsolete checkpoints of session '{SessionId}' lost to another writer. The old checkpoints remain until a later resume or expiry.", - sessionId); + LogCheckpointPruningRace(logger, sessionId, ex); } } catch (FoundryStorageException ex) @@ -414,11 +412,10 @@ entry.ParentCheckpointId is null || // so failing the resume over housekeeping would break a conversation that was about to // carry on. It is reported instead, because left unreported this is how a session's // checkpoints would silently pile up until the index no longer fits. - this._logger?.LogWarning( - ex, - "Could not prune obsolete checkpoints of session '{SessionId}' in the Foundry state store '{StoreName}'. The resume itself succeeded; the leftovers stay until the store's own expiry removes them.", - sessionId, - this.StoreName); + if (this._logger is { } logger) + { + LogCheckpointPruningFailed(logger, sessionId, this.StoreName, ex); + } } } @@ -611,4 +608,33 @@ private static string HashKeyParts(params string[] parts) } private sealed record IndexEntry(string CheckpointId, string? ParentCheckpointId, bool HasParentMetadata); + + [LoggerMessage(LogLevel.Debug, "Attempt {Attempt} of {MaxAttempts} to index checkpoint '{CheckpointId}' for session '{SessionId}' lost to another writer. Retrying.", EventId = 0)] + private static partial void LogCheckpointIndexRaceRetry( + ILogger logger, + int attempt, + int maxAttempts, + string checkpointId, + string sessionId, + Exception exception); + + [LoggerMessage(LogLevel.Debug, "Obsolete checkpoint '{CheckpointId}' of session '{SessionId}' was already gone.", EventId = 0)] + private static partial void LogObsoleteCheckpointAlreadyGone( + ILogger logger, + string checkpointId, + string sessionId, + Exception exception); + + [LoggerMessage(LogLevel.Debug, "Pruning obsolete checkpoints of session '{SessionId}' lost to another writer. The old checkpoints remain until a later resume or expiry.", EventId = 0)] + private static partial void LogCheckpointPruningRace( + ILogger logger, + string sessionId, + Exception exception); + + [LoggerMessage(LogLevel.Warning, "Could not prune obsolete checkpoints of session '{SessionId}' in the Foundry state store '{StoreName}'. The resume itself succeeded; the leftovers stay until the store's own expiry removes them.", EventId = 0)] + private static partial void LogCheckpointPruningFailed( + ILogger logger, + string sessionId, + string storeName, + Exception exception); } diff --git a/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/FoundryToolboxService.cs b/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/FoundryToolboxService.cs index 87cbc0dad35..ba2b988f27e 100644 --- a/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/FoundryToolboxService.cs +++ b/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/FoundryToolboxService.cs @@ -21,6 +21,7 @@ using ModelContextProtocol.Client; namespace Microsoft.Agents.AI.Foundry.Hosting; +#pragma warning disable SYSLIB1006 // Preserve the legacy EventId 0 for every migrated log message. /// /// An that eagerly connects to the Foundry Toolboxes MCP proxy at @@ -55,7 +56,7 @@ namespace Microsoft.Agents.AI.Foundry.Hosting; /// /// [Experimental(DiagnosticIds.Experiments.AgentsAIExperiments)] -public sealed class FoundryToolboxService : IHostedService, IAsyncDisposable +public sealed partial class FoundryToolboxService : IHostedService, IAsyncDisposable { private readonly FoundryToolboxOptions _options; private readonly TokenCredential _credential; @@ -161,8 +162,7 @@ public async Task StartAsync(CancellationToken cancellationToken) if (string.IsNullOrEmpty(projectEndpoint)) { - this._logger.LogWarning( - "Neither FOUNDRY_PROJECT_ENDPOINT nor AZURE_AI_PROJECT_ENDPOINT is set; toolbox support is disabled."); + LogToolboxSupportDisabled(this._logger); this.Tools = []; this.StartupStatus = FoundryToolboxStartupStatus.NoEndpoint; return; @@ -175,7 +175,7 @@ public async Task StartAsync(CancellationToken cancellationToken) if (this._options.ToolboxNames.Count == 0) { - this._logger.LogInformation("No pre-registered toolbox names configured."); + LogNoPreRegisteredToolboxes(this._logger); this.Tools = []; this.StartupStatus = FoundryToolboxStartupStatus.Healthy; return; @@ -202,13 +202,7 @@ public async Task StartAsync(CancellationToken cancellationToken) // per-request, and retry enumeration once the user has consented. this._pendingConsents[toolboxName] = consents; - if (this._logger.IsEnabled(LogLevel.Information)) - { - this._logger.LogInformation( - "Toolbox '{ToolboxName}' requires user OAuth consent before its tools can be enumerated. " + - "The container stays ready; the consent prompt is surfaced to the caller per-request.", - toolboxName); - } + LogToolboxRequiresConsent(this._logger, toolboxName); continue; } @@ -227,14 +221,7 @@ public async Task StartAsync(CancellationToken cancellationToken) // yet. Rather than failing readiness and bricking the container, keep it routable and // defer the toolbox: it is retried per-request via RetryDeferredToolboxesAsync, where // the user context is available and enumeration can succeed (or surface consent). - if (this._logger.IsEnabled(LogLevel.Warning)) - { - this._logger.LogWarning( - ex, - "Toolbox '{ToolboxName}' could not be enumerated at startup; deferring it to per-request resolution. " + - "The container stays ready and the toolbox is retried on the next request when the per-user context is available.", - toolboxName); - } + LogToolboxStartupEnumerationDeferred(this._logger, toolboxName, ex); deferred.Add(toolboxName); } @@ -329,13 +316,7 @@ internal async ValueTask> ResolvePendingConsentsAs { // Transient/other error: leave the toolbox pending so a later request retries. // Do not surface a consent prompt (we have no URL); proceed without these tools. - if (this._logger.IsEnabled(LogLevel.Warning)) - { - this._logger.LogWarning( - ex, - "Retry of consent-gated toolbox '{ToolboxName}' failed; it remains pending.", - toolboxName); - } + LogConsentGatedToolboxRetryFailed(this._logger, toolboxName, ex); } } @@ -399,13 +380,7 @@ internal async ValueTask RetryDeferredToolboxesAsync(CancellationToken cancellat catch (Exception ex) when (ex is not OperationCanceledException) { // Still failing — keep it deferred and retry on a later request. - if (this._logger.IsEnabled(LogLevel.Warning)) - { - this._logger.LogWarning( - ex, - "Retry of deferred toolbox '{ToolboxName}' failed; it remains deferred.", - toolboxName); - } + LogDeferredToolboxRetryFailed(this._logger, toolboxName, ex); } } } @@ -693,15 +668,12 @@ private void RecordDisposalFailure( List failures) { failures.Add(exception); - if (this._logger.IsEnabled(LogLevel.Warning)) - { - this._logger.LogWarning( - exception, - "Failed to dispose {Resource} for toolbox {ToolboxName} owned by {Owner}.", - resource, - toolboxName ?? "(none)", - owner); - } + LogToolboxResourceDisposalFailed( + this._logger, + resource, + toolboxName ?? "(none)", + owner, + exception); } /// @@ -829,10 +801,7 @@ private async Task OpenToolboxAsync( var proxyUrl = $"{this._resolvedEndpoint!}/toolboxes/{toolboxName}/mcp?api-version={this._options.ApiVersion}"; - if (this._logger.IsEnabled(LogLevel.Information)) - { - this._logger.LogInformation("Connecting to toolbox '{ToolboxName}' at {ProxyUrl}.", toolboxName, proxyUrl); - } + LogConnectingToToolbox(this._logger, toolboxName, proxyUrl); // Build the endpoint URI before allocating the HttpClient so a malformed URL cannot leak it. var endpoint = new Uri(proxyUrl); @@ -897,13 +866,7 @@ private async Task OpenToolboxAsync( throw; } - if (this._logger.IsEnabled(LogLevel.Information)) - { - this._logger.LogInformation( - "Toolbox '{ToolboxName}': discovered {ToolCount} tool(s).", - toolboxName, - mcpTools.Count); - } + LogToolboxToolsDiscovered(this._logger, toolboxName, mcpTools.Count); var wrapped = new List(mcpTools.Count); foreach (var tool in mcpTools) @@ -953,10 +916,7 @@ internal bool RequiresToolApproval(AIFunction tool, string toolboxName) } } - this._logger.LogWarning( - "Tool '{ToolName}' in toolbox '{ToolboxName}' has an unsupported approval configuration; requiring approval for every call.", - tool.Name, - toolboxName); + LogUnsupportedToolApprovalConfiguration(this._logger, tool.Name, toolboxName); return true; } @@ -1036,4 +996,57 @@ internal sealed record CachedToolbox(McpClient? Client, HttpClient HttpClient, I /// when enumeration is blocked pending user OAuth consent. /// internal sealed record ToolboxOpenResult(CachedToolbox? Cached, IReadOnlyList? Consents); + + [LoggerMessage(LogLevel.Warning, "Neither FOUNDRY_PROJECT_ENDPOINT nor AZURE_AI_PROJECT_ENDPOINT is set; toolbox support is disabled.", EventId = 0)] + private static partial void LogToolboxSupportDisabled(ILogger logger); + + [LoggerMessage(LogLevel.Information, "No pre-registered toolbox names configured.", EventId = 0)] + private static partial void LogNoPreRegisteredToolboxes(ILogger logger); + + [LoggerMessage(LogLevel.Information, "Toolbox '{ToolboxName}' requires user OAuth consent before its tools can be enumerated. The container stays ready; the consent prompt is surfaced to the caller per-request.", EventId = 0)] + private static partial void LogToolboxRequiresConsent(ILogger logger, string toolboxName); + + [LoggerMessage(LogLevel.Warning, "Toolbox '{ToolboxName}' could not be enumerated at startup; deferring it to per-request resolution. The container stays ready and the toolbox is retried on the next request when the per-user context is available.", EventId = 0)] + private static partial void LogToolboxStartupEnumerationDeferred( + ILogger logger, + string toolboxName, + Exception exception); + + [LoggerMessage(LogLevel.Warning, "Retry of consent-gated toolbox '{ToolboxName}' failed; it remains pending.", EventId = 0)] + private static partial void LogConsentGatedToolboxRetryFailed( + ILogger logger, + string toolboxName, + Exception exception); + + [LoggerMessage(LogLevel.Warning, "Retry of deferred toolbox '{ToolboxName}' failed; it remains deferred.", EventId = 0)] + private static partial void LogDeferredToolboxRetryFailed( + ILogger logger, + string toolboxName, + Exception exception); + + [LoggerMessage(LogLevel.Warning, "Failed to dispose {Resource} for toolbox {ToolboxName} owned by {Owner}.", EventId = 0)] + private static partial void LogToolboxResourceDisposalFailed( + ILogger logger, + string resource, + string toolboxName, + string owner, + Exception exception); + + [LoggerMessage(LogLevel.Information, "Connecting to toolbox '{ToolboxName}' at {ProxyUrl}.", EventId = 0)] + private static partial void LogConnectingToToolbox( + ILogger logger, + string toolboxName, + string proxyUrl); + + [LoggerMessage(LogLevel.Information, "Toolbox '{ToolboxName}': discovered {ToolCount} tool(s).", EventId = 0)] + private static partial void LogToolboxToolsDiscovered( + ILogger logger, + string toolboxName, + int toolCount); + + [LoggerMessage(LogLevel.Warning, "Tool '{ToolName}' in toolbox '{ToolboxName}' has an unsupported approval configuration; requiring approval for every call.", EventId = 0)] + private static partial void LogUnsupportedToolApprovalConfiguration( + ILogger logger, + string toolName, + string toolboxName); } diff --git a/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/HostedProtocolCompatibilityFilter.cs b/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/HostedProtocolCompatibilityFilter.cs index 08695b2b66c..debc5a7f8d1 100644 --- a/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/HostedProtocolCompatibilityFilter.cs +++ b/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/HostedProtocolCompatibilityFilter.cs @@ -16,7 +16,7 @@ namespace Microsoft.Agents.AI.Foundry.Hosting; /// Rejects an unsupported hosted Responses protocol before the request enters AgentServer's /// resilient task boundary. /// -internal sealed class HostedProtocolCompatibilityFilter : IEndpointFilter +internal sealed partial class HostedProtocolCompatibilityFilter : IEndpointFilter { private const string CallIdHeaderName = "x-agent-foundry-call-id"; private const string ErrorSourceHeaderName = "x-platform-error-source"; @@ -59,8 +59,7 @@ internal HostedProtocolCompatibilityFilter( return next(context); } - this._logger.LogError( - "Hosted container served unsupported Responses protocol 1.0.0 (no x-agent-foundry-call-id header); this image requires protocol 2.0.0."); + LogUnsupportedResponsesProtocol(this._logger); BinaryData responseData = ((IPersistableModel)new ApiErrorResponse(unsupportedProtocolError.Error)) @@ -77,4 +76,7 @@ internal HostedProtocolCompatibilityFilter( private static bool IsCreateResponseRequest(HttpRequest request) => HttpMethods.IsPost(request.Method) && request.Path.Value?.EndsWith("/responses", StringComparison.OrdinalIgnoreCase) is true; + + [LoggerMessage(LogLevel.Error, "Hosted container served unsupported Responses protocol 1.0.0 (no x-agent-foundry-call-id header); this image requires protocol 2.0.0.", EventId = 0)] + private static partial void LogUnsupportedResponsesProtocol(ILogger logger); } diff --git a/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/HostedStoredOutputHealthCheck.cs b/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/HostedStoredOutputHealthCheck.cs index 00320f6c991..b89a8cca8e4 100644 --- a/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/HostedStoredOutputHealthCheck.cs +++ b/dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/HostedStoredOutputHealthCheck.cs @@ -13,6 +13,7 @@ using Microsoft.Shared.Diagnostics; namespace Microsoft.Agents.AI.Foundry.Hosting; +#pragma warning disable SYSLIB1006 // Preserve the legacy EventId 0 for every migrated log message. /// /// Reports, on the GET /readiness probe, a registered agent configured to have its own service @@ -35,7 +36,7 @@ namespace Microsoft.Agents.AI.Foundry.Hosting; /// /// [Experimental(DiagnosticIds.Experiments.AgentsAIExperiments)] -internal sealed class HostedStoredOutputHealthCheck : IHealthCheck +internal sealed partial class HostedStoredOutputHealthCheck : IHealthCheck { private readonly IServiceProvider _serviceProvider; private readonly FoundryResponsesOptions _hostingOptions; @@ -137,19 +138,20 @@ private async Task StoresItsOwnResponsesAsync(AIAgent agent, CancellationT // about how it stores responses and is not held against it. A cancellation of its own, a // timeout inside the agent for instance, lands here too; only the health check's own // cancellation is left to propagate. - if (this._logger?.IsEnabled(LogLevel.Debug) is true) + if (this._logger is { } logger) { - this._logger.LogDebug(ex, "Could not probe the stored output setting for agent '{AgentName}'.", agent.Name); + LogStoredOutputProbeFailed(logger, agent.Name, ex); } return false; } - if (probe.StoredOutputEnabled is null && this._logger?.IsEnabled(LogLevel.Debug) is true) + if (probe.StoredOutputEnabled is null) { - this._logger.LogDebug( - "Agent '{AgentName}' builds a request whose stored output setting could not be determined.", - agent.Name); + if (this._logger is { } logger) + { + LogStoredOutputSettingUnknown(logger, agent.Name); + } } return probe.StoredOutputEnabled is true; @@ -159,4 +161,13 @@ private async Task StoresItsOwnResponsesAsync(AIAgent agent, CancellationT /// Every agent this container can serve: the ones registered under a name, plus the default. /// private List ResolveAgents() => FoundryHostingExtensions.ResolveRegisteredAgents(this._serviceProvider); + + [LoggerMessage(LogLevel.Debug, "Could not probe the stored output setting for agent '{AgentName}'.", EventId = 0)] + private static partial void LogStoredOutputProbeFailed( + ILogger logger, + string? agentName, + Exception exception); + + [LoggerMessage(LogLevel.Debug, "Agent '{AgentName}' builds a request whose stored output setting could not be determined.", EventId = 0)] + private static partial void LogStoredOutputSettingUnknown(ILogger logger, string? agentName); } diff --git a/dotnet/tests/Microsoft.Agents.AI.Foundry.Hosting.UnitTests/FoundryAgentSessionStoreTests.cs b/dotnet/tests/Microsoft.Agents.AI.Foundry.Hosting.UnitTests/FoundryAgentSessionStoreTests.cs index 8c01fce60a2..a7e47d6b5f8 100644 --- a/dotnet/tests/Microsoft.Agents.AI.Foundry.Hosting.UnitTests/FoundryAgentSessionStoreTests.cs +++ b/dotnet/tests/Microsoft.Agents.AI.Foundry.Hosting.UnitTests/FoundryAgentSessionStoreTests.cs @@ -241,8 +241,18 @@ public async Task DeleteSessionAsync_NothingStored_LogsTheIgnoredNotFoundAtDebug // Assert var entry = Assert.Single(logs.Entries); Assert.Equal(LogLevel.Debug, entry.Level); - Assert.Contains("conv-1", entry.Message, StringComparison.Ordinal); + Assert.Equal(0, entry.EventId.Id); + Assert.Equal("LogSessionNotFound", entry.EventId.Name); + Assert.Equal( + "Session 'conv-1' was not found in the Foundry state store 'agent-framework/sessions'. Nothing to delete.", + entry.Message); Assert.IsType(entry.Exception); + AssertProperty(entry.Properties, "SessionId", "conv-1"); + AssertProperty(entry.Properties, "StoreName", FoundryAgentSessionStore.DefaultStoreName); + AssertProperty( + entry.Properties, + "{OriginalFormat}", + "Session '{SessionId}' was not found in the Foundry state store '{StoreName}'. Nothing to delete."); } [Fact] @@ -469,6 +479,15 @@ public void Constructor_WithoutCredential_IsAllowedForTheSdkLocalFallback() private static FoundryAgentSessionStore NewStore(FakeStateStore backing, ILoggerFactory? loggerFactory = null) => new(_ => Task.FromResult(backing), loggerFactory: loggerFactory); + private static void AssertProperty( + IReadOnlyList> properties, + string name, + object expectedValue) + { + var property = Assert.Single(properties, property => property.Key == name); + Assert.Equal(expectedValue, property.Value); + } + private static AgentSessionStoreKey Key( string sessionId, string? partitionName = null, diff --git a/dotnet/tests/Microsoft.Agents.AI.Foundry.Hosting.UnitTests/FoundryToolboxServiceTests.cs b/dotnet/tests/Microsoft.Agents.AI.Foundry.Hosting.UnitTests/FoundryToolboxServiceTests.cs index b3f07983528..db218ce1522 100644 --- a/dotnet/tests/Microsoft.Agents.AI.Foundry.Hosting.UnitTests/FoundryToolboxServiceTests.cs +++ b/dotnet/tests/Microsoft.Agents.AI.Foundry.Hosting.UnitTests/FoundryToolboxServiceTests.cs @@ -8,6 +8,7 @@ using System.Threading; using System.Threading.Tasks; using Azure.Core; +using Microsoft.Agents.AI.Foundry.UnitTests.Hosting; using Microsoft.Extensions.AI; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Options; @@ -683,7 +684,7 @@ public async Task GetToolboxToolsAsync_ConcurrentOpaqueScopes_DoNotCollideAsync( public async Task RequestToolboxScope_DisposalFailure_CleansRemainingResourcesAndDoesNotThrowAsync() { // Arrange - var logger = new RecordingLogger(); + var logs = new RecordingLoggerFactory(); var handlers = new ConcurrentDictionary(StringComparer.Ordinal); var options = new FoundryToolboxOptions { @@ -693,7 +694,7 @@ public async Task RequestToolboxScope_DisposalFailure_CleansRemainingResourcesAn var service = new FoundryToolboxService( Options.Create(options), Mock.Of(), - logger) + logs.CreateLogger()) { ToolboxOpener = (name, _, _) => { @@ -722,7 +723,20 @@ public async Task RequestToolboxScope_DisposalFailure_CleansRemainingResourcesAn Assert.Null(exception); Assert.True(handlers["throws"].IsDisposed); Assert.True(handlers["continues"].IsDisposed); - Assert.Single(logger.Exceptions); + var warning = Assert.Single(logs.Entries, entry => entry.Level == LogLevel.Warning); + Assert.Equal(0, warning.EventId.Id); + Assert.Equal("LogToolboxResourceDisposalFailed", warning.EventId.Name); + Assert.Equal( + $"Failed to dispose HTTP client for toolbox throws owned by response scope '{scope.Id}'.", + warning.Message); + Assert.IsType(warning.Exception); + AssertProperty(warning.Properties, "Resource", "HTTP client"); + AssertProperty(warning.Properties, "ToolboxName", "throws"); + AssertProperty(warning.Properties, "Owner", $"response scope '{scope.Id}'"); + AssertProperty( + warning.Properties, + "{OriginalFormat}", + "Failed to dispose {Resource} for toolbox {ToolboxName} owned by {Owner}."); Assert.Empty(service.GetCurrentRequestTools()); await service.DisposeAsync(); @@ -732,7 +746,7 @@ public async Task RequestToolboxScope_DisposalFailure_CleansRemainingResourcesAn public async Task DisposeAsync_DisposalFailure_CleansRemainingResourcesAndThrowsAggregateAsync() { // Arrange - var logger = new RecordingLogger(); + var logs = new RecordingLoggerFactory(); var handlers = new ConcurrentDictionary(StringComparer.Ordinal); var options = new FoundryToolboxOptions { @@ -742,7 +756,7 @@ public async Task DisposeAsync_DisposalFailure_CleansRemainingResourcesAndThrows var service = new FoundryToolboxService( Options.Create(options), Mock.Of(), - logger) + logs.CreateLogger()) { ToolboxOpener = (name, _, _) => { @@ -772,7 +786,20 @@ public async Task DisposeAsync_DisposalFailure_CleansRemainingResourcesAndThrows Assert.Single(exception.InnerExceptions); Assert.True(handlers["throws"].IsDisposed); Assert.True(handlers["continues"].IsDisposed); - Assert.Single(logger.Exceptions); + var warning = Assert.Single(logs.Entries, entry => entry.Level == LogLevel.Warning); + Assert.Equal( + $"Failed to dispose HTTP client for toolbox throws owned by response scope '{scope.Id}'.", + warning.Message); + Assert.Same(exception.InnerException, warning.Exception); + } + + private static void AssertProperty( + IReadOnlyList> properties, + string name, + object expectedValue) + { + var property = Assert.Single(properties, property => property.Key == name); + Assert.Equal(expectedValue, property.Value); } private sealed class TrackingHttpMessageHandler : HttpMessageHandler @@ -802,27 +829,4 @@ protected override void Dispose(bool disposing) } } - private sealed class RecordingLogger : ILogger - { - internal ConcurrentBag Exceptions { get; } = []; - - public IDisposable? BeginScope(TState state) - where TState : notnull => - null; - - public bool IsEnabled(LogLevel logLevel) => true; - - public void Log( - LogLevel logLevel, - EventId eventId, - TState state, - Exception? exception, - Func formatter) - { - if (exception is not null) - { - this.Exceptions.Add(exception); - } - } - } } diff --git a/dotnet/tests/Microsoft.Agents.AI.Foundry.Hosting.UnitTests/RecordingLoggerFactory.cs b/dotnet/tests/Microsoft.Agents.AI.Foundry.Hosting.UnitTests/RecordingLoggerFactory.cs index 69a37fa5560..de14e3916e7 100644 --- a/dotnet/tests/Microsoft.Agents.AI.Foundry.Hosting.UnitTests/RecordingLoggerFactory.cs +++ b/dotnet/tests/Microsoft.Agents.AI.Foundry.Hosting.UnitTests/RecordingLoggerFactory.cs @@ -9,7 +9,13 @@ namespace Microsoft.Agents.AI.Foundry.UnitTests.Hosting; /// Captures what the system under test reported, so a test can assert on it. internal sealed class RecordingLoggerFactory : ILoggerFactory { - public List<(LogLevel Level, string Message, Exception? Exception)> Entries { get; } = []; + public List<( + LogLevel Level, + EventId EventId, + string Message, + Exception? Exception, + IReadOnlyList> Properties)> Entries + { get; } = []; public ILogger CreateLogger(string categoryName) => new RecordingLogger(this.Entries); @@ -21,13 +27,27 @@ public void Dispose() { } - private sealed class RecordingLogger(List<(LogLevel Level, string Message, Exception? Exception)> entries) : ILogger + private sealed class RecordingLogger( + List<( + LogLevel Level, + EventId EventId, + string Message, + Exception? Exception, + IReadOnlyList> Properties)> entries) : ILogger { public IDisposable? BeginScope(TState state) where TState : notnull => null; public bool IsEnabled(LogLevel logLevel) => true; public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) - => entries.Add((logLevel, formatter(state, exception), exception)); + { + List> properties = []; + if (state is IEnumerable> values) + { + properties.AddRange(values); + } + + entries.Add((logLevel, eventId, formatter(state, exception), exception, properties)); + } } }