Prevent FileLogger shutdown crash under thread-pool starvation#9802
Conversation
On the netstandard2.0 build (used by .NET Framework test hosts), FileLogger is disposed synchronously and Dispose() blocks on the async log loop via _logLoop.Wait(). Under thread-pool starvation (e.g. many test processes on a CI/Helix agent), the loop's continuation could be delayed past the flush timeout, causing Dispose() to throw and crash the test host on an otherwise successful run. Run a fully synchronous drain loop on the non-NETCOREAPP path so the consumer never schedules a continuation and cannot be starved, and make the flush timeout non-fatal (warn instead of throw) in both Dispose() and DisposeAsync(). Relates to dotnet/sdk#55215 Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
There was a problem hiding this comment.
Pull request overview
This PR fixes a shutdown crash in Microsoft.Testing.Platform's diagnostic FileLogger on the netstandard2.0 build (used by .netfx test hosts). Under thread-pool starvation (many concurrent test processes on CI/Helix), the async consumer-loop continuation could be delayed past the 5-minute flush timeout while Dispose() blocked a pool thread, causing Dispose() to throw InvalidOperationException and turn a passing run red (ref: dotnet/sdk#55215).
Changes:
- Adds a fully synchronous drain loop (
WriteLogToFile) on the non-NETCOREAPPpath, run viaTask.Run(Action), plus a new blockingWaitToRead()(MonitorWait/Pulse) onSingleConsumerUnboundedChannel<T>so shutdown can't be starved by a re-queued continuation. The existing asyncWaitToReadAsyncpath is untouched (the addedMonitor.Pulseis a no-op for async consumers). - Makes the flush timeout non-fatal: both
Dispose()andDisposeAsync()now warn to the console instead of throwing when the flush times out. - Registers the new internal API
SingleConsumerUnboundedChannel<T>.WaitToRead()inInternalAPI.Unshipped.txt.
Show a summary per file
| File | Description |
|---|---|
src/Platform/Microsoft.Testing.Platform/Logging/FileLogger.cs |
Splits the consumer loop into an async (NETCOREAPP) and a synchronous drain (WriteLogToFile) path; converts the flush-timeout throw in Dispose/DisposeAsync into a non-fatal console warning. |
src/Platform/Microsoft.Testing.Platform/Messages/SingleConsumerUnboundedChannel.cs |
Adds a blocking WaitToRead() and Monitor.Pulse wake-ups in Write/Complete to support a synchronous single consumer; async path unchanged. |
src/Platform/Microsoft.Testing.Platform/InternalAPI/InternalAPI.Unshipped.txt |
Declares the new WaitToRead() internal API, consistent with the type's existing tracked members. |
I verified the ITask.Run(Action) overload and its Task.Run(action) implementation exist, both resource strings are present, TimeoutAfterAsync throws TimeoutException (so the new catch is correct), the Monitor Wait/Pulse pattern is race-free for a single consumer (enqueue+pulse under the lock, condition re-checked in the while loop), and the new InternalAPI.Unshipped.txt entry follows the same #if !NETCOREAPP pattern already used by the type's shipped members. I found no concrete blocking defects. Note that this change alters process-shutdown semantics across multiple TFMs and introduces new Monitor-based blocking on a shared channel primitive, so it merits human sign-off.
Review details
- Files reviewed: 3/3 changed files
- Comments generated: 0
- Review effort level: Medium
![github-code-quality[bot]](https://avatars.githubusercontent.com/u/9919?s=60&v=4){kind=small}
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
![github-actions[bot]](https://avatars.githubusercontent.com/in/15368?s=60&v=4){kind=small}
There was a problem hiding this comment.
🤖 Automated content by GitHub Copilot. Generated by the Build Failure Analysis workflow. · 99.6 AIC · ⌖ 6.93 AIC · ⊞ 7.3K · ◷
There was a problem hiding this comment.
Note
🤖 Automated review by GitHub Copilot. Generated by the Expert Code Review workflow. To request a follow-up action, reply by tagging @copilot directly.
Review Summary
Overall: Clean PR with one acknowledged edge case. The fix is well-reasoned and the synchronous drain loop correctly addresses the root cause of the shutdown crash.
Dimensions Evaluated (14/22)
| # | Dimension | Verdict |
|---|---|---|
| 1 | Algorithmic Correctness | ✅ LGTM |
| 2 | Threading & Concurrency | |
| 3 | Security & IPC Contract Safety | ✅ LGTM |
| 4 | Public API & Binary Compatibility | ✅ LGTM |
| 5 | Performance & Allocations | ✅ LGTM |
| 6 | Cross-TFM Compatibility | ✅ LGTM |
| 7 | Resource & IDisposable Management | |
| 8 | Defensive Coding at Boundaries | ✅ LGTM |
| 9 | Localization & Resources | ✅ LGTM |
| 13 | Test Completeness | |
| 15 | Code Structure & Simplification | ✅ LGTM |
| 16 | Naming & Conventions | 📝 Nit (see inline) |
| 17 | Documentation Accuracy | ✅ LGTM |
| 21 | Scope & PR Discipline | ✅ LGTM |
Dimensions 10–12, 14, 18–20, 22 skipped (not applicable — no test/analyzer/build/PS1 files changed).
Key Notes
Threading (non-blocking observation): On the timeout path, Dispose() proceeds to dispose _writer/_fileStream while the consumer loop may still be running. This is a known trade-off that is strictly better than the old behavior (crash via InvalidOperationException). The sync loop fix makes the timeout practically unreachable.
Test coverage: The new WaitToRead() method and non-fatal timeout behavior have no direct unit tests. The Monitor Wait/Pulse pattern is well-understood, but a basic test covering "returns true when items exist / blocks until item arrives / returns false after Complete()" would guard against future regressions.
InternalAPI sort order (nit): The Messages namespace entry should appear before ServerMode/Services entries alphabetically.
- Declare SingleConsumerUnboundedChannel<T>.WaitToRead() in the Telemetry project's InternalAPI.Unshipped.txt (the file is linked into that assembly too), fixing the RS0051 build break. - Capture _channel into a non-null local in WriteLogToFile to make null-safety explicit for external analyzers. - Move the new InternalAPI entry to its sorted position. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
On flush timeout the consumer loop is still running and owns _writer/_fileStream. Falling through to Flush/Dispose them raced with the loop (StreamWriter and its stream aren't thread-safe), which could throw or truncate the log. On timeout we now warn and return without disposing those resources, leaving them for the OS to reclaim at process exit. No data is lost because the writer uses AutoFlush. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
…lelogger-shutdown-crash # Conflicts: # src/Platform/Microsoft.Testing.Platform/InternalAPI/InternalAPI.Unshipped.txt
- HIGH: start the file-logger consumer loop only after _writer is fully initialized. Task.Run could schedule the loop on another thread before _writer was assigned later in the constructor, risking a null-writer dereference. The channel is still created early so Log() can enqueue; only the loop start moves to the end. - Dispose the semaphore on the flush-timeout early-return paths in Dispose()/DisposeAsync() to avoid a managed-resource leak. It is not shared with the consumer loop (SyncFlush-only), so it's safe to dispose while the loop still owns the writer/stream. - Fix a stale comment: on NETCOREAPP the channel is completed via TryComplete(). - Add a chaos test that hammers the async-flush path from many threads then disposes, asserting every queued message is drained without loss or crash (repeated across iterations). Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
This comment has been minimized.
This comment has been minimized.
🔍 Build Failure AnalysisSummary — The build fails because the new Root cause 1: MSTEST0049 — Missing
|
| Code | Line | API |
|---|---|---|
MSTEST0049 |
298 | Task.Run(...) |
MSTEST0049 |
300 | startGate.Wait() |
MSTEST0049 |
309 | Task.WaitAll(producers) |
Root cause 2: CA1416 — Platform-unsupported APIs (browser)
ManualResetEventSlim.Wait() and Task.WaitAll() are annotated as unsupported on browser. Since this test project never runs on a browser, the cleanest fix is a #pragma warning disable CA1416 around the affected block.
Affected errors (×2 TFMs = 4 total)
| Code | Line | API |
|---|---|---|
CA1416 |
300 | ManualResetEventSlim.Wait() |
CA1416 |
309 | Task.WaitAll(...) |
Root cause 3: MSTEST0037 — Use Assert.HasCount instead of Assert.AreEqual for collection count
Line 316 compares lines.Length with Assert.AreEqual. The analyzer requires Assert.HasCount (used extensively elsewhere in this project).
Affected errors (×2 TFMs = 2 total)
| Code | Line | Message |
|---|---|---|
MSTEST0037 |
316 | Use Assert.HasCount instead of Assert.AreEqual |
Proposed fix — Assert.HasCount(producerCount * messagesPerProducer, lines) (note: lines not lines.Length).
Concrete fix summary
All 13 errors are in a single file: test/UnitTests/Microsoft.Testing.Platform.UnitTests/Logging/FileLoggerTests.cs. The fixes are:
- Pass
TestContext.CancellationTokentoTask.Run,startGate.Wait, andTask.WaitAll. - Add
#pragma warning disable CA1416/restorearound the blocking synchronization block. - Replace
Assert.AreEqual(..., lines.Length, ...)withAssert.HasCount(..., lines, ...).
See inline suggestions below.
Build overview
- Result: FAILED (266.1s)
- MSBuild: 18.10.0-preview-26359-110
- Projects: 49 total, 1 failed (
Microsoft.Testing.Platform.UnitTests.csproj) - Errors: 13 (4 unique, duplicated across 2 TFMs)
- Warnings: 1
All MSBuild errors (13)
| Code | File:Line | Message |
|---|---|---|
MSTEST0049 |
FileLoggerTests.cs:298 |
Consider using the overload that accepts a CancellationToken |
MSTEST0049 |
FileLoggerTests.cs:300 |
Consider using the overload that accepts a CancellationToken |
MSTEST0049 |
FileLoggerTests.cs:309 |
Consider using the overload that accepts a CancellationToken |
MSTEST0037 |
FileLoggerTests.cs:316 |
Use 'Assert.HasCount' instead of 'Assert.AreEqual' |
CA1416 |
FileLoggerTests.cs:300 |
'ManualResetEventSlim.Wait()' is unsupported on: 'browser' |
CA1416 |
FileLoggerTests.cs:309 |
'Task.WaitAll(params Task[])' is unsupported on: 'browser' |
| (above 6 repeated for 2nd TFM) |
🤖 Generated by the Build Failure Analysis workflow using (a href="(dev.azure.com/redacted) · commit 2b65b17
🤖 Automated content by GitHub Copilot. Generated by the Build Failure Analysis workflow. · 113.5 AIC · ⌖ 6.39 AIC · ⊞ 7.3K · [◷]( · ◷)
There was a problem hiding this comment.
🤖 Automated content by GitHub Copilot. Generated by the Build Failure Analysis workflow. · 113.5 AIC · ⌖ 6.39 AIC · ⊞ 7.3K · ◷
- Assert against the exact set of message payloads (parsed from each log line) instead of a substring check on the whole content, so prefix-overlapping IDs (P0M1 vs P0M10) can't mask loss/duplication. Also assert the actual-message set has the expected count to catch duplicates. - Use Assert.HasCount instead of Assert.AreEqual for the line count (MSTEST0037). - Pass TestContext.CancellationToken to Task.Run, ManualResetEventSlim.Wait, and Task.WaitAll (MSTEST0049), with CA1416 suppressions since this test never targets browser. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
This comment has been minimized.
This comment has been minimized.
Address review feedback on the FileLogger shutdown path: - Expose FileLogger.IsFileHandleReleased so callers can tell when a flush timeout left the consumer still owning the file. FileLoggerProvider.CheckLogFolderAndMoveToTheNewIfNeededAsync now skips the MoveFile (which would throw an IOException on Windows because the stream is opened with FileShare.Read) when the handle wasn't released, keeping the timeout non-fatal. - Make the FileLogger write-loop exception message path-neutral instead of naming WriteLogToFileAsync, which was wrong on the netstandard synchronous path. Regenerated xlf files. - Correct the timeout comments: AutoFlush only guarantees already-written records are on disk; records still queued may be lost if the process exits before the loop drains them. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
🧪 Test quality grade — PR #9802
This advisory comment was generated automatically. Grades are heuristic
|
Address review feedback: - FileLoggerProvider.CheckLogFolderAndMoveToTheNewIfNeededAsync no longer returns early on a flush timeout leaving a disposed logger in place (which would make every subsequent diagnostic write throw). It now always installs a fresh logger for the test result directory and only moves the old file when its handle was released, keeping logging alive on the degenerate timeout path. - Add an injectable flushTimeout seam on FileLogger so the timeout path is testable deterministically. - Add deterministic tests: assert the netstandard build starts the consumer via the synchronous ITask.Run(Action) overload (locking the anti-starvation fix that the async impl would not satisfy), assert IsFileHandleReleased after a clean dispose, and assert the flush timeout is non-fatal (no throw, warning emitted, handle reported not released) using a never-completing consumer and a short timeout. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
Problem
Investigated from dotnet/sdk#55215: a Microsoft.Testing.Platform test host runs all tests successfully but then crashes during shutdown while disposing the diagnostic file logger:
The process exits with
0xE0434352, turning a green run red.Root cause
MTP has no
net472build, so.netfxtest hosts load thenetstandard2.0MTP assembly, where#if NETCOREAPPis false andFileLoggeris onlyIDisposable. On that path:Dispose()blocks a thread-pool thread on_logLoop.Wait(5min).Task.Runand, afterComplete(), itsawait WaitToReadAsynccontinuation is re-queued to the thread pool (RunContinuationsAsynchronously).Under thread-pool starvation (many test processes running concurrently on a CI/Helix agent), that continuation can be delayed past the 5‑minute flush timeout while
Dispose()holds a pool thread — so the flush times out andDispose()throws, crashing an otherwise successful run.Fix
NETCOREAPPpath. The file-logger consumer now runs a fully synchronous loop (WriteLogToFile) viaTask.Run(Action). A synchronous delegate runs to completion on a single worker thread and blocks on the channel without ever scheduling a continuation, making shutdown immune to thread-pool starvation. Adds a blockingWaitToRead()(MonitorWait/Pulse) toSingleConsumerUnboundedChannel<T>— purely additive; the existing asyncWaitToReadAsyncused by AppInsights /AsyncConsumerDataProcessoris untouched.Dispose()andDisposeAsync()now warn to the console instead of throwing when the flush times out. A logger failing to flush must never crash a passing test run.The netcore path keeps its async loop and awaited
DisposeAsync(which never blocks a thread), aside from the non-fatal guard.Verification
net8.0/net9.0/netstandard2.0(0 warnings, 0 errors).FileLoggerunit tests: 34/34 pass onnet9.0(async path) and 34/34 onnet462(the new synchronous drain path).Notes
--diagnostic-synchronous-writewhen--diagnosticis enabled remains a good complementary mitigation, but is no longer required to avoid the crash.Thread/RunLongRunning) would tripCA1416(browser) /IDE0060on the shared constructor parameter;Task.Run(Action)with a blocking loop achieves the same starvation-immunity with minimal churn.