.NET: [Bug]: OutputConverter.FunctionResultContent creates OutputItemFunctionToolCallOutput with null id, causes HTTP 500 on persistence

[enhendrickson]

Description

Summary

When a Foundry-hosted agent invokes a tool, the OutputConverter.FunctionResultContent case creates OutputItemFunctionToolCallOutput items with a null Id field. This causes the Responses API storage layer to reject the persistence request with HTTP 500, followed by a 409 on retry (confirming partial resource creation). While Azure.AI.AgentServer.Responses v1.0.0-beta.5 gracefully catches this and emits a response.failed event instead of breaking the SSE stream, the root cause remains unfixed.

Root Cause

In OutputConverter.cs (~line 450-460), the FunctionResultContent case:

case FunctionResultContent functionResult:
{
    var outputText = EncodeFunctionResultAsJsonStringPayload(functionResult.Result);
    var itemId = GenerateItemId("fc");  // WRONG: "fc" is function_call prefix, not function_call_output
    var outputItem = new OutputItemFunctionToolCallOutput(
        functionResult.CallId,
        BinaryData.FromString(outputText));  // Id property stays null (get-only)
    var outputBuilder = stream.AddOutputItem<OutputItemFunctionToolCallOutput>(itemId);
    yield return outputBuilder.EmitAdded(outputItem);
    yield return outputBuilder.EmitDone(outputItem);
    break;
}

Problem: The 2-arg constructor OutputItemFunctionToolCallOutput(callId, output) doesn't set the Id property (it's get-only). When the item is serialized for persistence (using ModelReaderWriterOptions.Json), the id field is written as null, which violates the Responses API schema and causes HTTP 500.

