From 7f340ded3f6dc5e89552762bd232e3488c811c86 Mon Sep 17 00:00:00 2001 From: YuliiaKovalova <95473390+YuliiaKovalova@users.noreply.github.com> Date: Fri, 27 Mar 2026 16:08:51 +0100 Subject: [PATCH] Fix race condition in LoggingService.ProcessLoggingEvent after shutdown (#13450) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Summary Fix a race condition crash (access violation 0xC0000005 / NullReferenceException) in `LoggingService.ProcessLoggingEvent` when the method is called after the logging service has been shut down. ## Problem `ProcessLoggingEvent` directly accesses `_eventQueue`, `_dequeueEvent`, and `_enqueueEvent` without any shutdown guard. During `ShutdownComponent()`, `CleanLoggingEventProcessing()` disposes and nullifies all of these fields. If an external callback (e.g., `Process.Exited` from a `ProjectCachePlugin`) attempts to log a message after shutdown has completed, the null field access causes an unrecoverable crash. ### Reproduction Scenario 1. A build runs with a `ProjectCachePlugin` 2. The build completes and `LoggingService.ShutdownComponent()` is called 3. The cache plugin's external process exits, triggering `Process.OnExited` on a ThreadPool thread 4. The callback logs "Project cache service process exited" via `LoggingServiceToPluginLoggerAdapter.LogMessage` 5. This calls `ProcessLoggingEvent()` which accesses `_eventQueue.Count` → **null reference crash** ### Debugger Evidence ``` _serviceState = Shutdown _eventQueue = null _dequeueEvent = null _enqueueEvent = null _emptyQueueEvent = null _loggingEventProcessingCancellation = null buildEvent.Message = "Project cache service process exited" Call: System.Diagnostics.Process.OnExited -> ProjectCachePlugin.dll -> LoggingServiceToPluginLoggerAdapter.LogMessage ``` ## Root Cause `ProcessLoggingEvent` lacked two protections that already exist elsewhere in the codebase: 1. **Shutdown state guard** - Other public methods (`RegisterLogger`, `RegisterDistributedLogger`, `InitializeNodeLoggers`, `InitializeComponent`) all check `_serviceState != LoggingServiceState.Shutdown`. `ProcessLoggingEvent` did not. 2. **Local field capture** - The `LoggingEventProc` queue pump thread already captures `_eventQueue`, `_dequeueEvent`, `_emptyQueueEvent`, and `_enqueueEvent` into local variables to prevent races with `CleanLoggingEventProcessing()`. `ProcessLoggingEvent` accessed the fields directly. ## Fix Three layers of defense, all following patterns already established in the same file: 1. **Early return** when `_serviceState == LoggingServiceState.Shutdown` - silently drops the event, since the service is no longer operational. 2. **Capture fields to locals** before use - prevents null dereference if `CleanLoggingEventProcessing()` runs concurrently between the state check and the field reads. 3. **Null-check the captured locals** - second defense against the TOCTOU race between step 1 and step 2. ## Risk **Low.** The fix only adds early-exit guards - no behavioral change for the normal (non-shutdown) code path. The patterns used are already established in the same file. --- .../BackEnd/LoggingService_Tests.cs | 115 ++++++++++++++++++ .../Components/Logging/LoggingService.cs | 42 ++++++- 2 files changed, 151 insertions(+), 6 deletions(-) diff --git a/src/Build.UnitTests/BackEnd/LoggingService_Tests.cs b/src/Build.UnitTests/BackEnd/LoggingService_Tests.cs index 4d42f596bcb..7db8ea66ddd 100644 --- a/src/Build.UnitTests/BackEnd/LoggingService_Tests.cs +++ b/src/Build.UnitTests/BackEnd/LoggingService_Tests.cs @@ -1075,6 +1075,121 @@ public void ImportanceReflectsUnknownLoggerVerbosity() } #endregion + #region ProcessLoggingEvent After Shutdown Tests + + /// + /// Verify that ProcessLoggingEvent does not crash when called after the + /// LoggingService has been shut down (asynchronous mode). This reproduces + /// the race condition where an external callback (e.g., Process.Exited) + /// tries to log after ShutdownComponent has nullified internal state. + /// + [Fact] + public void ProcessLoggingEventAfterShutdown_Asynchronous_DoesNotThrow() + { + BuildParameters parameters = new BuildParameters(); + parameters.MaxNodeCount = 2; + MockHost mockHost = new MockHost(parameters); + + LoggingService loggingService = (LoggingService)LoggingService.CreateLoggingService(LoggerMode.Asynchronous, 1); + ((IBuildComponent)loggingService).InitializeComponent(mockHost); + loggingService.RegisterLogger(new ConsoleLogger()); + + // Shut down the service, which will null out _eventQueue, _dequeueEvent, _enqueueEvent. + ((IBuildComponent)loggingService).ShutdownComponent(); + loggingService.ServiceState.ShouldBe(LoggingServiceState.Shutdown); + + // Simulate a late callback (e.g., Process.Exited) trying to log after shutdown. + // This must not throw a NullReferenceException. + BuildMessageEventArgs lateEvent = new BuildMessageEventArgs("Project cache service process exited", null, null, MessageImportance.Low); + loggingService.ProcessLoggingEvent(lateEvent); + } + + /// + /// Verify that ProcessLoggingEvent does not crash when called after the + /// LoggingService has been shut down (synchronous mode). + /// + [Fact] + public void ProcessLoggingEventAfterShutdown_Synchronous_DoesNotThrow() + { + // _initializedService was created in synchronous mode by InitializeLoggingService(). + _initializedService.RegisterLogger(new ConsoleLogger()); + + ((IBuildComponent)_initializedService).ShutdownComponent(); + _initializedService.ServiceState.ShouldBe(LoggingServiceState.Shutdown); + + // Late log after shutdown - must not crash. + BuildMessageEventArgs lateEvent = new BuildMessageEventArgs("Late message after shutdown", null, null, MessageImportance.Low); + _initializedService.ProcessLoggingEvent(lateEvent); + } + + /// + /// Verify that ProcessLoggingEvent still works normally during an active build + /// (before shutdown). This ensures the fix does not break regular logging. + /// + [Fact] + public void ProcessLoggingEventDuringActiveBuild_StillWorks() + { + MockLogger mockLogger = new MockLogger(); + _initializedService.RegisterLogger(mockLogger); + + BuildMessageEventArgs messageEvent = new BuildMessageEventArgs("Test message during active build", null, null, MessageImportance.High); + _initializedService.ProcessLoggingEvent(messageEvent); + + // In synchronous mode, the event is routed immediately. + mockLogger.BuildMessageEvents.Count.ShouldBe(1); + mockLogger.BuildMessageEvents[0].Message.ShouldBe("Test message during active build"); + } + + /// + /// Verify that concurrent shutdown and ProcessLoggingEvent calls from multiple + /// threads do not cause a crash (simulates the race condition scenario). + /// + [Fact] + public void ProcessLoggingEventConcurrentWithShutdown_DoesNotThrow() + { + BuildParameters parameters = new BuildParameters(); + parameters.MaxNodeCount = 2; + MockHost mockHost = new MockHost(parameters); + + LoggingService loggingService = (LoggingService)LoggingService.CreateLoggingService(LoggerMode.Asynchronous, 1); + ((IBuildComponent)loggingService).InitializeComponent(mockHost); + loggingService.RegisterLogger(new ConsoleLogger()); + + using ManualResetEvent startSignal = new ManualResetEvent(false); + Exception caughtException = null; + + // Start a thread that will log events repeatedly. + Thread logThread = new Thread(() => + { + startSignal.WaitOne(); + for (int i = 0; i < 100; i++) + { + try + { + BuildMessageEventArgs msg = new BuildMessageEventArgs($"Message {i}", null, null, MessageImportance.Low); + loggingService.ProcessLoggingEvent(msg); + } + catch (Exception ex) + { + Interlocked.CompareExchange(ref caughtException, ex, null); + break; + } + } + }); + + logThread.Start(); + + // Signal both threads and immediately shut down from main thread. + startSignal.Set(); + ((IBuildComponent)loggingService).ShutdownComponent(); + + bool joined = logThread.Join(TimeSpan.FromSeconds(10)); + joined.ShouldBeTrue("Logging thread did not terminate within the allotted time."); + caughtException.ShouldBeNull(); + } + + #endregion + #region PrivateMethods /// diff --git a/src/Build/BackEnd/Components/Logging/LoggingService.cs b/src/Build/BackEnd/Components/Logging/LoggingService.cs index 24d8dcb0944..65c67c44041 100644 --- a/src/Build/BackEnd/Components/Logging/LoggingService.cs +++ b/src/Build/BackEnd/Components/Logging/LoggingService.cs @@ -1286,18 +1286,48 @@ public void LogBuildEvent(BuildEventArgs buildEvent) /// buildEvent is null protected internal virtual void ProcessLoggingEvent(object buildEvent) { + // Avoid processing events after shutdown has cleaned up resources. + // External code (e.g., plugin adapters) may hold references to LoggingService + // and attempt to log after shutdown has nullified internal state. + if (_serviceState == LoggingServiceState.Shutdown) + { + return; + } + ErrorUtilities.VerifyThrow(buildEvent != null, "buildEvent is null"); if (_logMode == LoggerMode.Asynchronous) { - // Block until queue is not full. - while (_eventQueue.Count >= _queueCapacity) + // Capture local references to prevent race with CleanLoggingEventProcessing + // which sets these fields to null during shutdown. + ConcurrentQueue eventQueue = _eventQueue; + AutoResetEvent dequeueEvent = _dequeueEvent; + AutoResetEvent enqueueEvent = _enqueueEvent; + + // Double-check after capturing references in case shutdown raced between + // the _serviceState check above and the field reads. + if (eventQueue == null || dequeueEvent == null || enqueueEvent == null) { - // Block and wait for dequeue event. - _dequeueEvent.WaitOne(); + return; } - _eventQueue.Enqueue(buildEvent); - _enqueueEvent.Set(); + try + { + // Block until queue is not full. + while (eventQueue.Count >= _queueCapacity) + { + // Block and wait for dequeue event. + dequeueEvent.WaitOne(); + } + + eventQueue.Enqueue(buildEvent); + enqueueEvent.Set(); + } + catch (ObjectDisposedException) + { + // Shutdown disposed the wait handles after we captured them; + // silently drop the event. + return; + } } else {