Skip to content

Commit db5eca3

Browse files
YuliiaKovalovaYuliiaKovalova
authored
Fix race condition in LoggingService.ProcessLoggingEvent after shutdown (#13450)
## 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.
1 parent 5065de5 commit db5eca3

2 files changed

Lines changed: 151 additions & 6 deletions

File tree

‎src/Build.UnitTests/BackEnd/LoggingService_Tests.cs‎

Lines changed: 115 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1075,6 +1075,121 @@ public void ImportanceReflectsUnknownLoggerVerbosity()
10751075
}
10761076
#endregion
10771077

1078+
#region ProcessLoggingEvent After Shutdown Tests
1079+
1080+
/// <summary>
1081+
/// Verify that ProcessLoggingEvent does not crash when called after the
1082+
/// LoggingService has been shut down (asynchronous mode). This reproduces
1083+
/// the race condition where an external callback (e.g., Process.Exited)
1084+
/// tries to log after ShutdownComponent has nullified internal state.
1085+
/// </summary>
1086+
[Fact]
1087+
public void ProcessLoggingEventAfterShutdown_Asynchronous_DoesNotThrow()
1088+
{
1089+
BuildParameters parameters = new BuildParameters();
1090+
parameters.MaxNodeCount = 2;
1091+
MockHost mockHost = new MockHost(parameters);
1092+
1093+
LoggingService loggingService = (LoggingService)LoggingService.CreateLoggingService(LoggerMode.Asynchronous, 1);
1094+
((IBuildComponent)loggingService).InitializeComponent(mockHost);
1095+
loggingService.RegisterLogger(new ConsoleLogger());
1096+
1097+
// Shut down the service, which will null out _eventQueue, _dequeueEvent, _enqueueEvent.
1098+
((IBuildComponent)loggingService).ShutdownComponent();
1099+
loggingService.ServiceState.ShouldBe(LoggingServiceState.Shutdown);
1100+
1101+
// Simulate a late callback (e.g., Process.Exited) trying to log after shutdown.
1102+
// This must not throw a NullReferenceException.
1103+
BuildMessageEventArgs lateEvent = new BuildMessageEventArgs("Project cache service process exited", null, null, MessageImportance.Low);
1104+
loggingService.ProcessLoggingEvent(lateEvent);
1105+
}
1106+
1107+
/// <summary>
1108+
/// Verify that ProcessLoggingEvent does not crash when called after the
1109+
/// LoggingService has been shut down (synchronous mode).
1110+
/// </summary>
1111+
[Fact]
1112+
public void ProcessLoggingEventAfterShutdown_Synchronous_DoesNotThrow()
1113+
{
1114+
// _initializedService was created in synchronous mode by InitializeLoggingService().
1115+
_initializedService.RegisterLogger(new ConsoleLogger());
1116+
1117+
((IBuildComponent)_initializedService).ShutdownComponent();
1118+
_initializedService.ServiceState.ShouldBe(LoggingServiceState.Shutdown);
1119+
1120+
// Late log after shutdown - must not crash.
1121+
BuildMessageEventArgs lateEvent = new BuildMessageEventArgs("Late message after shutdown", null, null, MessageImportance.Low);
1122+
_initializedService.ProcessLoggingEvent(lateEvent);
1123+
}
1124+
1125+
/// <summary>
1126+
/// Verify that ProcessLoggingEvent still works normally during an active build
1127+
/// (before shutdown). This ensures the fix does not break regular logging.
1128+
/// </summary>
1129+
[Fact]
1130+
public void ProcessLoggingEventDuringActiveBuild_StillWorks()
1131+
{
1132+
MockLogger mockLogger = new MockLogger();
1133+
_initializedService.RegisterLogger(mockLogger);
1134+
1135+
BuildMessageEventArgs messageEvent = new BuildMessageEventArgs("Test message during active build", null, null, MessageImportance.High);
1136+
_initializedService.ProcessLoggingEvent(messageEvent);
1137+
1138+
// In synchronous mode, the event is routed immediately.
1139+
mockLogger.BuildMessageEvents.Count.ShouldBe(1);
1140+
mockLogger.BuildMessageEvents[0].Message.ShouldBe("Test message during active build");
1141+
}
1142+
1143+
/// <summary>
1144+
/// Verify that concurrent shutdown and ProcessLoggingEvent calls from multiple
1145+
/// threads do not cause a crash (simulates the race condition scenario).
1146+
/// </summary>
1147+
[Fact]
1148+
public void ProcessLoggingEventConcurrentWithShutdown_DoesNotThrow()
1149+
{
1150+
BuildParameters parameters = new BuildParameters();
1151+
parameters.MaxNodeCount = 2;
1152+
MockHost mockHost = new MockHost(parameters);
1153+
1154+
LoggingService loggingService = (LoggingService)LoggingService.CreateLoggingService(LoggerMode.Asynchronous, 1);
1155+
((IBuildComponent)loggingService).InitializeComponent(mockHost);
1156+
loggingService.RegisterLogger(new ConsoleLogger());
1157+
1158+
using ManualResetEvent startSignal = new ManualResetEvent(false);
1159+
Exception caughtException = null;
1160+
1161+
// Start a thread that will log events repeatedly.
1162+
Thread logThread = new Thread(() =>
1163+
{
1164+
startSignal.WaitOne();
1165+
for (int i = 0; i < 100; i++)
1166+
{
1167+
try
1168+
{
1169+
BuildMessageEventArgs msg = new BuildMessageEventArgs($"Message {i}", null, null, MessageImportance.Low);
1170+
loggingService.ProcessLoggingEvent(msg);
1171+
}
1172+
catch (Exception ex)
1173+
{
1174+
Interlocked.CompareExchange(ref caughtException, ex, null);
1175+
break;
1176+
}
1177+
}
1178+
});
1179+
1180+
logThread.Start();
1181+
1182+
// Signal both threads and immediately shut down from main thread.
1183+
startSignal.Set();
1184+
((IBuildComponent)loggingService).ShutdownComponent();
1185+
1186+
bool joined = logThread.Join(TimeSpan.FromSeconds(10));
1187+
joined.ShouldBeTrue("Logging thread did not terminate within the allotted time.");
1188+
caughtException.ShouldBeNull();
1189+
}
1190+
1191+
#endregion
1192+
10781193
#region PrivateMethods
10791194

