Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
115 changes: 115 additions & 0 deletions src/Build.UnitTests/BackEnd/LoggingService_Tests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -1075,6 +1075,121 @@ public void ImportanceReflectsUnknownLoggerVerbosity()
}
#endregion

#region ProcessLoggingEvent After Shutdown Tests

/// <summary>
/// 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.
/// </summary>
[Fact]
public void ProcessLoggingEventAfterShutdown_Asynchronous_DoesNotThrow()
Comment on lines +1078 to +1087
Copy link

Copilot AI Apr 7, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These added tests don't use TestEnvironment / ITestOutputHelper patterns that are used broadly in this test suite to ensure deterministic cleanup and capture diagnostic output in CI. Consider updating the test class to accept ITestOutputHelper and creating a TestEnvironment in the new tests so failures include useful logs and any test state is reliably reverted.

Copilot uses AI. Check for mistakes.
{
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());

Comment on lines +1093 to +1096
Copy link

Copilot AI Apr 7, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The new tests register ConsoleLogger, which writes to stdout and can introduce noisy/flaky test output. Prefer using MockLogger (optionally constructed with ITestOutputHelper) so assertions can be made against captured events without depending on console IO.

Copilot uses AI. Check for mistakes.
// 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);
}

/// <summary>
/// Verify that ProcessLoggingEvent does not crash when called after the
/// LoggingService has been shut down (synchronous mode).
/// </summary>
[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);
}

/// <summary>
/// Verify that ProcessLoggingEvent still works normally during an active build
/// (before shutdown). This ensures the fix does not break regular logging.
/// </summary>
[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");
}

/// <summary>
/// Verify that concurrent shutdown and ProcessLoggingEvent calls from multiple
/// threads do not cause a crash (simulates the race condition scenario).
/// </summary>
[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;
}
}
});
Comment on lines +1164 to +1178
Copy link

Copilot AI Apr 7, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

logThread is created as a foreground Thread and waits on startSignal.WaitOne() with no timeout. If the test fails before startSignal.Set() (or if the thread blocks unexpectedly), it can leave a live foreground thread and hang the test host process. Set IsBackground = true and/or use a timed wait with an assertion so the thread can’t outlive the test.

Suggested change
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;
}
}
});
try
{
bool signaled = startSignal.WaitOne(TimeSpan.FromSeconds(10));
signaled.ShouldBeTrue("Logging thread did not receive the start signal within the allotted time.");
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;
}
}
}
catch (Exception ex)
{
Interlocked.CompareExchange(ref caughtException, ex, null);
}
})
{
IsBackground = true
};

Copilot uses AI. Check for mistakes.

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

/// <summary>
Expand Down
42 changes: 36 additions & 6 deletions src/Build/BackEnd/Components/Logging/LoggingService.cs
Original file line number Diff line number Diff line change
Expand Up @@ -1286,18 +1286,48 @@ public void LogBuildEvent(BuildEventArgs buildEvent)
/// <exception cref="InternalErrorException">buildEvent is null</exception>
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<object> 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
{
Expand Down
Loading