added trace messages in RegistryWatcher and in UI for agent config

This commit is contained in:
Oliver Kieselbach
2026-03-10 16:15:30 +01:00
parent ec7d76db75
commit 8ef67f2cb8
7 changed files with 80 additions and 8 deletions
@@ -99,6 +99,7 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
}
// Capture initial state before watcher starts
_logger.Trace("ProvisioningWatcher: capturing initial state before watcher starts");
CheckProvisioningStatus();
// Create and start watcher
@@ -106,9 +107,14 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
RegistryHive.LocalMachine,
ProvisioningStatusRegistryPath,
watchSubtree: true,
filter: RegistryNativeMethods.RegChangeNotifyFilter.LastSet);
filter: RegistryNativeMethods.RegChangeNotifyFilter.LastSet,
trace: msg => _logger.Trace($"RegistryWatcher: {msg}"));
_provisioningWatcher.Changed += (s, e) => CheckProvisioningStatus();
_provisioningWatcher.Changed += (s, e) =>
{
_logger.Trace("ProvisioningWatcher: Changed event fired — calling CheckProvisioningStatus");
CheckProvisioningStatus();
};
_provisioningWatcher.Error += (s, ex) => _logger.Warning($"Provisioning watcher handler error: {ex.Message}");
_provisioningWatcher.Start();
@@ -151,20 +157,38 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
using (var key = Registry.LocalMachine.OpenSubKey(ProvisioningStatusRegistryPath, writable: false))
{
if (key == null)
{
_logger.Trace("CheckProvisioningStatus: registry key not found");
return;
}
bool failureDetected = false;
string failureType = null;
int changedCount = 0;
int unchangedCount = 0;
int missingCount = 0;
foreach (var categoryName in ProvisioningCategoryNames)
{
var jsonValue = key.GetValue(categoryName)?.ToString();
if (string.IsNullOrEmpty(jsonValue))
{
missingCount++;
_logger.Trace($"CheckProvisioningStatus: {categoryName} — not present in registry");
continue;
}
// Skip if JSON is identical to last check (no change at all)
if (_lastProvisioningJson.TryGetValue(categoryName, out var lastJson) && lastJson == jsonValue)
{
unchangedCount++;
continue;
}
changedCount++;
bool isNew = !_lastProvisioningJson.ContainsKey(categoryName);
_logger.Trace($"CheckProvisioningStatus: {categoryName} — {(isNew ? "NEW" : "CHANGED")} (json length={jsonValue.Length})");
_logger.Trace($"CheckProvisioningStatus: {categoryName} — raw JSON: {jsonValue}");
_lastProvisioningJson[categoryName] = jsonValue;
var result = ProcessCategoryStatus(categoryName, jsonValue);
@@ -176,6 +200,10 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
}
}
_logger.Trace($"CheckProvisioningStatus: summary — changed={changedCount}, unchanged={unchangedCount}, missing={missingCount}, " +
$"seen={_provisioningCategorySeen.Count}, resolved={_provisioningCategoriesResolved.Count}/{_lastProvisioningJson.Count}, " +
$"failuresFired={_provisioningFailureFired.Count}");
// Self-termination: only auto-stop when all categories resolved with success (no failures).
// Uses RequestStop() which is safe to call from within the Changed handler (non-blocking).
if (_provisioningCategoriesResolved.Count > 0
@@ -245,8 +273,13 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
bool isFirstSeen = !_provisioningCategorySeen.Contains(categoryName);
bool categorySucceededChanged = HasCategorySucceededChanged(categoryName, categorySucceeded);
_logger.Trace($"ProcessCategory: {categoryLabel} — succeeded={categorySucceeded?.ToString() ?? "null"}, " +
$"isFirstSeen={isFirstSeen}, succeededChanged={categorySucceededChanged}, " +
$"subcategories={subcategories.Count} [{string.Join(", ", subcategories.Select(s => $"{s.Name}={s.State}"))}]");
if (isFirstSeen)
{
_logger.Trace($"ProcessCategory: {categoryLabel} — EMITTING first-seen event");
_provisioningCategorySeen.Add(categoryName);
_lastCategorySucceeded[categoryName] = categorySucceeded;
StoreSubcategoryStates(categoryName, subcategories);
@@ -254,6 +287,7 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
}
else if (categorySucceededChanged)
{
_logger.Trace($"ProcessCategory: {categoryLabel} — EMITTING categorySucceeded change ({_lastCategorySucceeded[categoryName]?.ToString() ?? "null"} → {categorySucceeded?.ToString() ?? "null"})");
_lastCategorySucceeded[categoryName] = categorySucceeded;
StoreSubcategoryStates(categoryName, subcategories);
var severity = categorySucceeded == false ? EventSeverity.Warning : EventSeverity.Info;
@@ -266,10 +300,21 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
StoreSubcategoryStates(categoryName, subcategories);
var failureTransitions = transitions.Where(t => t.IsFailure).ToList();
if (transitions.Count > 0)
{
_logger.Trace($"ProcessCategory: {categoryLabel} — subcategory transitions: " +
string.Join(", ", transitions.Select(t => $"{t.SubcategoryName}: {t.OldState}→{t.NewState} (failure={t.IsFailure})")));
}
if (failureTransitions.Count > 0)
{
_logger.Trace($"ProcessCategory: {categoryLabel} — EMITTING failure transition event");
EmitProvisioningEvent(categoryLabel, categorySucceeded, statusText, subcategories, EventSeverity.Warning, failureTransitions);
}
else
{
_logger.Trace($"ProcessCategory: {categoryLabel} — NO event emitted (no first-seen, no succeeded change, no failure transitions)");
}
}
// 5. Track resolved categories (both success and failure are final)
@@ -23,6 +23,7 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
private readonly bool _watchSubtree;
private readonly RegistryView _view;
private readonly RegistryNativeMethods.RegChangeNotifyFilter _filter;
private readonly Action<string> _trace;
private readonly object _sync = new object();
@@ -34,6 +35,7 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
public event EventHandler Changed;
public event EventHandler<Exception> Error;
/// <param name="trace">Optional trace callback for diagnostic logging (called on every loop iteration).</param>
public RegistryWatcher(
RegistryHive hive,
string subKey,
@@ -41,13 +43,15 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
RegistryView view = RegistryView.Default,
RegistryNativeMethods.RegChangeNotifyFilter filter =
RegistryNativeMethods.RegChangeNotifyFilter.LastSet |
RegistryNativeMethods.RegChangeNotifyFilter.ThreadAgnostic)
RegistryNativeMethods.RegChangeNotifyFilter.ThreadAgnostic,
Action<string> trace = null)
{
_hive = HiveToPointer(hive);
_subKey = subKey ?? throw new ArgumentNullException(nameof(subKey));
_watchSubtree = watchSubtree;
_view = view;
_filter = filter;
_trace = trace;
}
public bool IsRunning
@@ -174,6 +178,8 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
{
int samDesired = RegistryNativeMethods.GetSamDesired(_view);
_trace?.Invoke($"RegOpenKeyEx '{_subKey}' (view: {_view}, sam: 0x{samDesired:X})");
int openResult = RegistryNativeMethods.RegOpenKeyEx(
_hive,
_subKey,
@@ -188,15 +194,22 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
$"RegOpenKeyEx failed for '{_subKey}' (view: {_view}).");
}
_trace?.Invoke($"RegOpenKeyEx succeeded — handle valid: {!keyHandle.IsInvalid}");
using (keyHandle)
using (var changedEvent = new AutoResetEvent(false))
using (var cancelEvent = new ManualResetEvent(false))
using (cancellationToken.Register(() => cancelEvent.Set()))
{
WaitHandle[] waitHandles = { changedEvent, cancelEvent };
int iteration = 0;
while (!cancellationToken.IsCancellationRequested)
{
iteration++;
_trace?.Invoke($"Iteration {iteration}: calling RegNotifyChangeKeyValue (subtree={_watchSubtree}, filter=0x{(uint)_filter:X})");
int notifyResult = RegistryNativeMethods.RegNotifyChangeKeyValue(
keyHandle,
_watchSubtree,
@@ -211,13 +224,23 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
$"RegNotifyChangeKeyValue failed for '{_subKey}'.");
}
_trace?.Invoke($"Iteration {iteration}: waiting for change notification...");
int signaled = WaitHandle.WaitAny(waitHandles);
if (signaled == WaitHandle.WaitTimeout)
{
_trace?.Invoke($"Iteration {iteration}: WaitAny returned WaitTimeout — continuing");
continue;
}
if (signaled == 1)
{
_trace?.Invoke($"Iteration {iteration}: cancel event signaled — exiting loop");
break;
}
_trace?.Invoke($"Iteration {iteration}: change notification received — invoking Changed handler");
try
{
@@ -234,8 +257,11 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
// Ignore secondary error-handler failures.
}
}
_trace?.Invoke($"Iteration {iteration}: Changed handler completed");
}
_trace?.Invoke("WatchLoop exiting (cancellation requested)");
cancellationToken.ThrowIfCancellationRequested();
}
}
@@ -1 +1 @@
426
428
@@ -68,7 +68,7 @@ namespace AutopilotMonitor.Shared.Models
/// <summary>
/// Log verbosity level for the agent.
/// "Info" = normal messages, "Debug" = component state/decisions, "Verbose" = per-event tracing.
/// "Info" = normal messages, "Debug" = component state/decisions, "Verbose" = per-event tracing, "Trace" = full diagnostic output.
/// Default: "Info"
/// </summary>
public string LogLevel { get; set; } = "Info";
@@ -213,7 +213,7 @@ namespace AutopilotMonitor.Shared.Models
/// <summary>
/// Log verbosity level override for this tenant's agents.
/// null = use agent default ("Info"). Values: "Info", "Debug", "Verbose".
/// null = use agent default ("Info"). Values: "Info", "Debug", "Verbose", "Trace".
/// </summary>
public string LogLevel { get; set; }
@@ -260,7 +260,7 @@ export default function AgentSettingsSection({
<div className="flex items-center justify-between p-4 rounded-lg border border-gray-200 hover:border-violet-200 transition-colors">
<div>
<p className="font-medium text-gray-900">Log Level</p>
<p className="text-sm text-gray-500">Agent log verbosity — Info for normal operation, Debug for troubleshooting, Verbose for full tracing</p>
<p className="text-sm text-gray-500">Agent log verbosity — Info for normal operation, Debug for troubleshooting, Verbose for detailed tracing, Trace for full diagnostic output</p>
</div>
<select
value={logLevel}
@@ -270,6 +270,7 @@ export default function AgentSettingsSection({
<option value="Info">Info</option>
<option value="Debug">Debug</option>
<option value="Verbose">Verbose</option>
<option value="Trace">Trace</option>
</select>
</div>
File diff suppressed because one or more lines are too long