From bb3d9bffa752e1d09c521eabd6f495b3b041dfff Mon Sep 17 00:00:00 2001 From: ModerRAS Date: Wed, 13 May 2026 12:38:30 +0800 Subject: [PATCH 1/4] Add LLM tool call diagnostics --- .../ExceptionExtensions.cs | 21 ++ .../Service/AI/LLM/AnthropicService.cs | 62 +++- .../Service/AI/LLM/GeminiService.cs | 10 +- .../Service/AI/LLM/McpToolHelper.cs | 351 ++++++++++++++---- .../Service/AI/LLM/OllamaService.cs | 10 +- .../Service/AI/LLM/OpenAIResponsesService.cs | 116 ++++-- .../Service/AI/LLM/OpenAIService.cs | 47 ++- TelegramSearchBot.LLMAgent/LLMAgentProgram.cs | 46 ++- .../Service/AgentLoopService.cs | 19 +- .../Service/ToolExecutor.cs | 46 ++- .../AppBootstrap/AppBootstrap.cs | 7 +- .../Controller/AI/LLM/GeneralLLMController.cs | 5 + .../AI/LLM/LLMIterationCallbackController.cs | 5 + TelegramSearchBot/Program.cs | 5 +- .../Service/AI/LLM/ChunkPollingService.cs | 25 +- .../Service/AI/LLM/TelegramTaskConsumer.cs | 36 +- .../BotAPI/SendMessageService.Streaming.cs | 63 +++- 17 files changed, 723 insertions(+), 151 deletions(-) create mode 100644 TelegramSearchBot.Common/ExceptionExtensions.cs diff --git a/TelegramSearchBot.Common/ExceptionExtensions.cs b/TelegramSearchBot.Common/ExceptionExtensions.cs new file mode 100644 index 00000000..cfe864c0 --- /dev/null +++ b/TelegramSearchBot.Common/ExceptionExtensions.cs @@ -0,0 +1,21 @@ +using System; +using System.Reflection; + +namespace TelegramSearchBot.Common { + public static class ExceptionExtensions { + public static Exception GetPrimaryException(this Exception exception) { + ArgumentNullException.ThrowIfNull(exception); + + while ((exception is TargetInvocationException || exception is AggregateException) && exception.InnerException != null) { + exception = exception.InnerException; + } + + return exception; + } + + public static string GetLogSummary(this Exception exception) { + var primaryException = exception.GetPrimaryException(); + return $"{primaryException.GetType().Name}: {primaryException.Message}"; + } + } +} diff --git a/TelegramSearchBot.LLM/Service/AI/LLM/AnthropicService.cs b/TelegramSearchBot.LLM/Service/AI/LLM/AnthropicService.cs index 5fb20019..9f2df347 100644 --- a/TelegramSearchBot.LLM/Service/AI/LLM/AnthropicService.cs +++ b/TelegramSearchBot.LLM/Service/AI/LLM/AnthropicService.cs @@ -591,9 +591,22 @@ private async IAsyncEnumerable ExecWithNativeToolCallingAsync( assistantContentBlocks.Add(new TextBlockParam(responseText)); } foreach (var (id, name, inputJson) in toolUseBlocks) { - var parsedInput = string.IsNullOrWhiteSpace(inputJson) - ? new Dictionary() - : System.Text.Json.JsonSerializer.Deserialize>(inputJson); + Dictionary parsedInput; + try { + parsedInput = string.IsNullOrWhiteSpace(inputJson) + ? new Dictionary() + : System.Text.Json.JsonSerializer.Deserialize>(inputJson); + } catch (Exception ex) { + _logger.LogError( + ex, + "{ServiceName}: Failed to deserialize Anthropic native tool input for assistant history. ToolUseId={ToolUseId}, ToolName={ToolName}, InputJson={InputJson}, ErrorSummary={ErrorSummary}", + ServiceName, + id, + name, + inputJson, + ex.GetLogSummary()); + parsedInput = new Dictionary(); + } assistantContentBlocks.Add(new ToolUseBlockParam { ID = id, Name = name, @@ -615,7 +628,16 @@ private async IAsyncEnumerable ExecWithNativeToolCallingAsync( try { argsDict = System.Text.Json.JsonSerializer.Deserialize>(inputJson) .ToDictionary(kv => kv.Key, kv => kv.Value.ToString()); - } catch { } + } catch (Exception ex) { + _logger.LogError( + ex, + "{ServiceName}: Failed to deserialize Anthropic native tool input for display. ToolUseId={ToolUseId}, ToolName={ToolName}, InputJson={InputJson}, ErrorSummary={ErrorSummary}", + ServiceName, + id, + name, + inputJson, + ex.GetLogSummary()); + } } argsDict ??= new Dictionary(); toolNamesBuilder.Append(McpToolHelper.FormatToolCallDisplay(name, argsDict)); @@ -642,8 +664,15 @@ private async IAsyncEnumerable ExecWithNativeToolCallingAsync( _logger.LogInformation("{ServiceName}: Tool {ToolName} executed. Result length: {Length}", ServiceName, name, toolResultString.Length); } catch (Exception ex) { isError = true; - _logger.LogError(ex, "{ServiceName}: Error executing tool {ToolName}.", ServiceName, name); - toolResultString = $"Error executing tool {name}: {ex.Message}"; + _logger.LogError( + ex, + "{ServiceName}: Error executing Anthropic native tool {ToolName}. ToolUseId={ToolUseId}, InputJson={InputJson}, ErrorSummary={ErrorSummary}", + ServiceName, + name, + id, + inputJson, + ex.GetLogSummary()); + toolResultString = $"Error executing tool {name}: {ex.GetLogSummary()}"; } toolResultBlocks.Add(new ToolResultBlockParam(id) { @@ -765,8 +794,14 @@ private async IAsyncEnumerable ExecWithXmlToolCallingAsync( _logger.LogInformation("{ServiceName}: Tool {ToolName} executed. Result: {Result}", ServiceName, parsedToolName, toolResultString); } catch (Exception ex) { isError = true; - _logger.LogError(ex, "{ServiceName}: Error executing tool {ToolName}.", ServiceName, parsedToolName); - toolResultString = $"Error executing tool {parsedToolName}: {ex.Message}."; + _logger.LogError( + ex, + "{ServiceName}: Error executing Anthropic XML tool {ToolName}. Arguments={Arguments}, ErrorSummary={ErrorSummary}", + ServiceName, + parsedToolName, + JsonConvert.SerializeObject(toolArguments), + ex.GetLogSummary()); + toolResultString = $"Error executing tool {parsedToolName}: {ex.GetLogSummary()}."; } string feedbackPrefix = isError ? $"[Tool '{parsedToolName}' Execution Failed. Error: " : $"[Executed Tool '{parsedToolName}'. Result: "; @@ -896,8 +931,15 @@ public async IAsyncEnumerable ResumeFromSnapshotAsync( toolResultString = McpToolHelper.ConvertToolResultToString(toolResultObject); } catch (Exception ex) { isError = true; - _logger.LogError(ex, "{ServiceName}: Error executing tool {ToolName} (resume).", ServiceName, parsedToolName); - toolResultString = $"Error executing tool {parsedToolName}: {ex.Message}."; + _logger.LogError( + ex, + "{ServiceName}: Error executing Anthropic XML tool {ToolName} (resume). Arguments={Arguments}, SnapshotId={SnapshotId}, ErrorSummary={ErrorSummary}", + ServiceName, + parsedToolName, + JsonConvert.SerializeObject(firstToolCall.arguments), + snapshot.SnapshotId, + ex.GetLogSummary()); + toolResultString = $"Error executing tool {parsedToolName}: {ex.GetLogSummary()}."; } string feedbackPrefix = isError ? $"[Tool '{parsedToolName}' Execution Failed. Error: " : $"[Executed Tool '{parsedToolName}'. Result: "; diff --git a/TelegramSearchBot.LLM/Service/AI/LLM/GeminiService.cs b/TelegramSearchBot.LLM/Service/AI/LLM/GeminiService.cs index a6fbcc5c..827e9c13 100644 --- a/TelegramSearchBot.LLM/Service/AI/LLM/GeminiService.cs +++ b/TelegramSearchBot.LLM/Service/AI/LLM/GeminiService.cs @@ -437,8 +437,14 @@ public async IAsyncEnumerable ExecAsync( toolResult = McpToolHelper.ConvertToolResultToString(result); } catch (Exception ex) { isError = true; - _logger.LogError(ex, "Error executing tool {ToolName}", firstToolCall.toolName); - toolResult = $"Error executing tool {firstToolCall.toolName}: {ex.Message}"; + _logger.LogError( + ex, + "{ServiceName}: Error executing Gemini XML tool {ToolName}. Arguments={Arguments}, ErrorSummary={ErrorSummary}", + ServiceName, + firstToolCall.toolName, + JsonConvert.SerializeObject(firstToolCall.arguments), + ex.GetLogSummary()); + toolResult = $"Error executing tool {firstToolCall.toolName}: {ex.GetLogSummary()}"; } string feedback = isError diff --git a/TelegramSearchBot.LLM/Service/AI/LLM/McpToolHelper.cs b/TelegramSearchBot.LLM/Service/AI/LLM/McpToolHelper.cs index e66890c3..7e7c3ee5 100644 --- a/TelegramSearchBot.LLM/Service/AI/LLM/McpToolHelper.cs +++ b/TelegramSearchBot.LLM/Service/AI/LLM/McpToolHelper.cs @@ -1,6 +1,7 @@ using System; using System.Collections.Concurrent; using System.Collections.Generic; +using System.Diagnostics; using System.Globalization; using System.Linq; using System.Reflection; @@ -12,6 +13,7 @@ using Microsoft.Extensions.Logging; using Newtonsoft.Json; using TelegramSearchBot.Attributes; +using TelegramSearchBot.Common; using TelegramSearchBot.Model; using TelegramSearchBot.Model.AI; using TelegramSearchBot.Model.Tools; @@ -34,6 +36,8 @@ public static class McpToolHelper { private static string _sCachedProxyToolsXml; private static bool _sIsInitialized = false; private static readonly object _initializationLock = new object(); + private const int MaxToolLogValueLength = 2048; + private const int MaxToolLogPayloadLength = 8192; /// /// Information about an external tool from an MCP server. @@ -699,95 +703,270 @@ public static async Task ExecuteRegisteredToolAsync(string toolName, Dic /// Use the scoped overload when executing tools that require scoped services (e.g., DbContext). /// public static async Task ExecuteRegisteredToolAsync(string toolName, Dictionary stringArguments, IServiceProvider scopedProvider, ToolContext toolContext = null) { + var elapsed = Stopwatch.StartNew(); + var originalArguments = stringArguments ?? new Dictionary(StringComparer.OrdinalIgnoreCase); + var route = GetToolRoute(toolName); + _sLogger?.LogDebug( + "Tool execution requested. Tool={ToolName}, Route={Route}, ChatId={ChatId}, UserId={UserId}, MessageId={MessageId}, ArgumentKeys={ArgumentKeys}, ArgumentPreview={ArgumentPreview}", + toolName, + route, + toolContext?.ChatId, + toolContext?.UserId, + toolContext?.MessageId, + string.Join(",", originalArguments.Keys), + FormatArgumentsForLog(originalArguments)); + _sLogger?.LogTrace( + "Tool execution full argument snapshot. Tool={ToolName}, Arguments={Arguments}", + toolName, + FormatArgumentsForLog(originalArguments, MaxToolLogPayloadLength)); + // Clean CDATA markers if present and trim values - var cleanedArguments = new Dictionary(); - foreach (var kvp in stringArguments) { + var cleanedArguments = new Dictionary(StringComparer.OrdinalIgnoreCase); + foreach (var kvp in originalArguments) { var value = kvp.Value; - value = Regex.Replace(value, @"", "$1").Trim(); + value = Regex.Replace(value ?? string.Empty, @"", "$1").Trim(); cleanedArguments[kvp.Key] = value; } stringArguments = cleanedArguments; - // Check if this is a proxy tool (routed to remote process via IPC) - if (ProxyToolRegistry.ContainsKey(toolName) && _proxyToolExecutor != null) { - var proxyArguments = new Dictionary(stringArguments, StringComparer.OrdinalIgnoreCase); - if (toolContext != null) { - proxyArguments["__chatId"] = toolContext.ChatId.ToString(CultureInfo.InvariantCulture); - proxyArguments["__userId"] = toolContext.UserId.ToString(CultureInfo.InvariantCulture); - proxyArguments["__messageId"] = toolContext.MessageId.ToString(CultureInfo.InvariantCulture); + try { + // Check if this is a proxy tool (routed to remote process via IPC) + if (ProxyToolRegistry.ContainsKey(toolName) && _proxyToolExecutor != null) { + var proxyArguments = new Dictionary(stringArguments, StringComparer.OrdinalIgnoreCase); + if (toolContext != null) { + proxyArguments["__chatId"] = toolContext.ChatId.ToString(CultureInfo.InvariantCulture); + proxyArguments["__userId"] = toolContext.UserId.ToString(CultureInfo.InvariantCulture); + proxyArguments["__messageId"] = toolContext.MessageId.ToString(CultureInfo.InvariantCulture); + } + + _sLogger?.LogInformation( + "Executing proxy tool via agent IPC. Tool={ToolName}, ChatId={ChatId}, UserId={UserId}, MessageId={MessageId}, Arguments={Arguments}", + toolName, + toolContext?.ChatId, + toolContext?.UserId, + toolContext?.MessageId, + FormatArgumentsForLog(stringArguments)); + var proxyResult = await _proxyToolExecutor(toolName, proxyArguments); + _sLogger?.LogInformation( + "Proxy tool completed. Tool={ToolName}, ElapsedMs={ElapsedMs}, ResultLength={ResultLength}, ResultPreview={ResultPreview}", + toolName, + elapsed.ElapsedMilliseconds, + proxyResult?.Length ?? 0, + TruncateForLog(proxyResult)); + return proxyResult; } - var proxyResult = await _proxyToolExecutor(toolName, proxyArguments); - return proxyResult; - } + // Check if this is an external MCP tool + if (ExternalToolRegistry.TryGetValue(toolName, out var externalTool)) { + var externalResult = await ExecuteExternalToolAsync(toolName, externalTool, stringArguments); + _sLogger?.LogInformation( + "External MCP tool completed. Tool={ToolName}, Server={ServerName}, ElapsedMs={ElapsedMs}, ResultType={ResultType}, ResultPreview={ResultPreview}", + toolName, + externalTool.ServerName, + elapsed.ElapsedMilliseconds, + externalResult?.GetType().FullName ?? "null", + TruncateForLog(ConvertToolResultToString(externalResult))); + return externalResult; + } - // Check if this is an external MCP tool - if (ExternalToolRegistry.TryGetValue(toolName, out var externalTool)) { - return await ExecuteExternalToolAsync(toolName, externalTool, stringArguments); - } + if (!ToolRegistry.TryGetValue(toolName, out var toolInfo)) { + _sLogger?.LogError( + "Tool is not registered. Tool={ToolName}, Route={Route}, BuiltInCount={BuiltInCount}, ExternalCount={ExternalCount}, ProxyCount={ProxyCount}, AvailableTools={AvailableTools}, Arguments={Arguments}", + toolName, + route, + ToolRegistry.Count, + ExternalToolRegistry.Count, + ProxyToolRegistry.Count, + GetAvailableToolNamesForLog(), + FormatArgumentsForLog(stringArguments)); + throw new ArgumentException($"Tool '{toolName}' not registered."); + } - if (!ToolRegistry.TryGetValue(toolName, out var toolInfo)) { - throw new ArgumentException($"Tool '{toolName}' not registered."); - } + var method = toolInfo.Method; + var owningType = toolInfo.OwningType; + var methodParams = method.GetParameters(); + var convertedArgs = new object[methodParams.Length]; + + _sLogger?.LogDebug( + "Resolving local tool method. Tool={ToolName}, Type={TypeName}, Method={MethodName}, IsStatic={IsStatic}, Parameters={Parameters}, ScopedProvider={ScopedProviderType}, RootProvider={RootProviderType}", + toolName, + owningType.FullName, + method.Name, + method.IsStatic, + string.Join(",", methodParams.Select(p => $"{p.Name}:{p.ParameterType.Name}")), + scopedProvider?.GetType().FullName ?? "null", + _sServiceProvider?.GetType().FullName ?? "null"); + + for (int i = 0; i < methodParams.Length; i++) { + var paramInfo = methodParams[i]; + if (paramInfo.ParameterType == typeof(ToolContext)) { + convertedArgs[i] = toolContext; + _sLogger?.LogTrace("Injected ToolContext for tool parameter. Tool={ToolName}, Parameter={ParameterName}", toolName, paramInfo.Name); + continue; + } - var method = toolInfo.Method; - var owningType = toolInfo.OwningType; - var methodParams = method.GetParameters(); - var convertedArgs = new object[methodParams.Length]; + if (paramInfo.Name != null && stringArguments.TryGetValue(paramInfo.Name, out var stringValue)) { + convertedArgs[i] = ConvertArgumentValue(stringValue, paramInfo.ParameterType, paramInfo.Name); + _sLogger?.LogTrace( + "Converted tool argument. Tool={ToolName}, Parameter={ParameterName}, TargetType={TargetType}, ValuePreview={ValuePreview}", + toolName, + paramInfo.Name, + paramInfo.ParameterType.FullName, + TruncateForLog(stringValue)); + } else if (paramInfo.HasDefaultValue) { + convertedArgs[i] = paramInfo.DefaultValue; + _sLogger?.LogDebug("Using default value for missing tool parameter. Tool={ToolName}, Parameter={ParameterName}", toolName, paramInfo.Name); + } else if (paramInfo.IsOptional) { + convertedArgs[i] = Type.Missing; + _sLogger?.LogDebug("Using Type.Missing for optional tool parameter. Tool={ToolName}, Parameter={ParameterName}", toolName, paramInfo.Name); + } else { + // Check both attribute types + var builtInParamAttr = paramInfo.GetCustomAttribute(); + var mcpParamAttr = paramInfo.GetCustomAttribute(); + bool isActuallyRequired = builtInParamAttr?.IsRequired ?? mcpParamAttr?.IsRequired ?? ( !paramInfo.IsOptional && !paramInfo.HasDefaultValue && !( paramInfo.ParameterType.IsValueType && Nullable.GetUnderlyingType(paramInfo.ParameterType) == null ) ); + if (isActuallyRequired) { + _sLogger?.LogError( + "Missing required tool parameter. Tool={ToolName}, Parameter={ParameterName}, AvailableArgumentKeys={ArgumentKeys}, Arguments={Arguments}", + toolName, + paramInfo.Name, + string.Join(",", stringArguments.Keys), + FormatArgumentsForLog(stringArguments)); + throw new ArgumentException($"Missing required parameter '{paramInfo.Name}' for tool '{toolName}'."); + } else { + convertedArgs[i] = null; + } + } + } - for (int i = 0; i < methodParams.Length; i++) { - var paramInfo = methodParams[i]; - if (paramInfo.ParameterType == typeof(ToolContext)) { - convertedArgs[i] = toolContext; - continue; + // Use scoped provider if available, fallback to root provider + var provider = scopedProvider ?? _sServiceProvider; + object instance = null; + if (!method.IsStatic) { + if (provider != null) { + instance = provider.GetService(owningType); + if (instance == null) { + _sLogger?.LogWarning( + "DI did not resolve local tool type; trying parameterless constructor. Tool={ToolName}, Type={TypeName}, Provider={ProviderType}", + toolName, + owningType.FullName, + provider.GetType().FullName); + if (owningType.GetConstructor(Type.EmptyTypes) != null) + instance = Activator.CreateInstance(owningType); + } + } else if (owningType.GetConstructor(Type.EmptyTypes) != null) { + _sLogger?.LogWarning( + "No IServiceProvider available; creating local tool type via parameterless constructor. Tool={ToolName}, Type={TypeName}", + toolName, + owningType.FullName); + instance = Activator.CreateInstance(owningType); + } + + if (instance == null) + throw new InvalidOperationException($"Could not create an instance of type '{owningType.FullName}' to execute non-static tool '{toolName}'. Ensure McpToolHelper.EnsureInitialized was called with a valid IServiceProvider and the type is registered in DI or has a parameterless constructor."); } - if (stringArguments.TryGetValue(paramInfo.Name, out var stringValue)) { - convertedArgs[i] = ConvertArgumentValue(stringValue, paramInfo.ParameterType, paramInfo.Name); - } else if (paramInfo.HasDefaultValue) { - convertedArgs[i] = paramInfo.DefaultValue; - } else if (paramInfo.IsOptional) { - convertedArgs[i] = Type.Missing; + var result = method.Invoke(instance, convertedArgs); + + object finalResult; + if (result is Task taskResult) { + await taskResult; + if (taskResult.GetType().IsGenericType) { + finalResult = ( ( dynamic ) taskResult ).Result; + } else { + finalResult = null; + } } else { - // Check both attribute types - var builtInParamAttr = paramInfo.GetCustomAttribute(); - var mcpParamAttr = paramInfo.GetCustomAttribute(); - bool isActuallyRequired = builtInParamAttr?.IsRequired ?? mcpParamAttr?.IsRequired ?? ( !paramInfo.IsOptional && !paramInfo.HasDefaultValue && !( paramInfo.ParameterType.IsValueType && Nullable.GetUnderlyingType(paramInfo.ParameterType) == null ) ); - if (isActuallyRequired) - throw new ArgumentException($"Missing required parameter '{paramInfo.Name}' for tool '{toolName}'."); - else - convertedArgs[i] = null; + finalResult = result; } + + _sLogger?.LogInformation( + "Local tool completed. Tool={ToolName}, Type={TypeName}, Method={MethodName}, ElapsedMs={ElapsedMs}, ResultType={ResultType}, ResultPreview={ResultPreview}", + toolName, + owningType.FullName, + method.Name, + elapsed.ElapsedMilliseconds, + finalResult?.GetType().FullName ?? "null", + TruncateForLog(ConvertToolResultToString(finalResult))); + return finalResult; + } catch (Exception ex) { + _sLogger?.LogError( + ex, + "Tool execution failed. Tool={ToolName}, Route={Route}, ChatId={ChatId}, UserId={UserId}, MessageId={MessageId}, ElapsedMs={ElapsedMs}, ErrorSummary={ErrorSummary}, Arguments={Arguments}, AvailableTools={AvailableTools}", + toolName, + route, + toolContext?.ChatId, + toolContext?.UserId, + toolContext?.MessageId, + elapsed.ElapsedMilliseconds, + ex.GetLogSummary(), + FormatArgumentsForLog(stringArguments), + GetAvailableToolNamesForLog()); + throw; } + } - // Use scoped provider if available, fallback to root provider - var provider = scopedProvider ?? _sServiceProvider; - object instance = null; - if (!method.IsStatic) { - if (provider != null) { - instance = provider.GetService(owningType); - if (instance == null) { - if (owningType.GetConstructor(Type.EmptyTypes) != null) - instance = Activator.CreateInstance(owningType); - } - } else if (owningType.GetConstructor(Type.EmptyTypes) != null) { - instance = Activator.CreateInstance(owningType); - } + private static string GetToolRoute(string toolName) { + if (string.IsNullOrWhiteSpace(toolName)) { + return "EmptyName"; + } - if (instance == null) - throw new InvalidOperationException($"Could not create an instance of type '{owningType.FullName}' to execute non-static tool '{toolName}'. Ensure McpToolHelper.EnsureInitialized was called with a valid IServiceProvider and the type is registered in DI or has a parameterless constructor."); + if (ProxyToolRegistry.ContainsKey(toolName)) { + return _proxyToolExecutor == null ? "ProxyMissingExecutor" : "Proxy"; } - var result = method.Invoke(instance, convertedArgs); + if (ExternalToolRegistry.ContainsKey(toolName)) { + return _externalToolExecutor == null ? "ExternalMcpMissingExecutor" : "ExternalMcp"; + } - if (result is Task taskResult) { - await taskResult; - if (taskResult.GetType().IsGenericType) { - return ( ( dynamic ) taskResult ).Result; - } - return null; + if (ToolRegistry.ContainsKey(toolName)) { + return "Local"; } - return result; + + return "Unregistered"; + } + + private static string GetAvailableToolNamesForLog() { + var toolNames = ToolRegistry.Keys + .Concat(ExternalToolRegistry.Keys) + .Concat(ProxyToolRegistry.Keys) + .Distinct(StringComparer.OrdinalIgnoreCase) + .OrderBy(x => x, StringComparer.OrdinalIgnoreCase) + .Take(80) + .ToList(); + var suffix = ToolRegistry.Count + ExternalToolRegistry.Count + ProxyToolRegistry.Count > toolNames.Count + ? ",..." + : string.Empty; + return string.Join(",", toolNames) + suffix; + } + + private static string FormatArgumentsForLog(IDictionary arguments, int maxPayloadLength = MaxToolLogValueLength) { + if (arguments == null || arguments.Count == 0) { + return "{}"; + } + + try { + var sanitized = arguments.ToDictionary( + kvp => kvp.Key, + kvp => TruncateForLog(kvp.Value, MaxToolLogValueLength), + StringComparer.OrdinalIgnoreCase); + return TruncateForLog(JsonConvert.SerializeObject(sanitized), maxPayloadLength); + } catch (Exception ex) { + _sLogger?.LogWarning(ex, "Failed to serialize tool arguments for logging."); + return $""; + } + } + + private static string TruncateForLog(string value, int maxLength = MaxToolLogValueLength) { + if (value == null) { + return "null"; + } + + value = value.Replace("\r", "\\r").Replace("\n", "\\n"); + if (value.Length <= maxLength) { + return value; + } + + return value.Substring(0, maxLength) + $"..."; } private static object ConvertArgumentValue(string stringValue, Type targetType, string paramNameForError) { @@ -949,13 +1128,32 @@ private static async Task ExecuteExternalToolAsync(string qualifiedToolN throw new InvalidOperationException("External tool executor is not configured."); } - _sLogger?.LogInformation("Executing external MCP tool: {ToolName} on server {ServerName}", qualifiedToolName, toolInfo.ServerName); + _sLogger?.LogInformation( + "Executing external MCP tool. QualifiedTool={QualifiedToolName}, Server={ServerName}, ServerTool={ServerToolName}, Arguments={Arguments}", + qualifiedToolName, + toolInfo.ServerName, + toolInfo.ToolName, + FormatArgumentsForLog(arguments)); try { var result = await _externalToolExecutor(toolInfo.ServerName, toolInfo.ToolName, arguments); + _sLogger?.LogInformation( + "External MCP tool returned. QualifiedTool={QualifiedToolName}, Server={ServerName}, ServerTool={ServerToolName}, ResultLength={ResultLength}, ResultPreview={ResultPreview}", + qualifiedToolName, + toolInfo.ServerName, + toolInfo.ToolName, + result?.Length ?? 0, + TruncateForLog(result)); return result; } catch (Exception ex) { - _sLogger?.LogError(ex, "Error executing external MCP tool: {ToolName}", qualifiedToolName); + _sLogger?.LogError( + ex, + "Error executing external MCP tool. QualifiedTool={QualifiedToolName}, Server={ServerName}, ServerTool={ServerToolName}, ErrorSummary={ErrorSummary}, Arguments={Arguments}", + qualifiedToolName, + toolInfo.ServerName, + toolInfo.ToolName, + ex.GetLogSummary(), + FormatArgumentsForLog(arguments)); throw; } } @@ -986,6 +1184,7 @@ public static void RegisterExternalMcpTools(Interface.Mcp.IMcpServerManager mcpS // Clear stale registrations if no tools available ExternalToolRegistry.Clear(); _sCachedExternalToolsXml = string.Empty; + _sLogger?.LogInformation("No external MCP tools available; cleared external tool registry."); return; } @@ -1076,6 +1275,11 @@ public static async Task RefreshAgentToolDefsInRedisAsync(StackExchange.Redis.IC var json = JsonConvert.SerializeObject(toolDefs); await redis.GetDatabase().StringSetAsync( LlmAgentRedisKeys.AgentToolDefs, json, TimeSpan.FromHours(24)); + _sLogger?.LogInformation( + "Exported agent tool definitions to Redis. Count={Count}, PayloadBytes={PayloadBytes}, ToolNames={ToolNames}", + toolDefs.Count, + Encoding.UTF8.GetByteCount(json), + string.Join(",", toolDefs.Select(t => t.Name).Take(80))); } /// @@ -1091,10 +1295,12 @@ public static void RegisterProxyTools( var sb = new StringBuilder(); int registered = 0; + int skippedLocal = 0; foreach (var tool in toolDefinitions) { // Skip tools already registered locally if (ToolRegistry.ContainsKey(tool.Name)) { + skippedLocal++; continue; } @@ -1121,8 +1327,13 @@ public static void RegisterProxyTools( } _sCachedProxyToolsXml = sb.ToString(); - _sLogger?.LogInformation("Registered {Count} proxy tools (skipped {Skipped} locally available)", - registered, toolDefinitions.Count - registered); + _sLogger?.LogInformation( + "Registered proxy tools for agent process. Registered={RegisteredCount}, Provided={ProvidedCount}, SkippedLocal={SkippedLocalCount}, ProxyRegistryCount={ProxyRegistryCount}, ToolNames={ToolNames}", + registered, + toolDefinitions.Count, + skippedLocal, + ProxyToolRegistry.Count, + string.Join(",", ProxyToolRegistry.Keys.OrderBy(x => x, StringComparer.OrdinalIgnoreCase).Take(80))); } } } diff --git a/TelegramSearchBot.LLM/Service/AI/LLM/OllamaService.cs b/TelegramSearchBot.LLM/Service/AI/LLM/OllamaService.cs index 6cd1560b..37425e36 100644 --- a/TelegramSearchBot.LLM/Service/AI/LLM/OllamaService.cs +++ b/TelegramSearchBot.LLM/Service/AI/LLM/OllamaService.cs @@ -214,8 +214,14 @@ public async IAsyncEnumerable ExecAsync(Model.Data.Message message, long _logger.LogInformation("{ServiceName}: Tool {ToolName} executed. Result: {Result}", ServiceName, parsedToolName, toolResultString); } catch (Exception ex) { isError = true; - _logger.LogError(ex, "{ServiceName}: Error executing tool {ToolName}.", ServiceName, parsedToolName); - toolResultString = $"Error executing tool {parsedToolName}: {ex.Message}."; + _logger.LogError( + ex, + "{ServiceName}: Error executing Ollama XML tool {ToolName}. Arguments={Arguments}, ErrorSummary={ErrorSummary}", + ServiceName, + parsedToolName, + JsonConvert.SerializeObject(toolArguments), + ex.GetLogSummary()); + toolResultString = $"Error executing tool {parsedToolName}: {ex.GetLogSummary()}."; } string feedbackPrefix = isError ? $"[Tool '{parsedToolName}' Execution Failed. Error: " : $"[Executed Tool '{parsedToolName}'. Result: "; diff --git a/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIResponsesService.cs b/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIResponsesService.cs index cc80ef00..18440e7b 100644 --- a/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIResponsesService.cs +++ b/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIResponsesService.cs @@ -253,20 +253,44 @@ private async IAsyncEnumerable ExecWithResponsesApiAsync( var toolIndicators = new StringBuilder(); foreach (var funcCall in completedFuncCalls) { - string callId = funcCall.CallId; - string name = funcCall.FunctionName; - string argsJson = funcCall.FunctionArguments?.ToString() ?? "{}"; + string rawCallId = funcCall.CallId; + string rawName = funcCall.FunctionName; + string rawArgsJson = funcCall.FunctionArguments?.ToString() ?? "{}"; + string callId = rawCallId; + string name = rawName; + string argsJson = rawArgsJson; // Normalize callId = OpenAIService.NormalizeToolCallId(callId); name = OpenAIService.NormalizeToolCallName(name); argsJson = OpenAIService.NormalizeToolCallArguments(argsJson); - - // Add function call item to history - inputItems.Add(ResponseItem.CreateFunctionCallItem( + _logger.LogDebug( + "{ServiceName}: Responses API function call metadata normalized. RawCallId={RawCallId}, CallId={CallId}, RawName={RawName}, Name={Name}, RawArguments={RawArguments}, Arguments={Arguments}", + ServiceName, + rawCallId, callId, + rawName, name, - BinaryData.FromString(argsJson))); + rawArgsJson, + argsJson); + + // Add function call item to history + try { + inputItems.Add(ResponseItem.CreateFunctionCallItem( + callId, + name, + BinaryData.FromString(argsJson))); + } catch (Exception ex) { + _logger.LogError( + ex, + "{ServiceName}: Failed to create Responses API function call item. CallId={CallId}, ToolName={ToolName}, Arguments={Arguments}, ErrorSummary={ErrorSummary}", + ServiceName, + callId, + name, + argsJson, + ex.GetLogSummary()); + throw; + } // Format tool call display var argsDict = OpenAIService.DeserializeToolArgumentsForDisplay(argsJson); @@ -288,8 +312,15 @@ private async IAsyncEnumerable ExecWithResponsesApiAsync( _logger.LogInformation("{ServiceName}: Tool {ToolName} executed. Result length: {Length}", ServiceName, name, toolResultString.Length); } catch (Exception ex) { - _logger.LogError(ex, "{ServiceName}: Error executing tool {ToolName}.", ServiceName, name); - toolResultString = $"Error executing tool {name}: {ex.Message}"; + _logger.LogError( + ex, + "{ServiceName}: Error executing Responses API tool {ToolName}. CallId={CallId}, Arguments={Arguments}, ErrorSummary={ErrorSummary}", + ServiceName, + name, + callId, + argsJson, + ex.GetLogSummary()); + toolResultString = $"Error executing tool {name}: {ex.GetLogSummary()}"; } // Add function call output to history @@ -443,13 +474,38 @@ public async IAsyncEnumerable ResumeFromSnapshotAsync( } foreach (var funcCall in completedFuncCalls) { - string callId = OpenAIService.NormalizeToolCallId(funcCall.CallId); - string name = OpenAIService.NormalizeToolCallName(funcCall.FunctionName); - string argsJson = OpenAIService.NormalizeToolCallArguments(funcCall.FunctionArguments?.ToString() ?? "{}"); + string rawCallId = funcCall.CallId; + string rawName = funcCall.FunctionName; + string rawArgsJson = funcCall.FunctionArguments?.ToString() ?? "{}"; + string callId = OpenAIService.NormalizeToolCallId(rawCallId); + string name = OpenAIService.NormalizeToolCallName(rawName); + string argsJson = OpenAIService.NormalizeToolCallArguments(rawArgsJson); + _logger.LogDebug( + "{ServiceName}: Responses API resume function call metadata normalized. RawCallId={RawCallId}, CallId={CallId}, RawName={RawName}, Name={Name}, RawArguments={RawArguments}, Arguments={Arguments}", + ServiceName, + rawCallId, + callId, + rawName, + name, + rawArgsJson, + argsJson); - inputItems.Add(ResponseItem.CreateFunctionCallItem( - callId, name, - BinaryData.FromString(argsJson))); + try { + inputItems.Add(ResponseItem.CreateFunctionCallItem( + callId, name, + BinaryData.FromString(argsJson))); + } catch (Exception ex) { + _logger.LogError( + ex, + "{ServiceName}: Failed to create Responses API function call item during resume. CallId={CallId}, ToolName={ToolName}, Arguments={Arguments}, SnapshotId={SnapshotId}, ErrorSummary={ErrorSummary}", + ServiceName, + callId, + name, + argsJson, + snapshot.SnapshotId, + ex.GetLogSummary()); + throw; + } var argsDict = OpenAIService.DeserializeToolArgumentsForDisplay(argsJson); var toolIndicator = McpToolHelper.FormatToolCallDisplay(name, argsDict); @@ -467,8 +523,16 @@ public async IAsyncEnumerable ResumeFromSnapshotAsync( object toolResultObject = await McpToolHelper.ExecuteRegisteredToolAsync(name, argsDict, toolContext); toolResultString = McpToolHelper.ConvertToolResultToString(toolResultObject); } catch (Exception ex) { - _logger.LogError(ex, "{ServiceName}: Error executing tool {ToolName} (resume).", ServiceName, name); - toolResultString = $"Error executing tool {name}: {ex.Message}."; + _logger.LogError( + ex, + "{ServiceName}: Error executing Responses API tool {ToolName} (resume). CallId={CallId}, Arguments={Arguments}, SnapshotId={SnapshotId}, ErrorSummary={ErrorSummary}", + ServiceName, + name, + callId, + argsJson, + snapshot.SnapshotId, + ex.GetLogSummary()); + toolResultString = $"Error executing tool {name}: {ex.GetLogSummary()}."; } inputItems.Add(ResponseItem.CreateFunctionCallOutputItem(callId, toolResultString)); @@ -1133,18 +1197,24 @@ private static List DeserializeResponseItemsFromSnapshot(List 0 ? parts[0] : ""; - string name = parts.Length > 1 ? parts[1] : "unknown"; - string argsJson = parts.Length > 2 ? parts[2] : "{}"; + var payload = content.StartsWith(FuncCallMarker) + ? content.Substring(FuncCallMarker.Length) + : content; + var parts = payload.Split(new[] { "||" }, 3, StringSplitOptions.None); + string callId = OpenAIService.NormalizeToolCallId(parts.Length > 0 ? parts[0] : ""); + string name = OpenAIService.NormalizeToolCallName(parts.Length > 1 ? parts[1] : "unknown"); + string argsJson = OpenAIService.NormalizeToolCallArguments(parts.Length > 2 ? parts[2] : "{}"); result.Add(ResponseItem.CreateFunctionCallItem( callId, name, BinaryData.FromString(argsJson))); } else if (msg.Role == "__func_output__" || content.StartsWith(FuncOutputMarker)) { // Format: __FUNC_OUTPUT__||callId||output - var parts = content.Substring(FuncOutputMarker.Length).Split(new[] { "||" }, 2, StringSplitOptions.None); - string callId = parts.Length > 0 ? parts[0] : ""; + var payload = content.StartsWith(FuncOutputMarker) + ? content.Substring(FuncOutputMarker.Length) + : content; + var parts = payload.Split(new[] { "||" }, 2, StringSplitOptions.None); + string callId = OpenAIService.NormalizeToolCallId(parts.Length > 0 ? parts[0] : ""); string output = parts.Length > 1 ? parts[1] : ""; result.Add(ResponseItem.CreateFunctionCallOutputItem(callId, output)); } else { diff --git a/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIService.cs b/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIService.cs index 3c614a0c..c71f4f45 100644 --- a/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIService.cs +++ b/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIService.cs @@ -1105,7 +1105,20 @@ private async IAsyncEnumerable ExecWithNativeToolCallingAsync( } currentMessageContentBuilder.Append(toolIndicators.ToString()); } catch (Exception ex) { - _logger.LogError(ex, "{ServiceName}: Error building tool calls, returning error to LLM for self-correction", ServiceName); + _logger.LogError( + ex, + "{ServiceName}: Error building native tool calls, returning error to LLM for self-correction. FinishReason={FinishReason}, ToolCallCount={ToolCallCount}, ToolCallMetadata={ToolCallMetadata}, ErrorSummary={ErrorSummary}", + ServiceName, + finishReason, + toolCallAccumulators.Count, + JsonConvert.SerializeObject(toolCallAccumulators.ToDictionary( + kvp => kvp.Key, + kvp => new { + kvp.Value.Id, + kvp.Value.Name, + Arguments = kvp.Value.Arguments.ToString() + })), + ex.GetLogSummary()); const string errorMsg = "Tool call failed before execution due to malformed tool metadata. Please verify the tool name and parameters, then try again."; providerHistory.Add(new UserChatMessage(errorMsg)); continue; @@ -1129,8 +1142,15 @@ private async IAsyncEnumerable ExecWithNativeToolCallingAsync( toolResultString = McpToolHelper.ConvertToolResultToString(toolResultObject); _logger.LogInformation("{ServiceName}: Tool {ToolName} executed. Result length: {Length}", ServiceName, toolName, toolResultString.Length); } catch (Exception ex) { - _logger.LogError(ex, "{ServiceName}: Error executing tool {ToolName}.", ServiceName, toolName); - toolResultString = $"Error executing tool {toolName}: {ex.Message}"; + _logger.LogError( + ex, + "{ServiceName}: Error executing native tool {ToolName}. ToolCallId={ToolCallId}, Arguments={Arguments}, ErrorSummary={ErrorSummary}", + ServiceName, + toolName, + toolCall.Id, + toolCall.FunctionArguments?.ToString(), + ex.GetLogSummary()); + toolResultString = $"Error executing tool {toolName}: {ex.GetLogSummary()}"; } // Add tool result to history using the proper ToolChatMessage @@ -1247,8 +1267,14 @@ private async IAsyncEnumerable ExecWithXmlToolCallingAsync( _logger.LogInformation("{ServiceName}: Tool {ToolName} executed. Result: {Result}", ServiceName, parsedToolName, toolResultString); } catch (Exception ex) { isError = true; - _logger.LogError(ex, "{ServiceName}: Error executing tool {ToolName}.", ServiceName, parsedToolName); - toolResultString = $"Error executing tool {parsedToolName}: {ex.Message}."; + _logger.LogError( + ex, + "{ServiceName}: Error executing XML tool {ToolName}. Arguments={Arguments}, ErrorSummary={ErrorSummary}", + ServiceName, + parsedToolName, + JsonConvert.SerializeObject(toolArguments), + ex.GetLogSummary()); + toolResultString = $"Error executing tool {parsedToolName}: {ex.GetLogSummary()}."; } string feedbackPrefix = isError ? $"[Tool '{parsedToolName}' Execution Failed. Error: " : $"[Executed Tool '{parsedToolName}'. Result: "; @@ -1368,8 +1394,15 @@ public async IAsyncEnumerable ResumeFromSnapshotAsync(LlmContinuationSna toolResultString = McpToolHelper.ConvertToolResultToString(toolResultObject); } catch (Exception ex) { isError = true; - _logger.LogError(ex, "{ServiceName}: Error executing tool {ToolName} (resume).", ServiceName, parsedToolName); - toolResultString = $"Error executing tool {parsedToolName}: {ex.Message}."; + _logger.LogError( + ex, + "{ServiceName}: Error executing XML tool {ToolName} (resume). Arguments={Arguments}, SnapshotId={SnapshotId}, ErrorSummary={ErrorSummary}", + ServiceName, + parsedToolName, + JsonConvert.SerializeObject(toolArguments), + snapshot.SnapshotId, + ex.GetLogSummary()); + toolResultString = $"Error executing tool {parsedToolName}: {ex.GetLogSummary()}."; } string feedbackPrefix = isError ? $"[Tool '{parsedToolName}' Execution Failed. Error: " : $"[Executed Tool '{parsedToolName}'. Result: "; diff --git a/TelegramSearchBot.LLMAgent/LLMAgentProgram.cs b/TelegramSearchBot.LLMAgent/LLMAgentProgram.cs index dc013d4e..b30d270d 100644 --- a/TelegramSearchBot.LLMAgent/LLMAgentProgram.cs +++ b/TelegramSearchBot.LLMAgent/LLMAgentProgram.cs @@ -48,13 +48,16 @@ public static async Task RunAsync(string[] args) { private static async Task RegisterProxyToolsFromRedisAsync(ServiceProvider services, ILogger logger) { try { var redis = services.GetRequiredService(); + logger.LogDebug("Loading proxy tool definitions from Redis key {RedisKey}.", LlmAgentRedisKeys.AgentToolDefs); var json = await redis.GetDatabase().StringGetAsync(LlmAgentRedisKeys.AgentToolDefs); if (!json.HasValue || string.IsNullOrWhiteSpace(json.ToString())) { logger.LogWarning("No tool definitions found in Redis. Agent will have limited tools."); return; } - var toolDefs = JsonConvert.DeserializeObject>(json.ToString()); + var toolDefsJson = json.ToString(); + logger.LogDebug("Loaded proxy tool definition payload from Redis. Bytes={PayloadBytes}", System.Text.Encoding.UTF8.GetByteCount(toolDefsJson)); + var toolDefs = JsonConvert.DeserializeObject>(toolDefsJson); if (toolDefs == null || toolDefs.Count == 0) { logger.LogWarning("Empty tool definitions from Redis."); return; @@ -71,13 +74,35 @@ private static async Task RegisterProxyToolsFromRedisAsync(ServiceProvider servi if (arguments.TryGetValue("__userId", out var uid)) { long.TryParse(uid, out remoteUserId); arguments.Remove("__userId"); } if (arguments.TryGetValue("__messageId", out var mid)) { long.TryParse(mid, out remoteMessageId); arguments.Remove("__messageId"); } - return await toolExecutor.ExecuteRemoteToolAsync( - toolName, arguments, remoteChatId, remoteUserId, remoteMessageId, CancellationToken.None); + logger.LogInformation( + "Proxy tool call routed to main process. Tool={ToolName}, ChatId={ChatId}, UserId={UserId}, MessageId={MessageId}, ArgumentKeys={ArgumentKeys}", + toolName, + remoteChatId, + remoteUserId, + remoteMessageId, + string.Join(",", arguments.Keys)); + try { + return await toolExecutor.ExecuteRemoteToolAsync( + toolName, arguments, remoteChatId, remoteUserId, remoteMessageId, CancellationToken.None); + } catch (Exception ex) { + logger.LogError( + ex, + "Proxy tool call failed while routed to main process. Tool={ToolName}, ChatId={ChatId}, UserId={UserId}, MessageId={MessageId}, ErrorSummary={ErrorSummary}", + toolName, + remoteChatId, + remoteUserId, + remoteMessageId, + ex.GetLogSummary()); + throw; + } }); - logger.LogInformation("Imported {Count} tool definitions from Redis.", toolDefs.Count); + logger.LogInformation( + "Imported {Count} tool definitions from Redis. ToolNames={ToolNames}", + toolDefs.Count, + string.Join(",", toolDefs.Select(t => t.Name).Take(80))); } catch (Exception ex) { - logger.LogWarning(ex, "Failed to import tool definitions from Redis. Agent will have limited tools."); + logger.LogWarning(ex, "Failed to import tool definitions from Redis. Agent will have limited tools. ErrorSummary={ErrorSummary}", ex.GetLogSummary()); } } @@ -91,10 +116,13 @@ private static string[] NormalizeArgs(string[] args) { private static ServiceProvider BuildServices(int port) { var services = new ServiceCollection(); - services.AddLogging(builder => builder.AddSimpleConsole(options => { - options.SingleLine = true; - options.TimestampFormat = "[yyyy-MM-dd HH:mm:ss] "; - })); + services.AddLogging(builder => { + builder.SetMinimumLevel(LogLevel.Trace); + builder.AddSimpleConsole(options => { + options.SingleLine = true; + options.TimestampFormat = "[yyyy-MM-dd HH:mm:ss] "; + }); + }); services.AddHttpClient(); services.AddHttpClient("OllamaClient"); services.AddDbContext(options => { diff --git a/TelegramSearchBot.LLMAgent/Service/AgentLoopService.cs b/TelegramSearchBot.LLMAgent/Service/AgentLoopService.cs index f0be52be..5b1a5c5c 100644 --- a/TelegramSearchBot.LLMAgent/Service/AgentLoopService.cs +++ b/TelegramSearchBot.LLMAgent/Service/AgentLoopService.cs @@ -198,11 +198,13 @@ await _garnetClient.PublishTerminalAsync(new AgentStreamChunk { retryAttempt++; var delay = _transientRetryDelayFactory(retryAttempt); currentRecoveredContent = latestSnapshot; + var retryReason = ex.GetLogSummary(); _logger.LogWarning( ex, - "Agent task {TaskId} hit transient LLM overload. Retrying in {DelaySeconds}s (attempt {RetryAttempt}/{MaxRetries})", + "Agent task {TaskId} hit transient LLM overload ({RetryReason}). Retrying in {DelaySeconds}s (attempt {RetryAttempt}/{MaxRetries})", task.TaskId, + retryReason, delay.TotalSeconds, retryAttempt, MaxTransientOverloadRetries); @@ -214,27 +216,32 @@ await _garnetClient.PublishTerminalAsync(new AgentStreamChunk { ["lastSequence"] = sequence.ToString(), ["transientRetryCount"] = retryAttempt.ToString(), ["lastRetryAtUtc"] = DateTime.UtcNow.ToString("O"), - ["lastRetryReason"] = ex.Message + ["lastRetryReason"] = retryReason, + ["lastRetryDetails"] = ex.ToString(), + ["lastRetryExceptionType"] = ex.GetPrimaryException().GetType().FullName ?? ex.GetType().FullName }); if (delay > TimeSpan.Zero) { await Task.Delay(delay, cancellationToken); } } catch (Exception ex) { - _logger.LogError(ex, "Agent task {TaskId} failed", task.TaskId); + var errorSummary = ex.GetLogSummary(); + _logger.LogError(ex, "Agent task {TaskId} failed ({ErrorSummary})", task.TaskId, errorSummary); await _garnetClient.PublishTerminalAsync(new AgentStreamChunk { TaskId = task.TaskId, Type = AgentChunkType.Error, Sequence = sequence, - ErrorMessage = ex.Message + ErrorMessage = errorSummary }); - await _rpcClient.SaveTaskStateAsync(task.TaskId, AgentTaskStatus.Failed, ex.Message, new Dictionary { + await _rpcClient.SaveTaskStateAsync(task.TaskId, AgentTaskStatus.Failed, errorSummary, new Dictionary { ["payload"] = payload, ["workerChatId"] = workerChatId.ToString(), ["failedAtUtc"] = DateTime.UtcNow.ToString("O"), ["lastContent"] = latestSnapshot, ["lastSequence"] = sequence.ToString(), - ["transientRetryCount"] = retryAttempt.ToString() + ["transientRetryCount"] = retryAttempt.ToString(), + ["errorType"] = ex.GetPrimaryException().GetType().FullName ?? ex.GetType().FullName, + ["errorDetails"] = ex.ToString() }); return; } diff --git a/TelegramSearchBot.LLMAgent/Service/ToolExecutor.cs b/TelegramSearchBot.LLMAgent/Service/ToolExecutor.cs index 10aa45fa..4281c54a 100644 --- a/TelegramSearchBot.LLMAgent/Service/ToolExecutor.cs +++ b/TelegramSearchBot.LLMAgent/Service/ToolExecutor.cs @@ -1,15 +1,20 @@ using System.Data; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; using Newtonsoft.Json; +using TelegramSearchBot.Common; using TelegramSearchBot.Model.AI; namespace TelegramSearchBot.LLMAgent.Service { public sealed class ToolExecutor { private readonly GarnetClient _garnetClient; private readonly GarnetRpcClient _rpcClient; + private readonly ILogger _logger; - public ToolExecutor(GarnetClient garnetClient, GarnetRpcClient rpcClient) { + public ToolExecutor(GarnetClient garnetClient, GarnetRpcClient rpcClient, ILogger? logger = null) { _garnetClient = garnetClient; _rpcClient = rpcClient; + _logger = logger ?? NullLogger.Instance; } public Task EchoAsync(string text) => Task.FromResult(text); @@ -45,17 +50,54 @@ public async Task ExecuteRemoteToolAsync( Arguments = arguments }; + _logger.LogInformation( + "Queueing remote Telegram tool task. RequestId={RequestId}, Tool={ToolName}, ChatId={ChatId}, UserId={UserId}, MessageId={MessageId}, ArgumentKeys={ArgumentKeys}", + task.RequestId, + toolName, + chatId, + userId, + messageId, + string.Join(",", arguments.Keys)); await _garnetClient.RPushAsync(LlmAgentRedisKeys.TelegramTaskQueue, JsonConvert.SerializeObject(task)); var effectiveTimeout = timeout ?? TimeSpan.FromSeconds(60); - var result = await _rpcClient.WaitForTelegramResultAsync(task.RequestId, effectiveTimeout, cancellationToken); + TelegramAgentToolResult? result; + try { + result = await _rpcClient.WaitForTelegramResultAsync(task.RequestId, effectiveTimeout, cancellationToken); + } catch (Exception ex) { + _logger.LogError( + ex, + "Failed while waiting for remote Telegram tool result. RequestId={RequestId}, Tool={ToolName}, TimeoutSeconds={TimeoutSeconds}, ErrorSummary={ErrorSummary}", + task.RequestId, + toolName, + effectiveTimeout.TotalSeconds, + ex.GetLogSummary()); + throw; + } + if (result == null) { + _logger.LogError( + "Timed out waiting for remote Telegram tool result. RequestId={RequestId}, Tool={ToolName}, TimeoutSeconds={TimeoutSeconds}", + task.RequestId, + toolName, + effectiveTimeout.TotalSeconds); throw new TimeoutException($"Timed out waiting for remote tool '{toolName}' result after {effectiveTimeout.TotalSeconds}s."); } if (!result.Success) { + _logger.LogError( + "Remote Telegram tool returned failure. RequestId={RequestId}, Tool={ToolName}, Error={ErrorMessage}", + task.RequestId, + toolName, + result.ErrorMessage); throw new InvalidOperationException($"Remote tool '{toolName}' failed: {result.ErrorMessage}"); } + _logger.LogInformation( + "Remote Telegram tool completed. RequestId={RequestId}, Tool={ToolName}, ResultLength={ResultLength}, TelegramMessageId={TelegramMessageId}", + task.RequestId, + toolName, + result.Result?.Length ?? 0, + result.TelegramMessageId); return string.IsNullOrWhiteSpace(result.Result) ? "ok" : result.Result; } } diff --git a/TelegramSearchBot/AppBootstrap/AppBootstrap.cs b/TelegramSearchBot/AppBootstrap/AppBootstrap.cs index 694c16a6..81584707 100644 --- a/TelegramSearchBot/AppBootstrap/AppBootstrap.cs +++ b/TelegramSearchBot/AppBootstrap/AppBootstrap.cs @@ -329,12 +329,11 @@ public static bool TryDispatchStartupByReflection(string[] args) { } } catch (TargetInvocationException ex) { // 被调用的 Startup 方法内部抛出了异常 - Log.Error($"错误：启动过程 '{startupKey}' 中发生异常: {ex.InnerException?.Message ?? ex.Message}"); - // 可以考虑记录更详细的堆栈信息 ex.InnerException.StackTrace + Log.Error(ex, "错误：启动过程 '{StartupKey}' 中发生异常", startupKey); return false; // 目标方法执行失败 } catch (Exception ex) { // 其他反射或运行时错误 - Log.Error($"处理启动类型 '{startupKey}' 时发生意外错误: {ex.Message}"); + Log.Error(ex, "处理启动类型 '{StartupKey}' 时发生意外错误", startupKey); return false; // 反射或其他错误 } } @@ -364,7 +363,7 @@ private static void PrintUsageHint(Assembly assembly) { } } catch (Exception ex) { - Log.Error($" (无法自动列出类型: {ex.Message})"); + Log.Error(ex, " (无法自动列出类型)"); } } } diff --git a/TelegramSearchBot/Controller/AI/LLM/GeneralLLMController.cs b/TelegramSearchBot/Controller/AI/LLM/GeneralLLMController.cs index e1a01ac6..491dd3f0 100644 --- a/TelegramSearchBot/Controller/AI/LLM/GeneralLLMController.cs +++ b/TelegramSearchBot/Controller/AI/LLM/GeneralLLMController.cs @@ -184,6 +184,11 @@ await messageService.ExecuteAsync(new MessageOption() { if (agentTaskHandle != null) { var terminalChunk = await agentTaskHandle.Completion; if (terminalChunk.Type == AgentChunkType.Error) { + logger.LogError( + "AI Agent 执行失败，ChatId {ChatId}, MessageId {MessageId}, ErrorMessage: {ErrorMessage}", + telegramMessage.Chat.Id, + telegramMessage.MessageId, + terminalChunk.ErrorMessage); await SendMessageService.SendMessage($"AI Agent 执行失败：{terminalChunk.ErrorMessage}", telegramMessage.Chat.Id, telegramMessage.MessageId); } else if (terminalChunk.Type == AgentChunkType.IterationLimitReached && terminalChunk.ContinuationSnapshot != null) { var snapshotId = await ContinuationService.SaveSnapshotAsync(terminalChunk.ContinuationSnapshot); diff --git a/TelegramSearchBot/Controller/AI/LLM/LLMIterationCallbackController.cs b/TelegramSearchBot/Controller/AI/LLM/LLMIterationCallbackController.cs index 49b3d63c..7a28eb9c 100644 --- a/TelegramSearchBot/Controller/AI/LLM/LLMIterationCallbackController.cs +++ b/TelegramSearchBot/Controller/AI/LLM/LLMIterationCallbackController.cs @@ -199,6 +199,11 @@ await _messageService.ExecuteAsync(new MessageOption { if (agentTaskHandle != null) { var terminalChunk = await agentTaskHandle.Completion; if (terminalChunk.Type == AgentChunkType.Error) { + _logger.LogError( + "AI Agent resume failed，ChatId {ChatId}, SnapshotId {SnapshotId}, ErrorMessage: {ErrorMessage}", + snapshot.ChatId, + snapshotId, + terminalChunk.ErrorMessage); await _sendMessageService.SendMessage($"AI Agent 执行失败：{terminalChunk.ErrorMessage}", snapshot.ChatId, ( int ) snapshot.OriginalMessageId); } else if (terminalChunk.Type == AgentChunkType.IterationLimitReached && terminalChunk.ContinuationSnapshot != null) { var newSnapshotId = await _continuationService.SaveSnapshotAsync(terminalChunk.ContinuationSnapshot); diff --git a/TelegramSearchBot/Program.cs b/TelegramSearchBot/Program.cs index 9fa65273..fbe77eb7 100644 --- a/TelegramSearchBot/Program.cs +++ b/TelegramSearchBot/Program.cs @@ -21,12 +21,13 @@ static async Task Main(string[] args) { .CreateLogger(); Log.Logger = new LoggerConfiguration() - .MinimumLevel.Information() // 设置最低日志级别 + .MinimumLevel.Verbose() // 打开完整日志，便于追踪 LLM/Agent 级异常 .MinimumLevel.Override("Microsoft.EntityFrameworkCore.Database.Command", Serilog.Events.LogEventLevel.Debug) // SQL 语句只在 Debug 级别输出 .WriteTo.Console( - restrictedToMinimumLevel: LogEventLevel.Information, + restrictedToMinimumLevel: LogEventLevel.Verbose, outputTemplate: "[{Timestamp:yyyy-MM-dd HH:mm:ss} {Level:u3}] {Message:lj}{NewLine}{Exception}") .WriteTo.File($"{Env.WorkDir}/logs/log-.txt", + restrictedToMinimumLevel: LogEventLevel.Verbose, rollingInterval: RollingInterval.Day, outputTemplate: "[{Timestamp:yyyy-MM-dd HH:mm:ss} {Level:u3}] {Message:lj}{NewLine}{Exception}") .WriteTo.OpenTelemetry(options => { diff --git a/TelegramSearchBot/Service/AI/LLM/ChunkPollingService.cs b/TelegramSearchBot/Service/AI/LLM/ChunkPollingService.cs index 889ed52f..8e5d84b8 100644 --- a/TelegramSearchBot/Service/AI/LLM/ChunkPollingService.cs +++ b/TelegramSearchBot/Service/AI/LLM/ChunkPollingService.cs @@ -6,6 +6,7 @@ using System.Threading.Channels; using System.Threading.Tasks; using Microsoft.Extensions.Hosting; +using Microsoft.Extensions.Logging; using Newtonsoft.Json; using StackExchange.Redis; using TelegramSearchBot.Common; @@ -34,10 +35,12 @@ public async IAsyncEnumerable ReadSnapshotsAsync( public sealed class ChunkPollingService : BackgroundService { private readonly IConnectionMultiplexer _redis; + private readonly ILogger _logger; private readonly ConcurrentDictionary _trackedTasks = new(StringComparer.OrdinalIgnoreCase); - public ChunkPollingService(IConnectionMultiplexer redis) { + public ChunkPollingService(IConnectionMultiplexer redis, ILogger? logger = null) { _redis = redis; + _logger = logger ?? Microsoft.Extensions.Logging.Abstractions.NullLogger.Instance; } public AgentTaskStreamHandle TrackTask(string taskId) { @@ -47,7 +50,15 @@ public AgentTaskStreamHandle TrackTask(string taskId) { public async Task RunPollCycleAsync(CancellationToken cancellationToken = default) { foreach (var entry in _trackedTasks.ToArray()) { - await PollTaskAsync(entry.Key, entry.Value, cancellationToken); + try { + await PollTaskAsync(entry.Key, entry.Value, cancellationToken); + } catch (OperationCanceledException) { + throw; + } catch (RedisException ex) { + _logger.LogWarning(ex, "ChunkPollingService: redis error while polling task {TaskId}", entry.Key); + } catch (Exception ex) { + _logger.LogError(ex, "ChunkPollingService: failed to poll task {TaskId}", entry.Key); + } } } @@ -61,8 +72,10 @@ protected override async Task ExecuteAsync(CancellationToken stoppingToken) { await RunPollCycleAsync(stoppingToken); } catch (OperationCanceledException) { break; - } catch (RedisException) { - // Transient Redis failure – wait before retrying + } catch (RedisException ex) { + _logger.LogWarning(ex, "Redis error in ChunkPollingService poll loop, retrying after delay"); + } catch (Exception ex) { + _logger.LogError(ex, "Unexpected error in ChunkPollingService poll loop"); } try { @@ -193,8 +206,8 @@ private async Task DeliverFinalSnapshotAsync(string taskId, TrackedTask tracked, tracked.LastContent = snapshot.Content; await tracked.Channel.Writer.WriteAsync(snapshot, cancellationToken); } - } catch (Exception) { - // Best-effort: don't let snapshot read failure prevent task completion + } catch (Exception ex) { + _logger.LogWarning(ex, "ChunkPollingService: failed to deliver final snapshot for task {TaskId}", taskId); } } diff --git a/TelegramSearchBot/Service/AI/LLM/TelegramTaskConsumer.cs b/TelegramSearchBot/Service/AI/LLM/TelegramTaskConsumer.cs index f038bf4a..76b69760 100644 --- a/TelegramSearchBot/Service/AI/LLM/TelegramTaskConsumer.cs +++ b/TelegramSearchBot/Service/AI/LLM/TelegramTaskConsumer.cs @@ -89,6 +89,14 @@ private async Task ExecuteToolTaskAsync(TelegramAgentToolTask task, Cancellation }; try { + _logger.LogInformation( + "Executing Telegram tool task. RequestId={RequestId}, Tool={ToolName}, ChatId={ChatId}, UserId={UserId}, MessageId={MessageId}, ArgumentKeys={ArgumentKeys}", + task.RequestId, + task.ToolName, + task.ChatId, + task.UserId, + task.MessageId, + string.Join(",", task.Arguments.Keys)); if (task.ToolName.Equals("send_message", StringComparison.OrdinalIgnoreCase)) { // Special handling for send_message (needs ITelegramBotClient directly) await ExecuteSendMessageAsync(task, response, stoppingToken); @@ -97,8 +105,15 @@ private async Task ExecuteToolTaskAsync(TelegramAgentToolTask task, Cancellation await ExecuteGenericToolAsync(task, response); } } catch (Exception ex) when (ex is not OperationCanceledException) { - _logger.LogError(ex, "Failed to execute tool task {ToolName} (RequestId={RequestId})", task.ToolName, task.RequestId); - response.ErrorMessage = ex.Message; + _logger.LogError( + ex, + "Failed to execute tool task {ToolName} (RequestId={RequestId}, ChatId={ChatId}, UserId={UserId}, MessageId={MessageId})", + task.ToolName, + task.RequestId, + task.ChatId, + task.UserId, + task.MessageId); + response.ErrorMessage = ex.GetLogSummary(); } try { @@ -106,6 +121,13 @@ await _redis.GetDatabase().StringSetAsync( LlmAgentRedisKeys.TelegramResult(task.RequestId), JsonConvert.SerializeObject(response), TimeSpan.FromMinutes(5)); + _logger.LogInformation( + "Wrote Telegram tool task result. RequestId={RequestId}, Tool={ToolName}, Success={Success}, ResultLength={ResultLength}, Error={ErrorMessage}", + task.RequestId, + task.ToolName, + response.Success, + response.Result?.Length ?? 0, + response.ErrorMessage); } catch (Exception ex) { _logger.LogError(ex, "Failed to write tool result for {RequestId}", task.RequestId); } @@ -124,6 +146,11 @@ private async Task ExecuteSendMessageAsync(TelegramAgentToolTask task, TelegramA response.Success = true; response.TelegramMessageId = sent.MessageId; response.Result = sent.MessageId.ToString(); + _logger.LogInformation( + "send_message tool task completed. RequestId={RequestId}, ChatId={ChatId}, TelegramMessageId={TelegramMessageId}", + task.RequestId, + chatId, + sent.MessageId); } private async Task ExecuteGenericToolAsync(TelegramAgentToolTask task, TelegramAgentToolResult response) { @@ -138,6 +165,11 @@ private async Task ExecuteGenericToolAsync(TelegramAgentToolTask task, TelegramA task.ToolName, task.Arguments, scope.ServiceProvider, toolContext); response.Success = true; response.Result = McpToolHelper.ConvertToolResultToString(resultObj); + _logger.LogInformation( + "Generic Telegram tool task completed. RequestId={RequestId}, Tool={ToolName}, ResultLength={ResultLength}", + task.RequestId, + task.ToolName, + response.Result?.Length ?? 0); } } } diff --git a/TelegramSearchBot/Service/BotAPI/SendMessageService.Streaming.cs b/TelegramSearchBot/Service/BotAPI/SendMessageService.Streaming.cs index 36db9850..a4e556fc 100644 --- a/TelegramSearchBot/Service/BotAPI/SendMessageService.Streaming.cs +++ b/TelegramSearchBot/Service/BotAPI/SendMessageService.Streaming.cs @@ -371,22 +371,31 @@ await botClient.SendMessage( } // Generate a unique draftId to avoid collisions for concurrent requests to the same message - int draftId = unchecked(( int ) ( chatId ^ replyTo ^ DateTime.UtcNow.Ticks )); + int draftId = CreateDraftId(chatId, replyTo); string latestContent = null; - bool draftStarted = false; + + logger.LogDebug( + "SendDraftStream: Starting draft stream. ChatId {ChatId}, ReplyTo {ReplyTo}, DraftId {DraftId}", + chatId, + replyTo, + draftId); try { // Send initial placeholder as draft try { await botClient.SendMessageDraft(chatId, draftId, initialPlaceholderContent, parseMode: ParseMode.None, cancellationToken: cancellationToken); - draftStarted = true; } catch (Exception ex) { // Remember chats that don't support draft messages to avoid repeated failures if (ex.Message != null && ex.Message.Contains("TEXTDRAFT_PEER_INVALID", StringComparison.OrdinalIgnoreCase)) { _draftUnsupportedChats.TryAdd(chatId, true); logger.LogInformation("SendDraftStream: Chat {ChatId} does not support draft messages. Will use SendFullMessageStream for future requests.", chatId); } else { - logger.LogWarning(ex, "SendDraftStream: Failed to send initial draft placeholder, falling back to SendFullMessageStream."); + logger.LogWarning(ex, + "SendDraftStream: Failed to send initial draft placeholder. ChatId {ChatId}, DraftId {DraftId}, PlaceholderLength {PlaceholderLength}, PlaceholderPreview {PlaceholderPreview}. Falling back to SendFullMessageStream.", + chatId, + draftId, + initialPlaceholderContent?.Length ?? 0, + GetContentPreview(initialPlaceholderContent)); } // Fall back to the old method if sendMessageDraft is not supported return await SendFullMessageStream(fullMessagesStream, chatId, replyTo, initialPlaceholderContent, cancellationToken); @@ -404,9 +413,21 @@ await botClient.SendMessage( var html = MessageFormatHelper.ConvertMarkdownToTelegramHtml(displayMarkdown); if (!string.IsNullOrWhiteSpace(html)) { await botClient.SendMessageDraft(chatId, draftId, html, parseMode: ParseMode.Html, cancellationToken: cancellationToken); + } else if (!string.IsNullOrWhiteSpace(displayMarkdown)) { + logger.LogDebug( + "SendDraftStream: Markdown collapsed to empty HTML. ChatId {ChatId}, DraftId {DraftId}, MarkdownLength {MarkdownLength}, MarkdownPreview {MarkdownPreview}.", + chatId, + draftId, + displayMarkdown.Length, + GetContentPreview(displayMarkdown)); } } catch (Exception ex) { - logger.LogTrace(ex, "SendDraftStream: Error sending draft update, will retry on next chunk."); + logger.LogWarning(ex, + "SendDraftStream: Error sending draft update. ChatId {ChatId}, DraftId {DraftId}, MarkdownLength {MarkdownLength}, MarkdownPreview {MarkdownPreview}.", + chatId, + draftId, + latestContent?.Length ?? 0, + GetContentPreview(latestContent)); } } } catch (OperationCanceledException) { @@ -424,7 +445,12 @@ await botClient.SendMessage( await botClient.SendMessageDraft(chatId, draftId, finalHtml, parseMode: ParseMode.Html, cancellationToken: CancellationToken.None); } } catch (Exception ex) { - logger.LogWarning(ex, "SendDraftStream: Error sending final draft content."); + logger.LogWarning(ex, + "SendDraftStream: Error sending final draft content. ChatId {ChatId}, DraftId {DraftId}, MarkdownLength {MarkdownLength}, MarkdownPreview {MarkdownPreview}.", + chatId, + draftId, + latestContent.Length, + GetContentPreview(latestContent)); } } @@ -599,6 +625,31 @@ await botClient.SendMessage( return sentMessages; } + + private static int CreateDraftId(long chatId, int replyTo) { + var draftId = HashCode.Combine(chatId, replyTo, Environment.TickCount, Guid.NewGuid()); + return draftId == 0 ? 1 : draftId; + } + + private static string GetContentPreview(string? content, int maxLength = 240) { + if (string.IsNullOrEmpty(content)) { + return ""; + } + + var normalized = content + .Replace("\r", "\\r", StringComparison.Ordinal) + .Replace("\n", "\\n", StringComparison.Ordinal); + + if (normalized.Length <= maxLength) { + return normalized; + } + + var headLength = Math.Max(1, maxLength / 2); + var tailLength = Math.Max(1, maxLength - headLength); + var head = normalized[..headLength]; + var tail = normalized[^tailLength..]; + return $"{head}...{tail}"; + } #endregion } } From a07cb9dad08479a6374ddc9a1911f346f4792ee9 Mon Sep 17 00:00:00 2001 From: ModerRAS Date: Wed, 13 May 2026 12:49:38 +0800 Subject: [PATCH 2/4] Address tool diagnostics review feedback --- Docs/Build_and_Test_Guide.md | 7 ++---- README.md | 2 ++ TelegramSearchBot.Common/Env.cs | 12 ++++++++++ .../Service/AI/LLM/McpToolHelper.cs | 6 +++-- .../Service/AI/LLM/OpenAIResponsesService.cs | 11 +++++++-- .../Service/AI/LLM/OpenAIService.cs | 24 ++++++++++++++++++- TelegramSearchBot/Program.cs | 20 +++++++++------- .../Service/AI/LLM/ChunkPollingService.cs | 12 ++++++++-- 8 files changed, 73 insertions(+), 21 deletions(-) diff --git a/Docs/Build_and_Test_Guide.md b/Docs/Build_and_Test_Guide.md index 475732d5..d8412b05 100644 --- a/Docs/Build_and_Test_Guide.md +++ b/Docs/Build_and_Test_Guide.md @@ -267,11 +267,8 @@ jobs: #### 本地调试日志 ```bash -# 启用详细日志 -dotnet run --project TelegramSearchBot --verbosity detailed - -# 使用 Serilog 配置 -export SERILOG__MINIMUMLEVEL__DEFAULT=Debug +# Config.json 中默认 LogLevel=Verbose；需要降低噪声时可改为 Information/Warning +dotnet run --project TelegramSearchBot ``` #### 性能分析 diff --git a/README.md b/README.md index f7481822..cbc0c7ca 100644 --- a/README.md +++ b/README.md @@ -73,6 +73,7 @@ "OLTPAuth": "", "OLTPAuthUrl": "", "OLTPName": "", + "LogLevel": "Verbose", "BraveApiKey": "", "EnableAccounting": false } @@ -120,6 +121,7 @@ - `OLTPAuth`: OLTP日志推送认证密钥 - `OLTPAuthUrl`: OLTP日志推送URL - `OLTPName`: OLTP日志推送名称 + - `LogLevel`: Serilog 最小日志级别，支持 `Verbose`/`Debug`/`Information`/`Warning`/`Error`/`Fatal`，默认 `Verbose` 完整配置参考: [Env.cs](TelegramSearchBot.Common/Env.cs) diff --git a/TelegramSearchBot.Common/Env.cs b/TelegramSearchBot.Common/Env.cs index 24c65b43..3e499a78 100644 --- a/TelegramSearchBot.Common/Env.cs +++ b/TelegramSearchBot.Common/Env.cs @@ -3,6 +3,7 @@ using System.IO; using System.Text; using Newtonsoft.Json; +using Serilog.Events; namespace TelegramSearchBot.Common { public static class Env { @@ -42,6 +43,7 @@ static Env() { OLTPAuth = config.OLTPAuth; OLTPAuthUrl = config.OLTPAuthUrl; OLTPName = config.OLTPName; + SerilogMinimumLevel = ResolveSerilogMinimumLevel(config.LogLevel); BraveApiKey = config.BraveApiKey; EnableAccounting = config.EnableAccounting; EnableAutoUpdate = config.EnableAutoUpdate; @@ -120,6 +122,7 @@ private static string NormalizeBaseUrl(string? baseUrl, string fallback) { public static string OLTPAuth { get; set; } = null!; public static string OLTPAuthUrl { get; set; } = null!; public static string OLTPName { get; set; } = null!; + public static readonly LogEventLevel SerilogMinimumLevel; public static string BraveApiKey { get; set; } = null!; public static bool EnableAccounting { get; set; } = false; public static int MaxToolCycles { get; set; } @@ -153,6 +156,14 @@ public static string ResolveUpdateBaseUrl(Config config) { return NormalizeBaseUrl(uri.ToString(), DefaultUpdateBaseUrl); } + + public static LogEventLevel ResolveSerilogMinimumLevel(string? logLevel) { + if (Enum.TryParse(logLevel, ignoreCase: true, out var parsed)) { + return parsed; + } + + return LogEventLevel.Verbose; + } } public class Config { public string BaseUrl { get; set; } = "https://api.telegram.org"; @@ -178,6 +189,7 @@ public class Config { public string OLTPAuth { get; set; } = null!; public string OLTPAuthUrl { get; set; } = null!; public string OLTPName { get; set; } = null!; + public string LogLevel { get; set; } = "Verbose"; public string BraveApiKey { get; set; } = null!; public bool EnableAccounting { get; set; } = false; public int MaxToolCycles { get; set; } = 25; diff --git a/TelegramSearchBot.LLM/Service/AI/LLM/McpToolHelper.cs b/TelegramSearchBot.LLM/Service/AI/LLM/McpToolHelper.cs index 7e7c3ee5..cf26d59c 100644 --- a/TelegramSearchBot.LLM/Service/AI/LLM/McpToolHelper.cs +++ b/TelegramSearchBot.LLM/Service/AI/LLM/McpToolHelper.cs @@ -723,8 +723,10 @@ public static async Task ExecuteRegisteredToolAsync(string toolName, Dic // Clean CDATA markers if present and trim values var cleanedArguments = new Dictionary(StringComparer.OrdinalIgnoreCase); foreach (var kvp in originalArguments) { - var value = kvp.Value; - value = Regex.Replace(value ?? string.Empty, @"", "$1").Trim(); + var value = (kvp.Value ?? string.Empty).Trim(); + if (value.Contains("", "$1").Trim(); + } cleanedArguments[kvp.Key] = value; } stringArguments = cleanedArguments; diff --git a/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIResponsesService.cs b/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIResponsesService.cs index 18440e7b..211e389f 100644 --- a/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIResponsesService.cs +++ b/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIResponsesService.cs @@ -1191,6 +1191,7 @@ private static List DeserializeResponseItemsFromSnapshot(List(); if (serialized == null) return result; + var lastResolvedCallId = string.Empty; foreach (var msg in serialized) { string content = msg.Content ?? ""; @@ -1201,7 +1202,9 @@ private static List DeserializeResponseItemsFromSnapshot(List 0 ? parts[0] : ""); + string rawCallId = parts.Length > 0 ? parts[0] : ""; + string callId = OpenAIService.NormalizeToolCallId(rawCallId); + lastResolvedCallId = callId; string name = OpenAIService.NormalizeToolCallName(parts.Length > 1 ? parts[1] : "unknown"); string argsJson = OpenAIService.NormalizeToolCallArguments(parts.Length > 2 ? parts[2] : "{}"); result.Add(ResponseItem.CreateFunctionCallItem( @@ -1214,7 +1217,11 @@ private static List DeserializeResponseItemsFromSnapshot(List 0 ? parts[0] : ""); + string rawCallId = parts.Length > 0 ? parts[0] : ""; + string callId = string.IsNullOrWhiteSpace(rawCallId) && !string.IsNullOrWhiteSpace(lastResolvedCallId) + ? lastResolvedCallId + : OpenAIService.NormalizeToolCallId(rawCallId); + lastResolvedCallId = callId; string output = parts.Length > 1 ? parts[1] : ""; result.Add(ResponseItem.CreateFunctionCallOutputItem(callId, output)); } else { diff --git a/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIService.cs b/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIService.cs index c71f4f45..752fda5b 100644 --- a/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIService.cs +++ b/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIService.cs @@ -8,6 +8,7 @@ using System.Net.Http; // Added for IHttpClientFactory using System.Reflection; using System.Text; +using System.Text.RegularExpressions; using System.Threading; // For CancellationToken using System.Threading.Tasks; using Microsoft.EntityFrameworkCore; @@ -73,6 +74,27 @@ internal static Dictionary DeserializeToolArgumentsForDisplay(st } } + private static string SanitizeAndTruncateArguments(string arguments, int maxChars = 2048) { + if (string.IsNullOrWhiteSpace(arguments)) { + return string.Empty; + } + + var sanitized = arguments; + var sensitiveKeys = new[] { "api_key", "apikey", "apiKey", "token", "password", "secret", "authorization" }; + foreach (var key in sensitiveKeys) { + sanitized = Regex.Replace( + sanitized, + $"(\"{Regex.Escape(key)}\"\\s*:\\s*\")[^\"]*(\")", + "$1***$2", + RegexOptions.IgnoreCase); + } + + sanitized = sanitized.Replace("\r", "\\r").Replace("\n", "\\n"); + return sanitized.Length <= maxChars + ? sanitized + : sanitized.Substring(0, maxChars) + $"..."; + } + private readonly ILogger _logger; private readonly DataDbContext _dbContext; private readonly IHttpClientFactory _httpClientFactory; @@ -1116,7 +1138,7 @@ private async IAsyncEnumerable ExecWithNativeToolCallingAsync( kvp => new { kvp.Value.Id, kvp.Value.Name, - Arguments = kvp.Value.Arguments.ToString() + ArgumentsPreview = SanitizeAndTruncateArguments(kvp.Value.Arguments.ToString()) })), ex.GetLogSummary()); const string errorMsg = "Tool call failed before execution due to malformed tool metadata. Please verify the tool name and parameters, then try again."; diff --git a/TelegramSearchBot/Program.cs b/TelegramSearchBot/Program.cs index fbe77eb7..e5273c76 100644 --- a/TelegramSearchBot/Program.cs +++ b/TelegramSearchBot/Program.cs @@ -21,23 +21,25 @@ static async Task Main(string[] args) { .CreateLogger(); Log.Logger = new LoggerConfiguration() - .MinimumLevel.Verbose() // 打开完整日志，便于追踪 LLM/Agent 级异常 + .MinimumLevel.Is(Env.SerilogMinimumLevel) // 默认打开完整日志，便于追踪 LLM/Agent 级异常 .MinimumLevel.Override("Microsoft.EntityFrameworkCore.Database.Command", Serilog.Events.LogEventLevel.Debug) // SQL 语句只在 Debug 级别输出 .WriteTo.Console( - restrictedToMinimumLevel: LogEventLevel.Verbose, + restrictedToMinimumLevel: Env.SerilogMinimumLevel, outputTemplate: "[{Timestamp:yyyy-MM-dd HH:mm:ss} {Level:u3}] {Message:lj}{NewLine}{Exception}") .WriteTo.File($"{Env.WorkDir}/logs/log-.txt", - restrictedToMinimumLevel: LogEventLevel.Verbose, + restrictedToMinimumLevel: Env.SerilogMinimumLevel, rollingInterval: RollingInterval.Day, outputTemplate: "[{Timestamp:yyyy-MM-dd HH:mm:ss} {Level:u3}] {Message:lj}{NewLine}{Exception}") - .WriteTo.OpenTelemetry(options => { - options.Endpoint = Env.OLTPAuthUrl; - options.Headers = new Dictionary() { + .WriteTo.OpenTelemetry( + endpoint: Env.OLTPAuthUrl, + protocol: OtlpProtocol.HttpProtobuf, + headers: new Dictionary() { { "Authorization", $"Basic {Env.OLTPAuth}" }, { "stream-name", Env.OLTPName } - }; - options.Protocol = OtlpProtocol.HttpProtobuf; - }) + }, + resourceAttributes: null, + includedData: null, + restrictedToMinimumLevel: Env.SerilogMinimumLevel) .CreateLogger(); AppContext.SetSwitch("System.Net.Http.SocketsHttpHandler.Http2UnencryptedSupport", true); if (args.Length == 0) { diff --git a/TelegramSearchBot/Service/AI/LLM/ChunkPollingService.cs b/TelegramSearchBot/Service/AI/LLM/ChunkPollingService.cs index 8e5d84b8..57b2e6c9 100644 --- a/TelegramSearchBot/Service/AI/LLM/ChunkPollingService.cs +++ b/TelegramSearchBot/Service/AI/LLM/ChunkPollingService.cs @@ -73,9 +73,17 @@ protected override async Task ExecuteAsync(CancellationToken stoppingToken) { } catch (OperationCanceledException) { break; } catch (RedisException ex) { - _logger.LogWarning(ex, "Redis error in ChunkPollingService poll loop, retrying after delay"); + _logger.LogWarning( + ex, + "Redis error in ChunkPollingService poll loop, retrying after delay. TrackedTaskCount={TrackedTaskCount}, PollIntervalMs={PollIntervalMs}", + _trackedTasks.Count, + Env.AgentChunkPollingIntervalMilliseconds); } catch (Exception ex) { - _logger.LogError(ex, "Unexpected error in ChunkPollingService poll loop"); + _logger.LogError( + ex, + "Unexpected error in ChunkPollingService poll loop. TrackedTaskCount={TrackedTaskCount}, PollIntervalMs={PollIntervalMs}", + _trackedTasks.Count, + Env.AgentChunkPollingIntervalMilliseconds); } try { From e7bc4ab6046dc2ed15ed7fb79307ae4edf7a12a3 Mon Sep 17 00:00:00 2001 From: ModerRAS Date: Wed, 13 May 2026 12:58:04 +0800 Subject: [PATCH 3/4] Tighten Serilog log level parsing --- TelegramSearchBot.Common/Env.cs | 3 ++- .../Common/EnvBotApiEndpointTests.cs | 20 +++++++++++++++++++ 2 files changed, 22 insertions(+), 1 deletion(-) diff --git a/TelegramSearchBot.Common/Env.cs b/TelegramSearchBot.Common/Env.cs index 3e499a78..3964c34c 100644 --- a/TelegramSearchBot.Common/Env.cs +++ b/TelegramSearchBot.Common/Env.cs @@ -158,7 +158,8 @@ public static string ResolveUpdateBaseUrl(Config config) { } public static LogEventLevel ResolveSerilogMinimumLevel(string? logLevel) { - if (Enum.TryParse(logLevel, ignoreCase: true, out var parsed)) { + if (Enum.TryParse(logLevel, ignoreCase: true, out var parsed) && + Enum.IsDefined(typeof(LogEventLevel), parsed)) { return parsed; } diff --git a/TelegramSearchBot.Test/Common/EnvBotApiEndpointTests.cs b/TelegramSearchBot.Test/Common/EnvBotApiEndpointTests.cs index 6b823f0c..1a2d5a01 100644 --- a/TelegramSearchBot.Test/Common/EnvBotApiEndpointTests.cs +++ b/TelegramSearchBot.Test/Common/EnvBotApiEndpointTests.cs @@ -1,3 +1,4 @@ +using Serilog.Events; using TelegramSearchBot.Common; using Xunit; @@ -68,5 +69,24 @@ public void ResolveUpdateBaseUrl_FallsBackToDefaultWhenUrlIsNotHttpsOrLoopback() Assert.Equal(Env.DefaultUpdateBaseUrl, result); } + + [Theory] + [InlineData("Verbose", LogEventLevel.Verbose)] + [InlineData("Error", LogEventLevel.Error)] + public void ResolveSerilogMinimumLevel_ReturnsDefinedLogLevel(string logLevel, LogEventLevel expected) { + var result = Env.ResolveSerilogMinimumLevel(logLevel); + + Assert.Equal(expected, result); + } + + [Theory] + [InlineData("999")] + [InlineData("NotARealLevel")] + [InlineData("")] + public void ResolveSerilogMinimumLevel_FallsBackToVerboseForInvalidValue(string? logLevel) { + var result = Env.ResolveSerilogMinimumLevel(logLevel); + + Assert.Equal(LogEventLevel.Verbose, result); + } } } From 2c21ef0a9c6e82d728fd80e1a0549ad2fe091c20 Mon Sep 17 00:00:00 2001 From: ModerRAS Date: Wed, 13 May 2026 15:26:53 +0800 Subject: [PATCH 4/4] Preserve DeepSeek empty reasoning content --- .../Model/AI/LlmContinuationSnapshot.cs | 4 +- ...OpenAIProviderHistorySerializationTests.cs | 86 ++++++++++++++++++- .../Service/AI/LLM/OpenAIService.cs | 39 ++++++--- 3 files changed, 115 insertions(+), 14 deletions(-) diff --git a/TelegramSearchBot.Common/Model/AI/LlmContinuationSnapshot.cs b/TelegramSearchBot.Common/Model/AI/LlmContinuationSnapshot.cs index 5c678fd3..ea3a57ec 100644 --- a/TelegramSearchBot.Common/Model/AI/LlmContinuationSnapshot.cs +++ b/TelegramSearchBot.Common/Model/AI/LlmContinuationSnapshot.cs @@ -18,8 +18,8 @@ public class SerializedChatMessage { public string Content { get; set; } = null!; /// - /// The reasoning content for thinking mode models (e.g., Kimi-thinking-preview, QwQ). - /// This field must be passed back to the API in subsequent requests to avoid HTTP 400 errors. + /// The reasoning content for thinking mode models (e.g., Kimi-thinking-preview, QwQ, DeepSeek reasoning models). + /// Preserve the value as returned by the provider when resuming conversation state. /// public string? ReasoningContent { get; set; } } diff --git a/TelegramSearchBot.LLM.Test/Service/AI/LLM/OpenAIProviderHistorySerializationTests.cs b/TelegramSearchBot.LLM.Test/Service/AI/LLM/OpenAIProviderHistorySerializationTests.cs index cf71bac5..12cf1862 100644 --- a/TelegramSearchBot.LLM.Test/Service/AI/LLM/OpenAIProviderHistorySerializationTests.cs +++ b/TelegramSearchBot.LLM.Test/Service/AI/LLM/OpenAIProviderHistorySerializationTests.cs @@ -1,6 +1,14 @@ using System.Collections.Generic; +using System.ClientModel; +using System.ClientModel.Primitives; +using System.Net; +using System.Net.Http; +using System.Threading; +using System.Threading.Tasks; +using OpenAI; using OpenAI.Chat; using TelegramSearchBot.Model.AI; +using TelegramSearchBot.Model.Data; using TelegramSearchBot.Service.AI.LLM; using Xunit; @@ -186,7 +194,7 @@ public void SerializeProviderHistory_WithEmptyReasoningContent_Preserved() { } [Fact] - public void DeserializeProviderHistory_AlwaysCallsSetReasoningContent_EvenWithNull() { + public void DeserializeProviderHistory_WithNullReasoningContent_Succeeds() { // Arrange - serialized message with null ReasoningContent (old snapshot format) var serialized = new List { new SerializedChatMessage { Role = "system", Content = "System" }, @@ -194,7 +202,7 @@ public void DeserializeProviderHistory_AlwaysCallsSetReasoningContent_EvenWithNu new SerializedChatMessage { Role = "assistant", Content = "Hi", ReasoningContent = null }, }; - // Act - deserialize (DeserializeProviderHistory now always calls SetAssistantReasoningContent) + // Act - deserialize without adding an empty reasoning_content patch. var deserialized = OpenAIService.DeserializeProviderHistory(serialized); // Assert - deserialization succeeds even with null reasoning content @@ -205,6 +213,42 @@ public void DeserializeProviderHistory_AlwaysCallsSetReasoningContent_EvenWithNu // The key thing: NO exception thrown, deserialization succeeds } + [Fact] + public void ShouldIncludeEmptyReasoningContent_UsesDeepSeekGatewayOrModel() { + Assert.True(OpenAIService.ShouldIncludeEmptyReasoningContent( + new LLMChannel { Gateway = "https://api.deepseek.com/v1" }, + "deepseek-chat")); + + Assert.False(OpenAIService.ShouldIncludeEmptyReasoningContent( + new LLMChannel { Gateway = "https://api.minimaxi.com/v1" }, + "abab6.5s")); + } + + [Fact] + public async Task DeserializeProviderHistory_WithEmptyReasoningContent_ForDeepSeekSerializesOpenAIRequest() { + var serialized = new List { + new SerializedChatMessage { Role = "user", Content = "Hi" }, + new SerializedChatMessage { Role = "assistant", Content = "Hello", ReasoningContent = "" }, + new SerializedChatMessage { Role = "user", Content = "Use the available context." }, + }; + var history = OpenAIService.DeserializeProviderHistory(serialized, includeEmptyReasoningContent: true); + var handler = new CapturingHandler(); + var httpClient = new HttpClient(handler); + var options = new OpenAIClientOptions { + Endpoint = new System.Uri("https://example.test/v1"), + Transport = new HttpClientPipelineTransport(httpClient) + }; + var chatClient = new ChatClient("test-model", new ApiKeyCredential("test-key"), options); + + await chatClient.CompleteChatAsync(history, new ChatCompletionOptions()); + + Assert.True(handler.RequestSent); + Assert.Contains("\"reasoning_content\":\"\"", handler.RequestBody); + + var reserialized = OpenAIService.SerializeProviderHistory(history); + Assert.Equal("", reserialized[1].ReasoningContent); + } + [Fact] public void DeserializeProviderHistory_DeepSeekToolCallChain_PreservesAllReasoningContent() { // Simulate a DeepSeek tool call chain where reasoning_content must be preserved @@ -222,5 +266,43 @@ public void DeserializeProviderHistory_DeepSeekToolCallChain_PreservesAllReasoni Assert.IsType(deserialized[2]); Assert.IsType(deserialized[4]); } + + private sealed class CapturingHandler : HttpMessageHandler { + public bool RequestSent { get; private set; } + public string RequestBody { get; private set; } = string.Empty; + + protected override async Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) { + RequestSent = true; + RequestBody = request.Content is null + ? string.Empty + : await request.Content.ReadAsStringAsync(cancellationToken); + var response = new HttpResponseMessage(HttpStatusCode.OK) { + Content = new StringContent(""" + { + "id": "chatcmpl-test", + "object": "chat.completion", + "created": 1710000000, + "model": "test-model", + "choices": [ + { + "index": 0, + "message": { + "role": "assistant", + "content": "ok" + }, + "finish_reason": "stop" + } + ], + "usage": { + "prompt_tokens": 1, + "completion_tokens": 1, + "total_tokens": 2 + } + } + """) + }; + return response; + } + } } } diff --git a/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIService.cs b/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIService.cs index 752fda5b..b7beac5b 100644 --- a/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIService.cs +++ b/TelegramSearchBot.LLM/Service/AI/LLM/OpenAIService.cs @@ -1036,6 +1036,7 @@ private async IAsyncEnumerable ExecWithNativeToolCallingAsync( foreach (var tool in nativeTools) { completionOptions.Tools.Add(tool); } + var includeEmptyReasoningContent = ShouldIncludeEmptyReasoningContent(channel, modelName); try { int maxToolCycles = Env.MaxToolCycles; @@ -1116,8 +1117,7 @@ private async IAsyncEnumerable ExecWithNativeToolCallingAsync( if (!string.IsNullOrWhiteSpace(responseText)) { assistantMessage = new AssistantChatMessage(chatToolCalls) { Content = { ChatMessageContentPart.CreateTextPart(responseText) } }; } - // Set reasoning content for thinking mode models (always call, even for empty) - SetAssistantReasoningContent(assistantMessage, reasoningContent ?? ""); + SetAssistantReasoningContent(assistantMessage, reasoningContent, includeEmptyReasoningContent); providerHistory.Add(assistantMessage); var toolIndicators = new StringBuilder(); @@ -1185,8 +1185,7 @@ private async IAsyncEnumerable ExecWithNativeToolCallingAsync( // Not a tool call - regular text response if (!string.IsNullOrWhiteSpace(responseText)) { var assistantMsg = new AssistantChatMessage(responseText); - // Set reasoning content (always call, even for empty) - SetAssistantReasoningContent(assistantMsg, reasoningContent ?? ""); + SetAssistantReasoningContent(assistantMsg, reasoningContent, includeEmptyReasoningContent); providerHistory.Add(assistantMsg); } yield break; @@ -1353,7 +1352,8 @@ public async IAsyncEnumerable ResumeFromSnapshotAsync(LlmContinuationSna ServiceName, snapshot.SnapshotId, snapshot.ChatId, snapshot.ProviderHistory?.Count ?? 0); // Restore provider history from snapshot - List providerHistory = DeserializeProviderHistory(snapshot.ProviderHistory); + var includeEmptyReasoningContent = ShouldIncludeEmptyReasoningContent(channel, modelName); + List providerHistory = DeserializeProviderHistory(snapshot.ProviderHistory, includeEmptyReasoningContent); using var client = _httpClientFactory.CreateClient(); var clientOptions = new OpenAIClientOptions { @@ -1503,6 +1503,14 @@ public static List SerializeProviderHistory(List SerializeProviderHistory(List /// Deserialize portable format back to OpenAI ChatMessage list. /// - public static List DeserializeProviderHistory(List serialized) { + public static List DeserializeProviderHistory(List serialized, bool includeEmptyReasoningContent = false) { var result = new List(); if (serialized == null) return result; @@ -1561,8 +1569,7 @@ public static List DeserializeProviderHistory(List DeserializeProviderHistory(List - private static void SetAssistantReasoningContent(AssistantChatMessage msg, string reasoningContent) { + internal static bool ShouldIncludeEmptyReasoningContent(LLMChannel channel, string modelName) { + var gateway = channel?.Gateway ?? string.Empty; + var model = modelName ?? string.Empty; + return gateway.Contains("deepseek", StringComparison.OrdinalIgnoreCase) || + model.Contains("deepseek", StringComparison.OrdinalIgnoreCase); + } + + private static void SetAssistantReasoningContent(AssistantChatMessage msg, string reasoningContent, bool includeEmptyReasoningContent = false) { + if (reasoningContent is null || (reasoningContent.Length == 0 && !includeEmptyReasoningContent)) { + return; + } + // Try Patch.Set first (writes directly to JSON output) #pragma warning disable SCME0001 // Patch API is experimental but functional try { - msg.Patch.Set("$.reasoning_content"u8, reasoningContent ?? ""); + var encodedReasoningContent = System.Text.Json.JsonSerializer.SerializeToUtf8Bytes(reasoningContent); + msg.Patch.Set("$.reasoning_content"u8, encodedReasoningContent.AsSpan()); } catch { // Patch.Set not available or failed, fall through to reflection }