Skip to content

Commit 6ce195f

Browse files
JanKrivanekJanKrivanek
authored
Log assembly loads during task run (#8316)
Fixes #6303 Related: KirillOsenkov/MSBuildStructuredLog#653 Context Assembly loading logging for: Task runs - including loads in separate app domain for AppDomainIsolatedTask Except for tasks runs in OutOfProcessRaskHostNode - as neither LoggingService nor LoggingContext are available there - not sure if not supporting those is a problem. Sdk resolving (explicitly skipping resolvers defined in Microsoft.Build assembly) Loggers initialization (explicitly skipping resolvers defined in Microsoft.Build assembly orwithin Microsoft.Build.Logging namespace) - Note - loggers initialiation reordered - Binlog is the first one - as assembly load events are emited at the time of each logger initialization, currently LoggerService dispatches events immediately after construction, so as a result order of logger definitions matter (only the earlier initialized gets messages about latter ones initialization assembly loads). Alternative would be to change the LoggerService contract to start dispatching on explicit request (easy to implement and preserving current MSBuild behavior - however might be potentially breaking for API users?) or to cache those events and log them later (doable, but convoluted - probably not worth the efforts now) Evaluation Samples task run: Assembly loaded during TaskRun: System.Diagnostics.Debug, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a (location: C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System.Diagnostics.Debug\v4.0_4.0.0.0__b03f5f7f11d50a3a\System.Diagnostics.Debug.dll, MVID: bc6b825d-5f99-464e-a06d-e3ae4b860a34, AppDomain: [Default]) evaluation: Assembly loaded during Evaluation: System.Collections.Immutable, Version=7.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a (location: C:\Program Files\dotnet\shared\Microsoft.NETCore.App\7.0.2\System.Collections.Immutable.dll, MVID: 5a4c54a3-2092-428e-89cc-a391fd9d398a, AppDomain: [Default]) logger initialization: Assembly loaded during LoggerInitialization (MyLoggers.BasicFileLogger): System.Reflection.Metadata, Version=7.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a (location: C:\Program Files\dotnet\shared\Microsoft.NETCore.App\7.0.2\System.Reflection.Metadata.dll, MVID: c602a8ce-3890-40fc-aa9b-fa3c23f81aab, AppDomain: [Default]) custom sdk resolver (no sample - similar to logger initialization) Perf impact No observable impact. MSBUILDLOGALLASSEMBLYLOADS is used to turn on loggin of all assembly loads build command: msbuild.exe <proj> /nodeReuse:false /bl Scenario Mean Duration Orchard - MSBuild main 00:00:59.25 Orchard - curr branch 00:00:58.30 Orchard - curr branch, all loads 00:00:58.30 Console - MSBuild main 00:00:01.08 Console - curr branch 00:00:01.09 Console - curr branch, all loads 00:00:01.10
1 parent 2fb4845 commit 6ce195f

39 files changed

+650
-19
lines changed

‎documentation/wiki/ChangeWaves.md

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,7 @@ A wave of features is set to "rotate out" (i.e. become standard functionality) t
2727
- [Parse invalid property under target](https://github.com/dotnet/msbuild/pull/8190)
2828
- [Eliminate project string cache](https://github.com/dotnet/msbuild/pull/7965)
2929
- [Log an error when no provided search path for an import exists](https://github.com/dotnet/msbuild/pull/8095)
30+
- [Log assembly loads](https://github.com/dotnet/msbuild/pull/8316)
3031

3132
### 17.4
3233
- [Respect deps.json when loading assemblies](https://github.com/dotnet/msbuild/pull/7520)

‎src/Build.UnitTests/BinaryLogger_Tests.cs

Lines changed: 49 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -188,6 +188,55 @@ public void UnusedEnvironmentVariablesDoNotAppearInBinaryLog()
188188
}
189189
}
190190

191+
[Fact]
192+
public void AssemblyLoadsDuringTaskRunLogged()
193+
{
194+
using (TestEnvironment env = TestEnvironment.Create())
195+
{
196+
string contents = $"""
197+
<Project ToolsVersion="15.0" xmlns="http://schemas.microsoft.com/developer/msbuild/2003" DefaultTargets="Hello">
198+
<!-- This simple inline task displays "Hello, world!" -->
199+
<UsingTask
200+
TaskName="HelloWorld"
201+
TaskFactory="RoslynCodeTaskFactory"
202+
AssemblyFile="$(MSBuildToolsPath)\Microsoft.Build.Tasks.Core.dll" >
203+
<ParameterGroup />
204+
<Task>
205+
<Using Namespace="System"/>
206+
<Using Namespace="System.IO"/>
207+
<Using Namespace="System.Reflection"/>
208+
<Code Type="Fragment" Language="cs">
209+
<![CDATA[
210+
// Display "Hello, world!"
211+
Log.LogMessage("Hello, world!");
212+
//load assembly
213+
var assemblies = AppDomain.CurrentDomain.GetAssemblies();
214+
var diagAssembly = Assembly.LoadFrom(Path.Combine(Path.GetDirectoryName(assemblies[0].Location), "System.Diagnostics.Debug.dll"));
215+
Log.LogMessage("Loaded: " + diagAssembly);
216+
]]>
217+
</Code>
218+
</Task>
219+
</UsingTask>
220+
221+
<Target Name="Hello">
222+
<HelloWorld />
223+
</Target>
224+
</Project>
225+
""";
226+
TransientTestFolder logFolder = env.CreateFolder(createFolder: true);
227+
TransientTestFile projectFile = env.CreateFile(logFolder, "myProj.proj", contents);
228+
BinaryLogger logger = new();
229+
logger.Parameters = _logFile;
230+
env.SetEnvironmentVariable("MSBUILDNOINPROCNODE", "1");
231+
RunnerUtilities.ExecMSBuild($"{projectFile.Path} -nr:False -bl:{logger.Parameters}", out bool success);
232+
success.ShouldBeTrue();
233+
RunnerUtilities.ExecMSBuild($"{logger.Parameters} -flp:logfile={Path.Combine(logFolder.Path, "logFile.log")};verbosity=diagnostic", out success);
234+
success.ShouldBeTrue();
235+
string text = File.ReadAllText(Path.Combine(logFolder.Path, "logFile.log"));
236+
text.ShouldContain("Assembly loaded during TaskRun (InlineCode.HelloWorld): System.Diagnostics.Debug");
237+
}
238+
}
239+
191240
[Fact]
192241
public void BinaryLoggerShouldEmbedFilesViaTaskOutput()
193242
{

‎src/Build/BackEnd/Components/Communications/NodeProviderOutOfProcBase.cs

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -286,6 +286,8 @@ bool TryReuseAnyFromPossibleRunningNodes(int nodeId)
286286
{
287287
// Connection successful, use this node.
288288
CommunicationsUtilities.Trace("Successfully connected to existed node {0} which is PID {1}", nodeId, nodeToReuse.Id);
289+
string msg = ResourceUtilities.FormatResourceStringIgnoreCodeAndKeyword("NodeReused", nodeId, nodeToReuse.Id);
290+
_componentHost.LoggingService.LogBuildEvent(new BuildMessageEventArgs(msg, null, null, MessageImportance.Low));
289291

290292
CreateNodeContext(nodeId, nodeToReuse, nodeStream);
291293
return true;

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

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,8 @@
88
using System.Linq;
99
using System.Reflection;
1010
using System.Threading;
11+
using Microsoft.Build.BackEnd.Components.RequestBuilder;
12+
using Microsoft.Build.Evaluation;
1113
using Microsoft.Build.Framework;
1214
using Microsoft.Build.Shared;
1315
using InternalLoggerException = Microsoft.Build.Exceptions.InternalLoggerException;
@@ -1589,8 +1591,20 @@ private void RouteBuildEvent(BuildEventArgs eventArg)
15891591
/// <exception cref="Exception">Any exception which is a ExceptionHandling.IsCriticalException will not be wrapped</exception>
15901592
private void InitializeLogger(ILogger logger, IEventSource sourceForLogger)
15911593
{
1594+
ILogger UnwrapLoggerType(ILogger log)
1595+
{
1596+
while (log is ProjectCollection.ReusableLogger reusableLogger)
1597+
{
1598+
log = reusableLogger.OriginalLogger;
1599+
}
1600+
1601+
return log;
1602+
}
1603+
15921604
try
15931605
{
1606+
using var assemblyLoadTracker = AssemblyLoadsTracker.StartTracking(this, AssemblyLoadingContext.LoggerInitialization, UnwrapLoggerType(logger).GetType());
1607+
15941608
INodeLogger nodeLogger = logger as INodeLogger;
15951609
if (nodeLogger != null)
15961610
{

‎src/Build/BackEnd/Components/RequestBuilder/AssemblyLoadsTracker.cs

Lines changed: 174 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,174 @@
1+
// Licensed to the .NET Foundation under one or more agreements.
2+
// The .NET Foundation licenses this file to you under the MIT license.
3+
4+
using System;
5+
#if FEATURE_APPDOMAIN
6+
using System.Collections.Generic;
7+
using System.Linq;
8+
#endif
9+
using System.Reflection;
10+
using Microsoft.Build.BackEnd.Logging;
11+
using Microsoft.Build.Framework;
12+
13+
namespace Microsoft.Build.BackEnd.Components.RequestBuilder
14+
{
15+
internal sealed class AssemblyLoadsTracker : MarshalByRefObject, IDisposable
16+
{
17+
#if FEATURE_APPDOMAIN
18+
private static readonly List<AssemblyLoadsTracker> s_instances = new();
19+
#endif
20+
private readonly LoggingContext? _loggingContext;
21+
private readonly LoggingService? _loggingService;
22+
private readonly AssemblyLoadingContext _context;
23+
private readonly string? _initiator;
24+
private readonly AppDomain _appDomain;
25+
26+
private AssemblyLoadsTracker(
27+
LoggingContext? loggingContext,
28+
LoggingService? loggingService,
29+
AssemblyLoadingContext context,
30+
Type? initiator,
31+
AppDomain appDomain)
32+
{
33+
_loggingContext = loggingContext;
34+
_loggingService = loggingService;
35+
_context = context;
36+
_initiator = initiator?.FullName;
37+
_appDomain = appDomain;
38+
}
39+
40+
public static IDisposable StartTracking(
41+
LoggingContext loggingContext,
42+
AssemblyLoadingContext context,
43+
Type? initiator,
44+
AppDomain? appDomain = null)
45+
=> StartTracking(loggingContext, null, context, initiator, null, appDomain);
46+
47+
public static IDisposable StartTracking(
48+
LoggingContext loggingContext,
49+
AssemblyLoadingContext context,
50+
string? initiator = null,
51+
AppDomain? appDomain = null)
52+
=> StartTracking(loggingContext, null, context, null, initiator, appDomain);
53+
54+
public static IDisposable StartTracking(
55+
LoggingService loggingService,
56+
AssemblyLoadingContext context,
57+
Type initiator,
58+
AppDomain? appDomain = null)
59+
=> StartTracking(null, loggingService, context, initiator, null, appDomain);
60+
61+
62+
63+
#if FEATURE_APPDOMAIN
64+
public static void StopTracking(AppDomain appDomain)
65+
{
66+
if (ChangeWaves.AreFeaturesEnabled(ChangeWaves.Wave17_6) && !appDomain.IsDefaultAppDomain())
67+
{
68+
lock (s_instances)
69+
{
70+
foreach (AssemblyLoadsTracker tracker in s_instances.Where(t => t._appDomain == appDomain))
71+
{
72+
tracker.StopTracking();
73+
}
74+
75+
s_instances.RemoveAll(t => t._appDomain == appDomain);
76+
}
77+
}
78+
}
79+
#endif
80+
81+
public void Dispose()
82+
{
83+
StopTracking();
84+
}
85+
86+
private static bool IsBuiltinType(string? typeName)
87+
{
88+
if (string.IsNullOrEmpty(typeName))
89+
{
90+
return false;
91+
}
92+
93+
return typeName!.StartsWith("Microsoft.Build", StringComparison.Ordinal) ||
94+
typeName.StartsWith("Microsoft.NET.Build", StringComparison.Ordinal) ||
95+
typeName.StartsWith("Microsoft.NET.Sdk", StringComparison.Ordinal);
96+
}
97+
98+
private static IDisposable StartTracking(
99+
LoggingContext? loggingContext,
100+
LoggingService? loggingService,
101+
AssemblyLoadingContext context,
102+
Type? initiatorType,
103+
string? initiatorName,
104+
AppDomain? appDomain)
105+
{
106+
if (
107+
// Feature is not enabled
108+
!ChangeWaves.AreFeaturesEnabled(ChangeWaves.Wave17_6) ||
109+
(
110+
// We do not want to load all assembly loads (including those triggered by builtin types)
111+
!Traits.Instance.LogAllAssemblyLoads &&
112+
(
113+
// Load will be initiated by internal type - so we are not interested in those
114+
initiatorType?.Assembly == Assembly.GetExecutingAssembly()
115+
||
116+
IsBuiltinType(initiatorType?.FullName)
117+
||
118+
IsBuiltinType(initiatorName)
119+
)
120+
)
121+
)
122+
{
123+
return EmptyDisposable.Instance;
124+
}
125+
126+
var tracker = new AssemblyLoadsTracker(loggingContext, loggingService, context, initiatorType, appDomain ?? AppDomain.CurrentDomain);
127+
#if FEATURE_APPDOMAIN
128+
if (appDomain != null && !appDomain.IsDefaultAppDomain())
129+
{
130+
lock (s_instances)
131+
{
132+
s_instances.Add(tracker);
133+
}
134+
}
135+
#endif
136+
tracker.StartTracking();
137+
return tracker;
138+
}
139+
140+
private void StartTracking()
141+
{
142+
_appDomain.AssemblyLoad += CurrentDomainOnAssemblyLoad;
143+
}
144+
145+
private void StopTracking()
146+
{
147+
_appDomain.AssemblyLoad -= CurrentDomainOnAssemblyLoad;
148+
}
149+
150+
private void CurrentDomainOnAssemblyLoad(object? sender, AssemblyLoadEventArgs args)
151+
{
152+
string? assemblyName = args.LoadedAssembly.FullName;
153+
string assemblyPath = args.LoadedAssembly.Location;
154+
Guid mvid = args.LoadedAssembly.ManifestModule.ModuleVersionId;
155+
string? appDomainDescriptor = _appDomain.IsDefaultAppDomain()
156+
? null
157+
: $"{_appDomain.Id}|{_appDomain.FriendlyName}";
158+
159+
160+
AssemblyLoadBuildEventArgs buildArgs = new(_context, _initiator, assemblyName, assemblyPath, mvid, appDomainDescriptor)
161+
{
162+
BuildEventContext = _loggingContext?.BuildEventContext ?? BuildEventContext.Invalid
163+
};
164+
_loggingContext?.LogBuildEvent(buildArgs);
165+
_loggingService?.LogBuildEvent(buildArgs);
166+
}
167+
168+
private class EmptyDisposable : IDisposable
169+
{
170+
public static readonly IDisposable Instance = new EmptyDisposable();
171+
public void Dispose() { }
172+
}
173+
}
174+
}

‎src/Build/BackEnd/Components/RequestBuilder/TaskBuilder.cs

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@
1313
#endif
1414
using System.Threading;
1515
using System.Threading.Tasks;
16+
using Microsoft.Build.BackEnd.Components.RequestBuilder;
1617
using Microsoft.Build.Collections;
1718
using Microsoft.Build.Evaluation;
1819
using Microsoft.Build.Eventing;
@@ -661,6 +662,8 @@ private async Task<WorkUnitResult> InitializeAndExecuteTask(TaskLoggingContext t
661662
ProjectErrorUtilities.ThrowInvalidProject(_targetChildInstance.Location, "TaskDeclarationOrUsageError", _taskNode.Name);
662663
}
663664

665+
using var assemblyLoadsTracker = AssemblyLoadsTracker.StartTracking(taskLoggingContext, AssemblyLoadingContext.TaskRun, (_taskExecutionHost as TaskExecutionHost)?.TaskInstance?.GetType());
666+
664667
try
665668
{
666669
// UNDONE: Move this and the task host.

‎src/Build/Evaluation/Evaluator.cs

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@
1111
using System.Text;
1212
using Microsoft.Build.BackEnd;
1313
using Microsoft.Build.BackEnd.Components.Logging;
14+
using Microsoft.Build.BackEnd.Components.RequestBuilder;
1415
using Microsoft.Build.BackEnd.SdkResolution;
1516
using Microsoft.Build.Collections;
1617
using Microsoft.Build.Construction;
@@ -596,6 +597,7 @@ private static ProjectTargetInstance ReadNewTargetElement(ProjectTargetElement t
596597
private void Evaluate()
597598
{
598599
string projectFile = String.IsNullOrEmpty(_projectRootElement.ProjectFileLocation.File) ? "(null)" : _projectRootElement.ProjectFileLocation.File;
600+
using (AssemblyLoadsTracker.StartTracking(_evaluationLoggingContext, AssemblyLoadingContext.Evaluation))
599601
using (_evaluationProfiler.TrackPass(EvaluationPass.TotalEvaluation))
600602
{
601603
ErrorUtilities.VerifyThrow(_data.EvaluationId == BuildEventContext.InvalidEvaluationId, "There is no prior evaluation ID. The evaluator data needs to be reset at this point");
@@ -1843,6 +1845,8 @@ static string EvaluateProperty(string value, IElementLocation location,
18431845
// Combine SDK path with the "project" relative path
18441846
try
18451847
{
1848+
using var assemblyLoadsTracker = AssemblyLoadsTracker.StartTracking(_evaluationLoggingContext, AssemblyLoadingContext.SdkResolution, _sdkResolverService.GetType());
1849+
18461850
sdkResult = _sdkResolverService.ResolveSdk(_submissionId, sdkReference, _evaluationLoggingContext, importElement.Location, solutionPath, projectPath, _interactive, _isRunningInVisualStudio,
18471851
failOnUnresolvedSdk: !_loadSettings.HasFlag(ProjectLoadSettings.IgnoreMissingImports) || _loadSettings.HasFlag(ProjectLoadSettings.FailOnUnresolvedSdk));
18481852
}

‎src/Build/Instance/TaskFactories/AssemblyTaskFactory.cs

Lines changed: 13 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -8,9 +8,10 @@
88
using System.Threading.Tasks;
99
#endif
1010

11+
using Microsoft.Build.BackEnd.Components.RequestBuilder;
1112
using Microsoft.Build.Framework;
1213
using Microsoft.Build.Shared;
13-
14+
using System.IO;
1415
using ElementLocation = Microsoft.Build.Construction.ElementLocation;
1516
using TargetLoggingContext = Microsoft.Build.BackEnd.Logging.TargetLoggingContext;
1617
using TaskLoggingContext = Microsoft.Build.BackEnd.Logging.TaskLoggingContext;
@@ -210,6 +211,7 @@ public void CleanupTask(ITask task)
210211

211212
if (appDomain != null)
212213
{
214+
AssemblyLoadsTracker.StopTracking(appDomain);
213215
// Unload the AppDomain asynchronously to avoid a deadlock that can happen because
214216
// AppDomain.Unload blocks for the process's one Finalizer thread to finalize all
215217
// objects. Some objects are RCWs for STA COM objects and as such would need the
@@ -269,6 +271,10 @@ internal LoadedType InitializeFactory(
269271
{
270272
ErrorUtilities.VerifyThrowArgumentLength(taskName, nameof(taskName));
271273
_taskName = taskName;
274+
275+
string assemblyName = loadInfo.AssemblyName ?? Path.GetFileName(loadInfo.AssemblyFile);
276+
using var assemblyLoadsTracker = AssemblyLoadsTracker.StartTracking(targetLoggingContext, AssemblyLoadingContext.TaskRun, assemblyName);
277+
272278
_loadedType = _typeLoader.Load(taskName, loadInfo, _taskHostFactoryExplicitlyRequested);
273279
ProjectErrorUtilities.VerifyThrowInvalidProject(_loadedType != null, elementLocation, "TaskLoadFailure", taskName, loadInfo.AssemblyLocation, String.Empty);
274280
}
@@ -384,6 +390,7 @@ internal ITask CreateTaskInstance(ElementLocation taskLocation, TaskLoggingConte
384390
new TaskLoader.LogError(ErrorLoggingDelegate),
385391
#if FEATURE_APPDOMAIN
386392
appDomainSetup,
393+
appDomain => AssemblyLoadsTracker.StartTracking(taskLoggingContext, AssemblyLoadingContext.TaskRun, _loadedType.Type, appDomain),
387394
#endif
388395
isOutOfProc
389396
#if FEATURE_APPDOMAIN
@@ -393,10 +400,14 @@ internal ITask CreateTaskInstance(ElementLocation taskLocation, TaskLoggingConte
393400
#pragma warning restore SA1111, SA1009 // Closing parenthesis should be on line of last parameter
394401

395402
#if FEATURE_APPDOMAIN
396-
if (taskAppDomain != null)
403+
if (taskAppDomain != null && taskInstance != null)
397404
{
398405
_tasksAndAppDomains[taskInstance] = taskAppDomain;
399406
}
407+
else if (taskAppDomain != null)
408+
{
409+
AssemblyLoadsTracker.StopTracking(taskAppDomain);
410+
}
400411
#endif
401412

402413
return taskInstance;

‎src/Build/Logging/BinaryLogger/BinaryLogRecordKind.cs

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -34,5 +34,6 @@ internal enum BinaryLogRecordKind
3434
String,
3535
TaskParameter,
3636
ResponseFileUsed,
37+
AssemblyLoad,
3738
}
3839
}

‎src/Build/Logging/BinaryLogger/BinaryLogger.cs

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -57,7 +57,9 @@ public sealed class BinaryLogger : ILogger
5757
// - TargetSkippedEventArgs: added SkipReason, OriginalBuildEventContext
5858
// version 15:
5959
// - new record kind: ResponseFileUsedEventArgs
60-
internal const int FileFormatVersion = 15;
60+
// version 16:
61+
// - AssemblyLoadBuildEventArgs
62+
internal const int FileFormatVersion = 16;
6163

6264
private Stream stream;
6365
private BinaryWriter binaryWriter;

0 commit comments

Comments
 (0)