diff --git a/TelegramSearchBot.LLM.Test/Service/AI/LLM/McpToolHelperProxyTests.cs b/TelegramSearchBot.LLM.Test/Service/AI/LLM/McpToolHelperProxyTests.cs index 2fee59d5..b002424b 100644 --- a/TelegramSearchBot.LLM.Test/Service/AI/LLM/McpToolHelperProxyTests.cs +++ b/TelegramSearchBot.LLM.Test/Service/AI/LLM/McpToolHelperProxyTests.cs @@ -1,9 +1,11 @@ using TelegramSearchBot.Model; using TelegramSearchBot.Model.AI; using TelegramSearchBot.Service.AI.LLM; +using TelegramSearchBot.Test; using Xunit; namespace TelegramSearchBot.LLM.Test.Service.AI.LLM { + [Collection(McpToolHelperTestCollection.Name)] public class McpToolHelperProxyTests { [Fact] public async Task ExecuteRegisteredToolAsync_ProxyTool_ForwardsToolContextMetadata() { @@ -46,5 +48,48 @@ public async Task ExecuteRegisteredToolAsync_ProxyTool_ForwardsToolContextMetada Assert.Equal("456", forwardedArguments["__userId"]); Assert.Equal("789", forwardedArguments["__messageId"]); } + + [Fact] + public void TryParseToolCalls_ProxyToolXml_ParsesRegisteredProxyTool() { + var toolName = $"proxy_parse_test_{Guid.NewGuid():N}"; + + McpToolHelper.RegisterProxyTools([ + new ProxyToolDefinition { + Name = toolName, + Description = "Proxy search tool.", + Parameters = [ + new ProxyToolParameter { + Name = "query", + Type = "string", + Description = "Query text.", + Required = true + }, + new ProxyToolParameter { + Name = "count", + Type = "integer", + Description = "Result count.", + Required = false + } + ] + } + ], (_, _) => Task.FromResult("ok")); + + var xml = $""" + + + 苏州今日天气 + 5 + + +"""; + + var parsed = McpToolHelper.TryParseToolCalls(xml, out var parsedToolCalls); + + Assert.True(parsed); + Assert.Single(parsedToolCalls); + Assert.Equal(toolName, parsedToolCalls[0].toolName); + Assert.Equal("苏州今日天气", parsedToolCalls[0].arguments["query"]); + Assert.Equal("5", parsedToolCalls[0].arguments["count"]); + } } } diff --git a/TelegramSearchBot.LLM.Test/Service/AI/LLM/OpenAIToolCallNormalizationTests.cs b/TelegramSearchBot.LLM.Test/Service/AI/LLM/OpenAIToolCallNormalizationTests.cs index f82c3938..53683e09 100644 --- a/TelegramSearchBot.LLM.Test/Service/AI/LLM/OpenAIToolCallNormalizationTests.cs +++ b/TelegramSearchBot.LLM.Test/Service/AI/LLM/OpenAIToolCallNormalizationTests.cs @@ -1,4 +1,6 @@ using TelegramSearchBot.Service.AI.LLM; +using TelegramSearchBot.Model.AI; +using TelegramSearchBot.Model.Data; using Xunit; namespace TelegramSearchBot.LLM.Test.Service.AI.LLM { @@ -61,5 +63,35 @@ public void DeserializeToolArgumentsForDisplay_InvalidJson_ReturnsEmptyDictionar Assert.Empty(arguments); } + + [Fact] + public void IsMiniMaxCompatibleEndpoint_MiniMaxProvider_ReturnsTrue() { + var channel = new LLMChannel { + Provider = LLMProvider.MiniMax, + Gateway = "https://api.minimaxi.com/v1" + }; + + Assert.True(OpenAIService.IsMiniMaxCompatibleEndpoint(channel, "MiniMax-M2.7")); + } + + [Fact] + public void IsMiniMaxCompatibleEndpoint_MiniMaxGateway_ReturnsTrue() { + var channel = new LLMChannel { + Provider = LLMProvider.OpenAI, + Gateway = "https://api.minimaxi.com/v1" + }; + + Assert.True(OpenAIService.IsMiniMaxCompatibleEndpoint(channel, "some-model")); + } + + [Fact] + public void IsMiniMaxCompatibleEndpoint_OpenAIProvider_ReturnsFalse() { + var channel = new LLMChannel { + Provider = LLMProvider.OpenAI, + Gateway = "https://api.openai.com/v1" + }; + + Assert.False(OpenAIService.IsMiniMaxCompatibleEndpoint(channel, "gpt-4.1")); + } } } diff --git a/TelegramSearchBot.LLM/Service/AI/LLM/McpToolHelper.cs b/TelegramSearchBot.LLM/Service/AI/LLM/McpToolHelper.cs index cf26d59c..d580ba3d 100644 --- a/TelegramSearchBot.LLM/Service/AI/LLM/McpToolHelper.cs +++ b/TelegramSearchBot.LLM/Service/AI/LLM/McpToolHelper.cs @@ -484,7 +484,7 @@ public static bool TryParseToolCalls(string input, out List<(string toolName, Di // Check if there's a wrapper element containing tool elements if (doc.Root.Elements().Any(e => e.Name.LocalName.Equals("tool", StringComparison.OrdinalIgnoreCase) || - ToolRegistry.ContainsKey(e.Name.LocalName))) { + IsToolRegistered(e.Name.LocalName))) { // Process each tool element inside the wrapper foreach (var toolElement in doc.Root.Elements()) { var toolCall = ParseToolElement(toolElement); @@ -500,11 +500,18 @@ public static bool TryParseToolCalls(string input, out List<(string toolName, Di // Fallback to regex parsing for individual tool blocks var toolBlockMatches = Regex.Matches(processedInput, @"<(tool\b[^>]*|[\w]+)(?:\s[^>]*)?>[\s\S]*?<\/\1>", RegexOptions.IgnoreCase); - _sLogger?.LogInformation($"TryParseToolCalls: Found {toolBlockMatches.Count} tool elements in input: {processedInput}"); - _sLogger?.LogInformation($"TryParseToolCalls: Raw regex matches - Count: {toolBlockMatches.Count}"); - _sLogger?.LogInformation($"TryParseToolCalls: Using regex pattern: {@"<(tool\b[^>]*|[\w]+)(?:\s[^>]*)?>[\s\S]*?<\/\1>"}"); + _sLogger?.LogInformation( + "TryParseToolCalls: Found {ToolBlockCount} potential tool elements. BuiltInCount={BuiltInCount}, ExternalCount={ExternalCount}, ProxyCount={ProxyCount}, AvailableTools={AvailableTools}, InputPreview={InputPreview}", + toolBlockMatches.Count, + ToolRegistry.Count, + ExternalToolRegistry.Count, + ProxyToolRegistry.Count, + GetAvailableToolNamesForLog(), + TruncateForLog(processedInput, MaxToolLogPayloadLength)); + _sLogger?.LogDebug($"TryParseToolCalls: Raw regex matches - Count: {toolBlockMatches.Count}"); + _sLogger?.LogTrace($"TryParseToolCalls: Using regex pattern: {@"<(tool\b[^>]*|[\w]+)(?:\s[^>]*)?>[\s\S]*?<\/\1>"}"); for (int i = 0; i < toolBlockMatches.Count; i++) { - _sLogger?.LogInformation($"Match {i}: {toolBlockMatches[i].Value}"); + _sLogger?.LogTrace($"Match {i}: {toolBlockMatches[i].Value}"); } _sLogger?.LogDebug($"TryParseToolCalls: Found {toolBlockMatches.Count} potential tool blocks using regex."); @@ -549,27 +556,30 @@ public static bool TryParseToolCalls(string input, out List<(string toolName, Di private static (string toolName, Dictionary arguments) ParseToolElement(XElement element) { string toolName = null; + var requestedToolName = element.Name.LocalName; var arguments = new Dictionary(StringComparer.OrdinalIgnoreCase); // 确定工具名称 - 更灵活的匹配逻辑 if (element.Name.LocalName.Equals("tool", StringComparison.OrdinalIgnoreCase)) { - toolName = element.Attribute("name")?.Value; - if (string.IsNullOrEmpty(toolName)) { + requestedToolName = element.Attribute("name")?.Value; + if (string.IsNullOrEmpty(requestedToolName)) { _sLogger?.LogWarning("ParseToolElement: Tool element has no name attribute"); return (null, null); } + toolName = ResolveRegisteredToolName(requestedToolName); } else { - // 尝试匹配注册的工具名称 (built-in and external) - toolName = ToolRegistry.Keys.FirstOrDefault(k => - k.Equals(element.Name.LocalName, StringComparison.OrdinalIgnoreCase)); - if (toolName == null) { - toolName = ExternalToolRegistry.Keys.FirstOrDefault(k => - k.Equals(element.Name.LocalName, StringComparison.OrdinalIgnoreCase)); - } + // 尝试匹配注册的工具名称 (built-in, external, or proxy) + toolName = ResolveRegisteredToolName(requestedToolName); } - if (toolName == null || ( !ToolRegistry.ContainsKey(toolName) && !ExternalToolRegistry.ContainsKey(toolName) )) { - _sLogger?.LogWarning($"ParseToolElement: Unregistered tool '{element.Name.LocalName}'"); + if (toolName == null) { + _sLogger?.LogWarning( + "ParseToolElement: Unregistered tool '{ToolName}'. BuiltInCount={BuiltInCount}, ExternalCount={ExternalCount}, ProxyCount={ProxyCount}, AvailableTools={AvailableTools}", + requestedToolName, + ToolRegistry.Count, + ExternalToolRegistry.Count, + ProxyToolRegistry.Count, + GetAvailableToolNamesForLog()); return (null, null); } @@ -698,6 +708,16 @@ public static async Task ExecuteRegisteredToolAsync(string toolName, Dic return await ExecuteRegisteredToolAsync(toolName, stringArguments, null, toolContext); } + private static string ResolveRegisteredToolName(string toolName) { + if (string.IsNullOrWhiteSpace(toolName)) { + return null; + } + + return ToolRegistry.Keys.FirstOrDefault(k => k.Equals(toolName, StringComparison.OrdinalIgnoreCase)) + ?? ExternalToolRegistry.Keys.FirstOrDefault(k => k.Equals(toolName, StringComparison.OrdinalIgnoreCase)) + ?? ProxyToolRegistry.Keys.FirstOrDefault(k => k.Equals(toolName, StringComparison.OrdinalIgnoreCase)); + } + /// /// Executes a registered tool, optionally using a scoped IServiceProvider for DI resolution. /// Use the scoped overload when executing tools that require scoped services (e.g., DbContext). @@ -1171,7 +1191,7 @@ public static bool IsExternalTool(string toolName) { /// Check if a tool name is registered (built-in, external, or proxy). /// public static bool IsToolRegistered(string toolName) { - return ToolRegistry.ContainsKey(toolName) || ExternalToolRegistry.ContainsKey(toolName) || ProxyToolRegistry.ContainsKey(toolName); + return ResolveRegisteredToolName(toolName) != null; } /// diff --git a/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIResponsesService.cs b/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIResponsesService.cs index 211e389f..c5588f7f 100644 --- a/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIResponsesService.cs +++ b/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIResponsesService.cs @@ -292,13 +292,19 @@ private async IAsyncEnumerable ExecWithResponsesApiAsync( throw; } - // Format tool call display var argsDict = OpenAIService.DeserializeToolArgumentsForDisplay(argsJson); toolIndicators.Append(McpToolHelper.FormatToolCallDisplay(name, argsDict)); // Execute tool - _logger.LogInformation("{ServiceName}: Responses API tool call: {ToolName} with arguments: {Arguments}", - ServiceName, name, argsJson); + _logger.LogInformation( + "{ServiceName}: Responses API tool call parsed; executing now. Tool={ToolName}, CallId={CallId}, ChatId={ChatId}, UserId={UserId}, MessageId={MessageId}, Arguments={Arguments}", + ServiceName, + name, + callId, + ChatId, + message.FromUserId, + message.MessageId, + argsJson); string toolResultString; try { @@ -508,13 +514,18 @@ public async IAsyncEnumerable ResumeFromSnapshotAsync( } var argsDict = OpenAIService.DeserializeToolArgumentsForDisplay(argsJson); - var toolIndicator = McpToolHelper.FormatToolCallDisplay(name, argsDict); - newContentBuilder.Append(toolIndicator); - fullContentBuilder.Append(toolIndicator); - yield return newContentBuilder.ToString(); string toolResultString; try { + _logger.LogInformation( + "{ServiceName}: Responses API tool call parsed during resume; executing now. Tool={ToolName}, CallId={CallId}, ChatId={ChatId}, UserId={UserId}, MessageId={MessageId}, Arguments={Arguments}", + ServiceName, + name, + callId, + snapshot.ChatId, + snapshot.UserId, + snapshot.OriginalMessageId, + argsJson); var toolContext = new ToolContext { ChatId = snapshot.ChatId, UserId = snapshot.UserId, @@ -535,6 +546,11 @@ public async IAsyncEnumerable ResumeFromSnapshotAsync( toolResultString = $"Error executing tool {name}: {ex.GetLogSummary()}."; } + var toolIndicator = McpToolHelper.FormatToolCallDisplay(name, argsDict); + newContentBuilder.Append(toolIndicator); + fullContentBuilder.Append(toolIndicator); + yield return newContentBuilder.ToString(); + inputItems.Add(ResponseItem.CreateFunctionCallOutputItem(callId, toolResultString)); } continue; diff --git a/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIService.cs b/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIService.cs index b7beac5b..3f6410ae 100644 --- a/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIService.cs +++ b/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIService.cs @@ -74,6 +74,17 @@ internal static Dictionary DeserializeToolArgumentsForDisplay(st } } + internal static bool IsMiniMaxCompatibleEndpoint(LLMChannel channel, string modelName) { + if (channel?.Provider == LLMProvider.MiniMax) { + return true; + } + + var gateway = channel?.Gateway ?? string.Empty; + var model = modelName ?? string.Empty; + return gateway.Contains("minimax", StringComparison.OrdinalIgnoreCase) || + model.Contains("minimax", StringComparison.OrdinalIgnoreCase); + } + private static string SanitizeAndTruncateArguments(string arguments, int maxChars = 2048) { if (string.IsNullOrWhiteSpace(arguments)) { return string.Empty; @@ -942,6 +953,17 @@ public async IAsyncEnumerable ExecAsync(Model.Data.Message message, long useNativeToolCalling = false; } + var isMiniMaxCompatibleEndpoint = IsMiniMaxCompatibleEndpoint(channel, modelName); + _logger.LogInformation( + "{ServiceName}: Tool calling setup for model {Model}. UseNative={UseNative}, NativeToolCount={NativeToolCount}, Provider={Provider}, Gateway={Gateway}, IsMiniMaxCompatible={IsMiniMaxCompatible}", + ServiceName, + modelName, + useNativeToolCalling, + nativeTools?.Count ?? 0, + channel.Provider, + channel.Gateway, + isMiniMaxCompatibleEndpoint); + if (useNativeToolCalling) { bool nativeFailed = false; var nativeEnumerator = ExecWithNativeToolCallingAsync(message, ChatId, modelName, channel, executionContext, nativeTools, cancellationToken); @@ -1036,6 +1058,12 @@ private async IAsyncEnumerable ExecWithNativeToolCallingAsync( foreach (var tool in nativeTools) { completionOptions.Tools.Add(tool); } + _logger.LogInformation( + "{ServiceName}: Starting native tool call cycle. Model={Model}, ToolCount={ToolCount}, ToolNames={ToolNames}", + ServiceName, + modelName, + nativeTools.Count, + string.Join(",", nativeTools.Select(t => t.FunctionName).Take(80))); var includeEmptyReasoningContent = ShouldIncludeEmptyReasoningContent(channel, modelName); try { @@ -1050,6 +1078,13 @@ private async IAsyncEnumerable ExecWithNativeToolCallingAsync( var toolCallAccumulators = new Dictionary(); ChatFinishReason? finishReason = null; + _logger.LogDebug( + "{ServiceName}: Native cycle {Cycle} request. HistoryCount={HistoryCount}, ToolCount={ToolCount}", + ServiceName, + cycle + 1, + providerHistory.Count, + completionOptions.Tools.Count); + // --- Call LLM with tools --- await foreach (var update in chatClient.CompleteChatStreamingAsync(providerHistory, completionOptions, cancellationToken).WithCancellation(cancellationToken)) { if (cancellationToken.IsCancellationRequested) throw new TaskCanceledException(); @@ -1093,6 +1128,22 @@ private async IAsyncEnumerable ExecWithNativeToolCallingAsync( string responseText = contentBuilder.ToString().Trim(); string reasoningContent = reasoningContentBuilder.ToString().Trim(); + _logger.LogInformation( + "{ServiceName}: Native cycle {Cycle} completed. FinishReason={FinishReason}, TextLength={TextLength}, ReasoningLength={ReasoningLength}, ToolCallUpdateCount={ToolCallUpdateCount}, ToolCallMetadata={ToolCallMetadata}, TextPreview={TextPreview}", + ServiceName, + cycle + 1, + finishReason?.ToString() ?? "null", + responseText.Length, + reasoningContent.Length, + toolCallAccumulators.Count, + JsonConvert.SerializeObject(toolCallAccumulators.ToDictionary( + kvp => kvp.Key, + kvp => new { + kvp.Value.Id, + kvp.Value.Name, + ArgumentsPreview = SanitizeAndTruncateArguments(kvp.Value.Arguments.ToString()) + })), + SanitizeAndTruncateArguments(responseText, 1024)); // Check if this is a tool call response if (finishReason == ChatFinishReason.ToolCalls && toolCallAccumulators.Any()) { @@ -1146,19 +1197,25 @@ private async IAsyncEnumerable ExecWithNativeToolCallingAsync( continue; } - yield return currentMessageContentBuilder.ToString(); - // Execute each tool call (has its own inner try-catch for per-tool errors) if (chatToolCalls != null) { foreach (var toolCall in chatToolCalls) { string toolName = toolCall.FunctionName; - _logger.LogInformation("{ServiceName}: Native tool call: {ToolName} with arguments: {Arguments}", ServiceName, toolName, toolCall.FunctionArguments?.ToString()); string toolResultString; try { // Parse arguments from JSON var argsDict = DeserializeToolArgumentsForDisplay(toolCall.FunctionArguments?.ToString()); + _logger.LogInformation( + "{ServiceName}: Native tool call parsed; executing now. Tool={ToolName}, ToolCallId={ToolCallId}, ChatId={ChatId}, UserId={UserId}, MessageId={MessageId}, Arguments={Arguments}", + ServiceName, + toolName, + toolCall.Id, + ChatId, + message.FromUserId, + message.MessageId, + JsonConvert.SerializeObject(argsDict)); var toolContext = new ToolContext { ChatId = ChatId, UserId = message.FromUserId, MessageId = message.MessageId }; object toolResultObject = await McpToolHelper.ExecuteRegisteredToolAsync(toolName, argsDict, toolContext); toolResultString = McpToolHelper.ConvertToolResultToString(toolResultObject); @@ -1180,13 +1237,36 @@ private async IAsyncEnumerable ExecWithNativeToolCallingAsync( } } + yield return currentMessageContentBuilder.ToString(); + // Continue loop for next LLM call } else { + if (toolCallAccumulators.Any()) { + _logger.LogWarning( + "{ServiceName}: Native response contained tool call updates but finish reason was not ToolCalls. FinishReason={FinishReason}, ToolCallCount={ToolCallCount}", + ServiceName, + finishReason?.ToString() ?? "null", + toolCallAccumulators.Count); + } + // Not a tool call - regular text response if (!string.IsNullOrWhiteSpace(responseText)) { + _logger.LogInformation( + "{ServiceName}: Native cycle produced final text without native tool calls. FinishReason={FinishReason}, TextLength={TextLength}, ToolCount={ToolCount}, TextPreview={TextPreview}", + ServiceName, + finishReason?.ToString() ?? "null", + responseText.Length, + completionOptions.Tools.Count, + SanitizeAndTruncateArguments(responseText, 1024)); var assistantMsg = new AssistantChatMessage(responseText); SetAssistantReasoningContent(assistantMsg, reasoningContent, includeEmptyReasoningContent); providerHistory.Add(assistantMsg); + } else { + _logger.LogWarning( + "{ServiceName}: Native cycle produced empty final text and no native tool calls. FinishReason={FinishReason}, ToolCount={ToolCount}", + ServiceName, + finishReason?.ToString() ?? "null", + completionOptions.Tools.Count); } yield break; } @@ -1276,12 +1356,17 @@ private async IAsyncEnumerable ExecWithXmlToolCallingAsync( _logger.LogWarning("{ServiceName}: LLM returned multiple tool calls ({Count}). Only the first one ('{FirstToolName}') will be executed.", ServiceName, parsedToolCalls.Count, parsedToolName); } - currentMessageContentBuilder.Append(McpToolHelper.FormatToolCallDisplay(parsedToolName, toolArguments)); - yield return currentMessageContentBuilder.ToString(); - string toolResultString; bool isError = false; try { + _logger.LogInformation( + "{ServiceName}: XML tool call parsed; executing now. Tool={ToolName}, ChatId={ChatId}, UserId={UserId}, MessageId={MessageId}, Arguments={Arguments}", + ServiceName, + parsedToolName, + ChatId, + message.FromUserId, + message.MessageId, + JsonConvert.SerializeObject(toolArguments)); var toolContext = new ToolContext { ChatId = ChatId, UserId = message.FromUserId, MessageId = message.MessageId }; object toolResultObject = await McpToolHelper.ExecuteRegisteredToolAsync(parsedToolName, toolArguments, toolContext); toolResultString = McpToolHelper.ConvertToolResultToString(toolResultObject); @@ -1298,6 +1383,9 @@ private async IAsyncEnumerable ExecWithXmlToolCallingAsync( toolResultString = $"Error executing tool {parsedToolName}: {ex.GetLogSummary()}."; } + currentMessageContentBuilder.Append(McpToolHelper.FormatToolCallDisplay(parsedToolName, toolArguments)); + yield return currentMessageContentBuilder.ToString(); + string feedbackPrefix = isError ? $"[Tool '{parsedToolName}' Execution Failed. Error: " : $"[Executed Tool '{parsedToolName}'. Result: "; string feedback = $"{feedbackPrefix}{toolResultString}]"; providerHistory.Add(new UserChatMessage(feedback)); @@ -1403,17 +1491,21 @@ public async IAsyncEnumerable ResumeFromSnapshotAsync(LlmContinuationSna _logger.LogInformation("{ServiceName}: LLM requested tool (resume): {ToolName}", ServiceName, parsedToolName); - var toolIndicator = McpToolHelper.FormatToolCallDisplay(parsedToolName, toolArguments); - newContentBuilder.Append(toolIndicator); - fullContentBuilder.Append(toolIndicator); - yield return newContentBuilder.ToString(); - string toolResultString; bool isError = false; try { + _logger.LogInformation( + "{ServiceName}: XML tool call parsed during resume; executing now. Tool={ToolName}, ChatId={ChatId}, UserId={UserId}, MessageId={MessageId}, Arguments={Arguments}", + ServiceName, + parsedToolName, + snapshot.ChatId, + snapshot.UserId, + snapshot.OriginalMessageId, + JsonConvert.SerializeObject(toolArguments)); var toolContext = new ToolContext { ChatId = snapshot.ChatId, UserId = snapshot.UserId, MessageId = snapshot.OriginalMessageId }; object toolResultObject = await McpToolHelper.ExecuteRegisteredToolAsync(parsedToolName, toolArguments, toolContext); toolResultString = McpToolHelper.ConvertToolResultToString(toolResultObject); + _logger.LogInformation("{ServiceName}: Tool {ToolName} executed during resume. Result length: {Length}", ServiceName, parsedToolName, toolResultString.Length); } catch (Exception ex) { isError = true; _logger.LogError( @@ -1427,6 +1519,11 @@ public async IAsyncEnumerable ResumeFromSnapshotAsync(LlmContinuationSna toolResultString = $"Error executing tool {parsedToolName}: {ex.GetLogSummary()}."; } + var toolIndicator = McpToolHelper.FormatToolCallDisplay(parsedToolName, toolArguments); + newContentBuilder.Append(toolIndicator); + fullContentBuilder.Append(toolIndicator); + yield return newContentBuilder.ToString(); + string feedbackPrefix = isError ? $"[Tool '{parsedToolName}' Execution Failed. Error: " : $"[Executed Tool '{parsedToolName}'. Result: "; string feedback = $"{feedbackPrefix}{toolResultString}]"; providerHistory.Add(new UserChatMessage(feedback)); diff --git a/TelegramSearchBot.LLMAgent/Service/AgentLoopService.cs b/TelegramSearchBot.LLMAgent/Service/AgentLoopService.cs index 5b1a5c5c..0df14c64 100644 --- a/TelegramSearchBot.LLMAgent/Service/AgentLoopService.cs +++ b/TelegramSearchBot.LLMAgent/Service/AgentLoopService.cs @@ -104,7 +104,17 @@ public async Task RunAsync(long chatId, int port, CancellationToken cancellation var shouldStopAfterTask = false; try { - await ProcessTaskAsync(task, payload, chatId, recoveredContent, cancellationToken); + _logger.LogInformation( + "Agent loop starting task. TaskId={TaskId}, Kind={Kind}, ChatId={ChatId}, UserId={UserId}, MessageId={MessageId}, Model={Model}, RecoveryAttempt={RecoveryAttempt}, RecoveredContentLength={RecoveredContentLength}", + task.TaskId, + task.Kind, + task.ChatId, + task.UserId, + task.MessageId, + task.ModelName, + task.RecoveryAttempt, + recoveredContent?.Length ?? 0); + await ProcessTaskAsync(task, payload, chatId, recoveredContent ?? string.Empty, cancellationToken); } finally { session.Status = await IsShutdownRequestedAsync(chatId) ? "shutting_down" : "idle"; session.CurrentTaskId = string.Empty; @@ -134,8 +144,8 @@ public async Task ProcessTaskAsync( string recoveredContent, CancellationToken cancellationToken) { var sequence = 0; - var currentRecoveredContent = recoveredContent; - var latestSnapshot = recoveredContent; + var currentRecoveredContent = recoveredContent ?? string.Empty; + var latestSnapshot = currentRecoveredContent; var retryAttempt = 0; while (true) { @@ -146,13 +156,19 @@ public async Task ProcessTaskAsync( try { await foreach (var snapshot in executor.CallAsync(task, executionContext, cancellationToken).WithCancellation(cancellationToken)) { - latestSnapshot = snapshot; + var snapshotContent = snapshot ?? string.Empty; + latestSnapshot = snapshotContent; + _logger.LogDebug( + "Agent task produced snapshot. TaskId={TaskId}, Sequence={Sequence}, SnapshotLength={SnapshotLength}", + task.TaskId, + sequence, + snapshotContent.Length); await _rpcClient.SaveTaskStateAsync(task.TaskId, AgentTaskStatus.Running, null, new Dictionary { - ["lastContent"] = snapshot, + ["lastContent"] = snapshotContent, ["lastSequence"] = sequence.ToString() }); - if (!ShouldPublishSnapshot(snapshot, currentRecoveredContent, ref suppressUntilRecoveryCatchup)) { + if (!ShouldPublishSnapshot(snapshotContent, currentRecoveredContent, ref suppressUntilRecoveryCatchup)) { continue; } @@ -160,11 +176,21 @@ await _garnetClient.PublishSnapshotAsync(new AgentStreamChunk { TaskId = task.TaskId, Type = AgentChunkType.Snapshot, Sequence = sequence++, - Content = snapshot + Content = snapshotContent }); + _logger.LogDebug( + "Agent task snapshot published. TaskId={TaskId}, Sequence={Sequence}, SnapshotLength={SnapshotLength}", + task.TaskId, + sequence - 1, + snapshotContent.Length); } if (executionContext.IterationLimitReached && executionContext.SnapshotData != null) { + _logger.LogWarning( + "Agent task reached iteration limit. TaskId={TaskId}, Sequence={Sequence}, LastContentLength={LastContentLength}", + task.TaskId, + sequence, + executionContext.SnapshotData.LastAccumulatedContent?.Length ?? 0); await _garnetClient.PublishTerminalAsync(new AgentStreamChunk { TaskId = task.TaskId, Type = AgentChunkType.IterationLimitReached, @@ -180,6 +206,11 @@ await _garnetClient.PublishTerminalAsync(new AgentStreamChunk { ["transientRetryCount"] = retryAttempt.ToString() }); } else { + _logger.LogInformation( + "Agent task completed. TaskId={TaskId}, FinalSequence={Sequence}, LastContentLength={LastContentLength}", + task.TaskId, + sequence, + latestSnapshot.Length); await _garnetClient.PublishTerminalAsync(new AgentStreamChunk { TaskId = task.TaskId, Type = AgentChunkType.Done, @@ -199,6 +230,7 @@ await _garnetClient.PublishTerminalAsync(new AgentStreamChunk { var delay = _transientRetryDelayFactory(retryAttempt); currentRecoveredContent = latestSnapshot; var retryReason = ex.GetLogSummary(); + var primaryException = ex.GetPrimaryException(); _logger.LogWarning( ex, @@ -218,7 +250,7 @@ await _garnetClient.PublishTerminalAsync(new AgentStreamChunk { ["lastRetryAtUtc"] = DateTime.UtcNow.ToString("O"), ["lastRetryReason"] = retryReason, ["lastRetryDetails"] = ex.ToString(), - ["lastRetryExceptionType"] = ex.GetPrimaryException().GetType().FullName ?? ex.GetType().FullName + ["lastRetryExceptionType"] = primaryException.GetType().FullName ?? primaryException.GetType().Name }); if (delay > TimeSpan.Zero) { @@ -233,6 +265,7 @@ await _garnetClient.PublishTerminalAsync(new AgentStreamChunk { Sequence = sequence, ErrorMessage = errorSummary }); + var primaryException = ex.GetPrimaryException(); await _rpcClient.SaveTaskStateAsync(task.TaskId, AgentTaskStatus.Failed, errorSummary, new Dictionary { ["payload"] = payload, ["workerChatId"] = workerChatId.ToString(), @@ -240,7 +273,7 @@ await _garnetClient.PublishTerminalAsync(new AgentStreamChunk { ["lastContent"] = latestSnapshot, ["lastSequence"] = sequence.ToString(), ["transientRetryCount"] = retryAttempt.ToString(), - ["errorType"] = ex.GetPrimaryException().GetType().FullName ?? ex.GetType().FullName, + ["errorType"] = primaryException.GetType().FullName ?? primaryException.GetType().Name, ["errorDetails"] = ex.ToString() }); return; diff --git a/TelegramSearchBot/Service/AI/LLM/ChunkPollingService.cs b/TelegramSearchBot/Service/AI/LLM/ChunkPollingService.cs index 57b2e6c9..af068ff8 100644 --- a/TelegramSearchBot/Service/AI/LLM/ChunkPollingService.cs +++ b/TelegramSearchBot/Service/AI/LLM/ChunkPollingService.cs @@ -45,6 +45,7 @@ public ChunkPollingService(IConnectionMultiplexer redis, ILogger new TrackedTask()); + _logger.LogDebug("ChunkPollingService: tracking task {TaskId}. TrackedTaskCount={TrackedTaskCount}", taskId, _trackedTasks.Count); return tracked.Handle; } @@ -100,7 +101,12 @@ private async Task PollTaskAsync(string taskId, TrackedTask tracked, Cancellatio // Check for terminal chunk first (Done/Error/IterationLimitReached) var terminalJson = await db.StringGetAsync(LlmAgentRedisKeys.AgentTerminal(taskId)); if (terminalJson.HasValue) { - var terminal = JsonConvert.DeserializeObject(terminalJson.ToString()); + var terminalPayload = terminalJson.ToString(); + _logger.LogInformation( + "ChunkPollingService: terminal chunk found. TaskId={TaskId}, PayloadLength={PayloadLength}", + taskId, + terminalPayload.Length); + var terminal = JsonConvert.DeserializeObject(terminalPayload); if (terminal != null) { // Before completing, read the final snapshot from Redis and deliver it // so the consumer (SendDraftStream/SendFullMessageStream) sees the last content. @@ -117,11 +123,18 @@ private async Task PollTaskAsync(string taskId, TrackedTask tracked, Cancellatio tracked.Completion.TrySetResult(terminal); tracked.Channel.Writer.TryComplete(); _trackedTasks.TryRemove(taskId, out _); + _logger.LogInformation( + "ChunkPollingService: task completed from terminal chunk. TaskId={TaskId}, TerminalType={TerminalType}, Error={Error}", + taskId, + terminal.Type, + terminal.ErrorMessage); // Cleanup keys (use TTL as safety net, no race condition) _ = db.KeyDeleteAsync(LlmAgentRedisKeys.AgentSnapshot(taskId)); _ = db.KeyDeleteAsync(LlmAgentRedisKeys.AgentTerminal(taskId)); return; } + + _logger.LogWarning("ChunkPollingService: terminal chunk payload could not be deserialized. TaskId={TaskId}, PayloadPreview={PayloadPreview}", taskId, TruncateForLog(terminalPayload)); } // Check for snapshot updates @@ -142,6 +155,13 @@ private async Task PollTaskAsync(string taskId, TrackedTask tracked, Cancellatio if (chunk != null && chunk.Content != tracked.LastContent) { tracked.LastContent = chunk.Content; await tracked.Channel.Writer.WriteAsync(chunk, cancellationToken); + _logger.LogDebug( + "ChunkPollingService: delivered snapshot. TaskId={TaskId}, Sequence={Sequence}, ContentLength={ContentLength}", + taskId, + chunk.Sequence, + chunk.Content?.Length ?? 0); + } else if (chunk == null) { + _logger.LogWarning("ChunkPollingService: snapshot payload could not be deserialized. TaskId={TaskId}, PayloadPreview={PayloadPreview}", taskId, TruncateForLog(snapshotStr)); } } @@ -153,12 +173,23 @@ private async Task TryCompleteFromTaskStateAsync(string taskId, TrackedTask trac } var statusEntry = entries.FirstOrDefault(x => x.Name == "status").Value.ToString(); + if (string.IsNullOrWhiteSpace(statusEntry)) { + _logger.LogWarning("ChunkPollingService: task state missing status. TaskId={TaskId}, FieldCount={FieldCount}", taskId, entries.Length); + return; + } + if (!Enum.TryParse(statusEntry, ignoreCase: true, out var status)) { + _logger.LogWarning("ChunkPollingService: task state has unknown status. TaskId={TaskId}, Status={Status}", taskId, statusEntry); return; } if (status == AgentTaskStatus.Failed || status == AgentTaskStatus.Cancelled) { var error = entries.FirstOrDefault(x => x.Name == "error").Value.ToString(); + _logger.LogWarning( + "ChunkPollingService: completing task from failed task state. TaskId={TaskId}, Status={Status}, Error={Error}", + taskId, + status, + error); await CompleteTrackedTaskAsync(taskId, tracked, new AgentStreamChunk { TaskId = taskId, Type = AgentChunkType.Error, @@ -182,6 +213,10 @@ await tracked.Channel.Writer.WriteAsync(new AgentStreamChunk { Content = lastContent }, cancellationToken); tracked.LastContent = lastContent; + _logger.LogInformation( + "ChunkPollingService: delivered lastContent from completed task state. TaskId={TaskId}, ContentLength={ContentLength}", + taskId, + lastContent.Length); } } @@ -209,16 +244,32 @@ private async Task DeliverFinalSnapshotAsync(string taskId, TrackedTask tracked, var snapshotJson = await db.StringGetAsync(LlmAgentRedisKeys.AgentSnapshot(taskId)); if (!snapshotJson.HasValue) return; - var snapshot = JsonConvert.DeserializeObject(snapshotJson.ToString()); + var snapshotPayload = snapshotJson.ToString(); + var snapshot = JsonConvert.DeserializeObject(snapshotPayload); if (snapshot != null && !string.IsNullOrEmpty(snapshot.Content) && snapshot.Content != tracked.LastContent) { tracked.LastContent = snapshot.Content; await tracked.Channel.Writer.WriteAsync(snapshot, cancellationToken); + _logger.LogInformation( + "ChunkPollingService: delivered final snapshot. TaskId={TaskId}, Sequence={Sequence}, ContentLength={ContentLength}", + taskId, + snapshot.Sequence, + snapshot.Content.Length); + } else if (snapshot == null) { + _logger.LogWarning("ChunkPollingService: final snapshot payload could not be deserialized. TaskId={TaskId}, PayloadPreview={PayloadPreview}", taskId, TruncateForLog(snapshotPayload)); } } catch (Exception ex) { _logger.LogWarning(ex, "ChunkPollingService: failed to deliver final snapshot for task {TaskId}", taskId); } } + private static string TruncateForLog(string value, int maxLength = 512) { + if (string.IsNullOrEmpty(value) || value.Length <= maxLength) { + return value ?? string.Empty; + } + + return value.Substring(0, maxLength) + $"..."; + } + private sealed class TrackedTask { public Channel Channel { get; } = System.Threading.Channels.Channel.CreateUnbounded(); public TaskCompletionSource Completion { get; } = new(TaskCreationOptions.RunContinuationsAsynchronously);