From a5b45b54d47d4f002e13f7db24609166eff2412d Mon Sep 17 00:00:00 2001 From: ModerRAS Date: Wed, 29 Apr 2026 21:26:02 +0800 Subject: [PATCH] fix(qr+logging): resolve QR race condition, URL double messages, and EF Core log pollution MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit QR Race Condition Fix: - SubProcessService.RunRpc: swap SET/PUSH order — data key set BEFORE task pushed to queue - StringWaitGetDeleteAsync: add timeout (30s) and CancellationToken support - QRBootstrap: add null-safety for empty task/photoPath + structured logging URL Double Message Fix: - TrySendMessageWithFallback: replace Send.AddTask with AddTaskWithResult - sentMsg/editedMessage now properly set via await return value - Fallback only triggers on actual API failure, not on queue timing EF Core Log Pollution Fix: - Program.cs: create LoggerHolders.EfCoreLogger writing to logs/efcore-.txt - TelegramSearchBot.Common: new LoggerHolders.cs for cross-project logger sharing - DataDbContext + SearchCacheDbContext: LogTo → LoggerHolders.EfCoreLogger with null fallback - Serilog added to Common and Database projects for ILogger type support Structured Logging Added: - AutoQRController: log ChatId/MessageId at entry, no-QR, and QR-detected points - SubProcessService: log ForkName, guid, payloadLen, resultLen at RPC start/complete - QRBootstrap: log task/path at processing start and result length at completion Fixes: #337 --- TelegramSearchBot.Common/LoggerHolders.cs | 11 +++++++ .../TelegramSearchBot.Common.csproj | 1 + .../Model/DataDbContext.cs | 4 ++- .../Model/SearchCacheDbContext.cs | 4 ++- TelegramSearchBot/AppBootstrap/QRBootstrap.cs | 11 +++++++ .../Controller/AI/QR/AutoQRController.cs | 8 ++++- .../Extension/IDatabaseAsyncExtension.cs | 32 +++++++++++++++++-- TelegramSearchBot/Program.cs | 9 ++++++ .../Service/Abstract/SubProcessService.cs | 19 ++++++++--- .../Service/BotAPI/SendMessageService.cs | 10 +++--- 10 files changed, 94 insertions(+), 15 deletions(-) create mode 100644 TelegramSearchBot.Common/LoggerHolders.cs diff --git a/TelegramSearchBot.Common/LoggerHolders.cs b/TelegramSearchBot.Common/LoggerHolders.cs new file mode 100644 index 00000000..10509b9a --- /dev/null +++ b/TelegramSearchBot.Common/LoggerHolders.cs @@ -0,0 +1,11 @@ +using Serilog; + +namespace TelegramSearchBot.Common { + /// + /// Shared logger holder for EF Core logging. + /// Initialized by TelegramSearchBot.Program and used by Database project. + /// + public static class LoggerHolders { + public static Serilog.ILogger EfCoreLogger { get; set; } = null!; + } +} \ No newline at end of file diff --git a/TelegramSearchBot.Common/TelegramSearchBot.Common.csproj b/TelegramSearchBot.Common/TelegramSearchBot.Common.csproj index 820ed5a7..d43454d0 100644 --- a/TelegramSearchBot.Common/TelegramSearchBot.Common.csproj +++ b/TelegramSearchBot.Common/TelegramSearchBot.Common.csproj @@ -7,5 +7,6 @@ + diff --git a/TelegramSearchBot.Database/Model/DataDbContext.cs b/TelegramSearchBot.Database/Model/DataDbContext.cs index 08b8dc04..a5702e79 100644 --- a/TelegramSearchBot.Database/Model/DataDbContext.cs +++ b/TelegramSearchBot.Database/Model/DataDbContext.cs @@ -13,7 +13,9 @@ public class DataDbContext : DbContext { public DataDbContext(DbContextOptions options) : base(options) { } protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder) { // 日志配置 - optionsBuilder.LogTo(Log.Logger.Information, LogLevel.Information); + optionsBuilder.LogTo( + (TelegramSearchBot.Common.LoggerHolders.EfCoreLogger ?? Log.Logger).Information, + LogLevel.Information); // 数据库配置应该由外部通过DbContextOptions提供 // 不要在这里配置默认数据库 diff --git a/TelegramSearchBot.Database/Model/SearchCacheDbContext.cs b/TelegramSearchBot.Database/Model/SearchCacheDbContext.cs index f27d51e3..25208e45 100644 --- a/TelegramSearchBot.Database/Model/SearchCacheDbContext.cs +++ b/TelegramSearchBot.Database/Model/SearchCacheDbContext.cs @@ -8,7 +8,9 @@ public class SearchCacheDbContext : DbContext { public SearchCacheDbContext(DbContextOptions options) : base(options) { } protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder) { - optionsBuilder.LogTo(Log.Logger.Information, LogLevel.Information); + optionsBuilder.LogTo( + (TelegramSearchBot.Common.LoggerHolders.EfCoreLogger ?? Log.Logger).Information, + LogLevel.Information); } protected override void OnModelCreating(ModelBuilder modelBuilder) { diff --git a/TelegramSearchBot/AppBootstrap/QRBootstrap.cs b/TelegramSearchBot/AppBootstrap/QRBootstrap.cs index 90b35cc3..4207fca1 100644 --- a/TelegramSearchBot/AppBootstrap/QRBootstrap.cs +++ b/TelegramSearchBot/AppBootstrap/QRBootstrap.cs @@ -24,11 +24,22 @@ public static async Task Process(string[] args) { continue; } var task = db.ListLeftPop("QRTasks").ToString(); + if (string.IsNullOrWhiteSpace(task)) { + Log.Logger.Warning("Empty task from QRTasks queue — skipping"); + continue; + } var photoPath = db.StringGetDelete($"QRPost-{task}").ToString(); + if (string.IsNullOrWhiteSpace(photoPath)) { + Log.Logger.Warning("Empty QRPost key for task {task} — data not yet available or already consumed", task); + continue; + } string response = string.Empty; + Log.Logger.Information("QR processing started: task={task}, path={path}", task, photoPath); try { response = await qr.ExecuteAsync(photoPath); + Log.Logger.Information("QR result: task={task}, len={len}, content={preview}", task, response?.Length ?? -1, response?.Length > 100 ? response.Substring(0, 100) + "..." : response); } catch (Exception ex) { + Log.Logger.Warning(ex, "QR processing failed for task {task}", task); } db.StringSet($"QRResult-{task}", response); diff --git a/TelegramSearchBot/Controller/AI/QR/AutoQRController.cs b/TelegramSearchBot/Controller/AI/QR/AutoQRController.cs index 3f0674f6..555b60d5 100644 --- a/TelegramSearchBot/Controller/AI/QR/AutoQRController.cs +++ b/TelegramSearchBot/Controller/AI/QR/AutoQRController.cs @@ -58,6 +58,9 @@ public async Task ExecuteAsync(PipelineContext p) { if (p.BotMessageType != BotMessageType.Message) { return; } + _logger.LogInformation("AutoQR processing started for {ChatId}/{MessageId}", + e.Message.Chat.Id, e.Message.MessageId); + try { var filePath = IProcessPhoto.GetPhotoPath(e); if (filePath == null) { @@ -67,10 +70,13 @@ public async Task ExecuteAsync(PipelineContext p) { var qrStr = await _autoQRService.ExecuteAsync(filePath); if (string.IsNullOrWhiteSpace(qrStr)) { + _logger.LogInformation("No QR code detected for {ChatId}/{MessageId}", + e.Message.Chat.Id, e.Message.MessageId); return; } - _logger.LogInformation("QR Code recognized for {ChatId}/{MessageId}. Content: {QrStr}", e.Message.Chat.Id, e.Message.MessageId, qrStr); + _logger.LogInformation("QR Code recognized for {ChatId}/{MessageId}. Content: {QrStr}, Length: {QrStrLen}", + e.Message.Chat.Id, e.Message.MessageId, qrStr, qrStr.Length); // Add QR result to processing results p.ProcessingResults.Add($"[QR识别结果] {qrStr}"); diff --git a/TelegramSearchBot/Extension/IDatabaseAsyncExtension.cs b/TelegramSearchBot/Extension/IDatabaseAsyncExtension.cs index 00b8264f..f02f7057 100644 --- a/TelegramSearchBot/Extension/IDatabaseAsyncExtension.cs +++ b/TelegramSearchBot/Extension/IDatabaseAsyncExtension.cs @@ -2,17 +2,45 @@ using System.Collections.Generic; using System.Linq; using System.Text; +using System.Threading; using System.Threading.Tasks; using StackExchange.Redis; namespace TelegramSearchBot.Extension { public static class IDatabaseAsyncExtension { - public static async Task StringWaitGetDeleteAsync(this IDatabaseAsync db, string key) { + /// + /// Waits for a Redis key to appear and returns its value, then deletes the key. + /// Uses a polling approach with configurable timeout (default 30 seconds). + /// + /// The IDatabaseAsync instance. + /// The Redis key to wait for. + /// Maximum time to wait. Defaults to 30 seconds if null. + /// Cancellation token to abort the operation. + /// The string value of the key. + /// Thrown when cancellation is requested. + /// Thrown when the timeout elapses before the key appears. + public static async Task StringWaitGetDeleteAsync( + this IDatabaseAsync db, + string key, + TimeSpan? timeout = null, + CancellationToken cancellationToken = default) + { + var effectiveTimeout = timeout ?? TimeSpan.FromSeconds(30); + var startTime = DateTime.UtcNow; + while (true) { + cancellationToken.ThrowIfCancellationRequested(); + + var elapsed = DateTime.UtcNow - startTime; + if (elapsed > effectiveTimeout) { + throw new TimeoutException($"Timeout waiting for Redis key: {key}"); + } + if (!( await db.StringGetAsync(key) ).Equals(RedisValue.Null)) { + // Note: check-then-delete is not atomic but acceptable here since only one consumer polls this key return ( await db.StringGetDeleteAsync(key) ).ToString(); } else { - await Task.Delay(1000); + await Task.Delay(500, cancellationToken); } } } diff --git a/TelegramSearchBot/Program.cs b/TelegramSearchBot/Program.cs index 21f8006e..9fa65273 100644 --- a/TelegramSearchBot/Program.cs +++ b/TelegramSearchBot/Program.cs @@ -11,6 +11,15 @@ namespace TelegramSearchBot { class Program { static async Task Main(string[] args) { + // Separate logger for EF Core - writes only to logs/efcore-.txt + LoggerHolders.EfCoreLogger = new LoggerConfiguration() + .MinimumLevel.Information() + .WriteTo.File( + $"{Env.WorkDir}/logs/efcore-.txt", + rollingInterval: RollingInterval.Day, + outputTemplate: "[{Timestamp:yyyy-MM-dd HH:mm:ss} {Level:u3}] [EF] {Message:lj}{NewLine}{Exception}") + .CreateLogger(); + Log.Logger = new LoggerConfiguration() .MinimumLevel.Information() // 设置最低日志级别 .MinimumLevel.Override("Microsoft.EntityFrameworkCore.Database.Command", Serilog.Events.LogEventLevel.Debug) // SQL 语句只在 Debug 级别输出 diff --git a/TelegramSearchBot/Service/Abstract/SubProcessService.cs b/TelegramSearchBot/Service/Abstract/SubProcessService.cs index f716c93b..4f608bd1 100644 --- a/TelegramSearchBot/Service/Abstract/SubProcessService.cs +++ b/TelegramSearchBot/Service/Abstract/SubProcessService.cs @@ -4,6 +4,7 @@ using System.Text; using System.Threading.Tasks; using Microsoft.Extensions.DependencyInjection; +using Serilog; using StackExchange.Redis; using TelegramSearchBot.Attributes; using TelegramSearchBot.Common; @@ -22,10 +23,20 @@ public SubProcessService(IConnectionMultiplexer connectionMultiplexer) { public async Task RunRpc(string payload) { var db = connectionMultiplexer.GetDatabase(); var guid = Guid.NewGuid(); - await db.ListRightPushAsync($"{ForkName}Tasks", $"{guid}"); - await db.StringSetAsync($"{ForkName}Post-{guid}", payload); - await AppBootstrap.AppBootstrap.RateLimitForkAsync([ForkName, $"{Env.SchedulerPort}"]); - return await db.StringWaitGetDeleteAsync($"{ForkName}Result-{guid}"); + Log.Information("RunRpc started: ForkName={ForkName}, guid={guid}, payloadLen={payloadLen}", + ForkName, guid, payload?.Length ?? -1); + try { + await db.StringSetAsync($"{ForkName}Post-{guid}", payload); + await db.ListRightPushAsync($"{ForkName}Tasks", $"{guid}"); + await AppBootstrap.AppBootstrap.RateLimitForkAsync([ForkName, $"{Env.SchedulerPort}"]); + var result = await db.StringWaitGetDeleteAsync($"{ForkName}Result-{guid}"); + Log.Information("RunRpc completed: ForkName={ForkName}, guid={guid}, resultLen={resultLen}", + ForkName, guid, result?.Length ?? -1); + return result; + } catch (Exception ex) { + Log.Error(ex, "RunRpc failed: ForkName={ForkName}, guid={guid}", ForkName, guid); + throw; + } } } } diff --git a/TelegramSearchBot/Service/BotAPI/SendMessageService.cs b/TelegramSearchBot/Service/BotAPI/SendMessageService.cs index 64cbe62f..c7c09848 100644 --- a/TelegramSearchBot/Service/BotAPI/SendMessageService.cs +++ b/TelegramSearchBot/Service/BotAPI/SendMessageService.cs @@ -53,17 +53,15 @@ public async Task TrySendMessageWithFallback(long chatId, int messageId, string try { if (isEdit) { - Message editedMessage = null; - await Send.AddTask(async () => { - editedMessage = await botClient.EditMessageText( + var editedMessage = await Send.AddTaskWithResult(async () => { + return await botClient.EditMessageText( chatId: chatId, messageId: messageId, parseMode: currentParseMode, text: textToSend, linkPreviewOptions: linkPreviewOptions); }, isGroup); if (editedMessage != null && editedMessage.MessageId > 0) { logger.LogInformation($"Edited message {editedMessage.MessageId} successfully with {currentParseMode}."); } else { logger.LogWarning($"Editing message {messageId} with {currentParseMode} failed silently. Edit will be skipped."); } } else { - Message sentMsg = null; - await Send.AddTask(async () => { - sentMsg = await botClient.SendMessage( + var sentMsg = await Send.AddTaskWithResult(async () => { + return await botClient.SendMessage( chatId: chatId, text: textToSend, parseMode: currentParseMode, replyParameters: new ReplyParameters() { MessageId = replyToMessageId }, linkPreviewOptions: linkPreviewOptions);