From a9f86348ff9d2118df0d5c1f859e73beb5459fe1 Mon Sep 17 00:00:00 2001 From: GeWuYou <95328647+GeWuYou@users.noreply.github.com> Date: Tue, 21 Apr 2026 17:32:50 +0800 Subject: [PATCH] =?UTF-8?q?fix(core):=20=E4=BF=AE=E5=A4=8D=20AsyncLogAppen?= =?UTF-8?q?der=20=E5=88=B7=E6=96=B0=E7=AB=9E=E6=80=81?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - 修复 AsyncLogAppender 在队列已被后台线程提前清空时 Flush 仍可能超时失败的问题 - 新增 AsyncLogAppender 已处理队列场景的稳定回归测试并重新验证 GFramework.Core.Tests - 更新 analyzer-warning-reduction 的 tracking 与 trace 记录 PR267 failed-test follow-up --- .../Logging/AsyncLogAppenderTests.cs | 50 +++++++++++++++++++ .../Logging/Appenders/AsyncLogAppender.cs | 40 +++++++++++---- .../analyzer-warning-reduction-tracking.md | 19 +++++-- .../analyzer-warning-reduction-trace.md | 35 +++++++++++++ 4 files changed, 129 insertions(+), 15 deletions(-) diff --git a/GFramework.Core.Tests/Logging/AsyncLogAppenderTests.cs b/GFramework.Core.Tests/Logging/AsyncLogAppenderTests.cs index 89db303c..9e4590b5 100644 --- a/GFramework.Core.Tests/Logging/AsyncLogAppenderTests.cs +++ b/GFramework.Core.Tests/Logging/AsyncLogAppenderTests.cs @@ -120,6 +120,30 @@ public class AsyncLogAppenderTests Assert.That(observedResults, Has.All.True); } + [Test] + public void Flush_WhenEntriesAlreadyProcessed_Should_Still_ReportSuccess() + { + using var appendCompleted = new ManualResetEventSlim(); + var innerAppender = new SignalingAppender(appendCompleted); + using var asyncAppender = new AsyncLogAppender(innerAppender, bufferSize: 10); + var observedResults = new List(); + + asyncAppender.Append(new LogEntry(DateTime.UtcNow, LogLevel.Info, "TestLogger", "Already processed", null, null)); + Assert.That(appendCompleted.Wait(TimeSpan.FromSeconds(1)), Is.True); + + asyncAppender.OnFlushCompleted += (_, eventArgs) => observedResults.Add(eventArgs.Success); + + var result = asyncAppender.Flush(TimeSpan.FromSeconds(1)); + + Assert.Multiple(() => + { + Assert.That(result, Is.True); + Assert.That(observedResults, Has.Count.EqualTo(1)); + Assert.That(observedResults, Has.All.True); + Assert.That(innerAppender.FlushCount, Is.EqualTo(1)); + }); + } + [Test] public void Dispose_ShouldProcessRemainingEntries() { @@ -308,6 +332,32 @@ public class AsyncLogAppenderTests } } + private sealed class SignalingAppender : ILogAppender + { + private readonly ManualResetEventSlim _appendCompleted; + + public SignalingAppender(ManualResetEventSlim appendCompleted) + { + _appendCompleted = appendCompleted; + } + + public int FlushCount { get; private set; } + + public void Append(LogEntry entry) + { + _appendCompleted.Set(); + } + + public void Flush() + { + FlushCount++; + } + + public void Dispose() + { + } + } + private class ThrowingAppender : ILogAppender { public void Append(LogEntry entry) diff --git a/GFramework.Core/Logging/Appenders/AsyncLogAppender.cs b/GFramework.Core/Logging/Appenders/AsyncLogAppender.cs index c377acce..a3654f7a 100644 --- a/GFramework.Core/Logging/Appenders/AsyncLogAppender.cs +++ b/GFramework.Core/Logging/Appenders/AsyncLogAppender.cs @@ -23,6 +23,7 @@ public sealed class AsyncLogAppender : ILogAppender private readonly Action? _processingErrorHandler; private readonly Task _processingTask; private bool _disposed; + private int _isProcessingEntry; private volatile bool _flushRequested; /// @@ -140,6 +141,7 @@ public sealed class AsyncLogAppender : ILogAppender // 请求刷新 _flushRequested = true; + TrySignalFlushCompletion(); try { @@ -166,6 +168,7 @@ public sealed class AsyncLogAppender : ILogAppender { try { + Volatile.Write(ref _isProcessingEntry, 1); _innerAppender.Append(entry); } catch (Exception ex) @@ -173,18 +176,12 @@ public sealed class AsyncLogAppender : ILogAppender // 后台消费失败只通过显式回调暴露，避免测试宿主将 stderr 误判为测试告警。 ReportProcessingError(ex); } - - // 检查是否有刷新请求且通道已空 - if (_flushRequested && _channel.Reader.Count == 0) + finally { - _innerAppender.Flush(); - - // 发出完成信号 - if (_flushSemaphore.CurrentCount == 0) - { - _flushSemaphore.Release(); - } + Volatile.Write(ref _isProcessingEntry, 0); } + + TrySignalFlushCompletion(); } } catch (OperationCanceledException) @@ -209,6 +206,29 @@ public sealed class AsyncLogAppender : ILogAppender } } + /// + /// 在后台消费者已经处理完当前条目且队列为空时完成挂起的 Flush 请求。 + /// + private void TrySignalFlushCompletion() + { + if (!_flushRequested) + { + return; + } + + if (Volatile.Read(ref _isProcessingEntry) != 0 || _channel.Reader.Count != 0) + { + return; + } + + _innerAppender.Flush(); + + if (_flushSemaphore.CurrentCount == 0) + { + _flushSemaphore.Release(); + } + } + /// /// 上报后台处理异常，同时隔离观察者自身抛出的错误，避免终止处理循环。 /// 取消相关异常表示关闭流程中的预期控制流，不应被视为后台处理失败。 diff --git a/ai-plan/public/analyzer-warning-reduction/todos/analyzer-warning-reduction-tracking.md b/ai-plan/public/analyzer-warning-reduction/todos/analyzer-warning-reduction-tracking.md index 2c4d2b08..b782563c 100644 --- a/ai-plan/public/analyzer-warning-reduction/todos/analyzer-warning-reduction-tracking.md +++ b/ai-plan/public/analyzer-warning-reduction/todos/analyzer-warning-reduction-tracking.md @@ -7,12 +7,12 @@ ## 当前恢复点 -- 恢复点编号：`ANALYZER-WARNING-REDUCTION-RP-014` -- 当前阶段：`Phase 14` +- 恢复点编号：`ANALYZER-WARNING-REDUCTION-RP-015` +- 当前阶段：`Phase 15` - 当前焦点： - - 当前分支 PR #267 的 latest CodeRabbit unresolved threads、outside-diff comment 与 nitpick comment 已完成本地复核 - - 本轮优先收口仍然成立的 follow-up：`AsyncLogAppender` 接口路径重复触发 `OnFlushCompleted`、事件/XML 契约缺口、 - `PhaseChanged` 迁移文档说明与 `ai-plan` 基线表述歧义 + - 当前分支 PR #267 的失败测试已通过 `$gframework-pr-review` 与本地整包测试完成复核 + - 已确认并修复 `AsyncLogAppender.Flush()` 在“后台线程先清空队列”场景下可能超时返回 `false` 的竞态 + - 已补上稳定回归测试，避免只在整包 `GFramework.Core.Tests` 里偶发暴露的刷新完成信号问题再次回归 - 下一轮默认恢复到 `MA0016` 或 `MA0002` 低风险批次；`MA0015` 与 `MA0077` 继续作为尾项顺手吸收 - `GFramework.Godot` 的 `Timing.cs` 已同步适配新事件签名，但当前 worktree 的 Godot restore 资产仍受 Windows fallback package folder 干扰，独立 build 需在修复资产后补跑 - 后续继续按 warning 类型和数量批处理，而不是回退到按单文件切片推进 @@ -32,6 +32,8 @@ 并同步更新 `GFramework.Godot` 订阅点、定向测试与 `docs/zh-CN` 示例 - 已完成当前 PR #267 review follow-up：修复 `AsyncLogAppender` 的 `ILogAppender.Flush()` 双重完成通知，并补齐 `PhaseChanged` / `CoroutineExceptionEventArgs` XML 文档、`PhaseChanged` 迁移说明和 `ai-plan` 基线注释 +- 已完成当前 PR #267 failed-test follow-up：修复 `AsyncLogAppender.Flush()` 在队列已被后台线程提前清空时仍可能 + 等待满默认超时并返回 `false` 的竞态，并通过整包 `GFramework.Core.Tests` 重新验证 - 当前 `GFramework.Core` `net8.0` warnings-only 基线已降到 `9` 条；剩余 warning 集中在 `MA0016` 集合抽象接口、`MA0002` comparer 重载，以及 `MA0015` / `MA0077` 两个低数量尾项 @@ -62,6 +64,8 @@ 非标准签名；`GFramework.Core` `net8.0` warnings-only 基线由 `15` 降至 `9` - `RP-014` 使用 `gframework-pr-review` 复核当前分支 PR #267 的 latest head review threads、outside-diff comment 与 nitpick comment 后，确认 8 条高信号项中仍成立的是 1 个行为 bug 与 7 个文档/测试/跟踪缺口，并按最小改动收口 +- `RP-015` 使用 `$gframework-pr-review` 复核 PR #267 的 CTRF 失败测试评论后，确认 `AsyncLogAppender` 仍存在 + “队列已空但 Flush 仍超时失败”的竞态；该问题在本地整包 `GFramework.Core.Tests` 中可复现，现已修复并补上稳定回归测试 - 当前工作树分支 `fix/analyzer-warning-reduction-batch` 已在 `ai-plan/public/README.md` 建立 topic 映射 ## 当前风险 @@ -149,6 +153,11 @@ - 结果：`9 Warning(s)`，`0 Error(s)`；`AsyncLogAppender` 行为修复与 XML / 文档补充未引入新的 `GFramework.Core` `net8.0` 构建错误 - `dotnet test GFramework.Core.Tests/GFramework.Core.Tests.csproj -c Release --no-restore --filter "FullyQualifiedName~CoroutineSchedulerTests.Scheduler_Should_Raise_OnCoroutineException_With_EventArgs|FullyQualifiedName~AsyncLogAppenderTests.Flush_Should_Raise_OnFlushCompleted_With_Sender_And_Result|FullyQualifiedName~AsyncLogAppenderTests.ILogAppender_Flush_Should_Raise_OnFlushCompleted_Only_Once|FullyQualifiedName~ArchitectureLifecycleBehaviorTests.InitializeAsync_Should_Raise_PhaseChanged_With_Sender_And_EventArgs" -m:1 -p:RestoreFallbackFolders="" -nologo` - 结果：`4 Passed`，`0 Failed` +- `RP-015` 的验证结果： + - `dotnet test GFramework.Core.Tests/GFramework.Core.Tests.csproj -c Release --no-restore --disable-build-servers --filter "FullyQualifiedName~AsyncLogAppenderTests"` + - 结果：`15 Passed`，`0 Failed` + - `dotnet test GFramework.Core.Tests/GFramework.Core.Tests.csproj -c Release --no-restore --disable-build-servers` + - 结果：`1607 Passed`，`0 Failed` - active 跟踪文件只保留当前恢复点、活跃事实、风险与下一步，不再重复保存已完成阶段的长篇历史 ## 下一步 diff --git a/ai-plan/public/analyzer-warning-reduction/traces/analyzer-warning-reduction-trace.md b/ai-plan/public/analyzer-warning-reduction/traces/analyzer-warning-reduction-trace.md index 369c76ce..2bd3c807 100644 --- a/ai-plan/public/analyzer-warning-reduction/traces/analyzer-warning-reduction-trace.md +++ b/ai-plan/public/analyzer-warning-reduction/traces/analyzer-warning-reduction-trace.md @@ -1,5 +1,40 @@ # Analyzer Warning Reduction 追踪 +## 2026-04-21 — RP-015 + +### 阶段：PR #267 failed-test follow-up 收口（RP-015） + +- 触发背景： + - 用户指出“测试好像挂了”，按 `$gframework-pr-review` 重新抓取当前分支 PR #267 的 review / checks / CTRF 评论 + - PR 评论里同时存在一次 `2143 passed / 0 failed` 与一次 `1 failed` 的 CTRF 报告；失败用例为 + `AsyncLogAppenderTests.ILogAppender_Flush_Should_Raise_OnFlushCompleted_Only_Once` +- 复核过程： + - 先跑定向单测时该用例可以单独通过，因此继续核对 PR head commit 与本地整包测试，避免把旧评论误判成当前状态 + - 在 `dotnet test GFramework.Core.Tests/GFramework.Core.Tests.csproj -c Release --no-restore --disable-build-servers` + 下成功复现相同失败，确认问题仍存在于当前代码，而不是单纯的 PR 评论残留 + - 同时发现当前沙箱内如果用 shell 循环反复启动 `dotnet test`，会触发 `MSBuild` named pipe `Permission denied` + 的环境噪音；后续验证改为单次命令并显式加 `--disable-build-servers` +- 根因结论： + - `AsyncLogAppender.Flush()` 只依赖后台消费循环在处理完某个条目后检查 `_flushRequested` + - 当调用方执行 `Flush()` 前，后台线程已经把最后一个条目消费完并离开检查点时，`Flush()` 会一直等到默认超时， + 最终通过 `OnFlushCompleted` 发出一次 `Success=false` 的错误完成通知 +- 实施修复： + - 为 `AsyncLogAppender` 增加“当前是否仍有条目在途处理”的状态跟踪 + - 抽出 `TrySignalFlushCompletion()`，让 `Flush()` 在请求发出后先做一次即时完成判定；后台循环在每次处理结束后也复用 + 这条判定路径 + - 在 `AsyncLogAppenderTests` 中新增 `Flush_WhenEntriesAlreadyProcessed_Should_Still_ReportSuccess`，稳定覆盖 + “调用 Flush 前队列已被后台线程清空”的场景 +- 验证结果： + - `dotnet test GFramework.Core.Tests/GFramework.Core.Tests.csproj -c Release --no-restore --disable-build-servers --filter "FullyQualifiedName~AsyncLogAppenderTests"` + - 结果：`15 Passed`，`0 Failed` + - `dotnet test GFramework.Core.Tests/GFramework.Core.Tests.csproj -c Release --no-restore --disable-build-servers` + - 结果：`1607 Passed`，`0 Failed` +- 当前结论： + - PR #267 的 failed-test 信号不是纯粹的历史评论噪音，而是当前实现里仍存在的时序竞态 + - 修复后该竞态已被稳定回归测试覆盖，当前 `GFramework.Core.Tests` 整包通过 +- 下一步建议： + - 若继续 analyzer warning reduction 主题，恢复到 `MA0016` / `MA0002` 低风险批次 + ## 2026-04-21 — RP-014 ### 阶段：PR #267 review follow-up 收口（RP-014）