Fix ObjectDisposedException race condition in TimestampedFileLogger#53241
Conversation
Co-authored-by: marcpopMSFT <12663534+marcpopMSFT@users.noreply.github.com>
…riteMessage Co-authored-by: marcpopMSFT <12663534+marcpopMSFT@users.noreply.github.com>
|
The change looks reasonable and not recording that failure seems like an ok action. I didn't test this since it was a race condition already. |
There was a problem hiding this comment.
Pull request overview
Fixes an intermittent race in the Windows installer’s TimestampedFileLogger where background logging threads could throw after the logger begins disposal, causing an unhandled exception to surface to the user even though the workload install completed.
Changes:
- Guard
TimestampedFileLogger.WriteMessageagainst disposal/completion races by catchingObjectDisposedExceptionandInvalidOperationExceptionfrom the backingBlockingCollection. - (Unrelated) Adjust a trailing formatting/newline detail in
Microsoft.CodeAnalysis.NetAnalyzers.sarif.
Reviewed changes
Copilot reviewed 1 out of 2 changed files in this pull request and generated 2 comments.
| File | Description |
|---|---|
| src/Cli/dotnet/Installer/Windows/TimestampedFileLogger.cs | Adds exception handling around queue enqueue to avoid unhandled exceptions during concurrent disposal. |
| src/Microsoft.CodeAnalysis.NetAnalyzers/src/Microsoft.CodeAnalysis.NetAnalyzers.sarif | One-line change at EOF; appears unrelated to the logger fix. |
| if (!_messageQueue.IsAddingCompleted) | ||
| { | ||
| _messageQueue.Add(message); | ||
| try | ||
| { | ||
| _messageQueue.Add(message); |
There was a problem hiding this comment.
IsAddingCompleted check is still a TOCTOU gate (state can change immediately after the check). Since Add is now wrapped to handle disposal/completion races, consider removing the IsAddingCompleted check (or including it inside the try/catch) and just attempt the Add, dropping messages on InvalidOperationException/ObjectDisposedException. This reduces duplicated branching and eliminates an extra race window.
| try | ||
| { | ||
| _messageQueue.Add(message); | ||
| } | ||
| catch (ObjectDisposedException) | ||
| { | ||
| // The logger was disposed between the IsAddingCompleted check and Add. | ||
| } | ||
| catch (InvalidOperationException) | ||
| { | ||
| // CompleteAdding was called between the IsAddingCompleted check and Add. | ||
| } |
There was a problem hiding this comment.
This change is intended to prevent unhandled exceptions when Dispose() races with background logging threads. Please add a regression test that disposes the TimestampedFileLogger while one or more threads are concurrently calling LogMessage/WriteMessage, and asserts the operation completes without throwing (and optionally that logging stops cleanly).
|
/ba-g one timed out watch test unrelated to this change |
TimestampedFileLogger.WriteMessagehad a TOCTOU race condition: a background thread (pipe log processor or process exit handler) could pass theIsAddingCompletedcheck, then get preempted whileDispose()calledCompleteAdding()+_messageQueue.Dispose(), causing an unhandledObjectDisposedExceptionorInvalidOperationExceptionto surface to the user — even though the workload installed successfully.Changes
TimestampedFileLogger.WriteMessage: Wrap_messageQueue.Add()in a try/catch forObjectDisposedExceptionandInvalidOperationException. Messages that lose the race against disposal are silently dropped — the operation has already completed at that point.Original prompt
This section details on the original issue you should resolve
<issue_title>[NETSDKE2E][Intermittent]With NET8 preview 1 SDK installed, "Unhandled exception. System.ObjectDisposedException: Cannot access a disposed object." happens when installing Android workload in CLI</issue_title>
<issue_description>Repro steps:
1.Install .NET 8 SDK ( 8.0.100-preview.1.23108.10) from Pipelines - Run 20230209.1-8.0.100-preview.1.23108.10-166172 artifacts (azure.com)
2.Install workload in CLI
dotnet workload install android --skip-manifest-update
Expected Result:
Android workload Install successfully and the output shows correctly.
Actual Result:
Install Android workload successfully, but below message displayed.
Unhandled exception. System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'System.Collections.Concurrent.BlockingCollection`1[[System.String, System.Private.CoreLib, Version=8.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]'.
at Microsoft.DotNet.Installer.Windows.TimestampedFileLogger.WriteMessage(String message)
at Microsoft.DotNet.Installer.Windows.TimestampedFileLogger.ProcessLogRequests(Object logPipeName)
install log in temp folder.zip
dotnet --info:
.NET SDK:
Version: 8.0.100-preview.1.23108.10
Commit: 5725657a6b
Runtime Environment:
OS Name: Windows
OS Version: 10.0.22621
OS Platform: Windows
RID: win10-x64
Base Path: C:\Program Files\dotnet\sdk\8.0.100-preview.1.23108.10\
Host:
Version: 8.0.0-preview.1.23106.5
Architecture: x64
Commit: 9f654effb1
.NET SDKs installed:
8.0.100-preview.1.23108.10 [C:\Program Files\dotnet\sdk]
.NET runtimes installed:
Microsoft.AspNetCore.App 8.0.0-preview.1.23107.3 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.NETCore.App 8.0.0-preview.1.23106.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.WindowsDesktop.App 8.0.0-preview.1.23107.3 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
Other architectures found:
None
Environment variables:
Not set
global.json file:
Not found
Learn more:
https://aka.ms/dotnet/info
Download .NET:
https://aka.ms/dotnet/download
</issue_description>
Comments on the Issue (you are @copilot in this section)
@dsplaisted @joeloff Looks like TimestampedFileLogger is trying to log after it's been disposed. Not sure what's going on, I didn't see anything that might have changed with this recently. @joeloff I'll take a look. @joeloff Hmm, this is definitely some sort of race condition. @KirillOsenkov Just ran into this too: ``` Removing Microsoft.NETCore.App.Runtime.Mono.maccatalyst-x64.Msi.x64 .......... Done Removing Microsoft.NETCore.App.Runtime.Mono.maccatalyst-x64.Msi.x64 .......... DoneSuccessfully installed workload(s) tvos wasm-tools.
Unhandled exception. System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'System.Collections.Concurrent.BlockingCollection
1[[System.String, System.Private.CoreLib, Version=8.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]'. at Microsoft.DotNet.Installer.Windows.TimestampedFileLogger.WriteMessage(String message) at Microsoft.DotNet.Installer.Windows.TimestampedFileLogger.ProcessLogRequests(Object logPipeName) Unhandled exception. System.ObjectDisposedException: Cannot access a disposed object. Object name: 'System.Collections.Concurrent.BlockingCollection1[[System.String, System.Private.CoreLib, Version=8.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]'.at Microsoft.DotNet.Installer.Windows.SetupLoggerBase.LogMessage(String message)
at System.Diagnostics.Process.RaiseOnExited()
at System.Diagnostics.Process.CompletionCallback(Object waitHandleContext, Boolean wasSignaled)
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading.PortableThreadPool.CompleteWait(RegisteredWaitHandle handle, Boolean timedOut)
at System.Threading.ThreadPoolWorkQueue.Dispatch()
at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()