Skip to content

Conversation

@JanKrivanek
Copy link
Member

@JanKrivanek JanKrivanek commented Jul 17, 2024

Fixes #10342

Context

This change workarounds the attempts to log assembly loads via LoggingContext that was invalidated

Theory for rootcause

The AssemblyLoad is AppDomain wide - and doesn't 'respect' current thread nor async context. So if we mount it in one execution context and concurrently executing code leads to assembly loading - it'll still be reported. The handler is executed synchronously - meaning the originally mounting code can be continuing execution and eventually invalidating the passed LoggingContext.

Analysis Details

The added diagnostic showed the context tha was invalid was TaskLoggingContext, it as well showed that it was happening in msbuild within sdk (hence core version).

The TaskLoggingContext is passed to Tracker in 2 locations:

#if FEATURE_APPDOMAIN
appDomainSetup,
appDomain => AssemblyLoadsTracker.StartTracking(taskLoggingContext, AssemblyLoadingContext.TaskRun, _loadedType.Type, appDomain),
#endif

This is not part of core version - so out of question for us

And

private async Task<WorkUnitResult> InitializeAndExecuteTask(TaskLoggingContext taskLoggingContext, ItemBucket bucket, IDictionary<string, string> taskIdentityParameters, TaskHost taskHost, TaskExecutionMode howToExecuteTask)
{
if (!_taskExecutionHost.InitializeForBatch(taskLoggingContext, bucket, taskIdentityParameters))
{
ProjectErrorUtilities.ThrowInvalidProject(_targetChildInstance.Location, "TaskDeclarationOrUsageError", _taskNode.Name);
}
using var assemblyLoadsTracker = AssemblyLoadsTracker.StartTracking(taskLoggingContext, AssemblyLoadingContext.TaskRun, _taskExecutionHost?.TaskInstance?.GetType());
try
{
// UNDONE: Move this and the task host.
taskHost.LoggingContext = taskLoggingContext;
WorkUnitResult executionResult = await ExecuteInstantiatedTask(_taskExecutionHost, taskLoggingContext, taskHost, bucket, howToExecuteTask);
ErrorUtilities.VerifyThrow(executionResult != null, "Unexpected null execution result");
return executionResult;
}
finally
{
_taskExecutionHost.CleanupForBatch();
}
}

Here the tracker is wrapped in using - so the LoggingContex would need to be invalidated in this scope (or passed already invalid).

TaskLoggingContext is allways created valid (IsValid set to true in constructor) and only invalidated in

internal void LogTaskBatchFinished(string projectFullPath, bool success)
{
ErrorUtilities.VerifyThrow(this.IsValid, "invalid");
LoggingService.LogTaskFinished(
BuildEventContext,
_taskName,
projectFullPath,
_task.Location.File,
success);
this.IsValid = false;
}

which is called in a single place - in ExecuteBucket, which is outer scope for InitializeAndExecuteTask that contains the tracker call. The InitializeAndExecuteTask is async - but it doesn't influence the Dispose scope.

BUT - the fact that the mounting method (InitializeAndExecuteTask) is async suggest that there likely might be concurrently executing code.

This points to tracker actually logging an assembly load event from unrelated thread - supported by the fact that the AssemblyLoadsTracker seems to be on the very 'bottom' of the stack:

image

While the handler should be executed synchronously - so we'd expect the TaskBuilder frames below the tracker frames.

Simple unrelated test of trying to mount AssemblyLoad event in main function with simple console output, shows that the assembly loads can be reported from unrelated threads (while those 'hide' their frames, as they are not considered 'user code'):

image

Based on the stats from builds - this was happening as well in the past - just not that often. So it's not a new regression, just some change (our or arcade) increased parallel execution or loading of assemblies on other threads.

In ideal situation we'd 'somehow' filter out the assembly load events that are from different AsyncContext/ExecutionContext/SynchronizationContext than the one requesting the tracking - but it is currently not worth the efforts.

Co-authored-by: Rainer Sigwald <[email protected]>
@JanKrivanek JanKrivanek enabled auto-merge (squash) July 18, 2024 06:12
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

[Bug]: MSBuild crashes with "MSB0001: Internal MSBuild Error: must be valid"

4 participants