Why it happens: The 2-arg public constructor is for deserialization. The internal 9-arg constructor (used by the SDK's convenience method) has the proper id setup:

internal OutputItemFunctionToolCallOutput(
    string id,
    string callId,
    BinaryData output,
    ... other fields ...)

Reproduction

1. Deploy a Foundry hosted agent with Foundry.Hosting 1.8.0-preview
2. Register any tool via AddFoundryToolboxes() or AsOpenAIResponseTool()
3. Invoke the agent with a prompt that triggers the tool
4. Observe in logs:
   • Initial POST /storage/responses returns HTTP 500
   • Azure.Core auto-retry with same request-id returns HTTP 409 (resource already exists)
   • SSE stream terminates (beta.4) or emits response.failed event (beta.5)

Smoke test evidence (from this session):

17:15:13.534927401Z  POST /storage/responses ... HTTP 500
17:15:13.535XXX...Z  Azure.Core retry with request-id d08ad4aa-17aa-42e5-9ae6-03b1ebb857c3
17:15:13.536XXX...Z  HTTP 409 Conflict (resource already exists)
17:15:13.537XXX...Z  Persistence failed before terminal event for response caresp_...

Expected Behavior

Tool invocations should persist cleanly and the agent should return results to the client without storage errors.

Current Workaround (beta.5)

Upgrade to Azure.AI.AgentServer.Responses v1.0.0-beta.5, which contains ResponseOrchestrator.CreateStreamingAsync exception handling that catches persistence failures and emits response.failed with code "storage_error". The SSE stream completes gracefully instead of terminating abruptly.

<PackageReference Include="Azure.AI.AgentServer.Responses" Version="1.0.0-beta.5" />

Client-side mitigation: listen for response.failed events with code="storage_error" and display a user-friendly message.

Suggested Fix

Replace the manual 2-arg constructor usage with the SDK's convenience method, which handles id generation correctly:

case FunctionResultContent functionResult:
{
    var outputText = EncodeFunctionResultAsJsonStringPayload(functionResult.Result);
    foreach (var evt in stream.OutputItemFunctionCallOutput(
        functionResult.CallId,
        BinaryData.FromString(outputText)))
    {
        yield return evt;
    }
    break;
}

The convenience method uses IdGenerator.NewFunctionCallOutputItemId() internally, which generates proper "fco_{partitionKey}{entropy}" formatted ids.

Code Location

• File: dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/OutputConverter.cs
• Class: OutputConverter
• Method: (various overloads of the iterator that yield from FunctionResultContent case)
• Lines: ~450-460 (exact line number may vary with version)

Environment

• Microsoft.Agents.AI.Foundry.Hosting: 1.8.0-preview.260528.1
• Azure.AI.AgentServer.Responses: 1.0.0-beta.4 (buggy) → 1.0.0-beta.5 (graceful error)
• Azure.AI.Projects: 2.1.0-beta.1
• Foundry Hosted Agent: /responses protocol (streaming SSE)

Related

• Similar pattern (orphan function_call items) fixed in .NET: externalLoop + ApprovalRequiredAIFunction leaves dangling function_call in Azure Conversations API, breaks resume #5662 via deferred emission
• MCP-specific function_call_output pairing fixed in Python: [Bug]: Hosted toolbox MCP call_id from a previous turn is replayed as function_call_output without its function_call (400 from Responses API) #5546
• Multi-turn tool-call pairing issue .NET: Python: [Bug]: Multi-turn tool calls fail with both Responses API and Chat Completions API when used via agent-framework-ag-ui (Foundry project endpoint) #5941

Code Sample

See above

Error Messages / Stack Traces

event: log
data: {"timestamp":"2026-06-
...
data: {"timestamp":"2026-06-01T17:15:13.535652508\u002B00:00","stream":"stdout","message":"      X-Content-Type-Options:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.535652508\u002B00:00","stream":"stdout","message":"      x-ms-region:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.535652508\u002B00:00","stream":"stdout","message":"      Content-Type:application/json; charset=utf-8"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.535652508\u002B00:00","stream":"stdout","message":"      "}
event: log
data: {"timestamp":"2026-06-01T17:15:13.537980218\u002B00:00","stream":"stdout","message":"warn: Azure.AI.AgentServer.Responses.Internal.FoundryStorageLoggingPolicy[601900377]"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.537980218\u002B00:00","stream":"stdout","message":"      Foundry storage POST ***/storage/responses?api-version=v1 failed HTTP 500 in 84ms (x-ms-client-request-id: d08ad4aa-17aa-42e5-9ae6-03b1ebb857c3, traceparent: , x-request-id: 81537c4d05754d2d933e3d2d0fc9acb9, apim-request-id: fc5efbce-6a1a-471a-91ce-4ff3294c45e8, HasUserIsolationKey: True, HasChatIsolationKey: True)"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.388038235\u002B00:00","stream":"stdout","message":"warn: Azure.Core[8]"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.388038235\u002B00:00","stream":"stdout","message":"      Error response [d08ad4aa-17aa-42e5-9ae6-03b1ebb857c3] 409 Conflict (00.1s)\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.388038235\u002B00:00","stream":"stdout","message":"      Date:Mon, 01 Jun 2026 17:15:14 GMT"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.388038235\u002B00:00","stream":"stdout","message":"      Server:Kestrel"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.388038235\u002B00:00","stream":"stdout","message":"      Access-Control-Expose-Headers:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.388038235\u002B00:00","stream":"stdout","message":"      Transfer-Encoding:chunked"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.388038235\u002B00:00","stream":"stdout","message":"      Vary:REDA"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"CTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      x-ms-adc-version:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      request-context:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      x-ms-response-type:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      X-Request-ID:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      api-supported-versions:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      azureml-served-by-cluster:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      apim-request-id:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      Strict-Transport-Security:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      X-Content-Type-Options:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      x-ms-region:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      Content-Type:application/json; charset=utf-8"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      "}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"warn: Azure.AI.AgentServer.Responses.Internal.FoundryStorageLoggingPolicy[601900377]"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      Foundry storage POST ***/storage/responses?api-version=v1 failed HTTP 409 in 147ms (x-ms-client-request-id: d08ad4aa-17aa-42e5-9ae6-03b1ebb857c3, traceparent: 00-81537c4d05754d2d933e3d2d0fc9acb9-642e2c8ff637a06a-01, x-request-id: 81537c4d05754d2d933e3d2d0fc9acb9, apim-request-id: 127baf9d-138c-4919-afa3-e054a2822901, HasUserIsolationKey: True, HasChatIsolationKey: True)"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.393783479\u002B00:00","stream":"stdout","message":"fail: Azure.AI.AgentServer.Responses.Internal.ResponseOrchestrator[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.393783479\u002B00:00","stream":"stdout","message":"      Persistence failed before terminal event for response caresp_771858b530c8d3fd003nq4S1Uo6AJsETT7QmbDtRUOXepAPNnM"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.393783479\u002B00:00","stream":"stdout","message":"      Azure.AI.AgentServer.Responses.BadRequestException: The resource already exists or was modified concurrently. Please retry. [Request ID: 81537c4d05754d2d933e3d2d0fc9acb9]"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.393783479\u002B00:00","stream":"stdout","message":"         at Azure.AI.AgentServer.Responses.Internal.StorageErrorMapper.ThrowIfError(Response response)"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.393783479\u002B00:00","stream":"stdout","message":"         at Azure.AI.AgentServer.Responses.Internal.FoundryStorageProvider.SendStorageRequestAsync(HttpMessage message, CancellationToken cancellationToken)"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.393783479\u002B00:00","stream":"stdout","message":"         at Azure.AI.AgentServer.Responses.Internal.FoundryStorageProvider.CreateResponseAsync(CreateResponseRequest request, IsolationContext isolation, CancellationToken cancellationToken)"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.393783479\u002B00:00","stream":"stdout","message":"         at Azure.AI.AgentServer.Responses.Internal.ResponseOrchestrator.CreateStreamingAsync(CreateResponse request, ResponseExecution execution, ResponseContext context, CancellationToken ct)\u002BMoveNext()"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.461239698\u002B00:00","stream":"stdout","message":"info: Azure.AI.AgentServer.Responses.Internal.ResponseEndpointHandler[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.461239698\u002B00:00","stream":"stdout","message":"      SSE stream completed for response caresp_771858b530c8d3fd003nq4S1Uo6AJsETT7QmbDtRUOXepAPNnM"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.462403787\u002B00:00","stream":"stdout","message":"info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.462403787\u002B00:00","stream":"stdout","message":"      Executed endpoint \u0027HTTP: POST /responses\u0027"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.462987473\u002B00:00","stream":"stdout","message":"info: Azure.AI.AgentServer.Core.Internal.InboundRequestLoggingMiddleware[194824245]"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.462987473\u002B00:00","stream":"stdout","message":"      Inbound POST /responses completed HTTP 200 in 5984ms (x-request-id: 81537c4d05754d2d933e3d2d0fc9acb9, x-ms-client-request-id: 9d49784f-b683-487c-907f-7387f308101e, trace-id: 81537c4d05754d2d933e3d2d0fc9acb9)"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.464686554\u002B00:00","stream":"stdout","message":"info: Microsoft.AspNetCore.Hosting.Diagnostics[2]"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.464686554\u002B00:00","stream":"stdout","message":"      Request finished HTTP/1.1 POST http://be033f7d-ac1d-4afd-bb59-c8fcdf89bef4--8088.eastus2.adcproxy.io/responses - 200 - text/event-stream;\u002Bcharset=utf-8 5989.1084ms"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897021871\u002B00:00","stream":"stdout","message":"fail: Microsoft.Agents.A365.Observability.Runtime.Tracing.Exporters.Agent365Exporter[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897021871\u002B00:00","stream":"stdout","message":"      Agent365Exporter: Unhandled export exception."}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897021871\u002B00:00","stream":"stdout","message":"      System.ArgumentException: An item with the same key has already been added. Key: openai.api.type"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897021871\u002B00:00","stream":"stdout","message":"         at S"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897519714\u002B00:00","stream":"stdout","message":"ystem.Collections.Generic.Dictionary\u00602.TryInsert(TKey key, TValue value, InsertionBehavior behavior)"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897519714\u002B00:00","stream":"stdout","message":"         at System.Collections.Generic.Dictionary\u00602.Add(TKey key, TValue value)"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897519714\u002B00:00","stream":"stdout","message":"         at Microsoft.Agents.A365.Observability.Runtime.Common.ExportFormatter.MapAttributes(Activity activity)"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897519714\u002B00:00","stream":"stdout","message":"         at Microsoft.Agents.A365.Observability.Runtime.Common.ExportFormatter.BuildOtlpSpan(Activity activity)"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897519714\u002B00:00","stream":"stdout","message":"         at Microsoft.Agents.A365.Observability.Runtime.Common.ExportFormatter.BuildOtlpSpanWithTruncation(Activity activity)"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897519714\u002B00:00","stream":"stdout","message":"         at Microsoft.Agents.A365.Observability.Runtime.Common.ExportFormatter.FormatMany(IEnumerable\u00601 activities, Resource resource)"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897519714\u002B00:00","stream":"stdout","message":"         at Microsoft.Agents.A365.Observability.Runtime.Tracing.Exporters.Agent365ExporterCore.ExportBatchCoreAsync(IEnumerable\u00601 groups, Resource resource, Agent365ExporterOptions options, Func\u00603 tokenResolver, Func\u00602 sendAsync)"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897519714\u002B00:00","stream":"stdout","message":"         at Microsoft.Agents.A365.Observability.Runtime.Tracing.Exporters.Agent365Exporter.Export(Batch\u00601\u0026 batch)"}
event: log
data: {"timestamp":"2026-06-01T17:15:49.897808346Z","stream":"status","message":"No logs since last 32 seconds"}
event: log
data: {"timestamp":"2026-06-01T17:16:09.924769877Z","stream":"status","message":"No logs since last 52 seconds"}
event: log
data: {"timestamp":"2026-06-01T17:16:29.924356551Z","stream":"status","message":"No logs since last 72 seconds"}
event: log
data: {"timestamp":"2026-06-01T17:16:49.924360501Z","stream":"status","message":"No logs since last 92 seconds"}
event: log
data: {"timestamp":"2026-06-01T17:17:09.924327835Z","stream":"status","message":"No logs since last 112 seconds"}
event: log
data: {"timestamp":"2026-06-01T17:15:01.154+00:00","session_id":"9b44a66880e08e98a6ab083b775c0fb902b54a43eea724e12dc13194bc9c896","session_state":"Running","agent":"project-estimate-generator","generated_at":"2026-06-01T17:15:09.8055646+00:00","last_accessed":"2026-06-01T17:15:01.154+00:00"}
event: log
data: {"timestamp":"2026-06-01T17:15:09.893495392Z","stream":"status","message":"Connecting to the container..."}
event: log
data: {"timestamp":"2026-06-01T17:15:01.152886346\u002B00:00","stream":"stdout","message":"[DEBUG] Creating ChainedTokenCredential..."}
event: log
data: {"timestamp":"2026-06-01T17:15:01.204449269\u002B00:00","stream":"stdout","message":"[DEBUG] ChainedTokenCredential created."}
event: log
data: {"timestamp":"2026-06-01T17:15:01.204483600\u002B00:00","stream":"stdout","message":"[DEBUG] Creating AIProjectClient..."}
event: log
data: {"timestamp":"2026-06-01T17:15:01.215697493\u002B00:00","stream":"stdout","message":"[DEBUG] AIProjectClient created."}
event: log
data: {"timestamp":"2026-06-01T17:15:01.215727946\u002B00:00","stream":"stdout","message":"[INSTRUMENTATION:ENV_STATE_START]"}
event: log
data: {"timestamp":"2026-06-01T17:15:01.215735285\u002B00:00","stream":"stdout","message":"  WORKIQ_TOOLBOX_NAME=workiq-tools"}
event: log
data: {"timestamp":"2026-06-01T17:15:01.215741545\u002B00:00","stream":"stdout","message":"  FOUNDRY_AGENT_TOOLSET_ENDPOINT="}
event: log
data: {"timestamp":"2026-06-01T17:15:01.215747848\u002B00:00","stream":"stdout","message":"  WORKIQ_TOOLSET_ENDPOINT=https://aisvc-estgen-dev-eus2.services.ai.azure.com/api/projects/aisvc-estgen-dev-eus2-project/toolboxes"}
event: log
data: {"timestamp":"2026-06-01T17:15:01.215754326\u002B00:00","stream":"stdout","message":"[INSTRUMENTATION:ENV_STATE_END]"}
event: log
data: {"timestamp":"2026-06-01T17:15:01.215783296\u002B00:00","stream":"stdout","message":"[INFO] FOUNDRY_AGENT_TOOLSET_ENDPOINT was not provided by platform; using WORKIQ_TOOLSET_ENDPOINT fallback."}
event: log
data: {"timestamp":"2026-06-01T17:15:01.215790204\u002B00:00","stream":"stdout","message":"[INSTRUMENTATION:TOOLSET_ENDPOINT_FALLBACK] new_endpoint=https://aisvc-estgen-dev-eus2.services.ai.azure.com/api/projects/aisvc-estgen-dev-eus2-project/toolboxes"}
event: log
data: {"timestamp":"2026-06-01T17:15:01.215796786\u002B00:00","stream":"stdout","message":"[DEBUG] Building AIAgent..."}
event: log
data: {"timestamp":"2026-06-01T17:15:01.251243737\u002B00:00","stream":"stdout","message":"[DEBUG] AIAgent built. Now building AgentHost..."}
event: log
data: {"timestamp":"2026-06-01T17:15:01.299829461\u002B00:00","stream":"stdout","message":"[DEBUG] AgentHost builder created."}
event: log
data: {"timestamp":"2026-06-01T17:15:01.299959135\u002B00:00","stream":"stdout","message":"[DEBUG] Services registered."}
event: log
data: {"timestamp":"2026-06-01T17:15:01.299971544\u002B00:00","stream":"stdout","message":"[INFO] Registering Work IQ toolbox \u0027workiq-tools\u0027 via AddFoundryToolboxes."}
event: log
data: {"timestamp":"2026-06-01T17:15:01.299980974\u002B00:00","stream":"stdout","message":"[INSTRUMENTATION:TOOLBOX_REGISTER_START] toolbox=workiq-tools endpoint="}
event: log
data: {"timestamp":"2026-06-01T17:15:01.300428165\u002B00:00","stream":"stdout","message":"[INSTRUMENTATION:TOOLBOX_REGISTER_SUCCESS] toolbox=workiq-tools"}
event: log
data: {"timestamp":"2026-06-01T17:15:01.305077730\u002B00:00","stream":"stdout","message":"[DEBUG] Responses protocol registered."}
event: log
data: {"timestamp":"2026-06-01T17:15:01.305213087\u002B00:00","stream":"stdout","message":"[DEBUG] Invocations protocol registered. Building app..."}
event: log
data: {"timestamp":"2026-06-01T17:15:01.413368703\u002B00:00","stream":"stdout","message":"info: Azure.AI.AgentServer.Core.AgentHostBuilder[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:01.413368703\u002B00:00","stream":"stdout","message":"      AgentServer platform environment: IsHosted=True AgentName=project-estimate-generator AgentVersion=54 Port=8088 SessionId=9b44a66880e08e98a6ab083b775c0fb902b54a43eea724e12dc13194bc9c896 SseKeepAliveI"}
event: log
data: {"timestamp":"2026-06-01T17:15:01.413404891\u002B00:00","stream":"stdout","message":"nterval=00:00:15 WebSocketKeepAliveInterval=00:00:30"}
event: log
data: {"timestamp":"2026-06-01T17:15:01.415722090\u002B00:00","stream":"stdout","message":"info: Azure.AI.AgentServer.Core.AgentHostBuilder[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:01.415722090\u002B00:00","stream":"stdout","message":"      AgentServer connectivity: ProjectEndpoint=https://aisvc-estgen-dev-eus2.services.ai.azure.com OtlpEndpoint=(not set) AppInsightsConfigured=True"}
event: log
data: {"timestamp":"2026-06-01T17:15:01.415844952\u002B00:00","stream":"stdout","message":"info: Azure.AI.AgentServer.Core.AgentHostBuilder[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:01.415844952\u002B00:00","stream":"stdout","message":"      AgentServer host options: ShutdownTimeout=00:00:30 Protocols=responses, invocations"}
event: log
data: {"timestamp":"2026-06-01T17:15:01.445795730\u002B00:00","stream":"stdout","message":"[DEBUG] App built successfully."}
event: log
data: {"timestamp":"2026-06-01T17:15:01.445795730\u002B00:00","stream":"stdout","message":"[DEBUG] Starting app.Run()..."}
event: log
data: {"timestamp":"2026-06-01T17:15:01.613154808\u002B00:00","stream":"stdout","message":"info: ProjectEstimateAgent.Services.KnowledgeSourceBootstrapHostedService[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:01.613154808\u002B00:00","stream":"stdout","message":"      Starting knowledge source bootstrap hosted service..."}
event: log
data: {"timestamp":"2026-06-01T17:15:02.655373073\u002B00:00","stream":"stdout","message":"info: ProjectEstimateAgent.Services.KnowledgeSourceBootstrapService[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:02.655373073\u002B00:00","stream":"stdout","message":"      Loaded 3 knowledge source definition(s) from configuration."}
event: log
data: {"timestamp":"2026-06-01T17:15:02.657485769\u002B00:00","stream":"stdout","message":"info: ProjectEstimateAgent.Services.KnowledgeSourceBootstrapService[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:02.657485769\u002B00:00","stream":"stdout","message":"      Ensuring knowledge source \u0027ks-presales-current\u0027 has configured filter: Path:\u0022https://provisionsgroup.sharepoint.com/sites/Presales/Shared Documents\u0022"}
event: log
data: {"timestamp":"2026-06-01T17:15:02.749596731\u002B00:00","stream":"stdout","message":"info: ProjectEstimateAgent.Services.KnowledgeSourceBootstrapService[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:02.749596731\u002B00:00","stream":"stdout","message":"      Knowledge source \u0027ks-presales-current\u0027 is configured."}
event: log
data: {"timestamp":"2026-06-01T17:15:02.750058286\u002B00:00","stream":"stdout","message":"info: ProjectEstimateAgent.Services.KnowledgeSourceBootstrapService[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:02.750058286\u002B00:00","stream":"stdout","message":"      Ensuring knowledge source \u0027ks-presales-legacy\u0027 has configured filter: Path:\u0022https://provisionsgroup.sharepoint.com/sites/ProvisionsGroup/Shared Documents/Presales\u0022"}
event: log
data: {"timestamp":"2026-06-01T17:15:02.803248303\u002B00:00","stream":"stdout","message":"info: ProjectEstimateAgent.Services.KnowledgeSourceBootstrapService[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:02.803248303\u002B00:00","stream":"stdout","message":"      Knowledge source \u0027ks-presales-legacy\u0027 is configured."}
event: log
data: {"timestamp":"2026-06-01T17:15:02.803704494\u002B00:00","stream":"stdout","message":"info: ProjectEstimateAgent.Services.KnowledgeSourceBootstrapService[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:02.803704494\u002B00:00","stream":"stdout","message":"      Ensuring knowledge source \u0027ks-rate-card-2026\u0027 has configured filter: Path:\u0022https://provisionsgroup.sharepoint.com/sites/COE/Shared Documents/COE/Agreements/Templates/SOW/PPS/2026 Rate Card with PG360 Discounts (Jan 2026).pdf\u0022"}
event: log
data: {"timestamp":"2026-06-01T17:15:02.849064127\u002B00:00","stream":"stdout","message":"info: ProjectEstimateAgent.Services.KnowledgeSourceBootstrapService[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:02.849064127\u002B00:00","stream":"stdout","message":"      Knowledge source \u0027ks-rate-card-2026\u0027 is configured."}
event: log
data: {"timestamp":"2026-06-01T17:15:02.851105228\u002B00:00","stream":"stdout","message":"info: ProjectEstimateAgent.Services.KnowledgeSourceBootstrapService[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:02.851105228\u002B00:00","stream":"stdout","message":"      Creating or updating knowledge base \u0027estimate-knowledge-base\u0027 with 3 knowledge source(s)..."}
event: log
data: {"timestamp":"2026-06-01T17:15:02.852640814\u002B00:00","stream":"stdout","message":"info: ProjectEstimateAgent.Services.KnowledgeSourceBootstrapService[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:02.852640814\u002B00:00","stream":"stdout","message":"      Configured KB chat model using resource \u0027https://aisvc-estgen-dev-eus2.services.ai.azure.com/\u0027, deployment \u0027project-estimate-generator\u0027, model \u0027gpt-4.1-mini\u0027."}
event: log
data: {"timestamp":"2026-06-01T17:15:02.910596670\u002B00:00","stream":"stdout","message":"info: ProjectEstimateAgent.Services.KnowledgeSourceBootstrapService[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:02.910596670\u002B00:00","stream":"stdout","message":"      Knowledge base \u0027estimate-knowledge-base\u0027 is ready."}
event: log
data: {"timestamp":"2026-06-01T17:15:02.910649470\u002B00:00","stream":"stdout","message":"info: ProjectEstimateAgent.Services.KnowledgeSourceBootstrapService[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:02.910649470\u002B00:00","stream":"stdout","message":"      Knowledge source bootstrap completed successfully."}
event: log
data: {"timestamp":"2026-06-01T17:15:02.910971968\u002B00:00","stream":"stdout","message":"info: ProjectEstimateAgent.Services.KnowledgeSourceBootstrapHostedService[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:02.910971968\u002B00:00","stream":"stdout","message":"      Knowledge source bootstrap hosted service completed."}
event: log
data: {"timestamp":"2026-06-01T17:15:02.916339798\u002B00:00","stream":"stdout","message":"info: Microsoft.Agents.AI.Foundry.Hosting.FoundryToolboxService[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:02.916339798\u002B00:00","stream":"stdout","message":"      Connecting to toolbox \u0027workiq-tools\u0027 at https://aisvc-estgen-dev-eus2.services.ai.azure.com/api/projects/aisvc-estgen-dev-eus2-project/toolboxes/workiq-tools/mcp?api-version=v1."}
event: log
data: {"timestamp":"2026-06-01T17:15:07.254581279\u002B00:00","stream":"stdout","message":"info: Microsoft.Agents.AI.Foundry.Hosting.FoundryToolboxService[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:07.254581279\u002B00:00","stream":"stdout","message":"      Toolbox \u0027workiq-tools\u0027: discovered 1 tool(s)."}
event: log
data: {"timestamp":"2026-06-01T17:15:07.258015508\u002B00:00","stream":"stdout","message":"info: Azure.AI.AgentServer.Responses.Internal.ResponsesStartupLogger[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:07.258015508\u002B00:00","stream":"stdout","message":"      Responses protocol configuration: StorageProvider=FoundryStorageProvider DefaultModel=(not set) DefaultFetchHistoryCount=100 EventStreamTtl=00:10:00"}
event: log
data: {"timestamp":"2026-06-01T17:15:07.269450102\u002B00:00","stream":"stdout","message":"warn: Microsoft.AspNetCore.Server.Kestrel[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:07.269450102\u002B00:00","stream":"stdout","message":"      Overriding address(es) \u0027http://*:8080\u0027. Binding to endpoints defined via IConfiguration and/or UseKestrel() instead."}
event: log
data: {"timestamp":"2026-06-01T17:15:07.275613286\u002B00:00","stream":"stdout","message":"info: Microsoft.Hosting.Lifetime[14]"}
event: log
data: {"timestamp":"2026-06-01T17:15:07.275613286\u002B00:00","stream":"stdout","message":"      Now listening on: http://0.0.0.0:8088"}
event: log
data: {"timestamp":"2026-06-01T17:15:07.276989434\u002B00:00","stream":"stdout","message":"info: Microsoft.Hosting.Lifetime[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:07.276989434\u002B00:00","stream":"stdout","message":"      Application started. Press Ctrl\u002BC to shut down."}
event: log
data: {"timestamp":"2026-06-01T17:15:07.277066369\u002B00:00","stream":"stdout","message":"info: Microsoft.Hosting.Lifetime[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:07.277066369\u002B00:00","stream":"stdout","message":"      Hosting environment: Production"}
event: log
data: {"timestamp":"2026-06-01T17:15:07.277109465\u002B00:00","stream":"stdout","message":"info: Microsoft.Hosting.Lifetime[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:07.277109465\u002B00:00","stream":"stdout","message":"      Content root path: /app"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.234123671\u002B00:00","stream":"stdout","message":"info: Microsoft.AspNetCore.Hosting.Diagnostics[1]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.234123671\u002B00:00","stream":"stdout","message":"      Request starting HTTP/1.1 GET http://be033f7d-ac1d-4afd-bb59-c8fcdf89bef4--8088.eastus2.adcproxy.io/readiness - - -"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.296511297\u002B00:00","stream":"stdout","message":"info: Azure.AI.AgentServer.Core.Internal.InboundRequestLoggingMiddleware[1689694937]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.296511297\u002B00:00","stream":"stdout","message":"      Inbound GET /readiness starting (x-request-id: , x-ms-client-request-id: , trace-id: 81537c4d05754d2d933e3d2d0fc9acb9)"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.298628810\u002B00:00","stream":"stdout","message":"info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.298628810\u002B00:00","stream":"stdout","message":"      Executing endpoint \u0027Health checks\u0027"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.307695251\u002B00:00","stream":"stdout","message":"info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.307695251\u002B00:00","stream":"stdout","message":"      Executed endpoint \u0027Health checks\u0027"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.309398868\u002B00:00","stream":"stdout","message":"info: Azure.AI.AgentServer.Core.Internal.InboundRequestLoggingMiddleware[194824245]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.309398868\u002B00:00","stream":"stdout","message":"      Inbound GET /readiness completed HTTP 200 in 18ms (x-request-id: , x-ms-client-request-id: , trace-id: 81537c4d05754d2d933e3d2d0fc9acb9)"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.311431804\u002B00:00","stream":"stdout","message":"info: Microsoft.AspNetCore.Hosting.Diagnostics[2]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.311431804\u002B00:00","stream":"stdout","message":"      Request finished HTTP/1.1 GET http://be033f7d-ac1d-4afd-bb59-c8fcdf89bef4--8088.eastus2.adcproxy.io/readiness - 200 - text/plain 84.4453ms"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.476261623\u002B00:00","stream":"stdout","message":"info: Microsoft.AspNetCore.Hosting.Diagnostics[1]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.476261623\u002B00:00","stream":"stdout","message":"      Request starting HTTP/1.1 POST http://be033f7d-ac1d-4afd-bb59-c8fcdf89bef4--8088.eastus2.adcproxy.io/responses - application/json 376"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.483015651\u002B00:00","stream":"stdout","message":"info: Azure.AI.AgentServer.Core.Internal.InboundRequestLoggingMiddleware[1689694937]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.483015651\u002B00:00","stream":"stdout","message":"      Inbound POST /responses starting (x-request-id: 81537c4d05754d2d933e3d2d0fc9acb9, x-ms-client-request-id: 9d49784f-b683-487c-907f-7387f308101e, trace-id: 81537c4d05754d2d933e3d2d0fc9acb9)"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.483015651\u002B00:00","stream":"stdout","message":"info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.483015651\u002B00:00","stream":"stdout","message":"      Executing endpoint \u0027HTTP: POST /responses\u0027"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.504603661\u002B00:00","stream":"stdout","message":"info: Azure.AI.AgentServer.Responses.Internal.ResponseEndpointHandler[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.504603661\u002B00:00","stream":"stdout","message":"      Creating response caresp_771858b530c8d3fd003nq4S1Uo6AJsETT7QmbDtRUOXepAPNnM: Streaming=True Background=False Store=True Model= ConversationId=conv_771858b530c8d3fd00LmEobxLdj1pBnHqLw8zxHiWJRh2J2AoE PreviousResponseId=(null) HasUserIsolationKey=True HasChatIsolationKey=True"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.515947282\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.515947282\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:08Z - a995d665-cf2f-461b-a2d5-0a593a6374d1] [Internal cache] Total number of cache partitions found while getting access tokens: 2"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.517258847\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.517258847\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:08Z - a995d665-cf2f-461b-a2d5-0a593a6374d1] [FindAccessTokenAsync] Discovered 2 access tokens in cache using partition key: system_assigned_managed_identity_managed_identity_AppTokenCache"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.518048590\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.518048590\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:08Z - a995d665-cf2f-461b-a2d5-0a593a6374d1] \r"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.518048590\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] Cache Refresh Reason: NotApplicable\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.518048590\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] DurationInCacheInMs: 0\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.518048590\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] DurationTotalInMs: 5\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.518048590\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] DurationInHttpInMs: 0"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.518202327\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.518202327\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:08Z - a995d665-cf2f-461b-a2d5-0a593a6374d1] TokenEndpoint: ****"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.662670472\u002B00:00","stream":"stdout","message":"info: Azure.AI.AgentServer.Responses.Internal.FoundryStorageLoggingPolicy[194824245]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.662670472\u002B00:00","stream":"stdout","message":"      Foundry storage GET ***/storage/history/item_ids?api-version=v1 completed HTTP 200 in 141ms (x-ms-client-request-id: 47d8012f-79d4-44b5-bd91-90cbd736b0f0, traceparent: , x-request-id: 81537c4d05754d2d933e3d2d0fc9acb9, apim-request-id: fcc0a017-bd61-4438-824d-673573d74564, HasUserIsolationKey: True, HasChatIsolationKey: True)"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.671612328\u002B00:00","stream":"stdout","message":"info: Azure.AI.AgentServer.Responses.Internal.ResponseEndpointHandler[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.671612328\u002B00:00","stream":"stdout","message":"      SSE stream started for response caresp_771858b530c8d3fd003nq4S1Uo6AJsETT7QmbDtRUOXepAPNnM"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.676999716\u002B00:00","stream":"stdout","message":"info: Azure.AI.AgentServer.Responses.Internal.ResponseOrchestrator[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.676999716\u002B00:00","stream":"stdout","message":"      Invoking handler AgentFrameworkResponseHandler for response caresp_771858b530c8d3fd003nq4S1Uo6AJsETT7QmbDtRUOXepAPNnM"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.870701481\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.870701481\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:08Z - 40549c85-3fca-4947-aa3a-8e7d2b0420c6] [Internal cache] Total number of cache partitions found while getting access tokens: 2"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.881210573\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.881210573\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:08Z - 40549c85-3fca-4947-aa3a-8e7d2b0420c6] [FindAccessTokenAsync] Discovered 2 access tokens in cache using partition key: system_assigned_managed_identity_managed_identity_AppTokenCache"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.881210573\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.881210573\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:08Z - 40549c85-3fca-4947-aa3a-8e7d2b0420c6] \r"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.881210573\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] Cache Refresh Reason: NotApplicable\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.881210573\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] DurationInCacheInMs: 0\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.881210573\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] DurationTotalInMs: 0\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.881210573\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] DurationInHttpInMs: 0"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.881210573\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:08.881210573\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:08Z - 40549c85-3fca-4947-aa3a-8e7d2b0420c6] TokenEndpoint: ****\n"}
event: log
data: {"timestamp":"2026-06-01T17:15:09.897151699Z","stream":"status","message":"Successfully connected to container"}
event: log
data: {"timestamp":"2026-06-01T17:15:10.510970736\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:10.510970736\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:10Z - 7c61f865-20dc-4547-b147-d0ed3e218439] [Internal cache] Total number of cache partitions found while getting access tokens: 2"}
event: log
data: {"timestamp":"2026-06-01T17:15:10.515845931\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:10.515845931\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:10Z - 7c61f865-20dc-4547-b147-d0ed3e218439] [FindAccessTokenAsync] Discovered 2 access tokens in cache using partition key: system_assigned_managed_identity_managed_identity_AppTokenCache"}
event: log
data: {"timestamp":"2026-06-01T17:15:10.515845931\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:10.515845931\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:10Z - 7c61f865-20dc-4547-b147-d0ed3e218439] \r"}
event: log
data: {"timestamp":"2026-06-01T17:15:10.515845931\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] Cache Refresh Reason: NotApplicable\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:10.515845931\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] DurationInCacheInMs: 0\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:10.515845931\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] DurationTotalInMs: 0\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:10.515845931\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] DurationInHttpInMs: 0"}
event: log
data: {"timestamp":"2026-06-01T17:15:10.515845931\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:10.515845931\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:10Z - 7c61f865-20dc-4547-b147-d0ed3e218439] TokenEndpoint: ****"}
event: log
data: {"timestamp":"2026-06-01T17:15:11.419103224\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:11.419103224\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:11Z - 416e66ca-5e34-47b0-944f-c2f780d54d4a] [Internal cache] Total number of cache partitions found while getting access tokens: 2"}
event: log
data: {"timestamp":"2026-06-01T17:15:11.419480754\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:11.419480754\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:11Z - 416e66ca-5e34-47b0-944f-c2f780d54d4a] [FindAccessTokenAsync] Discovered 2 access tokens in cache using partition key: system_assigned_managed_identity_managed_identity_AppTokenCache"}
event: log
data: {"timestamp":"2026-06-01T17:15:11.419751359\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:11.419751359\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:11Z - 416e66ca-5e34-47b0-944f-c2f780d54d4a] \r"}
event: log
data: {"timestamp":"2026-06-01T17:15:11.419751359\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] Cache Refresh Reason: NotApplicable\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:11.419751359\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] Duratio"}
event: log
data: {"timestamp":"2026-06-01T17:15:11.419959883\u002B00:00","stream":"stdout","message":"nInCacheInMs: 0\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:11.419959883\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] DurationTotalInMs: 0\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:11.419959883\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] DurationInHttpInMs: 0"}
event: log
data: {"timestamp":"2026-06-01T17:15:11.420299337\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:11.420299337\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:11Z - 416e66ca-5e34-47b0-944f-c2f780d54d4a] TokenEndpoint: ****"}
event: log
data: {"timestamp":"2026-06-01T17:15:12.584968735\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:12.584968735\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:12Z - b5697f3b-b08b-40fa-a582-e8bfc62d5778] [Internal cache] Total number of cache partitions found while getting access tokens: 2"}
event: log
data: {"timestamp":"2026-06-01T17:15:12.585416893\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:12.585416893\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:12Z - b5697f3b-b08b-40fa-a582-e8bfc62d5778] [FindAccessTokenAsync] Discovered 1 access tokens in cache using partition key: 358af454-6244-4efa-9db8-1829093f"}
event: log
data: {"timestamp":"2026-06-01T17:15:12.585501542\u002B00:00","stream":"stdout","message":"29f9_managed_identity_AppTokenCache"}
event: log
data: {"timestamp":"2026-06-01T17:15:12.585818479\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:12.585818479\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:12Z - b5697f3b-b08b-40fa-a582-e8bfc62d5778] \r"}
event: log
data: {"timestamp":"2026-06-01T17:15:12.585818479\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] Cache Refresh Reason: NotApplicable\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:12.585818479\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] Duratio"}
event: log
data: {"timestamp":"2026-06-01T17:15:12.586096308\u002B00:00","stream":"stdout","message":"nInCacheInMs: 0\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:12.586096308\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] DurationTotalInMs: 0\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:12.586096308\u002B00:00","stream":"stdout","message":"      [LogMetricsFromAuthResult] DurationInHttpInMs: 0"}
event: log
data: {"timestamp":"2026-06-01T17:15:12.586389162\u002B00:00","stream":"stdout","message":"info: Azure.Identity[24]"}
event: log
data: {"timestamp":"2026-06-01T17:15:12.586389162\u002B00:00","stream":"stdout","message":"      False MSAL 4.83.1.0 MSAL.NetCore .NET 10.0.8 Linux [2026-06-01 17:15:12Z - b5697f3b-b08b-40fa-a582-e8bfc62d5778] TokenEndpoint: ****"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.534927401\u002B00:00","stream":"stdout","message":"warn: Azure.Core[8]"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.534927401\u002B00:00","stream":"stdout","message":"      Error response [d08ad4aa-17aa-42e5-9ae6-03b1ebb857c3] 500 Internal Server Error (00.1s)\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.534927401\u002B00:00","stream":"stdout","message":"      Date:Mon, 01 Jun 2026 17:15:13 GMT"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.534927401\u002B00:00","stream":"stdout","message":"      Server:Kestrel"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.534927401\u002B00:00","stream":"stdout","message":"      Access-Control-Expose-Headers:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.534927401\u002B00:00","stream":"stdout","message":"      Transfer-Encoding:chunked"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.534927401\u002B00:00","stream":"stdout","message":"  "}
event: log
data: {"timestamp":"2026-06-01T17:15:13.535244353\u002B00:00","stream":"stdout","message":"    Vary:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.535244353\u002B00:00","stream":"stdout","message":"      x-ms-adc-version:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.535244353\u002B00:00","stream":"stdout","message":"      request-context:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.535244353\u002B00:00","stream":"stdout","message":"      x-ms-response-type:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.535244353\u002B00:00","stream":"stdout","message":"      X-Request-ID:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.535244353\u002B00:00","stream":"stdout","message":"      api-supported-versions:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.535244353\u002B00:00","stream":"stdout","message":"      azureml-served-by-cluster:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.535244353\u002B00:00","stream":"stdout","message":"      apim-request-id:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.535244353\u002B00:00","stream":"stdout","message":"   "}
event: log
data: {"timestamp":"2026-06-01T17:15:13.535652508\u002B00:00","stream":"stdout","message":"   Strict-Transport-Security:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.535652508\u002B00:00","stream":"stdout","message":"      X-Content-Type-Options:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.535652508\u002B00:00","stream":"stdout","message":"      x-ms-region:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.535652508\u002B00:00","stream":"stdout","message":"      Content-Type:application/json; charset=utf-8"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.535652508\u002B00:00","stream":"stdout","message":"      "}
event: log
data: {"timestamp":"2026-06-01T17:15:13.537980218\u002B00:00","stream":"stdout","message":"warn: Azure.AI.AgentServer.Responses.Internal.FoundryStorageLoggingPolicy[601900377]"}
event: log
data: {"timestamp":"2026-06-01T17:15:13.537980218\u002B00:00","stream":"stdout","message":"      Foundry storage POST ***/storage/responses?api-version=v1 failed HTTP 500 in 84ms (x-ms-client-request-id: d08ad4aa-17aa-42e5-9ae6-03b1ebb857c3, traceparent: , x-request-id: 81537c4d05754d2d933e3d2d0fc9acb9, apim-request-id: fc5efbce-6a1a-471a-91ce-4ff3294c45e8, HasUserIsolationKey: True, HasChatIsolationKey: True)"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.388038235\u002B00:00","stream":"stdout","message":"warn: Azure.Core[8]"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.388038235\u002B00:00","stream":"stdout","message":"      Error response [d08ad4aa-17aa-42e5-9ae6-03b1ebb857c3] 409 Conflict (00.1s)\r"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.388038235\u002B00:00","stream":"stdout","message":"      Date:Mon, 01 Jun 2026 17:15:14 GMT"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.388038235\u002B00:00","stream":"stdout","message":"      Server:Kestrel"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.388038235\u002B00:00","stream":"stdout","message":"      Access-Control-Expose-Headers:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.388038235\u002B00:00","stream":"stdout","message":"      Transfer-Encoding:chunked"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.388038235\u002B00:00","stream":"stdout","message":"      Vary:REDA"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"CTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      x-ms-adc-version:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      request-context:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      x-ms-response-type:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      X-Request-ID:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      api-supported-versions:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      azureml-served-by-cluster:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      apim-request-id:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      Strict-Transport-Security:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      X-Content-Type-Options:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      x-ms-region:REDACTED"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      Content-Type:application/json; charset=utf-8"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      "}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"warn: Azure.AI.AgentServer.Responses.Internal.FoundryStorageLoggingPolicy[601900377]"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.389962066\u002B00:00","stream":"stdout","message":"      Foundry storage POST ***/storage/responses?api-version=v1 failed HTTP 409 in 147ms (x-ms-client-request-id: d08ad4aa-17aa-42e5-9ae6-03b1ebb857c3, traceparent: 00-81537c4d05754d2d933e3d2d0fc9acb9-642e2c8ff637a06a-01, x-request-id: 81537c4d05754d2d933e3d2d0fc9acb9, apim-request-id: 127baf9d-138c-4919-afa3-e054a2822901, HasUserIsolationKey: True, HasChatIsolationKey: True)"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.393783479\u002B00:00","stream":"stdout","message":"fail: Azure.AI.AgentServer.Responses.Internal.ResponseOrchestrator[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.393783479\u002B00:00","stream":"stdout","message":"      Persistence failed before terminal event for response caresp_771858b530c8d3fd003nq4S1Uo6AJsETT7QmbDtRUOXepAPNnM"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.393783479\u002B00:00","stream":"stdout","message":"      Azure.AI.AgentServer.Responses.BadRequestException: The resource already exists or was modified concurrently. Please retry. [Request ID: 81537c4d05754d2d933e3d2d0fc9acb9]"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.393783479\u002B00:00","stream":"stdout","message":"         at Azure.AI.AgentServer.Responses.Internal.StorageErrorMapper.ThrowIfError(Response response)"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.393783479\u002B00:00","stream":"stdout","message":"         at Azure.AI.AgentServer.Responses.Internal.FoundryStorageProvider.SendStorageRequestAsync(HttpMessage message, CancellationToken cancellationToken)"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.393783479\u002B00:00","stream":"stdout","message":"         at Azure.AI.AgentServer.Responses.Internal.FoundryStorageProvider.CreateResponseAsync(CreateResponseRequest request, IsolationContext isolation, CancellationToken cancellationToken)"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.393783479\u002B00:00","stream":"stdout","message":"         at Azure.AI.AgentServer.Responses.Internal.ResponseOrchestrator.CreateStreamingAsync(CreateResponse request, ResponseExecution execution, ResponseContext context, CancellationToken ct)\u002BMoveNext()"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.461239698\u002B00:00","stream":"stdout","message":"info: Azure.AI.AgentServer.Responses.Internal.ResponseEndpointHandler[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.461239698\u002B00:00","stream":"stdout","message":"      SSE stream completed for response caresp_771858b530c8d3fd003nq4S1Uo6AJsETT7QmbDtRUOXepAPNnM"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.462403787\u002B00:00","stream":"stdout","message":"info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.462403787\u002B00:00","stream":"stdout","message":"      Executed endpoint \u0027HTTP: POST /responses\u0027"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.462987473\u002B00:00","stream":"stdout","message":"info: Azure.AI.AgentServer.Core.Internal.InboundRequestLoggingMiddleware[194824245]"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.462987473\u002B00:00","stream":"stdout","message":"      Inbound POST /responses completed HTTP 200 in 5984ms (x-request-id: 81537c4d05754d2d933e3d2d0fc9acb9, x-ms-client-request-id: 9d49784f-b683-487c-907f-7387f308101e, trace-id: 81537c4d05754d2d933e3d2d0fc9acb9)"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.464686554\u002B00:00","stream":"stdout","message":"info: Microsoft.AspNetCore.Hosting.Diagnostics[2]"}
event: log
data: {"timestamp":"2026-06-01T17:15:14.464686554\u002B00:00","stream":"stdout","message":"      Request finished HTTP/1.1 POST http://be033f7d-ac1d-4afd-bb59-c8fcdf89bef4--8088.eastus2.adcproxy.io/responses - 200 - text/event-stream;\u002Bcharset=utf-8 5989.1084ms"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897021871\u002B00:00","stream":"stdout","message":"fail: Microsoft.Agents.A365.Observability.Runtime.Tracing.Exporters.Agent365Exporter[0]"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897021871\u002B00:00","stream":"stdout","message":"      Agent365Exporter: Unhandled export exception."}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897021871\u002B00:00","stream":"stdout","message":"      System.ArgumentException: An item with the same key has already been added. Key: openai.api.type"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897021871\u002B00:00","stream":"stdout","message":"         at S"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897519714\u002B00:00","stream":"stdout","message":"ystem.Collections.Generic.Dictionary\u00602.TryInsert(TKey key, TValue value, InsertionBehavior behavior)"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897519714\u002B00:00","stream":"stdout","message":"         at System.Collections.Generic.Dictionary\u00602.Add(TKey key, TValue value)"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897519714\u002B00:00","stream":"stdout","message":"         at Microsoft.Agents.A365.Observability.Runtime.Common.ExportFormatter.MapAttributes(Activity activity)"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897519714\u002B00:00","stream":"stdout","message":"         at Microsoft.Agents.A365.Observability.Runtime.Common.ExportFormatter.BuildOtlpSpan(Activity activity)"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897519714\u002B00:00","stream":"stdout","message":"         at Microsoft.Agents.A365.Observability.Runtime.Common.ExportFormatter.BuildOtlpSpanWithTruncation(Activity activity)"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897519714\u002B00:00","stream":"stdout","message":"         at Microsoft.Agents.A365.Observability.Runtime.Common.ExportFormatter.FormatMany(IEnumerable\u00601 activities, Resource resource)"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897519714\u002B00:00","stream":"stdout","message":"         at Microsoft.Agents.A365.Observability.Runtime.Tracing.Exporters.Agent365ExporterCore.ExportBatchCoreAsync(IEnumerable\u00601 groups, Resource resource, Agent365ExporterOptions options, Func\u00603 tokenResolver, Func\u00602 sendAsync)"}
event: log
data: {"timestamp":"2026-06-01T17:15:17.897519714\u002B00:00","stream":"stdout","message":"         at Microsoft.Agents.A365.Observability.Runtime.Tracing.Exporters.Agent365Exporter.Export(Batch\u00601\u0026 batch)"}
event: log
data: {"timestamp":"2026-06-01T17:15:49.897808346Z","stream":"status","message":"No logs since last 32 seconds"}
event: log
data: {"timestamp":"2026-06-01T17:16:09.924769877Z","stream":"status","message":"No logs since last 52 seconds"}
event: log
data: {"timestamp":"2026-06-01T17:16:29.924356551Z","stream":"status","message":"No logs since last 72 seconds"}
event: log
data: {"timestamp":"2026-06-01T17:16:49.924360501Z","stream":"status","message":"No logs since last 92 seconds"}
event: log
data: {"timestamp":"2026-06-01T17:17:09.924327835Z","stream":"status","message":"No logs since last 112 seconds"}

Package Versions

Azure.AI.AgentServer.Responses v1.0.0-beta.5

.NET Version

10

Additional Context

No response

[github-actions]

🤖 Automated triage reproduction notes (agent-authored — trust but verify)

Agent analysis

Repro: OutputConverter.ConvertUpdatesToEventsAsync() in dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/OutputConverter.cs (FunctionResultContent case, ~line 265) previously used the public 2-arg OutputItemFunctionToolCallOutput(callId, output) constructor which does not set the read-only Id property, causing null id on the wire. Already fixed by commit b298113 which switches to stream.OutputItemFunctionCallOutput(callId, output) convenience method. Regression test at dotnet/tests/Microsoft.Agents.AI.Foundry.Hosting.UnitTests/OutputConverterTests.cs:712 confirms fix.

• Failing test: none
• Files examined: dotnet/src/Microsoft.Agents.AI.Foundry.Hosting/OutputConverter.cs, dotnet/tests/Microsoft.Agents.AI.Foundry.Hosting.UnitTests/OutputConverterTests.cs, dotnet/nuget/nuget-package.props
• Tests run: ConvertUpdatesToEventsAsync_FunctionResult_OutputItemHasIdAsync (passed - regression test added by fix commit)
• Reported version: 1.8.0-preview.260528.1
• Current version: 1.8.0-preview