10801195
/// <summary>

‎src/Build/BackEnd/Components/Logging/LoggingService.cs‎

Lines changed: 36 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -1294,18 +1294,48 @@ public void LogBuildEvent(BuildEventArgs buildEvent)
12941294
/// <exception cref="InternalErrorException">buildEvent is null</exception>
12951295
protected internal virtual void ProcessLoggingEvent(object buildEvent)
12961296
{
1297+
// Avoid processing events after shutdown has cleaned up resources.
1298+
// External code (e.g., plugin adapters) may hold references to LoggingService
1299+
// and attempt to log after shutdown has nullified internal state.
1300+
if (_serviceState == LoggingServiceState.Shutdown)
1301+
{
1302+
return;
1303+
}
1304+
12971305
ErrorUtilities.VerifyThrow(buildEvent != null, "buildEvent is null");
12981306
if (_logMode == LoggerMode.Asynchronous)
12991307
{
1300-
// Block until queue is not full.
1301-
while (_eventQueue.Count >= _queueCapacity)
1308+
// Capture local references to prevent race with CleanLoggingEventProcessing
1309+
// which sets these fields to null during shutdown.
1310+
ConcurrentQueue<object> eventQueue = _eventQueue;
1311+
AutoResetEvent dequeueEvent = _dequeueEvent;
1312+
AutoResetEvent enqueueEvent = _enqueueEvent;
1313+
1314+
// Double-check after capturing references in case shutdown raced between
1315+
// the _serviceState check above and the field reads.
1316+
if (eventQueue == null || dequeueEvent == null || enqueueEvent == null)
13021317
{
1303-
// Block and wait for dequeue event.
1304-
_dequeueEvent.WaitOne();
1318+
return;
13051319
}
13061320

1307-
_eventQueue.Enqueue(buildEvent);
1308-
_enqueueEvent.Set();
1321+
try
1322+
{
1323+
// Block until queue is not full.
1324+
while (eventQueue.Count >= _queueCapacity)
1325+
{
1326+
// Block and wait for dequeue event.
1327+
dequeueEvent.WaitOne();
1328+
}
1329+
1330+
eventQueue.Enqueue(buildEvent);
1331+
enqueueEvent.Set();
1332+
}
1333+
catch (ObjectDisposedException)
1334+
{
1335+
// Shutdown disposed the wait handles after we captured them;
1336+
// silently drop the event.
1337+
return;
1338+
}
13091339
}
13101340
else
13111341
{

0 commit comments

Comments
 (0)