Skip to content

Commit 944f573

Browse files
authored
Improve logging from agent (#43672)
1 parent 1dcae19 commit 944f573

File tree

16 files changed

+612
-303
lines changed

16 files changed

+612
-303
lines changed
Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,28 @@
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+
namespace Microsoft.Extensions.HotReload;
5+
6+
internal sealed class AgentReporter
7+
{
8+
private readonly List<(string message, AgentMessageSeverity severity)> _log = [];
9+
10+
public void Report(string message, AgentMessageSeverity severity)
11+
{
12+
_log.Add((message, severity));
13+
}
14+
15+
public IReadOnlyCollection<(string message, AgentMessageSeverity severity)> GetAndClearLogEntries(ResponseLoggingLevel level)
16+
{
17+
lock (_log)
18+
{
19+
var filteredLog = (level != ResponseLoggingLevel.Verbose)
20+
? _log.Where(static entry => entry.severity != AgentMessageSeverity.Verbose)
21+
: _log;
22+
23+
var log = filteredLog.ToArray();
24+
_log.Clear();
25+
return log;
26+
}
27+
}
28+
}

src/BuiltInTools/DotNetDeltaApplier/HotReloadAgent.cs

Lines changed: 60 additions & 177 deletions
Large diffs are not rendered by default.
Lines changed: 239 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,239 @@
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.Reflection;
5+
6+
namespace Microsoft.Extensions.HotReload;
7+
8+
/// <summary>
9+
/// Finds and invokes metadata update handlers.
10+
/// </summary>
11+
internal sealed class MetadataUpdateHandlerInvoker(AgentReporter reporter)
12+
{
13+
internal sealed class RegisteredActions(IReadOnlyList<Action<Type[]?>> clearCache, IReadOnlyList<Action<Type[]?>> updateApplication)
14+
{
15+
public void Invoke(Type[] updatedTypes)
16+
{
17+
foreach (var action in clearCache)
18+
{
19+
action(updatedTypes);
20+
}
21+
22+
foreach (var action in updateApplication)
23+
{
24+
action(updatedTypes);
25+
}
26+
}
27+
28+
/// <summary>
29+
/// For testing.
30+
/// </summary>
31+
internal IEnumerable<Action<Type[]?>> ClearCache => clearCache;
32+
33+
/// <summary>
34+
/// For testing.
35+
/// </summary>
36+
internal IEnumerable<Action<Type[]?>> UpdateApplication => updateApplication;
37+
}
38+
39+
private const string ClearCacheHandlerName = "ClearCache";
40+
private const string UpdateApplicationHandlerName = "UpdateApplication";
41+
42+
private RegisteredActions? _actions;
43+
44+
/// <summary>
45+
/// Call when a new assembly is loaded.
46+
/// </summary>
47+
internal void Clear()
48+
=> Interlocked.Exchange(ref _actions, null);
49+
50+
/// <summary>
51+
/// Invokes all registerd handlers.
52+
/// </summary>
53+
internal void Invoke(Type[] updatedTypes)
54+
{
55+
try
56+
{
57+
// Defer discovering metadata updata handlers until after hot reload deltas have been applied.
58+
// This should give enough opportunity for AppDomain.GetAssemblies() to be sufficiently populated.
59+
var actions = _actions;
60+
if (actions == null)
61+
{
62+
Interlocked.CompareExchange(ref _actions, GetMetadataUpdateHandlerActions(), null);
63+
actions = _actions;
64+
}
65+
66+
reporter.Report("Invoking metadata update handlers.", AgentMessageSeverity.Verbose);
67+
68+
actions.Invoke(updatedTypes);
69+
70+
reporter.Report("Deltas applied.", AgentMessageSeverity.Verbose);
71+
}
72+
catch (Exception e)
73+
{
74+
reporter.Report(e.ToString(), AgentMessageSeverity.Warning);
75+
}
76+
}
77+
78+
private IEnumerable<Type> GetHandlerTypes()
79+
{
80+
// We need to execute MetadataUpdateHandlers in a well-defined order. For v1, the strategy that is used is to topologically
81+
// sort assemblies so that handlers in a dependency are executed before the dependent (e.g. the reflection cache action
82+
// in System.Private.CoreLib is executed before System.Text.Json clears its own cache.)
83+
// This would ensure that caches and updates more lower in the application stack are up to date
84+
// before ones higher in the stack are recomputed.
85+
var sortedAssemblies = TopologicalSort(AppDomain.CurrentDomain.GetAssemblies());
86+
87+
foreach (var assembly in sortedAssemblies)
88+
{
89+
foreach (var attr in TryGetCustomAttributesData(assembly))
90+
{
91+
// Look up the attribute by name rather than by type. This would allow netstandard targeting libraries to
92+
// define their own copy without having to cross-compile.
93+
if (attr.AttributeType.FullName != "System.Reflection.Metadata.MetadataUpdateHandlerAttribute")
94+
{
95+
continue;
96+
}
97+
98+
IList<CustomAttributeTypedArgument> ctorArgs = attr.ConstructorArguments;
99+
if (ctorArgs.Count != 1 ||
100+
ctorArgs[0].Value is not Type handlerType)
101+
{
102+
reporter.Report($"'{attr}' found with invalid arguments.", AgentMessageSeverity.Warning);
103+
continue;
104+
}
105+
106+
yield return handlerType;
107+
}
108+
}
109+
}
110+
111+
public RegisteredActions GetMetadataUpdateHandlerActions()
112+
=> GetMetadataUpdateHandlerActions(GetHandlerTypes());
113+
114+
/// <summary>
115+
/// Internal for testing.
116+
/// </summary>
117+
internal RegisteredActions GetMetadataUpdateHandlerActions(IEnumerable<Type> handlerTypes)
118+
{
119+
var clearCacheActions = new List<Action<Type[]?>>();
120+
var updateApplicationActions = new List<Action<Type[]?>>();
121+
122+
foreach (var handlerType in handlerTypes)
123+
{
124+
bool methodFound = false;
125+
126+
if (GetUpdateMethod(handlerType, ClearCacheHandlerName) is MethodInfo clearCache)
127+
{
128+
clearCacheActions.Add(CreateAction(clearCache));
129+
methodFound = true;
130+
}
131+
132+
if (GetUpdateMethod(handlerType, UpdateApplicationHandlerName) is MethodInfo updateApplication)
133+
{
134+
updateApplicationActions.Add(CreateAction(updateApplication));
135+
methodFound = true;
136+
}
137+
138+
if (!methodFound)
139+
{
140+
reporter.Report(
141+
$"Expected to find a static method '{ClearCacheHandlerName}' or '{UpdateApplicationHandlerName}' on type '{handlerType.AssemblyQualifiedName}' but neither exists.",
142+
AgentMessageSeverity.Warning);
143+
}
144+
}
145+
146+
return new RegisteredActions(clearCacheActions, updateApplicationActions);
147+
148+
Action<Type[]?> CreateAction(MethodInfo update)
149+
{
150+
var action = (Action<Type[]?>)update.CreateDelegate(typeof(Action<Type[]?>));
151+
return types =>
152+
{
153+
try
154+
{
155+
action(types);
156+
}
157+
catch (Exception ex)
158+
{
159+
reporter.Report($"Exception from '{action}': {ex}", AgentMessageSeverity.Warning);
160+
}
161+
};
162+
}
163+
164+
MethodInfo? GetUpdateMethod(Type handlerType, string name)
165+
{
166+
if (handlerType.GetMethod(name, BindingFlags.Public | BindingFlags.NonPublic | BindingFlags.Static, binder: null, new[] { typeof(Type[]) }, modifiers: null) is MethodInfo updateMethod &&
167+
updateMethod.ReturnType == typeof(void))
168+
{
169+
return updateMethod;
170+
}
171+
172+
foreach (MethodInfo method in handlerType.GetMethods(BindingFlags.Public | BindingFlags.NonPublic | BindingFlags.Static | BindingFlags.Instance))
173+
{
174+
if (method.Name == name)
175+
{
176+
reporter.Report($"Type '{handlerType}' has method '{method}' that does not match the required signature.", AgentMessageSeverity.Warning);
177+
break;
178+
}
179+
}
180+
181+
return null;
182+
}
183+
}
184+
185+
private IList<CustomAttributeData> TryGetCustomAttributesData(Assembly assembly)
186+
{
187+
try
188+
{
189+
return assembly.GetCustomAttributesData();
190+
}
191+
catch (Exception e)
192+
{
193+
// In cross-platform scenarios, such as debugging in VS through WSL, Roslyn
194+
// runs on Windows, and the agent runs on Linux. Assemblies accessible to Windows
195+
// may not be available or loaded on linux (such as WPF's assemblies).
196+
// In such case, we can ignore the assemblies and continue enumerating handlers for
197+
// the rest of the assemblies of current domain.
198+
reporter.Report($"'{assembly.FullName}' is not loaded ({e.Message})", AgentMessageSeverity.Verbose);
199+
return [];
200+
}
201+
}
202+
203+
/// <summary>
204+
/// Internal for testing.
205+
/// </summary>
206+
internal static List<Assembly> TopologicalSort(Assembly[] assemblies)
207+
{
208+
var sortedAssemblies = new List<Assembly>(assemblies.Length);
209+
210+
var visited = new HashSet<string>(StringComparer.Ordinal);
211+
212+
foreach (var assembly in assemblies)
213+
{
214+
Visit(assemblies, assembly, sortedAssemblies, visited);
215+
}
216+
217+
static void Visit(Assembly[] assemblies, Assembly assembly, List<Assembly> sortedAssemblies, HashSet<string> visited)
218+
{
219+
var assemblyIdentifier = assembly.GetName().Name!;
220+
if (!visited.Add(assemblyIdentifier))
221+
{
222+
return;
223+
}
224+
225+
foreach (var dependencyName in assembly.GetReferencedAssemblies())
226+
{
227+
var dependency = Array.Find(assemblies, a => a.GetName().Name == dependencyName.Name);
228+
if (dependency is not null)
229+
{
230+
Visit(assemblies, dependency, sortedAssemblies, visited);
231+
}
232+
}
233+
234+
sortedAssemblies.Add(assembly);
235+
}
236+
237+
return sortedAssemblies;
238+
}
239+
}

src/BuiltInTools/DotNetDeltaApplier/StartupHook.cs

Lines changed: 23 additions & 48 deletions
Original file line numberDiff line numberDiff line change
@@ -8,12 +8,9 @@
88

99
internal sealed class StartupHook
1010
{
11-
private static readonly bool s_logDeltaClientMessages = Environment.GetEnvironmentVariable(EnvironmentVariables.Names.HotReloadDeltaClientLogMessages) == "1";
11+
private static readonly bool s_logToStandardOutput = Environment.GetEnvironmentVariable(EnvironmentVariables.Names.HotReloadDeltaClientLogMessages) == "1";
1212
private static readonly string s_namedPipeName = Environment.GetEnvironmentVariable(EnvironmentVariables.Names.DotnetWatchHotReloadNamedPipeName);
1313
private static readonly string s_targetProcessPath = Environment.GetEnvironmentVariable(EnvironmentVariables.Names.DotnetWatchHotReloadTargetProcessPath);
14-
#if DEBUG
15-
private static readonly string s_logFile = Path.Combine(Path.GetTempPath(), $"HotReload_{s_namedPipeName}.log");
16-
#endif
1714

1815
/// <summary>
1916
/// Invoked by the runtime when the containing assembly is listed in DOTNET_STARTUP_HOOKS.
@@ -36,22 +33,37 @@ public static void Initialize()
3633

3734
Log($"Loaded into process: {processPath}");
3835

39-
#if DEBUG
40-
Log($"Log path: {s_logFile}");
41-
#endif
4236
ClearHotReloadEnvironmentVariables();
4337

44-
Task.Run(async () =>
38+
_ = Task.Run(async () =>
4539
{
46-
using var hotReloadAgent = new HotReloadAgent(Log);
40+
Log($"Connecting to hot-reload server");
41+
42+
const int TimeOutMS = 5000;
43+
44+
using var pipeClient = new NamedPipeClientStream(".", s_namedPipeName, PipeDirection.InOut, PipeOptions.CurrentUserOnly | PipeOptions.Asynchronous);
4745
try
4846
{
49-
await ReceiveDeltas(hotReloadAgent);
47+
await pipeClient.ConnectAsync(TimeOutMS);
48+
Log("Connected.");
49+
}
50+
catch (TimeoutException)
51+
{
52+
Log($"Failed to connect in {TimeOutMS}ms.");
53+
return;
54+
}
55+
56+
using var agent = new HotReloadAgent(pipeClient, Log);
57+
try
58+
{
59+
await agent.ReceiveDeltasAsync();
5060
}
5161
catch (Exception ex)
5262
{
5363
Log(ex.Message);
5464
}
65+
66+
Log("Stopped received delta updates. Server is no longer connected.");
5567
});
5668
}
5769

@@ -81,50 +93,13 @@ internal static string RemoveCurrentAssembly(string environment)
8193
return string.Join(Path.PathSeparator, updatedValues);
8294
}
8395

84-
public static async Task ReceiveDeltas(HotReloadAgent hotReloadAgent)
85-
{
86-
Log($"Connecting to hot-reload server");
87-
88-
const int TimeOutMS = 5000;
89-
90-
using var pipeClient = new NamedPipeClientStream(".", s_namedPipeName, PipeDirection.InOut, PipeOptions.CurrentUserOnly | PipeOptions.Asynchronous);
91-
try
92-
{
93-
await pipeClient.ConnectAsync(TimeOutMS);
94-
Log("Connected.");
95-
}
96-
catch (TimeoutException)
97-
{
98-
Log($"Failed to connect in {TimeOutMS}ms.");
99-
return;
100-
}
101-
102-
var initPayload = new ClientInitializationPayload(hotReloadAgent.Capabilities);
103-
Log("Writing capabilities: " + initPayload.Capabilities);
104-
initPayload.Write(pipeClient);
105-
106-
while (pipeClient.IsConnected)
107-
{
108-
var update = await UpdatePayload.ReadAsync(pipeClient, default);
109-
Log("Attempting to apply deltas.");
110-
111-
hotReloadAgent.ApplyDeltas(update.Deltas);
112-
pipeClient.WriteByte(UpdatePayload.ApplySuccessValue);
113-
}
114-
115-
Log("Stopped received delta updates. Server is no longer connected.");
116-
}
117-
11896
private static void Log(string message)
11997
{
120-
if (s_logDeltaClientMessages)
98+
if (s_logToStandardOutput)
12199
{
122100
Console.ForegroundColor = ConsoleColor.DarkGray;
123101
Console.WriteLine($"dotnet watch 🕵️ [{s_namedPipeName}] {message}");
124102
Console.ResetColor();
125-
#if DEBUG
126-
File.AppendAllText(s_logFile, message + Environment.NewLine);
127-
#endif
128103
}
129104
}
130105
}

src/BuiltInTools/dotnet-watch/EnvironmentOptions.cs

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@
22
// The .NET Foundation licenses this file to you under the MIT license.
33

44
using System.Diagnostics;
5+
using Microsoft.Extensions.Tools.Internal;
56

67
namespace Microsoft.DotNet.Watcher
78
{
@@ -11,6 +12,11 @@ internal enum TestFlags
1112
None = 0,
1213
RunningAsTest = 1 << 0,
1314
MockBrowser = 1 << 1,
15+
16+
/// <summary>
17+
/// Elevates the severity of <see cref="MessageDescriptor.WaitingForChanges"/> from <see cref="MessageSeverity.Output"/>.
18+
/// </summary>
19+
ElevateWaitingForChangesMessageSeverity = 1 << 2,
1420
}
1521

1622
internal sealed record EnvironmentOptions(

0 commit comments

Comments
 (0)