From 44b0b6938f10b11579f621ab1ce4f69c29914be2 Mon Sep 17 00:00:00 2001 From: "Eric J. Smith" Date: Thu, 10 Sep 2026 18:13:26 -0500 Subject: [PATCH 1/3] Fix Exie model tool continuations and provider diagnostics --- .../Configuration/AssistantOptions.cs | 2 +- .../Utility/AppDiagnostics.cs | 4 + .../Api/Endpoints/AssistantEndpoints.cs | 46 +- src/Exceptionless.Web/ApmExtensions.cs | 2 +- .../Assistant/AssistantModels.cs | 4 + .../Assistant/AssistantProviderDiagnostics.cs | 287 +++++++++++++ .../AssistantProviderErrorDetails.cs | 261 ++++++++++++ .../Assistant/AssistantProviderException.cs | 5 +- .../Assistant/AssistantService.cs | 317 ++++++++++---- .../Assistant/AssistantTurnDiagnostics.cs | 190 +++++++++ src/Exceptionless.Web/appsettings.yml | 3 +- .../Assistant/AssistantDiagnosticsTests.cs | 377 +++++++++++++++++ .../AssistantProviderTelemetryTests.cs | 203 +++++++++ .../AssistantQualityEvaluationTests.cs | 27 +- ...ssistantServiceProviderDiagnosticsTests.cs | 120 ++++++ .../Assistant/AssistantServiceTests.cs | 394 +++++++++++++++++- tests/Exceptionless.Tests/Assistant/README.md | 34 +- 17 files changed, 2159 insertions(+), 117 deletions(-) create mode 100644 src/Exceptionless.Web/Assistant/AssistantProviderDiagnostics.cs create mode 100644 src/Exceptionless.Web/Assistant/AssistantProviderErrorDetails.cs create mode 100644 src/Exceptionless.Web/Assistant/AssistantTurnDiagnostics.cs create mode 100644 tests/Exceptionless.Tests/Assistant/AssistantDiagnosticsTests.cs create mode 100644 tests/Exceptionless.Tests/Assistant/AssistantProviderTelemetryTests.cs create mode 100644 tests/Exceptionless.Tests/Assistant/AssistantServiceProviderDiagnosticsTests.cs diff --git a/src/Exceptionless.Core/Configuration/AssistantOptions.cs b/src/Exceptionless.Core/Configuration/AssistantOptions.cs index b1059d671b..f996058b16 100644 --- a/src/Exceptionless.Core/Configuration/AssistantOptions.cs +++ b/src/Exceptionless.Core/Configuration/AssistantOptions.cs @@ -5,7 +5,7 @@ namespace Exceptionless.Core.Configuration; public sealed class AssistantOptions { public const string DefaultEndpoint = "https://openrouter.ai/api/v1/chat/completions"; - public const string DefaultModel = "~deepseek/deepseek-v4-flash-latest"; + public const string DefaultModel = "deepseek/deepseek-v4.1-flash"; public bool Enabled { get; internal set; } public bool IsConfigured => !String.IsNullOrWhiteSpace(ApiKey); diff --git a/src/Exceptionless.Core/Utility/AppDiagnostics.cs b/src/Exceptionless.Core/Utility/AppDiagnostics.cs index e59dc6bf7a..883cbfd65b 100644 --- a/src/Exceptionless.Core/Utility/AppDiagnostics.cs +++ b/src/Exceptionless.Core/Utility/AppDiagnostics.cs @@ -10,6 +10,7 @@ public static class AppDiagnostics internal static readonly AssemblyName AssemblyName = typeof(AppDiagnostics).Assembly.GetName(); internal static readonly string? AssemblyVersion = typeof(AppDiagnostics).Assembly.GetCustomAttribute()?.InformationalVersion ?? AssemblyName.Version?.ToString(); internal static readonly ActivitySource ActivitySource = new(AssemblyName.Name ?? "Exceptionless", AssemblyVersion); + internal static readonly ActivitySource AssistantActivitySource = new("Exceptionless.Assistant", AssemblyVersion); internal static readonly Meter Meter = new("Exceptionless", AssemblyVersion); private static readonly string _metricsPrefix = "ex."; @@ -91,6 +92,9 @@ 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 turn duration by outcome and failure reason"); + internal static readonly Histogram AssistantProviderDuration = Meter.CreateHistogram("ex.assistant.provider.duration", unit: "ms", description: "Assistant provider request duration by outcome"); + internal static readonly Histogram AssistantToolDuration = Meter.CreateHistogram("ex.assistant.tool.duration", unit: "ms", description: "Assistant tool duration by tool and outcome"); 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/Api/Endpoints/AssistantEndpoints.cs b/src/Exceptionless.Web/Api/Endpoints/AssistantEndpoints.cs index 9a0fbaa0dd..8f2acc0ccb 100644 --- a/src/Exceptionless.Web/Api/Endpoints/AssistantEndpoints.cs +++ b/src/Exceptionless.Web/Api/Endpoints/AssistantEndpoints.cs @@ -99,17 +99,37 @@ private static async Task StreamChatAsync( using var turnCancellationSource = CancellationTokenSource.CreateLinkedTokenSource(httpContext.RequestAborted); turnCancellationSource.CancelAfter(TimeSpan.FromSeconds(AssistantLimits.MaximumTurnDurationSeconds)); + using var diagnostics = new AssistantTurnDiagnostics(logger, timeProvider, organizationId!, request.ConversationId!, httpContext.TraceIdentifier, httpContext.RequestAborted); + var response = assistantService.StreamAsync(request, userId, planOptions, diagnostics, turnCancellationSource.Token); + await WriteResponseAsync(httpContext, response, assistantUsageService, organizationId!, diagnostics, turnCancellationSource.Token); + + return HttpResults.Empty; + } + + internal static async Task WriteResponseAsync( + HttpContext httpContext, + IAsyncEnumerable response, + AssistantUsageService assistantUsageService, + string organizationId, + AssistantTurnDiagnostics diagnostics, + CancellationToken cancellationToken) + { bool responseFailed = false; try { - await foreach (var item in assistantService.StreamAsync(request, userId, planOptions, turnCancellationSource.Token)) + await foreach (var item in response.WithCancellation(cancellationToken)) { + diagnostics.Observe(item); responseFailed |= item.Type == "error"; - await JsonSerializer.SerializeAsync(httpContext.Response.Body, item, s_jsonOptions, turnCancellationSource.Token); - await httpContext.Response.WriteAsync("\n", turnCancellationSource.Token); - await httpContext.Response.Body.FlushAsync(turnCancellationSource.Token); + string stage = diagnostics.Stage; + diagnostics.Stage = "response_write"; + await JsonSerializer.SerializeAsync(httpContext.Response.Body, item, s_jsonOptions, cancellationToken); + await httpContext.Response.WriteAsync("\n", cancellationToken); + await httpContext.Response.Body.FlushAsync(cancellationToken); + diagnostics.Stage = stage; } + diagnostics.Finish(responseFailed ? "failed" : "completed"); if (responseFailed) await assistantUsageService.RecordTurnFailedAsync(organizationId); else @@ -118,10 +138,14 @@ private static async Task StreamChatAsync( catch (OperationCanceledException) when (httpContext.RequestAborted.IsCancellationRequested) { // The browser closing or stopping the stream is expected. + diagnostics.Finish("cancelled", "client_disconnected"); await assistantUsageService.RecordTurnCancelledAsync(organizationId); } catch (OperationCanceledException) { + string failureCode = cancellationToken.IsCancellationRequested ? "turn_timeout" + : diagnostics.Stage is "provider_request" or "provider_stream" ? "provider_timeout" : "operation_cancelled"; + diagnostics.Finish("failed", failureCode); await assistantUsageService.RecordTurnFailedAsync(organizationId); var error = AssistantStreamEvent.Error("Exie took too long to complete this response. Try narrowing the question."); await JsonSerializer.SerializeAsync(httpContext.Response.Body, error, s_jsonOptions, CancellationToken.None); @@ -129,14 +153,22 @@ private static async Task StreamChatAsync( } catch (Exception ex) { + string failureCode = ex switch + { + AssistantProviderException providerException => providerException.FailureCode, + _ when diagnostics.Stage == "response_write" => "response_write_error", + _ when diagnostics.Stage == "tool_execution" => "tool_execution_error", + HttpRequestException when diagnostics.Stage is "provider_request" or "provider_stream" => "provider_transport_error", + JsonException when diagnostics.Stage == "provider_stream" => "invalid_provider_response", + IOException when diagnostics.Stage == "provider_stream" => "provider_stream_error", + _ => "internal_error" + }; + diagnostics.Finish("failed", failureCode, ex); await assistantUsageService.RecordTurnFailedAsync(organizationId); - logger.LogError(ex, "Unable to stream an in-app assistant response"); var error = AssistantStreamEvent.Error(ex is AssistantProviderException ? ex.Message : "Exie could not complete this request."); await JsonSerializer.SerializeAsync(httpContext.Response.Body, error, s_jsonOptions, CancellationToken.None); await httpContext.Response.WriteAsync("\n", CancellationToken.None); } - - return HttpResults.Empty; } private static async Task GetAccessAsync( diff --git a/src/Exceptionless.Web/ApmExtensions.cs b/src/Exceptionless.Web/ApmExtensions.cs index 0f6af7263f..be2f81c505 100644 --- a/src/Exceptionless.Web/ApmExtensions.cs +++ b/src/Exceptionless.Web/ApmExtensions.cs @@ -72,7 +72,7 @@ public static IHostBuilder AddApm(this IHostBuilder builder, ApmConfig config) }); b.AddHttpClientInstrumentation(); - b.AddSource("Exceptionless", "Foundatio"); + b.AddSource("Exceptionless", "Exceptionless.Assistant", "Foundatio"); if (config.EnableRedis) b.AddRedisInstrumentation(c => diff --git a/src/Exceptionless.Web/Assistant/AssistantModels.cs b/src/Exceptionless.Web/Assistant/AssistantModels.cs index 098ccab84c..4a9fc6ad84 100644 --- a/src/Exceptionless.Web/Assistant/AssistantModels.cs +++ b/src/Exceptionless.Web/Assistant/AssistantModels.cs @@ -43,10 +43,14 @@ public sealed record AssistantStreamEvent( string? Message = null, IReadOnlyCollection? SuggestedActions = null) { + [System.Text.Json.Serialization.JsonIgnore] + internal string? FailureCode { get; init; } + public static AssistantStreamEvent TextDelta(string text) => new("text_delta", Text: text); public static AssistantStreamEvent ToolCall(string id, string name, string arguments) => new("tool_call", ToolCallId: id, ToolName: name, Arguments: arguments); public static AssistantStreamEvent ToolResult(string id, string name, string result) => new("tool_result", ToolCallId: id, ToolName: name, Result: result); public static AssistantStreamEvent Suggestions(IReadOnlyCollection actions) => new("suggested_actions", SuggestedActions: actions); public static AssistantStreamEvent Error(string message) => new("error", Message: message); + internal static AssistantStreamEvent Error(string message, string failureCode) => new("error", Message: message) { FailureCode = failureCode }; public static AssistantStreamEvent Done() => new("done"); } diff --git a/src/Exceptionless.Web/Assistant/AssistantProviderDiagnostics.cs b/src/Exceptionless.Web/Assistant/AssistantProviderDiagnostics.cs new file mode 100644 index 0000000000..ce90af0074 --- /dev/null +++ b/src/Exceptionless.Web/Assistant/AssistantProviderDiagnostics.cs @@ -0,0 +1,287 @@ +using System.Diagnostics; +using System.Net.Sockets; +using System.Text.Json; + +namespace Exceptionless.Web.Assistant; + +internal sealed class AssistantProviderDiagnostics( + ILogger logger, + TimeProvider timeProvider, + AssistantTurnDiagnostics turn, + int inputCharacters, + bool allowTools, + CancellationToken cancellationToken) : IDisposable +{ + private readonly long _started = timeProvider.GetTimestamp(); + private readonly Activity? _activity = AppDiagnostics.AssistantActivitySource.StartActivity("assistant.provider"); + private bool _finished; + private bool _receivedError; + private Dictionary? _request; + private string? _apiKey; + private string? _requestSettings; + private string? _errorDetails; + private string? _routingDetails; + private string? _responseBodyState; + private bool _detailsTruncated; + private bool _detailsRedacted; + private int _chunks; + private double? _headersDuration; + private double? _firstChunkDuration; + private double? _lastChunkDuration; + private string? _exceptionType; + private string? _transportError; + private string? _socketError; + + public string? GenerationId { get; private set; } + public string? Model { get; private set; } + public string? ProviderName { get; private set; } + public int? StatusCode { get; private set; } + public string? FinishReason { get; private set; } + public bool UsageReceived { get; private set; } + public long? PromptTokens { get; private set; } + public long? CompletionTokens { get; private set; } + public long? ReasoningTokens { get; private set; } + public string? RequestId { get; private set; } + public string? ErrorCode { get; private set; } + public string? ErrorType { get; private set; } + public string? ProviderErrorCode { get; private set; } + public string? NativeFinishReason { get; private set; } + public string? ContentType { get; private set; } + public double? RetryAfterSeconds { get; private set; } + public string? Outcome { get; private set; } + + public void ObserveRequest(Dictionary request, string? apiKey) + { + _request = request; + _apiKey = apiKey; + _requestSettings = JsonSerializer.Serialize(new + { + max_tokens = request.GetValueOrDefault("max_tokens") as int?, + temperature = request.GetValueOrDefault("temperature") as double?, + tool_choice = request.GetValueOrDefault("tool_choice") is "none" ? "none" : "auto", + tool_count = (request.GetValueOrDefault("tools") as object[])?.Length, + message_count = (request.GetValueOrDefault("messages") as ICollection)?.Count, + maximum_prompt_price = AssistantLimits.MaximumProviderPromptPricePerMillionTokens, + maximum_completion_price = AssistantLimits.MaximumProviderCompletionPricePerMillionTokens + }); + } + + public void ObserveResponse(HttpResponseMessage response) + { + StatusCode = (int)response.StatusCode; + _headersDuration = timeProvider.GetElapsedTime(_started).TotalMilliseconds; + ContentType = SafeMetadata(response.Content.Headers.ContentType?.MediaType); + RequestId = GetHeader(response, "X-Request-Id") ?? GetHeader(response, "Request-Id") ?? GetHeader(response, "X-OpenRouter-Request-Id"); + RetryAfterSeconds = response.Headers.RetryAfter?.Delta?.TotalSeconds + ?? (response.Headers.RetryAfter?.Date - timeProvider.GetUtcNow())?.TotalSeconds; + if (response.Headers.TryGetValues("X-Generation-Id", out var values)) + { + GenerationId = SafeMetadata(values.FirstOrDefault()); + } + turn.Stage = "provider_stream"; + } + + public void ObserveChunk(JsonElement chunk) + { + if (chunk.ValueKind != JsonValueKind.Object) + { + return; + } + _chunks++; + _lastChunkDuration = timeProvider.GetElapsedTime(_started).TotalMilliseconds; + _firstChunkDuration ??= _lastChunkDuration; + GenerationId = GetMetadata(chunk, "id") ?? GenerationId; + Model = GetMetadata(chunk, "model") ?? Model; + ProviderName = GetMetadata(chunk, "provider") ?? ProviderName; + _receivedError |= chunk.TryGetProperty("error", out _); + if (chunk.TryGetProperty("error", out _) || chunk.TryGetProperty("openrouter_metadata", out _)) + { + ObserveErrorDetails(chunk); + } + if (chunk.TryGetProperty("usage", out var usage) && usage.ValueKind == JsonValueKind.Object) + { + UsageReceived = true; + PromptTokens = GetTokenCount(usage, "prompt_tokens") ?? PromptTokens; + CompletionTokens = GetTokenCount(usage, "completion_tokens") ?? CompletionTokens; + if (usage.TryGetProperty("completion_tokens_details", out var details) && details.ValueKind == JsonValueKind.Object + && GetTokenCount(details, "reasoning_tokens") is { } value) + { + ReasoningTokens = value; + } + } + if (chunk.TryGetProperty("choices", out var choices) && choices.ValueKind == JsonValueKind.Array && choices.GetArrayLength() > 0) + { + string? reason = GetMetadata(choices[0], "finish_reason"); + if (reason is not null) + { + FinishReason = reason is "stop" or "length" or "tool_calls" or "content_filter" or "error" ? reason : "unknown"; + } + NativeFinishReason = GetMetadata(choices[0], "native_finish_reason") ?? NativeFinishReason; + } + } + + public async Task ObserveErrorResponseAsync(HttpResponseMessage response, CancellationToken cancellationToken) + { + // Limit reads before parsing, including HTML/proxy errors and responses with no length. + const int maximumCharacters = 32_768; + using var reader = new StreamReader(await response.Content.ReadAsStreamAsync(cancellationToken)); + var buffer = new char[maximumCharacters + 1]; + int length = await reader.ReadBlockAsync(buffer.AsMemory(), cancellationToken); + _detailsTruncated = length > maximumCharacters; + _responseBodyState = _detailsTruncated ? "truncated" : length == 0 ? "empty" : "json"; + if (_detailsTruncated || length == 0) + { + return; + } + + try + { + using var document = JsonDocument.Parse(new string(buffer, 0, length), new JsonDocumentOptions { MaxDepth = 32 }); + ObserveErrorDetails(document.RootElement); + } + catch (JsonException) + { + // HTML and malformed JSON can echo arbitrary request data. Keep the response + // classification and headers, not an unfilterable body. + _responseBodyState = "invalid_json"; + } + } + + private void ObserveErrorDetails(JsonElement envelope) + { + if (envelope.ValueKind != JsonValueKind.Object) + { + _responseBodyState = "invalid_shape"; + return; + } + + GenerationId = GetMetadata(envelope, "id") ?? GenerationId; + Model = GetMetadata(envelope, "model") ?? Model; + ProviderName = GetMetadata(envelope, "provider") ?? ProviderName; + var messages = _request is not null && _request.TryGetValue("messages", out var value) + ? JsonSerializer.SerializeToElement(value) : default; + var details = new AssistantProviderErrorDetails(messages, _apiKey); + if (envelope.TryGetProperty("error", out var error)) + { + _receivedError = true; + _responseBodyState ??= "json"; + ErrorCode = GetCode(error, "code"); + ErrorType = GetMetadata(error, "type"); + if (error.ValueKind == JsonValueKind.Object && error.TryGetProperty("metadata", out var metadata)) + { + ErrorType = GetMetadata(metadata, "error_type") ?? ErrorType; + ProviderErrorCode = GetCode(metadata, "provider_code") ?? GetCode(metadata, "provider_error_code"); + ProviderName = GetMetadata(metadata, "provider_name") ?? ProviderName; + } + + _errorDetails = JsonSerializer.Serialize(details.Capture(error)); + } + + if (envelope.TryGetProperty("openrouter_metadata", out var routing)) + { + _routingDetails = JsonSerializer.Serialize(details.Capture(routing)); + } + + _detailsTruncated |= details.Truncated; + _detailsRedacted |= details.Redacted; + } + + public void Complete(int outputCharacters, int toolCalls, bool receivedDone) + { + string outcome = _receivedError ? "provider_error" : FinishReason switch + { + "length" => "output_limit", + "content_filter" => "content_filter", + "error" => "provider_error", + _ when outputCharacters == 0 && toolCalls == 0 => "empty_response", + _ when !receivedDone && FinishReason is null => "incomplete_stream", + _ => "completed" + }; + Finish(outcome, outputCharacters, toolCalls, receivedDone); + } + + public void RecordException(Exception exception, int? outputCharacters = null, int? toolCalls = null, bool receivedDone = false) + { + _exceptionType = exception.GetType().FullName; + _transportError = (exception as HttpRequestException)?.HttpRequestError.ToString(); + _socketError = (exception.InnerException as SocketException)?.SocketErrorCode.ToString(); + string outcome = exception switch + { + AssistantProviderException providerException => providerException.FailureCode, + OperationCanceledException => GetCancellationOutcome(), + HttpRequestException => "provider_transport_error", + JsonException => "invalid_provider_response", + IOException => "provider_stream_error", + _ => "internal_error" + }; + Finish(outcome, outputCharacters, toolCalls, receivedDone); + } + + public void Reject(string reason, int outputCharacters, int toolCalls, bool receivedDone) => Finish(reason, outputCharacters, toolCalls, receivedDone); + + private void Finish(string outcome, int? outputCharacters = null, int? toolCalls = null, bool receivedDone = false) + { + if (_finished) + { + return; + } + _finished = true; + Outcome = outcome; + double duration = timeProvider.GetElapsedTime(_started).TotalMilliseconds; + _activity?.SetTag("assistant.provider.outcome", outcome); + _activity?.SetTag("assistant.provider.generation_id", GenerationId); + _activity?.SetTag("assistant.provider.model", Model ?? turn.Model); + _activity?.SetTag("assistant.provider.name", ProviderName); + _activity?.SetTag("assistant.provider.finish_reason", FinishReason); + _activity?.SetTag("http.response.status_code", StatusCode); + _activity?.SetTag("assistant.provider.error.code", ErrorCode); + _activity?.SetTag("assistant.provider.error.type", ErrorType); + _activity?.SetTag("assistant.provider.error.provider_code", ProviderErrorCode); + _activity?.SetTag("assistant.provider.request_id", RequestId); + if (outcome is not ("completed" or "cancelled")) + { + _activity?.SetStatus(ActivityStatusCode.Error, outcome); + } + AppDiagnostics.AssistantProviderDuration.Record(duration, new KeyValuePair("outcome", outcome)); + logger.Log(outcome is "completed" or "cancelled" ? LogLevel.Information : LogLevel.Warning, + "Assistant provider request {ProviderRequestNumber} {ProviderOutcome} for turn {AssistantTurnId}: duration={DurationMs} ms generation={ProviderGenerationId} model={ProviderModel} provider={ProviderName} status={ProviderStatusCode} finish={ProviderFinishReason} input_characters={InputCharacters} output_characters={OutputCharacters} tools_allowed={ToolsAllowed} tool_calls={ToolCalls} usage_received={UsageReceived} prompt_tokens={PromptTokens} completion_tokens={CompletionTokens} reasoning_tokens={ReasoningTokens} received_done={ReceivedDone} request={ProviderRequestId} error_code={ProviderErrorCode} error_type={ProviderErrorType} upstream_code={UpstreamErrorCode} native_finish={ProviderNativeFinishReason} retry_after={RetryAfterSeconds} content_type={ProviderContentType} headers_ms={HeadersDurationMs} first_chunk_ms={FirstChunkDurationMs} last_chunk_ms={LastChunkDurationMs} chunks={ChunkCount} error_details={ProviderErrorDetails} routing={ProviderRoutingDetails} body_state={ProviderErrorBodyState} details_truncated={ProviderDetailsTruncated} details_redacted={ProviderDetailsRedacted} exception_type={ExceptionType} transport_error={TransportError} socket_error={SocketError} request_settings={ProviderRequestSettings}", + turn.ProviderRequests, outcome, turn.TurnId, duration, GenerationId, Model ?? turn.Model, ProviderName, StatusCode, + FinishReason, inputCharacters, outputCharacters, allowTools, toolCalls, UsageReceived, PromptTokens, CompletionTokens, ReasoningTokens, receivedDone, + RequestId, ErrorCode, ErrorType, ProviderErrorCode, NativeFinishReason, RetryAfterSeconds, ContentType, _headersDuration, + _firstChunkDuration, _lastChunkDuration, _chunks, _errorDetails, _routingDetails, _responseBodyState, _detailsTruncated, _detailsRedacted, + _exceptionType, _transportError, _socketError, _requestSettings); + _request = null; + _apiKey = null; + _activity?.Dispose(); + } + + public void Dispose() => Finish(StatusCode is < 200 or >= 300 ? "provider_http_error" + : _receivedError || FinishReason == "error" ? "provider_error" + : cancellationToken.IsCancellationRequested ? GetCancellationOutcome() : "interrupted"); + + private string GetCancellationOutcome() + { + string reason = turn.GetCancellationReason(cancellationToken, "provider_timeout"); + return reason == "client_disconnected" ? "cancelled" : reason; + } + + private string? GetMetadata(JsonElement element, string name) + => element.ValueKind == JsonValueKind.Object && element.TryGetProperty(name, out var property) && property.ValueKind == JsonValueKind.String + ? SafeMetadata(property.GetString()) : null; + + private string? GetCode(JsonElement element, string name) + => element.ValueKind == JsonValueKind.Object && element.TryGetProperty(name, out var property) && property.ValueKind == JsonValueKind.Number + && property.TryGetInt32(out int value) ? value.ToString(System.Globalization.CultureInfo.InvariantCulture) : GetMetadata(element, name); + + private string? GetHeader(HttpResponseMessage response, string name) + => response.Headers.TryGetValues(name, out var values) ? SafeMetadata(values.FirstOrDefault()) : null; + + private static long? GetTokenCount(JsonElement element, string name) + => element.TryGetProperty(name, out var property) && property.ValueKind == JsonValueKind.Number && property.TryGetInt64(out long value) + ? Math.Max(0, value) : null; + + private string? SafeMetadata(string? value) + => value is { Length: > 0 and <= 128 } && (String.IsNullOrEmpty(_apiKey) || !value.Contains(_apiKey, StringComparison.Ordinal)) + && value.All(character => Char.IsAsciiLetterOrDigit(character) || character is '-' or '_' or '/' or '.' or ':' or '~' or ' ') + ? value : null; +} diff --git a/src/Exceptionless.Web/Assistant/AssistantProviderErrorDetails.cs b/src/Exceptionless.Web/Assistant/AssistantProviderErrorDetails.cs new file mode 100644 index 0000000000..db4edd45c4 --- /dev/null +++ b/src/Exceptionless.Web/Assistant/AssistantProviderErrorDetails.cs @@ -0,0 +1,261 @@ +using System.Text.Json; +using System.Text.RegularExpressions; + +namespace Exceptionless.Web.Assistant; + +// Provider errors sometimes wrap the useful error in metadata.raw, and sometimes echo +// the request there too. Extract diagnostic fields instead of logging the response body. +internal sealed class AssistantProviderErrorDetails(JsonElement requestMessages, string? apiKey) +{ + private const int MaximumTextLength = 2048; + private const int MaximumFields = 64; + private const int MaximumItems = 16; + private static readonly Regex s_credentials = new( + @"\b(?:Bearer|Basic)\s+[^\s,;]+|\bsk-[A-Za-z0-9_-]+|\b(?:api[_-]?key|password|secret|access[_-]?token|authorization)\s*[:=]\s*[^\s,;]+", + RegexOptions.IgnoreCase | RegexOptions.CultureInvariant | RegexOptions.NonBacktracking, TimeSpan.FromMilliseconds(100)); + private static readonly Regex s_urls = new(@"https?://[^\s<>""']+", RegexOptions.CultureInvariant | RegexOptions.NonBacktracking, TimeSpan.FromMilliseconds(100)); + private readonly string[] _requestValues = GetRequestValues(requestMessages, apiKey).OrderByDescending(value => value.Length).ToArray(); + private int _fields; + private int _remainingCharacters = 8192; + + public bool Truncated { get; private set; } + public bool Redacted { get; private set; } + + public Dictionary Capture(JsonElement value, int depth = 0) + { + var result = new Dictionary(); + if (value.ValueKind != JsonValueKind.Object) + { + return result; + } + + foreach (var property in value.EnumerateObject()) + { + if (_fields >= MaximumFields || depth >= 6 || _remainingCharacters <= 0) + { + Truncated = true; + break; + } + + switch (property.Name) + { + case "code": case "type": case "message": case "msg": case "param": + case "error_type": case "provider_code": case "provider_error_code": case "provider_name": + case "limit_source": case "is_byok": case "failed_routing_step": case "input_endpoint_count": + case "reason": case "endpoint_count": case "request_id": + case "requested": case "strategy": case "region": case "attempt": case "total": + case "provider": case "model": case "status": case "selected": + _fields++; + result[property.Name] = CaptureScalar(property.Value); + break; + case "error": case "metadata": case "endpoints": + _fields++; + result[property.Name] = Capture(property.Value, depth + 1); + break; + case "raw": case "detail": + _fields++; + result[property.Name] = CaptureNested(property.Value, depth + 1); + break; + case "errors": case "ineligibility_reasons": case "routing_funnel": case "attempts": case "available": case "loc": + _fields++; + result[property.Name] = CaptureArray(property.Value, depth + 1); + break; + case "step": + _fields++; + result[property.Name] = CaptureScalar(property.Value); + break; + } + } + + return result; + } + + public string SanitizeText(string value) + { + string sanitized; + try + { + foreach (string requestValue in _requestValues) + { + value = requestValue.Length >= 8 + ? value.Replace(requestValue, "[REDACTED]", StringComparison.Ordinal) + : Regex.Replace(value, $@"(? Char.IsControl(character) ? ' ' : character)); + int length = Math.Min(MaximumTextLength, _remainingCharacters); + if (sanitized.Length > length) + { + Truncated = true; + sanitized = sanitized[..length]; + } + + _remainingCharacters -= sanitized.Length; + return sanitized; + } + + private object? CaptureScalar(JsonElement value) => value.ValueKind switch + { + JsonValueKind.String => SanitizeText(value.GetString()!), + JsonValueKind.Number when value.TryGetDecimal(out decimal number) => number, + JsonValueKind.True => true, + JsonValueKind.False => false, + _ => null + }; + + private object? CaptureNested(JsonElement value, int depth) + { + if (depth >= 6) + { + Truncated = true; + return null; + } + + if (value.ValueKind == JsonValueKind.Object) + { + return Capture(value, depth); + } + + if (value.ValueKind == JsonValueKind.Array) + { + return CaptureArray(value, depth); + } + + if (value.ValueKind != JsonValueKind.String) + { + return CaptureScalar(value); + } + + string text = value.GetString()!; + if (text.TrimStart().StartsWith('{') || text.TrimStart().StartsWith('[')) + { + try + { + using var document = JsonDocument.Parse(text, new JsonDocumentOptions { MaxDepth = 16 }); + return CaptureNested(document.RootElement, depth + 1); + } + catch (JsonException) + { + // A partial JSON body cannot be safely filtered by field name. + return "[INVALID JSON]"; + } + } + + return SanitizeText(text); + } + + private object? CaptureArray(JsonElement value, int depth) + { + if (value.ValueKind != JsonValueKind.Array) + { + return null; + } + + Truncated |= value.GetArrayLength() > MaximumItems; + return value.EnumerateArray().Take(MaximumItems).Select(item => CaptureNested(item, depth)).ToArray(); + } + + private static HashSet GetRequestValues(JsonElement messages, string? apiKey) + { + var values = new HashSet(StringComparer.Ordinal); + if (!String.IsNullOrEmpty(apiKey)) + { + values.Add(apiKey); + } + + if (messages.ValueKind == JsonValueKind.Array) + { + foreach (var message in messages.EnumerateArray()) + { + if (message.ValueKind != JsonValueKind.Object) + { + continue; + } + + if (message.TryGetProperty("content", out var content) && content.ValueKind == JsonValueKind.String) + { + AddValue(content.GetString()!, values); + } + + foreach (string name in new[] { "reasoning", "reasoning_content", "reasoning_details" }) + { + if (message.TryGetProperty(name, out var reasoning)) + { + AddJsonValues(reasoning, values); + } + } + + if (message.TryGetProperty("tool_calls", out var calls) && calls.ValueKind == JsonValueKind.Array) + { + foreach (var call in calls.EnumerateArray()) + { + if (call.TryGetProperty("function", out var function) && function.TryGetProperty("arguments", out var arguments) + && arguments.ValueKind == JsonValueKind.String) + { + AddValue(arguments.GetString()!, values); + } + } + } + } + } + + return values; + } + + private static void AddValue(string value, HashSet values) + { + if (!String.IsNullOrEmpty(value)) + { + values.Add(value); + } + + foreach (string line in value.Split('\n', StringSplitOptions.TrimEntries | StringSplitOptions.RemoveEmptyEntries)) + { + if (line.Length >= 8) + { + values.Add(line); + } + } + + try + { + using var document = JsonDocument.Parse(value); + AddJsonValues(document.RootElement, values); + } + catch (JsonException) + { + } + } + + private static void AddJsonValues(JsonElement value, HashSet values) + { + if (value.ValueKind == JsonValueKind.Object) + { + foreach (var property in value.EnumerateObject()) + { + AddJsonValues(property.Value, values); + } + } + else if (value.ValueKind == JsonValueKind.Array) + { + foreach (var item in value.EnumerateArray()) + { + AddJsonValues(item, values); + } + } + else if (value.ValueKind == JsonValueKind.String && value.GetString() is { Length: > 0 } text) + { + values.Add(text); + } + } +} diff --git a/src/Exceptionless.Web/Assistant/AssistantProviderException.cs b/src/Exceptionless.Web/Assistant/AssistantProviderException.cs index da724717e0..501ac03bd2 100644 --- a/src/Exceptionless.Web/Assistant/AssistantProviderException.cs +++ b/src/Exceptionless.Web/Assistant/AssistantProviderException.cs @@ -1,3 +1,6 @@ namespace Exceptionless.Web.Assistant; -public sealed class AssistantProviderException(string message) : Exception(message); +public sealed class AssistantProviderException(string message) : Exception(message) +{ + internal string FailureCode { get; init; } = "provider_error"; +} diff --git a/src/Exceptionless.Web/Assistant/AssistantService.cs b/src/Exceptionless.Web/Assistant/AssistantService.cs index c52de20f52..0674167dbb 100644 --- a/src/Exceptionless.Web/Assistant/AssistantService.cs +++ b/src/Exceptionless.Web/Assistant/AssistantService.cs @@ -36,14 +36,26 @@ public sealed class AssistantService( private static readonly JsonSerializerOptions s_jsonOptions = new JsonSerializerOptions(JsonSerializerDefaults.Web).ConfigureExceptionlessApiDefaults(); private static readonly Regex s_rawDsmlPattern = new(@"<\s*/?\s*[|｜]\s*DSML\s*[|｜]", RegexOptions.IgnoreCase | RegexOptions.CultureInvariant, TimeSpan.FromSeconds(1)); - public async IAsyncEnumerable StreamAsync( + public IAsyncEnumerable StreamAsync( AssistantChatRequest request, string userId, AssistantPlanOptions planOptions, + CancellationToken cancellationToken = default) + => StreamAsync(request, userId, planOptions, null, cancellationToken); + + internal async IAsyncEnumerable StreamAsync( + AssistantChatRequest request, + string userId, + AssistantPlanOptions planOptions, + AssistantTurnDiagnostics? diagnostics, [EnumeratorCancellation] CancellationToken cancellationToken = default) { var options = appOptions.AssistantOptions; string model = (await assistantModelSettingsService.GetAsync()).Model; + if (diagnostics is not null) + { + diagnostics.Model = model; + } AssistantConversationState? conversationState = null; if (!String.IsNullOrWhiteSpace(request.OrganizationId) && !String.IsNullOrWhiteSpace(request.ConversationId)) { @@ -71,10 +83,14 @@ public async IAsyncEnumerable StreamAsync( { if (completedToolRounds > 0) { + if (diagnostics is not null) + { + diagnostics.Stage = "usage_check"; + } var usageDecision = await assistantUsageService.TryContinueTurnAsync(request.OrganizationId, planOptions); if (!usageDecision.Allowed) { - yield return AssistantStreamEvent.Error(usageDecision.Message ?? "Exie reached this organization's usage limit."); + yield return AssistantStreamEvent.Error(usageDecision.Message ?? "Exie reached this organization's usage limit.", "usage_limit"); yield return AssistantStreamEvent.Done(); yield break; } @@ -101,6 +117,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(); @@ -110,87 +128,138 @@ public async IAsyncEnumerable StreamAsync( if (providerInputCharacters > AssistantLimits.MaximumProviderInputCharacters) { throw new AssistantProviderException( - "This conversation contains too much context for one response. Clear the conversation or narrow the question."); + "This conversation contains too much context for one response. Clear the conversation or narrow the question.") { FailureCode = "context_limit" }; } + if (diagnostics is not null) + { + diagnostics.Stage = "usage_reservation"; + } await using var providerRequest = await assistantUsageService.StartProviderRequestAsync(request.OrganizationId, providerInputCharacters); - using var response = await SendRequestAsync(messages, options, model, allowTools, request, cancellationToken); - providerRequest.MarkAccepted(); - await using var stream = await response.Content.ReadAsStreamAsync(cancellationToken); - using var reader = new StreamReader(stream); - - while (await reader.ReadLineAsync(cancellationToken) is { } line) + using var providerDiagnostics = diagnostics?.StartProviderRequest(providerInputCharacters, allowTools, cancellationToken); + bool receivedDone = false; + try { - if (!line.StartsWith("data:", StringComparison.Ordinal)) - continue; - - string payload = line[5..].Trim(); - if (payload.Length == 0 || payload == "[DONE]") - continue; - - using var document = JsonDocument.Parse(payload); - if (document.RootElement.TryGetProperty("error", out var error)) - throw new AssistantProviderException(GetProviderError(error)); + using var response = await SendRequestAsync(messages, options, model, allowTools, request, providerDiagnostics, cancellationToken); + providerRequest.MarkAccepted(); + await using var stream = await response.Content.ReadAsStreamAsync(cancellationToken); + using var reader = new StreamReader(stream); - if (!usageRecorded && TryGetProviderUsage(document.RootElement, out var usage)) + while (await reader.ReadLineAsync(cancellationToken) is { } line) { - usageRecorded = true; - try + if (!line.StartsWith("data:", StringComparison.Ordinal)) + continue; + + string payload = line[5..].Trim(); + if (payload == "[DONE]") { - await providerRequest.ReconcileAsync(usage); + receivedDone = true; + continue; } - catch (Exception ex) + if (payload.Length == 0) + continue; + + try { - // Disposal records the conservative reservation when detailed provider - // accounting cannot be reconciled. - logger.LogError(ex, "Unable to record assistant provider usage for organization {OrganizationId}", request.OrganizationId); - } - } + using var document = JsonDocument.Parse(payload); + providerDiagnostics?.ObserveChunk(document.RootElement); + if (document.RootElement.TryGetProperty("error", out var error)) + throw new AssistantProviderException(GetProviderError(error)); - if (!document.RootElement.TryGetProperty("choices", out var choices) || choices.GetArrayLength() == 0) - continue; + if (!usageRecorded && TryGetProviderUsage(document.RootElement, out var usage)) + { + usageRecorded = true; + try + { + await providerRequest.ReconcileAsync(usage); + } + catch (Exception ex) + { + // Disposal records the conservative reservation when detailed provider + // accounting cannot be reconciled. + logger.LogError(ex, "Unable to record assistant provider usage for organization {OrganizationId}", request.OrganizationId); + } + } - var delta = choices[0].GetProperty("delta"); - if (delta.TryGetProperty("content", out var content) && content.ValueKind == JsonValueKind.String) - { - string? text = content.GetString(); - if (!String.IsNullOrEmpty(text)) - { - assistantContent.Append(text); - assistantContentChunks.Add(text); - } - } + if (!document.RootElement.TryGetProperty("choices", out var choices) || choices.GetArrayLength() == 0) + continue; - if (!delta.TryGetProperty("tool_calls", out var toolCallUpdates)) - 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()); + } - foreach (var update in toolCallUpdates.EnumerateArray()) - { - int index = update.GetProperty("index").GetInt32(); - if (!toolCalls.TryGetValue(index, out var pending)) - { - pending = new PendingToolCall(); - toolCalls[index] = pending; - } + if (delta.TryGetProperty("reasoning_details", out var reasoningDetails) && reasoningDetails.ValueKind == JsonValueKind.Array) + { + foreach (var detail in reasoningDetails.EnumerateArray()) + { + assistantReasoningDetails.Add(detail.Clone()); + } + } - if (update.TryGetProperty("id", out var id) && id.ValueKind == JsonValueKind.String) - pending.Id = id.GetString() ?? pending.Id; + if (delta.TryGetProperty("content", out var content) && content.ValueKind == JsonValueKind.String) + { + string? text = content.GetString(); + if (!String.IsNullOrEmpty(text)) + { + assistantContent.Append(text); + assistantContentChunks.Add(text); + } + } - if (!update.TryGetProperty("function", out var function)) - continue; + if (!delta.TryGetProperty("tool_calls", out var toolCallUpdates)) + continue; - if (function.TryGetProperty("name", out var name) && name.ValueKind == JsonValueKind.String) - pending.Name += name.GetString(); - if (function.TryGetProperty("arguments", out var arguments) && arguments.ValueKind == JsonValueKind.String) - pending.Arguments.Append(arguments.GetString()); + foreach (var update in toolCallUpdates.EnumerateArray()) + { + int index = update.GetProperty("index").GetInt32(); + if (!toolCalls.TryGetValue(index, out var pending)) + { + pending = new PendingToolCall(); + toolCalls[index] = pending; + } + + if (update.TryGetProperty("id", out var id) && id.ValueKind == JsonValueKind.String) + pending.Id = id.GetString() ?? pending.Id; + + if (!update.TryGetProperty("function", out var function)) + continue; + + if (function.TryGetProperty("name", out var name) && name.ValueKind == JsonValueKind.String) + pending.Name += name.GetString(); + if (function.TryGetProperty("arguments", out var arguments) && arguments.ValueKind == JsonValueKind.String) + pending.Arguments.Append(arguments.GetString()); + } + } + catch (Exception ex) when (ex is InvalidOperationException or KeyNotFoundException or FormatException) + { + throw new JsonException("The AI provider returned an invalid response structure.", ex); + } } } + catch (Exception ex) + { + providerDiagnostics?.RecordException(ex, assistantContent.Length, toolCalls.Count, receivedDone); + throw; + } + + if (diagnostics is not null) + { + diagnostics.Stage = "response_validation"; + } if (s_rawDsmlPattern.IsMatch(assistantContent.ToString())) { + providerDiagnostics?.Reject("malformed_response", assistantContent.Length, toolCalls.Count, receivedDone); if (malformedResponseRetries < AssistantLimits.MaximumMalformedResponseRetries) { malformedResponseRetries++; + if (diagnostics is not null) + { + diagnostics.MalformedResponseRetries = malformedResponseRetries; + } logger.LogWarning( "Assistant provider returned raw DSML content for organization {OrganizationId}; retrying response", request.OrganizationId); @@ -206,7 +275,7 @@ public async IAsyncEnumerable StreamAsync( logger.LogWarning( "Assistant provider returned raw DSML content again for organization {OrganizationId}", request.OrganizationId); - yield return AssistantStreamEvent.Error("Exie received a malformed response from the AI provider. Please try again."); + yield return AssistantStreamEvent.Error("Exie received a malformed response from the AI provider. Please try again.", "malformed_response"); yield return AssistantStreamEvent.Done(); yield break; } @@ -217,6 +286,15 @@ public async IAsyncEnumerable StreamAsync( malformedResponseCorrection = null; } + if (!allowTools && toolCalls.Count > 0) + { + providerDiagnostics?.Reject("tool_round_limit", assistantContent.Length, toolCalls.Count, receivedDone); + } + else + { + providerDiagnostics?.Complete(assistantContent.Length, toolCalls.Count, receivedDone); + } + foreach (string text in assistantContentChunks) { yield return AssistantStreamEvent.TextDelta(text); @@ -226,7 +304,14 @@ public async IAsyncEnumerable StreamAsync( { if (assistantContent.Length == 0) { - yield return AssistantStreamEvent.Error("Exie stopped before providing an answer. Please try again."); + string failureCode = providerDiagnostics?.FinishReason switch + { + "length" => "output_limit", + "content_filter" => "content_filter", + "error" => "provider_error", + _ => "empty_response" + }; + yield return AssistantStreamEvent.Error("Exie stopped before providing an answer. Please try again.", failureCode); } else if (pendingSuggestedActions.Count > 0) { @@ -239,7 +324,7 @@ public async IAsyncEnumerable StreamAsync( if (!allowTools) { - yield return AssistantStreamEvent.Error("Exie could not finish using the available tool results. Try narrowing the question."); + yield return AssistantStreamEvent.Error("Exie could not finish using the available tool results. Try narrowing the question.", "tool_round_limit"); yield return AssistantStreamEvent.Done(); yield break; } @@ -269,17 +354,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 { @@ -293,6 +368,10 @@ public async IAsyncEnumerable StreamAsync( requireFinalAnswer = true; completedToolRounds++; + if (diagnostics is not null) + { + diagnostics.ToolRounds = completedToolRounds; + } continue; } @@ -300,24 +379,16 @@ 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) { string arguments = toolCall.Arguments.ToString(); + diagnostics?.StartTool(toolCall.Name); yield return AssistantStreamEvent.ToolCall(toolCall.Id, toolCall.Name, arguments); + long toolStarted = timeProvider.GetTimestamp(); string result; if (remainingToolCalls <= 0) { @@ -350,9 +421,18 @@ public async IAsyncEnumerable StreamAsync( if (toolCall.Name == SearchStacksTool) remainingProjectSearches--; - result = await ExecuteToolAsync(toolCall.Name, arguments, request, cancellationToken); + try + { + result = await ExecuteToolAsync(toolCall.Name, arguments, request, cancellationToken); + } + catch (Exception ex) + { + diagnostics?.RecordToolException(ex, timeProvider.GetElapsedTime(toolStarted).TotalMilliseconds, cancellationToken); + throw; + } } + diagnostics?.RecordToolResult(result, timeProvider.GetElapsedTime(toolStarted).TotalMilliseconds); if (toolCall.Name == GetProjectSetupTool) configureHref = AssistantSuggestedActionParser.GetProjectSetupHref(result) ?? configureHref; @@ -372,6 +452,10 @@ public async IAsyncEnumerable StreamAsync( && !String.IsNullOrWhiteSpace(request.OrganizationId) && !String.IsNullOrWhiteSpace(request.ConversationId)) { + if (diagnostics is not null) + { + diagnostics.Stage = "conversation_save"; + } await assistantConversationService.AppendToolResultsAsync( userId, request.OrganizationId, @@ -381,16 +465,21 @@ await assistantConversationService.AppendToolResultsAsync( } completedToolRounds++; + if (diagnostics is not null) + { + diagnostics.ToolRounds = completedToolRounds; + } } } - 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, AssistantProviderDiagnostics? diagnostics, CancellationToken cancellationToken) { var client = httpClientFactory.CreateClient(nameof(AssistantService)); using var providerRequest = new HttpRequestMessage(HttpMethod.Post, options.Endpoint); providerRequest.Headers.Authorization = new("Bearer", options.ApiKey); providerRequest.Headers.TryAddWithoutValidation("HTTP-Referer", appOptions.BaseURL); providerRequest.Headers.TryAddWithoutValidation("X-OpenRouter-Title", "Exceptionless"); + providerRequest.Headers.TryAddWithoutValidation("X-OpenRouter-Metadata", "enabled"); var payload = new Dictionary { ["model"] = model, @@ -407,19 +496,63 @@ 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); + diagnostics?.ObserveRequest(payload, options.ApiKey); var response = await client.SendAsync(providerRequest, HttpCompletionOption.ResponseHeadersRead, cancellationToken); + diagnostics?.ObserveResponse(response); 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(); - throw new AssistantProviderException($"The AI provider returned status {(int)response.StatusCode}."); + using (response) + { + if (diagnostics is not null) + { + await diagnostics.ObserveErrorResponseAsync(response, cancellationToken); + } + + logger.LogWarning("Assistant provider returned HTTP {StatusCode} with generation {ProviderGenerationId}", (int)response.StatusCode, diagnostics?.GenerationId); + } + throw new AssistantProviderException($"The AI provider returned status {(int)response.StatusCode}.") { FailureCode = "provider_http_error" }; + } + + 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( diff --git a/src/Exceptionless.Web/Assistant/AssistantTurnDiagnostics.cs b/src/Exceptionless.Web/Assistant/AssistantTurnDiagnostics.cs new file mode 100644 index 0000000000..a862d01f89 --- /dev/null +++ b/src/Exceptionless.Web/Assistant/AssistantTurnDiagnostics.cs @@ -0,0 +1,190 @@ +using System.Diagnostics; +using System.Text.Json; +using Exceptionless.Web.Mcp; + +namespace Exceptionless.Web.Assistant; + +internal sealed class AssistantTurnDiagnostics : IDisposable +{ + private readonly ILogger _logger; + private readonly TimeProvider _timeProvider; + private readonly long _started; + private readonly Activity? _activity; + private readonly IDisposable? _scope; + private readonly CancellationToken _requestAborted; + private bool _finished; + private double? _firstTextDuration; + private string? _failureCode; + + public AssistantTurnDiagnostics(ILogger logger, TimeProvider timeProvider, string organizationId, string conversationId, string requestId, CancellationToken requestAborted = default) + { + _logger = logger; + _timeProvider = timeProvider; + _requestAborted = requestAborted; + _started = timeProvider.GetTimestamp(); + _activity = AppDiagnostics.AssistantActivitySource.StartActivity("assistant.turn"); + TurnId = Guid.NewGuid().ToString("N"); + OrganizationId = organizationId; + ConversationId = conversationId; + RequestId = requestId; + TraceId = Activity.Current?.TraceId.ToString(); + _activity?.SetTag("assistant.turn.id", TurnId); + _activity?.SetTag("organization.id", organizationId); + _activity?.SetTag("assistant.conversation.id", conversationId); + _scope = logger.BeginScope(new Dictionary + { + ["AssistantTurnId"] = TurnId, + ["OrganizationId"] = organizationId, + ["ConversationId"] = conversationId, + ["RequestId"] = requestId, + ["TraceId"] = TraceId + }); + } + + public string TurnId { get; } + public string OrganizationId { get; } + public string ConversationId { get; } + public string RequestId { get; } + public string? TraceId { get; } + public bool IsClientDisconnected => _requestAborted.IsCancellationRequested; + public string? Model { get; set; } + public string Stage { get; set; } = "initializing"; + public int ProviderRequests { get; private set; } + public int ToolCalls { get; private set; } + public int ToolFailures { get; private set; } + public int ToolRounds { get; set; } + public int MalformedResponseRetries { get; set; } + public string? LastTool { get; private set; } + public string? LastToolError { get; private set; } + public AssistantProviderDiagnostics? Provider { get; private set; } + + public string GetCancellationReason(CancellationToken cancellationToken, string operationReason) + => IsClientDisconnected ? "client_disconnected" : cancellationToken.IsCancellationRequested ? "turn_timeout" : operationReason; + + public AssistantProviderDiagnostics StartProviderRequest(int inputCharacters, bool allowTools, CancellationToken cancellationToken) + { + Stage = "provider_request"; + ProviderRequests++; + Provider = new AssistantProviderDiagnostics(_logger, _timeProvider, this, inputCharacters, allowTools, cancellationToken); + return Provider; + } + + public void Observe(AssistantStreamEvent item) + { + if (item.Type == "error") + { + _failureCode ??= item.FailureCode ?? "response_error"; + } + if (item.Type == "text_delta" && !String.IsNullOrEmpty(item.Text)) + { + _firstTextDuration ??= ElapsedMilliseconds; + } + } + + public void StartTool(string name) + { + Stage = "tool_execution"; + LastTool = GetToolName(name); + ToolCalls++; + } + + public void RecordToolResult(string result, double durationMilliseconds) + { + using var document = JsonDocument.Parse(result); + var root = document.RootElement; + bool failed = root.ValueKind == JsonValueKind.Object && root.TryGetProperty("ok", out var ok) && ok.ValueKind == JsonValueKind.False; + string? errorCode = null; + if (failed) + { + ToolFailures++; + errorCode = "tool_error"; + if (root.TryGetProperty("error", out var error) && error.ValueKind == JsonValueKind.Object + && error.TryGetProperty("code", out var code) && code.ValueKind == JsonValueKind.String) + { + errorCode = GetToolErrorCode(code.GetString()); + } + LastToolError = errorCode; + _logger.LogWarning("Assistant tool {ToolName} failed with {ToolErrorCode} in {DurationMs} ms for turn {AssistantTurnId}", + LastTool, errorCode, durationMilliseconds, TurnId); + } + + AppDiagnostics.AssistantToolDuration.Record(durationMilliseconds, + new("tool", LastTool), new("outcome", failed ? "failed" : "completed"), new("reason", errorCode ?? "none")); + } + + public void RecordToolException(Exception exception, double durationMilliseconds, CancellationToken cancellationToken) + { + LastToolError = exception is OperationCanceledException ? GetCancellationReason(cancellationToken, "operation_cancelled") : "tool_execution_error"; + bool cancelled = LastToolError == "client_disconnected"; + string outcome = cancelled ? "cancelled" : "failed"; + if (!cancelled) + { + ToolFailures++; + } + + _logger.Log(cancelled ? LogLevel.Information : LogLevel.Warning, + "Assistant tool {ToolName} {ToolOutcome} with {ToolErrorCode} in {DurationMs} ms for turn {AssistantTurnId}: exception_type={ExceptionType}", + LastTool, outcome, LastToolError, durationMilliseconds, TurnId, exception.GetType().FullName); + AppDiagnostics.AssistantToolDuration.Record(durationMilliseconds, + new("tool", LastTool), new("outcome", outcome), new("reason", LastToolError)); + } + + public void Finish(string outcome, string? failureCode = null, Exception? exception = null) + { + if (_finished) + { + return; + } + _finished = true; + string reason = failureCode ?? _failureCode ?? "none"; + _activity?.SetTag("assistant.outcome", outcome); + _activity?.SetTag("assistant.failure.reason", reason); + _activity?.SetTag("assistant.stage", Stage); + _activity?.SetTag("assistant.model", Model); + _activity?.SetTag("assistant.provider.requests", ProviderRequests); + _activity?.SetTag("assistant.tool.calls", ToolCalls); + if (outcome == "failed") + { + _activity?.SetStatus(ActivityStatusCode.Error, reason); + } + + AppDiagnostics.AssistantTurnDuration.Record(ElapsedMilliseconds, + new("outcome", outcome), new("reason", reason), new("stage", Stage)); + + // Include correlation in the message as well as the scope: the production console + // formatter does not render scope properties, and streaming errors retain HTTP 200. + var level = outcome == "failed" ? exception is null ? LogLevel.Warning : LogLevel.Error : LogLevel.Information; + _logger.Log(level, + "Assistant turn {AssistantTurnId} {Outcome}: reason={FailureReason} stage={Stage} duration={DurationMs} ms first_text={FirstTextDurationMs} ms organization={OrganizationId} conversation={ConversationId} request={RequestId} trace={TraceId} model={Model} provider_requests={ProviderRequests} tool_rounds={ToolRounds} tool_calls={ToolCalls} tool_failures={ToolFailures} last_tool={LastTool} last_tool_error={LastToolError} malformed_retries={MalformedResponseRetries} generation={ProviderGenerationId} provider_model={ProviderModel} provider={ProviderName} status={ProviderStatusCode} finish={ProviderFinishReason} usage_received={ProviderUsageReceived} reasoning_tokens={ReasoningTokens} exception_type={ExceptionType} exception_stack={ExceptionStackTrace}", + TurnId, outcome, reason, Stage, ElapsedMilliseconds, _firstTextDuration, OrganizationId, ConversationId, RequestId, TraceId, + Model, ProviderRequests, ToolRounds, ToolCalls, ToolFailures, LastTool, LastToolError, MalformedResponseRetries, + Provider?.GenerationId, Provider?.Model, Provider?.ProviderName, Provider?.StatusCode, Provider?.FinishReason, + Provider?.UsageReceived, Provider?.ReasoningTokens, exception?.GetType().FullName, exception?.StackTrace); + } + + private double ElapsedMilliseconds => _timeProvider.GetElapsedTime(_started).TotalMilliseconds; + + public void Dispose() + { + _scope?.Dispose(); + _activity?.Dispose(); + } + + private static string GetToolName(string name) => name switch + { + "get_event" or "get_stack" or "get_project_setup" or "get_stack_events" or "list_projects" or "search_stacks" + or "update_stack_status" or "snooze_stack" or "set_stack_critical" or "add_stack_reference_link" or "remove_stack_reference_link" => name, + _ => "unknown" + }; + + private static string GetToolErrorCode(string? code) => code switch + { + McpErrorCodes.ContextMismatch or McpErrorCodes.ContextRequired or McpErrorCodes.Forbidden or McpErrorCodes.InvalidClientPlatform + or McpErrorCodes.InvalidCursor or McpErrorCodes.InvalidDetailSize or McpErrorCodes.InvalidFilter or McpErrorCodes.InvalidGroupBy + or McpErrorCodes.InvalidId or McpErrorCodes.InvalidInterval or McpErrorCodes.InvalidLimit or McpErrorCodes.InvalidReferenceUrl + or McpErrorCodes.InvalidSnooze or McpErrorCodes.InvalidSort or McpErrorCodes.InvalidStatus or McpErrorCodes.InvalidTimeRange + or McpErrorCodes.InvalidVersion or McpErrorCodes.NotAccessible or McpErrorCodes.NotFound or McpErrorCodes.QueryFailed + or McpErrorCodes.UnknownFilterField or "tool_call_limit_reached" or "project_search_limit_reached" => code, + _ => "tool_error" + }; +} diff --git a/src/Exceptionless.Web/appsettings.yml b/src/Exceptionless.Web/appsettings.yml index 785c089916..21f26aa2a6 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: Information Exceptionless.Web.Security.ApiKeyAuthenticationHandler: Warning Foundatio.Metrics: Warning Foundatio.Utility.ScheduledTimer: Warning @@ -31,7 +32,7 @@ Serilog: Assistant: Endpoint: https://openrouter.ai/api/v1/chat/completions - Model: "~deepseek/deepseek-v4-flash-latest" + Model: "deepseek/deepseek-v4.1-flash" ApiKey: Apm: diff --git a/tests/Exceptionless.Tests/Assistant/AssistantDiagnosticsTests.cs b/tests/Exceptionless.Tests/Assistant/AssistantDiagnosticsTests.cs new file mode 100644 index 0000000000..acaa36139a --- /dev/null +++ b/tests/Exceptionless.Tests/Assistant/AssistantDiagnosticsTests.cs @@ -0,0 +1,377 @@ +using System.Collections.Concurrent; +using System.Diagnostics; +using System.Diagnostics.Metrics; +using System.Net; +using System.Text.Json; +using Exceptionless.Core; +using Exceptionless.Web.Api.Endpoints; +using Exceptionless.Web.Assistant; +using Foundatio.Caching; +using Microsoft.AspNetCore.Http; +using Microsoft.Extensions.Configuration; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Hosting; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Time.Testing; +using OpenTelemetry.Trace; +using Xunit; + +namespace Exceptionless.Tests.Assistant; + +public sealed class AssistantDiagnosticsTests +{ + [Fact] + public void AddApm_ExieActivitySource_CreatesExportableSpans() + { + // The APM source file is linked into both Web and Job. Select the Web copy + // explicitly to exercise its real registration without ambiguous type references. + var assembly = typeof(AssistantService).Assembly; + var configType = assembly.GetType("OpenTelemetry.ApmConfig", throwOnError: true)!; + var config = Activator.CreateInstance(configType, new ConfigurationBuilder().Build(), "test", "1.0", false); + var builder = new HostBuilder(); + assembly.GetType("OpenTelemetry.ApmExtensions", throwOnError: true)! + .GetMethod("AddApm")!.Invoke(null, [builder, config]); + using var host = builder.Build(); + _ = host.Services.GetRequiredService(); + + using var activity = AppDiagnostics.AssistantActivitySource.StartActivity("assistant.turn"); + + Assert.NotNull(activity); + Assert.True(activity.IsAllDataRequested); + using var pipelineActivity = AppDiagnostics.StartActivity("Event Pipeline"); + Assert.Null(pipelineActivity); + } + + [Theory] + [InlineData("empty_response")] + [InlineData("output_limit")] + [InlineData("malformed_response")] + [InlineData("tool_round_limit")] + [InlineData("usage_limit")] + public async Task WriteResponseAsync_StreamedError_RecordsCorrelatedFailureWithoutChangingResponse(string reason) + { + var logger = new RecordingAssistantLogger(); + var time = new FakeTimeProvider(); + using var diagnostics = new AssistantTurnDiagnostics(logger, time, "organization-id", "conversation-id", "request-id"); + using var cache = new InMemoryCacheClient(); + var recorder = new RecordingAssistantUsageRecorder(); + var context = CreateHttpContext(); + time.Advance(TimeSpan.FromSeconds(12)); + + await AssistantEndpoints.WriteResponseAsync(context, + StreamEvents([AssistantStreamEvent.Error("private error detail", reason), AssistantStreamEvent.Done()]), + CreateUsageService(cache, recorder), "organization-id", diagnostics, TestContext.Current.CancellationToken); + + var entry = Assert.Single(logger.Entries); + Assert.Equal(LogLevel.Warning, entry.Level); + Assert.Equal("failed", entry.Properties["Outcome"]); + Assert.Equal(reason, entry.Properties["FailureReason"]); + Assert.Equal(12_000d, entry.Properties["DurationMs"]); + Assert.Equal("organization-id", entry.Properties["OrganizationId"]); + Assert.Equal("conversation-id", entry.Properties["ConversationId"]); + Assert.Equal("request-id", entry.Properties["RequestId"]); + Assert.Equal(diagnostics.TurnId, entry.Properties["AssistantTurnId"]); + Assert.DoesNotContain("private error detail", entry.Message); + Assert.Equal(1, Assert.Single(recorder.Records).Increment.Failed); + + Assert.Equal(StatusCodes.Status200OK, context.Response.StatusCode); + var events = await ReadEventsAsync(context); + Assert.Equal("private error detail", events[0].GetProperty("message").GetString()); + Assert.False(events[0].TryGetProperty("failure_code", out _)); + Assert.False(events[0].TryGetProperty("FailureCode", out _)); + Assert.Equal("done", events[1].GetProperty("type").GetString()); + } + + [Theory] + [InlineData(false, true, "provider_stream", "failed", "turn_timeout")] + [InlineData(false, false, "provider_stream", "failed", "provider_timeout")] + [InlineData(true, true, "provider_stream", "cancelled", "client_disconnected")] + [InlineData(false, false, "tool_execution", "failed", "operation_cancelled")] + public async Task WriteResponseAsync_Cancellation_DistinguishesClientAndServer( + bool clientDisconnected, bool deadlineExpired, string stage, string outcome, string reason) + { + var logger = new RecordingAssistantLogger(); + using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); + diagnostics.Stage = stage; + using var cache = new InMemoryCacheClient(); + var recorder = new RecordingAssistantUsageRecorder(); + var context = CreateHttpContext(); + using var cancellation = new CancellationTokenSource(); + if (deadlineExpired) + await cancellation.CancelAsync(); + if (clientDisconnected) + context.RequestAborted = cancellation.Token; + + await AssistantEndpoints.WriteResponseAsync(context, + StreamEvents([], new OperationCanceledException("private provider detail")), + CreateUsageService(cache, recorder), "organization-id", diagnostics, cancellation.Token); + + var entry = Assert.Single(logger.Entries); + Assert.Equal(outcome, entry.Properties["Outcome"]); + Assert.Equal(reason, entry.Properties["FailureReason"]); + Assert.Equal(stage, entry.Properties["Stage"]); + Assert.DoesNotContain("private provider detail", entry.Message); + var usage = Assert.Single(recorder.Records).Increment; + Assert.Equal(clientDisconnected ? 0 : 1, usage.Failed); + Assert.Equal(clientDisconnected ? 1 : 0, usage.Cancelled); + var events = await ReadEventsAsync(context); + if (clientDisconnected) + Assert.Empty(events); + else + Assert.Equal("Exie took too long to complete this response. Try narrowing the question.", Assert.Single(events).GetProperty("message").GetString()); + } + + [Fact] + public async Task WriteResponseAsync_ProviderException_RecordsReasonWithoutLoggingProviderMessage() + { + var logger = new RecordingAssistantLogger(); + using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); + using var cache = new InMemoryCacheClient(); + var recorder = new RecordingAssistantUsageRecorder(); + var context = CreateHttpContext(); + await AssistantEndpoints.WriteResponseAsync(context, + StreamEvents([], new AssistantProviderException("private provider detail") { FailureCode = "provider_http_error" }), + CreateUsageService(cache, recorder), "organization-id", diagnostics, TestContext.Current.CancellationToken); + + var entry = Assert.Single(logger.Entries); + Assert.Equal(LogLevel.Error, entry.Level); + Assert.Equal("provider_http_error", entry.Properties["FailureReason"]); + Assert.Equal(typeof(AssistantProviderException).FullName, entry.Properties["ExceptionType"]); + Assert.DoesNotContain("private provider detail", entry.Message); + Assert.Equal(1, Assert.Single(recorder.Records).Increment.Failed); + } + + [Fact] + public async Task WriteResponseAsync_Success_RecordsCompletionAndFirstTextWithoutLoggingAnswer() + { + var logger = new RecordingAssistantLogger(); + var time = new FakeTimeProvider(); + using var diagnostics = new AssistantTurnDiagnostics(logger, time, "organization-id", "conversation-id", "request-id"); + using var cache = new InMemoryCacheClient(); + var recorder = new RecordingAssistantUsageRecorder(); + var context = CreateHttpContext(); + time.Advance(TimeSpan.FromSeconds(3)); + await AssistantEndpoints.WriteResponseAsync(context, + StreamEvents([AssistantStreamEvent.TextDelta("private answer"), AssistantStreamEvent.Done()]), + CreateUsageService(cache, recorder), "organization-id", diagnostics, TestContext.Current.CancellationToken); + + var entry = Assert.Single(logger.Entries); + Assert.Equal("completed", entry.Properties["Outcome"]); + Assert.Equal("none", entry.Properties["FailureReason"]); + Assert.Equal(3000d, entry.Properties["FirstTextDurationMs"]); + Assert.DoesNotContain("private answer", entry.Message); + Assert.Equal(1, Assert.Single(recorder.Records).Increment.Completed); + } + + [Fact] + public void Finish_FailedTurn_RecordsErrorSpanAndBoundedMetricTagsOnce() + { + var activities = new ConcurrentQueue(); + var activitySource = AppDiagnostics.AssistantActivitySource; + using var listener = new ActivityListener + { + ShouldListenTo = source => source == activitySource, + Sample = (ref ActivityCreationOptions _) => ActivitySamplingResult.AllDataAndRecorded, + SampleUsingParentId = (ref ActivityCreationOptions _) => ActivitySamplingResult.AllDataAndRecorded, + ActivityStopped = activity => activities.Enqueue(activity) + }; + ActivitySource.AddActivityListener(listener); + var measurements = new List>(); + string? turnId = null; + using var meterListener = new MeterListener + { + InstrumentPublished = (instrument, current) => + { + if (instrument.Name == "ex.assistant.turn.duration") + current.EnableMeasurementEvents(instrument); + } + }; + meterListener.SetMeasurementEventCallback((_, _, tags, _) => + { + if (Activity.Current?.GetTagItem("assistant.turn.id") as string == turnId) + measurements.Add(tags.ToArray().ToDictionary(tag => tag.Key, tag => tag.Value)); + }); + meterListener.Start(); + var logger = new RecordingAssistantLogger(); + using (var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id")) + { + turnId = diagnostics.TurnId; + diagnostics.Stage = "provider_stream"; + diagnostics.Finish("failed", "turn_timeout"); + diagnostics.Finish("completed"); + } + + var measurement = Assert.Single(measurements); + Assert.Equal(3, measurement.Count); + Assert.Equal("failed", measurement["outcome"]); + Assert.Equal("turn_timeout", measurement["reason"]); + Assert.Equal("provider_stream", measurement["stage"]); + var activity = Assert.Single(activities, activity => activity.GetTagItem("assistant.turn.id") as string == turnId); + Assert.Equal(ActivityStatusCode.Error, activity.Status); + Assert.Equal("turn_timeout", activity.StatusDescription); + Assert.Single(logger.Entries); + } + + [Theory] + [InlineData("client", "cancelled")] + [InlineData("turn", "turn_timeout")] + [InlineData("provider", "provider_timeout")] + public void RecordException_CancellationSource_RecordsExpectedProviderOutcome(string source, string expectedOutcome) + { + using var requestAborted = new CancellationTokenSource(); + using var deadline = CancellationTokenSource.CreateLinkedTokenSource(requestAborted.Token); + var logger = new RecordingAssistantLogger(); + using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id", requestAborted.Token); + using (var provider = diagnostics.StartProviderRequest(100, true, deadline.Token)) + { + if (source == "client") + { + requestAborted.Cancel(); + } + else if (source == "turn") + { + deadline.Cancel(); + } + provider.RecordException(new OperationCanceledException("private cancellation detail")); + } + + var entry = Assert.Single(logger.Entries); + Assert.Equal(expectedOutcome, entry.Properties["ProviderOutcome"]); + Assert.Equal(source == "client" ? LogLevel.Information : LogLevel.Warning, entry.Level); + Assert.DoesNotContain("private cancellation detail", entry.Message); + } + + [Fact] + public void ObserveChunk_OutputLimit_RecordsGenerationAndReasoningWithoutContent() + { + var logger = new RecordingAssistantLogger(); + using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); + diagnostics.Model = "configured-model"; + using var provider = diagnostics.StartProviderRequest(1000, true, TestContext.Current.CancellationToken); + using var response = new HttpResponseMessage(HttpStatusCode.OK); + response.Headers.Add("X-Generation-Id", "gen-header"); + provider.ObserveResponse(response); + using var document = JsonDocument.Parse(""" + {"id":"gen-stream","model":"resolved-model","provider":"Example Provider", + "choices":[{"delta":{"reasoning":"private reasoning"},"finish_reason":"length"}], + "usage":{"prompt_tokens":100,"completion_tokens":2048,"completion_tokens_details":{"reasoning_tokens":2048}}} + """); + provider.ObserveChunk(document.RootElement); + provider.Complete(0, 0, true); + + Assert.Equal("gen-stream", provider.GenerationId); + Assert.Equal("length", provider.FinishReason); + Assert.Equal(2048, provider.ReasoningTokens); + var entry = Assert.Single(logger.Entries); + Assert.Equal(LogLevel.Warning, entry.Level); + Assert.Equal("output_limit", entry.Properties["ProviderOutcome"]); + Assert.Equal("resolved-model", entry.Properties["ProviderModel"]); + Assert.Equal(100L, entry.Properties["PromptTokens"]); + Assert.Equal(2048L, entry.Properties["CompletionTokens"]); + Assert.DoesNotContain("private reasoning", entry.Message); + } + + [Fact] + public void ObserveChunk_UnexpectedMetadata_DoesNotThrowOrLogUnboundedValues() + { + var logger = new RecordingAssistantLogger(); + using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); + using var provider = diagnostics.StartProviderRequest(1000, true, TestContext.Current.CancellationToken); + using var document = JsonDocument.Parse(""" + {"id":"private\nvalue","model":{"unexpected":true},"provider":null, + "choices":[{"finish_reason":"unexpected-provider-string"}], + "usage":{"completion_tokens_details":{"reasoning_tokens":"not-a-number"}}} + """); + provider.ObserveChunk(document.RootElement); + provider.Complete(10, 0, true); + + Assert.Null(provider.GenerationId); + Assert.Null(provider.Model); + Assert.Null(provider.ReasoningTokens); + Assert.Equal("unknown", provider.FinishReason); + Assert.DoesNotContain("private", Assert.Single(logger.Entries).Message); + } + + [Fact] + public void RecordToolResult_FailedTool_RecordsCodeWithoutArgumentsOrResult() + { + var logger = new RecordingAssistantLogger(); + using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); + diagnostics.StartTool("search_stacks"); + diagnostics.RecordToolResult("""{"ok":false,"error":{"code":"invalid_filter","message":"private filter"}}""", 100); + diagnostics.StartTool("private-hallucinated-tool-name"); + diagnostics.RecordToolResult("""{"ok":false,"error":{"code":"private-error-code","message":"private details"}}""", 100); + diagnostics.Finish("completed"); + + Assert.Equal(2, diagnostics.ToolFailures); + Assert.Equal("unknown", diagnostics.LastTool); + Assert.Equal("tool_error", diagnostics.LastToolError); + Assert.Equal("invalid_filter", logger.Entries[0].Properties["ToolErrorCode"]); + Assert.All(logger.Entries, entry => Assert.DoesNotContain("private", entry.Message)); + Assert.Equal("completed", logger.Entries[^1].Properties["Outcome"]); + } + + [Theory] + [InlineData("null")] + [InlineData("[]")] + [InlineData("\"text\"")] + public void RecordToolResult_NonObjectResult_DoesNotInterruptTheTurn(string result) + { + var logger = new RecordingAssistantLogger(); + using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); + diagnostics.StartTool("get_event"); + diagnostics.RecordToolResult(result, 100); + + Assert.Equal(0, diagnostics.ToolFailures); + Assert.Empty(logger.Entries); + } + + private static DefaultHttpContext CreateHttpContext() + { + var context = new DefaultHttpContext(); + context.Response.Body = new MemoryStream(); + return context; + } + + private static async Task ReadEventsAsync(HttpContext context) + { + context.Response.Body.Position = 0; + using var reader = new StreamReader(context.Response.Body, leaveOpen: true); + string content = await reader.ReadToEndAsync(TestContext.Current.CancellationToken); + return content.Split('\n', StringSplitOptions.RemoveEmptyEntries).Select(line => + { + using var document = JsonDocument.Parse(line); + return document.RootElement.Clone(); + }).ToArray(); + } + + private static AssistantUsageService CreateUsageService(ICacheClient cache, RecordingAssistantUsageRecorder recorder) + { + var options = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary { ["BaseURL"] = "https://localhost" }) + .Build()); + return new AssistantUsageService(cache, null!, recorder, options, TimeProvider.System, NullLogger.Instance); + } + + private static async IAsyncEnumerable StreamEvents(AssistantStreamEvent[] events, Exception? exception = null) + { + await Task.Yield(); + if (exception is not null) + throw exception; + foreach (var item in events) + yield return item; + } +} + +internal 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(new AssistantLogEntry(logLevel, formatter(state, exception), + ((IEnumerable>)(object)state!).ToDictionary(property => property.Key, property => property.Value))); +} + +internal sealed record AssistantLogEntry(LogLevel Level, string Message, Dictionary Properties); diff --git a/tests/Exceptionless.Tests/Assistant/AssistantProviderTelemetryTests.cs b/tests/Exceptionless.Tests/Assistant/AssistantProviderTelemetryTests.cs new file mode 100644 index 0000000000..e6ca5e6602 --- /dev/null +++ b/tests/Exceptionless.Tests/Assistant/AssistantProviderTelemetryTests.cs @@ -0,0 +1,203 @@ +using System.Diagnostics; +using System.Net; +using System.Text.Json; +using Exceptionless.Insulation.Security; +using Exceptionless.Models; +using Exceptionless.Serializer; +using Exceptionless.Web.Assistant; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Time.Testing; +using Serilog; +using Serilog.Extensions.Logging; +using Serilog.Sinks.Exceptionless; +using Xunit; + +namespace Exceptionless.Tests.Assistant; + +public sealed class AssistantProviderTelemetryTests +{ + [Fact] + public void Capture_ValidationError_PreservesParameterLocationWithoutInput() + { + using var error = JsonDocument.Parse(""" + {"detail":[{"type":"missing","loc":["body","messages",2,"reasoning_content"], + "msg":"Field required","input":{"content":"private-input-canary"}}]} + """); + var sanitizer = new AssistantProviderErrorDetails(default, null); + + using var captured = JsonDocument.Parse(JsonSerializer.Serialize(sanitizer.Capture(error.RootElement))); + var detail = captured.RootElement.GetProperty("detail")[0]; + Assert.Equal(2, detail.GetProperty("loc")[2].GetInt32()); + Assert.Equal("reasoning_content", detail.GetProperty("loc")[3].GetString()); + Assert.Equal("Field required", detail.GetProperty("msg").GetString()); + Assert.False(detail.TryGetProperty("input", out _)); + } + + [Fact] + public void ObserveChunk_RoutingRestriction_RecordsExclusionReasonsAndLegacyProviderCode() + { + var logger = new RecordingAssistantLogger(); + using var turn = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); + using var provider = turn.StartProviderRequest(100, true, TestContext.Current.CancellationToken); + using var document = JsonDocument.Parse(""" + {"error":{"code":"404","message":"No eligible providers","metadata":{ + "provider_error_code":"no_endpoints","input_endpoint_count":2, + "failed_routing_step":"Filter by Guardrails", + "ineligibility_reasons":[{"reason":"paid-model-training-violation-by-account","endpoint_count":2}], + "routing_funnel":[{"step":"Initial Endpoints","endpoint_count":7}] + }}} + """); + provider.ObserveChunk(document.RootElement); + provider.RecordException(new AssistantProviderException("Provider returned error")); + + var entry = Assert.Single(logger.Entries); + Assert.Equal("404", entry.Properties["ProviderErrorCode"]); + Assert.Equal("no_endpoints", entry.Properties["UpstreamErrorCode"]); + string details = Assert.IsType(entry.Properties["ProviderErrorDetails"]); + Assert.Contains("paid-model-training-violation-by-account", details); + Assert.Contains("Filter by Guardrails", details); + Assert.Contains("Initial Endpoints", details); + } + + [Theory] + [InlineData("private-body-canary", "invalid_json")] + [InlineData("{\"error\":\"private-body-canary", "invalid_json")] + [InlineData("[]", "invalid_shape")] + [InlineData("", "empty")] + public async Task ObserveErrorResponseAsync_InvalidBody_RetainsStatusWithoutLeakingBody(string body, string expectedState) + { + var logger = new RecordingAssistantLogger(); + using var turn = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); + using var provider = turn.StartProviderRequest(100, true, TestContext.Current.CancellationToken); + using var response = new HttpResponseMessage(HttpStatusCode.BadGateway) { Content = new StringContent(body) }; + provider.ObserveResponse(response); + await provider.ObserveErrorResponseAsync(response, TestContext.Current.CancellationToken); + provider.RecordException(new AssistantProviderException("Rejected") { FailureCode = "provider_http_error" }); + + var entry = Assert.Single(logger.Entries); + Assert.Equal(502, entry.Properties["ProviderStatusCode"]); + Assert.Equal(expectedState, entry.Properties["ProviderErrorBodyState"]); + Assert.DoesNotContain("private-body-canary", entry.Message); + } + + [Fact] + public async Task ObserveErrorResponseAsync_OversizedBody_ReportsTruncation() + { + var logger = new RecordingAssistantLogger(); + using var turn = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); + using var provider = turn.StartProviderRequest(100, true, TestContext.Current.CancellationToken); + using var response = new HttpResponseMessage(HttpStatusCode.BadGateway) { Content = new StringContent(new string('x', 100_000)) }; + provider.ObserveResponse(response); + await provider.ObserveErrorResponseAsync(response, TestContext.Current.CancellationToken); + provider.RecordException(new AssistantProviderException("Rejected") { FailureCode = "provider_http_error" }); + + var entry = Assert.Single(logger.Entries); + Assert.Equal("truncated", entry.Properties["ProviderErrorBodyState"]); + Assert.Equal(true, entry.Properties["ProviderDetailsTruncated"]); + Assert.Null(entry.Properties["ProviderErrorDetails"]); + } + + [Fact] + public void ObserveChunk_StreamFailure_RecordsProgressAndTiming() + { + var logger = new RecordingAssistantLogger(); + var time = new FakeTimeProvider(); + using var turn = new AssistantTurnDiagnostics(logger, time, "organization-id", "conversation-id", "request-id"); + using var provider = turn.StartProviderRequest(100, true, TestContext.Current.CancellationToken); + using var response = new HttpResponseMessage(HttpStatusCode.OK); + time.Advance(TimeSpan.FromSeconds(1)); + provider.ObserveResponse(response); + using var chunk = JsonDocument.Parse("""{"id":"gen-progress","choices":[{"delta":{"content":"private output"}}]}"""); + time.Advance(TimeSpan.FromSeconds(2)); + provider.ObserveChunk(chunk.RootElement); + time.Advance(TimeSpan.FromSeconds(7)); + provider.RecordException(new IOException("private exception message"), 14, 1); + + var entry = Assert.Single(logger.Entries); + Assert.Equal(1000d, entry.Properties["HeadersDurationMs"]); + Assert.Equal(3000d, entry.Properties["FirstChunkDurationMs"]); + Assert.Equal(3000d, entry.Properties["LastChunkDurationMs"]); + Assert.Equal(10_000d, entry.Properties["DurationMs"]); + Assert.Equal(1, entry.Properties["ChunkCount"]); + Assert.Equal(14, entry.Properties["OutputCharacters"]); + Assert.Equal(1, entry.Properties["ToolCalls"]); + Assert.False(Assert.IsType(entry.Properties["ReceivedDone"])); + Assert.DoesNotContain("private", entry.Message); + } + + [Fact] + public void Capture_ErrorMessages_RedactsRequestValuesAndBoundsText() + { + using var request = JsonDocument.Parse(""" + [{"role":"user","content":"private-prompt-canary"}, + {"role":"assistant","reasoning":"private-reasoning-canary","tool_calls":[{"function":{"arguments":"{\"filter\":\"private-filter-canary\"}"}}]}, + {"role":"tool","content":"{\"message\":\"private-result-canary\"}"}] + """); + using var error = JsonDocument.Parse(JsonSerializer.Serialize(new + { + message = "Missing reasoning_content. private-prompt-canary private-reasoning-canary private-filter-canary private-result-canary sk-or-v1-provider-key-canary api-key-canary https://example.test?token=canary", + metadata = new { raw = new { error = new { message = new string('x', 10_000) } } }, + messages = new[] { new { content = "other-prompt-canary" } } + })); + var sanitizer = new AssistantProviderErrorDetails(request.RootElement, "api-key-canary"); + string result = JsonSerializer.Serialize(sanitizer.Capture(error.RootElement)); + + Assert.Contains("Missing reasoning_content", result); + Assert.DoesNotContain("canary", result); + Assert.True(sanitizer.Redacted); + Assert.True(sanitizer.Truncated); + Assert.True(result.Length < 4096); + } + + [Fact] + public void RecordException_ExceptionlessSink_PreservesDiagnosticFieldsAndOmitsSecrets() + { + Event? submittedEvent = null; + using var client = new ExceptionlessClient(configuration => + { + configuration.ApiKey = "00000000000000000000000000000000"; + configuration.UseInMemoryStorage(); + }); + client.SubmittingEvent += (_, args) => + { + submittedEvent = args.Event; + args.Cancel = true; + }; + using var serilog = new LoggerConfiguration() + .ApplySensitiveDataLogging() + .WriteTo.Sink(new ExceptionlessSink(client: client)) + .CreateLogger(); + using var loggerFactory = new SerilogLoggerFactory(serilog, dispose: false); + using var parent = new Activity("http-request").Start(); + using var turn = new AssistantTurnDiagnostics(loggerFactory.CreateLogger(), TimeProvider.System, + "organization-id", "conversation-id", "request-id"); + using var provider = turn.StartProviderRequest(100, true, TestContext.Current.CancellationToken); + provider.ObserveRequest(new Dictionary + { + ["messages"] = new[] { new { role = "user", content = "private-prompt-canary" } } + }, "private-api-key-canary"); + using var response = new HttpResponseMessage(HttpStatusCode.OK); + provider.ObserveResponse(response); + using var document = JsonDocument.Parse(""" + {"id":"gen-sink-test","provider":"Fireworks","error":{"code":429,"message":"Provider returned error","metadata":{ + "error_type":"rate_limit_exceeded","provider_code":"rate_limited", + "raw":{"error":{"message":"Missing reasoning_content: private-prompt-canary private-api-key-canary"},"request":{"content":"other-private-canary"}} + }}} + """); + provider.ObserveChunk(document.RootElement); + provider.RecordException(new AssistantProviderException("private-exception-canary")); + + Assert.NotNull(submittedEvent); + Assert.Contains("ProviderErrorDetails", submittedEvent.Data.Keys); + Assert.Contains("ProviderErrorCode", submittedEvent.Data.Keys); + Assert.Contains("AssistantTurnId", submittedEvent.Data.Keys); + string serialized = new DefaultJsonSerializer().Serialize(submittedEvent); + Assert.Contains("ProviderErrorDetails", serialized); + Assert.Contains("ProviderErrorCode", serialized); + Assert.Contains("rate_limit_exceeded", serialized); + Assert.Contains("Missing reasoning_content", serialized); + Assert.Contains("gen-sink-test", serialized); + Assert.Contains(turn.TurnId, serialized); + Assert.DoesNotContain("canary", serialized); + } +} diff --git a/tests/Exceptionless.Tests/Assistant/AssistantQualityEvaluationTests.cs b/tests/Exceptionless.Tests/Assistant/AssistantQualityEvaluationTests.cs index 949198549d..f166fa49e6 100644 --- a/tests/Exceptionless.Tests/Assistant/AssistantQualityEvaluationTests.cs +++ b/tests/Exceptionless.Tests/Assistant/AssistantQualityEvaluationTests.cs @@ -1,5 +1,6 @@ using System.Net.Http.Headers; using System.Net.Http.Json; +using System.Text; using System.Text.Json; using Exceptionless.Core; using Exceptionless.Core.Models; @@ -50,7 +51,7 @@ protected override async Task ResetDataAsync() [Fact(Skip = "Set RUN_ASSISTANT_EVALS=true to run the billable assistant quality gate.", SkipUnless = nameof(EvaluationsEnabled))] [Trait("Category", "AssistantEvaluation")] - public async Task ProductionScenarios_MeetToolEfficiencyAndAnswerQualityGate() + public async Task CurrentEvent_MeetsToolEfficiencyAndAnswerQualityGate() { RequireEvaluationConfiguration(); @@ -63,6 +64,13 @@ public async Task ProductionScenarios_MeetToolEfficiencyAndAnswerQualityGate() Assert.DoesNotContain("get_stack", currentPage.ToolCalls); Assert.DoesNotContain("list_projects", currentPage.ToolCalls); Assert.DoesNotContain("search_stacks", currentPage.ToolCalls); + } + + [Fact(Skip = "Set RUN_ASSISTANT_EVALS=true to run the billable assistant quality gate.", SkipUnless = nameof(EvaluationsEnabled))] + [Trait("Category", "AssistantEvaluation")] + public async Task ProjectTopErrors_MeetsToolEfficiencyAndAnswerQualityGate() + { + RequireEvaluationConfiguration(); var projectTopErrors = await SendAssistantTurnAsync( "What are the top errors in this project in the last 24 hours? Link each result.", @@ -72,6 +80,13 @@ public async Task ProductionScenarios_MeetToolEfficiencyAndAnswerQualityGate() Assert.Equal(1, projectTopErrors.ToolCalls.Count(call => call == "search_stacks")); Assert.DoesNotContain("list_projects", projectTopErrors.ToolCalls); Assert.Contains("/next/stack/", projectTopErrors.Text, StringComparison.Ordinal); + } + + [Fact(Skip = "Set RUN_ASSISTANT_EVALS=true to run the billable assistant quality gate.", SkipUnless = nameof(EvaluationsEnabled))] + [Trait("Category", "AssistantEvaluation")] + public async Task OrganizationTopErrors_MeetsToolEfficiencyAndAnswerQualityGate() + { + RequireEvaluationConfiguration(); var organizationTopErrors = await SendAssistantTurnAsync( "Across all projects in this organization, what are the top errors in the last 24 hours? Link each result.", @@ -81,6 +96,13 @@ public async Task ProductionScenarios_MeetToolEfficiencyAndAnswerQualityGate() Assert.Equal(1, organizationTopErrors.ToolCalls.Count(call => call == "list_projects")); Assert.InRange(organizationTopErrors.ToolCalls.Count(call => call == "search_stacks"), 1, AssistantLimits.MaximumProjectsPerTurn); Assert.Contains("/next/stack/", organizationTopErrors.Text, StringComparison.Ordinal); + } + + [Fact(Skip = "Set RUN_ASSISTANT_EVALS=true to run the billable assistant quality gate.", SkipUnless = nameof(EvaluationsEnabled))] + [Trait("Category", "AssistantEvaluation")] + public async Task ClientSetup_MeetsToolEfficiencyAndAnswerQualityGate() + { + RequireEvaluationConfiguration(); var clientSetup = await SendAssistantTurnAsync( "How do I configure this project to start sending events?", @@ -104,7 +126,8 @@ private async Task SendAssistantTurnAsync(string prompt, string { using var client = CreateHttpClient(); using var request = new HttpRequestMessage(HttpMethod.Post, "assistant/chat"); - request.Headers.Authorization = new AuthenticationHeaderValue("Bearer", SampleDataService.TEST_USER_API_KEY); + request.Headers.Authorization = new AuthenticationHeaderValue("Basic", Convert.ToBase64String( + Encoding.UTF8.GetBytes($"{SampleDataService.TEST_ORG_USER_EMAIL}:{SampleDataService.TEST_ORG_USER_PASSWORD}"))); request.Content = JsonContent.Create(new { conversation_id = Guid.NewGuid().ToString("N"), diff --git a/tests/Exceptionless.Tests/Assistant/AssistantServiceProviderDiagnosticsTests.cs b/tests/Exceptionless.Tests/Assistant/AssistantServiceProviderDiagnosticsTests.cs new file mode 100644 index 0000000000..8ef4b1bee6 --- /dev/null +++ b/tests/Exceptionless.Tests/Assistant/AssistantServiceProviderDiagnosticsTests.cs @@ -0,0 +1,120 @@ +using System.Net; +using System.Text; +using System.Text.Json; +using Exceptionless.Core; +using Exceptionless.Web.Assistant; +using Microsoft.Extensions.Configuration; +using Xunit; + +namespace Exceptionless.Tests.Assistant; + +public sealed partial class AssistantServiceTests +{ + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task StreamAsync_UpstreamError_PreservesCauseAndCorrelationWithoutRequestContent(bool streaming) + { + const string privatePrompt = "private-prompt-canary"; + const string apiKey = "api-key-canary"; + string error = JsonSerializer.Serialize(new + { + id = "gen-failed-request", + model = "resolved-model", + provider = "Fireworks", + error = new + { + code = 429, + message = "Provider returned error", + metadata = new + { + error_type = "rate_limit_exceeded", + provider_code = "invalid_request_error", + limit_source = "upstream_provider_shared_pool", + raw = JsonSerializer.Serialize(new + { + error = new + { + type = "invalid_request_error", + message = $"Missing reasoning_content at messages[2]. Input: {privatePrompt}. Authorization: Bearer {apiKey}", + param = "messages[2].reasoning_content" + }, + request = new { messages = new[] { new { content = "unrelated-private-content-canary" } } } + }), + flagged_input = "flagged-content-canary" + } + }, + choices = new[] { new { delta = new { content = "" }, finish_reason = "error", native_finish_reason = "upstream_error" } }, + openrouter_metadata = new + { + attempt = 2, + strategy = "fallback", + attempts = new[] { new { provider = "Fireworks", model = "resolved-model", status = 429 } }, + pipeline = new[] { new { data = new { prompt = "pipeline-content-canary" } } } + } + }); + var handler = new ProviderErrorHandler(streaming, error); + var options = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary { ["BaseURL"] = "https://localhost", ["Assistant:ApiKey"] = apiKey }) + .Build()); + var logger = new RecordingAssistantLogger(); + using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); + var service = CreateAssistantService(handler, options, logger: logger); + + var exception = await Assert.ThrowsAsync(async () => + { + await foreach (var _ in service.StreamAsync( + new AssistantChatRequest([new AssistantChatMessage("user", privatePrompt)], OrganizationId: "organization-id"), + "user-id", CreatePlanOptions(), diagnostics, TestContext.Current.CancellationToken)) + { + } + }); + diagnostics.Finish("failed", exception.FailureCode, exception); + + var entry = Assert.Single(logger.Entries, entry => entry.Properties.ContainsKey("ProviderOutcome")); + Assert.Equal(streaming ? 200 : 429, entry.Properties["ProviderStatusCode"]); + Assert.Equal("429", entry.Properties["ProviderErrorCode"]); + Assert.Equal("rate_limit_exceeded", entry.Properties["ProviderErrorType"]); + Assert.Equal("invalid_request_error", entry.Properties["UpstreamErrorCode"]); + Assert.Equal("gen-failed-request", entry.Properties["ProviderGenerationId"]); + Assert.Equal("request-provider-id", entry.Properties["ProviderRequestId"]); + Assert.Equal(30d, entry.Properties["RetryAfterSeconds"]); + Assert.Equal("Fireworks", entry.Properties["ProviderName"]); + Assert.Equal(diagnostics.TurnId, entry.Properties["AssistantTurnId"]); + Assert.Equal(streaming ? "upstream_error" : null, entry.Properties["ProviderNativeFinishReason"]); + Assert.False(Assert.IsType(entry.Properties["ReceivedDone"])); + Assert.True(Assert.IsType(entry.Properties["ProviderDetailsRedacted"])); + Assert.Contains("Missing reasoning_content at messages[2]", Assert.IsType(entry.Properties["ProviderErrorDetails"])); + Assert.Contains("upstream_provider_shared_pool", Assert.IsType(entry.Properties["ProviderErrorDetails"])); + Assert.Contains("fallback", Assert.IsType(entry.Properties["ProviderRoutingDetails"])); + using var settings = JsonDocument.Parse(Assert.IsType(entry.Properties["ProviderRequestSettings"])); + Assert.Equal(AssistantLimits.MaximumOutputTokens, settings.RootElement.GetProperty("max_tokens").GetInt32()); + Assert.Equal("auto", settings.RootElement.GetProperty("tool_choice").GetString()); + Assert.True(settings.RootElement.GetProperty("tool_count").GetInt32() > 0); + Assert.True(settings.RootElement.GetProperty("message_count").GetInt32() > 0); + Assert.Equal("conversation-id", logger.Entries[^1].Properties["ConversationId"]); + + string rendered = String.Join('\n', logger.Entries.Select(entry => entry.Message)); + Assert.DoesNotContain("canary", rendered); + Assert.Equal("enabled", handler.RouterMetadataHeader); + } + + private sealed class ProviderErrorHandler(bool streaming, string error) : HttpMessageHandler + { + public string? RouterMetadataHeader { get; private set; } + + protected override Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) + { + RouterMetadataHeader = request.Headers.GetValues("X-OpenRouter-Metadata").Single(); + var response = new HttpResponseMessage(streaming ? HttpStatusCode.OK : HttpStatusCode.TooManyRequests) + { + Content = new StringContent(streaming ? $"data: {error}\n\n" : error, Encoding.UTF8, + streaming ? "text/event-stream" : "application/json") + }; + response.Headers.Add("X-Request-Id", "request-provider-id"); + response.Headers.Add("X-Generation-Id", "gen-header-id"); + response.Headers.RetryAfter = new System.Net.Http.Headers.RetryConditionHeaderValue(TimeSpan.FromSeconds(30)); + return Task.FromResult(response); + } + } +} diff --git a/tests/Exceptionless.Tests/Assistant/AssistantServiceTests.cs b/tests/Exceptionless.Tests/Assistant/AssistantServiceTests.cs index 35ce5e8d9b..092b1c38ff 100644 --- a/tests/Exceptionless.Tests/Assistant/AssistantServiceTests.cs +++ b/tests/Exceptionless.Tests/Assistant/AssistantServiceTests.cs @@ -1,3 +1,5 @@ +using System.Diagnostics; +using System.Diagnostics.Metrics; using System.Net; using System.Text; using System.Text.Json; @@ -7,6 +9,7 @@ using Exceptionless.Core.Models.Billing; using Exceptionless.Core.Serialization; using Exceptionless.Core.Services; +using Exceptionless.Web.Api.Endpoints; using Exceptionless.Web.Assistant; using Exceptionless.Web.Mcp; using Foundatio.Caching; @@ -16,12 +19,13 @@ using Foundatio.Serializer; using Microsoft.AspNetCore.Http; using Microsoft.Extensions.Configuration; +using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; using Xunit; namespace Exceptionless.Tests.Assistant; -public sealed class AssistantServiceTests +public sealed partial class AssistantServiceTests { [Theory] [InlineData("requested-project", "Named project", "current-project", "requested-project")] @@ -109,7 +113,7 @@ [new AssistantChatMessage("user", "Say hello")], item => Assert.Equal("done", item.Type)); Assert.Equal("Bearer", handler.AuthorizationScheme); using var providerRequest = JsonDocument.Parse(handler.RequestBody); - Assert.Equal("~deepseek/deepseek-v4-flash-latest", providerRequest.RootElement.GetProperty("model").GetString()); + Assert.Equal("deepseek/deepseek-v4.1-flash", providerRequest.RootElement.GetProperty("model").GetString()); Assert.Contains($"\"max_tokens\":{AssistantLimits.MaximumOutputTokens}", handler.RequestBody); Assert.Contains("get_event", handler.RequestBody); Assert.Contains("get_stack", handler.RequestBody); @@ -207,6 +211,79 @@ public async Task StreamAsync_RuntimeModelOverride_UsesOverride() Assert.Equal("z-ai/glm-5.3-flash", providerRequest.RootElement.GetProperty("model").GetString()); } + [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 +580,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); @@ -986,6 +1066,256 @@ public async Task StreamAsync_EmptyResponse_EmitsClearErrorAndCompletion() item => Assert.Equal("done", item.Type)); } + [Theory] + [InlineData("length", "output_limit")] + [InlineData("content_filter", "content_filter")] + [InlineData("stop", "empty_response")] + public async Task StreamAsync_EmptyProviderAnswer_RecordsProviderReasonAndGeneration(string finishReason, string failureCode) + { + string payload = JsonSerializer.Serialize(new + { + id = "gen-empty-answer", + model = "resolved-model", + choices = new[] { new { delta = new { content = "" }, finish_reason = finishReason } }, + usage = new { prompt_tokens = 100, completion_tokens = 2048, completion_tokens_details = new { reasoning_tokens = 2048 } } + }); + var handler = new StubHttpMessageHandler($"data: {payload}\n\ndata: [DONE]\n\n"); + var options = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary { ["BaseURL"] = "https://localhost", ["Assistant:ApiKey"] = "test-key" }) + .Build()); + var logger = new RecordingAssistantLogger(); + using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); + var service = CreateAssistantService(handler, options); + var events = new List(); + + await foreach (var item in service.StreamAsync( + new AssistantChatRequest([new AssistantChatMessage("user", "private question")]), + "user-id", CreatePlanOptions(), diagnostics, TestContext.Current.CancellationToken)) + events.Add(item); + + Assert.Equal(failureCode, Assert.Single(events, item => item.Type == "error").FailureCode); + Assert.Equal("gen-empty-answer", diagnostics.Provider?.GenerationId); + Assert.Equal("resolved-model", diagnostics.Provider?.Model); + Assert.Equal(2048, diagnostics.Provider?.ReasoningTokens); + Assert.Equal(1, diagnostics.ProviderRequests); + Assert.DoesNotContain(logger.Entries, entry => entry.Message.Contains("private question", StringComparison.Ordinal)); + } + + [Fact] + public async Task StreamAsync_ProviderStreamError_RecordsProviderErrorMessage() + { + var handler = new StubHttpMessageHandler(""" + data: {"id":"gen-stream-error","error":{"message":"private provider error"}} + + """); + var options = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary { ["BaseURL"] = "https://localhost", ["Assistant:ApiKey"] = "test-key" }) + .Build()); + var logger = new RecordingAssistantLogger(); + using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); + var service = CreateAssistantService(handler, options); + + var exception = await Assert.ThrowsAsync(async () => + { + await foreach (var _ in service.StreamAsync( + new AssistantChatRequest([new AssistantChatMessage("user", "private question")]), + "user-id", CreatePlanOptions(), diagnostics, TestContext.Current.CancellationToken)) + { + } + }); + + Assert.Equal("provider_error", exception.FailureCode); + var entry = Assert.Single(logger.Entries); + Assert.Equal("provider_error", entry.Properties["ProviderOutcome"]); + Assert.Equal(200, entry.Properties["ProviderStatusCode"]); + Assert.Equal("gen-stream-error", entry.Properties["ProviderGenerationId"]); + Assert.Contains("private provider error", Assert.IsType(entry.Properties["ProviderErrorDetails"])); + } + + [Theory] + [InlineData("transport", "provider_transport_error")] + [InlineData("stream", "provider_stream_error")] + [InlineData("json", "invalid_provider_response")] + [InlineData("timeout", "provider_timeout")] + public async Task StreamAsync_ProviderThrows_RecordsFailureCategory(string failure, string expectedOutcome) + { + var options = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary { ["BaseURL"] = "https://localhost", ["Assistant:ApiKey"] = "test-key" }) + .Build()); + var logger = new RecordingAssistantLogger(); + using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); + var service = CreateAssistantService(new FailingProviderHttpMessageHandler(failure), options); + + var exception = await Record.ExceptionAsync(async () => + { + await foreach (var _ in service.StreamAsync( + new AssistantChatRequest([new AssistantChatMessage("user", "private question")]), + "user-id", CreatePlanOptions(), diagnostics, TestContext.Current.CancellationToken)) + { + } + }); + + Assert.NotNull(exception); + var entry = Assert.Single(logger.Entries); + Assert.Equal(expectedOutcome, entry.Properties["ProviderOutcome"]); + Assert.DoesNotContain("private", entry.Message); + } + + [Theory] + [InlineData("[]")] + [InlineData("null")] + [InlineData("{\"choices\":{}}")] + [InlineData("{\"choices\":[{}]}")] + [InlineData("{\"choices\":[{\"delta\":[]}]}")] + [InlineData("{\"choices\":[{\"delta\":{\"tool_calls\":[{}]}}]}")] + [InlineData("{\"choices\":[{\"delta\":{\"tool_calls\":[{\"index\":2147483648}]}}]}")] + [InlineData("{\"usage\":{\"prompt_tokens\":\"private invalid token count\"}}")] + public async Task StreamAsync_InvalidProviderShape_RecordsProviderAndTurnFailure(string payload) + { + var options = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary { ["BaseURL"] = "https://localhost", ["Assistant:ApiKey"] = "test-key" }) + .Build()); + var logger = new RecordingAssistantLogger(); + using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); + using var cache = new InMemoryCacheClient(); + var recorder = new RecordingAssistantUsageRecorder(); + var usageService = new AssistantUsageService(cache, CreateLockProvider(cache, TimeProvider.System), recorder, options, + TimeProvider.System, NullLogger.Instance); + var service = CreateAssistantService(new StubHttpMessageHandler($"data: {payload}\n\ndata: [DONE]\n"), options, cache, usageService: usageService); + var context = new DefaultHttpContext(); + using var response = new MemoryStream(); + context.Response.Body = response; + + await AssistantEndpoints.WriteResponseAsync(context, + service.StreamAsync(new AssistantChatRequest([new AssistantChatMessage("user", "private question")]), + "user-id", CreatePlanOptions(), diagnostics, TestContext.Current.CancellationToken), + usageService, "organization-id", diagnostics, TestContext.Current.CancellationToken); + + var providerEntry = Assert.Single(logger.Entries, entry => entry.Properties.ContainsKey("ProviderOutcome")); + var turnEntry = Assert.Single(logger.Entries, entry => entry.Properties.ContainsKey("Outcome")); + Assert.Equal("invalid_provider_response", providerEntry.Properties["ProviderOutcome"]); + Assert.Equal("invalid_provider_response", turnEntry.Properties["FailureReason"]); + Assert.Equal("failed", turnEntry.Properties["Outcome"]); + Assert.All(logger.Entries, entry => Assert.DoesNotContain("private", entry.Message)); + } + + [Theory] + [InlineData("exception", "failed", "tool_execution_error")] + [InlineData("client", "cancelled", "client_disconnected")] + [InlineData("turn", "failed", "turn_timeout")] + public async Task StreamAsync_ToolThrows_RecordsToolOutcomeAndDuration(string failure, string outcome, string reason) + { + var activitySource = AppDiagnostics.AssistantActivitySource; + using var activityListener = new ActivityListener + { + ShouldListenTo = source => source == activitySource, + Sample = (ref ActivityCreationOptions _) => ActivitySamplingResult.AllDataAndRecorded + }; + ActivitySource.AddActivityListener(activityListener); + var logger = new RecordingAssistantLogger(); + using var requestAborted = new CancellationTokenSource(); + using var cancellation = CancellationTokenSource.CreateLinkedTokenSource(requestAborted.Token, TestContext.Current.CancellationToken); + using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id", requestAborted.Token); + var measurements = new List>(); + using var meterListener = new MeterListener + { + InstrumentPublished = (instrument, listener) => + { + if (instrument.Name == "ex.assistant.tool.duration") + { + listener.EnableMeasurementEvents(instrument); + } + } + }; + meterListener.SetMeasurementEventCallback((_, _, tags, _) => + { + if (Activity.Current?.GetTagItem("assistant.turn.id") as string == diagnostics.TurnId) + { + measurements.Add(tags.ToArray().ToDictionary(tag => tag.Key, tag => tag.Value)); + } + }); + meterListener.Start(); + // An array where a tool argument object is required throws during invocation. + var handler = new StubHttpMessageHandler(""" + data: {"choices":[{"delta":{"tool_calls":[{"index":0,"id":"tool-1","function":{"name":"search_stacks","arguments":"[]"}}]}}]} + + data: [DONE] + + """); + var options = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary { ["BaseURL"] = "https://localhost", ["Assistant:ApiKey"] = "test-key" }) + .Build()); + var service = CreateAssistantService(handler, options); + var exception = await Record.ExceptionAsync(async () => + { + await foreach (var item in service.StreamAsync( + new AssistantChatRequest([new AssistantChatMessage("user", "Find my errors")]), + "user-id", CreatePlanOptions(), diagnostics, cancellation.Token)) + { + if (failure == "client" && item.Type == "tool_call") + { + requestAborted.Cancel(); + } + else if (failure == "turn" && item.Type == "tool_call") + { + cancellation.Cancel(); + } + } + }); + + if (failure != "exception") + { + Assert.IsAssignableFrom(exception); + } + else + { + Assert.IsType(exception); + } + Assert.Equal(1, diagnostics.ToolCalls); + Assert.Equal(failure == "client" ? 0 : 1, diagnostics.ToolFailures); + Assert.Equal(reason, diagnostics.LastToolError); + var measurement = Assert.Single(measurements); + Assert.Equal("search_stacks", measurement["tool"]); + Assert.Equal(outcome, measurement["outcome"]); + Assert.Equal(diagnostics.LastToolError, measurement["reason"]); + } + + [Theory] + [InlineData(HttpStatusCode.TemporaryRedirect)] + [InlineData(HttpStatusCode.TooManyRequests)] + [InlineData(HttpStatusCode.InternalServerError)] + public async Task StreamAsync_HttpRejection_RecordsSanitizedProviderError(HttpStatusCode responseStatus) + { + var handler = new RejectedHttpMessageHandler(responseStatus); + var options = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary { ["BaseURL"] = "https://localhost", ["Assistant:ApiKey"] = "test-key" }) + .Build()); + var logger = new RecordingAssistantLogger(); + using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); + var service = CreateAssistantService(handler, options, logger: logger); + + var exception = await Assert.ThrowsAsync(async () => + { + await foreach (var _ in service.StreamAsync( + new AssistantChatRequest([new AssistantChatMessage("user", "private question")]), + "user-id", CreatePlanOptions(), diagnostics, TestContext.Current.CancellationToken)) + { + } + }); + + Assert.Equal("provider_http_error", exception.FailureCode); + var providerEntry = Assert.Single(logger.Entries, entry => entry.Properties.ContainsKey("ProviderOutcome")); + Assert.Equal(exception.FailureCode, providerEntry.Properties["ProviderOutcome"]); + Assert.Equal((int)responseStatus, diagnostics.Provider?.StatusCode); + Assert.Contains(logger.Entries, entry => entry.Properties.TryGetValue("StatusCode", out var status) && status is int code && code == (int)responseStatus); + Assert.Contains("Rejected", Assert.IsType(providerEntry.Properties["ProviderErrorDetails"])); + Assert.All(logger.Entries, entry => + { + Assert.DoesNotContain("private question", entry.Message); + Assert.DoesNotContain("test-key", entry.Message); + }); + } + [Fact] public async Task StreamAsync_RawDsmlResponse_RetriesWithoutEmittingMarkup() { @@ -1085,11 +1415,14 @@ public async Task StreamAsync_RepeatedRawDsmlResponse_EmitsClearErrorAndCompleti .Build()); var service = CreateAssistantService(handler, appOptions); var events = new List(); + var logger = new RecordingAssistantLogger(); + using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); await foreach (var item in service.StreamAsync( new AssistantChatRequest([new AssistantChatMessage("user", "Find recent errors")]), "user-id", CreatePlanOptions(), + diagnostics, TestContext.Current.CancellationToken)) { events.Add(item); @@ -1104,10 +1437,15 @@ public async Task StreamAsync_RepeatedRawDsmlResponse_EmitsClearErrorAndCompleti }, item => Assert.Equal("done", item.Type)); Assert.DoesNotContain(events, item => item.Type == "text_delta"); + var providerEntries = logger.Entries.Where(entry => entry.Properties.ContainsKey("ProviderOutcome")).ToArray(); + Assert.Equal(2, providerEntries.Length); + Assert.All(providerEntries, entry => Assert.Equal("malformed_response", entry.Properties["ProviderOutcome"])); } - [Fact] - public async Task StreamAsync_ToolBudgetExhausted_RequestsFinalSynthesisWithoutTools() + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task StreamAsync_ToolBudgetExhausted_RequestsFinalSynthesisWithToolChoiceNone(bool providerIgnoresToolLimit) { const string toolCallResponse = """ data: {"choices":[{"delta":{"tool_calls":[{"index":0,"id":"call-1","function":{"name":"unknown_tool","arguments":"{}"}}]}}]} @@ -1119,7 +1457,7 @@ public async Task StreamAsync_ToolBudgetExhausted_RequestsFinalSynthesisWithoutT toolCallResponse, toolCallResponse.Replace("call-1", "call-2"), toolCallResponse.Replace("call-1", "call-3"), - """ + providerIgnoresToolLimit ? toolCallResponse.Replace("call-1", "call-4") : """ data: {"choices":[{"delta":{"content":"Here is the available result."}}]} data: [DONE] @@ -1134,6 +1472,8 @@ public async Task StreamAsync_ToolBudgetExhausted_RequestsFinalSynthesisWithoutT .Build()); var service = CreateAssistantService(handler, appOptions); var events = new List(); + var logger = new RecordingAssistantLogger(); + using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); await foreach (var item in service.StreamAsync( new AssistantChatRequest( @@ -1141,6 +1481,7 @@ [new AssistantChatMessage("user", "Investigate the errors")], OrganizationId: "organization-id"), "user-id", CreatePlanOptions(), + diagnostics, TestContext.Current.CancellationToken)) { events.Add(item); @@ -1148,11 +1489,23 @@ [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); - Assert.DoesNotContain(events, item => item.Type == "error"); + var finalProviderEntry = logger.Entries.Last(entry => entry.Properties.ContainsKey("ProviderOutcome")); + if (providerIgnoresToolLimit) + { + Assert.Equal("tool_round_limit", Assert.Single(events, item => item.Type == "error").FailureCode); + Assert.Equal("tool_round_limit", finalProviderEntry.Properties["ProviderOutcome"]); + } + else + { + Assert.Contains(events, item => item.Text == "Here is the available result."); + Assert.DoesNotContain(events, item => item.Type == "error"); + Assert.Equal("completed", finalProviderEntry.Properties["ProviderOutcome"]); + } } [Fact] @@ -1229,7 +1582,8 @@ private static AssistantService CreateAssistantService( ICacheClient? cache = null, ILockProvider? lockProvider = null, AssistantUsageService? usageService = null, - AssistantModelSettingsService? modelSettingsService = null) + AssistantModelSettingsService? modelSettingsService = null, + ILogger? logger = null) { cache ??= new InMemoryCacheClient(new InMemoryCacheClientOptions { @@ -1256,7 +1610,7 @@ private static AssistantService CreateAssistantService( modelSettingsService, usageService, TimeProvider.System, - NullLogger.Instance); + logger ?? NullLogger.Instance); } private static AssistantModelSettingsService CreateAssistantModelSettingsService(AppOptions appOptions) @@ -1314,6 +1668,24 @@ protected override async Task SendAsync(HttpRequestMessage } } + private sealed class FailingProviderHttpMessageHandler(string failure) : HttpMessageHandler + { + protected override Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) + => failure switch + { + "transport" => Task.FromException(new HttpRequestException("private transport detail")), + "timeout" => Task.FromException(new TaskCanceledException("private timeout detail")), + "stream" => Task.FromResult(new HttpResponseMessage(HttpStatusCode.OK) { Content = new StreamContent(new FailingProviderStream()) }), + _ => Task.FromResult(new HttpResponseMessage(HttpStatusCode.OK) { Content = new StringContent("data: invalid-json\n\n") }) + }; + } + + private sealed class FailingProviderStream : MemoryStream + { + public override ValueTask ReadAsync(Memory buffer, CancellationToken cancellationToken = default) + => ValueTask.FromException(new IOException("private stream detail")); + } + private sealed class RejectedHttpMessageHandler(HttpStatusCode statusCode) : HttpMessageHandler { protected override Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) diff --git a/tests/Exceptionless.Tests/Assistant/README.md b/tests/Exceptionless.Tests/Assistant/README.md index fbc6d8e9e2..4c334ebb93 100644 --- a/tests/Exceptionless.Tests/Assistant/README.md +++ b/tests/Exceptionless.Tests/Assistant/README.md @@ -1,6 +1,6 @@ # Exie quality evaluations -The assistant quality gate is an opt-in integration test that calls the configured AI provider and uses the real Exceptionless HTTP endpoint, authentication, Elasticsearch test data, and MCP tools. It checks the behaviors that have caused the most visible failures: +The assistant quality gate is an opt-in integration test suite that calls the configured AI provider and uses the real Exceptionless HTTP endpoint, authentication, Elasticsearch test data, and MCP tools. It checks the behaviors that have caused the most visible failures: - a current event is fetched directly without rediscovering its project or stack; - a project-scoped top-errors question uses one stack search and returns navigable links; @@ -19,3 +19,35 @@ dotnet tests/Exceptionless.Tests/bin/Debug/net10.0/Exceptionless.Tests.dll \ ``` Set `EX_Assistant__Model` and `EX_Assistant__Endpoint` to evaluate a candidate model or compatible provider. Use a dedicated provider key with a small monthly hard limit; the tests never print the key. + +Each scenario runs independently and authenticates as the seeded organization user, so a failure in one scenario does not prevent the remaining scenarios from exercising the provider. + +Exie defaults to the pinned `deepseek/deepseek-v4.1-flash` model. Model changes must preserve these provider contracts: + +- Keep streamed reasoning with the assistant's tool calls for subsequent provider requests in the same turn. Prefer structured reasoning blocks so their order, signatures, and opaque data survive. Never send reasoning to the browser or persist it with conversation tool results. See [OpenRouter reasoning preservation](https://openrouter.ai/docs/guides/best-practices/reasoning-tokens#preserving-reasoning). +- Include tool definitions on every request containing tool results. When requesting a final answer after suggestions or tool-budget exhaustion, use `tool_choice: "none"`. See [OpenRouter tool calling](https://openrouter.ai/docs/guides/features/tool-calling). + +## Failure diagnostics + +The streaming endpoint emits a structured summary for each turn and each provider request. `Exceptionless.Web.Assistant: Information` keeps completed and cancelled summaries visible even when production's default log level is Warning. Failures emit Warning or Error events. The `Exceptionless.Assistant` activity source also exports turn/provider spans; the existing application meter records `ex.assistant.turn.duration`, `ex.assistant.provider.duration`, and `ex.assistant.tool.duration` histograms with bounded outcome/reason tags. + +Start with the failed turn in production `ex-prod-app` logs or Exceptionless events from `Exceptionless.Web.Assistant.AssistantService`. Search for its `AssistantTurnId` to collect every provider request and tool failure. Turn summaries include `OrganizationId`, `ConversationId`, `RequestId`, and `TraceId`; provider summaries include `ProviderGenerationId` and `ProviderRequestId` for an OpenRouter investigation. Use `ProviderRequestNumber` to distinguish the initial request, tool continuations, and malformed-response retries. + +| Evidence | Fields and interpretation | +| --- | --- | +| Turn outcome | `Outcome`, `FailureReason`, `Stage`, `DurationMs`, `FirstTextDurationMs`. Distinguishes a provider failure, turn deadline, tool exception, response-write failure, and client disconnect. | +| Provider rejection | `ProviderStatusCode` is the HTTP status; `ProviderErrorCode` is the body/stream error code. HTTP 200 can contain a later error with code 429. `ProviderErrorType` is OpenRouter's normalized type; `UpstreamErrorCode` is the provider-specific code. | +| Actual cause | `ProviderErrorDetails` is a JSON string containing selected error messages, parameter locations, nested `metadata.raw` errors, rate-limit source, routing exclusions, and routing funnel steps. | +| Routing | `ProviderModel`, `ProviderName`, and `ProviderRoutingDetails` identify the resolved model, selected provider, and available attempt metadata. Requests opt in with `X-OpenRouter-Metadata: enabled`; OpenRouter may omit metadata for some responses. | +| Request constraints | `ProviderRequestSettings` records output-token limit, temperature, tool choice/count, message count, and provider price caps. `InputCharacters` records request size without content. | +| Stream progress | `HeadersDurationMs`, `FirstChunkDurationMs`, `LastChunkDurationMs`, `ChunkCount`, `OutputCharacters`, `ToolCalls`, `ReceivedDone`, `ProviderFinishReason`, `ProviderNativeFinishReason`, and token counts distinguish a connection failure, interrupted stream, output limit, or reasoning-only response. | +| Transport and retry | `RetryAfterSeconds`, `ProviderContentType`, `ExceptionType`, `TransportError`, and `SocketError` retain response/transport evidence without logging arbitrary exception messages. The turn event also contains `ExceptionStackTrace`. | +| Diagnostic limits | `ProviderErrorBodyState`, `ProviderDetailsTruncated`, and `ProviderDetailsRedacted` explain missing or filtered details. Non-JSON, invalid, empty, or oversized HTTP error bodies are classified without recording their raw content. | + +Useful failure reasons include `provider_http_error`, `provider_error`, `provider_transport_error`, `provider_stream_error`, `invalid_provider_response`, `provider_timeout`, `turn_timeout`, `empty_response`, `output_limit`, `content_filter`, `malformed_response`, `tool_round_limit`, `tool_execution_error`, `response_write_error`, `usage_limit`, and `context_limit`. `client_disconnected` is cancellation. A provider warning can precede a recovered turn; assess the final turn outcome as well. Completion records delivery, not whether the answer solved the user's problem; use the quality evaluations above for that. + +Error extraction uses an allowlist and removes echoed request values, credentials, and URLs. Prompts, answer text, reasoning, tool arguments/results, flagged input, and arbitrary router pipeline data are not copied into diagnostic events. HTTP error reads are capped at 32,768 characters. Error/routing extraction shares a budget of 64 fields, 16 items per array, six nesting levels, 2,048 characters per text field, and 8,192 total text characters. These bounds are explicit so missing provider evidence is distinguishable from an empty upstream error. + +Focused tests cover HTTP and in-stream failures, routing and validation errors, timeouts, cancellation, stream progress, malformed/oversized bodies, correlation, and credential/request redaction. A test also passes the provider failure through the real Serilog Exceptionless sink and serializes the intercepted event to verify that the useful details survive without submitting any event externally. + +See OpenRouter's [error semantics](https://openrouter.ai/docs/api_reference/errors-and-debugging) and [router metadata](https://openrouter.ai/docs/guides/features/router-metadata) for upstream field definitions. From 5e05f4665ca93c13aec13474b00fee950ed61a67 Mon Sep 17 00:00:00 2001 From: "Eric J. Smith" Date: Thu, 10 Sep 2026 23:27:56 -0500 Subject: [PATCH 2/3] Narrow Exie fix to tool compatibility and provider failure logging --- .../Configuration/AssistantOptions.cs | 2 +- .../Utility/AppDiagnostics.cs | 4 - .../Api/Endpoints/AssistantEndpoints.cs | 46 +-- src/Exceptionless.Web/ApmExtensions.cs | 2 +- .../Assistant/AssistantModels.cs | 4 - .../Assistant/AssistantProviderDiagnostics.cs | 287 ------------- .../AssistantProviderErrorDetails.cs | 261 ------------ .../Assistant/AssistantProviderException.cs | 5 +- .../Assistant/AssistantService.cs | 310 ++++++-------- .../Assistant/AssistantTurnDiagnostics.cs | 190 --------- src/Exceptionless.Web/appsettings.yml | 3 +- .../Assistant/AssistantDiagnosticsTests.cs | 377 ----------------- .../AssistantProviderTelemetryTests.cs | 203 --------- .../AssistantQualityEvaluationTests.cs | 27 +- ...ssistantServiceProviderDiagnosticsTests.cs | 120 ------ .../Assistant/AssistantServiceTests.cs | 389 +++++------------- tests/Exceptionless.Tests/Assistant/README.md | 34 +- 17 files changed, 244 insertions(+), 2020 deletions(-) delete mode 100644 src/Exceptionless.Web/Assistant/AssistantProviderDiagnostics.cs delete mode 100644 src/Exceptionless.Web/Assistant/AssistantProviderErrorDetails.cs delete mode 100644 src/Exceptionless.Web/Assistant/AssistantTurnDiagnostics.cs delete mode 100644 tests/Exceptionless.Tests/Assistant/AssistantDiagnosticsTests.cs delete mode 100644 tests/Exceptionless.Tests/Assistant/AssistantProviderTelemetryTests.cs delete mode 100644 tests/Exceptionless.Tests/Assistant/AssistantServiceProviderDiagnosticsTests.cs diff --git a/src/Exceptionless.Core/Configuration/AssistantOptions.cs b/src/Exceptionless.Core/Configuration/AssistantOptions.cs index f996058b16..b1059d671b 100644 --- a/src/Exceptionless.Core/Configuration/AssistantOptions.cs +++ b/src/Exceptionless.Core/Configuration/AssistantOptions.cs @@ -5,7 +5,7 @@ namespace Exceptionless.Core.Configuration; public sealed class AssistantOptions { public const string DefaultEndpoint = "https://openrouter.ai/api/v1/chat/completions"; - public const string DefaultModel = "deepseek/deepseek-v4.1-flash"; + public const string DefaultModel = "~deepseek/deepseek-v4-flash-latest"; public bool Enabled { get; internal set; } public bool IsConfigured => !String.IsNullOrWhiteSpace(ApiKey); diff --git a/src/Exceptionless.Core/Utility/AppDiagnostics.cs b/src/Exceptionless.Core/Utility/AppDiagnostics.cs index 883cbfd65b..e59dc6bf7a 100644 --- a/src/Exceptionless.Core/Utility/AppDiagnostics.cs +++ b/src/Exceptionless.Core/Utility/AppDiagnostics.cs @@ -10,7 +10,6 @@ public static class AppDiagnostics internal static readonly AssemblyName AssemblyName = typeof(AppDiagnostics).Assembly.GetName(); internal static readonly string? AssemblyVersion = typeof(AppDiagnostics).Assembly.GetCustomAttribute()?.InformationalVersion ?? AssemblyName.Version?.ToString(); internal static readonly ActivitySource ActivitySource = new(AssemblyName.Name ?? "Exceptionless", AssemblyVersion); - internal static readonly ActivitySource AssistantActivitySource = new("Exceptionless.Assistant", AssemblyVersion); internal static readonly Meter Meter = new("Exceptionless", AssemblyVersion); private static readonly string _metricsPrefix = "ex."; @@ -92,9 +91,6 @@ 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 turn duration by outcome and failure reason"); - internal static readonly Histogram AssistantProviderDuration = Meter.CreateHistogram("ex.assistant.provider.duration", unit: "ms", description: "Assistant provider request duration by outcome"); - internal static readonly Histogram AssistantToolDuration = Meter.CreateHistogram("ex.assistant.tool.duration", unit: "ms", description: "Assistant tool duration by tool and outcome"); 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/Api/Endpoints/AssistantEndpoints.cs b/src/Exceptionless.Web/Api/Endpoints/AssistantEndpoints.cs index 8f2acc0ccb..9a0fbaa0dd 100644 --- a/src/Exceptionless.Web/Api/Endpoints/AssistantEndpoints.cs +++ b/src/Exceptionless.Web/Api/Endpoints/AssistantEndpoints.cs @@ -99,37 +99,17 @@ private static async Task StreamChatAsync( using var turnCancellationSource = CancellationTokenSource.CreateLinkedTokenSource(httpContext.RequestAborted); turnCancellationSource.CancelAfter(TimeSpan.FromSeconds(AssistantLimits.MaximumTurnDurationSeconds)); - using var diagnostics = new AssistantTurnDiagnostics(logger, timeProvider, organizationId!, request.ConversationId!, httpContext.TraceIdentifier, httpContext.RequestAborted); - var response = assistantService.StreamAsync(request, userId, planOptions, diagnostics, turnCancellationSource.Token); - await WriteResponseAsync(httpContext, response, assistantUsageService, organizationId!, diagnostics, turnCancellationSource.Token); - - return HttpResults.Empty; - } - - internal static async Task WriteResponseAsync( - HttpContext httpContext, - IAsyncEnumerable response, - AssistantUsageService assistantUsageService, - string organizationId, - AssistantTurnDiagnostics diagnostics, - CancellationToken cancellationToken) - { bool responseFailed = false; try { - await foreach (var item in response.WithCancellation(cancellationToken)) + await foreach (var item in assistantService.StreamAsync(request, userId, planOptions, turnCancellationSource.Token)) { - diagnostics.Observe(item); responseFailed |= item.Type == "error"; - string stage = diagnostics.Stage; - diagnostics.Stage = "response_write"; - await JsonSerializer.SerializeAsync(httpContext.Response.Body, item, s_jsonOptions, cancellationToken); - await httpContext.Response.WriteAsync("\n", cancellationToken); - await httpContext.Response.Body.FlushAsync(cancellationToken); - diagnostics.Stage = stage; + await JsonSerializer.SerializeAsync(httpContext.Response.Body, item, s_jsonOptions, turnCancellationSource.Token); + await httpContext.Response.WriteAsync("\n", turnCancellationSource.Token); + await httpContext.Response.Body.FlushAsync(turnCancellationSource.Token); } - diagnostics.Finish(responseFailed ? "failed" : "completed"); if (responseFailed) await assistantUsageService.RecordTurnFailedAsync(organizationId); else @@ -138,14 +118,10 @@ internal static async Task WriteResponseAsync( catch (OperationCanceledException) when (httpContext.RequestAborted.IsCancellationRequested) { // The browser closing or stopping the stream is expected. - diagnostics.Finish("cancelled", "client_disconnected"); await assistantUsageService.RecordTurnCancelledAsync(organizationId); } catch (OperationCanceledException) { - string failureCode = cancellationToken.IsCancellationRequested ? "turn_timeout" - : diagnostics.Stage is "provider_request" or "provider_stream" ? "provider_timeout" : "operation_cancelled"; - diagnostics.Finish("failed", failureCode); await assistantUsageService.RecordTurnFailedAsync(organizationId); var error = AssistantStreamEvent.Error("Exie took too long to complete this response. Try narrowing the question."); await JsonSerializer.SerializeAsync(httpContext.Response.Body, error, s_jsonOptions, CancellationToken.None); @@ -153,22 +129,14 @@ internal static async Task WriteResponseAsync( } catch (Exception ex) { - string failureCode = ex switch - { - AssistantProviderException providerException => providerException.FailureCode, - _ when diagnostics.Stage == "response_write" => "response_write_error", - _ when diagnostics.Stage == "tool_execution" => "tool_execution_error", - HttpRequestException when diagnostics.Stage is "provider_request" or "provider_stream" => "provider_transport_error", - JsonException when diagnostics.Stage == "provider_stream" => "invalid_provider_response", - IOException when diagnostics.Stage == "provider_stream" => "provider_stream_error", - _ => "internal_error" - }; - diagnostics.Finish("failed", failureCode, ex); await assistantUsageService.RecordTurnFailedAsync(organizationId); + logger.LogError(ex, "Unable to stream an in-app assistant response"); var error = AssistantStreamEvent.Error(ex is AssistantProviderException ? ex.Message : "Exie could not complete this request."); await JsonSerializer.SerializeAsync(httpContext.Response.Body, error, s_jsonOptions, CancellationToken.None); await httpContext.Response.WriteAsync("\n", CancellationToken.None); } + + return HttpResults.Empty; } private static async Task GetAccessAsync( diff --git a/src/Exceptionless.Web/ApmExtensions.cs b/src/Exceptionless.Web/ApmExtensions.cs index be2f81c505..0f6af7263f 100644 --- a/src/Exceptionless.Web/ApmExtensions.cs +++ b/src/Exceptionless.Web/ApmExtensions.cs @@ -72,7 +72,7 @@ public static IHostBuilder AddApm(this IHostBuilder builder, ApmConfig config) }); b.AddHttpClientInstrumentation(); - b.AddSource("Exceptionless", "Exceptionless.Assistant", "Foundatio"); + b.AddSource("Exceptionless", "Foundatio"); if (config.EnableRedis) b.AddRedisInstrumentation(c => diff --git a/src/Exceptionless.Web/Assistant/AssistantModels.cs b/src/Exceptionless.Web/Assistant/AssistantModels.cs index 4a9fc6ad84..098ccab84c 100644 --- a/src/Exceptionless.Web/Assistant/AssistantModels.cs +++ b/src/Exceptionless.Web/Assistant/AssistantModels.cs @@ -43,14 +43,10 @@ public sealed record AssistantStreamEvent( string? Message = null, IReadOnlyCollection? SuggestedActions = null) { - [System.Text.Json.Serialization.JsonIgnore] - internal string? FailureCode { get; init; } - public static AssistantStreamEvent TextDelta(string text) => new("text_delta", Text: text); public static AssistantStreamEvent ToolCall(string id, string name, string arguments) => new("tool_call", ToolCallId: id, ToolName: name, Arguments: arguments); public static AssistantStreamEvent ToolResult(string id, string name, string result) => new("tool_result", ToolCallId: id, ToolName: name, Result: result); public static AssistantStreamEvent Suggestions(IReadOnlyCollection actions) => new("suggested_actions", SuggestedActions: actions); public static AssistantStreamEvent Error(string message) => new("error", Message: message); - internal static AssistantStreamEvent Error(string message, string failureCode) => new("error", Message: message) { FailureCode = failureCode }; public static AssistantStreamEvent Done() => new("done"); } diff --git a/src/Exceptionless.Web/Assistant/AssistantProviderDiagnostics.cs b/src/Exceptionless.Web/Assistant/AssistantProviderDiagnostics.cs deleted file mode 100644 index ce90af0074..0000000000 --- a/src/Exceptionless.Web/Assistant/AssistantProviderDiagnostics.cs +++ /dev/null @@ -1,287 +0,0 @@ -using System.Diagnostics; -using System.Net.Sockets; -using System.Text.Json; - -namespace Exceptionless.Web.Assistant; - -internal sealed class AssistantProviderDiagnostics( - ILogger logger, - TimeProvider timeProvider, - AssistantTurnDiagnostics turn, - int inputCharacters, - bool allowTools, - CancellationToken cancellationToken) : IDisposable -{ - private readonly long _started = timeProvider.GetTimestamp(); - private readonly Activity? _activity = AppDiagnostics.AssistantActivitySource.StartActivity("assistant.provider"); - private bool _finished; - private bool _receivedError; - private Dictionary? _request; - private string? _apiKey; - private string? _requestSettings; - private string? _errorDetails; - private string? _routingDetails; - private string? _responseBodyState; - private bool _detailsTruncated; - private bool _detailsRedacted; - private int _chunks; - private double? _headersDuration; - private double? _firstChunkDuration; - private double? _lastChunkDuration; - private string? _exceptionType; - private string? _transportError; - private string? _socketError; - - public string? GenerationId { get; private set; } - public string? Model { get; private set; } - public string? ProviderName { get; private set; } - public int? StatusCode { get; private set; } - public string? FinishReason { get; private set; } - public bool UsageReceived { get; private set; } - public long? PromptTokens { get; private set; } - public long? CompletionTokens { get; private set; } - public long? ReasoningTokens { get; private set; } - public string? RequestId { get; private set; } - public string? ErrorCode { get; private set; } - public string? ErrorType { get; private set; } - public string? ProviderErrorCode { get; private set; } - public string? NativeFinishReason { get; private set; } - public string? ContentType { get; private set; } - public double? RetryAfterSeconds { get; private set; } - public string? Outcome { get; private set; } - - public void ObserveRequest(Dictionary request, string? apiKey) - { - _request = request; - _apiKey = apiKey; - _requestSettings = JsonSerializer.Serialize(new - { - max_tokens = request.GetValueOrDefault("max_tokens") as int?, - temperature = request.GetValueOrDefault("temperature") as double?, - tool_choice = request.GetValueOrDefault("tool_choice") is "none" ? "none" : "auto", - tool_count = (request.GetValueOrDefault("tools") as object[])?.Length, - message_count = (request.GetValueOrDefault("messages") as ICollection)?.Count, - maximum_prompt_price = AssistantLimits.MaximumProviderPromptPricePerMillionTokens, - maximum_completion_price = AssistantLimits.MaximumProviderCompletionPricePerMillionTokens - }); - } - - public void ObserveResponse(HttpResponseMessage response) - { - StatusCode = (int)response.StatusCode; - _headersDuration = timeProvider.GetElapsedTime(_started).TotalMilliseconds; - ContentType = SafeMetadata(response.Content.Headers.ContentType?.MediaType); - RequestId = GetHeader(response, "X-Request-Id") ?? GetHeader(response, "Request-Id") ?? GetHeader(response, "X-OpenRouter-Request-Id"); - RetryAfterSeconds = response.Headers.RetryAfter?.Delta?.TotalSeconds - ?? (response.Headers.RetryAfter?.Date - timeProvider.GetUtcNow())?.TotalSeconds; - if (response.Headers.TryGetValues("X-Generation-Id", out var values)) - { - GenerationId = SafeMetadata(values.FirstOrDefault()); - } - turn.Stage = "provider_stream"; - } - - public void ObserveChunk(JsonElement chunk) - { - if (chunk.ValueKind != JsonValueKind.Object) - { - return; - } - _chunks++; - _lastChunkDuration = timeProvider.GetElapsedTime(_started).TotalMilliseconds; - _firstChunkDuration ??= _lastChunkDuration; - GenerationId = GetMetadata(chunk, "id") ?? GenerationId; - Model = GetMetadata(chunk, "model") ?? Model; - ProviderName = GetMetadata(chunk, "provider") ?? ProviderName; - _receivedError |= chunk.TryGetProperty("error", out _); - if (chunk.TryGetProperty("error", out _) || chunk.TryGetProperty("openrouter_metadata", out _)) - { - ObserveErrorDetails(chunk); - } - if (chunk.TryGetProperty("usage", out var usage) && usage.ValueKind == JsonValueKind.Object) - { - UsageReceived = true; - PromptTokens = GetTokenCount(usage, "prompt_tokens") ?? PromptTokens; - CompletionTokens = GetTokenCount(usage, "completion_tokens") ?? CompletionTokens; - if (usage.TryGetProperty("completion_tokens_details", out var details) && details.ValueKind == JsonValueKind.Object - && GetTokenCount(details, "reasoning_tokens") is { } value) - { - ReasoningTokens = value; - } - } - if (chunk.TryGetProperty("choices", out var choices) && choices.ValueKind == JsonValueKind.Array && choices.GetArrayLength() > 0) - { - string? reason = GetMetadata(choices[0], "finish_reason"); - if (reason is not null) - { - FinishReason = reason is "stop" or "length" or "tool_calls" or "content_filter" or "error" ? reason : "unknown"; - } - NativeFinishReason = GetMetadata(choices[0], "native_finish_reason") ?? NativeFinishReason; - } - } - - public async Task ObserveErrorResponseAsync(HttpResponseMessage response, CancellationToken cancellationToken) - { - // Limit reads before parsing, including HTML/proxy errors and responses with no length. - const int maximumCharacters = 32_768; - using var reader = new StreamReader(await response.Content.ReadAsStreamAsync(cancellationToken)); - var buffer = new char[maximumCharacters + 1]; - int length = await reader.ReadBlockAsync(buffer.AsMemory(), cancellationToken); - _detailsTruncated = length > maximumCharacters; - _responseBodyState = _detailsTruncated ? "truncated" : length == 0 ? "empty" : "json"; - if (_detailsTruncated || length == 0) - { - return; - } - - try - { - using var document = JsonDocument.Parse(new string(buffer, 0, length), new JsonDocumentOptions { MaxDepth = 32 }); - ObserveErrorDetails(document.RootElement); - } - catch (JsonException) - { - // HTML and malformed JSON can echo arbitrary request data. Keep the response - // classification and headers, not an unfilterable body. - _responseBodyState = "invalid_json"; - } - } - - private void ObserveErrorDetails(JsonElement envelope) - { - if (envelope.ValueKind != JsonValueKind.Object) - { - _responseBodyState = "invalid_shape"; - return; - } - - GenerationId = GetMetadata(envelope, "id") ?? GenerationId; - Model = GetMetadata(envelope, "model") ?? Model; - ProviderName = GetMetadata(envelope, "provider") ?? ProviderName; - var messages = _request is not null && _request.TryGetValue("messages", out var value) - ? JsonSerializer.SerializeToElement(value) : default; - var details = new AssistantProviderErrorDetails(messages, _apiKey); - if (envelope.TryGetProperty("error", out var error)) - { - _receivedError = true; - _responseBodyState ??= "json"; - ErrorCode = GetCode(error, "code"); - ErrorType = GetMetadata(error, "type"); - if (error.ValueKind == JsonValueKind.Object && error.TryGetProperty("metadata", out var metadata)) - { - ErrorType = GetMetadata(metadata, "error_type") ?? ErrorType; - ProviderErrorCode = GetCode(metadata, "provider_code") ?? GetCode(metadata, "provider_error_code"); - ProviderName = GetMetadata(metadata, "provider_name") ?? ProviderName; - } - - _errorDetails = JsonSerializer.Serialize(details.Capture(error)); - } - - if (envelope.TryGetProperty("openrouter_metadata", out var routing)) - { - _routingDetails = JsonSerializer.Serialize(details.Capture(routing)); - } - - _detailsTruncated |= details.Truncated; - _detailsRedacted |= details.Redacted; - } - - public void Complete(int outputCharacters, int toolCalls, bool receivedDone) - { - string outcome = _receivedError ? "provider_error" : FinishReason switch - { - "length" => "output_limit", - "content_filter" => "content_filter", - "error" => "provider_error", - _ when outputCharacters == 0 && toolCalls == 0 => "empty_response", - _ when !receivedDone && FinishReason is null => "incomplete_stream", - _ => "completed" - }; - Finish(outcome, outputCharacters, toolCalls, receivedDone); - } - - public void RecordException(Exception exception, int? outputCharacters = null, int? toolCalls = null, bool receivedDone = false) - { - _exceptionType = exception.GetType().FullName; - _transportError = (exception as HttpRequestException)?.HttpRequestError.ToString(); - _socketError = (exception.InnerException as SocketException)?.SocketErrorCode.ToString(); - string outcome = exception switch - { - AssistantProviderException providerException => providerException.FailureCode, - OperationCanceledException => GetCancellationOutcome(), - HttpRequestException => "provider_transport_error", - JsonException => "invalid_provider_response", - IOException => "provider_stream_error", - _ => "internal_error" - }; - Finish(outcome, outputCharacters, toolCalls, receivedDone); - } - - public void Reject(string reason, int outputCharacters, int toolCalls, bool receivedDone) => Finish(reason, outputCharacters, toolCalls, receivedDone); - - private void Finish(string outcome, int? outputCharacters = null, int? toolCalls = null, bool receivedDone = false) - { - if (_finished) - { - return; - } - _finished = true; - Outcome = outcome; - double duration = timeProvider.GetElapsedTime(_started).TotalMilliseconds; - _activity?.SetTag("assistant.provider.outcome", outcome); - _activity?.SetTag("assistant.provider.generation_id", GenerationId); - _activity?.SetTag("assistant.provider.model", Model ?? turn.Model); - _activity?.SetTag("assistant.provider.name", ProviderName); - _activity?.SetTag("assistant.provider.finish_reason", FinishReason); - _activity?.SetTag("http.response.status_code", StatusCode); - _activity?.SetTag("assistant.provider.error.code", ErrorCode); - _activity?.SetTag("assistant.provider.error.type", ErrorType); - _activity?.SetTag("assistant.provider.error.provider_code", ProviderErrorCode); - _activity?.SetTag("assistant.provider.request_id", RequestId); - if (outcome is not ("completed" or "cancelled")) - { - _activity?.SetStatus(ActivityStatusCode.Error, outcome); - } - AppDiagnostics.AssistantProviderDuration.Record(duration, new KeyValuePair("outcome", outcome)); - logger.Log(outcome is "completed" or "cancelled" ? LogLevel.Information : LogLevel.Warning, - "Assistant provider request {ProviderRequestNumber} {ProviderOutcome} for turn {AssistantTurnId}: duration={DurationMs} ms generation={ProviderGenerationId} model={ProviderModel} provider={ProviderName} status={ProviderStatusCode} finish={ProviderFinishReason} input_characters={InputCharacters} output_characters={OutputCharacters} tools_allowed={ToolsAllowed} tool_calls={ToolCalls} usage_received={UsageReceived} prompt_tokens={PromptTokens} completion_tokens={CompletionTokens} reasoning_tokens={ReasoningTokens} received_done={ReceivedDone} request={ProviderRequestId} error_code={ProviderErrorCode} error_type={ProviderErrorType} upstream_code={UpstreamErrorCode} native_finish={ProviderNativeFinishReason} retry_after={RetryAfterSeconds} content_type={ProviderContentType} headers_ms={HeadersDurationMs} first_chunk_ms={FirstChunkDurationMs} last_chunk_ms={LastChunkDurationMs} chunks={ChunkCount} error_details={ProviderErrorDetails} routing={ProviderRoutingDetails} body_state={ProviderErrorBodyState} details_truncated={ProviderDetailsTruncated} details_redacted={ProviderDetailsRedacted} exception_type={ExceptionType} transport_error={TransportError} socket_error={SocketError} request_settings={ProviderRequestSettings}", - turn.ProviderRequests, outcome, turn.TurnId, duration, GenerationId, Model ?? turn.Model, ProviderName, StatusCode, - FinishReason, inputCharacters, outputCharacters, allowTools, toolCalls, UsageReceived, PromptTokens, CompletionTokens, ReasoningTokens, receivedDone, - RequestId, ErrorCode, ErrorType, ProviderErrorCode, NativeFinishReason, RetryAfterSeconds, ContentType, _headersDuration, - _firstChunkDuration, _lastChunkDuration, _chunks, _errorDetails, _routingDetails, _responseBodyState, _detailsTruncated, _detailsRedacted, - _exceptionType, _transportError, _socketError, _requestSettings); - _request = null; - _apiKey = null; - _activity?.Dispose(); - } - - public void Dispose() => Finish(StatusCode is < 200 or >= 300 ? "provider_http_error" - : _receivedError || FinishReason == "error" ? "provider_error" - : cancellationToken.IsCancellationRequested ? GetCancellationOutcome() : "interrupted"); - - private string GetCancellationOutcome() - { - string reason = turn.GetCancellationReason(cancellationToken, "provider_timeout"); - return reason == "client_disconnected" ? "cancelled" : reason; - } - - private string? GetMetadata(JsonElement element, string name) - => element.ValueKind == JsonValueKind.Object && element.TryGetProperty(name, out var property) && property.ValueKind == JsonValueKind.String - ? SafeMetadata(property.GetString()) : null; - - private string? GetCode(JsonElement element, string name) - => element.ValueKind == JsonValueKind.Object && element.TryGetProperty(name, out var property) && property.ValueKind == JsonValueKind.Number - && property.TryGetInt32(out int value) ? value.ToString(System.Globalization.CultureInfo.InvariantCulture) : GetMetadata(element, name); - - private string? GetHeader(HttpResponseMessage response, string name) - => response.Headers.TryGetValues(name, out var values) ? SafeMetadata(values.FirstOrDefault()) : null; - - private static long? GetTokenCount(JsonElement element, string name) - => element.TryGetProperty(name, out var property) && property.ValueKind == JsonValueKind.Number && property.TryGetInt64(out long value) - ? Math.Max(0, value) : null; - - private string? SafeMetadata(string? value) - => value is { Length: > 0 and <= 128 } && (String.IsNullOrEmpty(_apiKey) || !value.Contains(_apiKey, StringComparison.Ordinal)) - && value.All(character => Char.IsAsciiLetterOrDigit(character) || character is '-' or '_' or '/' or '.' or ':' or '~' or ' ') - ? value : null; -} diff --git a/src/Exceptionless.Web/Assistant/AssistantProviderErrorDetails.cs b/src/Exceptionless.Web/Assistant/AssistantProviderErrorDetails.cs deleted file mode 100644 index db4edd45c4..0000000000 --- a/src/Exceptionless.Web/Assistant/AssistantProviderErrorDetails.cs +++ /dev/null @@ -1,261 +0,0 @@ -using System.Text.Json; -using System.Text.RegularExpressions; - -namespace Exceptionless.Web.Assistant; - -// Provider errors sometimes wrap the useful error in metadata.raw, and sometimes echo -// the request there too. Extract diagnostic fields instead of logging the response body. -internal sealed class AssistantProviderErrorDetails(JsonElement requestMessages, string? apiKey) -{ - private const int MaximumTextLength = 2048; - private const int MaximumFields = 64; - private const int MaximumItems = 16; - private static readonly Regex s_credentials = new( - @"\b(?:Bearer|Basic)\s+[^\s,;]+|\bsk-[A-Za-z0-9_-]+|\b(?:api[_-]?key|password|secret|access[_-]?token|authorization)\s*[:=]\s*[^\s,;]+", - RegexOptions.IgnoreCase | RegexOptions.CultureInvariant | RegexOptions.NonBacktracking, TimeSpan.FromMilliseconds(100)); - private static readonly Regex s_urls = new(@"https?://[^\s<>""']+", RegexOptions.CultureInvariant | RegexOptions.NonBacktracking, TimeSpan.FromMilliseconds(100)); - private readonly string[] _requestValues = GetRequestValues(requestMessages, apiKey).OrderByDescending(value => value.Length).ToArray(); - private int _fields; - private int _remainingCharacters = 8192; - - public bool Truncated { get; private set; } - public bool Redacted { get; private set; } - - public Dictionary Capture(JsonElement value, int depth = 0) - { - var result = new Dictionary(); - if (value.ValueKind != JsonValueKind.Object) - { - return result; - } - - foreach (var property in value.EnumerateObject()) - { - if (_fields >= MaximumFields || depth >= 6 || _remainingCharacters <= 0) - { - Truncated = true; - break; - } - - switch (property.Name) - { - case "code": case "type": case "message": case "msg": case "param": - case "error_type": case "provider_code": case "provider_error_code": case "provider_name": - case "limit_source": case "is_byok": case "failed_routing_step": case "input_endpoint_count": - case "reason": case "endpoint_count": case "request_id": - case "requested": case "strategy": case "region": case "attempt": case "total": - case "provider": case "model": case "status": case "selected": - _fields++; - result[property.Name] = CaptureScalar(property.Value); - break; - case "error": case "metadata": case "endpoints": - _fields++; - result[property.Name] = Capture(property.Value, depth + 1); - break; - case "raw": case "detail": - _fields++; - result[property.Name] = CaptureNested(property.Value, depth + 1); - break; - case "errors": case "ineligibility_reasons": case "routing_funnel": case "attempts": case "available": case "loc": - _fields++; - result[property.Name] = CaptureArray(property.Value, depth + 1); - break; - case "step": - _fields++; - result[property.Name] = CaptureScalar(property.Value); - break; - } - } - - return result; - } - - public string SanitizeText(string value) - { - string sanitized; - try - { - foreach (string requestValue in _requestValues) - { - value = requestValue.Length >= 8 - ? value.Replace(requestValue, "[REDACTED]", StringComparison.Ordinal) - : Regex.Replace(value, $@"(? Char.IsControl(character) ? ' ' : character)); - int length = Math.Min(MaximumTextLength, _remainingCharacters); - if (sanitized.Length > length) - { - Truncated = true; - sanitized = sanitized[..length]; - } - - _remainingCharacters -= sanitized.Length; - return sanitized; - } - - private object? CaptureScalar(JsonElement value) => value.ValueKind switch - { - JsonValueKind.String => SanitizeText(value.GetString()!), - JsonValueKind.Number when value.TryGetDecimal(out decimal number) => number, - JsonValueKind.True => true, - JsonValueKind.False => false, - _ => null - }; - - private object? CaptureNested(JsonElement value, int depth) - { - if (depth >= 6) - { - Truncated = true; - return null; - } - - if (value.ValueKind == JsonValueKind.Object) - { - return Capture(value, depth); - } - - if (value.ValueKind == JsonValueKind.Array) - { - return CaptureArray(value, depth); - } - - if (value.ValueKind != JsonValueKind.String) - { - return CaptureScalar(value); - } - - string text = value.GetString()!; - if (text.TrimStart().StartsWith('{') || text.TrimStart().StartsWith('[')) - { - try - { - using var document = JsonDocument.Parse(text, new JsonDocumentOptions { MaxDepth = 16 }); - return CaptureNested(document.RootElement, depth + 1); - } - catch (JsonException) - { - // A partial JSON body cannot be safely filtered by field name. - return "[INVALID JSON]"; - } - } - - return SanitizeText(text); - } - - private object? CaptureArray(JsonElement value, int depth) - { - if (value.ValueKind != JsonValueKind.Array) - { - return null; - } - - Truncated |= value.GetArrayLength() > MaximumItems; - return value.EnumerateArray().Take(MaximumItems).Select(item => CaptureNested(item, depth)).ToArray(); - } - - private static HashSet GetRequestValues(JsonElement messages, string? apiKey) - { - var values = new HashSet(StringComparer.Ordinal); - if (!String.IsNullOrEmpty(apiKey)) - { - values.Add(apiKey); - } - - if (messages.ValueKind == JsonValueKind.Array) - { - foreach (var message in messages.EnumerateArray()) - { - if (message.ValueKind != JsonValueKind.Object) - { - continue; - } - - if (message.TryGetProperty("content", out var content) && content.ValueKind == JsonValueKind.String) - { - AddValue(content.GetString()!, values); - } - - foreach (string name in new[] { "reasoning", "reasoning_content", "reasoning_details" }) - { - if (message.TryGetProperty(name, out var reasoning)) - { - AddJsonValues(reasoning, values); - } - } - - if (message.TryGetProperty("tool_calls", out var calls) && calls.ValueKind == JsonValueKind.Array) - { - foreach (var call in calls.EnumerateArray()) - { - if (call.TryGetProperty("function", out var function) && function.TryGetProperty("arguments", out var arguments) - && arguments.ValueKind == JsonValueKind.String) - { - AddValue(arguments.GetString()!, values); - } - } - } - } - } - - return values; - } - - private static void AddValue(string value, HashSet values) - { - if (!String.IsNullOrEmpty(value)) - { - values.Add(value); - } - - foreach (string line in value.Split('\n', StringSplitOptions.TrimEntries | StringSplitOptions.RemoveEmptyEntries)) - { - if (line.Length >= 8) - { - values.Add(line); - } - } - - try - { - using var document = JsonDocument.Parse(value); - AddJsonValues(document.RootElement, values); - } - catch (JsonException) - { - } - } - - private static void AddJsonValues(JsonElement value, HashSet values) - { - if (value.ValueKind == JsonValueKind.Object) - { - foreach (var property in value.EnumerateObject()) - { - AddJsonValues(property.Value, values); - } - } - else if (value.ValueKind == JsonValueKind.Array) - { - foreach (var item in value.EnumerateArray()) - { - AddJsonValues(item, values); - } - } - else if (value.ValueKind == JsonValueKind.String && value.GetString() is { Length: > 0 } text) - { - values.Add(text); - } - } -} diff --git a/src/Exceptionless.Web/Assistant/AssistantProviderException.cs b/src/Exceptionless.Web/Assistant/AssistantProviderException.cs index 501ac03bd2..da724717e0 100644 --- a/src/Exceptionless.Web/Assistant/AssistantProviderException.cs +++ b/src/Exceptionless.Web/Assistant/AssistantProviderException.cs @@ -1,6 +1,3 @@ namespace Exceptionless.Web.Assistant; -public sealed class AssistantProviderException(string message) : Exception(message) -{ - internal string FailureCode { get; init; } = "provider_error"; -} +public sealed class AssistantProviderException(string message) : Exception(message); diff --git a/src/Exceptionless.Web/Assistant/AssistantService.cs b/src/Exceptionless.Web/Assistant/AssistantService.cs index 0674167dbb..f770e7c57e 100644 --- a/src/Exceptionless.Web/Assistant/AssistantService.cs +++ b/src/Exceptionless.Web/Assistant/AssistantService.cs @@ -36,26 +36,14 @@ public sealed class AssistantService( private static readonly JsonSerializerOptions s_jsonOptions = new JsonSerializerOptions(JsonSerializerDefaults.Web).ConfigureExceptionlessApiDefaults(); private static readonly Regex s_rawDsmlPattern = new(@"<\s*/?\s*[|｜]\s*DSML\s*[|｜]", RegexOptions.IgnoreCase | RegexOptions.CultureInvariant, TimeSpan.FromSeconds(1)); - public IAsyncEnumerable StreamAsync( + public async IAsyncEnumerable StreamAsync( AssistantChatRequest request, string userId, AssistantPlanOptions planOptions, - CancellationToken cancellationToken = default) - => StreamAsync(request, userId, planOptions, null, cancellationToken); - - internal async IAsyncEnumerable StreamAsync( - AssistantChatRequest request, - string userId, - AssistantPlanOptions planOptions, - AssistantTurnDiagnostics? diagnostics, [EnumeratorCancellation] CancellationToken cancellationToken = default) { var options = appOptions.AssistantOptions; string model = (await assistantModelSettingsService.GetAsync()).Model; - if (diagnostics is not null) - { - diagnostics.Model = model; - } AssistantConversationState? conversationState = null; if (!String.IsNullOrWhiteSpace(request.OrganizationId) && !String.IsNullOrWhiteSpace(request.ConversationId)) { @@ -83,14 +71,10 @@ internal async IAsyncEnumerable StreamAsync( { if (completedToolRounds > 0) { - if (diagnostics is not null) - { - diagnostics.Stage = "usage_check"; - } var usageDecision = await assistantUsageService.TryContinueTurnAsync(request.OrganizationId, planOptions); if (!usageDecision.Allowed) { - yield return AssistantStreamEvent.Error(usageDecision.Message ?? "Exie reached this organization's usage limit.", "usage_limit"); + yield return AssistantStreamEvent.Error(usageDecision.Message ?? "Exie reached this organization's usage limit."); yield return AssistantStreamEvent.Done(); yield break; } @@ -128,138 +112,108 @@ internal async IAsyncEnumerable StreamAsync( if (providerInputCharacters > AssistantLimits.MaximumProviderInputCharacters) { throw new AssistantProviderException( - "This conversation contains too much context for one response. Clear the conversation or narrow the question.") { FailureCode = "context_limit" }; + "This conversation contains too much context for one response. Clear the conversation or narrow the question."); } - if (diagnostics is not null) - { - diagnostics.Stage = "usage_reservation"; - } await using var providerRequest = await assistantUsageService.StartProviderRequestAsync(request.OrganizationId, providerInputCharacters); - using var providerDiagnostics = diagnostics?.StartProviderRequest(providerInputCharacters, allowTools, cancellationToken); - bool receivedDone = false; - try + using var response = await SendRequestAsync(messages, options, model, allowTools, request, 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) { - using var response = await SendRequestAsync(messages, options, model, allowTools, request, providerDiagnostics, cancellationToken); - providerRequest.MarkAccepted(); - await using var stream = await response.Content.ReadAsStreamAsync(cancellationToken); - using var reader = new StreamReader(stream); + if (!line.StartsWith("data:", StringComparison.Ordinal)) + continue; - while (await reader.ReadLineAsync(cancellationToken) is { } line) + string payload = line[5..].Trim(); + if (payload.Length == 0 || payload == "[DONE]") + continue; + + using var document = JsonDocument.Parse(payload); + generationId = GetProviderValue(document.RootElement, "id") ?? generationId; + providerName = GetProviderValue(document.RootElement, "provider") ?? providerName; + if (document.RootElement.TryGetProperty("error", out var error)) { - if (!line.StartsWith("data:", StringComparison.Ordinal)) - continue; + LogProviderFailure(response, document.RootElement, model, request, generationId, providerName); + throw new AssistantProviderException(GetProviderError(error)); + } - string payload = line[5..].Trim(); - if (payload == "[DONE]") + if (!usageRecorded && TryGetProviderUsage(document.RootElement, out var usage)) + { + usageRecorded = true; + try { - receivedDone = true; - continue; + await providerRequest.ReconcileAsync(usage); } - if (payload.Length == 0) - continue; - - try + catch (Exception ex) { - using var document = JsonDocument.Parse(payload); - providerDiagnostics?.ObserveChunk(document.RootElement); - if (document.RootElement.TryGetProperty("error", out var error)) - throw new AssistantProviderException(GetProviderError(error)); - - if (!usageRecorded && TryGetProviderUsage(document.RootElement, out var usage)) - { - usageRecorded = true; - try - { - await providerRequest.ReconcileAsync(usage); - } - catch (Exception ex) - { - // Disposal records the conservative reservation when detailed provider - // accounting cannot be reconciled. - logger.LogError(ex, "Unable to record assistant provider usage for organization {OrganizationId}", request.OrganizationId); - } - } + // Disposal records the conservative reservation when detailed provider + // accounting cannot be reconciled. + logger.LogError(ex, "Unable to record assistant provider usage for organization {OrganizationId}", request.OrganizationId); + } + } - if (!document.RootElement.TryGetProperty("choices", out var choices) || choices.GetArrayLength() == 0) - continue; + if (!document.RootElement.TryGetProperty("choices", out var choices) || choices.GetArrayLength() == 0) + 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()); - } + 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("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(); - if (!String.IsNullOrEmpty(text)) - { - assistantContent.Append(text); - assistantContentChunks.Add(text); - } - } + if (delta.TryGetProperty("content", out var content) && content.ValueKind == JsonValueKind.String) + { + string? text = content.GetString(); + if (!String.IsNullOrEmpty(text)) + { + assistantContent.Append(text); + assistantContentChunks.Add(text); + } + } - if (!delta.TryGetProperty("tool_calls", out var toolCallUpdates)) - continue; + if (!delta.TryGetProperty("tool_calls", out var toolCallUpdates)) + continue; - foreach (var update in toolCallUpdates.EnumerateArray()) - { - int index = update.GetProperty("index").GetInt32(); - if (!toolCalls.TryGetValue(index, out var pending)) - { - pending = new PendingToolCall(); - toolCalls[index] = pending; - } - - if (update.TryGetProperty("id", out var id) && id.ValueKind == JsonValueKind.String) - pending.Id = id.GetString() ?? pending.Id; - - if (!update.TryGetProperty("function", out var function)) - continue; - - if (function.TryGetProperty("name", out var name) && name.ValueKind == JsonValueKind.String) - pending.Name += name.GetString(); - if (function.TryGetProperty("arguments", out var arguments) && arguments.ValueKind == JsonValueKind.String) - pending.Arguments.Append(arguments.GetString()); - } - } - catch (Exception ex) when (ex is InvalidOperationException or KeyNotFoundException or FormatException) + foreach (var update in toolCallUpdates.EnumerateArray()) + { + int index = update.GetProperty("index").GetInt32(); + if (!toolCalls.TryGetValue(index, out var pending)) { - throw new JsonException("The AI provider returned an invalid response structure.", ex); + pending = new PendingToolCall(); + toolCalls[index] = pending; } - } - } - catch (Exception ex) - { - providerDiagnostics?.RecordException(ex, assistantContent.Length, toolCalls.Count, receivedDone); - throw; - } - if (diagnostics is not null) - { - diagnostics.Stage = "response_validation"; + if (update.TryGetProperty("id", out var id) && id.ValueKind == JsonValueKind.String) + pending.Id = id.GetString() ?? pending.Id; + + if (!update.TryGetProperty("function", out var function)) + continue; + + if (function.TryGetProperty("name", out var name) && name.ValueKind == JsonValueKind.String) + pending.Name += name.GetString(); + if (function.TryGetProperty("arguments", out var arguments) && arguments.ValueKind == JsonValueKind.String) + pending.Arguments.Append(arguments.GetString()); + } } if (s_rawDsmlPattern.IsMatch(assistantContent.ToString())) { - providerDiagnostics?.Reject("malformed_response", assistantContent.Length, toolCalls.Count, receivedDone); if (malformedResponseRetries < AssistantLimits.MaximumMalformedResponseRetries) { malformedResponseRetries++; - if (diagnostics is not null) - { - diagnostics.MalformedResponseRetries = malformedResponseRetries; - } logger.LogWarning( "Assistant provider returned raw DSML content for organization {OrganizationId}; retrying response", request.OrganizationId); @@ -275,7 +229,7 @@ internal async IAsyncEnumerable StreamAsync( logger.LogWarning( "Assistant provider returned raw DSML content again for organization {OrganizationId}", request.OrganizationId); - yield return AssistantStreamEvent.Error("Exie received a malformed response from the AI provider. Please try again.", "malformed_response"); + yield return AssistantStreamEvent.Error("Exie received a malformed response from the AI provider. Please try again."); yield return AssistantStreamEvent.Done(); yield break; } @@ -286,15 +240,6 @@ internal async IAsyncEnumerable StreamAsync( malformedResponseCorrection = null; } - if (!allowTools && toolCalls.Count > 0) - { - providerDiagnostics?.Reject("tool_round_limit", assistantContent.Length, toolCalls.Count, receivedDone); - } - else - { - providerDiagnostics?.Complete(assistantContent.Length, toolCalls.Count, receivedDone); - } - foreach (string text in assistantContentChunks) { yield return AssistantStreamEvent.TextDelta(text); @@ -304,14 +249,7 @@ internal async IAsyncEnumerable StreamAsync( { if (assistantContent.Length == 0) { - string failureCode = providerDiagnostics?.FinishReason switch - { - "length" => "output_limit", - "content_filter" => "content_filter", - "error" => "provider_error", - _ => "empty_response" - }; - yield return AssistantStreamEvent.Error("Exie stopped before providing an answer. Please try again.", failureCode); + yield return AssistantStreamEvent.Error("Exie stopped before providing an answer. Please try again."); } else if (pendingSuggestedActions.Count > 0) { @@ -324,7 +262,7 @@ internal async IAsyncEnumerable StreamAsync( if (!allowTools) { - yield return AssistantStreamEvent.Error("Exie could not finish using the available tool results. Try narrowing the question.", "tool_round_limit"); + yield return AssistantStreamEvent.Error("Exie could not finish using the available tool results. Try narrowing the question."); yield return AssistantStreamEvent.Done(); yield break; } @@ -368,10 +306,6 @@ internal async IAsyncEnumerable StreamAsync( requireFinalAnswer = true; completedToolRounds++; - if (diagnostics is not null) - { - diagnostics.ToolRounds = completedToolRounds; - } continue; } @@ -385,10 +319,8 @@ internal async IAsyncEnumerable StreamAsync( foreach (var toolCall in executableToolCalls) { string arguments = toolCall.Arguments.ToString(); - diagnostics?.StartTool(toolCall.Name); yield return AssistantStreamEvent.ToolCall(toolCall.Id, toolCall.Name, arguments); - long toolStarted = timeProvider.GetTimestamp(); string result; if (remainingToolCalls <= 0) { @@ -421,18 +353,9 @@ internal async IAsyncEnumerable StreamAsync( if (toolCall.Name == SearchStacksTool) remainingProjectSearches--; - try - { - result = await ExecuteToolAsync(toolCall.Name, arguments, request, cancellationToken); - } - catch (Exception ex) - { - diagnostics?.RecordToolException(ex, timeProvider.GetElapsedTime(toolStarted).TotalMilliseconds, cancellationToken); - throw; - } + result = await ExecuteToolAsync(toolCall.Name, arguments, request, cancellationToken); } - diagnostics?.RecordToolResult(result, timeProvider.GetElapsedTime(toolStarted).TotalMilliseconds); if (toolCall.Name == GetProjectSetupTool) configureHref = AssistantSuggestedActionParser.GetProjectSetupHref(result) ?? configureHref; @@ -452,10 +375,6 @@ internal async IAsyncEnumerable StreamAsync( && !String.IsNullOrWhiteSpace(request.OrganizationId) && !String.IsNullOrWhiteSpace(request.ConversationId)) { - if (diagnostics is not null) - { - diagnostics.Stage = "conversation_save"; - } await assistantConversationService.AppendToolResultsAsync( userId, request.OrganizationId, @@ -465,21 +384,16 @@ await assistantConversationService.AppendToolResultsAsync( } completedToolRounds++; - if (diagnostics is not null) - { - diagnostics.ToolRounds = completedToolRounds; - } } } - private async Task SendRequestAsync(List messages, AssistantOptions options, string model, bool allowTools, AssistantChatRequest chatRequest, AssistantProviderDiagnostics? diagnostics, CancellationToken cancellationToken) + private async Task SendRequestAsync(List messages, AssistantOptions options, string model, bool allowTools, AssistantChatRequest chatRequest, CancellationToken cancellationToken) { var client = httpClientFactory.CreateClient(nameof(AssistantService)); using var providerRequest = new HttpRequestMessage(HttpMethod.Post, options.Endpoint); providerRequest.Headers.Authorization = new("Bearer", options.ApiKey); providerRequest.Headers.TryAddWithoutValidation("HTTP-Referer", appOptions.BaseURL); providerRequest.Headers.TryAddWithoutValidation("X-OpenRouter-Title", "Exceptionless"); - providerRequest.Headers.TryAddWithoutValidation("X-OpenRouter-Metadata", "enabled"); var payload = new Dictionary { ["model"] = model, @@ -504,23 +418,25 @@ private async Task SendRequestAsync(List messages, } providerRequest.Content = JsonContent.Create(payload); - diagnostics?.ObserveRequest(payload, options.ApiKey); var response = await client.SendAsync(providerRequest, HttpCompletionOption.ResponseHeadersRead, cancellationToken); - diagnostics?.ObserveResponse(response); if (response.IsSuccessStatusCode) return response; using (response) { - if (diagnostics is not null) + try { - await diagnostics.ObserveErrorResponseAsync(response, cancellationToken); + 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); } - - logger.LogWarning("Assistant provider returned HTTP {StatusCode} with generation {ProviderGenerationId}", (int)response.StatusCode, diagnostics?.GenerationId); } - throw new AssistantProviderException($"The AI provider returned status {(int)response.StatusCode}.") { FailureCode = "provider_http_error" }; + throw new AssistantProviderException($"The AI provider returned status {(int)response.StatusCode}."); } private static Dictionary CreateAssistantToolMessage( @@ -825,7 +741,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/Assistant/AssistantTurnDiagnostics.cs b/src/Exceptionless.Web/Assistant/AssistantTurnDiagnostics.cs deleted file mode 100644 index a862d01f89..0000000000 --- a/src/Exceptionless.Web/Assistant/AssistantTurnDiagnostics.cs +++ /dev/null @@ -1,190 +0,0 @@ -using System.Diagnostics; -using System.Text.Json; -using Exceptionless.Web.Mcp; - -namespace Exceptionless.Web.Assistant; - -internal sealed class AssistantTurnDiagnostics : IDisposable -{ - private readonly ILogger _logger; - private readonly TimeProvider _timeProvider; - private readonly long _started; - private readonly Activity? _activity; - private readonly IDisposable? _scope; - private readonly CancellationToken _requestAborted; - private bool _finished; - private double? _firstTextDuration; - private string? _failureCode; - - public AssistantTurnDiagnostics(ILogger logger, TimeProvider timeProvider, string organizationId, string conversationId, string requestId, CancellationToken requestAborted = default) - { - _logger = logger; - _timeProvider = timeProvider; - _requestAborted = requestAborted; - _started = timeProvider.GetTimestamp(); - _activity = AppDiagnostics.AssistantActivitySource.StartActivity("assistant.turn"); - TurnId = Guid.NewGuid().ToString("N"); - OrganizationId = organizationId; - ConversationId = conversationId; - RequestId = requestId; - TraceId = Activity.Current?.TraceId.ToString(); - _activity?.SetTag("assistant.turn.id", TurnId); - _activity?.SetTag("organization.id", organizationId); - _activity?.SetTag("assistant.conversation.id", conversationId); - _scope = logger.BeginScope(new Dictionary - { - ["AssistantTurnId"] = TurnId, - ["OrganizationId"] = organizationId, - ["ConversationId"] = conversationId, - ["RequestId"] = requestId, - ["TraceId"] = TraceId - }); - } - - public string TurnId { get; } - public string OrganizationId { get; } - public string ConversationId { get; } - public string RequestId { get; } - public string? TraceId { get; } - public bool IsClientDisconnected => _requestAborted.IsCancellationRequested; - public string? Model { get; set; } - public string Stage { get; set; } = "initializing"; - public int ProviderRequests { get; private set; } - public int ToolCalls { get; private set; } - public int ToolFailures { get; private set; } - public int ToolRounds { get; set; } - public int MalformedResponseRetries { get; set; } - public string? LastTool { get; private set; } - public string? LastToolError { get; private set; } - public AssistantProviderDiagnostics? Provider { get; private set; } - - public string GetCancellationReason(CancellationToken cancellationToken, string operationReason) - => IsClientDisconnected ? "client_disconnected" : cancellationToken.IsCancellationRequested ? "turn_timeout" : operationReason; - - public AssistantProviderDiagnostics StartProviderRequest(int inputCharacters, bool allowTools, CancellationToken cancellationToken) - { - Stage = "provider_request"; - ProviderRequests++; - Provider = new AssistantProviderDiagnostics(_logger, _timeProvider, this, inputCharacters, allowTools, cancellationToken); - return Provider; - } - - public void Observe(AssistantStreamEvent item) - { - if (item.Type == "error") - { - _failureCode ??= item.FailureCode ?? "response_error"; - } - if (item.Type == "text_delta" && !String.IsNullOrEmpty(item.Text)) - { - _firstTextDuration ??= ElapsedMilliseconds; - } - } - - public void StartTool(string name) - { - Stage = "tool_execution"; - LastTool = GetToolName(name); - ToolCalls++; - } - - public void RecordToolResult(string result, double durationMilliseconds) - { - using var document = JsonDocument.Parse(result); - var root = document.RootElement; - bool failed = root.ValueKind == JsonValueKind.Object && root.TryGetProperty("ok", out var ok) && ok.ValueKind == JsonValueKind.False; - string? errorCode = null; - if (failed) - { - ToolFailures++; - errorCode = "tool_error"; - if (root.TryGetProperty("error", out var error) && error.ValueKind == JsonValueKind.Object - && error.TryGetProperty("code", out var code) && code.ValueKind == JsonValueKind.String) - { - errorCode = GetToolErrorCode(code.GetString()); - } - LastToolError = errorCode; - _logger.LogWarning("Assistant tool {ToolName} failed with {ToolErrorCode} in {DurationMs} ms for turn {AssistantTurnId}", - LastTool, errorCode, durationMilliseconds, TurnId); - } - - AppDiagnostics.AssistantToolDuration.Record(durationMilliseconds, - new("tool", LastTool), new("outcome", failed ? "failed" : "completed"), new("reason", errorCode ?? "none")); - } - - public void RecordToolException(Exception exception, double durationMilliseconds, CancellationToken cancellationToken) - { - LastToolError = exception is OperationCanceledException ? GetCancellationReason(cancellationToken, "operation_cancelled") : "tool_execution_error"; - bool cancelled = LastToolError == "client_disconnected"; - string outcome = cancelled ? "cancelled" : "failed"; - if (!cancelled) - { - ToolFailures++; - } - - _logger.Log(cancelled ? LogLevel.Information : LogLevel.Warning, - "Assistant tool {ToolName} {ToolOutcome} with {ToolErrorCode} in {DurationMs} ms for turn {AssistantTurnId}: exception_type={ExceptionType}", - LastTool, outcome, LastToolError, durationMilliseconds, TurnId, exception.GetType().FullName); - AppDiagnostics.AssistantToolDuration.Record(durationMilliseconds, - new("tool", LastTool), new("outcome", outcome), new("reason", LastToolError)); - } - - public void Finish(string outcome, string? failureCode = null, Exception? exception = null) - { - if (_finished) - { - return; - } - _finished = true; - string reason = failureCode ?? _failureCode ?? "none"; - _activity?.SetTag("assistant.outcome", outcome); - _activity?.SetTag("assistant.failure.reason", reason); - _activity?.SetTag("assistant.stage", Stage); - _activity?.SetTag("assistant.model", Model); - _activity?.SetTag("assistant.provider.requests", ProviderRequests); - _activity?.SetTag("assistant.tool.calls", ToolCalls); - if (outcome == "failed") - { - _activity?.SetStatus(ActivityStatusCode.Error, reason); - } - - AppDiagnostics.AssistantTurnDuration.Record(ElapsedMilliseconds, - new("outcome", outcome), new("reason", reason), new("stage", Stage)); - - // Include correlation in the message as well as the scope: the production console - // formatter does not render scope properties, and streaming errors retain HTTP 200. - var level = outcome == "failed" ? exception is null ? LogLevel.Warning : LogLevel.Error : LogLevel.Information; - _logger.Log(level, - "Assistant turn {AssistantTurnId} {Outcome}: reason={FailureReason} stage={Stage} duration={DurationMs} ms first_text={FirstTextDurationMs} ms organization={OrganizationId} conversation={ConversationId} request={RequestId} trace={TraceId} model={Model} provider_requests={ProviderRequests} tool_rounds={ToolRounds} tool_calls={ToolCalls} tool_failures={ToolFailures} last_tool={LastTool} last_tool_error={LastToolError} malformed_retries={MalformedResponseRetries} generation={ProviderGenerationId} provider_model={ProviderModel} provider={ProviderName} status={ProviderStatusCode} finish={ProviderFinishReason} usage_received={ProviderUsageReceived} reasoning_tokens={ReasoningTokens} exception_type={ExceptionType} exception_stack={ExceptionStackTrace}", - TurnId, outcome, reason, Stage, ElapsedMilliseconds, _firstTextDuration, OrganizationId, ConversationId, RequestId, TraceId, - Model, ProviderRequests, ToolRounds, ToolCalls, ToolFailures, LastTool, LastToolError, MalformedResponseRetries, - Provider?.GenerationId, Provider?.Model, Provider?.ProviderName, Provider?.StatusCode, Provider?.FinishReason, - Provider?.UsageReceived, Provider?.ReasoningTokens, exception?.GetType().FullName, exception?.StackTrace); - } - - private double ElapsedMilliseconds => _timeProvider.GetElapsedTime(_started).TotalMilliseconds; - - public void Dispose() - { - _scope?.Dispose(); - _activity?.Dispose(); - } - - private static string GetToolName(string name) => name switch - { - "get_event" or "get_stack" or "get_project_setup" or "get_stack_events" or "list_projects" or "search_stacks" - or "update_stack_status" or "snooze_stack" or "set_stack_critical" or "add_stack_reference_link" or "remove_stack_reference_link" => name, - _ => "unknown" - }; - - private static string GetToolErrorCode(string? code) => code switch - { - McpErrorCodes.ContextMismatch or McpErrorCodes.ContextRequired or McpErrorCodes.Forbidden or McpErrorCodes.InvalidClientPlatform - or McpErrorCodes.InvalidCursor or McpErrorCodes.InvalidDetailSize or McpErrorCodes.InvalidFilter or McpErrorCodes.InvalidGroupBy - or McpErrorCodes.InvalidId or McpErrorCodes.InvalidInterval or McpErrorCodes.InvalidLimit or McpErrorCodes.InvalidReferenceUrl - or McpErrorCodes.InvalidSnooze or McpErrorCodes.InvalidSort or McpErrorCodes.InvalidStatus or McpErrorCodes.InvalidTimeRange - or McpErrorCodes.InvalidVersion or McpErrorCodes.NotAccessible or McpErrorCodes.NotFound or McpErrorCodes.QueryFailed - or McpErrorCodes.UnknownFilterField or "tool_call_limit_reached" or "project_search_limit_reached" => code, - _ => "tool_error" - }; -} diff --git a/src/Exceptionless.Web/appsettings.yml b/src/Exceptionless.Web/appsettings.yml index 21f26aa2a6..785c089916 100644 --- a/src/Exceptionless.Web/appsettings.yml +++ b/src/Exceptionless.Web/appsettings.yml @@ -9,7 +9,6 @@ Serilog: #Exceptionless.Core.Repositories.StackRepository: Verbose #Exceptionless.Core.Repositories: Verbose Exceptionless.Web.Program: Information - Exceptionless.Web.Assistant: Information Exceptionless.Web.Security.ApiKeyAuthenticationHandler: Warning Foundatio.Metrics: Warning Foundatio.Utility.ScheduledTimer: Warning @@ -32,7 +31,7 @@ Serilog: Assistant: Endpoint: https://openrouter.ai/api/v1/chat/completions - Model: "deepseek/deepseek-v4.1-flash" + Model: "~deepseek/deepseek-v4-flash-latest" ApiKey: Apm: diff --git a/tests/Exceptionless.Tests/Assistant/AssistantDiagnosticsTests.cs b/tests/Exceptionless.Tests/Assistant/AssistantDiagnosticsTests.cs deleted file mode 100644 index acaa36139a..0000000000 --- a/tests/Exceptionless.Tests/Assistant/AssistantDiagnosticsTests.cs +++ /dev/null @@ -1,377 +0,0 @@ -using System.Collections.Concurrent; -using System.Diagnostics; -using System.Diagnostics.Metrics; -using System.Net; -using System.Text.Json; -using Exceptionless.Core; -using Exceptionless.Web.Api.Endpoints; -using Exceptionless.Web.Assistant; -using Foundatio.Caching; -using Microsoft.AspNetCore.Http; -using Microsoft.Extensions.Configuration; -using Microsoft.Extensions.DependencyInjection; -using Microsoft.Extensions.Hosting; -using Microsoft.Extensions.Logging; -using Microsoft.Extensions.Logging.Abstractions; -using Microsoft.Extensions.Time.Testing; -using OpenTelemetry.Trace; -using Xunit; - -namespace Exceptionless.Tests.Assistant; - -public sealed class AssistantDiagnosticsTests -{ - [Fact] - public void AddApm_ExieActivitySource_CreatesExportableSpans() - { - // The APM source file is linked into both Web and Job. Select the Web copy - // explicitly to exercise its real registration without ambiguous type references. - var assembly = typeof(AssistantService).Assembly; - var configType = assembly.GetType("OpenTelemetry.ApmConfig", throwOnError: true)!; - var config = Activator.CreateInstance(configType, new ConfigurationBuilder().Build(), "test", "1.0", false); - var builder = new HostBuilder(); - assembly.GetType("OpenTelemetry.ApmExtensions", throwOnError: true)! - .GetMethod("AddApm")!.Invoke(null, [builder, config]); - using var host = builder.Build(); - _ = host.Services.GetRequiredService(); - - using var activity = AppDiagnostics.AssistantActivitySource.StartActivity("assistant.turn"); - - Assert.NotNull(activity); - Assert.True(activity.IsAllDataRequested); - using var pipelineActivity = AppDiagnostics.StartActivity("Event Pipeline"); - Assert.Null(pipelineActivity); - } - - [Theory] - [InlineData("empty_response")] - [InlineData("output_limit")] - [InlineData("malformed_response")] - [InlineData("tool_round_limit")] - [InlineData("usage_limit")] - public async Task WriteResponseAsync_StreamedError_RecordsCorrelatedFailureWithoutChangingResponse(string reason) - { - var logger = new RecordingAssistantLogger(); - var time = new FakeTimeProvider(); - using var diagnostics = new AssistantTurnDiagnostics(logger, time, "organization-id", "conversation-id", "request-id"); - using var cache = new InMemoryCacheClient(); - var recorder = new RecordingAssistantUsageRecorder(); - var context = CreateHttpContext(); - time.Advance(TimeSpan.FromSeconds(12)); - - await AssistantEndpoints.WriteResponseAsync(context, - StreamEvents([AssistantStreamEvent.Error("private error detail", reason), AssistantStreamEvent.Done()]), - CreateUsageService(cache, recorder), "organization-id", diagnostics, TestContext.Current.CancellationToken); - - var entry = Assert.Single(logger.Entries); - Assert.Equal(LogLevel.Warning, entry.Level); - Assert.Equal("failed", entry.Properties["Outcome"]); - Assert.Equal(reason, entry.Properties["FailureReason"]); - Assert.Equal(12_000d, entry.Properties["DurationMs"]); - Assert.Equal("organization-id", entry.Properties["OrganizationId"]); - Assert.Equal("conversation-id", entry.Properties["ConversationId"]); - Assert.Equal("request-id", entry.Properties["RequestId"]); - Assert.Equal(diagnostics.TurnId, entry.Properties["AssistantTurnId"]); - Assert.DoesNotContain("private error detail", entry.Message); - Assert.Equal(1, Assert.Single(recorder.Records).Increment.Failed); - - Assert.Equal(StatusCodes.Status200OK, context.Response.StatusCode); - var events = await ReadEventsAsync(context); - Assert.Equal("private error detail", events[0].GetProperty("message").GetString()); - Assert.False(events[0].TryGetProperty("failure_code", out _)); - Assert.False(events[0].TryGetProperty("FailureCode", out _)); - Assert.Equal("done", events[1].GetProperty("type").GetString()); - } - - [Theory] - [InlineData(false, true, "provider_stream", "failed", "turn_timeout")] - [InlineData(false, false, "provider_stream", "failed", "provider_timeout")] - [InlineData(true, true, "provider_stream", "cancelled", "client_disconnected")] - [InlineData(false, false, "tool_execution", "failed", "operation_cancelled")] - public async Task WriteResponseAsync_Cancellation_DistinguishesClientAndServer( - bool clientDisconnected, bool deadlineExpired, string stage, string outcome, string reason) - { - var logger = new RecordingAssistantLogger(); - using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); - diagnostics.Stage = stage; - using var cache = new InMemoryCacheClient(); - var recorder = new RecordingAssistantUsageRecorder(); - var context = CreateHttpContext(); - using var cancellation = new CancellationTokenSource(); - if (deadlineExpired) - await cancellation.CancelAsync(); - if (clientDisconnected) - context.RequestAborted = cancellation.Token; - - await AssistantEndpoints.WriteResponseAsync(context, - StreamEvents([], new OperationCanceledException("private provider detail")), - CreateUsageService(cache, recorder), "organization-id", diagnostics, cancellation.Token); - - var entry = Assert.Single(logger.Entries); - Assert.Equal(outcome, entry.Properties["Outcome"]); - Assert.Equal(reason, entry.Properties["FailureReason"]); - Assert.Equal(stage, entry.Properties["Stage"]); - Assert.DoesNotContain("private provider detail", entry.Message); - var usage = Assert.Single(recorder.Records).Increment; - Assert.Equal(clientDisconnected ? 0 : 1, usage.Failed); - Assert.Equal(clientDisconnected ? 1 : 0, usage.Cancelled); - var events = await ReadEventsAsync(context); - if (clientDisconnected) - Assert.Empty(events); - else - Assert.Equal("Exie took too long to complete this response. Try narrowing the question.", Assert.Single(events).GetProperty("message").GetString()); - } - - [Fact] - public async Task WriteResponseAsync_ProviderException_RecordsReasonWithoutLoggingProviderMessage() - { - var logger = new RecordingAssistantLogger(); - using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); - using var cache = new InMemoryCacheClient(); - var recorder = new RecordingAssistantUsageRecorder(); - var context = CreateHttpContext(); - await AssistantEndpoints.WriteResponseAsync(context, - StreamEvents([], new AssistantProviderException("private provider detail") { FailureCode = "provider_http_error" }), - CreateUsageService(cache, recorder), "organization-id", diagnostics, TestContext.Current.CancellationToken); - - var entry = Assert.Single(logger.Entries); - Assert.Equal(LogLevel.Error, entry.Level); - Assert.Equal("provider_http_error", entry.Properties["FailureReason"]); - Assert.Equal(typeof(AssistantProviderException).FullName, entry.Properties["ExceptionType"]); - Assert.DoesNotContain("private provider detail", entry.Message); - Assert.Equal(1, Assert.Single(recorder.Records).Increment.Failed); - } - - [Fact] - public async Task WriteResponseAsync_Success_RecordsCompletionAndFirstTextWithoutLoggingAnswer() - { - var logger = new RecordingAssistantLogger(); - var time = new FakeTimeProvider(); - using var diagnostics = new AssistantTurnDiagnostics(logger, time, "organization-id", "conversation-id", "request-id"); - using var cache = new InMemoryCacheClient(); - var recorder = new RecordingAssistantUsageRecorder(); - var context = CreateHttpContext(); - time.Advance(TimeSpan.FromSeconds(3)); - await AssistantEndpoints.WriteResponseAsync(context, - StreamEvents([AssistantStreamEvent.TextDelta("private answer"), AssistantStreamEvent.Done()]), - CreateUsageService(cache, recorder), "organization-id", diagnostics, TestContext.Current.CancellationToken); - - var entry = Assert.Single(logger.Entries); - Assert.Equal("completed", entry.Properties["Outcome"]); - Assert.Equal("none", entry.Properties["FailureReason"]); - Assert.Equal(3000d, entry.Properties["FirstTextDurationMs"]); - Assert.DoesNotContain("private answer", entry.Message); - Assert.Equal(1, Assert.Single(recorder.Records).Increment.Completed); - } - - [Fact] - public void Finish_FailedTurn_RecordsErrorSpanAndBoundedMetricTagsOnce() - { - var activities = new ConcurrentQueue(); - var activitySource = AppDiagnostics.AssistantActivitySource; - using var listener = new ActivityListener - { - ShouldListenTo = source => source == activitySource, - Sample = (ref ActivityCreationOptions _) => ActivitySamplingResult.AllDataAndRecorded, - SampleUsingParentId = (ref ActivityCreationOptions _) => ActivitySamplingResult.AllDataAndRecorded, - ActivityStopped = activity => activities.Enqueue(activity) - }; - ActivitySource.AddActivityListener(listener); - var measurements = new List>(); - string? turnId = null; - using var meterListener = new MeterListener - { - InstrumentPublished = (instrument, current) => - { - if (instrument.Name == "ex.assistant.turn.duration") - current.EnableMeasurementEvents(instrument); - } - }; - meterListener.SetMeasurementEventCallback((_, _, tags, _) => - { - if (Activity.Current?.GetTagItem("assistant.turn.id") as string == turnId) - measurements.Add(tags.ToArray().ToDictionary(tag => tag.Key, tag => tag.Value)); - }); - meterListener.Start(); - var logger = new RecordingAssistantLogger(); - using (var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id")) - { - turnId = diagnostics.TurnId; - diagnostics.Stage = "provider_stream"; - diagnostics.Finish("failed", "turn_timeout"); - diagnostics.Finish("completed"); - } - - var measurement = Assert.Single(measurements); - Assert.Equal(3, measurement.Count); - Assert.Equal("failed", measurement["outcome"]); - Assert.Equal("turn_timeout", measurement["reason"]); - Assert.Equal("provider_stream", measurement["stage"]); - var activity = Assert.Single(activities, activity => activity.GetTagItem("assistant.turn.id") as string == turnId); - Assert.Equal(ActivityStatusCode.Error, activity.Status); - Assert.Equal("turn_timeout", activity.StatusDescription); - Assert.Single(logger.Entries); - } - - [Theory] - [InlineData("client", "cancelled")] - [InlineData("turn", "turn_timeout")] - [InlineData("provider", "provider_timeout")] - public void RecordException_CancellationSource_RecordsExpectedProviderOutcome(string source, string expectedOutcome) - { - using var requestAborted = new CancellationTokenSource(); - using var deadline = CancellationTokenSource.CreateLinkedTokenSource(requestAborted.Token); - var logger = new RecordingAssistantLogger(); - using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id", requestAborted.Token); - using (var provider = diagnostics.StartProviderRequest(100, true, deadline.Token)) - { - if (source == "client") - { - requestAborted.Cancel(); - } - else if (source == "turn") - { - deadline.Cancel(); - } - provider.RecordException(new OperationCanceledException("private cancellation detail")); - } - - var entry = Assert.Single(logger.Entries); - Assert.Equal(expectedOutcome, entry.Properties["ProviderOutcome"]); - Assert.Equal(source == "client" ? LogLevel.Information : LogLevel.Warning, entry.Level); - Assert.DoesNotContain("private cancellation detail", entry.Message); - } - - [Fact] - public void ObserveChunk_OutputLimit_RecordsGenerationAndReasoningWithoutContent() - { - var logger = new RecordingAssistantLogger(); - using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); - diagnostics.Model = "configured-model"; - using var provider = diagnostics.StartProviderRequest(1000, true, TestContext.Current.CancellationToken); - using var response = new HttpResponseMessage(HttpStatusCode.OK); - response.Headers.Add("X-Generation-Id", "gen-header"); - provider.ObserveResponse(response); - using var document = JsonDocument.Parse(""" - {"id":"gen-stream","model":"resolved-model","provider":"Example Provider", - "choices":[{"delta":{"reasoning":"private reasoning"},"finish_reason":"length"}], - "usage":{"prompt_tokens":100,"completion_tokens":2048,"completion_tokens_details":{"reasoning_tokens":2048}}} - """); - provider.ObserveChunk(document.RootElement); - provider.Complete(0, 0, true); - - Assert.Equal("gen-stream", provider.GenerationId); - Assert.Equal("length", provider.FinishReason); - Assert.Equal(2048, provider.ReasoningTokens); - var entry = Assert.Single(logger.Entries); - Assert.Equal(LogLevel.Warning, entry.Level); - Assert.Equal("output_limit", entry.Properties["ProviderOutcome"]); - Assert.Equal("resolved-model", entry.Properties["ProviderModel"]); - Assert.Equal(100L, entry.Properties["PromptTokens"]); - Assert.Equal(2048L, entry.Properties["CompletionTokens"]); - Assert.DoesNotContain("private reasoning", entry.Message); - } - - [Fact] - public void ObserveChunk_UnexpectedMetadata_DoesNotThrowOrLogUnboundedValues() - { - var logger = new RecordingAssistantLogger(); - using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); - using var provider = diagnostics.StartProviderRequest(1000, true, TestContext.Current.CancellationToken); - using var document = JsonDocument.Parse(""" - {"id":"private\nvalue","model":{"unexpected":true},"provider":null, - "choices":[{"finish_reason":"unexpected-provider-string"}], - "usage":{"completion_tokens_details":{"reasoning_tokens":"not-a-number"}}} - """); - provider.ObserveChunk(document.RootElement); - provider.Complete(10, 0, true); - - Assert.Null(provider.GenerationId); - Assert.Null(provider.Model); - Assert.Null(provider.ReasoningTokens); - Assert.Equal("unknown", provider.FinishReason); - Assert.DoesNotContain("private", Assert.Single(logger.Entries).Message); - } - - [Fact] - public void RecordToolResult_FailedTool_RecordsCodeWithoutArgumentsOrResult() - { - var logger = new RecordingAssistantLogger(); - using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); - diagnostics.StartTool("search_stacks"); - diagnostics.RecordToolResult("""{"ok":false,"error":{"code":"invalid_filter","message":"private filter"}}""", 100); - diagnostics.StartTool("private-hallucinated-tool-name"); - diagnostics.RecordToolResult("""{"ok":false,"error":{"code":"private-error-code","message":"private details"}}""", 100); - diagnostics.Finish("completed"); - - Assert.Equal(2, diagnostics.ToolFailures); - Assert.Equal("unknown", diagnostics.LastTool); - Assert.Equal("tool_error", diagnostics.LastToolError); - Assert.Equal("invalid_filter", logger.Entries[0].Properties["ToolErrorCode"]); - Assert.All(logger.Entries, entry => Assert.DoesNotContain("private", entry.Message)); - Assert.Equal("completed", logger.Entries[^1].Properties["Outcome"]); - } - - [Theory] - [InlineData("null")] - [InlineData("[]")] - [InlineData("\"text\"")] - public void RecordToolResult_NonObjectResult_DoesNotInterruptTheTurn(string result) - { - var logger = new RecordingAssistantLogger(); - using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); - diagnostics.StartTool("get_event"); - diagnostics.RecordToolResult(result, 100); - - Assert.Equal(0, diagnostics.ToolFailures); - Assert.Empty(logger.Entries); - } - - private static DefaultHttpContext CreateHttpContext() - { - var context = new DefaultHttpContext(); - context.Response.Body = new MemoryStream(); - return context; - } - - private static async Task ReadEventsAsync(HttpContext context) - { - context.Response.Body.Position = 0; - using var reader = new StreamReader(context.Response.Body, leaveOpen: true); - string content = await reader.ReadToEndAsync(TestContext.Current.CancellationToken); - return content.Split('\n', StringSplitOptions.RemoveEmptyEntries).Select(line => - { - using var document = JsonDocument.Parse(line); - return document.RootElement.Clone(); - }).ToArray(); - } - - private static AssistantUsageService CreateUsageService(ICacheClient cache, RecordingAssistantUsageRecorder recorder) - { - var options = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() - .AddInMemoryCollection(new Dictionary { ["BaseURL"] = "https://localhost" }) - .Build()); - return new AssistantUsageService(cache, null!, recorder, options, TimeProvider.System, NullLogger.Instance); - } - - private static async IAsyncEnumerable StreamEvents(AssistantStreamEvent[] events, Exception? exception = null) - { - await Task.Yield(); - if (exception is not null) - throw exception; - foreach (var item in events) - yield return item; - } -} - -internal 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(new AssistantLogEntry(logLevel, formatter(state, exception), - ((IEnumerable>)(object)state!).ToDictionary(property => property.Key, property => property.Value))); -} - -internal sealed record AssistantLogEntry(LogLevel Level, string Message, Dictionary Properties); diff --git a/tests/Exceptionless.Tests/Assistant/AssistantProviderTelemetryTests.cs b/tests/Exceptionless.Tests/Assistant/AssistantProviderTelemetryTests.cs deleted file mode 100644 index e6ca5e6602..0000000000 --- a/tests/Exceptionless.Tests/Assistant/AssistantProviderTelemetryTests.cs +++ /dev/null @@ -1,203 +0,0 @@ -using System.Diagnostics; -using System.Net; -using System.Text.Json; -using Exceptionless.Insulation.Security; -using Exceptionless.Models; -using Exceptionless.Serializer; -using Exceptionless.Web.Assistant; -using Microsoft.Extensions.Logging; -using Microsoft.Extensions.Time.Testing; -using Serilog; -using Serilog.Extensions.Logging; -using Serilog.Sinks.Exceptionless; -using Xunit; - -namespace Exceptionless.Tests.Assistant; - -public sealed class AssistantProviderTelemetryTests -{ - [Fact] - public void Capture_ValidationError_PreservesParameterLocationWithoutInput() - { - using var error = JsonDocument.Parse(""" - {"detail":[{"type":"missing","loc":["body","messages",2,"reasoning_content"], - "msg":"Field required","input":{"content":"private-input-canary"}}]} - """); - var sanitizer = new AssistantProviderErrorDetails(default, null); - - using var captured = JsonDocument.Parse(JsonSerializer.Serialize(sanitizer.Capture(error.RootElement))); - var detail = captured.RootElement.GetProperty("detail")[0]; - Assert.Equal(2, detail.GetProperty("loc")[2].GetInt32()); - Assert.Equal("reasoning_content", detail.GetProperty("loc")[3].GetString()); - Assert.Equal("Field required", detail.GetProperty("msg").GetString()); - Assert.False(detail.TryGetProperty("input", out _)); - } - - [Fact] - public void ObserveChunk_RoutingRestriction_RecordsExclusionReasonsAndLegacyProviderCode() - { - var logger = new RecordingAssistantLogger(); - using var turn = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); - using var provider = turn.StartProviderRequest(100, true, TestContext.Current.CancellationToken); - using var document = JsonDocument.Parse(""" - {"error":{"code":"404","message":"No eligible providers","metadata":{ - "provider_error_code":"no_endpoints","input_endpoint_count":2, - "failed_routing_step":"Filter by Guardrails", - "ineligibility_reasons":[{"reason":"paid-model-training-violation-by-account","endpoint_count":2}], - "routing_funnel":[{"step":"Initial Endpoints","endpoint_count":7}] - }}} - """); - provider.ObserveChunk(document.RootElement); - provider.RecordException(new AssistantProviderException("Provider returned error")); - - var entry = Assert.Single(logger.Entries); - Assert.Equal("404", entry.Properties["ProviderErrorCode"]); - Assert.Equal("no_endpoints", entry.Properties["UpstreamErrorCode"]); - string details = Assert.IsType(entry.Properties["ProviderErrorDetails"]); - Assert.Contains("paid-model-training-violation-by-account", details); - Assert.Contains("Filter by Guardrails", details); - Assert.Contains("Initial Endpoints", details); - } - - [Theory] - [InlineData("private-body-canary", "invalid_json")] - [InlineData("{\"error\":\"private-body-canary", "invalid_json")] - [InlineData("[]", "invalid_shape")] - [InlineData("", "empty")] - public async Task ObserveErrorResponseAsync_InvalidBody_RetainsStatusWithoutLeakingBody(string body, string expectedState) - { - var logger = new RecordingAssistantLogger(); - using var turn = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); - using var provider = turn.StartProviderRequest(100, true, TestContext.Current.CancellationToken); - using var response = new HttpResponseMessage(HttpStatusCode.BadGateway) { Content = new StringContent(body) }; - provider.ObserveResponse(response); - await provider.ObserveErrorResponseAsync(response, TestContext.Current.CancellationToken); - provider.RecordException(new AssistantProviderException("Rejected") { FailureCode = "provider_http_error" }); - - var entry = Assert.Single(logger.Entries); - Assert.Equal(502, entry.Properties["ProviderStatusCode"]); - Assert.Equal(expectedState, entry.Properties["ProviderErrorBodyState"]); - Assert.DoesNotContain("private-body-canary", entry.Message); - } - - [Fact] - public async Task ObserveErrorResponseAsync_OversizedBody_ReportsTruncation() - { - var logger = new RecordingAssistantLogger(); - using var turn = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); - using var provider = turn.StartProviderRequest(100, true, TestContext.Current.CancellationToken); - using var response = new HttpResponseMessage(HttpStatusCode.BadGateway) { Content = new StringContent(new string('x', 100_000)) }; - provider.ObserveResponse(response); - await provider.ObserveErrorResponseAsync(response, TestContext.Current.CancellationToken); - provider.RecordException(new AssistantProviderException("Rejected") { FailureCode = "provider_http_error" }); - - var entry = Assert.Single(logger.Entries); - Assert.Equal("truncated", entry.Properties["ProviderErrorBodyState"]); - Assert.Equal(true, entry.Properties["ProviderDetailsTruncated"]); - Assert.Null(entry.Properties["ProviderErrorDetails"]); - } - - [Fact] - public void ObserveChunk_StreamFailure_RecordsProgressAndTiming() - { - var logger = new RecordingAssistantLogger(); - var time = new FakeTimeProvider(); - using var turn = new AssistantTurnDiagnostics(logger, time, "organization-id", "conversation-id", "request-id"); - using var provider = turn.StartProviderRequest(100, true, TestContext.Current.CancellationToken); - using var response = new HttpResponseMessage(HttpStatusCode.OK); - time.Advance(TimeSpan.FromSeconds(1)); - provider.ObserveResponse(response); - using var chunk = JsonDocument.Parse("""{"id":"gen-progress","choices":[{"delta":{"content":"private output"}}]}"""); - time.Advance(TimeSpan.FromSeconds(2)); - provider.ObserveChunk(chunk.RootElement); - time.Advance(TimeSpan.FromSeconds(7)); - provider.RecordException(new IOException("private exception message"), 14, 1); - - var entry = Assert.Single(logger.Entries); - Assert.Equal(1000d, entry.Properties["HeadersDurationMs"]); - Assert.Equal(3000d, entry.Properties["FirstChunkDurationMs"]); - Assert.Equal(3000d, entry.Properties["LastChunkDurationMs"]); - Assert.Equal(10_000d, entry.Properties["DurationMs"]); - Assert.Equal(1, entry.Properties["ChunkCount"]); - Assert.Equal(14, entry.Properties["OutputCharacters"]); - Assert.Equal(1, entry.Properties["ToolCalls"]); - Assert.False(Assert.IsType(entry.Properties["ReceivedDone"])); - Assert.DoesNotContain("private", entry.Message); - } - - [Fact] - public void Capture_ErrorMessages_RedactsRequestValuesAndBoundsText() - { - using var request = JsonDocument.Parse(""" - [{"role":"user","content":"private-prompt-canary"}, - {"role":"assistant","reasoning":"private-reasoning-canary","tool_calls":[{"function":{"arguments":"{\"filter\":\"private-filter-canary\"}"}}]}, - {"role":"tool","content":"{\"message\":\"private-result-canary\"}"}] - """); - using var error = JsonDocument.Parse(JsonSerializer.Serialize(new - { - message = "Missing reasoning_content. private-prompt-canary private-reasoning-canary private-filter-canary private-result-canary sk-or-v1-provider-key-canary api-key-canary https://example.test?token=canary", - metadata = new { raw = new { error = new { message = new string('x', 10_000) } } }, - messages = new[] { new { content = "other-prompt-canary" } } - })); - var sanitizer = new AssistantProviderErrorDetails(request.RootElement, "api-key-canary"); - string result = JsonSerializer.Serialize(sanitizer.Capture(error.RootElement)); - - Assert.Contains("Missing reasoning_content", result); - Assert.DoesNotContain("canary", result); - Assert.True(sanitizer.Redacted); - Assert.True(sanitizer.Truncated); - Assert.True(result.Length < 4096); - } - - [Fact] - public void RecordException_ExceptionlessSink_PreservesDiagnosticFieldsAndOmitsSecrets() - { - Event? submittedEvent = null; - using var client = new ExceptionlessClient(configuration => - { - configuration.ApiKey = "00000000000000000000000000000000"; - configuration.UseInMemoryStorage(); - }); - client.SubmittingEvent += (_, args) => - { - submittedEvent = args.Event; - args.Cancel = true; - }; - using var serilog = new LoggerConfiguration() - .ApplySensitiveDataLogging() - .WriteTo.Sink(new ExceptionlessSink(client: client)) - .CreateLogger(); - using var loggerFactory = new SerilogLoggerFactory(serilog, dispose: false); - using var parent = new Activity("http-request").Start(); - using var turn = new AssistantTurnDiagnostics(loggerFactory.CreateLogger(), TimeProvider.System, - "organization-id", "conversation-id", "request-id"); - using var provider = turn.StartProviderRequest(100, true, TestContext.Current.CancellationToken); - provider.ObserveRequest(new Dictionary - { - ["messages"] = new[] { new { role = "user", content = "private-prompt-canary" } } - }, "private-api-key-canary"); - using var response = new HttpResponseMessage(HttpStatusCode.OK); - provider.ObserveResponse(response); - using var document = JsonDocument.Parse(""" - {"id":"gen-sink-test","provider":"Fireworks","error":{"code":429,"message":"Provider returned error","metadata":{ - "error_type":"rate_limit_exceeded","provider_code":"rate_limited", - "raw":{"error":{"message":"Missing reasoning_content: private-prompt-canary private-api-key-canary"},"request":{"content":"other-private-canary"}} - }}} - """); - provider.ObserveChunk(document.RootElement); - provider.RecordException(new AssistantProviderException("private-exception-canary")); - - Assert.NotNull(submittedEvent); - Assert.Contains("ProviderErrorDetails", submittedEvent.Data.Keys); - Assert.Contains("ProviderErrorCode", submittedEvent.Data.Keys); - Assert.Contains("AssistantTurnId", submittedEvent.Data.Keys); - string serialized = new DefaultJsonSerializer().Serialize(submittedEvent); - Assert.Contains("ProviderErrorDetails", serialized); - Assert.Contains("ProviderErrorCode", serialized); - Assert.Contains("rate_limit_exceeded", serialized); - Assert.Contains("Missing reasoning_content", serialized); - Assert.Contains("gen-sink-test", serialized); - Assert.Contains(turn.TurnId, serialized); - Assert.DoesNotContain("canary", serialized); - } -} diff --git a/tests/Exceptionless.Tests/Assistant/AssistantQualityEvaluationTests.cs b/tests/Exceptionless.Tests/Assistant/AssistantQualityEvaluationTests.cs index f166fa49e6..949198549d 100644 --- a/tests/Exceptionless.Tests/Assistant/AssistantQualityEvaluationTests.cs +++ b/tests/Exceptionless.Tests/Assistant/AssistantQualityEvaluationTests.cs @@ -1,6 +1,5 @@ using System.Net.Http.Headers; using System.Net.Http.Json; -using System.Text; using System.Text.Json; using Exceptionless.Core; using Exceptionless.Core.Models; @@ -51,7 +50,7 @@ protected override async Task ResetDataAsync() [Fact(Skip = "Set RUN_ASSISTANT_EVALS=true to run the billable assistant quality gate.", SkipUnless = nameof(EvaluationsEnabled))] [Trait("Category", "AssistantEvaluation")] - public async Task CurrentEvent_MeetsToolEfficiencyAndAnswerQualityGate() + public async Task ProductionScenarios_MeetToolEfficiencyAndAnswerQualityGate() { RequireEvaluationConfiguration(); @@ -64,13 +63,6 @@ public async Task CurrentEvent_MeetsToolEfficiencyAndAnswerQualityGate() Assert.DoesNotContain("get_stack", currentPage.ToolCalls); Assert.DoesNotContain("list_projects", currentPage.ToolCalls); Assert.DoesNotContain("search_stacks", currentPage.ToolCalls); - } - - [Fact(Skip = "Set RUN_ASSISTANT_EVALS=true to run the billable assistant quality gate.", SkipUnless = nameof(EvaluationsEnabled))] - [Trait("Category", "AssistantEvaluation")] - public async Task ProjectTopErrors_MeetsToolEfficiencyAndAnswerQualityGate() - { - RequireEvaluationConfiguration(); var projectTopErrors = await SendAssistantTurnAsync( "What are the top errors in this project in the last 24 hours? Link each result.", @@ -80,13 +72,6 @@ public async Task ProjectTopErrors_MeetsToolEfficiencyAndAnswerQualityGate() Assert.Equal(1, projectTopErrors.ToolCalls.Count(call => call == "search_stacks")); Assert.DoesNotContain("list_projects", projectTopErrors.ToolCalls); Assert.Contains("/next/stack/", projectTopErrors.Text, StringComparison.Ordinal); - } - - [Fact(Skip = "Set RUN_ASSISTANT_EVALS=true to run the billable assistant quality gate.", SkipUnless = nameof(EvaluationsEnabled))] - [Trait("Category", "AssistantEvaluation")] - public async Task OrganizationTopErrors_MeetsToolEfficiencyAndAnswerQualityGate() - { - RequireEvaluationConfiguration(); var organizationTopErrors = await SendAssistantTurnAsync( "Across all projects in this organization, what are the top errors in the last 24 hours? Link each result.", @@ -96,13 +81,6 @@ public async Task OrganizationTopErrors_MeetsToolEfficiencyAndAnswerQualityGate( Assert.Equal(1, organizationTopErrors.ToolCalls.Count(call => call == "list_projects")); Assert.InRange(organizationTopErrors.ToolCalls.Count(call => call == "search_stacks"), 1, AssistantLimits.MaximumProjectsPerTurn); Assert.Contains("/next/stack/", organizationTopErrors.Text, StringComparison.Ordinal); - } - - [Fact(Skip = "Set RUN_ASSISTANT_EVALS=true to run the billable assistant quality gate.", SkipUnless = nameof(EvaluationsEnabled))] - [Trait("Category", "AssistantEvaluation")] - public async Task ClientSetup_MeetsToolEfficiencyAndAnswerQualityGate() - { - RequireEvaluationConfiguration(); var clientSetup = await SendAssistantTurnAsync( "How do I configure this project to start sending events?", @@ -126,8 +104,7 @@ private async Task SendAssistantTurnAsync(string prompt, string { using var client = CreateHttpClient(); using var request = new HttpRequestMessage(HttpMethod.Post, "assistant/chat"); - request.Headers.Authorization = new AuthenticationHeaderValue("Basic", Convert.ToBase64String( - Encoding.UTF8.GetBytes($"{SampleDataService.TEST_ORG_USER_EMAIL}:{SampleDataService.TEST_ORG_USER_PASSWORD}"))); + request.Headers.Authorization = new AuthenticationHeaderValue("Bearer", SampleDataService.TEST_USER_API_KEY); request.Content = JsonContent.Create(new { conversation_id = Guid.NewGuid().ToString("N"), diff --git a/tests/Exceptionless.Tests/Assistant/AssistantServiceProviderDiagnosticsTests.cs b/tests/Exceptionless.Tests/Assistant/AssistantServiceProviderDiagnosticsTests.cs deleted file mode 100644 index 8ef4b1bee6..0000000000 --- a/tests/Exceptionless.Tests/Assistant/AssistantServiceProviderDiagnosticsTests.cs +++ /dev/null @@ -1,120 +0,0 @@ -using System.Net; -using System.Text; -using System.Text.Json; -using Exceptionless.Core; -using Exceptionless.Web.Assistant; -using Microsoft.Extensions.Configuration; -using Xunit; - -namespace Exceptionless.Tests.Assistant; - -public sealed partial class AssistantServiceTests -{ - [Theory] - [InlineData(false)] - [InlineData(true)] - public async Task StreamAsync_UpstreamError_PreservesCauseAndCorrelationWithoutRequestContent(bool streaming) - { - const string privatePrompt = "private-prompt-canary"; - const string apiKey = "api-key-canary"; - string error = JsonSerializer.Serialize(new - { - id = "gen-failed-request", - model = "resolved-model", - provider = "Fireworks", - error = new - { - code = 429, - message = "Provider returned error", - metadata = new - { - error_type = "rate_limit_exceeded", - provider_code = "invalid_request_error", - limit_source = "upstream_provider_shared_pool", - raw = JsonSerializer.Serialize(new - { - error = new - { - type = "invalid_request_error", - message = $"Missing reasoning_content at messages[2]. Input: {privatePrompt}. Authorization: Bearer {apiKey}", - param = "messages[2].reasoning_content" - }, - request = new { messages = new[] { new { content = "unrelated-private-content-canary" } } } - }), - flagged_input = "flagged-content-canary" - } - }, - choices = new[] { new { delta = new { content = "" }, finish_reason = "error", native_finish_reason = "upstream_error" } }, - openrouter_metadata = new - { - attempt = 2, - strategy = "fallback", - attempts = new[] { new { provider = "Fireworks", model = "resolved-model", status = 429 } }, - pipeline = new[] { new { data = new { prompt = "pipeline-content-canary" } } } - } - }); - var handler = new ProviderErrorHandler(streaming, error); - var options = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() - .AddInMemoryCollection(new Dictionary { ["BaseURL"] = "https://localhost", ["Assistant:ApiKey"] = apiKey }) - .Build()); - var logger = new RecordingAssistantLogger(); - using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); - var service = CreateAssistantService(handler, options, logger: logger); - - var exception = await Assert.ThrowsAsync(async () => - { - await foreach (var _ in service.StreamAsync( - new AssistantChatRequest([new AssistantChatMessage("user", privatePrompt)], OrganizationId: "organization-id"), - "user-id", CreatePlanOptions(), diagnostics, TestContext.Current.CancellationToken)) - { - } - }); - diagnostics.Finish("failed", exception.FailureCode, exception); - - var entry = Assert.Single(logger.Entries, entry => entry.Properties.ContainsKey("ProviderOutcome")); - Assert.Equal(streaming ? 200 : 429, entry.Properties["ProviderStatusCode"]); - Assert.Equal("429", entry.Properties["ProviderErrorCode"]); - Assert.Equal("rate_limit_exceeded", entry.Properties["ProviderErrorType"]); - Assert.Equal("invalid_request_error", entry.Properties["UpstreamErrorCode"]); - Assert.Equal("gen-failed-request", entry.Properties["ProviderGenerationId"]); - Assert.Equal("request-provider-id", entry.Properties["ProviderRequestId"]); - Assert.Equal(30d, entry.Properties["RetryAfterSeconds"]); - Assert.Equal("Fireworks", entry.Properties["ProviderName"]); - Assert.Equal(diagnostics.TurnId, entry.Properties["AssistantTurnId"]); - Assert.Equal(streaming ? "upstream_error" : null, entry.Properties["ProviderNativeFinishReason"]); - Assert.False(Assert.IsType(entry.Properties["ReceivedDone"])); - Assert.True(Assert.IsType(entry.Properties["ProviderDetailsRedacted"])); - Assert.Contains("Missing reasoning_content at messages[2]", Assert.IsType(entry.Properties["ProviderErrorDetails"])); - Assert.Contains("upstream_provider_shared_pool", Assert.IsType(entry.Properties["ProviderErrorDetails"])); - Assert.Contains("fallback", Assert.IsType(entry.Properties["ProviderRoutingDetails"])); - using var settings = JsonDocument.Parse(Assert.IsType(entry.Properties["ProviderRequestSettings"])); - Assert.Equal(AssistantLimits.MaximumOutputTokens, settings.RootElement.GetProperty("max_tokens").GetInt32()); - Assert.Equal("auto", settings.RootElement.GetProperty("tool_choice").GetString()); - Assert.True(settings.RootElement.GetProperty("tool_count").GetInt32() > 0); - Assert.True(settings.RootElement.GetProperty("message_count").GetInt32() > 0); - Assert.Equal("conversation-id", logger.Entries[^1].Properties["ConversationId"]); - - string rendered = String.Join('\n', logger.Entries.Select(entry => entry.Message)); - Assert.DoesNotContain("canary", rendered); - Assert.Equal("enabled", handler.RouterMetadataHeader); - } - - private sealed class ProviderErrorHandler(bool streaming, string error) : HttpMessageHandler - { - public string? RouterMetadataHeader { get; private set; } - - protected override Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) - { - RouterMetadataHeader = request.Headers.GetValues("X-OpenRouter-Metadata").Single(); - var response = new HttpResponseMessage(streaming ? HttpStatusCode.OK : HttpStatusCode.TooManyRequests) - { - Content = new StringContent(streaming ? $"data: {error}\n\n" : error, Encoding.UTF8, - streaming ? "text/event-stream" : "application/json") - }; - response.Headers.Add("X-Request-Id", "request-provider-id"); - response.Headers.Add("X-Generation-Id", "gen-header-id"); - response.Headers.RetryAfter = new System.Net.Http.Headers.RetryConditionHeaderValue(TimeSpan.FromSeconds(30)); - return Task.FromResult(response); - } - } -} diff --git a/tests/Exceptionless.Tests/Assistant/AssistantServiceTests.cs b/tests/Exceptionless.Tests/Assistant/AssistantServiceTests.cs index 092b1c38ff..dcd714f379 100644 --- a/tests/Exceptionless.Tests/Assistant/AssistantServiceTests.cs +++ b/tests/Exceptionless.Tests/Assistant/AssistantServiceTests.cs @@ -1,5 +1,3 @@ -using System.Diagnostics; -using System.Diagnostics.Metrics; using System.Net; using System.Text; using System.Text.Json; @@ -9,7 +7,6 @@ using Exceptionless.Core.Models.Billing; using Exceptionless.Core.Serialization; using Exceptionless.Core.Services; -using Exceptionless.Web.Api.Endpoints; using Exceptionless.Web.Assistant; using Exceptionless.Web.Mcp; using Foundatio.Caching; @@ -25,7 +22,7 @@ namespace Exceptionless.Tests.Assistant; -public sealed partial class AssistantServiceTests +public sealed class AssistantServiceTests { [Theory] [InlineData("requested-project", "Named project", "current-project", "requested-project")] @@ -113,7 +110,7 @@ [new AssistantChatMessage("user", "Say hello")], item => Assert.Equal("done", item.Type)); Assert.Equal("Bearer", handler.AuthorizationScheme); using var providerRequest = JsonDocument.Parse(handler.RequestBody); - Assert.Equal("deepseek/deepseek-v4.1-flash", providerRequest.RootElement.GetProperty("model").GetString()); + Assert.Equal("~deepseek/deepseek-v4-flash-latest", providerRequest.RootElement.GetProperty("model").GetString()); Assert.Contains($"\"max_tokens\":{AssistantLimits.MaximumOutputTokens}", handler.RequestBody); Assert.Contains("get_event", handler.RequestBody); Assert.Contains("get_stack", handler.RequestBody); @@ -211,6 +208,84 @@ public async Task StreamAsync_RuntimeModelOverride_UsesOverride() Assert.Equal("z-ai/glm-5.3-flash", providerRequest.RootElement.GetProperty("model").GetString()); } + [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 ProviderFailureLogger(); + 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); + 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)); + } + + [Theory] + [InlineData("private-proxy-body-canary")] + [InlineData("{invalid-json")] + public async Task StreamAsync_InvalidHttpErrorBody_LogsStatusWithoutHidingRejection(string content) + { + var logger = new ProviderFailureLogger(); + 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); + 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")] @@ -1066,256 +1141,6 @@ public async Task StreamAsync_EmptyResponse_EmitsClearErrorAndCompletion() item => Assert.Equal("done", item.Type)); } - [Theory] - [InlineData("length", "output_limit")] - [InlineData("content_filter", "content_filter")] - [InlineData("stop", "empty_response")] - public async Task StreamAsync_EmptyProviderAnswer_RecordsProviderReasonAndGeneration(string finishReason, string failureCode) - { - string payload = JsonSerializer.Serialize(new - { - id = "gen-empty-answer", - model = "resolved-model", - choices = new[] { new { delta = new { content = "" }, finish_reason = finishReason } }, - usage = new { prompt_tokens = 100, completion_tokens = 2048, completion_tokens_details = new { reasoning_tokens = 2048 } } - }); - var handler = new StubHttpMessageHandler($"data: {payload}\n\ndata: [DONE]\n\n"); - var options = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() - .AddInMemoryCollection(new Dictionary { ["BaseURL"] = "https://localhost", ["Assistant:ApiKey"] = "test-key" }) - .Build()); - var logger = new RecordingAssistantLogger(); - using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); - var service = CreateAssistantService(handler, options); - var events = new List(); - - await foreach (var item in service.StreamAsync( - new AssistantChatRequest([new AssistantChatMessage("user", "private question")]), - "user-id", CreatePlanOptions(), diagnostics, TestContext.Current.CancellationToken)) - events.Add(item); - - Assert.Equal(failureCode, Assert.Single(events, item => item.Type == "error").FailureCode); - Assert.Equal("gen-empty-answer", diagnostics.Provider?.GenerationId); - Assert.Equal("resolved-model", diagnostics.Provider?.Model); - Assert.Equal(2048, diagnostics.Provider?.ReasoningTokens); - Assert.Equal(1, diagnostics.ProviderRequests); - Assert.DoesNotContain(logger.Entries, entry => entry.Message.Contains("private question", StringComparison.Ordinal)); - } - - [Fact] - public async Task StreamAsync_ProviderStreamError_RecordsProviderErrorMessage() - { - var handler = new StubHttpMessageHandler(""" - data: {"id":"gen-stream-error","error":{"message":"private provider error"}} - - """); - var options = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() - .AddInMemoryCollection(new Dictionary { ["BaseURL"] = "https://localhost", ["Assistant:ApiKey"] = "test-key" }) - .Build()); - var logger = new RecordingAssistantLogger(); - using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); - var service = CreateAssistantService(handler, options); - - var exception = await Assert.ThrowsAsync(async () => - { - await foreach (var _ in service.StreamAsync( - new AssistantChatRequest([new AssistantChatMessage("user", "private question")]), - "user-id", CreatePlanOptions(), diagnostics, TestContext.Current.CancellationToken)) - { - } - }); - - Assert.Equal("provider_error", exception.FailureCode); - var entry = Assert.Single(logger.Entries); - Assert.Equal("provider_error", entry.Properties["ProviderOutcome"]); - Assert.Equal(200, entry.Properties["ProviderStatusCode"]); - Assert.Equal("gen-stream-error", entry.Properties["ProviderGenerationId"]); - Assert.Contains("private provider error", Assert.IsType(entry.Properties["ProviderErrorDetails"])); - } - - [Theory] - [InlineData("transport", "provider_transport_error")] - [InlineData("stream", "provider_stream_error")] - [InlineData("json", "invalid_provider_response")] - [InlineData("timeout", "provider_timeout")] - public async Task StreamAsync_ProviderThrows_RecordsFailureCategory(string failure, string expectedOutcome) - { - var options = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() - .AddInMemoryCollection(new Dictionary { ["BaseURL"] = "https://localhost", ["Assistant:ApiKey"] = "test-key" }) - .Build()); - var logger = new RecordingAssistantLogger(); - using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); - var service = CreateAssistantService(new FailingProviderHttpMessageHandler(failure), options); - - var exception = await Record.ExceptionAsync(async () => - { - await foreach (var _ in service.StreamAsync( - new AssistantChatRequest([new AssistantChatMessage("user", "private question")]), - "user-id", CreatePlanOptions(), diagnostics, TestContext.Current.CancellationToken)) - { - } - }); - - Assert.NotNull(exception); - var entry = Assert.Single(logger.Entries); - Assert.Equal(expectedOutcome, entry.Properties["ProviderOutcome"]); - Assert.DoesNotContain("private", entry.Message); - } - - [Theory] - [InlineData("[]")] - [InlineData("null")] - [InlineData("{\"choices\":{}}")] - [InlineData("{\"choices\":[{}]}")] - [InlineData("{\"choices\":[{\"delta\":[]}]}")] - [InlineData("{\"choices\":[{\"delta\":{\"tool_calls\":[{}]}}]}")] - [InlineData("{\"choices\":[{\"delta\":{\"tool_calls\":[{\"index\":2147483648}]}}]}")] - [InlineData("{\"usage\":{\"prompt_tokens\":\"private invalid token count\"}}")] - public async Task StreamAsync_InvalidProviderShape_RecordsProviderAndTurnFailure(string payload) - { - var options = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() - .AddInMemoryCollection(new Dictionary { ["BaseURL"] = "https://localhost", ["Assistant:ApiKey"] = "test-key" }) - .Build()); - var logger = new RecordingAssistantLogger(); - using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); - using var cache = new InMemoryCacheClient(); - var recorder = new RecordingAssistantUsageRecorder(); - var usageService = new AssistantUsageService(cache, CreateLockProvider(cache, TimeProvider.System), recorder, options, - TimeProvider.System, NullLogger.Instance); - var service = CreateAssistantService(new StubHttpMessageHandler($"data: {payload}\n\ndata: [DONE]\n"), options, cache, usageService: usageService); - var context = new DefaultHttpContext(); - using var response = new MemoryStream(); - context.Response.Body = response; - - await AssistantEndpoints.WriteResponseAsync(context, - service.StreamAsync(new AssistantChatRequest([new AssistantChatMessage("user", "private question")]), - "user-id", CreatePlanOptions(), diagnostics, TestContext.Current.CancellationToken), - usageService, "organization-id", diagnostics, TestContext.Current.CancellationToken); - - var providerEntry = Assert.Single(logger.Entries, entry => entry.Properties.ContainsKey("ProviderOutcome")); - var turnEntry = Assert.Single(logger.Entries, entry => entry.Properties.ContainsKey("Outcome")); - Assert.Equal("invalid_provider_response", providerEntry.Properties["ProviderOutcome"]); - Assert.Equal("invalid_provider_response", turnEntry.Properties["FailureReason"]); - Assert.Equal("failed", turnEntry.Properties["Outcome"]); - Assert.All(logger.Entries, entry => Assert.DoesNotContain("private", entry.Message)); - } - - [Theory] - [InlineData("exception", "failed", "tool_execution_error")] - [InlineData("client", "cancelled", "client_disconnected")] - [InlineData("turn", "failed", "turn_timeout")] - public async Task StreamAsync_ToolThrows_RecordsToolOutcomeAndDuration(string failure, string outcome, string reason) - { - var activitySource = AppDiagnostics.AssistantActivitySource; - using var activityListener = new ActivityListener - { - ShouldListenTo = source => source == activitySource, - Sample = (ref ActivityCreationOptions _) => ActivitySamplingResult.AllDataAndRecorded - }; - ActivitySource.AddActivityListener(activityListener); - var logger = new RecordingAssistantLogger(); - using var requestAborted = new CancellationTokenSource(); - using var cancellation = CancellationTokenSource.CreateLinkedTokenSource(requestAborted.Token, TestContext.Current.CancellationToken); - using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id", requestAborted.Token); - var measurements = new List>(); - using var meterListener = new MeterListener - { - InstrumentPublished = (instrument, listener) => - { - if (instrument.Name == "ex.assistant.tool.duration") - { - listener.EnableMeasurementEvents(instrument); - } - } - }; - meterListener.SetMeasurementEventCallback((_, _, tags, _) => - { - if (Activity.Current?.GetTagItem("assistant.turn.id") as string == diagnostics.TurnId) - { - measurements.Add(tags.ToArray().ToDictionary(tag => tag.Key, tag => tag.Value)); - } - }); - meterListener.Start(); - // An array where a tool argument object is required throws during invocation. - var handler = new StubHttpMessageHandler(""" - data: {"choices":[{"delta":{"tool_calls":[{"index":0,"id":"tool-1","function":{"name":"search_stacks","arguments":"[]"}}]}}]} - - data: [DONE] - - """); - var options = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() - .AddInMemoryCollection(new Dictionary { ["BaseURL"] = "https://localhost", ["Assistant:ApiKey"] = "test-key" }) - .Build()); - var service = CreateAssistantService(handler, options); - var exception = await Record.ExceptionAsync(async () => - { - await foreach (var item in service.StreamAsync( - new AssistantChatRequest([new AssistantChatMessage("user", "Find my errors")]), - "user-id", CreatePlanOptions(), diagnostics, cancellation.Token)) - { - if (failure == "client" && item.Type == "tool_call") - { - requestAborted.Cancel(); - } - else if (failure == "turn" && item.Type == "tool_call") - { - cancellation.Cancel(); - } - } - }); - - if (failure != "exception") - { - Assert.IsAssignableFrom(exception); - } - else - { - Assert.IsType(exception); - } - Assert.Equal(1, diagnostics.ToolCalls); - Assert.Equal(failure == "client" ? 0 : 1, diagnostics.ToolFailures); - Assert.Equal(reason, diagnostics.LastToolError); - var measurement = Assert.Single(measurements); - Assert.Equal("search_stacks", measurement["tool"]); - Assert.Equal(outcome, measurement["outcome"]); - Assert.Equal(diagnostics.LastToolError, measurement["reason"]); - } - - [Theory] - [InlineData(HttpStatusCode.TemporaryRedirect)] - [InlineData(HttpStatusCode.TooManyRequests)] - [InlineData(HttpStatusCode.InternalServerError)] - public async Task StreamAsync_HttpRejection_RecordsSanitizedProviderError(HttpStatusCode responseStatus) - { - var handler = new RejectedHttpMessageHandler(responseStatus); - var options = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() - .AddInMemoryCollection(new Dictionary { ["BaseURL"] = "https://localhost", ["Assistant:ApiKey"] = "test-key" }) - .Build()); - var logger = new RecordingAssistantLogger(); - using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); - var service = CreateAssistantService(handler, options, logger: logger); - - var exception = await Assert.ThrowsAsync(async () => - { - await foreach (var _ in service.StreamAsync( - new AssistantChatRequest([new AssistantChatMessage("user", "private question")]), - "user-id", CreatePlanOptions(), diagnostics, TestContext.Current.CancellationToken)) - { - } - }); - - Assert.Equal("provider_http_error", exception.FailureCode); - var providerEntry = Assert.Single(logger.Entries, entry => entry.Properties.ContainsKey("ProviderOutcome")); - Assert.Equal(exception.FailureCode, providerEntry.Properties["ProviderOutcome"]); - Assert.Equal((int)responseStatus, diagnostics.Provider?.StatusCode); - Assert.Contains(logger.Entries, entry => entry.Properties.TryGetValue("StatusCode", out var status) && status is int code && code == (int)responseStatus); - Assert.Contains("Rejected", Assert.IsType(providerEntry.Properties["ProviderErrorDetails"])); - Assert.All(logger.Entries, entry => - { - Assert.DoesNotContain("private question", entry.Message); - Assert.DoesNotContain("test-key", entry.Message); - }); - } - [Fact] public async Task StreamAsync_RawDsmlResponse_RetriesWithoutEmittingMarkup() { @@ -1415,14 +1240,11 @@ public async Task StreamAsync_RepeatedRawDsmlResponse_EmitsClearErrorAndCompleti .Build()); var service = CreateAssistantService(handler, appOptions); var events = new List(); - var logger = new RecordingAssistantLogger(); - using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); await foreach (var item in service.StreamAsync( new AssistantChatRequest([new AssistantChatMessage("user", "Find recent errors")]), "user-id", CreatePlanOptions(), - diagnostics, TestContext.Current.CancellationToken)) { events.Add(item); @@ -1437,15 +1259,10 @@ public async Task StreamAsync_RepeatedRawDsmlResponse_EmitsClearErrorAndCompleti }, item => Assert.Equal("done", item.Type)); Assert.DoesNotContain(events, item => item.Type == "text_delta"); - var providerEntries = logger.Entries.Where(entry => entry.Properties.ContainsKey("ProviderOutcome")).ToArray(); - Assert.Equal(2, providerEntries.Length); - Assert.All(providerEntries, entry => Assert.Equal("malformed_response", entry.Properties["ProviderOutcome"])); } - [Theory] - [InlineData(false)] - [InlineData(true)] - public async Task StreamAsync_ToolBudgetExhausted_RequestsFinalSynthesisWithToolChoiceNone(bool providerIgnoresToolLimit) + [Fact] + public async Task StreamAsync_ToolBudgetExhausted_RequestsFinalSynthesisWithToolChoiceNone() { const string toolCallResponse = """ data: {"choices":[{"delta":{"tool_calls":[{"index":0,"id":"call-1","function":{"name":"unknown_tool","arguments":"{}"}}]}}]} @@ -1457,7 +1274,7 @@ public async Task StreamAsync_ToolBudgetExhausted_RequestsFinalSynthesisWithTool toolCallResponse, toolCallResponse.Replace("call-1", "call-2"), toolCallResponse.Replace("call-1", "call-3"), - providerIgnoresToolLimit ? toolCallResponse.Replace("call-1", "call-4") : """ + """ data: {"choices":[{"delta":{"content":"Here is the available result."}}]} data: [DONE] @@ -1472,8 +1289,6 @@ public async Task StreamAsync_ToolBudgetExhausted_RequestsFinalSynthesisWithTool .Build()); var service = CreateAssistantService(handler, appOptions); var events = new List(); - var logger = new RecordingAssistantLogger(); - using var diagnostics = new AssistantTurnDiagnostics(logger, TimeProvider.System, "organization-id", "conversation-id", "request-id"); await foreach (var item in service.StreamAsync( new AssistantChatRequest( @@ -1481,7 +1296,6 @@ [new AssistantChatMessage("user", "Investigate the errors")], OrganizationId: "organization-id"), "user-id", CreatePlanOptions(), - diagnostics, TestContext.Current.CancellationToken)) { events.Add(item); @@ -1493,19 +1307,9 @@ [new AssistantChatMessage("user", "Investigate the errors")], 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); - var finalProviderEntry = logger.Entries.Last(entry => entry.Properties.ContainsKey("ProviderOutcome")); - if (providerIgnoresToolLimit) - { - Assert.Equal("tool_round_limit", Assert.Single(events, item => item.Type == "error").FailureCode); - Assert.Equal("tool_round_limit", finalProviderEntry.Properties["ProviderOutcome"]); - } - else - { - Assert.Contains(events, item => item.Text == "Here is the available result."); - Assert.DoesNotContain(events, item => item.Type == "error"); - Assert.Equal("completed", finalProviderEntry.Properties["ProviderOutcome"]); - } + Assert.DoesNotContain(events, item => item.Type == "error"); } [Fact] @@ -1668,22 +1472,23 @@ protected override async Task SendAsync(HttpRequestMessage } } - private sealed class FailingProviderHttpMessageHandler(string failure) : HttpMessageHandler + private sealed class ProviderFailureHandler(HttpStatusCode status, string content) : HttpMessageHandler { protected override Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) - => failure switch - { - "transport" => Task.FromException(new HttpRequestException("private transport detail")), - "timeout" => Task.FromException(new TaskCanceledException("private timeout detail")), - "stream" => Task.FromResult(new HttpResponseMessage(HttpStatusCode.OK) { Content = new StreamContent(new FailingProviderStream()) }), - _ => Task.FromResult(new HttpResponseMessage(HttpStatusCode.OK) { Content = new StringContent("data: invalid-json\n\n") }) - }; + { + var response = new HttpResponseMessage(status) { Content = new StringContent(content) }; + response.Headers.Add("X-Generation-Id", "gen-header"); + return Task.FromResult(response); + } } - private sealed class FailingProviderStream : MemoryStream + private sealed class ProviderFailureLogger : ILogger { - public override ValueTask ReadAsync(Memory buffer, CancellationToken cancellationToken = default) - => ValueTask.FromException(new IOException("private stream detail")); + 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 diff --git a/tests/Exceptionless.Tests/Assistant/README.md b/tests/Exceptionless.Tests/Assistant/README.md index 4c334ebb93..fbc6d8e9e2 100644 --- a/tests/Exceptionless.Tests/Assistant/README.md +++ b/tests/Exceptionless.Tests/Assistant/README.md @@ -1,6 +1,6 @@ # Exie quality evaluations -The assistant quality gate is an opt-in integration test suite that calls the configured AI provider and uses the real Exceptionless HTTP endpoint, authentication, Elasticsearch test data, and MCP tools. It checks the behaviors that have caused the most visible failures: +The assistant quality gate is an opt-in integration test that calls the configured AI provider and uses the real Exceptionless HTTP endpoint, authentication, Elasticsearch test data, and MCP tools. It checks the behaviors that have caused the most visible failures: - a current event is fetched directly without rediscovering its project or stack; - a project-scoped top-errors question uses one stack search and returns navigable links; @@ -19,35 +19,3 @@ dotnet tests/Exceptionless.Tests/bin/Debug/net10.0/Exceptionless.Tests.dll \ ``` Set `EX_Assistant__Model` and `EX_Assistant__Endpoint` to evaluate a candidate model or compatible provider. Use a dedicated provider key with a small monthly hard limit; the tests never print the key. - -Each scenario runs independently and authenticates as the seeded organization user, so a failure in one scenario does not prevent the remaining scenarios from exercising the provider. - -Exie defaults to the pinned `deepseek/deepseek-v4.1-flash` model. Model changes must preserve these provider contracts: - -- Keep streamed reasoning with the assistant's tool calls for subsequent provider requests in the same turn. Prefer structured reasoning blocks so their order, signatures, and opaque data survive. Never send reasoning to the browser or persist it with conversation tool results. See [OpenRouter reasoning preservation](https://openrouter.ai/docs/guides/best-practices/reasoning-tokens#preserving-reasoning). -- Include tool definitions on every request containing tool results. When requesting a final answer after suggestions or tool-budget exhaustion, use `tool_choice: "none"`. See [OpenRouter tool calling](https://openrouter.ai/docs/guides/features/tool-calling). - -## Failure diagnostics - -The streaming endpoint emits a structured summary for each turn and each provider request. `Exceptionless.Web.Assistant: Information` keeps completed and cancelled summaries visible even when production's default log level is Warning. Failures emit Warning or Error events. The `Exceptionless.Assistant` activity source also exports turn/provider spans; the existing application meter records `ex.assistant.turn.duration`, `ex.assistant.provider.duration`, and `ex.assistant.tool.duration` histograms with bounded outcome/reason tags. - -Start with the failed turn in production `ex-prod-app` logs or Exceptionless events from `Exceptionless.Web.Assistant.AssistantService`. Search for its `AssistantTurnId` to collect every provider request and tool failure. Turn summaries include `OrganizationId`, `ConversationId`, `RequestId`, and `TraceId`; provider summaries include `ProviderGenerationId` and `ProviderRequestId` for an OpenRouter investigation. Use `ProviderRequestNumber` to distinguish the initial request, tool continuations, and malformed-response retries. - -| Evidence | Fields and interpretation | -| --- | --- | -| Turn outcome | `Outcome`, `FailureReason`, `Stage`, `DurationMs`, `FirstTextDurationMs`. Distinguishes a provider failure, turn deadline, tool exception, response-write failure, and client disconnect. | -| Provider rejection | `ProviderStatusCode` is the HTTP status; `ProviderErrorCode` is the body/stream error code. HTTP 200 can contain a later error with code 429. `ProviderErrorType` is OpenRouter's normalized type; `UpstreamErrorCode` is the provider-specific code. | -| Actual cause | `ProviderErrorDetails` is a JSON string containing selected error messages, parameter locations, nested `metadata.raw` errors, rate-limit source, routing exclusions, and routing funnel steps. | -| Routing | `ProviderModel`, `ProviderName`, and `ProviderRoutingDetails` identify the resolved model, selected provider, and available attempt metadata. Requests opt in with `X-OpenRouter-Metadata: enabled`; OpenRouter may omit metadata for some responses. | -| Request constraints | `ProviderRequestSettings` records output-token limit, temperature, tool choice/count, message count, and provider price caps. `InputCharacters` records request size without content. | -| Stream progress | `HeadersDurationMs`, `FirstChunkDurationMs`, `LastChunkDurationMs`, `ChunkCount`, `OutputCharacters`, `ToolCalls`, `ReceivedDone`, `ProviderFinishReason`, `ProviderNativeFinishReason`, and token counts distinguish a connection failure, interrupted stream, output limit, or reasoning-only response. | -| Transport and retry | `RetryAfterSeconds`, `ProviderContentType`, `ExceptionType`, `TransportError`, and `SocketError` retain response/transport evidence without logging arbitrary exception messages. The turn event also contains `ExceptionStackTrace`. | -| Diagnostic limits | `ProviderErrorBodyState`, `ProviderDetailsTruncated`, and `ProviderDetailsRedacted` explain missing or filtered details. Non-JSON, invalid, empty, or oversized HTTP error bodies are classified without recording their raw content. | - -Useful failure reasons include `provider_http_error`, `provider_error`, `provider_transport_error`, `provider_stream_error`, `invalid_provider_response`, `provider_timeout`, `turn_timeout`, `empty_response`, `output_limit`, `content_filter`, `malformed_response`, `tool_round_limit`, `tool_execution_error`, `response_write_error`, `usage_limit`, and `context_limit`. `client_disconnected` is cancellation. A provider warning can precede a recovered turn; assess the final turn outcome as well. Completion records delivery, not whether the answer solved the user's problem; use the quality evaluations above for that. - -Error extraction uses an allowlist and removes echoed request values, credentials, and URLs. Prompts, answer text, reasoning, tool arguments/results, flagged input, and arbitrary router pipeline data are not copied into diagnostic events. HTTP error reads are capped at 32,768 characters. Error/routing extraction shares a budget of 64 fields, 16 items per array, six nesting levels, 2,048 characters per text field, and 8,192 total text characters. These bounds are explicit so missing provider evidence is distinguishable from an empty upstream error. - -Focused tests cover HTTP and in-stream failures, routing and validation errors, timeouts, cancellation, stream progress, malformed/oversized bodies, correlation, and credential/request redaction. A test also passes the provider failure through the real Serilog Exceptionless sink and serializes the intercepted event to verify that the useful details survive without submitting any event externally. - -See OpenRouter's [error semantics](https://openrouter.ai/docs/api_reference/errors-and-debugging) and [router metadata](https://openrouter.ai/docs/guides/features/router-metadata) for upstream field definitions. From 4cbe9c4652ef4e469eeb952871f04547216353d1 Mon Sep 17 00:00:00 2001 From: "Eric J. Smith" Date: Thu, 10 Sep 2026 23:37:42 -0500 Subject: [PATCH 3/3] Restore Exie response and provider timing telemetry --- .../Utility/AppDiagnostics.cs | 4 + src/Exceptionless.Web/ApmExtensions.cs | 8 + .../Assistant/AssistantProviderTiming.cs | 40 +++++ .../Assistant/AssistantService.cs | 48 +++++- src/Exceptionless.Web/appsettings.yml | 1 + .../Assistant/AssistantServiceTests.cs | 140 +++++++++++++++++- 6 files changed, 231 insertions(+), 10 deletions(-) create mode 100644 src/Exceptionless.Web/Assistant/AssistantProviderTiming.cs 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 f770e7c57e..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)) { @@ -116,7 +149,8 @@ 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); @@ -132,9 +166,12 @@ 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); @@ -209,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) @@ -387,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); @@ -420,6 +460,7 @@ private async Task SendRequestAsync(List messages, providerRequest.Content = JsonContent.Create(payload); var response = await client.SendAsync(providerRequest, HttpCompletionOption.ResponseHeadersRead, cancellationToken); + timing.HeadersDuration = timing.ElapsedMilliseconds; if (response.IsSuccessStatusCode) return response; @@ -477,6 +518,7 @@ private async Task ExecuteToolAsync( AssistantChatRequest request, CancellationToken cancellationToken) { + using var toolTimer = AppDiagnostics.AssistantToolDuration.StartTimer(); cancellationToken.ThrowIfCancellationRequested(); using var _ = assistantToolContext.BeginTools(request.OrganizationId); using var document = ParseArguments(arguments); 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 dcd714f379..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; @@ -18,6 +19,7 @@ using Microsoft.Extensions.Configuration; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Time.Testing; using Xunit; namespace Exceptionless.Tests.Assistant; @@ -208,6 +210,92 @@ 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")] @@ -223,7 +311,7 @@ public async Task StreamAsync_ProviderFailure_LogsCauseAndCorrelation(bool strea string content = streaming ? "data: {\"id\":\"gen-stream\",\"provider\":\"Fireworks\",\"choices\":[]}\n\ndata: " + error.ReplaceLineEndings("") + "\n\n" : error; - var logger = new ProviderFailureLogger(); + var logger = new RecordingAssistantLogger(); var appOptions = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() .AddInMemoryCollection(new Dictionary { @@ -243,7 +331,7 @@ [new AssistantChatMessage("user", "private-prompt-canary")], OrganizationId: "or } }); - var properties = Assert.Single(logger.Entries); + 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"]); @@ -255,6 +343,11 @@ [new AssistantChatMessage("user", "private-prompt-canary")], OrganizationId: "or 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] @@ -262,7 +355,7 @@ [new AssistantChatMessage("user", "private-prompt-canary")], OrganizationId: "or [InlineData("{invalid-json")] public async Task StreamAsync_InvalidHttpErrorBody_LogsStatusWithoutHidingRejection(string content) { - var logger = new ProviderFailureLogger(); + var logger = new RecordingAssistantLogger(); var appOptions = AppOptions.ReadFromConfiguration(new ConfigurationBuilder() .AddInMemoryCollection(new Dictionary { @@ -280,7 +373,7 @@ public async Task StreamAsync_InvalidHttpErrorBody_LogsStatusWithoutHidingReject }); Assert.Contains("502", exception.Message); - var properties = Assert.Single(logger.Entries); + 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)); @@ -1387,7 +1480,8 @@ private static AssistantService CreateAssistantService( ILockProvider? lockProvider = null, AssistantUsageService? usageService = null, AssistantModelSettingsService? modelSettingsService = null, - ILogger? logger = null) + ILogger? logger = null, + TimeProvider? timeProvider = null) { cache ??= new InMemoryCacheClient(new InMemoryCacheClientOptions { @@ -1413,7 +1507,7 @@ private static AssistantService CreateAssistantService( new AssistantConversationService(cache, lockProvider, NullLogger.Instance), modelSettingsService, usageService, - TimeProvider.System, + timeProvider ?? TimeProvider.System, logger ?? NullLogger.Instance); } @@ -1472,6 +1566,38 @@ 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) @@ -1482,7 +1608,7 @@ protected override Task SendAsync(HttpRequestMessage reques } } - private sealed class ProviderFailureLogger : ILogger + private sealed class RecordingAssistantLogger : ILogger { public List> Entries { get; } = []; public IDisposable? BeginScope(TState state) where TState : notnull => null;