diff --git a/src/Exceptionless.Core/Utility/AppDiagnostics.cs b/src/Exceptionless.Core/Utility/AppDiagnostics.cs index e59dc6bf7a..fbd2338ab3 100644 --- a/src/Exceptionless.Core/Utility/AppDiagnostics.cs +++ b/src/Exceptionless.Core/Utility/AppDiagnostics.cs @@ -91,6 +91,10 @@ public GaugeInfo(Meter meter, string name) internal static readonly Counter EventsSubmitted = Meter.CreateCounter("ex.events.submitted", description: "Events submitted to the pipeline to be processed"); internal static readonly Counter AssistantTurns = Meter.CreateCounter("ex.assistant.turns", description: "Assistant turns accepted"); internal static readonly Counter AssistantTurnOutcomes = Meter.CreateCounter("ex.assistant.turn.outcomes", description: "Assistant turn outcomes"); + internal static readonly Histogram AssistantTurnDuration = Meter.CreateHistogram("ex.assistant.turn.duration", unit: "ms", description: "Assistant response duration including provider and tool work"); + internal static readonly Histogram AssistantFirstTextDuration = Meter.CreateHistogram("ex.assistant.turn.first_text.duration", unit: "ms", description: "Time until the first visible assistant text is emitted"); + internal static readonly Histogram AssistantProviderDuration = Meter.CreateHistogram("ex.assistant.provider.duration", unit: "ms", description: "Assistant provider request duration including streaming"); + internal static readonly Histogram AssistantToolDuration = Meter.CreateHistogram("ex.assistant.tool.duration", unit: "ms", description: "Assistant tool execution duration"); internal static readonly Counter AssistantTurnsBlocked = Meter.CreateCounter("ex.assistant.turns.blocked", description: "Assistant turns blocked by a usage limit"); internal static readonly Counter AssistantProviderRequests = Meter.CreateCounter("ex.assistant.provider.requests", description: "Assistant provider requests"); internal static readonly Counter AssistantToolCalls = Meter.CreateCounter("ex.assistant.tool.calls", description: "Assistant tool calls"); diff --git a/src/Exceptionless.Web/ApmExtensions.cs b/src/Exceptionless.Web/ApmExtensions.cs index 0f6af7263f..41c504c405 100644 --- a/src/Exceptionless.Web/ApmExtensions.cs +++ b/src/Exceptionless.Web/ApmExtensions.cs @@ -129,6 +129,14 @@ public static IHostBuilder AddApm(this IHostBuilder builder, ApmConfig config) b.AddRuntimeInstrumentation(); b.AddProcessInstrumentation(); + foreach (string name in new[] { "ex.assistant.turn.duration", "ex.assistant.turn.first_text.duration", "ex.assistant.provider.duration", "ex.assistant.tool.duration" }) + { + b.AddView(name, new ExplicitBucketHistogramConfiguration + { + Boundaries = [50, 100, 250, 500, 1000, 2500, 5000, 10000, 30000, 60000, 120000] + }); + } + b.AddView( "http.server.request.duration", new ExplicitBucketHistogramConfiguration diff --git a/src/Exceptionless.Web/Assistant/AssistantProviderTiming.cs b/src/Exceptionless.Web/Assistant/AssistantProviderTiming.cs new file mode 100644 index 0000000000..d444dceb73 --- /dev/null +++ b/src/Exceptionless.Web/Assistant/AssistantProviderTiming.cs @@ -0,0 +1,40 @@ +using System.Diagnostics; + +namespace Exceptionless.Web.Assistant; + +internal sealed class AssistantProviderTiming( + ILogger logger, + TimeProvider timeProvider, + AssistantChatRequest request, + string model) : IDisposable +{ + private readonly long _started = timeProvider.GetTimestamp(); + private bool _completed; + private bool _disposed; + + public double ElapsedMilliseconds => timeProvider.GetElapsedTime(_started).TotalMilliseconds; + public double? HeadersDuration { get; set; } + public double? FirstChunkDuration { get; set; } + public string? GenerationId { get; set; } + public string? ProviderName { get; set; } + + public void Complete() + { + _completed = true; + Dispose(); + } + + public void Dispose() + { + if (_disposed) + return; + + _disposed = true; + double duration = ElapsedMilliseconds; + AppDiagnostics.AssistantProviderDuration.Record(duration, new KeyValuePair("model", model)); + logger.LogInformation( + "Assistant provider timing: duration={DurationMs} ms headers={HeadersDurationMs} ms first_chunk={FirstChunkDurationMs} ms stream_completed={ProviderStreamCompleted} model={Model} provider={ProviderName} generation={ProviderGenerationId} organization={OrganizationId} conversation={ConversationId} trace={TraceId}", + duration, HeadersDuration, FirstChunkDuration, _completed, model, ProviderName, GenerationId, + request.OrganizationId, request.ConversationId, Activity.Current?.TraceId.ToString()); + } +} diff --git a/src/Exceptionless.Web/Assistant/AssistantService.cs b/src/Exceptionless.Web/Assistant/AssistantService.cs index c52de20f52..fb2bf493f1 100644 --- a/src/Exceptionless.Web/Assistant/AssistantService.cs +++ b/src/Exceptionless.Web/Assistant/AssistantService.cs @@ -1,3 +1,4 @@ +using System.Diagnostics; using System.Net.Http.Json; using System.Runtime.CompilerServices; using System.Text; @@ -41,9 +42,41 @@ public async IAsyncEnumerable StreamAsync( string userId, AssistantPlanOptions planOptions, [EnumeratorCancellation] CancellationToken cancellationToken = default) + { + long started = timeProvider.GetTimestamp(); + double? firstTextDuration = null; + string? model = null; + try + { + model = (await assistantModelSettingsService.GetAsync()).Model; + await foreach (var item in StreamCoreAsync(request, userId, planOptions, model, cancellationToken)) + { + if (firstTextDuration is null && item.Type == "text_delta" && !String.IsNullOrEmpty(item.Text)) + { + firstTextDuration = timeProvider.GetElapsedTime(started).TotalMilliseconds; + AppDiagnostics.AssistantFirstTextDuration.Record(firstTextDuration.Value, new KeyValuePair("model", model)); + } + yield return item; + } + } + finally + { + double duration = timeProvider.GetElapsedTime(started).TotalMilliseconds; + AppDiagnostics.AssistantTurnDuration.Record(duration, new KeyValuePair("model", model)); + logger.LogInformation( + "Assistant response timing: duration={DurationMs} ms first_text={FirstTextDurationMs} ms model={Model} organization={OrganizationId} conversation={ConversationId} trace={TraceId}", + duration, firstTextDuration, model, request.OrganizationId, request.ConversationId, Activity.Current?.TraceId.ToString()); + } + } + + private async IAsyncEnumerable StreamCoreAsync( + AssistantChatRequest request, + string userId, + AssistantPlanOptions planOptions, + string model, + [EnumeratorCancellation] CancellationToken cancellationToken) { var options = appOptions.AssistantOptions; - string model = (await assistantModelSettingsService.GetAsync()).Model; AssistantConversationState? conversationState = null; if (!String.IsNullOrWhiteSpace(request.OrganizationId) && !String.IsNullOrWhiteSpace(request.ConversationId)) { @@ -101,6 +134,8 @@ public async IAsyncEnumerable StreamAsync( var toolCalls = new Dictionary(); var assistantContent = new StringBuilder(); + var assistantReasoning = new StringBuilder(); + var assistantReasoningDetails = new List(); // A streamed response cannot be retracted after malformed provider markup reaches the // browser, so hold this provider round until its content is known to be safe. var assistantContentChunks = new List(); @@ -114,10 +149,13 @@ public async IAsyncEnumerable StreamAsync( } await using var providerRequest = await assistantUsageService.StartProviderRequestAsync(request.OrganizationId, providerInputCharacters); - using var response = await SendRequestAsync(messages, options, model, allowTools, request, cancellationToken); + using var providerTiming = new AssistantProviderTiming(logger, timeProvider, request, model); + using var response = await SendRequestAsync(messages, options, model, allowTools, request, providerTiming, cancellationToken); providerRequest.MarkAccepted(); await using var stream = await response.Content.ReadAsStreamAsync(cancellationToken); using var reader = new StreamReader(stream); + string? generationId = null; + string? providerName = null; while (await reader.ReadLineAsync(cancellationToken) is { } line) { @@ -128,9 +166,17 @@ public async IAsyncEnumerable StreamAsync( if (payload.Length == 0 || payload == "[DONE]") continue; + providerTiming.FirstChunkDuration ??= providerTiming.ElapsedMilliseconds; using var document = JsonDocument.Parse(payload); + generationId = GetProviderValue(document.RootElement, "id") ?? generationId; + providerName = GetProviderValue(document.RootElement, "provider") ?? providerName; + providerTiming.GenerationId = generationId; + providerTiming.ProviderName = providerName; if (document.RootElement.TryGetProperty("error", out var error)) + { + LogProviderFailure(response, document.RootElement, model, request, generationId, providerName); throw new AssistantProviderException(GetProviderError(error)); + } if (!usageRecorded && TryGetProviderUsage(document.RootElement, out var usage)) { @@ -151,6 +197,20 @@ public async IAsyncEnumerable StreamAsync( continue; var delta = choices[0].GetProperty("delta"); + if ((delta.TryGetProperty("reasoning", out var reasoning) || delta.TryGetProperty("reasoning_content", out reasoning)) + && reasoning.ValueKind == JsonValueKind.String) + { + assistantReasoning.Append(reasoning.GetString()); + } + + if (delta.TryGetProperty("reasoning_details", out var reasoningDetails) && reasoningDetails.ValueKind == JsonValueKind.Array) + { + foreach (var detail in reasoningDetails.EnumerateArray()) + { + assistantReasoningDetails.Add(detail.Clone()); + } + } + if (delta.TryGetProperty("content", out var content) && content.ValueKind == JsonValueKind.String) { string? text = content.GetString(); @@ -186,6 +246,9 @@ public async IAsyncEnumerable StreamAsync( } } + // Stop before yielding text or running tools so provider time excludes that work. + providerTiming.Complete(); + if (s_rawDsmlPattern.IsMatch(assistantContent.ToString())) { if (malformedResponseRetries < AssistantLimits.MaximumMalformedResponseRetries) @@ -269,17 +332,7 @@ public async IAsyncEnumerable StreamAsync( } pendingSuggestedActions = suggestedActions; - messages.Add(new - { - role = "assistant", - content = (string?)null, - tool_calls = suggestedActionCalls.Select(call => new - { - id = call.Id, - type = "function", - function = new { name = call.Name, arguments = call.Arguments.ToString() } - }).ToArray() - }); + messages.Add(CreateAssistantToolMessage(suggestedActionCalls, assistantContent, assistantReasoning, assistantReasoningDetails)); string suggestionResult = JsonSerializer.Serialize(new { @@ -300,17 +353,7 @@ public async IAsyncEnumerable StreamAsync( // let the model offer fresh suggestions with its final answer after the tool results. pendingSuggestedActions = []; await assistantUsageService.RecordToolCallsAsync(request.OrganizationId, executableToolCalls.Length); - messages.Add(new - { - role = "assistant", - content = assistantContent.Length == 0 ? null : assistantContent.ToString(), - tool_calls = executableToolCalls.Select(call => new - { - id = call.Id, - type = "function", - function = new { name = call.Name, arguments = call.Arguments.ToString() } - }).ToArray() - }); + messages.Add(CreateAssistantToolMessage(executableToolCalls, assistantContent, assistantReasoning, assistantReasoningDetails)); var conversationToolResults = new List(); foreach (var toolCall in executableToolCalls) @@ -384,7 +427,7 @@ await assistantConversationService.AppendToolResultsAsync( } } - private async Task SendRequestAsync(List messages, AssistantOptions options, string model, bool allowTools, AssistantChatRequest chatRequest, CancellationToken cancellationToken) + private async Task SendRequestAsync(List messages, AssistantOptions options, string model, bool allowTools, AssistantChatRequest chatRequest, AssistantProviderTiming timing, CancellationToken cancellationToken) { var client = httpClientFactory.CreateClient(nameof(AssistantService)); using var providerRequest = new HttpRequestMessage(HttpMethod.Post, options.Endpoint); @@ -407,27 +450,75 @@ private async Task SendRequestAsync(List messages, } } }; - if (allowTools) - payload["tools"] = AssistantToolDefinitions.Create(tools, chatRequest); + // Tool results still require their schemas when the model must produce a final answer. + payload["tools"] = AssistantToolDefinitions.Create(tools, chatRequest); + if (!allowTools) + { + payload["tool_choice"] = "none"; + } providerRequest.Content = JsonContent.Create(payload); var response = await client.SendAsync(providerRequest, HttpCompletionOption.ResponseHeadersRead, cancellationToken); + timing.HeadersDuration = timing.ElapsedMilliseconds; if (response.IsSuccessStatusCode) return response; - string detail = await response.Content.ReadAsStringAsync(cancellationToken); - logger.LogWarning("Assistant provider returned {StatusCode}: {Detail}", (int)response.StatusCode, detail); - response.Dispose(); + using (response) + { + try + { + using var document = await JsonDocument.ParseAsync(await response.Content.ReadAsStreamAsync(cancellationToken), cancellationToken: cancellationToken); + LogProviderFailure(response, document.RootElement, model, chatRequest); + } + catch (JsonException) + { + // Proxy/HTML errors still need their HTTP status and correlation IDs. + LogProviderFailure(response, default, model, chatRequest); + } + } throw new AssistantProviderException($"The AI provider returned status {(int)response.StatusCode}."); } + private static Dictionary CreateAssistantToolMessage( + PendingToolCall[] toolCalls, + StringBuilder content, + StringBuilder reasoning, + List reasoningDetails) + { + var message = new Dictionary + { + ["role"] = "assistant", + ["content"] = content.Length == 0 ? null : content.ToString(), + ["tool_calls"] = toolCalls.Select(call => new + { + id = call.Id, + type = "function", + function = new { name = call.Name, arguments = call.Arguments.ToString() } + }).ToArray() + }; + + // Reasoning belongs only to this turn's provider conversation. Never send it to the + // browser or persist it with tool results. Structured blocks retain signatures and order. + if (reasoningDetails.Count > 0) + { + message["reasoning_details"] = reasoningDetails; + } + else if (reasoning.Length > 0) + { + message["reasoning"] = reasoning.ToString(); + } + + return message; + } + private async Task ExecuteToolAsync( string name, string arguments, AssistantChatRequest request, CancellationToken cancellationToken) { + using var toolTimer = AppDiagnostics.AssistantToolDuration.StartTimer(); cancellationToken.ThrowIfCancellationRequested(); using var _ = assistantToolContext.BeginTools(request.OrganizationId); using var document = ParseArguments(arguments); @@ -692,7 +783,47 @@ private static int GetBoundedInt32(JsonElement element, int defaultValue, int ma } private static string GetProviderError(JsonElement error) - => error.TryGetProperty("message", out var message) ? message.GetString() ?? "The AI provider returned an error." : "The AI provider returned an error."; + => error.ValueKind == JsonValueKind.Object && error.TryGetProperty("message", out var message) && message.ValueKind == JsonValueKind.String + ? message.GetString() ?? "The AI provider returned an error." : "The AI provider returned an error."; + + private void LogProviderFailure(HttpResponseMessage response, JsonElement body, string model, AssistantChatRequest request, + string? generationId = null, string? providerName = null) + { + var error = body.ValueKind == JsonValueKind.Object && body.TryGetProperty("error", out var value) ? value : default; + var metadata = error.ValueKind == JsonValueKind.Object && error.TryGetProperty("metadata", out value) ? value : default; + generationId = GetProviderValue(body, "id") ?? generationId; + if (generationId is null && response.Headers.TryGetValues("X-Generation-Id", out var ids)) + { + generationId = ids.FirstOrDefault(); + } + + // Keep known error fields. Arbitrary metadata.raw/flagged_input can include request content. + logger.LogWarning( + "Assistant provider failed: model={Model} status={ProviderStatusCode} code={ProviderErrorCode} type={ProviderErrorType} upstream_code={UpstreamErrorCode} provider={ProviderName} generation={ProviderGenerationId} organization={OrganizationId} conversation={ConversationId} message={ProviderMessage}", + model, (int)response.StatusCode, GetProviderValue(error, "code"), + GetProviderValue(metadata, "error_type") ?? GetProviderValue(error, "type"), + GetProviderValue(metadata, "provider_code") ?? GetProviderValue(metadata, "provider_error_code"), + GetProviderValue(metadata, "provider_name") ?? GetProviderValue(body, "provider") ?? providerName, + generationId, request.OrganizationId, request.ConversationId, GetProviderError(error)); + } + + private static string? GetProviderValue(JsonElement element, string name) + { + if (element.ValueKind != JsonValueKind.Object || !element.TryGetProperty(name, out var property)) + { + return null; + } + + string? value = property.ValueKind switch + { + JsonValueKind.String => property.GetString(), + JsonValueKind.Number => property.GetRawText(), + _ => null + }; + return value is { Length: > 0 and <= 128 } + && value.All(character => Char.IsAsciiLetterOrDigit(character) || character is ' ' or '-' or '_' or '.' or '/' or ':') + ? value : null; + } private sealed class PendingToolCall { diff --git a/src/Exceptionless.Web/appsettings.yml b/src/Exceptionless.Web/appsettings.yml index 785c089916..bbbfb19f18 100644 --- a/src/Exceptionless.Web/appsettings.yml +++ b/src/Exceptionless.Web/appsettings.yml @@ -9,6 +9,7 @@ Serilog: #Exceptionless.Core.Repositories.StackRepository: Verbose #Exceptionless.Core.Repositories: Verbose Exceptionless.Web.Program: Information + Exceptionless.Web.Assistant.AssistantService: Information Exceptionless.Web.Security.ApiKeyAuthenticationHandler: Warning Foundatio.Metrics: Warning Foundatio.Utility.ScheduledTimer: Warning diff --git a/tests/Exceptionless.Tests/Assistant/AssistantServiceTests.cs b/tests/Exceptionless.Tests/Assistant/AssistantServiceTests.cs index 35ce5e8d9b..f1edd7c2e7 100644 --- a/tests/Exceptionless.Tests/Assistant/AssistantServiceTests.cs +++ b/tests/Exceptionless.Tests/Assistant/AssistantServiceTests.cs @@ -1,3 +1,4 @@ +using System.Diagnostics.Metrics; using System.Net; using System.Text; using System.Text.Json; @@ -16,7 +17,9 @@ using Foundatio.Serializer; using Microsoft.AspNetCore.Http; using Microsoft.Extensions.Configuration; +using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Time.Testing; using Xunit; namespace Exceptionless.Tests.Assistant; @@ -207,6 +210,248 @@ public async Task StreamAsync_RuntimeModelOverride_UsesOverride() Assert.Equal("z-ai/glm-5.3-flash", providerRequest.RootElement.GetProperty("model").GetString()); } + [Fact] + public async Task StreamAsync_Timing_SeparatesProviderStreamingFromVisibleResponse() + { + var timeProvider = new FakeTimeProvider(); + var logger = new RecordingAssistantLogger(); + var appOptions = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary + { + ["BaseURL"] = "https://localhost", + ["Assistant:ApiKey"] = "test-key", + ["Assistant:Model"] = "timing-test-model" + }).Build()); + var measurements = new Dictionary>(); + using var listener = new MeterListener(); + listener.InstrumentPublished = (instrument, meterListener) => + { + if (instrument.Meter.Name == "Exceptionless" && instrument.Name.StartsWith("ex.assistant.", StringComparison.Ordinal)) + meterListener.EnableMeasurementEvents(instrument); + }; + listener.SetMeasurementEventCallback((instrument, measurement, tags, _) => + { + foreach (var tag in tags) + { + if (tag.Key != "model" || !Equals(tag.Value, "timing-test-model")) + continue; + + if (!measurements.TryGetValue(instrument.Name, out var values)) + measurements[instrument.Name] = values = []; + values.Add(measurement); + } + }); + listener.Start(); + var service = CreateAssistantService(new TimingHttpMessageHandler(timeProvider), appOptions, logger: logger, timeProvider: timeProvider); + + await foreach (var item in service.StreamAsync(new AssistantChatRequest([new AssistantChatMessage("user", "Hello")]), + "user-id", CreatePlanOptions(), TestContext.Current.CancellationToken)) + { + if (item.Type == "text_delta") + timeProvider.Advance(TimeSpan.FromMilliseconds(1000)); + } + + var provider = Assert.Single(logger.Entries, entry => entry.ContainsKey("HeadersDurationMs")); + Assert.Equal(200d, provider["HeadersDurationMs"]); + Assert.Equal(700d, provider["FirstChunkDurationMs"]); + Assert.Equal(700d, provider["DurationMs"]); + Assert.Equal(true, provider["ProviderStreamCompleted"]); + var turn = Assert.Single(logger.Entries, entry => entry.ContainsKey("FirstTextDurationMs")); + Assert.Equal(700d, turn["FirstTextDurationMs"]); + Assert.Equal(2700d, turn["DurationMs"]); + Assert.Equal(700d, Assert.Single(measurements["ex.assistant.provider.duration"])); + Assert.Equal(700d, Assert.Single(measurements["ex.assistant.turn.first_text.duration"])); + Assert.Equal(2700d, Assert.Single(measurements["ex.assistant.turn.duration"])); + } + + [Fact] + public async Task StreamAsync_Cancellation_RecordsElapsedTimeWithoutFirstText() + { + var timeProvider = new FakeTimeProvider(); + var logger = new RecordingAssistantLogger(); + using var cancellation = new CancellationTokenSource(); + var appOptions = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary + { + ["BaseURL"] = "https://localhost", + ["Assistant:ApiKey"] = "test-key" + }).Build()); + var service = CreateAssistantService(new TimingHttpMessageHandler(timeProvider, cancellation.Cancel), + appOptions, logger: logger, timeProvider: timeProvider); + + await Assert.ThrowsAnyAsync(async () => + { + await foreach (var _ in service.StreamAsync(new AssistantChatRequest([new AssistantChatMessage("user", "Hello")]), + "user-id", CreatePlanOptions(), cancellation.Token)) + { + } + }); + + var provider = Assert.Single(logger.Entries, entry => entry.ContainsKey("HeadersDurationMs")); + Assert.Equal(200d, provider["DurationMs"]); + Assert.Null(provider["HeadersDurationMs"]); + Assert.Equal(false, provider["ProviderStreamCompleted"]); + var turn = Assert.Single(logger.Entries, entry => entry.ContainsKey("FirstTextDurationMs")); + Assert.Equal(200d, turn["DurationMs"]); + Assert.Null(turn["FirstTextDurationMs"]); + } + + [Theory] + [InlineData(false, "429", "provider_code")] + [InlineData(true, "429", "provider_code")] + [InlineData(true, "\"429\"", "provider_error_code")] + public async Task StreamAsync_ProviderFailure_LogsCauseAndCorrelation(bool streaming, string code, string upstreamCodeProperty) + { + string error = $$$$""" + {"error":{"code":{{{{code}}}},"message":"Rate limit exceeded","metadata":{ + "error_type":"rate_limit_exceeded","{{{{upstreamCodeProperty}}}}":"rate_limited", + "provider_name":"Fireworks","raw":"private-provider-body-canary","flagged_input":"private-input-canary" + }}} + """; + string content = streaming + ? "data: {\"id\":\"gen-stream\",\"provider\":\"Fireworks\",\"choices\":[]}\n\ndata: " + error.ReplaceLineEndings("") + "\n\n" + : error; + var logger = new RecordingAssistantLogger(); + var appOptions = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary + { + ["BaseURL"] = "https://localhost", + ["Assistant:ApiKey"] = "private-key-canary", + ["Assistant:Model"] = "deepseek/deepseek-v4.1-flash" + }).Build()); + var service = CreateAssistantService(new ProviderFailureHandler(streaming ? HttpStatusCode.OK : HttpStatusCode.TooManyRequests, content), + appOptions, logger: logger); + + await Assert.ThrowsAsync(async () => + { + await foreach (var _ in service.StreamAsync(new AssistantChatRequest( + [new AssistantChatMessage("user", "private-prompt-canary")], OrganizationId: "organization-id", ConversationId: "conversation-id"), + "user-id", CreatePlanOptions(), TestContext.Current.CancellationToken)) + { + } + }); + + var properties = Assert.Single(logger.Entries, entry => entry.ContainsKey("ProviderStatusCode")); + Assert.Equal(streaming ? 200 : 429, properties["ProviderStatusCode"]); + Assert.Equal("429", properties["ProviderErrorCode"]); + Assert.Equal("rate_limit_exceeded", properties["ProviderErrorType"]); + Assert.Equal("rate_limited", properties["UpstreamErrorCode"]); + Assert.Equal("Rate limit exceeded", properties["ProviderMessage"]); + Assert.Equal("Fireworks", properties["ProviderName"]); + Assert.Equal("deepseek/deepseek-v4.1-flash", properties["Model"]); + Assert.Equal(streaming ? "gen-stream" : "gen-header", properties["ProviderGenerationId"]); + Assert.Equal("conversation-id", properties["ConversationId"]); + Assert.Equal("organization-id", properties["OrganizationId"]); + Assert.DoesNotContain("canary", JsonSerializer.Serialize(properties)); + var providerTiming = Assert.Single(logger.Entries, entry => entry.ContainsKey("HeadersDurationMs")); + Assert.Equal(false, providerTiming["ProviderStreamCompleted"]); + Assert.NotNull(providerTiming["HeadersDurationMs"]); + var turnTiming = Assert.Single(logger.Entries, entry => entry.ContainsKey("FirstTextDurationMs")); + Assert.Null(turnTiming["FirstTextDurationMs"]); + } + + [Theory] + [InlineData("private-proxy-body-canary")] + [InlineData("{invalid-json")] + public async Task StreamAsync_InvalidHttpErrorBody_LogsStatusWithoutHidingRejection(string content) + { + var logger = new RecordingAssistantLogger(); + var appOptions = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary + { + ["BaseURL"] = "https://localhost", + ["Assistant:ApiKey"] = "test-key" + }).Build()); + var service = CreateAssistantService(new ProviderFailureHandler(HttpStatusCode.BadGateway, content), appOptions, logger: logger); + + var exception = await Assert.ThrowsAsync(async () => + { + await foreach (var _ in service.StreamAsync(new AssistantChatRequest([new AssistantChatMessage("user", "Hello")]), + "user-id", CreatePlanOptions(), TestContext.Current.CancellationToken)) + { + } + }); + + Assert.Contains("502", exception.Message); + var properties = Assert.Single(logger.Entries, entry => entry.ContainsKey("ProviderStatusCode")); + Assert.Equal(502, properties["ProviderStatusCode"]); + Assert.Equal("gen-header", properties["ProviderGenerationId"]); + Assert.DoesNotContain("private-proxy-body-canary", JsonSerializer.Serialize(properties)); + } + + [Theory] + [InlineData("unknown_tool", "reasoning")] + [InlineData("unknown_tool", "reasoning_content")] + [InlineData("unknown_tool", "reasoning_details")] + [InlineData("suggest_followups", "reasoning")] + [InlineData("suggest_followups", "reasoning_content")] + [InlineData("suggest_followups", "reasoning_details")] + public async Task StreamAsync_ToolReasoning_PreservesProviderContextWithoutExposingIt(string toolName, string reasoningProperty) + { + string firstReasoning = reasoningProperty == "reasoning_details" + ? "\"reasoning_details\":[{\"type\":\"reasoning.text\",\"text\":\"Private reasoning.\",\"index\":0}]" + : $"\"{reasoningProperty}\":\"Private \""; + string secondReasoning = reasoningProperty == "reasoning_details" + ? "\"reasoning_details\":[{\"type\":\"reasoning.encrypted\",\"data\":\"opaque-context\",\"id\":\"block-1\",\"index\":1}]" + : $"\"{reasoningProperty}\":\"reasoning.\""; + var handler = new StubHttpMessageHandler( + $$$""" + data: {"choices":[{"delta":{ {{{firstReasoning}}} }}]} + + data: {"choices":[{"delta":{ {{{secondReasoning}}}, "tool_calls":[{"index":0,"id":"call-1","function":{"name":"{{{toolName}}}","arguments":"{}"}}] }}]} + + data: [DONE] + + """, + """ + data: {"choices":[{"delta":{"content":"Final answer."}}]} + + data: [DONE] + + """); + var appOptions = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary + { + ["BaseURL"] = "https://localhost", + ["Assistant:ApiKey"] = "test-key" + }) + .Build()); + var service = CreateAssistantService(handler, appOptions); + var events = new List(); + + await foreach (var item in service.StreamAsync( + new AssistantChatRequest([new AssistantChatMessage("user", "Investigate this")], OrganizationId: "organization-id"), + "user-id", + CreatePlanOptions(), + TestContext.Current.CancellationToken)) + { + events.Add(item); + } + + using var followup = JsonDocument.Parse(handler.RequestBodies[1]); + var assistant = Assert.Single(followup.RootElement.GetProperty("messages").EnumerateArray(), + message => message.GetProperty("role").GetString() == "assistant"); + if (reasoningProperty == "reasoning_details") + { + var details = assistant.GetProperty("reasoning_details"); + Assert.Equal(2, details.GetArrayLength()); + Assert.Equal("Private reasoning.", details[0].GetProperty("text").GetString()); + Assert.Equal("opaque-context", details[1].GetProperty("data").GetString()); + Assert.Equal("block-1", details[1].GetProperty("id").GetString()); + Assert.False(assistant.TryGetProperty("reasoning", out _)); + } + else + { + Assert.Equal("Private reasoning.", assistant.GetProperty("reasoning").GetString()); + Assert.False(assistant.TryGetProperty("reasoning_details", out _)); + } + + Assert.Equal("Final answer.", Assert.Single(events, item => item.Type == "text_delta").Text); + string visibleEvents = JsonSerializer.Serialize(events); + Assert.DoesNotContain("Private", visibleEvents); + Assert.DoesNotContain("opaque-context", visibleEvents); + } + [Fact] public async Task StreamAsync_ExplicitWriteRequest_ExecutesToolWithoutConfirmationGate() { @@ -503,7 +748,10 @@ [new AssistantChatMessage("user", "Investigate this")], } Assert.Equal(2, handler.RequestBodies.Count); - Assert.DoesNotContain("\"tools\":", handler.RequestBodies[1]); + using var initialRequest = JsonDocument.Parse(handler.RequestBodies[0]); + using var finalRequest = JsonDocument.Parse(handler.RequestBodies[1]); + Assert.Equal(initialRequest.RootElement.GetProperty("tools").GetRawText(), finalRequest.RootElement.GetProperty("tools").GetRawText()); + Assert.Equal("none", finalRequest.RootElement.GetProperty("tool_choice").GetString()); Assert.Contains("Suggestions captured", handler.RequestBodies[1]); var suggestions = Assert.Single(events, item => item.Type == "suggested_actions").SuggestedActions!; Assert.Equal(AssistantLimits.MaximumSuggestedActions, suggestions.Count); @@ -1107,7 +1355,7 @@ public async Task StreamAsync_RepeatedRawDsmlResponse_EmitsClearErrorAndCompleti } [Fact] - public async Task StreamAsync_ToolBudgetExhausted_RequestsFinalSynthesisWithoutTools() + public async Task StreamAsync_ToolBudgetExhausted_RequestsFinalSynthesisWithToolChoiceNone() { const string toolCallResponse = """ data: {"choices":[{"delta":{"tool_calls":[{"index":0,"id":"call-1","function":{"name":"unknown_tool","arguments":"{}"}}]}}]} @@ -1148,7 +1396,9 @@ [new AssistantChatMessage("user", "Investigate the errors")], Assert.Equal(4, handler.RequestBodies.Count); Assert.All(handler.RequestBodies.Take(3), body => Assert.Contains("\"tools\":", body)); - Assert.DoesNotContain("\"tools\":", handler.RequestBodies[3]); + using var finalRequest = JsonDocument.Parse(handler.RequestBodies[3]); + Assert.NotEmpty(finalRequest.RootElement.GetProperty("tools").EnumerateArray()); + Assert.Equal("none", finalRequest.RootElement.GetProperty("tool_choice").GetString()); Assert.Contains("The tool budget is exhausted", handler.RequestBodies[3]); Assert.Contains(events, item => item.Text == "Here is the available result."); Assert.Equal("done", events[^1].Type); @@ -1229,7 +1479,9 @@ private static AssistantService CreateAssistantService( ICacheClient? cache = null, ILockProvider? lockProvider = null, AssistantUsageService? usageService = null, - AssistantModelSettingsService? modelSettingsService = null) + AssistantModelSettingsService? modelSettingsService = null, + ILogger? logger = null, + TimeProvider? timeProvider = null) { cache ??= new InMemoryCacheClient(new InMemoryCacheClientOptions { @@ -1255,8 +1507,8 @@ private static AssistantService CreateAssistantService( new AssistantConversationService(cache, lockProvider, NullLogger.Instance), modelSettingsService, usageService, - TimeProvider.System, - NullLogger.Instance); + timeProvider ?? TimeProvider.System, + logger ?? NullLogger.Instance); } private static AssistantModelSettingsService CreateAssistantModelSettingsService(AppOptions appOptions) @@ -1314,6 +1566,57 @@ protected override async Task SendAsync(HttpRequestMessage } } + private sealed class TimingHttpMessageHandler(FakeTimeProvider timeProvider, Action? beforeHeaders = null) : HttpMessageHandler + { + protected override Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) + { + timeProvider.Advance(TimeSpan.FromMilliseconds(200)); + beforeHeaders?.Invoke(); + cancellationToken.ThrowIfCancellationRequested(); + const string content = """ + data: {"choices":[{"delta":{"content":"Hello"}}]} + + data: {"choices":[{"delta":{"content":" again"}}]} + + data: [DONE] + + """; + return Task.FromResult(new HttpResponseMessage(HttpStatusCode.OK) + { + Content = new StreamContent(new TimingStream(timeProvider, Encoding.UTF8.GetBytes(content))) + }); + } + } + + private sealed class TimingStream(FakeTimeProvider timeProvider, byte[] content) : MemoryStream(content) + { + public override ValueTask ReadAsync(Memory buffer, CancellationToken cancellationToken = default) + { + if (Position < Length) + timeProvider.Advance(TimeSpan.FromMilliseconds(500)); + return base.ReadAsync(buffer, cancellationToken); + } + } + + private sealed class ProviderFailureHandler(HttpStatusCode status, string content) : HttpMessageHandler + { + protected override Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) + { + var response = new HttpResponseMessage(status) { Content = new StringContent(content) }; + response.Headers.Add("X-Generation-Id", "gen-header"); + return Task.FromResult(response); + } + } + + private sealed class RecordingAssistantLogger : ILogger + { + public List> Entries { 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) + => Entries.Add(((IEnumerable>)(object)state!).ToDictionary(pair => pair.Key, pair => pair.Value)); + } + private sealed class RejectedHttpMessageHandler(HttpStatusCode statusCode) : HttpMessageHandler { protected override Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)