Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Bypass logcontext validity check #10401

Merged
merged 2 commits into from
Jul 18, 2024
Merged

Bypass logcontext validity check #10401

merged 2 commits into from
Jul 18, 2024

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 <raines@microsoft.com>
@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"
3 participants