mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-11-03 09:03:29 +00:00
Compare commits
21 Commits
| Author | SHA1 | Date | |
|---|---|---|---|
| 43b3008266 | |||
| 2304436b8c | |||
| ad875d4021 | |||
| fd6b68231e | |||
| 88494a312f | |||
| 6901f6f682 | |||
| 82c0b20be1 | |||
| 4fa439cc3c | |||
| b631c63c53 | |||
| e9aaf3db53 | |||
| a37930e87a | |||
| 6bc5d47afe | |||
| 0ebbf87e5b | |||
| fec4bcc6c5 | |||
| 6ce2176aa0 | |||
| 1fe4e6711e | |||
| 61947c416c | |||
| 25c65f1837 | |||
| eb287248c6 | |||
| 738a349710 | |||
| 73525f1d34 |
+1
-1
Submodule .claude/commands updated: 0efa7c79ca...d937abd228
+1
-1
Submodule internal updated: f7d94b395a...af17a42883
@@ -125,5 +125,74 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Logging
|
||||
// No assertion needed beyond "did not throw"; the regression we guard against is
|
||||
// the original swallow-all behaviour, which the rotation refactor must preserve.
|
||||
}
|
||||
|
||||
[Theory]
|
||||
[InlineData(AgentLogLevel.Info, "INFO")]
|
||||
[InlineData(AgentLogLevel.Debug, "INFO,DEBUG")]
|
||||
[InlineData(AgentLogLevel.Verbose, "INFO,DEBUG,VERBOSE")]
|
||||
[InlineData(AgentLogLevel.Trace, "INFO,DEBUG,VERBOSE,TRACE")]
|
||||
public void Each_level_adds_to_the_one_before_it(AgentLogLevel level, string expectedTags)
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = new AgentLogger(tmp.Path, level);
|
||||
|
||||
logger.Info("line");
|
||||
logger.Debug("line");
|
||||
logger.Verbose("line");
|
||||
logger.Trace("line");
|
||||
|
||||
var tags = ReadLines(tmp.Path).Select(Tag);
|
||||
Assert.Equal(expectedTags, string.Join(",", tags));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void RepeatKey_sends_an_identical_repeat_to_trace_and_a_change_back_to_its_level()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Trace);
|
||||
|
||||
logger.Info("rule A ran", repeatKey: "rule:A");
|
||||
logger.Info("rule A ran", repeatKey: "rule:A");
|
||||
logger.Info("rule A ran again with new data", repeatKey: "rule:A");
|
||||
logger.Info("rule A ran", repeatKey: "rule:A");
|
||||
|
||||
Assert.Equal(new[] { "INFO", "TRACE", "INFO", "INFO" }, ReadLines(tmp.Path).Select(Tag).ToArray());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void RepeatKey_keeps_subjects_apart()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Trace);
|
||||
|
||||
logger.Debug("scan failed: access denied", repeatKey: "scan:System");
|
||||
logger.Debug("scan failed: access denied", repeatKey: "scan:Application");
|
||||
logger.Debug("scan failed: access denied", repeatKey: "scan:System");
|
||||
|
||||
Assert.Equal(new[] { "DEBUG", "DEBUG", "TRACE" }, ReadLines(tmp.Path).Select(Tag).ToArray());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void RepeatKey_does_not_remember_a_line_its_level_did_not_write()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Info);
|
||||
|
||||
logger.Debug("waiting for the policy", repeatKey: "hello.poll");
|
||||
logger.SetLogLevel(AgentLogLevel.Debug);
|
||||
logger.Debug("waiting for the policy", repeatKey: "hello.poll");
|
||||
|
||||
Assert.Equal(new[] { "DEBUG" }, ReadLines(tmp.Path).Select(Tag).ToArray());
|
||||
}
|
||||
|
||||
private static string[] ReadLines(string dir) =>
|
||||
File.ReadAllLines(Path.Combine(dir, BaseName + ".log"));
|
||||
|
||||
// "[2026-10-30 12:00:00.000] [INFO] message" -> "INFO"
|
||||
private static string Tag(string line)
|
||||
{
|
||||
var open = line.IndexOf("] [", StringComparison.Ordinal) + 3;
|
||||
return line.Substring(open, line.IndexOf(']', open) - open);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+31
@@ -164,5 +164,36 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring
|
||||
var info = f.InfoEvent("hello_pin_status");
|
||||
Assert.Equal("false", info.Payload![SignalPayloadKeys.ImmediateUpload]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void A_throwing_HelloCompleted_handler_is_logged_and_the_completion_stands()
|
||||
{
|
||||
// The handler carries the Hello resolution to the decision engine; a fault there used
|
||||
// to vanish without a trace.
|
||||
using var f = new Fixture();
|
||||
f.Tracker.HelloCompleted += (_, _) => throw new InvalidOperationException("handler bug");
|
||||
|
||||
f.Tracker.ProcessHelloEvent(300, Fixed, "Microsoft-Windows-User Device Registration", isBackfill: false);
|
||||
|
||||
Assert.True(f.Tracker.IsHelloCompleted);
|
||||
f.InfoEvent("hello_provisioning_completed");
|
||||
Assert.Contains("[WARN] HelloTracker: HelloCompleted handler threw: handler bug", ReadLog(f));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void A_repeated_terminal_event_logs_COMPLETED_once()
|
||||
{
|
||||
// Live plus backfill deliver event 300 twice; only the first one completes Hello.
|
||||
using var f = new Fixture();
|
||||
|
||||
f.Tracker.ProcessHelloEvent(300, Fixed, "Microsoft-Windows-User Device Registration", isBackfill: false);
|
||||
f.Tracker.ProcessHelloEvent(300, Fixed, "Microsoft-Windows-User Device Registration", isBackfill: true);
|
||||
|
||||
var log = ReadLog(f);
|
||||
Assert.Single(log.Split('\n'), l => l.Contains("Windows Hello provisioning COMPLETED successfully"));
|
||||
}
|
||||
|
||||
private static string ReadLog(Fixture f) =>
|
||||
System.IO.File.ReadAllText(System.IO.Path.Combine(f.Tmp.Path, "agent.log"));
|
||||
}
|
||||
}
|
||||
|
||||
+277
@@ -0,0 +1,277 @@
|
||||
using System.Collections.Generic;
|
||||
using System.IO;
|
||||
using System.Linq;
|
||||
using System.Threading.Tasks;
|
||||
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
{
|
||||
/// <summary>
|
||||
/// IME rolls a log with File.Move at 3 MB. The tracker used to take the archive for a new file and
|
||||
/// read it from 0: every app line played again, finished apps fell back to Installing and the
|
||||
/// subgraph line of an older app marked the running app as skipped (session 190fed00).
|
||||
/// </summary>
|
||||
public sealed partial class ImeLogTrackerOverwriteRewindTests
|
||||
{
|
||||
private const string FirstStamp = "20260910-193000";
|
||||
private const string SecondStamp = "20260910-193500";
|
||||
|
||||
private static string Folder(Harness h) => Path.GetDirectoryName(h.LogPath)!;
|
||||
|
||||
private static string ArchivePath(Harness h, string stamp = FirstStamp)
|
||||
=> Path.Combine(Folder(h), $"{Path.GetFileNameWithoutExtension(h.LogName)}-{stamp}.log");
|
||||
|
||||
private static string Roll(Harness h, string stamp = FirstStamp)
|
||||
{
|
||||
var archive = ArchivePath(h, stamp);
|
||||
File.Move(h.LogPath, archive);
|
||||
return archive;
|
||||
}
|
||||
|
||||
private static List<ImeLogPattern> AppPatterns() => new List<ImeLogPattern>
|
||||
{
|
||||
new ImeLogPattern
|
||||
{
|
||||
PatternId = "T-POLICIES", Category = "always", Enabled = true,
|
||||
Pattern = @"^policies discovered = (?<policies>\[.*\])", Action = "policiesDiscovered",
|
||||
Parameters = new Dictionary<string, string>(),
|
||||
},
|
||||
new ImeLogPattern
|
||||
{
|
||||
PatternId = "T-SUBGRAPH", Category = "always", Enabled = true,
|
||||
Pattern = @"^subgraph (?<id>[\w-]+)", Action = "cancelStuckAndSetCurrent",
|
||||
Parameters = new Dictionary<string, string>(),
|
||||
},
|
||||
new ImeLogPattern
|
||||
{
|
||||
PatternId = "T-INSTALLING", Category = "always", Enabled = true,
|
||||
Pattern = @"^installing (?<id>[\w-]+)", Action = "updateStateInstalling",
|
||||
Parameters = new Dictionary<string, string>(),
|
||||
},
|
||||
new ImeLogPattern
|
||||
{
|
||||
PatternId = "T-INSTALLED", Category = "always", Enabled = true,
|
||||
Pattern = @"^installed (?<id>[\w-]+)", Action = "updateStateInstalled",
|
||||
Parameters = new Dictionary<string, string>(),
|
||||
},
|
||||
};
|
||||
|
||||
private const string AppPoliciesLine = @"policies discovered = [{""Id"":""app-1"",""Name"":""App One""},{""Id"":""app-2"",""Name"":""App Two""}]";
|
||||
|
||||
private static string OneFinishedOneRunning() =>
|
||||
Entry(AppPoliciesLine) + Entry("subgraph app-1") + Entry("installing app-1") + Entry("installed app-1")
|
||||
+ Entry("subgraph app-2") + Entry("installing app-2");
|
||||
|
||||
[Theory]
|
||||
[InlineData("AppWorkload.log")]
|
||||
[InlineData("AppActionProcessor.log")]
|
||||
[InlineData("HealthScripts.log")]
|
||||
[InlineData("AgentExecutor.log")]
|
||||
[InlineData("IntuneManagementExtension.log")]
|
||||
public async Task Rolled_over_log_is_not_read_again(string logName)
|
||||
{
|
||||
using var h = new Harness(logName, MarkerPatterns());
|
||||
h.Append(Entry("marker 1") + Entry("marker 2") + Entry("marker 3"));
|
||||
await h.Pass();
|
||||
|
||||
Roll(h);
|
||||
h.Append(Entry("marker 4"));
|
||||
h.Now = h.Now.AddMilliseconds(100);
|
||||
await h.Pass();
|
||||
Assert.Equal(new[] { 1, 2, 3, 4 }, h.Matched());
|
||||
|
||||
h.Tracker.RequestOverwriteCheckForTest();
|
||||
h.Now = h.Now.AddSeconds(2);
|
||||
await h.Pass();
|
||||
Assert.Equal(new[] { 1, 2, 3, 4 }, h.Matched());
|
||||
Assert.Equal(0, h.Health.OverwriteRewinds);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Bytes_written_after_the_last_read_come_from_the_archive_once_and_first()
|
||||
{
|
||||
using var h = new Harness("AppWorkload.log", MarkerPatterns());
|
||||
h.Append(Entry("marker 1") + Entry("marker 2"));
|
||||
await h.Pass();
|
||||
|
||||
h.Append(Entry("marker 3"));
|
||||
Roll(h);
|
||||
h.Append(Entry("marker 4"));
|
||||
h.Now = h.Now.AddMilliseconds(100);
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(new[] { 1, 2, 3, 4 }, h.Matched());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Line_held_back_at_the_end_of_the_file_is_finished_from_the_archive()
|
||||
{
|
||||
using var h = new Harness("AppWorkload.log", MarkerPatterns());
|
||||
var second = Entry("marker 2");
|
||||
h.Append(Entry("marker 1") + second.Substring(0, 10));
|
||||
await h.Pass();
|
||||
Assert.Equal(new[] { 1 }, h.Matched());
|
||||
|
||||
h.Append(second.Substring(10));
|
||||
Roll(h);
|
||||
h.Append(Entry("marker 3"));
|
||||
h.Now = h.Now.AddMilliseconds(100);
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(new[] { 1, 2, 3 }, h.Matched());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Rollover_leaves_finished_and_running_apps_alone()
|
||||
{
|
||||
using var h = new Harness("AppWorkload.log", AppPatterns());
|
||||
var transitions = new List<string>();
|
||||
h.Tracker.OnAppStateChanged = (pkg, from, to) => transitions.Add($"{pkg.Id}:{from}->{to}");
|
||||
h.Append(OneFinishedOneRunning());
|
||||
await h.Pass();
|
||||
var before = transitions.ToList();
|
||||
|
||||
Roll(h);
|
||||
h.Append(Entry("marker unrelated"));
|
||||
h.Now = h.Now.AddMilliseconds(100);
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(before, transitions);
|
||||
var states = h.Tracker.GetAllKnownPackageStates().ToDictionary(p => p.Id, p => p.InstallationState);
|
||||
Assert.Equal(AppInstallationState.Installed, states["app-1"]);
|
||||
Assert.Equal(AppInstallationState.Installing, states["app-2"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Without_a_readable_identity_the_archive_is_read_again_as_before()
|
||||
{
|
||||
// The fallback, and the proof that the tests above catch the replay: this is what they saw before the fix.
|
||||
using var h = new Harness("AppWorkload.log", AppPatterns());
|
||||
h.Tracker.FileIdentityProvider = _ => null!;
|
||||
var transitions = new List<string>();
|
||||
h.Tracker.OnAppStateChanged = (pkg, from, to) => transitions.Add($"{pkg.Id}:{from}->{to}");
|
||||
h.Append(OneFinishedOneRunning());
|
||||
await h.Pass();
|
||||
|
||||
Roll(h);
|
||||
h.Append(Entry("marker unrelated"));
|
||||
h.Now = h.Now.AddMilliseconds(100);
|
||||
await h.Pass();
|
||||
|
||||
Assert.Contains("app-2:Installing->Skipped", transitions);
|
||||
Assert.Contains("app-1:Installed->Installing", transitions);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Live_file_that_sorts_before_its_archive_hands_over_its_bookmark()
|
||||
{
|
||||
// LogMaxHistory <= 1: the archive is _X.log, which sorts behind X.log. The pass reaches the
|
||||
// shrunken live file first, and the next rollover replaces the archive under the same name.
|
||||
using var h = new Harness("IntuneManagementExtension.log", MarkerPatterns());
|
||||
var archive = Path.Combine(Folder(h), "_IntuneManagementExtension.log");
|
||||
h.Append(Entry("marker 1") + Entry("marker 2") + Entry("marker 3") + Entry("marker 4"));
|
||||
await h.Pass();
|
||||
|
||||
File.Move(h.LogPath, archive);
|
||||
h.Append(Entry("marker 5"));
|
||||
h.Now = h.Now.AddMilliseconds(100);
|
||||
await h.Pass();
|
||||
Assert.Equal(new[] { 1, 2, 3, 4, 5 }, h.Matched());
|
||||
|
||||
h.Append(Entry("marker 6"));
|
||||
File.Delete(archive);
|
||||
File.Move(h.LogPath, archive);
|
||||
h.Append(Entry("marker 8"));
|
||||
h.Now = h.Now.AddMilliseconds(100);
|
||||
await h.Pass();
|
||||
h.Now = h.Now.AddMilliseconds(100);
|
||||
await h.Pass();
|
||||
Assert.Equal(new[] { 1, 2, 3, 4, 5, 6, 8 }, h.Matched());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Rollover_during_a_restart_with_a_longer_new_file_loses_and_repeats_nothing()
|
||||
{
|
||||
using var h = new Harness("AppWorkload.log", MarkerPatterns());
|
||||
h.Append(Entry("marker 1") + Entry("marker 2"));
|
||||
await h.Pass();
|
||||
|
||||
h.Restart();
|
||||
h.Append(Entry("marker 3"));
|
||||
Roll(h);
|
||||
h.Append(Entry("marker 4") + Entry("marker 5") + Entry("marker 6") + Entry("marker 7"));
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(new[] { 1, 2, 3, 4, 5, 6, 7 }, h.Matched());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Two_rollovers_during_a_restart_with_the_bookmarked_file_deleted_lose_nothing()
|
||||
{
|
||||
using var h = new Harness("AppWorkload.log", MarkerPatterns());
|
||||
h.Append(Entry("marker 1") + Entry("marker 2"));
|
||||
await h.Pass();
|
||||
|
||||
h.Restart();
|
||||
var first = Roll(h, FirstStamp);
|
||||
h.Append(Entry("marker 3"));
|
||||
Roll(h, SecondStamp);
|
||||
h.Append(Entry("marker 4") + Entry("marker 5") + Entry("marker 6"));
|
||||
File.Delete(first);
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(new[] { 1, 2, 3, 4, 5, 6 }, h.Matched());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Archives_found_at_the_first_start_are_read_from_the_beginning_in_order()
|
||||
{
|
||||
using var h = new Harness("AppWorkload.log", MarkerPatterns());
|
||||
File.WriteAllText(ArchivePath(h, FirstStamp), Entry("marker 1") + Entry("marker 2"));
|
||||
File.WriteAllText(ArchivePath(h, SecondStamp), Entry("marker 3"));
|
||||
h.Append(Entry("marker 4"));
|
||||
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(new[] { 1, 2, 3, 4 }, h.Matched());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Platform_script_in_flight_keeps_its_end_block_across_a_rollover()
|
||||
{
|
||||
// Reading the archive again used to restore the marker of the run in flight by accident.
|
||||
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
|
||||
h.Append(Entry("ExecutorLog AgentExecutor gets invoked") + Entry(PlatformStartLine) + Entry("[Executor] created powershell with process id 12708"));
|
||||
await h.Pass();
|
||||
|
||||
Roll(h);
|
||||
h.Append(Entry("Powershell exit code is 0") + Entry("write output done. output = Hello from E, error = ") + Entry("Agent executor completed."));
|
||||
h.Now = h.Now.AddMilliseconds(100);
|
||||
await h.Pass();
|
||||
|
||||
h.Tracker.ProcessLogMessageForTest(ResultLine);
|
||||
var script = Assert.Single(h.Completed);
|
||||
Assert.Equal(PlatformId, script.PolicyId);
|
||||
Assert.Equal(0, script.ExitCode);
|
||||
Assert.Equal("Hello from E", script.Stdout);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Identity_of_a_real_file_survives_a_rename_and_differs_from_the_next_file()
|
||||
{
|
||||
using var h = new Harness("AppWorkload.log", MarkerPatterns());
|
||||
h.Append(Entry("marker 1"));
|
||||
var before = ImeLogFileIdentity.TryRead(h.LogPath);
|
||||
Assert.NotNull(before);
|
||||
|
||||
var archive = Roll(h);
|
||||
h.Append(Entry("marker 2"));
|
||||
|
||||
Assert.Equal(before, ImeLogFileIdentity.TryRead(archive));
|
||||
Assert.NotEqual(before, ImeLogFileIdentity.TryRead(h.LogPath));
|
||||
Assert.Null(ImeLogFileIdentity.TryRead(archive + ".missing"));
|
||||
}
|
||||
}
|
||||
}
|
||||
+187
@@ -0,0 +1,187 @@
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
{
|
||||
/// <summary>
|
||||
/// A bookmark belongs to a file, not to a name: IME rolls a log by renaming it, so the identity
|
||||
/// (volume plus file index) tells what happened to the bytes behind the bookmark.
|
||||
/// </summary>
|
||||
public sealed class LogFilePositionTrackerTests
|
||||
{
|
||||
private const string Live = @"C:\Logs\AppWorkload.log";
|
||||
private const string Archive = @"C:\Logs\AppWorkload-20260910-193000.log";
|
||||
private const string Underscore = @"C:\Logs\_AppWorkload.log";
|
||||
|
||||
private static readonly DateTime Checked = new DateTime(2026, 9, 10, 19, 30, 0, DateTimeKind.Utc);
|
||||
|
||||
private static Dictionary<string, string> Ids(params (string Path, string Id)[] entries)
|
||||
{
|
||||
var ids = new Dictionary<string, string>(StringComparer.OrdinalIgnoreCase);
|
||||
foreach (var entry in entries) ids[entry.Path] = entry.Id;
|
||||
return ids;
|
||||
}
|
||||
|
||||
private static LogFilePositionTracker TrackerWithBookmark(string path, string id, long position)
|
||||
{
|
||||
var tracker = new LogFilePositionTracker();
|
||||
tracker.Reconcile(Ids((path, id)));
|
||||
tracker.MarkChecked(path, Checked);
|
||||
tracker.SetPosition(path, position);
|
||||
return tracker;
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Renamed_file_keeps_its_bookmark_and_the_old_path_starts_over()
|
||||
{
|
||||
var tracker = TrackerWithBookmark(Live, "A", 3000);
|
||||
|
||||
var moves = tracker.Reconcile(Ids((Archive, "A"), (Live, "B")));
|
||||
|
||||
var move = Assert.Single(moves);
|
||||
Assert.Equal(Live, move.From);
|
||||
Assert.Equal(Archive, move.To);
|
||||
Assert.Equal(3000, move.Position);
|
||||
Assert.Equal(3000, tracker.GetPosition(Archive));
|
||||
Assert.Equal("A", tracker.GetFileId(Archive));
|
||||
Assert.Equal(0, tracker.GetPosition(Live));
|
||||
Assert.Equal("B", tracker.GetFileId(Live));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Both_paths_keep_the_freshness_reference()
|
||||
{
|
||||
var tracker = TrackerWithBookmark(Live, "A", 3000);
|
||||
|
||||
tracker.Reconcile(Ids((Archive, "A"), (Live, "B")));
|
||||
|
||||
Assert.True(tracker.HasSeen(Archive));
|
||||
Assert.Equal(Checked, tracker.GetLastCheckedUtc(Archive));
|
||||
Assert.True(tracker.HasSeen(Live));
|
||||
Assert.Equal(Checked, tracker.GetLastCheckedUtc(Live));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Renamed_file_whose_old_path_is_not_recreated_yet_keeps_its_bookmark()
|
||||
{
|
||||
var tracker = TrackerWithBookmark(Live, "A", 3000);
|
||||
|
||||
var moves = tracker.Reconcile(Ids((Archive, "A")));
|
||||
|
||||
Assert.Single(moves);
|
||||
Assert.Equal(3000, tracker.GetPosition(Archive));
|
||||
Assert.Equal(0, tracker.GetPosition(Live));
|
||||
Assert.False(tracker.HasIdentity(Live));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Second_name_for_the_same_file_moves_nothing()
|
||||
{
|
||||
var tracker = TrackerWithBookmark(Live, "A", 3000);
|
||||
|
||||
var moves = tracker.Reconcile(Ids((Live, "A"), (Archive, "A")));
|
||||
|
||||
Assert.Empty(moves);
|
||||
Assert.Equal(3000, tracker.GetPosition(Live));
|
||||
Assert.False(tracker.HasSeen(Archive));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Unknown_file_stays_unseen_so_its_first_pass_is_not_taken_for_fresh_lines()
|
||||
{
|
||||
var tracker = TrackerWithBookmark(Live, "A", 3000);
|
||||
|
||||
var moves = tracker.Reconcile(Ids((Live, "A"), (Archive, "X")));
|
||||
|
||||
Assert.Empty(moves);
|
||||
Assert.True(tracker.HasIdentity(Archive));
|
||||
Assert.False(tracker.HasSeen(Archive));
|
||||
Assert.Equal(0, tracker.GetPosition(Archive));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Path_holding_another_file_with_no_one_to_take_over_starts_at_zero()
|
||||
{
|
||||
var tracker = TrackerWithBookmark(Live, "A", 3000);
|
||||
|
||||
var moves = tracker.Reconcile(Ids((Live, "B")));
|
||||
|
||||
Assert.Empty(moves);
|
||||
// GetSafePosition alone would keep 3000 here when the new file is longer: lost lines.
|
||||
Assert.Equal(0, tracker.GetSafePosition(Live, 5000));
|
||||
Assert.Equal("B", tracker.GetFileId(Live));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Unreadable_identity_changes_nothing()
|
||||
{
|
||||
var tracker = TrackerWithBookmark(Live, "A", 3000);
|
||||
|
||||
var moves = tracker.Reconcile(Ids((Live, null!), (Archive, null!)));
|
||||
|
||||
Assert.Empty(moves);
|
||||
Assert.Equal(3000, tracker.GetPosition(Live));
|
||||
Assert.Equal("A", tracker.GetFileId(Live));
|
||||
Assert.True(tracker.HasIdentity(Archive));
|
||||
Assert.Null(tracker.GetFileId(Archive));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Single_slot_archive_is_replaced_by_the_next_rollover()
|
||||
{
|
||||
// LogMaxHistory <= 1: IME deletes _X.log and renames X.log to it.
|
||||
var tracker = TrackerWithBookmark(Underscore, "A", 9000);
|
||||
tracker.Reconcile(Ids((Underscore, "A"), (Live, "B")));
|
||||
tracker.SetPosition(Live, 3000);
|
||||
|
||||
var moves = tracker.Reconcile(Ids((Underscore, "B"), (Live, "C")));
|
||||
|
||||
var move = Assert.Single(moves);
|
||||
Assert.Equal(Live, move.From);
|
||||
Assert.Equal(Underscore, move.To);
|
||||
Assert.Equal(3000, tracker.GetPosition(Underscore));
|
||||
Assert.Equal(0, tracker.GetPosition(Live));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void A_renamed_file_can_leave_the_path_it_moved_into()
|
||||
{
|
||||
var tracker = TrackerWithBookmark(Live, "A", 3000);
|
||||
tracker.Reconcile(Ids((Live, "A"), (Underscore, "B")));
|
||||
tracker.SetPosition(Underscore, 700);
|
||||
|
||||
var moves = tracker.Reconcile(Ids((Underscore, "A"), (Archive, "B"), (Live, "C")));
|
||||
|
||||
Assert.Equal(2, moves.Count);
|
||||
Assert.Equal(3000, tracker.GetPosition(Underscore));
|
||||
Assert.Equal(700, tracker.GetPosition(Archive));
|
||||
Assert.Equal(0, tracker.GetPosition(Live));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Behind_bookmark_only_when_smaller_than_the_position()
|
||||
{
|
||||
var tracker = TrackerWithBookmark(Live, "A", 3000);
|
||||
|
||||
Assert.True(tracker.IsBehindBookmark(Live, 2999));
|
||||
Assert.False(tracker.IsBehindBookmark(Live, 3000));
|
||||
Assert.False(tracker.IsBehindBookmark(Archive, 0));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Restored_identity_is_used_to_find_a_rollover_during_the_downtime()
|
||||
{
|
||||
var tracker = new LogFilePositionTracker();
|
||||
tracker.RestorePosition(Live, 3000, 3000);
|
||||
tracker.RestoreFileId(Live, "A");
|
||||
|
||||
var moves = tracker.Reconcile(Ids((Archive, "A"), (Live, "B")));
|
||||
|
||||
Assert.Single(moves);
|
||||
Assert.Equal(3000, tracker.GetPosition(Archive));
|
||||
Assert.Equal(0, tracker.GetPosition(Live));
|
||||
}
|
||||
}
|
||||
}
|
||||
+59
@@ -1,5 +1,6 @@
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using System.Linq;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Agent.V2.Core.Orchestration;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
|
||||
@@ -304,6 +305,64 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Orchestration
|
||||
Assert.Same(step.NewState, sut.CurrentState);
|
||||
}
|
||||
|
||||
// ========================================================================= Step log levels
|
||||
|
||||
[Fact]
|
||||
public void ApplyStep_logs_a_stage_change_at_info()
|
||||
{
|
||||
using var rig = new Rig();
|
||||
rig.Logger.SetLogLevel(AgentLogLevel.Trace);
|
||||
var sut = rig.Build();
|
||||
var (step, signal) = rig.ReduceAbort(); // SessionStarted -> Failed
|
||||
|
||||
sut.ApplyStep(step, signal);
|
||||
|
||||
Assert.Contains(StepLines(rig), l => l.Contains("[INFO] DecisionStep:") && l.Contains("stage=SessionStarted->Failed"));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void ApplyStep_logs_informational_pass_through_and_no_op_at_trace()
|
||||
{
|
||||
using var rig = new Rig();
|
||||
rig.Logger.SetLogLevel(AgentLogLevel.Trace);
|
||||
var sut = rig.Build();
|
||||
|
||||
var (noOp, noOpSignal) = rig.ReduceSessionStarted(ordinal: 0);
|
||||
sut.ApplyStep(noOp, noOpSignal);
|
||||
var (info, infoSignal) = rig.ReduceInformational(sut, ordinal: 1);
|
||||
sut.ApplyStep(info, infoSignal);
|
||||
|
||||
var lines = StepLines(rig);
|
||||
Assert.Equal(2, lines.Length);
|
||||
Assert.All(lines, l => Assert.Contains("[TRACE] DecisionStep:", l));
|
||||
Assert.Contains("(no-op)", lines[0]);
|
||||
Assert.Contains("kind=InformationalEvent", lines[1]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void ApplyStep_logs_informational_pass_through_with_failed_effect_at_debug()
|
||||
{
|
||||
using var rig = new Rig();
|
||||
rig.Logger.SetLogLevel(AgentLogLevel.Trace);
|
||||
rig.Effects.ScriptResult(new EffectRunResult(
|
||||
sessionMustAbort: false,
|
||||
abortReason: null,
|
||||
failures: new[] { new EffectFailure(DecisionEffectKind.EmitEventTimelineEntry, "emit failed", isTransient: false, exhaustedRetries: true) },
|
||||
classifierInvocations: 0,
|
||||
classifierSkippedByAntiLoop: 0));
|
||||
var sut = rig.Build();
|
||||
var (step, signal) = rig.ReduceInformational(sut, ordinal: 0);
|
||||
|
||||
sut.ApplyStep(step, signal);
|
||||
|
||||
Assert.Contains(StepLines(rig), l => l.Contains("[DEBUG] DecisionStep:") && l.Contains("failures=1"));
|
||||
}
|
||||
|
||||
private static string[] StepLines(Rig rig) =>
|
||||
System.IO.File.ReadAllLines(System.IO.Path.Combine(rig.Tmp.Path, "agent.log"))
|
||||
.Where(l => l.Contains("DecisionStep:"))
|
||||
.ToArray();
|
||||
|
||||
// ========================================================================= Argument validation
|
||||
|
||||
[Fact]
|
||||
|
||||
+45
@@ -0,0 +1,45 @@
|
||||
using System;
|
||||
using System.IO;
|
||||
using System.Linq;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Agent.V2.Core.Orchestration;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Tests.Orchestration
|
||||
{
|
||||
/// <summary>
|
||||
/// <see cref="TimelineEventStream.Publish"/> isolates subscribers: a throwing one must neither
|
||||
/// break the emit path nor starve the subscribers after it, and its fault must reach the log
|
||||
/// (Debug once, an identical repeat on Trace).
|
||||
/// </summary>
|
||||
public sealed class TimelineEventStreamTests
|
||||
{
|
||||
[Fact]
|
||||
public void A_throwing_subscriber_is_logged_and_the_next_one_still_runs()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Trace);
|
||||
var sut = new TimelineEventStream(logger);
|
||||
var delivered = 0;
|
||||
sut.EventEmitted += ThrowingSubscriber;
|
||||
sut.EventEmitted += (_, _, _) => delivered++;
|
||||
|
||||
sut.Publish("app_install_started", EnrollmentPhase.Unknown, "ImeLogTracker");
|
||||
sut.Publish("app_install_completed", EnrollmentPhase.Unknown, "ImeLogTracker");
|
||||
|
||||
Assert.Equal(2, delivered);
|
||||
var lines = File.ReadAllLines(Path.Combine(tmp.Path, "agent.log"))
|
||||
.Where(l => l.Contains("TimelineEventStream: subscriber"))
|
||||
.ToArray();
|
||||
Assert.Equal(2, lines.Length);
|
||||
Assert.Contains("[DEBUG]", lines[0]);
|
||||
Assert.Contains("ThrowingSubscriber threw: subscriber bug", lines[0]);
|
||||
Assert.Contains("[TRACE]", lines[1]);
|
||||
}
|
||||
|
||||
private static void ThrowingSubscriber(string eventType, EnrollmentPhase phase, string source) =>
|
||||
throw new InvalidOperationException("subscriber bug");
|
||||
}
|
||||
}
|
||||
@@ -2,7 +2,9 @@ using System;
|
||||
using System.Diagnostics;
|
||||
using System.Threading;
|
||||
using System.Threading.Tasks;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Agent.V2.Core.Security;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
|
||||
using Xunit;
|
||||
|
||||
// xUnit1031 (no blocking Task.Wait in tests) intentionally suppressed — the API
|
||||
@@ -22,9 +24,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Security
|
||||
/// Drives <see cref="TenantIdAwaiter.WaitForTenantIdCore"/> through every interesting
|
||||
/// path with a fake <see cref="IRegistryChangeSignal"/> + scripted probe so the
|
||||
/// orchestration logic is verified without touching the registry. The public
|
||||
/// <see cref="TenantIdAwaiter.WaitForTenantId"/> wrapper isn't covered here — the
|
||||
/// HKCU integration test in <c>RegistryWatcherIntegrationTests</c> proves the
|
||||
/// CompositeRegistryChangeSignal / RegNotifyChangeKeyValue plumbing separately.
|
||||
/// <c>WaitForTenantId</c> wrapper is covered through its internal overload with a scripted
|
||||
/// resolver (which probes log); the HKCU integration test in
|
||||
/// <c>RegistryWatcherIntegrationTests</c> proves the CompositeRegistryChangeSignal /
|
||||
/// RegNotifyChangeKeyValue plumbing separately.
|
||||
/// <para>
|
||||
/// Single-threaded collection: these tests use <c>Thread.Sleep</c> as a synchronisation
|
||||
/// primitive (waiting for the awaiter to enter its WaitAny loop before triggering the
|
||||
@@ -258,5 +261,44 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Security
|
||||
logger: null!,
|
||||
ct: CancellationToken.None));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Initial_miss_never_probes_with_the_logger()
|
||||
{
|
||||
// AgentBootstrap probes with its logger before it calls the awaiter; the resolver's
|
||||
// miss block must not land a second time from the awaiter's own first check.
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Info);
|
||||
int loggedProbes = 0, silentProbes = 0;
|
||||
|
||||
var result = TenantIdAwaiter.WaitForTenantId(
|
||||
timeoutSeconds: 1,
|
||||
logger: logger,
|
||||
ct: CancellationToken.None,
|
||||
resolve: l => { if (l != null) loggedProbes++; else silentProbes++; return null!; },
|
||||
signalFactory: () => new FakeSignal());
|
||||
|
||||
Assert.Null(result);
|
||||
Assert.Equal(0, loggedProbes);
|
||||
Assert.True(silentProbes >= 1, $"expected a silent first check, saw {silentProbes}");
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Initial_hit_probes_once_more_with_the_logger_for_the_source_line()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Info);
|
||||
var loggedProbes = 0;
|
||||
|
||||
var result = TenantIdAwaiter.WaitForTenantId(
|
||||
timeoutSeconds: 600,
|
||||
logger: logger,
|
||||
ct: CancellationToken.None,
|
||||
resolve: l => { if (l != null) loggedProbes++; return "tenant-1"; },
|
||||
signalFactory: () => throw new InvalidOperationException("no wait expected on a hit"));
|
||||
|
||||
Assert.Equal("tenant-1", result);
|
||||
Assert.Equal(1, loggedProbes);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+6
-1
@@ -258,13 +258,18 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.SignalAdapters
|
||||
using var f = new Fixture();
|
||||
using var adapter = new AadJoinWatcherAdapter(
|
||||
f.Watcher, f.Ingress, f.Clock,
|
||||
onRealUserJoined: () => throw new InvalidOperationException("boom"));
|
||||
onRealUserJoined: () => throw new InvalidOperationException("boom"),
|
||||
logger: f.Logger);
|
||||
|
||||
// The signal post completes BEFORE the callback fires — even if the callback
|
||||
// throws, the decision signal must already be on the bus.
|
||||
adapter.TriggerFromTest("alice@contoso.com", "x");
|
||||
|
||||
Assert.Single(f.Ingress.Posted, p => p.Kind == DecisionSignalKind.AadUserJoinedLate);
|
||||
// ...and the fault is in the log instead of vanishing.
|
||||
Assert.Contains(
|
||||
"[WARN] AadJoinWatcherAdapter: onRealUserJoined callback threw: boom",
|
||||
System.IO.File.ReadAllText(System.IO.Path.Combine(f.Tmp.Path, "agent.log")));
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+41
@@ -126,6 +126,47 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Telemetry
|
||||
Assert.Equal(2, collector.CollectInvocationCount);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Stop_then_Dispose_logs_Stopped_once()
|
||||
{
|
||||
// Hosts call Stop and then Dispose, which stops again; the log used to show
|
||||
// "[X] Stopped" twice in the same millisecond.
|
||||
using var tmp = new TempDirectory();
|
||||
var collector = new BlockingCollector(NewPost(), NewLogger(tmp));
|
||||
|
||||
collector.Start();
|
||||
collector.Stop();
|
||||
collector.Dispose();
|
||||
|
||||
var log = File.ReadAllText(Path.Combine(tmp.Path, "logs", "agent.log"));
|
||||
Assert.Equal(1, CountOccurrences(log, "[BlockingCollector] Stopped"));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Dispose_without_Start_logs_no_Stopped_line()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = NewLogger(tmp);
|
||||
var collector = new BlockingCollector(NewPost(), logger);
|
||||
logger.Info("marker"); // make sure the log file exists
|
||||
|
||||
collector.Dispose();
|
||||
|
||||
var log = File.ReadAllText(Path.Combine(tmp.Path, "logs", "agent.log"));
|
||||
Assert.DoesNotContain("[BlockingCollector] Stopped", log);
|
||||
}
|
||||
|
||||
private static int CountOccurrences(string text, string value)
|
||||
{
|
||||
int count = 0, index = 0;
|
||||
while ((index = text.IndexOf(value, index, StringComparison.Ordinal)) >= 0)
|
||||
{
|
||||
count++;
|
||||
index += value.Length;
|
||||
}
|
||||
return count;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Test-only collector subclass: signals when <see cref="Collect"/> is entered and
|
||||
/// blocks until the test releases it, so we can exercise the reentrancy gate
|
||||
|
||||
+32
-9
@@ -14,8 +14,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Transport
|
||||
{
|
||||
/// <summary>
|
||||
/// <see cref="BackendTelemetryUploader"/> emits upload-cadence log lines (flushing / ingest
|
||||
/// OK / ingest TRANSIENT / ingest PERMANENT) so the transport path is observable. The
|
||||
/// success-path lines (flushing, ingest OK) are pipeline mechanics and live on Debug;
|
||||
/// OK / ingest TRANSIENT / ingest PERMANENT) so the transport path is observable. The send
|
||||
/// ("flushing") is mechanics and lives on Trace, the success record ("ingest OK") on Verbose;
|
||||
/// failures (TRANSIENT/PERMANENT/TIMEOUT/NETWORK) live on Warning/Error and remain
|
||||
/// visible at the default Info level. We assert on log-file content because AgentLogger
|
||||
/// writes to disk; checking the file is the most faithful production proxy.
|
||||
@@ -54,11 +54,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Transport
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task UploadBatch_logs_flush_start_and_ingest_OK_on_success_at_debug()
|
||||
public async Task UploadBatch_logs_flush_start_at_trace_and_ingest_OK_at_verbose()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
// Success-path transport lines live on Debug; capture at that level to assert them.
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Debug);
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Trace);
|
||||
|
||||
var handler = new RecordingHttpMessageHandler();
|
||||
handler.QueueStatus(HttpStatusCode.OK);
|
||||
@@ -75,11 +74,35 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Transport
|
||||
|
||||
// AgentLogger writes each line with File.AppendAllText — content is already on disk.
|
||||
var logContent = ReadLogs(tmp.Path);
|
||||
Assert.Contains("BackendTelemetryUploader: flushing 2 item(s)", logContent);
|
||||
// Each upload now carries a per-request correlation id (X-Correlation-ID) for
|
||||
// end-to-end tracing; it precedes the item count in the cadence log lines.
|
||||
Assert.Contains("[TRACE] BackendTelemetryUploader: flushing 2 item(s)", logContent);
|
||||
// Each upload carries a per-request correlation id (X-Correlation-ID) for end-to-end
|
||||
// tracing; the success record carries the batch's item range so it stands alone.
|
||||
Assert.Contains("[VERBOSE] BackendTelemetryUploader: ingest OK (corr=", logContent);
|
||||
Assert.Contains("items=2, firstId=1, lastId=2, bytes=", logContent);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task UploadBatch_success_at_verbose_logs_the_record_without_the_send_line()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Verbose);
|
||||
|
||||
var handler = new RecordingHttpMessageHandler();
|
||||
handler.QueueStatus(HttpStatusCode.OK);
|
||||
using var http = new HttpClient(handler) { Timeout = TimeSpan.FromSeconds(30) };
|
||||
|
||||
var sut = new BackendTelemetryUploader(
|
||||
httpClient: http,
|
||||
baseUrl: "https://backend.test",
|
||||
tenantId: "T1",
|
||||
logger: logger);
|
||||
|
||||
var result = await sut.UploadBatchAsync(new[] { NewEventItem(1) }, CancellationToken.None);
|
||||
Assert.True(result.Success);
|
||||
|
||||
var logContent = ReadLogs(tmp.Path);
|
||||
Assert.DoesNotContain("BackendTelemetryUploader: flushing", logContent);
|
||||
Assert.Contains("BackendTelemetryUploader: ingest OK (corr=", logContent);
|
||||
Assert.Contains("items=2", logContent);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
|
||||
+18
@@ -550,6 +550,24 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Transport
|
||||
Assert.Contains("network", result.ErrorReason);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Network_error_reason_names_the_cause_instead_of_the_generic_text()
|
||||
{
|
||||
using var rig = new Rig();
|
||||
rig.Handler.QueueThrow(new HttpRequestException(
|
||||
"An error occurred while sending the request.",
|
||||
new WebException(
|
||||
"Unable to connect to the remote server",
|
||||
new System.Net.Sockets.SocketException((int)System.Net.Sockets.SocketError.TimedOut),
|
||||
WebExceptionStatus.ConnectFailure,
|
||||
null)));
|
||||
|
||||
var result = await rig.Sut.UploadBatchAsync(new[] { NewEventItem(1) }, CancellationToken.None);
|
||||
|
||||
Assert.True(result.IsTransient);
|
||||
Assert.StartsWith("network: status=ConnectFailure, socket=TimedOut: ", result.ErrorReason);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task HttpClient_timeout_maps_to_Transient()
|
||||
{
|
||||
|
||||
+10
-3
@@ -3,6 +3,7 @@ using System;
|
||||
using System.Collections.Generic;
|
||||
using System.Threading;
|
||||
using System.Threading.Tasks;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
|
||||
using AutopilotMonitor.Agent.V2.Core.Transport.Telemetry;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
@@ -33,10 +34,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Transport
|
||||
public FakeBackendTelemetryUploader Uploader { get; } = new FakeBackendTelemetryUploader();
|
||||
public TelemetryUploadOrchestrator Sut { get; }
|
||||
|
||||
public Rig()
|
||||
public Rig(AgentLogger? logger = null)
|
||||
{
|
||||
Spool = new TelemetrySpool(Tmp.Path, Clock);
|
||||
Sut = new TelemetryUploadOrchestrator(Spool, Uploader, Clock, batchSize: 10, retryBackoffs: new[] { TimeSpan.Zero });
|
||||
Sut = new TelemetryUploadOrchestrator(Spool, Uploader, Clock, batchSize: 10, retryBackoffs: new[] { TimeSpan.Zero }, logger: logger);
|
||||
}
|
||||
|
||||
public void Dispose() { Sut.Dispose(); Tmp.Dispose(); }
|
||||
@@ -140,7 +141,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Transport
|
||||
[Fact]
|
||||
public async Task Handler_exception_does_not_break_drain_cursor()
|
||||
{
|
||||
using var rig = new Rig();
|
||||
using var logTmp = new TempDirectory();
|
||||
var logger = new AgentLogger(logTmp.Path, AgentLogLevel.Info);
|
||||
using var rig = new Rig(logger);
|
||||
rig.Sut.Enqueue(Draft());
|
||||
rig.Uploader.QueueOkWithSignals(deviceKillSignal: true);
|
||||
|
||||
@@ -150,6 +153,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Transport
|
||||
// Upload still succeeded — the cursor moves, drain returns success.
|
||||
Assert.Equal(1, drain.UploadedItems);
|
||||
Assert.Equal(0, drain.FailedBatches);
|
||||
// The handler fault is no longer silent.
|
||||
Assert.Contains(
|
||||
"[WARN] TelemetryUploadOrchestrator: ServerResponseReceived handler threw: handler bug",
|
||||
System.IO.File.ReadAllText(System.IO.Path.Combine(logTmp.Path, "agent.log")));
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
|
||||
@@ -2,7 +2,9 @@ using System;
|
||||
using System.ComponentModel;
|
||||
using System.Net;
|
||||
using System.Net.Http;
|
||||
using System.Net.Sockets;
|
||||
using System.Security.Authentication;
|
||||
using System.Threading.Tasks;
|
||||
using AutopilotMonitor.Agent.V2.Core.Monitoring.Transport;
|
||||
using Xunit;
|
||||
|
||||
@@ -69,5 +71,56 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Transport
|
||||
Assert.Equal("boom", TransportErrorCodes.MessageWithNativeCode(new InvalidOperationException("boom")));
|
||||
Assert.Null(TransportErrorCodes.MessageWithNativeCode(null!));
|
||||
}
|
||||
|
||||
// The .NET Framework shape of a failed connect or name lookup through HttpClient.
|
||||
private static Exception SendFailureChain(WebExceptionStatus status, SocketError socketError) =>
|
||||
new HttpRequestException(
|
||||
"An error occurred while sending the request.",
|
||||
new WebException("Unable to connect to the remote server", new SocketException((int)socketError), status, null));
|
||||
|
||||
[Theory]
|
||||
[InlineData(WebExceptionStatus.ConnectFailure, SocketError.TimedOut, "status=ConnectFailure, socket=TimedOut: ")]
|
||||
[InlineData(WebExceptionStatus.NameResolutionFailure, SocketError.HostNotFound, "status=NameResolutionFailure, socket=HostNotFound: ")]
|
||||
public void Send_failure_names_status_and_socket_error(WebExceptionStatus status, SocketError socketError, string expectedPrefix)
|
||||
{
|
||||
var described = TransportErrorCodes.DescribeSendFailure(SendFailureChain(status, socketError));
|
||||
|
||||
Assert.StartsWith(expectedPrefix, described);
|
||||
Assert.DoesNotContain("An error occurred while sending the request", described);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Send_failure_of_a_tls_handshake_names_status_and_native_code()
|
||||
{
|
||||
var described = TransportErrorCodes.DescribeSendFailure(TlsFailureChain(new Win32Exception(IllegalMessage)));
|
||||
|
||||
Assert.StartsWith("status=SecureChannelFailure, win32=0x80090326: ", described);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Send_failure_without_details_is_the_innermost_message()
|
||||
{
|
||||
Assert.Equal("inner", TransportErrorCodes.DescribeSendFailure(new HttpRequestException("outer", new InvalidOperationException("inner"))));
|
||||
Assert.Equal("boom", TransportErrorCodes.DescribeSendFailure(new InvalidOperationException("boom")));
|
||||
Assert.Null(TransportErrorCodes.DescribeSendFailure(null!));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Real_refused_connect_names_the_endpoint_it_tried()
|
||||
{
|
||||
// The endpoint in the message is what tells the backend from a proxy, and only a real
|
||||
// connect produces it: a hand-built SocketException carries none.
|
||||
var listener = new TcpListener(IPAddress.Loopback, 0);
|
||||
listener.Start();
|
||||
var port = ((IPEndPoint)listener.LocalEndpoint).Port;
|
||||
listener.Stop();
|
||||
|
||||
using var client = new HttpClient(new HttpClientHandler { UseProxy = false });
|
||||
var failure = await Assert.ThrowsAsync<HttpRequestException>(() => client.GetAsync($"http://127.0.0.1:{port}/"));
|
||||
|
||||
var described = TransportErrorCodes.DescribeSendFailure(failure);
|
||||
Assert.StartsWith("status=ConnectFailure, socket=ConnectionRefused: ", described);
|
||||
Assert.Contains($"127.0.0.1:{port}", described);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -53,7 +53,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Configuration
|
||||
|
||||
|
||||
/// <summary>
|
||||
/// Log verbosity level: Info (default), Debug, Verbose.
|
||||
/// Log verbosity level: Info (default), Debug, Verbose, Trace (see <see cref="AgentLogLevel"/>).
|
||||
/// Overridable via remote config.
|
||||
/// </summary>
|
||||
public AgentLogLevel LogLevel { get; set; } = AgentLogLevel.Info;
|
||||
|
||||
@@ -151,9 +151,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Configuration
|
||||
try
|
||||
{
|
||||
if (attempt == 1)
|
||||
_logger.Info("Fetching remote configuration from backend...");
|
||||
_logger.Debug("Fetching remote configuration from backend...");
|
||||
else
|
||||
_logger.Info($"Fetching remote configuration from backend (attempt {attempt}/{maxAttempts})...");
|
||||
_logger.Debug($"Fetching remote configuration from backend (attempt {attempt}/{maxAttempts})...");
|
||||
|
||||
var config = await CallBackendAsync();
|
||||
|
||||
@@ -208,7 +208,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Configuration
|
||||
if (attempt < maxAttempts)
|
||||
{
|
||||
var delay = InitialFetchRetryBackoff[attempt - 1];
|
||||
_logger.Info($"Retrying remote config fetch in {delay.TotalSeconds:0}s...");
|
||||
_logger.Debug($"Retrying remote config fetch in {delay.TotalSeconds:0}s...");
|
||||
try { await DelayBetweenAttemptsAsync(delay); }
|
||||
catch (TaskCanceledException) { break; }
|
||||
}
|
||||
|
||||
@@ -1,13 +1,24 @@
|
||||
using System;
|
||||
using System.Collections.Concurrent;
|
||||
using System.IO;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Logging
|
||||
{
|
||||
/// <summary>
|
||||
/// Log verbosity levels for the agent.
|
||||
/// Info = normal operational messages (default)
|
||||
/// Debug = includes DEBUG-tagged lines (component state, config, decisions)
|
||||
/// Verbose = includes VERBOSE-tagged lines (per-event details, hot-path tracing)
|
||||
/// Log verbosity levels for the agent. Each level adds to the one before it.
|
||||
/// Info = the enrollment flow an admin follows: one line per thing that happened
|
||||
/// (state change, milestone, result), repeated only when its content changed.
|
||||
/// Debug = why and how: decision details, extra attributes, suppression decisions,
|
||||
/// attempts in retry loops. Grows with the number of apps, scripts and phases,
|
||||
/// not with elapsed time.
|
||||
/// Verbose = everything known about one thing: full payloads, raw JSON, adapter mappings,
|
||||
/// the record of each upload batch. Every line carries content of its own.
|
||||
/// Trace = the mechanics: watcher arm/fire, poll ticks without a result, debounce,
|
||||
/// per-item enqueue, per-signal pass-through. Grows with time or with the number
|
||||
/// of notifications; one line alone says almost nothing.
|
||||
/// An identical repeat of a line goes to Trace after its first occurrence (repeatKey).
|
||||
/// A caught unexpected exception is never logged below Debug. Warning and Error are always
|
||||
/// written.
|
||||
/// </summary>
|
||||
public enum AgentLogLevel
|
||||
{
|
||||
@@ -32,6 +43,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Logging
|
||||
private AgentLogLevel _logLevel;
|
||||
private readonly object _lockObject = new object();
|
||||
|
||||
// Last message written under each repeatKey; bounded because callers key by call site
|
||||
// plus subject (rule, category, file, policy).
|
||||
private readonly ConcurrentDictionary<string, string> _lastMessageByRepeatKey =
|
||||
new ConcurrentDictionary<string, string>(StringComparer.Ordinal);
|
||||
|
||||
private readonly long _maxFileSizeBytes;
|
||||
private readonly string _logDirectory;
|
||||
private readonly string _logFileBaseName; // "agent"
|
||||
@@ -122,21 +138,48 @@ namespace AutopilotMonitor.Agent.V2.Core.Logging
|
||||
Log("TRACE", message);
|
||||
}
|
||||
|
||||
public void Verbose(string message)
|
||||
/// <param name="repeatKey">Names the call site and its subject. A message equal to the
|
||||
/// last one written under this key goes to Trace instead.</param>
|
||||
public void Verbose(string message, string repeatKey = null)
|
||||
{
|
||||
if (_logLevel >= AgentLogLevel.Verbose)
|
||||
Log("VERBOSE", message);
|
||||
if (_logLevel < AgentLogLevel.Verbose) return;
|
||||
if (IsRepeat(repeatKey, message)) Trace(message);
|
||||
else Log("VERBOSE", message);
|
||||
}
|
||||
|
||||
public void Debug(string message)
|
||||
/// <param name="repeatKey">Names the call site and its subject. A message equal to the
|
||||
/// last one written under this key goes to Trace instead.</param>
|
||||
public void Debug(string message, string repeatKey = null)
|
||||
{
|
||||
if (_logLevel >= AgentLogLevel.Debug)
|
||||
Log("DEBUG", message);
|
||||
if (_logLevel < AgentLogLevel.Debug) return;
|
||||
if (IsRepeat(repeatKey, message)) Trace(message);
|
||||
else Log("DEBUG", message);
|
||||
}
|
||||
|
||||
public void Info(string message)
|
||||
/// <param name="repeatKey">Names the call site and its subject. A message equal to the
|
||||
/// last one written under this key goes to Trace instead.</param>
|
||||
public void Info(string message, string repeatKey = null)
|
||||
{
|
||||
Log("INFO", message);
|
||||
if (IsRepeat(repeatKey, message)) Trace(message);
|
||||
else Log("INFO", message);
|
||||
}
|
||||
|
||||
// Records the message under the key and reports whether it equals the previous one.
|
||||
// Only reached once the requested level is enabled, so a line that was never written
|
||||
// cannot turn its first visible occurrence into a repeat.
|
||||
private bool IsRepeat(string repeatKey, string message)
|
||||
{
|
||||
if (repeatKey == null) return false;
|
||||
var repeat = false;
|
||||
_lastMessageByRepeatKey.AddOrUpdate(
|
||||
repeatKey,
|
||||
message,
|
||||
(_, previous) =>
|
||||
{
|
||||
repeat = string.Equals(previous, message, StringComparison.Ordinal);
|
||||
return message;
|
||||
});
|
||||
return repeat;
|
||||
}
|
||||
|
||||
public void Warning(string message)
|
||||
|
||||
+1
-1
@@ -426,7 +426,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
if (_logger == null) return;
|
||||
var stateList = string.Join(", ", this.Select(x => $"{x.Name ?? x.Id}:{x.InstallationState}"));
|
||||
_logger.Debug($"App states [{Count}]: {stateList}");
|
||||
_logger.Verbose($"App states [{Count}]: {stateList}");
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+33
@@ -0,0 +1,33 @@
|
||||
using System;
|
||||
using AutopilotMonitor.Agent.V2.Core.Monitoring.Interop;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
/// <summary>
|
||||
/// Which file a path holds right now: volume serial plus file index. IME rolls a log with
|
||||
/// <c>File.Move</c>, so the identity stays with the bytes when the name changes.
|
||||
/// </summary>
|
||||
internal static class ImeLogFileIdentity
|
||||
{
|
||||
/// <summary>
|
||||
/// Null when the file cannot be opened. An attribute-only handle with full sharing, so it
|
||||
/// can never make IME's rename of the log fail.
|
||||
/// </summary>
|
||||
public static string TryRead(string path)
|
||||
{
|
||||
using (var handle = FileNativeMethods.CreateFileW(
|
||||
path,
|
||||
FileNativeMethods.FILE_READ_ATTRIBUTES,
|
||||
FileNativeMethods.FILE_SHARE_READ | FileNativeMethods.FILE_SHARE_WRITE | FileNativeMethods.FILE_SHARE_DELETE,
|
||||
IntPtr.Zero,
|
||||
FileNativeMethods.OPEN_EXISTING,
|
||||
0,
|
||||
IntPtr.Zero))
|
||||
{
|
||||
if (handle.IsInvalid) return null;
|
||||
if (!FileNativeMethods.GetFileInformationByHandle(handle, out var info)) return null;
|
||||
return $"{info.VolumeSerialNumber:X8}-{info.FileIndexHigh:X8}{info.FileIndexLow:X8}";
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
+40
-26
@@ -19,7 +19,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
public partial class ImeLogTracker
|
||||
{
|
||||
// PR3-A2: dedup state for `IME impersonation` lines. ~24 identical per session at
|
||||
// DEBUG flooded the log; we now emit on user change + a 60s rollup with the count.
|
||||
// DEBUG flooded the log; a user change logs at Debug, the 60s rollup with the count at Trace.
|
||||
private string _lastImpersonationUser;
|
||||
private int _impersonationRepeatCount;
|
||||
private DateTime _impersonationLastRollupUtc = DateTime.MinValue;
|
||||
@@ -111,12 +111,23 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
var now = DateTime.UtcNow;
|
||||
if (now - _impersonationLastRollupUtc >= ImpersonationRollupInterval)
|
||||
{
|
||||
_logger.Debug($"IME impersonation: same as before (user='{current}', n={_impersonationRepeatCount} since last rollup)");
|
||||
_logger.Trace($"IME impersonation: same as before (user='{current}', n={_impersonationRepeatCount} since last rollup)");
|
||||
_impersonationLastRollupUtc = now;
|
||||
_impersonationRepeatCount = 0;
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Info for what a line of this enrollment reports. A line replayed from a previous
|
||||
/// enrollment's log (historic-replay guard) is context, not progress: Debug. Only for
|
||||
/// handlers that run while that line is processed, since the flag describes the line.
|
||||
/// </summary>
|
||||
private void LogLineActivity(string message, string repeatKey = null)
|
||||
{
|
||||
if (_currentLineIsHistoricReplay) _logger.Debug(message + " (historic line)", repeatKey);
|
||||
else _logger.Info(message, repeatKey);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Result of IME's check right after an install (D-392). After an exit code that asked for a
|
||||
/// restart that check decides nothing: IME sets no error then and checks again after the
|
||||
@@ -276,7 +287,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// map). Prefer the source CMTrace timestamp; latest start wins on a policy re-run.
|
||||
var startedAtUtc = LastMatchedLogTimestamp ?? UtcNowProvider();
|
||||
_healthScriptStartTimes[id] = (startedAtUtc, CaptureLastMatchedProvenance());
|
||||
_logger.Info($"ImeLogTracker: health script started: {id}");
|
||||
LogLineActivity($"ImeLogTracker: health script started: {id}", repeatKey: "ImeLogTracker.hsStarted:" + id);
|
||||
|
||||
// A replayed line of a previous enrollment bypasses the recurrence gate: the
|
||||
// adapter drops its event, and a dropped run must not count as the policy's
|
||||
@@ -285,7 +296,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
&& !_recurringScripts.OnStart(id, startedAtUtc, policyType, LastMatchedPatternId))
|
||||
{
|
||||
_stateDirty = true;
|
||||
_logger.Debug($"ImeLogTracker: health script {id} is a recurring policy — start held until its result is known");
|
||||
_logger.Debug($"ImeLogTracker: health script {id} is a recurring policy — start held until its result is known", repeatKey: "ImeLogTracker.hsStartHeld:" + id);
|
||||
return;
|
||||
}
|
||||
_stateDirty = true;
|
||||
@@ -501,7 +512,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
RecordInvocationMarker(null, isClose: false);
|
||||
NoteInvocationActivity();
|
||||
if (!string.IsNullOrEmpty(kind) && !string.Equals(kind, "powershell", StringComparison.OrdinalIgnoreCase))
|
||||
_logger.Debug($"ImeLogTracker: AgentExecutor invocation of kind '{kind}' — exit/output lines not captured as a platform script");
|
||||
_logger.Trace($"ImeLogTracker: AgentExecutor invocation of kind '{kind}' — exit/output lines not captured as a platform script");
|
||||
}
|
||||
|
||||
private void HandleAgentExecutorCompleted()
|
||||
@@ -1076,10 +1087,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
DurationBasis = "script_runtime",
|
||||
};
|
||||
|
||||
_logger.Info($"ImeLogTracker: health-script {scriptPart} early-signal for {id}: " +
|
||||
$"compliance={compliance}, exit={exitCode}, " +
|
||||
$"stdout={(stdout == null ? "n/a" : stdout.Length + " chars")}, " +
|
||||
$"stderr={(stderr == null ? "n/a" : stderr.Length + " chars")}");
|
||||
LogLineActivity($"ImeLogTracker: health-script {scriptPart} early-signal for {id}: " +
|
||||
$"compliance={compliance}, exit={exitCode}, " +
|
||||
$"stdout={(stdout == null ? "n/a" : stdout.Length + " chars")}, " +
|
||||
$"stderr={(stderr == null ? "n/a" : stderr.Length + " chars")}",
|
||||
repeatKey: "ImeLogTracker.hsEarly:" + scriptPart + ":" + id);
|
||||
|
||||
EmitScriptEvent(enriched);
|
||||
|
||||
@@ -1303,11 +1315,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
EmitScriptEvent(postDetection);
|
||||
}
|
||||
|
||||
_logger.Info($"ImeLogTracker: health-script result emitted for {policyId} " +
|
||||
$"(status={remediationStatus?.ToString() ?? "?"}, " +
|
||||
$"firstDetectExit={firstDetectExit?.ToString() ?? "n/a"}, " +
|
||||
$"remediationExit={remediationExit?.ToString() ?? "n/a"}, " +
|
||||
$"lastDetectExit={lastDetectExit?.ToString() ?? "n/a"})");
|
||||
// "result for", not "emitted": the recurrence gate in EmitScriptEvent may hold a
|
||||
// repeat back and logs that itself.
|
||||
LogLineActivity($"ImeLogTracker: health-script result for {policyId} " +
|
||||
$"(status={remediationStatus?.ToString() ?? "?"}, " +
|
||||
$"firstDetectExit={firstDetectExit?.ToString() ?? "n/a"}, " +
|
||||
$"remediationExit={remediationExit?.ToString() ?? "n/a"}, " +
|
||||
$"lastDetectExit={lastDetectExit?.ToString() ?? "n/a"})",
|
||||
repeatKey: "ImeLogTracker.hsResult:" + policyId);
|
||||
}
|
||||
|
||||
private static ScriptExecutionState BuildHealthScriptPhase(
|
||||
@@ -1377,7 +1392,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
_stateDirty = true;
|
||||
if (!emit)
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: health script {script.PolicyId} {script.ScriptPart} repeats its last reported result — counted, not emitted");
|
||||
_logger.Debug($"ImeLogTracker: health script {script.PolicyId} {script.ScriptPart} repeats its last reported result — counted, not emitted", repeatKey: "ImeLogTracker.hsRepeat:" + script.PolicyId + ":" + script.ScriptPart);
|
||||
return;
|
||||
}
|
||||
if (releasedStart != null) RaiseScriptStarted(releasedStart);
|
||||
@@ -1433,7 +1448,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
private void HandleImeStarted()
|
||||
{
|
||||
_logger.Info("ImeLogTracker: IME Agent Started detected");
|
||||
LogLineActivity("ImeLogTracker: IME Agent Started detected");
|
||||
|
||||
// Log any currently active app — it will be re-evaluated by new log entries after IME restart.
|
||||
// We intentionally do NOT mark it as Installed here because IME may retry the app.
|
||||
@@ -1509,11 +1524,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
_logger.Debug(
|
||||
"ImeLogTracker: zero-app user session observed before the user ESP phase " +
|
||||
$"(current phase: {_lastEspPhaseDetected ?? "(none)"}) - deferring until AccountSetup");
|
||||
$"(current phase: {_lastEspPhaseDetected ?? "(none)"}) - deferring until AccountSetup", repeatKey: "ImeLogTracker.zeroAppDeferred");
|
||||
return;
|
||||
}
|
||||
|
||||
_logger.Info("ImeLogTracker: user session enumerated with zero targeted apps - treating as user session completed");
|
||||
_logger.Info("ImeLogTracker: user session enumerated with zero targeted apps - treating as user session completed", repeatKey: "ImeLogTracker.zeroAppUserSession");
|
||||
OnUserSessionCompleted?.Invoke();
|
||||
}
|
||||
|
||||
@@ -1531,7 +1546,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// which would corrupt tracking if we allowed it to trigger a phase change.
|
||||
if (phaseOrd < _currentPhaseOrder)
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: ignoring backward phase transition to {espPhaseString} (current phase order: {_currentPhaseOrder})");
|
||||
_logger.Trace($"ImeLogTracker: ignoring backward phase transition to {espPhaseString} (current phase order: {_currentPhaseOrder})");
|
||||
return;
|
||||
}
|
||||
|
||||
@@ -1572,7 +1587,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
_phasePackageSnapshots[_lastEspPhaseDetected] =
|
||||
new List<AppPackageState>(_packageStates);
|
||||
_logger.Info($"ImeLogTracker: Snapshotted {_packageStates.CountAll} package states from {_lastEspPhaseDetected} phase");
|
||||
_logger.Debug($"ImeLogTracker: Snapshotted {_packageStates.CountAll} package states from {_lastEspPhaseDetected} phase");
|
||||
}
|
||||
|
||||
_packageStates.Clear();
|
||||
@@ -1586,12 +1601,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
// First detection of any phase OR a real transition into a new phase: surface on Info
|
||||
// so phase boundaries are visible without enabling Debug. Re-matches of the same phase
|
||||
// (IME re-emits the phase string periodically as it re-evaluates app sets) stay on
|
||||
// Debug to avoid Info repetition.
|
||||
// (IME re-emits the phase string periodically as it re-evaluates app sets) are
|
||||
// identical repeats and go to Trace (D-394).
|
||||
if (isFirstOrChangedPhase)
|
||||
_logger.Info($"ImeLogTracker: ESP phase detected: {espPhaseString}");
|
||||
else
|
||||
_logger.Debug($"ImeLogTracker: ESP phase detected: {espPhaseString}");
|
||||
_logger.Trace($"ImeLogTracker: ESP phase detected: {espPhaseString}");
|
||||
ActivatePatterns(logPhaseIsCurrentPhase);
|
||||
|
||||
OnEspPhaseChanged?.Invoke(espPhaseString);
|
||||
@@ -1645,7 +1660,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
// Ignore user-targeted packages during device setup (we only track device phase in general)
|
||||
_packageStates.AddUpdateFromJsonPolicies(policies, ignoreUserTargeted: false);
|
||||
_logger.Info($"ImeLogTracker: discovered {policies.Count} policies, tracking {_packageStates.Count} packages");
|
||||
_logger.Info($"ImeLogTracker: discovered {policies.Count} policies, tracking {_packageStates.Count} packages", repeatKey: "ImeLogTracker.policies");
|
||||
OnPoliciesDiscovered?.Invoke(policiesJson);
|
||||
}
|
||||
}
|
||||
@@ -1694,7 +1709,6 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
_allAppsCompletedFired = true;
|
||||
_logger.Info($"ImeLogTracker: all {_packageStates.CountAll} apps completed");
|
||||
OnAllAppsCompleted?.Invoke();
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -1709,7 +1723,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
if (changed)
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: {pkg.Name ?? id} downloading: {bytes}/{ofbytes}");
|
||||
_logger.Verbose($"ImeLogTracker: {pkg.Name ?? id} downloading: {bytes}/{ofbytes}");
|
||||
OnAppStateChanged?.Invoke(pkg, oldState, AppInstallationState.Downloading);
|
||||
}
|
||||
}
|
||||
|
||||
+71
-20
@@ -51,23 +51,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
if (!Directory.Exists(_logFolder))
|
||||
return;
|
||||
|
||||
// Get all matching log files, sorted by name (archived files come before current).
|
||||
// M2: a SINGLE directory enumeration filtered in-memory against the patterns, instead
|
||||
// of one Directory.GetFiles(pattern) per LogFilePattern every 100 ms poll (~90 folder
|
||||
// enumerations/s → 1). The in-memory regex match is anchored, so it is also immune to
|
||||
// the Win32 "*.ext" 8.3 search-pattern quirk.
|
||||
var files = new List<string>();
|
||||
try
|
||||
{
|
||||
foreach (var filePath in Directory.EnumerateFiles(_logFolder))
|
||||
{
|
||||
if (MatchesLogFilePattern(Path.GetFileName(filePath)))
|
||||
files.Add(filePath);
|
||||
}
|
||||
}
|
||||
catch (DirectoryNotFoundException) { }
|
||||
|
||||
files.Sort(StringComparer.OrdinalIgnoreCase);
|
||||
var files = EnumerateLogFiles();
|
||||
if (FileIdentitiesAreDue(files)) ReconcileFileIdentities(files);
|
||||
|
||||
// Σ(file length − bookmark) after this pass — the tracker's queue depth.
|
||||
long backlogBytes = 0;
|
||||
@@ -83,7 +68,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
catch (FileNotFoundException) { }
|
||||
catch (IOException ex)
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: IO error reading {filePath}: {ex.Message}");
|
||||
_logger.Debug($"ImeLogTracker: IO error reading {filePath}: {ex.Message}", repeatKey: "ImeLogTracker.ioError:" + filePath);
|
||||
}
|
||||
}
|
||||
|
||||
@@ -94,6 +79,66 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// All matching log files, sorted by name (archived files come before current).
|
||||
/// M2: a SINGLE directory enumeration filtered in-memory against the patterns, instead
|
||||
/// of one Directory.GetFiles(pattern) per LogFilePattern every 100 ms poll (~90 folder
|
||||
/// enumerations/s → 1). The in-memory regex match is anchored, so it is also immune to
|
||||
/// the Win32 "*.ext" 8.3 search-pattern quirk.
|
||||
/// </summary>
|
||||
private List<string> EnumerateLogFiles()
|
||||
{
|
||||
var files = new List<string>();
|
||||
try
|
||||
{
|
||||
foreach (var filePath in Directory.EnumerateFiles(_logFolder))
|
||||
{
|
||||
if (MatchesLogFilePattern(Path.GetFileName(filePath)))
|
||||
files.Add(filePath);
|
||||
}
|
||||
}
|
||||
catch (DirectoryNotFoundException) { }
|
||||
|
||||
files.Sort(StringComparer.OrdinalIgnoreCase);
|
||||
return files;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// On the first pass (a restart can have rolled logs over) and when a file has no known
|
||||
/// identity yet, which is how a rolled-over archive first shows up. Nothing is opened in
|
||||
/// the regular poll.
|
||||
/// </summary>
|
||||
private bool FileIdentitiesAreDue(List<string> files)
|
||||
{
|
||||
if (!_fileIdentitiesReconciled) return true;
|
||||
foreach (var filePath in files)
|
||||
{
|
||||
if (!_positionTracker.HasIdentity(filePath)) return true;
|
||||
}
|
||||
return false;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Lets every bookmark follow its file (see <see cref="LogFilePositionTracker.Reconcile"/>).
|
||||
/// Reading a rolled-over log again would replay every app and script line in it: finished
|
||||
/// apps fall back to Installing, and the subgraph line of an older app marks the app that is
|
||||
/// running right now as skipped.
|
||||
/// </summary>
|
||||
private void ReconcileFileIdentities(List<string> files)
|
||||
{
|
||||
_fileIdentitiesReconciled = true;
|
||||
|
||||
var idByPath = new Dictionary<string, string>(StringComparer.OrdinalIgnoreCase);
|
||||
foreach (var filePath in files) idByPath[filePath] = FileIdentityProvider(filePath);
|
||||
|
||||
foreach (var move in _positionTracker.Reconcile(idByPath))
|
||||
{
|
||||
MoveFileContext(move.From, move.To);
|
||||
_logger.Info($"ImeLogTracker: {Path.GetFileName(move.From)} rolled over to {Path.GetFileName(move.To)} - continuing at offset {move.Position} instead of reading it again");
|
||||
}
|
||||
_stateDirty = true;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// One pass over one file: the bytes behind the bookmark, on a multi-writer file preceded
|
||||
/// by the overwrite check that may move the bookmark back first (see
|
||||
@@ -104,6 +149,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
var fileInfo = new FileInfo(filePath);
|
||||
if (!fileInfo.Exists) return 0;
|
||||
|
||||
// IME renamed the file after this pass listed the folder, or its archive sorts behind it
|
||||
// (_IntuneManagementExtension.log). Either way the archive needs the bookmark before the
|
||||
// read below resets it.
|
||||
if (_positionTracker.IsBehindBookmark(filePath, fileInfo.Length))
|
||||
ReconcileFileIdentities(EnumerateLogFiles());
|
||||
|
||||
// Captured BEFORE MarkChecked below stamps this pass. Growth measured
|
||||
// against a previously observed state is what makes this pass's lines valid
|
||||
// "written now" anchors — for the per-file measurement AND per-line anchoring.
|
||||
@@ -588,7 +639,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
_currentLineIsHistoricReplay = isStaleReplayLine;
|
||||
if (isStaleReplayLine && AppMutatingActions.Contains(pattern.Action?.ToLower() ?? string.Empty))
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: skipped app action '{pattern.Action}' for historic line ({ResolveEntryUtc(entry):o})");
|
||||
_logger.Trace($"ImeLogTracker: skipped app action '{pattern.Action}' for historic line ({ResolveEntryUtc(entry):o})");
|
||||
return;
|
||||
}
|
||||
|
||||
@@ -684,7 +735,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
break;
|
||||
|
||||
case "enrollmentcompleted":
|
||||
_logger.Info("ImeLogTracker: User session completed detected");
|
||||
LogLineActivity("ImeLogTracker: User session completed detected", repeatKey: "ImeLogTracker.userSessionCompleted");
|
||||
OnUserSessionCompleted?.Invoke();
|
||||
break;
|
||||
|
||||
|
||||
+29
@@ -616,6 +616,35 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
private void InvalidateInvocationMarkersFrom(string fileName, long offset) => TakeInvocationMarkersFrom(fileName, offset, out _);
|
||||
|
||||
/// <summary>
|
||||
/// A log was rolled over: what the tracker knows about its bytes goes with them. The markers keep
|
||||
/// <see cref="_lastPlatformMarker"/> alive, so the run in flight still owns its lines in the fresh file;
|
||||
/// the ledger stays behind and empties, an archive is not checked for overwrites.
|
||||
/// </summary>
|
||||
private void MoveFileContext(string fromPath, string toPath)
|
||||
{
|
||||
var from = Path.GetFileName(fromPath);
|
||||
var to = Path.GetFileName(toPath);
|
||||
|
||||
List<InvocationMarker> markers;
|
||||
if (_invocationMarkers.TryGetValue(from, out markers))
|
||||
{
|
||||
_invocationMarkers.Remove(from);
|
||||
_invocationMarkers[to] = markers;
|
||||
}
|
||||
if (_platformMarkerFiles.Contains(from)) _platformMarkerFiles.Add(to);
|
||||
|
||||
FileLedger ledger;
|
||||
if (_ledgers.TryGetValue(from, out ledger)) ledger.Clear();
|
||||
|
||||
HeldTail held;
|
||||
if (_heldTails.TryGetValue(fromPath, out held))
|
||||
{
|
||||
_heldTails.Remove(fromPath);
|
||||
_heldTails[toPath] = held;
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// An entry that reads unchanged after a rewind keeps its markers: gives back the set-aside markers at exactly
|
||||
/// <paramref name="entryOffset"/>. Set-aside markers in front of it belonged to entries that changed and stay
|
||||
|
||||
+15
-12
@@ -88,6 +88,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// system clock, ImeLogHost rewires it to the agent IClock, tests to their VirtualClock.
|
||||
internal Func<DateTime> UtcNowProvider { get; set; } = () => DateTime.UtcNow;
|
||||
|
||||
// Which file a path holds; null when unreadable. Tests swap it to cover that path.
|
||||
internal Func<string, string> FileIdentityProvider { get; set; } = ImeLogFileIdentity.TryRead;
|
||||
|
||||
// False until the bookmarks were checked against the disk once in this process.
|
||||
private bool _fileIdentitiesReconciled;
|
||||
|
||||
/// <summary>
|
||||
/// CMTrace timestamps from IME are emitted in UTC, but DateTimeKind may arrive as
|
||||
/// Unspecified depending on the parser path. Normalize via SpecifyKind=Utc rather than
|
||||
@@ -494,7 +500,6 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
public Action OnImeStarted { get; set; }
|
||||
public Action<AppPackageState, AppInstallationState, AppInstallationState> OnAppStateChanged { get; set; }
|
||||
public Action<string> OnPoliciesDiscovered { get; set; }
|
||||
public Action OnAllAppsCompleted { get; set; }
|
||||
public Action OnUserSessionCompleted { get; set; }
|
||||
public Action<string> OnImeSessionChange { get; set; }
|
||||
// Args: errorCode (may be empty when IME logged none), raw failure line excerpt.
|
||||
@@ -954,13 +959,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
if (!Directory.Exists(_logFolder)) return;
|
||||
var inputs = new List<ImeLogEraPreScan.ScanInput>();
|
||||
var files = new List<string>();
|
||||
foreach (var filePath in Directory.EnumerateFiles(_logFolder))
|
||||
{
|
||||
if (MatchesLogFilePattern(Path.GetFileName(filePath)))
|
||||
files.Add(filePath);
|
||||
}
|
||||
files.Sort(StringComparer.OrdinalIgnoreCase);
|
||||
var files = EnumerateLogFiles();
|
||||
// First: the read below resets the bookmark of a file that shrank, and the archive
|
||||
// that file moved to during the downtime still needs that bookmark.
|
||||
ReconcileFileIdentities(files);
|
||||
foreach (var filePath in files)
|
||||
{
|
||||
var info = new FileInfo(filePath);
|
||||
@@ -994,9 +996,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
LoadState();
|
||||
|
||||
// Era anchors for the backlog the first pass is about to read (2026-09-04). Runs
|
||||
// before the poll loop so every replayed line already finds its era; read-only on
|
||||
// the position tracker. Replay tooling anchors nothing — its logs did not come from
|
||||
// this device's bootstrap.
|
||||
// before the poll loop so every replayed line already finds its era. Replay tooling
|
||||
// anchors nothing — its logs did not come from this device's bootstrap.
|
||||
if (!SimulationMode) PreScanEras();
|
||||
|
||||
_cts = new CancellationTokenSource();
|
||||
@@ -1180,6 +1181,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
var fullPath = Path.Combine(_logFolder, kvp.Key);
|
||||
_positionTracker.RestorePosition(fullPath, kvp.Value.Position, kvp.Value.LastKnownSize);
|
||||
_positionTracker.RestoreFileId(fullPath, kvp.Value.FileId);
|
||||
}
|
||||
}
|
||||
|
||||
@@ -1346,7 +1348,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
state.FilePositions[fileName] = new FilePositionData
|
||||
{
|
||||
Position = kvp.Value.Position,
|
||||
LastKnownSize = kvp.Value.LastKnownSize
|
||||
LastKnownSize = kvp.Value.LastKnownSize,
|
||||
FileId = _positionTracker.GetFileId(kvp.Key)
|
||||
};
|
||||
}
|
||||
|
||||
|
||||
+3
@@ -250,5 +250,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
public long Position { get; set; }
|
||||
public long LastKnownSize { get; set; }
|
||||
|
||||
/// <summary>Which file the position belongs to (see <see cref="LogFilePositionTracker.Reconcile"/>); null on older state files.</summary>
|
||||
public string FileId { get; set; }
|
||||
}
|
||||
}
|
||||
|
||||
+127
-6
@@ -13,12 +13,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
private readonly Dictionary<string, FilePositionState> _positions
|
||||
= new Dictionary<string, FilePositionState>(StringComparer.OrdinalIgnoreCase);
|
||||
|
||||
/// <summary>
|
||||
/// Gets the safe read position for a file, detecting rollover/truncation.
|
||||
/// If the current file size is smaller than the stored position, the file
|
||||
/// has been rotated - resets to 0 to read from beginning.
|
||||
/// Returns 0 if no position has been recorded yet.
|
||||
/// </summary>
|
||||
// Which file each path held when last checked (see Reconcile). Apart from _positions: a file
|
||||
// whose identity is known but which no pass looked at yet must still count as unseen for
|
||||
// HasSeen. A null value means the identity could not be read.
|
||||
private readonly Dictionary<string, string> _fileIds
|
||||
= new Dictionary<string, string>(StringComparer.OrdinalIgnoreCase);
|
||||
|
||||
/// <summary>
|
||||
/// Whether this file was already observed in an earlier pass.
|
||||
/// <para>
|
||||
@@ -31,6 +31,112 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// </summary>
|
||||
public bool HasSeen(string filePath) => _positions.ContainsKey(filePath);
|
||||
|
||||
/// <summary>Whether <see cref="Reconcile"/> already looked at this path.</summary>
|
||||
public bool HasIdentity(string filePath) => _fileIds.ContainsKey(filePath);
|
||||
|
||||
/// <summary>The identity recorded for this path, or null.</summary>
|
||||
public string GetFileId(string filePath)
|
||||
{
|
||||
string id;
|
||||
return _fileIds.TryGetValue(filePath, out id) ? id : null;
|
||||
}
|
||||
|
||||
/// <summary>Restores a persisted identity. <see cref="Reconcile"/> checks it against the disk on the next pass.</summary>
|
||||
public void RestoreFileId(string filePath, string fileId)
|
||||
{
|
||||
if (fileId != null) _fileIds[filePath] = fileId;
|
||||
}
|
||||
|
||||
/// <summary>True when the file is smaller than its bookmark: it was rolled over or truncated.</summary>
|
||||
public bool IsBehindBookmark(string filePath, long currentFileSize)
|
||||
{
|
||||
FilePositionState state;
|
||||
return _positions.TryGetValue(filePath, out state) && currentFileSize < state.Position;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Brings the bookmarks in line with the files on disk. A bookmark belongs to a file, not to
|
||||
/// a name: IME rolls a log by renaming it, so a known file under a new path keeps its
|
||||
/// position and only the bytes behind it are still unread. The old path starts at 0 with
|
||||
/// whatever file it holds next, and keeps its freshness reference because that file was
|
||||
/// written since the last look. Returns the moves.
|
||||
/// <list type="bullet">
|
||||
/// <item>A file that is still at its old path as well (a hard link) moves nothing.</item>
|
||||
/// <item>A path that holds another file with no bookmark to take over starts at 0, even
|
||||
/// when the new file is longer than the old position.</item>
|
||||
/// <item>An unreadable identity (null) changes nothing, the path keeps its bookmark.</item>
|
||||
/// </list>
|
||||
/// </summary>
|
||||
public List<BookmarkMove> Reconcile(IDictionary<string, string> idByPath)
|
||||
{
|
||||
var moves = new List<BookmarkMove>();
|
||||
var claimed = new HashSet<string>(StringComparer.OrdinalIgnoreCase);
|
||||
foreach (var entry in idByPath)
|
||||
{
|
||||
if (entry.Value == null || GetFileId(entry.Key) == entry.Value) continue;
|
||||
var holder = FindBookmarkLeftBehind(entry.Value, entry.Key, idByPath);
|
||||
if (holder != null && claimed.Add(holder))
|
||||
moves.Add(new BookmarkMove(holder, entry.Key, _positions[holder].Position));
|
||||
}
|
||||
|
||||
// In two steps: a path can be source and target at once (X.log becomes _X.log while
|
||||
// _X.log's own file was replaced).
|
||||
var movedStates = new List<FilePositionState>();
|
||||
foreach (var move in moves)
|
||||
{
|
||||
var state = _positions[move.From];
|
||||
movedStates.Add(state);
|
||||
_positions[move.From] = new FilePositionState { LastCheckedUtc = state.LastCheckedUtc };
|
||||
_fileIds.Remove(move.From);
|
||||
}
|
||||
for (var i = 0; i < moves.Count; i++)
|
||||
{
|
||||
_positions[moves[i].To] = movedStates[i];
|
||||
_fileIds[moves[i].To] = idByPath[moves[i].To];
|
||||
}
|
||||
|
||||
foreach (var entry in idByPath)
|
||||
{
|
||||
if (entry.Value == null)
|
||||
{
|
||||
if (!_fileIds.ContainsKey(entry.Key)) _fileIds[entry.Key] = null;
|
||||
continue;
|
||||
}
|
||||
|
||||
string known;
|
||||
FilePositionState state;
|
||||
if (_fileIds.TryGetValue(entry.Key, out known) && known != null && known != entry.Value
|
||||
&& _positions.TryGetValue(entry.Key, out state))
|
||||
{
|
||||
state.Position = 0;
|
||||
state.LastKnownSize = 0;
|
||||
}
|
||||
_fileIds[entry.Key] = entry.Value;
|
||||
}
|
||||
|
||||
return moves;
|
||||
}
|
||||
|
||||
private string FindBookmarkLeftBehind(string fileId, string newPath, IDictionary<string, string> idByPath)
|
||||
{
|
||||
foreach (var known in _fileIds)
|
||||
{
|
||||
if (known.Value != fileId || string.Equals(known.Key, newPath, StringComparison.OrdinalIgnoreCase)) continue;
|
||||
if (!_positions.ContainsKey(known.Key)) continue;
|
||||
|
||||
string stillThere;
|
||||
if (idByPath.TryGetValue(known.Key, out stillThere) && stillThere == fileId) continue;
|
||||
return known.Key;
|
||||
}
|
||||
return null;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Gets the safe read position for a file, detecting rollover/truncation.
|
||||
/// If the current file size is smaller than the stored position, the file
|
||||
/// has been rotated - resets to 0 to read from beginning.
|
||||
/// Returns 0 if no position has been recorded yet.
|
||||
/// </summary>
|
||||
public long GetSafePosition(string filePath, long currentFileSize)
|
||||
{
|
||||
FilePositionState state;
|
||||
@@ -144,6 +250,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>One bookmark that followed its file to a new path.</summary>
|
||||
public sealed class BookmarkMove
|
||||
{
|
||||
public BookmarkMove(string from, string to, long position)
|
||||
{
|
||||
From = from;
|
||||
To = to;
|
||||
Position = position;
|
||||
}
|
||||
|
||||
public string From { get; }
|
||||
public string To { get; }
|
||||
public long Position { get; }
|
||||
}
|
||||
|
||||
public class FilePositionState
|
||||
{
|
||||
public long Position { get; set; }
|
||||
|
||||
+7
-7
@@ -225,7 +225,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
// Check against exclusion list
|
||||
if (IsExcludedUser(owner))
|
||||
{
|
||||
_logger.Debug($"DesktopArrivalDetector: explorer.exe PID {proc.Id} owned by excluded user '{owner}' — skipping");
|
||||
_logger.Debug($"DesktopArrivalDetector: explorer.exe PID {proc.Id} owned by excluded user '{owner}' — skipping", repeatKey: "DesktopArrivalDetector.excludedUser");
|
||||
|
||||
// Trace this decision once so it's visible in the backend
|
||||
if (!_excludedUserTraced)
|
||||
@@ -238,7 +238,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
$"explorer.exe found but owned by excluded user '{owner}' — not a real user desktop",
|
||||
new Dictionary<string, object> { { "pid", proc.Id }, { "session", proc.SessionId }, { "owner", owner } });
|
||||
}
|
||||
catch (Exception ex) { _logger.Verbose($"DesktopArrivalDetector: OnTraceEvent failed: {ex.Message}"); }
|
||||
catch (Exception ex) { _logger.Debug($"DesktopArrivalDetector: OnTraceEvent failed: {ex.Message}"); }
|
||||
}
|
||||
continue;
|
||||
}
|
||||
@@ -254,7 +254,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
$"Real user desktop detected (explorer.exe PID {proc.Id}, user '[redacted]')",
|
||||
new Dictionary<string, object> { { "pid", proc.Id }, { "session", proc.SessionId }, { "owner", "[redacted]" } });
|
||||
}
|
||||
catch (Exception ex) { _logger.Verbose($"DesktopArrivalDetector: OnTraceEvent failed: {ex.Message}"); }
|
||||
catch (Exception ex) { _logger.Debug($"DesktopArrivalDetector: OnTraceEvent failed: {ex.Message}"); }
|
||||
|
||||
// First-poll observability snapshot still fires before we stop polling —
|
||||
// there is value in distinguishing "found on first poll" (Stage already
|
||||
@@ -335,7 +335,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
{ "wtsErrorCount", _wtsErrorCountSinceStart },
|
||||
});
|
||||
}
|
||||
catch (Exception ex) { _logger.Verbose($"DesktopArrivalDetector: first-poll emit failed: {ex.Message}"); }
|
||||
catch (Exception ex) { _logger.Debug($"DesktopArrivalDetector: first-poll emit failed: {ex.Message}"); }
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -371,7 +371,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
{ "wtsErrorCount", _wtsErrorCountSinceStart },
|
||||
});
|
||||
}
|
||||
catch (Exception ex) { _logger.Verbose($"DesktopArrivalDetector: no-candidate emit failed: {ex.Message}"); }
|
||||
catch (Exception ex) { _logger.Debug($"DesktopArrivalDetector: no-candidate emit failed: {ex.Message}"); }
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -393,7 +393,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
{ "startReason", startReason },
|
||||
});
|
||||
}
|
||||
catch (Exception ex) { _logger.Verbose($"DesktopArrivalDetector: detector-started emit failed: {ex.Message}"); }
|
||||
catch (Exception ex) { _logger.Debug($"DesktopArrivalDetector: detector-started emit failed: {ex.Message}"); }
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -445,7 +445,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Verbose($"DesktopArrivalDetector: OOBE state check failed: {ex.Message}");
|
||||
_logger.Debug($"DesktopArrivalDetector: OOBE state check failed: {ex.Message}", repeatKey: "DesktopArrivalDetector.oobeCheckFailed");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
+3
-1
@@ -471,7 +471,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
|
||||
public void Stop()
|
||||
{
|
||||
_logger.Info("Stopping ESP and Hello tracker");
|
||||
// Hosts call Stop and then Dispose, which stops again; the second pass finds nothing.
|
||||
if (_helloTracker != null || _shellCoreTracker != null || _provisioningTracker != null || _modernDeploymentTracker != null)
|
||||
_logger.Info("Stopping ESP and Hello tracker");
|
||||
|
||||
DisposeTracker(ref _modernDeploymentTracker, "ModernDeployment", t => t.Stop());
|
||||
DisposeProvisioningTracker();
|
||||
|
||||
+1
-1
@@ -98,7 +98,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
{
|
||||
if (rootKey == null)
|
||||
{
|
||||
logger?.Debug("EspPolicyProviderProbe: EnrollmentStatusTracking registry key not found");
|
||||
logger?.Debug("EspPolicyProviderProbe: EnrollmentStatusTracking registry key not found", repeatKey: "EspPolicyProviderProbe.noTrackingKey");
|
||||
return EspPolicyProviderSnapshot.Empty;
|
||||
}
|
||||
|
||||
|
||||
+11
-8
@@ -418,7 +418,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
}
|
||||
else
|
||||
{
|
||||
_logger.Debug("Periodic Hello policy check: No WHfB policy found yet - will check again");
|
||||
_logger.Trace("Periodic Hello policy check: No WHfB policy found yet - will check again");
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -636,7 +636,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
severity = EventSeverity.Info;
|
||||
message = "Windows Hello for Business provisioned successfully - NGC key registered";
|
||||
shouldTriggerHelloCompleted = MarkHelloCompleted();
|
||||
_logger.Info("Windows Hello provisioning COMPLETED successfully");
|
||||
// A repeat (live plus backfill) is already reported by MarkHelloCompleted.
|
||||
if (shouldTriggerHelloCompleted) _logger.Info("Windows Hello provisioning COMPLETED successfully");
|
||||
break;
|
||||
|
||||
case EventId_NgcKeyRegistrationFailed: // 301
|
||||
@@ -644,7 +645,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
severity = EventSeverity.Error;
|
||||
message = "Windows Hello for Business provisioning failed - NGC key registration error";
|
||||
shouldTriggerHelloCompleted = MarkHelloCompleted();
|
||||
_logger.Info("Windows Hello provisioning COMPLETED with failure");
|
||||
if (shouldTriggerHelloCompleted) _logger.Info("Windows Hello provisioning COMPLETED with failure");
|
||||
break;
|
||||
|
||||
case EventId_ProvisioningWillNotLaunch: // 360
|
||||
@@ -658,7 +659,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
severity = EventSeverity.Warning;
|
||||
message = "Windows Hello for Business provisioning blocked";
|
||||
shouldTriggerHelloCompleted = MarkHelloCompleted();
|
||||
_logger.Info("Windows Hello provisioning COMPLETED (blocked)");
|
||||
if (shouldTriggerHelloCompleted) _logger.Info("Windows Hello provisioning COMPLETED (blocked)");
|
||||
break;
|
||||
|
||||
case EventId_PinStatus: // 376
|
||||
@@ -719,12 +720,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
|| eventType == Constants.EventTypes.DeviceRegistrationEvent
|
||||
});
|
||||
|
||||
_logger.Info($"Hello event detected: {eventType} (EventID {eventId}{(isBackfill ? ", backfill" : "")})");
|
||||
_logger.Debug($"Hello event detected: {eventType} (EventID {eventId}{(isBackfill ? ", backfill" : "")})");
|
||||
|
||||
if (shouldTriggerHelloCompleted)
|
||||
{
|
||||
EmitHelloPolicyDetectionMismatch(eventType, eventId, timestamp);
|
||||
try { HelloCompleted?.Invoke(this, EventArgs.Empty); } catch { }
|
||||
try { HelloCompleted?.Invoke(this, EventArgs.Empty); }
|
||||
catch (Exception ex) { _logger.Warning($"HelloTracker: HelloCompleted handler threw: {ex.Message}"); }
|
||||
}
|
||||
}
|
||||
|
||||
@@ -969,12 +971,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
ImmediateUpload = shouldTriggerHelloCompleted
|
||||
});
|
||||
|
||||
_logger.Info($"HelloForBusiness event detected: {eventType} (EventID {eventId}{(isBackfill ? ", backfill" : "")})");
|
||||
_logger.Debug($"HelloForBusiness event detected: {eventType} (EventID {eventId}{(isBackfill ? ", backfill" : "")})");
|
||||
|
||||
if (shouldTriggerHelloCompleted)
|
||||
{
|
||||
EmitHelloPolicyDetectionMismatch(eventType, eventId, timestamp);
|
||||
try { HelloCompleted?.Invoke(this, EventArgs.Empty); } catch { }
|
||||
try { HelloCompleted?.Invoke(this, EventArgs.Empty); }
|
||||
catch (Exception ex) { _logger.Warning($"HelloTracker: HelloCompleted handler threw: {ex.Message}"); }
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
+2
-2
@@ -545,7 +545,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
|
||||
if (description.IndexOf("WhiteGlove", StringComparison.OrdinalIgnoreCase) < 0)
|
||||
{
|
||||
_logger.Trace($"ManagementService Event 509 without WhiteGlove keyword — ignoring: {description}");
|
||||
_logger.Debug($"ManagementService Event 509 without WhiteGlove keyword — ignoring: {description}", repeatKey: "ModernDeploymentTracker.nonWhiteGlove509");
|
||||
return;
|
||||
}
|
||||
|
||||
@@ -624,7 +624,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
using (record)
|
||||
{
|
||||
found++;
|
||||
_logger.Info($"Backfill found ManagementService Event {record.Id} at {record.TimeCreated:O}");
|
||||
_logger.Debug($"Backfill found ManagementService Event {record.Id} at {record.TimeCreated:O}");
|
||||
ProcessRecord(record, "ManagementService", ManagementChannel, isBackfill: true);
|
||||
}
|
||||
}
|
||||
|
||||
+6
-3
@@ -97,7 +97,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
hasValues: entries.Any(e => !oobeOnly || IsOobeName(e.Key)), line: line);
|
||||
}
|
||||
|
||||
/// <summary>One agent.log line per present key, one naming the absent keys.</summary>
|
||||
/// <summary>
|
||||
/// One agent.log line per present key, one naming the absent keys. Debug: registry detail
|
||||
/// behind the update page; the oobe_update_state event carries the content.
|
||||
/// </summary>
|
||||
public static void Log(AgentLogger logger, string moment, IReadOnlyList<KeyState> states)
|
||||
{
|
||||
if (logger == null || states == null) return;
|
||||
@@ -110,11 +113,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
absent.Add(state.Path);
|
||||
continue;
|
||||
}
|
||||
logger.Info($"OOBE update registry ({moment}): HKLM\\{state.Path}: {state.Line}");
|
||||
logger.Debug($"OOBE update registry ({moment}): HKLM\\{state.Path}: {state.Line}");
|
||||
}
|
||||
|
||||
if (absent.Count > 0)
|
||||
logger.Info($"OOBE update registry ({moment}): absent: {string.Join(", ", absent)}");
|
||||
logger.Debug($"OOBE update registry ({moment}): absent: {string.Join(", ", absent)}");
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
|
||||
+8
-11
@@ -514,13 +514,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
changedCount++;
|
||||
bool isNew = !_lastProvisioningJson.ContainsKey(categoryName);
|
||||
// Guard: the raw-JSON interpolation is materialized regardless of log
|
||||
// level (Trace() only drops the string after it is built), and this runs
|
||||
// per changed category every poll — skip the alloc when Trace is off.
|
||||
if (_logger.LogLevel >= AgentLogLevel.Trace)
|
||||
{
|
||||
_logger.Trace($"CheckProvisioningStatus: {categoryName} — {(isNew ? "NEW" : "CHANGED")} (json length={jsonValue.Length})");
|
||||
_logger.Trace($"CheckProvisioningStatus: {categoryName} — raw JSON: {jsonValue}");
|
||||
}
|
||||
// level (Verbose() only drops the string after it is built), and this runs
|
||||
// per changed category every poll — skip the alloc when Verbose is off.
|
||||
if (_logger.LogLevel >= AgentLogLevel.Verbose)
|
||||
_logger.Verbose($"CheckProvisioningStatus: {categoryName} {(isNew ? "new" : "changed")}, raw JSON: {jsonValue}");
|
||||
|
||||
_lastProvisioningJson[categoryName] = jsonValue;
|
||||
// TryFireProvisioningFailure (inside ProcessCategoryStatus) arms the
|
||||
@@ -1007,7 +1004,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
bool isFirstSeen = !_provisioningCategorySeen.Contains(categoryName);
|
||||
bool categorySucceededChanged = HasCategorySucceededChanged(categoryName, categorySucceeded);
|
||||
|
||||
_logger.Trace($"ProcessCategory: {categoryLabel} — succeeded={categorySucceeded?.ToString() ?? "null"}, " +
|
||||
_logger.Verbose($"ProcessCategory: {categoryLabel} — succeeded={categorySucceeded?.ToString() ?? "null"}, " +
|
||||
$"isFirstSeen={isFirstSeen}, succeededChanged={categorySucceededChanged}, " +
|
||||
$"subcategories={subcategories.Count} [{string.Join(", ", subcategories.Select(s => $"{s.Name}={s.State}"))}]");
|
||||
|
||||
@@ -1050,7 +1047,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
var failureTransitions = transitions.Where(t => t.IsFailure).ToList();
|
||||
if (transitions.Count > 0)
|
||||
{
|
||||
_logger.Trace($"ProcessCategory: {categoryLabel} — subcategory transitions: " +
|
||||
_logger.Debug($"ProcessCategory: {categoryLabel} — subcategory transitions: " +
|
||||
string.Join(", ", transitions.Select(t => $"{t.SubcategoryName}: {t.OldState}→{t.NewState} (failure={t.IsFailure})")));
|
||||
}
|
||||
|
||||
@@ -1115,7 +1112,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
|
||||
var errorCode = TryExtractErrorCode(failedSubcategoryInfo?.StatusText);
|
||||
|
||||
_logger.Info(
|
||||
_logger.Debug(
|
||||
$"Provisioning subcategory failure: {categoryLabel}/{failedSubcategoryName ?? "category-level"} — " +
|
||||
$"escalating as {failureTypeName} (errorCode={errorCode ?? "n/a"})");
|
||||
_logger.Warning($"Provisioning failure detected: {failureTypeName}");
|
||||
@@ -1886,7 +1883,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
Data = eventData
|
||||
});
|
||||
|
||||
_logger.Info($"Provisioning status event: {categoryLabel} — {statusText} (succeeded={succeeded?.ToString() ?? "in_progress"})");
|
||||
_logger.Info($"Provisioning status event: {categoryLabel} — {statusText} (succeeded={succeeded?.ToString() ?? "in_progress"})", repeatKey: "ProvisioningStatus.event:" + categoryLabel);
|
||||
}
|
||||
|
||||
private void EmitRawRegistryDump(string categoryLabel, string rawJson, string trigger)
|
||||
|
||||
+15
-11
@@ -266,24 +266,27 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
{
|
||||
try
|
||||
{
|
||||
var stoppedAny = false;
|
||||
lock (_stateLock)
|
||||
{
|
||||
DisposeAndNull(ref _servicesAppearanceWatcher);
|
||||
DisposeAndNull(ref _machineSoftwareAppearanceWatcher);
|
||||
DisposeAndNull(ref _userSoftwareAppearanceWatcher);
|
||||
DisposeAndNull(ref _uninstallAppearanceWatcher);
|
||||
stoppedAny |= DisposeAndNull(ref _servicesAppearanceWatcher);
|
||||
stoppedAny |= DisposeAndNull(ref _machineSoftwareAppearanceWatcher);
|
||||
stoppedAny |= DisposeAndNull(ref _userSoftwareAppearanceWatcher);
|
||||
stoppedAny |= DisposeAndNull(ref _uninstallAppearanceWatcher);
|
||||
|
||||
_serviceRealmjoinDebounce?.Dispose(); _serviceRealmjoinDebounce = null;
|
||||
_machineRealmJoinDebounce?.Dispose(); _machineRealmJoinDebounce = null;
|
||||
_userRealmJoinDebounce?.Dispose(); _userRealmJoinDebounce = null;
|
||||
_uninstallDebounce?.Dispose(); _uninstallDebounce = null;
|
||||
|
||||
DisposeAndNull(ref _serviceRealmjoinWatcher);
|
||||
DisposeAndNull(ref _machineRealmJoinWatcher);
|
||||
DisposeAndNull(ref _userRealmJoinWatcher);
|
||||
DisposeAndNull(ref _uninstallWatcher);
|
||||
stoppedAny |= DisposeAndNull(ref _serviceRealmjoinWatcher);
|
||||
stoppedAny |= DisposeAndNull(ref _machineRealmJoinWatcher);
|
||||
stoppedAny |= DisposeAndNull(ref _userRealmJoinWatcher);
|
||||
stoppedAny |= DisposeAndNull(ref _uninstallWatcher);
|
||||
}
|
||||
_logger.Info($"RealmJoinWatcher: stopped ({reason})");
|
||||
// Hosts call Stop and then Dispose, which stops again; only the pass that
|
||||
// stopped a watcher logs.
|
||||
if (stoppedAny) _logger.Info($"RealmJoinWatcher: stopped ({reason})");
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
@@ -913,11 +916,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
}
|
||||
}
|
||||
|
||||
private static void DisposeAndNull(ref RegistryWatcher? w)
|
||||
private static bool DisposeAndNull(ref RegistryWatcher? w)
|
||||
{
|
||||
if (w == null) return;
|
||||
if (w == null) return false;
|
||||
try { w.Dispose(); } catch { }
|
||||
w = null;
|
||||
return true;
|
||||
}
|
||||
|
||||
// Test seams — drive the read paths deterministically without touching the real registry.
|
||||
|
||||
+1
-1
@@ -384,7 +384,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
ImmediateUpload = true
|
||||
});
|
||||
|
||||
_logger.Info($"Shell-Core event detected: {eventType} (EventID {eventId})");
|
||||
_logger.Debug($"Shell-Core event detected: {eventType} (EventID {eventId})");
|
||||
|
||||
// Set the source-event timestamp BEFORE each event raise so adapters / coordinators
|
||||
// can read it during their synchronous handler. Cleared in finally so a stale value
|
||||
|
||||
+1
-1
@@ -568,7 +568,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Trace($"StallProbeCollector: eventlog scan of {channel} failed: {ex.Message}");
|
||||
_logger.Debug($"StallProbeCollector: eventlog scan of {channel} failed: {ex.Message}", repeatKey: "StallProbeCollector.scanFailed:" + channel);
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -9,6 +9,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Interop
|
||||
/// Win32 file-handle declarations for <c>PinnedSourceFolder</c>: open a file or directory
|
||||
/// without following a reparse point at its final component, and ask the handle where it
|
||||
/// really points (<c>GetFinalPathNameByHandle</c>) instead of trusting the path string.
|
||||
/// <c>ImeLogFileIdentity</c> reads a file's identity through the same declarations.
|
||||
/// </summary>
|
||||
internal static class FileNativeMethods
|
||||
{
|
||||
@@ -18,6 +19,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Interop
|
||||
|
||||
public const uint FILE_SHARE_READ = 0x1;
|
||||
public const uint FILE_SHARE_WRITE = 0x2;
|
||||
public const uint FILE_SHARE_DELETE = 0x4;
|
||||
|
||||
public const uint OPEN_EXISTING = 3;
|
||||
|
||||
|
||||
+5
-5
@@ -344,7 +344,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
_logger.Info($"Diagnostics package created: {zipFileName} ({zipBytes.Length / 1024} KB)");
|
||||
|
||||
// Fetch a short-lived upload URL just before uploading — never stored in config or on disk
|
||||
_logger.Info("Requesting diagnostics upload URL from backend...");
|
||||
_logger.Debug("Requesting diagnostics upload URL from backend...");
|
||||
var uploadUrlResponse = await _apiClient.GetDiagnosticsUploadUrlAsync(
|
||||
_configuration.TenantId,
|
||||
_configuration.SessionId,
|
||||
@@ -708,7 +708,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
// Expected outcome, not a packaging problem: the subtree is off limits by design.
|
||||
foreach (var refused in refusedDirectories)
|
||||
{
|
||||
_logger.Info($"Diagnostics subfolder skipped by guard: {refused}");
|
||||
_logger.Debug($"Diagnostics subfolder skipped by guard: {refused}");
|
||||
ManifestLine($"SKIPPED DIR (path guard): {refused}");
|
||||
}
|
||||
|
||||
@@ -800,7 +800,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
}
|
||||
|
||||
tracker.RecordIncluded(length);
|
||||
_logger.Debug($"Added to diagnostics package: {entryName} ({length / 1024} KB)");
|
||||
_logger.Verbose($"Added to diagnostics package: {entryName} ({length / 1024} KB)");
|
||||
ManifestLine($"ADDED: {entryName} ({length} bytes)");
|
||||
}
|
||||
}
|
||||
@@ -1066,7 +1066,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
{
|
||||
try
|
||||
{
|
||||
_logger.Info($"Uploading diagnostics package (attempt {attempt}/{maxRetries}, {data.Length / 1024} KB)...");
|
||||
_logger.Debug($"Uploading diagnostics package (attempt {attempt}/{maxRetries}, {data.Length / 1024} KB)...");
|
||||
|
||||
using var content = new ByteArrayContent(data);
|
||||
content.Headers.Add("x-ms-blob-type", "BlockBlob");
|
||||
@@ -1101,7 +1101,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
if (attempt < maxRetries)
|
||||
{
|
||||
var delay = TimeSpan.FromSeconds(Math.Pow(2, attempt)); // 2s, 4s, 8s
|
||||
_logger.Info($"Retrying blob upload in {delay.TotalSeconds}s...");
|
||||
_logger.Debug($"Retrying blob upload in {delay.TotalSeconds}s...");
|
||||
await Task.Delay(delay);
|
||||
}
|
||||
}
|
||||
|
||||
+1
-1
@@ -97,7 +97,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
var dedupKey = BuildDedupKey(action);
|
||||
if (!_seenActionIds.TryAdd(dedupKey, 0))
|
||||
{
|
||||
_logger.Debug($"ServerActionDispatcher: duplicate action '{action.Type}' ({dedupKey}) — skipping");
|
||||
_logger.Debug($"ServerActionDispatcher: duplicate action '{action.Type}' ({dedupKey}) — skipping", repeatKey: "ServerActionDispatcher.duplicate:" + dedupKey);
|
||||
continue;
|
||||
}
|
||||
|
||||
|
||||
+7
-7
@@ -50,7 +50,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
using (explorerProcess)
|
||||
{
|
||||
sessionId = (uint)explorerProcess.SessionId;
|
||||
logger.Info($"UserSessionProcessLauncher: Found explorer.exe PID {explorerProcess.Id} in session {sessionId}");
|
||||
logger.Debug($"UserSessionProcessLauncher: Found explorer.exe PID {explorerProcess.Id} in session {sessionId}");
|
||||
}
|
||||
|
||||
// Get the interactive session token via WTS.
|
||||
@@ -80,7 +80,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
return false;
|
||||
}
|
||||
|
||||
logger.Info($"UserSessionProcessLauncher: Token duplicated and stamped to session {sessionId}");
|
||||
logger.Debug($"UserSessionProcessLauncher: Token duplicated and stamped to session {sessionId}");
|
||||
|
||||
// Create an environment block for the user (using session-stamped token)
|
||||
if (!ProcessNativeMethods.CreateEnvironmentBlock(out environment, dupToken, false))
|
||||
@@ -121,7 +121,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
{
|
||||
cxhProcess = FindProcessInSession("CloudExperienceHost", sessionId);
|
||||
if (cxhProcess != null)
|
||||
logger.Info($"UserSessionProcessLauncher: CloudExperienceHost PID {cxhProcess.Id} running " +
|
||||
logger.Debug($"UserSessionProcessLauncher: CloudExperienceHost PID {cxhProcess.Id} running " +
|
||||
$"in session {sessionId} — will monitor for exit during retries");
|
||||
}
|
||||
catch { }
|
||||
@@ -162,7 +162,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
}
|
||||
|
||||
ProcessNativeMethods.CloseHandle(pi.hThread);
|
||||
logger.Info($"UserSessionProcessLauncher: Attempt {attempt} — created PID {pi.dwProcessId}" +
|
||||
logger.Debug($"UserSessionProcessLauncher: Attempt {attempt} — created PID {pi.dwProcessId}" +
|
||||
$" [{(useExplicitDesktop ? "explicit" : "default")} desktop], verifying startup...");
|
||||
|
||||
// Wait 3s to verify the process survives DLL init + CLR bootstrap.
|
||||
@@ -190,10 +190,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
// On 23H2: CXH never exits → WaitForExit times out → same as regular retry interval.
|
||||
if (cxhProcess != null)
|
||||
{
|
||||
logger.Info($"UserSessionProcessLauncher: Attempt {attempt} — 0x8007045A, waiting for CXH exit (up to {retryIntervalSeconds}s)...");
|
||||
logger.Debug($"UserSessionProcessLauncher: Attempt {attempt} — 0x8007045A, waiting for CXH exit (up to {retryIntervalSeconds}s)...");
|
||||
if (cxhProcess.WaitForExit(retryIntervalSeconds * 1000))
|
||||
{
|
||||
logger.Info("UserSessionProcessLauncher: CloudExperienceHost exited — desktop should be available");
|
||||
logger.Debug("UserSessionProcessLauncher: CloudExperienceHost exited — desktop should be available");
|
||||
cxhProcess.Dispose();
|
||||
cxhProcess = null;
|
||||
System.Threading.Thread.Sleep(500); // brief delay for desktop init
|
||||
@@ -201,7 +201,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
}
|
||||
else
|
||||
{
|
||||
logger.Info($"UserSessionProcessLauncher: Attempt {attempt} — 0x8007045A (desktop locked?) — retrying in {retryIntervalSeconds}s...");
|
||||
logger.Debug($"UserSessionProcessLauncher: Attempt {attempt} — 0x8007045A (desktop locked?) — retrying in {retryIntervalSeconds}s...");
|
||||
System.Threading.Thread.Sleep(retryIntervalSeconds * 1000);
|
||||
}
|
||||
continue;
|
||||
|
||||
+2
-2
@@ -81,7 +81,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
/// <summary>Final-shutdown scan — captures any AutoLogon written during the user phase.</summary>
|
||||
public void AnalyzeAtShutdown()
|
||||
{
|
||||
_logger.Info($"{Name}: Running shutdown AutoLogon scan");
|
||||
_logger.Debug($"{Name}: Running shutdown AutoLogon scan");
|
||||
RunScan("shutdown");
|
||||
}
|
||||
|
||||
@@ -91,7 +91,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
/// </summary>
|
||||
public void AnalyzeAtDeviceSetupComplete()
|
||||
{
|
||||
_logger.Info($"{Name}: Running device-setup-complete AutoLogon scan");
|
||||
_logger.Debug($"{Name}: Running device-setup-complete AutoLogon scan");
|
||||
RunScan("device_setup_complete");
|
||||
}
|
||||
|
||||
|
||||
+1
-1
@@ -81,7 +81,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
|
||||
public void AnalyzeAtStartup()
|
||||
{
|
||||
_logger.Info($"{Name}: scanning prefetch for a post-boot cmd.exe console artifact");
|
||||
_logger.Debug($"{Name}: scanning prefetch for a post-boot cmd.exe console artifact");
|
||||
try { RunScan(); }
|
||||
catch (Exception ex) { _logger.Error($"{Name}: scan failed unexpectedly", ex); }
|
||||
}
|
||||
|
||||
+1
-1
@@ -80,7 +80,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
|
||||
public void AnalyzeAtStartup()
|
||||
{
|
||||
_logger.Info($"{Name}: Running startup analysis");
|
||||
_logger.Debug($"{Name}: Running startup analysis");
|
||||
RunAnalysis("startup");
|
||||
}
|
||||
|
||||
|
||||
+2
-2
@@ -114,13 +114,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
|
||||
public void AnalyzeAtStartup()
|
||||
{
|
||||
_logger.Info($"{Name}: Running startup analysis");
|
||||
_logger.Debug($"{Name}: Running startup analysis");
|
||||
RunAnalysis("startup", EnrollmentPhase.Unknown);
|
||||
}
|
||||
|
||||
public void AnalyzeAtShutdown()
|
||||
{
|
||||
_logger.Info($"{Name}: Running shutdown analysis");
|
||||
_logger.Debug($"{Name}: Running shutdown analysis");
|
||||
|
||||
// At shutdown a user has logged in — their profile folder is expected. Detect logged-in
|
||||
// users via explorer.exe owner (same technique as DesktopArrivalDetector); RunAnalysis
|
||||
|
||||
+5
-5
@@ -92,7 +92,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
|
||||
public void AnalyzeAtStartup()
|
||||
{
|
||||
_logger.Info($"{Name}: Running startup analysis (baseline inventory)");
|
||||
_logger.Debug($"{Name}: Running startup analysis (baseline inventory)");
|
||||
try
|
||||
{
|
||||
// The collection ALWAYS runs — _startupInventory is the in-memory base for the
|
||||
@@ -106,7 +106,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
Constants.EventTypes.SoftwareInventoryAnalysis + ":startup",
|
||||
BuildInventoryFingerprint(_startupInventory)))
|
||||
{
|
||||
_logger.Info($"{Name}: baseline inventory unchanged since last emission — startup events suppressed (restart dedup), delta base kept in memory");
|
||||
_logger.Debug($"{Name}: baseline inventory unchanged since last emission — startup events suppressed (restart dedup), delta base kept in memory");
|
||||
return;
|
||||
}
|
||||
|
||||
@@ -156,7 +156,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
{
|
||||
if (Interlocked.CompareExchange(ref _part1ShutdownSnapshotEmitted, 1, 0) != 0)
|
||||
{
|
||||
_logger.Info($"{Name}: AnalyzeAtShutdown(whiteGlovePart=1) skipped — Part-1 snapshot already emitted (likely by WhiteGloveInventoryTrigger)");
|
||||
_logger.Debug($"{Name}: AnalyzeAtShutdown(whiteGlovePart=1) skipped — Part-1 snapshot already emitted (likely by WhiteGloveInventoryTrigger)");
|
||||
return;
|
||||
}
|
||||
}
|
||||
@@ -164,12 +164,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
{
|
||||
if (Interlocked.CompareExchange(ref _part2ShutdownSnapshotEmitted, 1, 0) != 0)
|
||||
{
|
||||
_logger.Info($"{Name}: AnalyzeAtShutdown(whiteGlovePart=2) skipped — Part-2 snapshot already emitted");
|
||||
_logger.Debug($"{Name}: AnalyzeAtShutdown(whiteGlovePart=2) skipped — Part-2 snapshot already emitted");
|
||||
return;
|
||||
}
|
||||
}
|
||||
|
||||
_logger.Info($"{Name}: Running shutdown analysis (delta detection, whiteGlovePart={whiteGlovePart?.ToString() ?? "none"})");
|
||||
_logger.Debug($"{Name}: Running shutdown analysis (delta detection, whiteGlovePart={whiteGlovePart?.ToString() ?? "none"})");
|
||||
try
|
||||
{
|
||||
var currentInventory = CollectAndNormalize();
|
||||
|
||||
@@ -62,9 +62,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry
|
||||
/// <summary>Stops the collection timer without disposing the collector.</summary>
|
||||
public void Stop()
|
||||
{
|
||||
// Hosts call Stop and then Dispose, which stops again; only a running timer logs.
|
||||
var wasRunning = _timer != null;
|
||||
_timer?.Dispose();
|
||||
_timer = null;
|
||||
Logger.Info($"[{GetType().Name}] Stopped");
|
||||
if (wasRunning) Logger.Info($"[{GetType().Name}] Stopped");
|
||||
OnAfterStop();
|
||||
}
|
||||
|
||||
@@ -117,7 +119,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry
|
||||
// duration of any single slow Collect.
|
||||
if (Interlocked.CompareExchange(ref _collecting, 1, 0) != 0)
|
||||
{
|
||||
Logger.Debug($"[{GetType().Name}] tick skipped — previous Collect still running");
|
||||
Logger.Trace($"[{GetType().Name}] tick skipped — previous Collect still running");
|
||||
return;
|
||||
}
|
||||
|
||||
|
||||
+7
-7
@@ -209,7 +209,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
default: modeLabel = $"{autopilotMode}"; break;
|
||||
}
|
||||
data["autopilotModeLabel"] = modeLabel;
|
||||
_logger.Info($"EnrollmentTracker: AutopilotMode={autopilotMode} ({modeLabel})");
|
||||
_logger.Info($"EnrollmentTracker: AutopilotMode={autopilotMode} ({modeLabel})", repeatKey: "DeviceInfo.autopilotMode");
|
||||
}
|
||||
|
||||
// --- Interpret CloudAssignedDomainJoinMethod ---
|
||||
@@ -238,7 +238,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Trace($"EnrollmentTracker: Failed to parse PolicyJsonCache for DomainJoinMethod: {ex.Message}");
|
||||
_logger.Debug($"EnrollmentTracker: Failed to parse PolicyJsonCache for DomainJoinMethod: {ex.Message}");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -261,10 +261,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
|
||||
if (isHybridJoin)
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: Hybrid Azure AD Join profile detected");
|
||||
_logger.Info("EnrollmentTracker: Hybrid Azure AD Join profile detected", repeatKey: "DeviceInfo.hybridProfile");
|
||||
}
|
||||
|
||||
_logger.Info($"EnrollmentTracker: Read {data.Count} values from AutopilotPolicyCache");
|
||||
_logger.Info($"EnrollmentTracker: Read {data.Count} values from AutopilotPolicyCache", repeatKey: "DeviceInfo.policyCache");
|
||||
}
|
||||
else
|
||||
{
|
||||
@@ -390,7 +390,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
{ "detectionRule", detectionRule }
|
||||
});
|
||||
|
||||
_logger.Info($"EnrollmentTracker: enrollment type detected: {detectedType}");
|
||||
_logger.Info($"EnrollmentTracker: enrollment type detected: {detectedType}", repeatKey: "DeviceInfo.enrollmentType");
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
@@ -810,7 +810,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
if (hasAnyEspEvidence)
|
||||
{
|
||||
var summary = BuildSummary(snapshot, tracking);
|
||||
_logger.Info($"EnrollmentTracker: ESP configuration detected — {summary}");
|
||||
_logger.Info($"EnrollmentTracker: ESP configuration detected — {summary}", repeatKey: "DeviceInfo.espConfig");
|
||||
EmitDeviceInfoEvent(Constants.EventTypes.EspConfigDetected, $"ESP configuration: {summary}", data);
|
||||
PostEspConfigDetectedSignal(snapshot);
|
||||
}
|
||||
@@ -1004,7 +1004,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
var fingerprint = Persistence.StartupEventGate.ComputeFingerprint(data, excludedFields);
|
||||
if (_startupGate.ShouldEmit(eventType, fingerprint)) return true;
|
||||
|
||||
_logger.Debug($"EnrollmentTracker: '{eventType}' suppressed — payload unchanged since last emission (restart dedup)");
|
||||
_logger.Debug($"EnrollmentTracker: '{eventType}' suppressed — payload unchanged since last emission (restart dedup)", repeatKey: "DeviceInfo.unchanged:" + eventType);
|
||||
return false;
|
||||
}
|
||||
|
||||
|
||||
+4
-4
@@ -89,7 +89,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
/// </summary>
|
||||
public (string enrollmentType, bool isHybridJoin, bool? skipUserStatusPage, bool? skipDeviceStatusPage, int? autopilotMode, bool hasAadJoinedUser, bool isFooUserDetected) CollectAll()
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: collecting device info (at start)");
|
||||
_logger.Debug("EnrollmentTracker: collecting device info (at start)");
|
||||
|
||||
CollectOSInfoAndBootTime();
|
||||
CollectNetworkAndDnsConfiguration();
|
||||
@@ -113,7 +113,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
/// </summary>
|
||||
public void CollectAtEnrollmentStart()
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: collecting device info (at enrollment start)");
|
||||
_logger.Debug("EnrollmentTracker: collecting device info (at enrollment start)");
|
||||
|
||||
CollectAadJoinStatus();
|
||||
CollectAutopilotProfile();
|
||||
@@ -134,7 +134,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
/// </summary>
|
||||
public void RefreshEspConfiguration(string trigger)
|
||||
{
|
||||
_logger.Info($"EnrollmentTracker: re-collecting ESP configuration (trigger={trigger})");
|
||||
_logger.Debug($"EnrollmentTracker: re-collecting ESP configuration (trigger={trigger})");
|
||||
CollectEspConfiguration();
|
||||
}
|
||||
|
||||
@@ -144,7 +144,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
/// </summary>
|
||||
public void CollectAtEnd()
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: collecting device info (at end)");
|
||||
_logger.Debug("EnrollmentTracker: collecting device info (at end)");
|
||||
|
||||
// BitLocker can be enabled during enrollment via policy
|
||||
CollectBitLockerStatus();
|
||||
|
||||
+1
-1
@@ -171,7 +171,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
values[valueName] = value.ToString();
|
||||
}
|
||||
|
||||
logger.Info($"ZtdEvidence: read {values.Count} values from Diagnostics\\Autopilot");
|
||||
logger.Info($"ZtdEvidence: read {values.Count} values from Diagnostics\\Autopilot", repeatKey: "ZtdEvidence.read");
|
||||
return values.Count > 0 ? values : null;
|
||||
}
|
||||
}
|
||||
|
||||
+3
-3
@@ -130,7 +130,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors
|
||||
var resolvedPaths = ResolveLogPaths(filePath, rule.RuleId, context);
|
||||
if (resolvedPaths.Count == 0)
|
||||
{
|
||||
context.Logger.Debug($"LogParser rule {rule.RuleId}: no files found for: {filePath}");
|
||||
context.Logger.Debug($"LogParser rule {rule.RuleId}: no files found for: {filePath}", repeatKey: "LogParserCollector.noFiles:" + rule.RuleId + "|" + filePath);
|
||||
context.DebugLog(rule.RuleId, GatherRuleDebugLog.StageLogParser,
|
||||
$"no files matched target {filePath}" + (HasWildcard(Path.GetFileName(filePath)) ? " (wildcard)" : "") + " — nothing to parse");
|
||||
return null;
|
||||
@@ -456,7 +456,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors
|
||||
state.CommitLogPosition(rule.RuleId, filePath, endPosition, lineNumberBase + committedLines, head, heldTailStart);
|
||||
|
||||
if (matchCount > 0)
|
||||
context.Logger.Debug($"LogParser rule {rule.RuleId}: {matchCount} matches from {linesRead} lines in {fileName}");
|
||||
context.Logger.Verbose($"LogParser rule {rule.RuleId}: {matchCount} matches from {linesRead} lines in {fileName}");
|
||||
|
||||
// Per-file outcome — always written so a "matched 0" run is visible too.
|
||||
context.DebugLog(rule.RuleId, GatherRuleDebugLog.StageLogParser,
|
||||
@@ -496,7 +496,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors
|
||||
}
|
||||
else if (start == LogReadStart.Replaced)
|
||||
{
|
||||
context.Logger.Info($"LogParser rule {rule.RuleId}: {fileName} was replaced since the last read — reading it from the beginning");
|
||||
context.Logger.Debug($"LogParser rule {rule.RuleId}: {fileName} was replaced since the last read — reading it from the beginning");
|
||||
context.DebugLog(rule.RuleId, GatherRuleDebugLog.StageLogParser,
|
||||
$"{fileName}: file start changed since the last read (replaced or rewritten) — saved position {known.Position} discarded, reading from the beginning");
|
||||
}
|
||||
|
||||
+8
-8
@@ -261,7 +261,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
interval
|
||||
);
|
||||
_intervalTimers[intervalRule.RuleId] = timer;
|
||||
_logger.Info($" Interval rule {intervalRule.RuleId} scheduled every {intervalRule.IntervalSeconds}s");
|
||||
_logger.Debug($" Interval rule {intervalRule.RuleId} scheduled every {intervalRule.IntervalSeconds}s");
|
||||
DebugLog(intervalRule.RuleId, GatherRuleDebugLog.StageTrigger,
|
||||
$"interval timer scheduled every {intervalRule.IntervalSeconds}s (first run after one full interval — no immediate execution)");
|
||||
}
|
||||
@@ -321,7 +321,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
continue;
|
||||
}
|
||||
|
||||
_logger.Info($"Phase exit triggered rule {rule.RuleId} (left phase: {previousPhaseName}, now: {phaseName})");
|
||||
_logger.Debug($"Phase exit triggered rule {rule.RuleId} (left phase: {previousPhaseName}, now: {phaseName})");
|
||||
exitRules.Add(rule);
|
||||
}
|
||||
}
|
||||
@@ -374,7 +374,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
foreach (var rule in deferredStartup)
|
||||
{
|
||||
var deferredRule = rule;
|
||||
_logger.Info($"Phase {phaseName} activated deferred startup rule {deferredRule.RuleId}");
|
||||
_logger.Debug($"Phase {phaseName} activated deferred startup rule {deferredRule.RuleId}");
|
||||
DebugLog(deferredRule.RuleId, GatherRuleDebugLog.StageTrigger,
|
||||
$"phase {phaseName} activated deferred startup rule");
|
||||
ThreadPool.QueueUserWorkItem(_ => ExecuteRule(deferredRule));
|
||||
@@ -405,7 +405,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
continue;
|
||||
}
|
||||
|
||||
_logger.Info($"Phase change triggered rule {rule.RuleId} (phase: {phaseName})");
|
||||
_logger.Debug($"Phase change triggered rule {rule.RuleId} (phase: {phaseName})");
|
||||
DebugLog(rule.RuleId, GatherRuleDebugLog.StageTrigger, $"phase_change to {phaseName} fired");
|
||||
ThreadPool.QueueUserWorkItem(_ => ExecuteRule(rule));
|
||||
}
|
||||
@@ -450,7 +450,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
continue;
|
||||
}
|
||||
|
||||
_logger.Info($"Event triggered rule {rule.RuleId} (event: {eventType})");
|
||||
_logger.Debug($"Event triggered rule {rule.RuleId} (event: {eventType})");
|
||||
DebugLog(rule.RuleId, GatherRuleDebugLog.StageTrigger, $"on_event {eventType} fired");
|
||||
ThreadPool.QueueUserWorkItem(_ => ExecuteRule(rule));
|
||||
}
|
||||
@@ -461,7 +461,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
{
|
||||
try
|
||||
{
|
||||
_logger.Info($"Executing gather rule: {rule.RuleId} ({rule.Title})");
|
||||
_logger.Info($"Executing gather rule: {rule.RuleId} ({rule.Title})", repeatKey: "GatherRuleExecutor.exec:" + rule.RuleId);
|
||||
DebugLog(rule.RuleId, GatherRuleDebugLog.StageExec, $"executing: collector={rule.CollectorType}, target={rule.Target}");
|
||||
|
||||
var collectorType = rule.CollectorType?.ToLower();
|
||||
@@ -673,7 +673,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
&& (int)_currentPhase >= (int)fromPhase)
|
||||
{
|
||||
_fromPhaseLatched.Add(rule.RuleId);
|
||||
_logger.Info($"Gather rule {rule.RuleId}: from-phase scope latched at {_currentPhase} (activeFromPhase={rule.ActiveFromPhase})");
|
||||
_logger.Debug($"Gather rule {rule.RuleId}: from-phase scope latched at {_currentPhase} (activeFromPhase={rule.ActiveFromPhase})");
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -755,7 +755,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
}
|
||||
|
||||
if (!emit)
|
||||
_logger.Debug($"Gather rule {rule.RuleId}: result unchanged, emit suppressed (on_change)");
|
||||
_logger.Trace($"Gather rule {rule.RuleId}: result unchanged, emit suppressed (on_change)");
|
||||
return emit;
|
||||
}
|
||||
|
||||
|
||||
+1
-1
@@ -356,7 +356,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
{
|
||||
var oldest = files.OrderBy(file => file.Value.LastTouched).First();
|
||||
files.Remove(oldest.Key);
|
||||
_logger.Info($"GatherRuleSessionState: rule {ruleId} tracks more than {MaxLogFilesPerRule} files — forgot the position of {Path.GetFileName(oldest.Key)}");
|
||||
_logger.Debug($"GatherRuleSessionState: rule {ruleId} tracks more than {MaxLogFilesPerRule} files — forgot the position of {Path.GetFileName(oldest.Key)}");
|
||||
}
|
||||
|
||||
private static string Prefix(string hash) => hash.Length > 8 ? hash.Substring(0, 8) : hash;
|
||||
|
||||
+1
-1
@@ -91,7 +91,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Debug($"[{SourceName}] failed to save state: {ex.Message}");
|
||||
_logger.Debug($"[{SourceName}] failed to save state: {ex.Message}", repeatKey: "GatherRuleStatePersistence.save:" + SourceName);
|
||||
return false;
|
||||
}
|
||||
}
|
||||
|
||||
+1
-1
@@ -196,7 +196,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office
|
||||
var leaf = Path.GetFileName(relativeName);
|
||||
if (!string.IsNullOrEmpty(leaf) && _binaries.Contains(leaf))
|
||||
{
|
||||
_logger.Info($"[OfficeBinaryWatcher] core Office binary appeared: {leaf}");
|
||||
_logger.Info($"[OfficeBinaryWatcher] core Office binary appeared: {leaf}", repeatKey: "OfficeBinaryWatcher.appeared:" + leaf);
|
||||
Raise();
|
||||
}
|
||||
}
|
||||
|
||||
+1
-1
@@ -194,7 +194,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office
|
||||
{
|
||||
// Debounce: C2R may start another short-lived worker after a small gap. Only
|
||||
// close the window if none reappears within the settle period.
|
||||
_logger.Debug($"[OfficeProcessWatcher] last worker exited — settling {_settleSeconds}s before closing the install window");
|
||||
_logger.Trace($"[OfficeProcessWatcher] last worker exited — settling {_settleSeconds}s before closing the install window");
|
||||
StartSettleTimer();
|
||||
}
|
||||
}
|
||||
|
||||
+1
-1
@@ -121,7 +121,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office
|
||||
}
|
||||
_watchedKey = ancestor;
|
||||
_mode = WatchMode.Bootstrap;
|
||||
_logger.Debug($"[RegistryChangeWatcher] target HKLM\\{_targetSubKey} absent — bootstrap-watching HKLM\\{ancestorPath} (name-only)");
|
||||
_logger.Debug($"[RegistryChangeWatcher] target HKLM\\{_targetSubKey} absent — bootstrap-watching HKLM\\{ancestorPath} (name-only)", repeatKey: "RegistryChangeWatcher.bootstrap:" + _targetSubKey);
|
||||
if (!ArmNotify(subtree: false, BootstrapFilter)) return;
|
||||
|
||||
// TOCTOU: the target may have been created between TryOpen and arming the ancestor watch.
|
||||
|
||||
+5
-5
@@ -127,7 +127,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"Process metrics read failed: {ex.Message}");
|
||||
Logger.Debug($"Process metrics read failed: {ex.Message}", repeatKey: "AgentSelfMetricsCollector.process");
|
||||
}
|
||||
|
||||
// --- Spool stats (P2 telemetry) ---
|
||||
@@ -155,7 +155,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"Spool metrics read failed: {ex.Message}");
|
||||
Logger.Debug($"Spool metrics read failed: {ex.Message}", repeatKey: "AgentSelfMetricsCollector.spool");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -186,7 +186,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"Network metrics read failed: {ex.Message}");
|
||||
Logger.Debug($"Network metrics read failed: {ex.Message}", repeatKey: "AgentSelfMetricsCollector.network");
|
||||
}
|
||||
|
||||
// --- IME log tracker health ---
|
||||
@@ -224,7 +224,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"IME tracker health read failed: {ex.Message}");
|
||||
Logger.Debug($"IME tracker health read failed: {ex.Message}", repeatKey: "AgentSelfMetricsCollector.imeTracker");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -262,7 +262,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"Signal pipeline health read failed: {ex.Message}");
|
||||
Logger.Debug($"Signal pipeline health read failed: {ex.Message}", repeatKey: "AgentSelfMetricsCollector.signalPipeline");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
+11
-8
@@ -153,7 +153,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
{
|
||||
if (_permanentlyDisabled || !_dormant) return;
|
||||
_dormant = false;
|
||||
Logger.Info("[DeliveryOptimizationCollector] Waking up — download activity detected");
|
||||
Logger.Debug("[DeliveryOptimizationCollector] Waking up — download activity detected");
|
||||
ResumeTimer();
|
||||
}
|
||||
|
||||
@@ -167,7 +167,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
_officeActive = active;
|
||||
if (active)
|
||||
{
|
||||
Logger.Info("[DeliveryOptimizationCollector] Office install active — sampling DO for Office CDN jobs");
|
||||
Logger.Debug("[DeliveryOptimizationCollector] Office install active — sampling DO for Office CDN jobs");
|
||||
WakeUp();
|
||||
}
|
||||
}
|
||||
@@ -243,7 +243,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
|
||||
if (!hasActiveDownloads && !hasPendingEnrichment && !officeKeepAwake)
|
||||
{
|
||||
Logger.Info("[DeliveryOptimizationCollector] Going dormant — no active downloads, pending enrichment or Office install");
|
||||
Logger.Debug("[DeliveryOptimizationCollector] Going dormant — no active downloads, pending enrichment or Office install");
|
||||
_dormant = true;
|
||||
PauseTimer();
|
||||
// Natural persistence point: all downloads are done — which is exactly when an
|
||||
@@ -278,7 +278,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
{
|
||||
_runspace = RunspaceFactory.CreateRunspace();
|
||||
_runspace.Open();
|
||||
Logger.Info("[DeliveryOptimizationCollector] PowerShell Runspace opened");
|
||||
Logger.Debug("[DeliveryOptimizationCollector] PowerShell Runspace opened");
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
@@ -343,7 +343,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
_permanentlyDisabled = true;
|
||||
return null;
|
||||
}
|
||||
Logger.Debug($"[DeliveryOptimizationCollector] PS error stream: {firstError}");
|
||||
Logger.Debug($"[DeliveryOptimizationCollector] PS error stream: {firstError}", repeatKey: "DeliveryOptimizationCollector.psError");
|
||||
}
|
||||
|
||||
return results;
|
||||
@@ -386,7 +386,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
{
|
||||
if (results.Count == 0)
|
||||
{
|
||||
Logger.Verbose("[DeliveryOptimizationCollector] No DO entries returned");
|
||||
Logger.Trace("[DeliveryOptimizationCollector] No DO entries returned");
|
||||
return;
|
||||
}
|
||||
|
||||
@@ -568,8 +568,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
WriteToLogFile(logEntries);
|
||||
}
|
||||
|
||||
Logger.Verbose($"[DeliveryOptimizationCollector] Poll: {results.Count} entries, " +
|
||||
$"{progressCount} progress updates, {matchCount} new matches ({_enrichedAppIds.Count} total enriched)");
|
||||
var pollSummary = $"[DeliveryOptimizationCollector] Poll: {results.Count} entries, " +
|
||||
$"{progressCount} progress updates, {matchCount} new matches ({_enrichedAppIds.Count} total enriched)";
|
||||
// A poll that found nothing new is a tick (Trace); one with progress or matches is content.
|
||||
if (progressCount > 0 || matchCount > 0) Logger.Verbose(pollSummary);
|
||||
else Logger.Trace(pollSummary);
|
||||
}
|
||||
|
||||
// Office C2R content CDN hosts — version-independent (a FileId build marker like "_16_0_" would
|
||||
|
||||
+5
-1
@@ -80,6 +80,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
|
||||
public void Stop()
|
||||
{
|
||||
// Hosts call Stop and then Dispose, which stops again; only a started detector logs.
|
||||
var wasRunning = _connectivityCheckClient != null;
|
||||
NetworkChange.NetworkAddressChanged -= OnNetworkAddressChanged;
|
||||
|
||||
lock (_stateLock)
|
||||
@@ -91,7 +93,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
_connectivityCheckClient?.Dispose();
|
||||
_connectivityCheckClient = null;
|
||||
|
||||
_logger.Info("NetworkChangeDetector: stopped");
|
||||
if (wasRunning) _logger.Info("NetworkChangeDetector: stopped");
|
||||
}
|
||||
|
||||
public void Dispose()
|
||||
@@ -158,6 +160,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
// Suppress events when network hasn't actually changed (DHCP renewals, OS chatter)
|
||||
if (previousState != null && previousState.IsSameNetwork(newState))
|
||||
{
|
||||
// Every occurrence on purpose, no repeatKey: when it happened is the information
|
||||
// (did anything move on the network when uploads stopped?).
|
||||
_logger.Debug("NetworkChangeDetector: network address changed but same logical network — suppressing");
|
||||
return;
|
||||
}
|
||||
|
||||
+6
-6
@@ -123,7 +123,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"CPU counter read failed: {ex.Message}");
|
||||
Logger.Debug($"CPU counter read failed: {ex.Message}", repeatKey: "PerformanceCollector.cpu");
|
||||
}
|
||||
|
||||
// Memory info via GlobalMemoryStatusEx (kernel32)
|
||||
@@ -138,12 +138,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
else
|
||||
{
|
||||
Logger.Debug("GlobalMemoryStatusEx returned no data");
|
||||
Logger.Debug("GlobalMemoryStatusEx returned no data", repeatKey: "PerformanceCollector.memoryNoData");
|
||||
}
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"Memory query failed: {ex.Message}");
|
||||
Logger.Debug($"Memory query failed: {ex.Message}", repeatKey: "PerformanceCollector.memory");
|
||||
}
|
||||
|
||||
// Disk queue length
|
||||
@@ -154,7 +154,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"Disk queue counter read failed: {ex.Message}");
|
||||
Logger.Debug($"Disk queue counter read failed: {ex.Message}", repeatKey: "PerformanceCollector.diskQueue");
|
||||
}
|
||||
|
||||
// Disk free space on system drive
|
||||
@@ -181,7 +181,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"Disk space query failed: {ex.Message}");
|
||||
Logger.Debug($"Disk space query failed: {ex.Message}", repeatKey: "PerformanceCollector.diskSpace");
|
||||
}
|
||||
|
||||
// Network throughput (bytes sent/received delta + rate)
|
||||
@@ -271,7 +271,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"Network throughput collection failed: {ex.Message}");
|
||||
Logger.Debug($"Network throughput collection failed: {ex.Message}", repeatKey: "PerformanceCollector.network");
|
||||
}
|
||||
|
||||
if (data.Count > 0)
|
||||
|
||||
+6
-1
@@ -174,7 +174,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Security
|
||||
lock (_lock) { _startWatcher = null; }
|
||||
// Surface the dead live detector so the backend can distinguish it from a clean run.
|
||||
var handler = WatcherArmFailed;
|
||||
try { handler?.Invoke(this, ex); } catch { /* never throw from Start */ }
|
||||
try { handler?.Invoke(this, ex); }
|
||||
catch (Exception handlerEx)
|
||||
{
|
||||
// Never throw from Start.
|
||||
_logger.Warning($"[ConsoleBypassWatcher] WatcherArmFailed handler threw: {handlerEx.Message}");
|
||||
}
|
||||
}
|
||||
|
||||
// 2) Startup probe — catch a console already open before the watcher armed. Win32_Process
|
||||
|
||||
@@ -194,7 +194,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Transport
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Swallow — distress channel must never cascade failures into the caller
|
||||
_logger?.Debug($"[DistressChannel] Failed to send report: {ex.Message}");
|
||||
_logger?.Debug($"[DistressChannel] Failed to send report: {TransportErrorCodes.DescribeSendFailure(ex)}");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -180,7 +180,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Transport
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Swallow — emergency channel must never cascade failures into the caller
|
||||
_logger?.Debug($"[EmergencyChannel] Failed to send report: {ex.Message}");
|
||||
_logger?.Debug($"[EmergencyChannel] Failed to send report: {TransportErrorCodes.DescribeSendFailure(ex)}");
|
||||
}
|
||||
|
||||
if (!delivered)
|
||||
|
||||
@@ -93,7 +93,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Transport
|
||||
attempt.PrimaryError = error;
|
||||
|
||||
// Retry ipinfo.io once after a short delay (network may still be initializing during Autopilot)
|
||||
logger?.Info($"GeoLocation: Retrying ipinfo.io after {RetryDelay.TotalSeconds}s...");
|
||||
logger?.Debug($"GeoLocation: Retrying ipinfo.io after {RetryDelay.TotalSeconds}s...");
|
||||
await Task.Delay(RetryDelay);
|
||||
|
||||
(result, error) = await TryProvider("ipinfo.io", IpInfoUrl, ParseIpInfo, logger);
|
||||
@@ -131,7 +131,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Transport
|
||||
{
|
||||
try
|
||||
{
|
||||
logger?.Info($"GeoLocation: Querying {name}...");
|
||||
logger?.Debug($"GeoLocation: Querying {name}...");
|
||||
|
||||
using (var httpResponse = await SharedHttpClient.GetAsync(url))
|
||||
{
|
||||
|
||||
+1
-1
@@ -29,7 +29,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Transport
|
||||
|
||||
try
|
||||
{
|
||||
logger.Info($"NTP time check: querying {ntpServer}");
|
||||
logger.Debug($"NTP time check: querying {ntpServer}");
|
||||
|
||||
// NTP request packet: 48 bytes, first byte = 0x1B (LI=0, VN=3, Mode=3)
|
||||
var ntpData = new byte[48];
|
||||
|
||||
@@ -47,7 +47,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Transport
|
||||
}
|
||||
|
||||
// Execute tzutil /s to set the timezone
|
||||
logger.Info($"Timezone auto-set: setting timezone to {windowsId} (IANA: {ianaTimezone}, previous: {result.PreviousTimezone})");
|
||||
logger.Debug($"Timezone auto-set: setting timezone to {windowsId} (IANA: {ianaTimezone}, previous: {result.PreviousTimezone})");
|
||||
|
||||
var psi = new ProcessStartInfo
|
||||
{
|
||||
|
||||
@@ -1,6 +1,8 @@
|
||||
using System;
|
||||
using System.ComponentModel;
|
||||
using System.Globalization;
|
||||
using System.Net;
|
||||
using System.Net.Sockets;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Transport
|
||||
{
|
||||
@@ -31,6 +33,38 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Transport
|
||||
return code == null ? ex.Message : $"{ex.Message} (win32 {code})";
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// What a failed send hit, in one line: the <see cref="WebException.Status"/>, the socket error
|
||||
/// or native code, and the innermost message. On .NET Framework a socket error's message names
|
||||
/// the endpoint it tried, which tells a backend that does not answer from a proxy that does not.
|
||||
/// </summary>
|
||||
public static string DescribeSendFailure(Exception ex)
|
||||
{
|
||||
if (ex == null) return null;
|
||||
|
||||
WebExceptionStatus? status = null;
|
||||
SocketError? socketError = null;
|
||||
var innermost = ex;
|
||||
for (var current = ex; current != null; current = current.InnerException)
|
||||
{
|
||||
innermost = current;
|
||||
if (current is WebException web && status == null) status = web.Status;
|
||||
if (current is SocketException socket) socketError = socket.SocketErrorCode;
|
||||
}
|
||||
|
||||
var code = socketError.HasValue ? $"socket={socketError.Value}" : NativeCodePart(ex);
|
||||
var details = status.HasValue
|
||||
? (code == null ? $"status={status.Value}" : $"status={status.Value}, {code}")
|
||||
: code;
|
||||
return details == null ? innermost.Message : $"{details}: {innermost.Message}";
|
||||
}
|
||||
|
||||
private static string NativeCodePart(Exception ex)
|
||||
{
|
||||
var code = InnermostNativeCode(ex);
|
||||
return code == null ? null : $"win32={code}";
|
||||
}
|
||||
|
||||
/// <summary>Eight-digit hex with <c>0x</c>: <c>-2146893018</c> → <c>0x80090326</c>.</summary>
|
||||
public static string Hex(int value) => "0x" + value.ToString("X8", CultureInfo.InvariantCulture);
|
||||
}
|
||||
|
||||
@@ -190,7 +190,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
if (_transitionEmitter != null)
|
||||
{
|
||||
try { _transitionEmitter.Emit(step.Transition); }
|
||||
catch { /* best-effort upload; local state already consistent */ }
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Best-effort upload; the local journal already holds the transition.
|
||||
_logger.Debug($"DecisionStepProcessor: transition not handed to the upload spool: {ex.Message}", repeatKey: "DecisionStepProcessor.transitionEmit");
|
||||
}
|
||||
}
|
||||
|
||||
// 2) EffectRunner — Async-Methode vom Ingress-Worker-Thread sync ausführen.
|
||||
@@ -271,21 +275,28 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
_currentState = step.NewState;
|
||||
_consecutiveJournalFailures = 0;
|
||||
|
||||
// PR3-D1: per-step observability. Stage transitions and effect-bearing steps fire
|
||||
// at DEBUG (operator-relevant); pure no-op steps (Stage unchanged + no effects)
|
||||
// fire at VERBOSE so a steady stream of e.g. ClassifierTick + InformationalEvent
|
||||
// pass-throughs doesn't drown the log.
|
||||
// PR3-D1: per-step observability. A stage change is the enrollment flow (Info); other
|
||||
// effect-bearing steps and dead ends are decision detail (Debug); InformationalEvent
|
||||
// pass-throughs, the self-re-arming classifier tick and no-op steps are mechanics
|
||||
// (Trace). The journal keeps every step either way.
|
||||
var newStage = step.NewState.Stage;
|
||||
if (previousStage != newStage || step.Effects.Count > 0)
|
||||
{
|
||||
_logger.Debug(
|
||||
var line =
|
||||
$"DecisionStep: ord={signal.SessionSignalOrdinal} kind={signal.Kind} " +
|
||||
$"stage={previousStage}->{newStage} effects=[{string.Join(",", step.Effects.Select(e => e.Kind))}] " +
|
||||
$"abort={effectResult.SessionMustAbort} failures={effectResult.Failures.Count}");
|
||||
$"abort={effectResult.SessionMustAbort} failures={effectResult.Failures.Count}";
|
||||
if (previousStage != newStage) _logger.Info(line);
|
||||
else if (IsRoutineStep(signal, effectResult)) _logger.Trace(line);
|
||||
else _logger.Debug(line);
|
||||
}
|
||||
else if (step.Transition.DeadEndReason != null)
|
||||
{
|
||||
_logger.Debug($"DecisionStep: ord={signal.SessionSignalOrdinal} kind={signal.Kind} stage={previousStage} dead end ({step.Transition.DeadEndReason})");
|
||||
}
|
||||
else
|
||||
{
|
||||
_logger.Verbose($"DecisionStep: ord={signal.SessionSignalOrdinal} kind={signal.Kind} stage={previousStage} (no-op)");
|
||||
_logger.Trace($"DecisionStep: ord={signal.SessionSignalOrdinal} kind={signal.Kind} stage={previousStage} (no-op)");
|
||||
}
|
||||
|
||||
// 5) Terminal-stage detection (M4.6.β). Fires exactly once per agent run when the
|
||||
@@ -505,6 +516,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
return _passThroughStepsSinceSnapshot >= SnapshotPassThroughFloor;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// A step that runs for every informational event, or for the classifier tick that re-arms
|
||||
/// itself every 30 s, without changing the stage. Decided by the signal, not the effect:
|
||||
/// real decisions emit timeline entries too. A failed effect run is never routine.
|
||||
/// </summary>
|
||||
private static bool IsRoutineStep(DecisionSignal signal, EffectRunResult effectResult)
|
||||
{
|
||||
if (effectResult.SessionMustAbort || effectResult.Failures.Count > 0) return false;
|
||||
if (signal.Kind == DecisionSignalKind.InformationalEvent) return true;
|
||||
return signal.Kind == DecisionSignalKind.DeadlineFired
|
||||
&& signal.Payload != null
|
||||
&& signal.Payload.TryGetValue(SignalPayloadKeys.Deadline, out var deadline)
|
||||
&& string.Equals(deadline, DeadlineNames.ClassifierTick, StringComparison.Ordinal);
|
||||
}
|
||||
|
||||
private void TryTriggerQuarantine(string reason)
|
||||
{
|
||||
try
|
||||
|
||||
@@ -206,7 +206,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
!string.IsNullOrEmpty(lastVerdictId) &&
|
||||
snapshotHash == lastVerdictId)
|
||||
{
|
||||
_logger?.Debug(
|
||||
_logger?.Trace(
|
||||
$"EffectRunner: classifier {effect.ClassifierId} skipped (snapshotHash unchanged: {ShortHash(snapshotHash)})");
|
||||
return new ClassifierEffectOutcome(invoked: false, skippedByAntiLoop: true, failure: null);
|
||||
}
|
||||
|
||||
@@ -456,7 +456,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
// (eventType, phase) here. Fed to the collector-host factory at step 14 so gather-rule
|
||||
// phase_change/on_event triggers key off the ENGINE-REDUCED timeline (RealmJoin gate
|
||||
// et al. respected) instead of raw pre-reduce signals — see TimelineEventStream doc.
|
||||
_timelineEvents = new TimelineEventStream();
|
||||
_timelineEvents = new TimelineEventStream(_logger);
|
||||
_timelineEmitter = new EventTimelineEmitter(eventEmitter, _timelineEvents);
|
||||
_backPressureObserver = new BackPressureEventObserver(eventEmitter, _clock);
|
||||
|
||||
@@ -836,7 +836,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
}),
|
||||
payload: payload);
|
||||
|
||||
_logger.Info(
|
||||
_logger.Debug(
|
||||
$"EnrollmentOrchestrator: EspConfigDetected bootstrap posted (SkipUser={snapshot.SkipUser?.ToString() ?? "unknown"}, SkipDevice={snapshot.SkipDevice?.ToString() ?? "unknown"}, AllowContinueAnyway={snapshot.AllowContinueAnyway?.ToString() ?? "unknown"}, SyncFailureTimeoutMinutes={snapshot.SyncFailureTimeoutMinutes?.ToString() ?? "unknown"}).");
|
||||
}
|
||||
catch (Exception ex)
|
||||
|
||||
@@ -33,7 +33,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
Func<bool>? isHybridJoinProbe = null)
|
||||
{
|
||||
_watcher = new AadJoinWatcher(logger);
|
||||
_adapter = new AadJoinWatcherAdapter(_watcher, ingress, clock, onRealUserJoined: onRealUserJoined);
|
||||
_adapter = new AadJoinWatcherAdapter(_watcher, ingress, clock, onRealUserJoined: onRealUserJoined, logger: logger);
|
||||
var post = new InformationalEventPost(ingress, clock);
|
||||
_hybridLoginPendingDetector = new HybridLoginPendingDetector(
|
||||
watcher: _watcher,
|
||||
|
||||
+1
-1
@@ -50,7 +50,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
{
|
||||
if (Interlocked.Exchange(ref _fired, 1) == 1)
|
||||
{
|
||||
_logger.Info("AutoLogonDeviceSetupTrigger: duplicate DeviceSetupProvisioningComplete ignored (already fired)");
|
||||
_logger.Debug("AutoLogonDeviceSetupTrigger: duplicate DeviceSetupProvisioningComplete ignored (already fired)");
|
||||
return;
|
||||
}
|
||||
|
||||
|
||||
@@ -108,13 +108,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
try { _collector.CollectAll(); }
|
||||
catch (Exception ex) { _logger.Warning($"DeviceInfoHost: CollectAll threw: {ex.Message}"); }
|
||||
});
|
||||
_logger.Info("DeviceInfoHost: CollectAll scheduled on background thread.");
|
||||
_logger.Debug("DeviceInfoHost: CollectAll scheduled on background thread.");
|
||||
|
||||
if (_observableIngress != null && _handler == null)
|
||||
{
|
||||
_handler = OnSignalPosted;
|
||||
_observableIngress.SignalPosted += _handler;
|
||||
_logger.Info("DeviceInfoHost: armed phase-driven re-collections (DeviceSetup → enrollment refresh; FinalizingSetup/desktop → end collect).");
|
||||
_logger.Debug("DeviceInfoHost: armed phase-driven re-collections (DeviceSetup → enrollment refresh; FinalizingSetup/desktop → end collect).");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -134,7 +134,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
if (!runStartRefresh && !runEndCollect) return;
|
||||
|
||||
var trigger = kind == DecisionSignalKind.DesktopArrived ? "desktop_arrived" : "esp_phase_changed";
|
||||
_logger.Info($"DeviceInfoHost: trigger '{trigger}' — scheduling re-collect (enrollmentStart={runStartRefresh}, end={runEndCollect}).");
|
||||
_logger.Debug($"DeviceInfoHost: trigger '{trigger}' — scheduling re-collect (enrollmentStart={runStartRefresh}, end={runEndCollect}).");
|
||||
|
||||
// Offload WMI/registry IO off the ingress writer thread. The gate suppresses
|
||||
// everything that did not actually change.
|
||||
@@ -170,7 +170,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
if (!_espConfigRefreshesFired.Add(trigger)) return;
|
||||
}
|
||||
|
||||
_logger.Info($"DeviceInfoHost: ESP-config refresh trigger '{trigger}' — scheduling re-collect.");
|
||||
_logger.Debug($"DeviceInfoHost: ESP-config refresh trigger '{trigger}' — scheduling re-collect.");
|
||||
Task.Run(() =>
|
||||
{
|
||||
try { _collector.RefreshEspConfiguration(trigger); }
|
||||
|
||||
+1
-1
@@ -133,7 +133,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Verbose($"GatherRuleExecutorHost: timeline-trigger dispatch failed: {ex.Message}");
|
||||
_logger.Debug($"GatherRuleExecutorHost: timeline-trigger dispatch failed: {ex.Message}", repeatKey: "GatherRuleExecutorHost.dispatchFailed");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
+2
-2
@@ -80,7 +80,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
filter: RegistryNativeMethods.RegChangeNotifyFilter.Name
|
||||
| RegistryNativeMethods.RegChangeNotifyFilter.LastSet
|
||||
| RegistryNativeMethods.RegChangeNotifyFilter.ThreadAgnostic,
|
||||
trace: msg => _logger?.Debug($"ImeRegistryAppState watcher: {msg}"));
|
||||
trace: msg => _logger?.Trace($"ImeRegistryAppState watcher: {msg}"));
|
||||
_watcher.Changed += (_, __) => ScheduleDebouncedTick();
|
||||
_watcher.Error += (_, ex) =>
|
||||
{
|
||||
@@ -131,7 +131,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Observer.Tick is itself fail-soft; this is the last-resort belt.
|
||||
_logger?.Debug($"ImeRegistryAppState tick failed: {ex.Message}");
|
||||
_logger?.Debug($"ImeRegistryAppState tick failed: {ex.Message}", repeatKey: "ImeRegistryAppStateHost.tickFailed");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
+2
-2
@@ -205,7 +205,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
catch (Exception ex)
|
||||
{
|
||||
error = ex;
|
||||
_logger.Info($"[{Name}] arm attempt '{modeLabel}' failed ({ex.GetType().Name}: {ex.Message})");
|
||||
_logger.Debug($"[{Name}] arm attempt '{modeLabel}' failed ({ex.GetType().Name}: {ex.Message})");
|
||||
lock (_lock) { _watcher = null; }
|
||||
return false;
|
||||
}
|
||||
@@ -264,7 +264,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Debug($"[{Name}] debounced power tick failed: {ex.Message}");
|
||||
_logger.Debug($"[{Name}] debounced power tick failed: {ex.Message}", repeatKey: "PowerStateWatcherHost.tickFailed");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
+1
-1
@@ -199,7 +199,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Verbose($"UserEspKeepAwakeHost: signal dispatch failed: {ex.Message}");
|
||||
_logger.Debug($"UserEspKeepAwakeHost: signal dispatch failed: {ex.Message}", repeatKey: "UserEspKeepAwakeHost.dispatchFailed");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
+1
-1
@@ -58,7 +58,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
{
|
||||
if (Interlocked.Exchange(ref _fired, 1) == 1)
|
||||
{
|
||||
_logger.Info("WhiteGloveInventoryTrigger: duplicate WhiteGloveCompleted ignored (already fired)");
|
||||
_logger.Debug("WhiteGloveInventoryTrigger: duplicate WhiteGloveCompleted ignored (already fired)");
|
||||
return;
|
||||
}
|
||||
|
||||
|
||||
@@ -142,13 +142,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
payload: payload,
|
||||
typedPayload: typedPayload);
|
||||
|
||||
// PR3-D5: lifecycle-event observability — DEBUG so it doesn't dominate at INFO,
|
||||
// but every event that hits the timeline has a matching agent-log line. First
|
||||
// PR3-D5: lifecycle-event observability — VERBOSE (per-item detail, D-394), so every
|
||||
// event that hits the timeline has a matching agent-log line at that level. First
|
||||
// 8 payload keys are usually enough to identify the event variant.
|
||||
if (_logger != null)
|
||||
{
|
||||
var keys = string.Join(",", payload.Keys.Take(8));
|
||||
_logger.Debug(
|
||||
_logger.Verbose(
|
||||
$"InformationalEventPost: emit eventType={eventType} source={source} " +
|
||||
$"immediate={immediateUpload} severity={severity?.ToString() ?? "default"} " +
|
||||
$"dataKeys=[{keys}]");
|
||||
|
||||
@@ -383,11 +383,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
var handler = SignalPosted;
|
||||
if (handler == null) return;
|
||||
try { handler(kind, payload); }
|
||||
catch
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Observer exceptions MUST NOT disrupt the production ingress path. The idle-
|
||||
// activity observer (Codex Finding 4) is advisory — dropping one observation
|
||||
// is strictly better than surfacing a mid-Post exception to a collector thread.
|
||||
_logger?.Debug($"SignalIngress: SignalPosted observer threw: {ex.Message}", repeatKey: "SignalIngress.signalPostedObserver");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -413,9 +414,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
{
|
||||
_observer.OnBackPressure(origin, _channelCapacity, queueLengthAtBlock, blockedFor);
|
||||
}
|
||||
catch
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Observer-Fehler dürfen den Produktions-Pfad nicht aufhalten. Weglucken.
|
||||
// An observer fault must not hold up the production path.
|
||||
_logger?.Debug($"SignalIngress: back-pressure observer threw: {ex.Message}", repeatKey: "SignalIngress.backPressureObserver");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -518,9 +520,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
|
||||
_nextSignalOrdinal = signalOrdinal + 1;
|
||||
// PR3-D2: 1:1 correlation marker for D1 (DecisionStepProcessor logs the same ord +
|
||||
// kind on the receive side). Verbose because the steady-state happy-path is the
|
||||
// dominant cardinality.
|
||||
_logger?.Verbose($"SignalIngress: processed ord={signalOrdinal} kind={item.Kind} origin={item.SourceOrigin}.");
|
||||
// kind on the receive side). Trace: one line per signal is mechanics (D-394).
|
||||
_logger?.Trace($"SignalIngress: processed ord={signalOrdinal} kind={item.Kind} origin={item.SourceOrigin}.");
|
||||
Interlocked.Increment(ref _processedCount);
|
||||
|
||||
// Project the signal onto the telemetry transport for backend upload. Local
|
||||
@@ -530,7 +531,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
if (_signalEmitter != null)
|
||||
{
|
||||
try { _signalEmitter.Emit(signal); }
|
||||
catch { /* best-effort upload; local state already consistent */ }
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Best-effort upload; the local SignalLog already holds the signal.
|
||||
_logger?.Debug($"SignalIngress: signal not handed to the upload spool: {ex.Message}", repeatKey: "SignalIngress.signalEmit");
|
||||
}
|
||||
}
|
||||
|
||||
var state = _processor.CurrentState;
|
||||
@@ -544,9 +549,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
}
|
||||
catch
|
||||
{
|
||||
// Processor-Fehler (z.B. Journal-Write, Effect-Transient-Exhaust) werden in
|
||||
// M4.4.5 vom Orchestrator geloggt + ggf. Quarantine ausgelöst. M4.4.0
|
||||
// verschluckt bewusst, damit der Ingress-Worker nicht verstummt.
|
||||
// ApplyStep logs its own failures (a journal append fault at Error, before it
|
||||
// rethrows and counts towards quarantine); swallowed here so the worker keeps running.
|
||||
}
|
||||
|
||||
// Codex follow-up (post-#50 #B): inline durable-abort path. When the step's
|
||||
@@ -649,7 +653,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
if (_signalEmitter != null)
|
||||
{
|
||||
try { _signalEmitter.Emit(syntheticSignal); }
|
||||
catch { /* best-effort upload */ }
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Best-effort upload; the local SignalLog already holds the signal.
|
||||
_logger?.Debug($"SignalIngress: signal not handed to the upload spool: {ex.Message}", repeatKey: "SignalIngress.signalEmit");
|
||||
}
|
||||
}
|
||||
|
||||
var state = _processor.CurrentState;
|
||||
@@ -662,8 +670,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
catch
|
||||
{
|
||||
// Processor fault on the terminal transition — Journal has the abort
|
||||
// transition committed (reducer produces Stage=Failed unconditionally).
|
||||
// Swallowed by convention; worker must not die from this path.
|
||||
// transition committed (reducer produces Stage=Failed unconditionally), and
|
||||
// ApplyStep has logged the fault. Swallowed so the worker does not die here.
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -1,5 +1,6 @@
|
||||
#nullable enable
|
||||
using System;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
@@ -24,11 +25,19 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
/// <b>Threading</b>: <see cref="Publish"/> runs on the ingress worker thread (the effect
|
||||
/// execution path). Subscribers must stay fast and must not block; subscriber exceptions are
|
||||
/// swallowed per handler so the emit path can never throw (an exception here would surface
|
||||
/// as an EffectRunner transient retry and duplicate the emitted event).
|
||||
/// as an EffectRunner transient retry and duplicate the emitted event). They are logged at
|
||||
/// Debug, an identical repeat at Trace.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public sealed class TimelineEventStream
|
||||
{
|
||||
private readonly AgentLogger? _logger;
|
||||
|
||||
public TimelineEventStream(AgentLogger? logger = null)
|
||||
{
|
||||
_logger = logger;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Raised once per emitted timeline event with its <see cref="EnrollmentEvent.EventType"/>
|
||||
/// and parsed <see cref="EnrollmentEvent.Phase"/> (<see cref="EnrollmentPhase.Unknown"/>
|
||||
@@ -48,9 +57,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
foreach (Action<string, EnrollmentPhase, string> subscriber in handler.GetInvocationList())
|
||||
{
|
||||
try { subscriber(eventType, phase, source); }
|
||||
catch
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Subscriber isolation — see class doc: the emit path must never throw.
|
||||
var name = $"{subscriber.Method.DeclaringType?.Name}.{subscriber.Method.Name}";
|
||||
_logger?.Debug($"TimelineEventStream: subscriber {name} threw: {ex.Message}", repeatKey: "TimelineEventStream.subscriber:" + name);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -249,7 +249,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Persistence
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Debug($"StartupEventGate: failed to save state: {ex.Message}");
|
||||
_logger.Debug($"StartupEventGate: failed to save state: {ex.Message}", repeatKey: "StartupEventGate.save");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -64,7 +64,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
_logger,
|
||||
_analyzerConfig.LocalAdminAllowedAccounts,
|
||||
_startupEventGate));
|
||||
_logger.Info("LocalAdminAnalyzer registered");
|
||||
_logger.Debug("LocalAdminAnalyzer registered");
|
||||
}
|
||||
else
|
||||
{
|
||||
@@ -79,7 +79,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
_post,
|
||||
_logger,
|
||||
_startupEventGate));
|
||||
_logger.Info("SoftwareInventoryAnalyzer registered");
|
||||
_logger.Debug("SoftwareInventoryAnalyzer registered");
|
||||
}
|
||||
else
|
||||
{
|
||||
@@ -94,7 +94,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
_post,
|
||||
_logger,
|
||||
_startupEventGate));
|
||||
_logger.Info("IntegrityBypassAnalyzer registered");
|
||||
_logger.Debug("IntegrityBypassAnalyzer registered");
|
||||
}
|
||||
else
|
||||
{
|
||||
@@ -113,7 +113,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
_post,
|
||||
_logger,
|
||||
_startupEventGate));
|
||||
_logger.Info("ConsolePrefetchScanner registered");
|
||||
_logger.Debug("ConsolePrefetchScanner registered");
|
||||
}
|
||||
else
|
||||
{
|
||||
@@ -128,7 +128,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
_configuration.TenantId,
|
||||
_post,
|
||||
_logger));
|
||||
_logger.Info("AutoLogonAnalyzer registered (always-on)");
|
||||
_logger.Debug("AutoLogonAnalyzer registered (always-on)");
|
||||
|
||||
_logger.Info($"Analyzers initialized: {_analyzers.Count} active");
|
||||
}
|
||||
@@ -144,7 +144,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
if (_analyzers.Count == 0) return;
|
||||
|
||||
var snapshot = new List<IAgentAnalyzer>(_analyzers);
|
||||
_logger.Info($"Scheduling {snapshot.Count} startup analyzer(s) on background thread");
|
||||
_logger.Debug($"Scheduling {snapshot.Count} startup analyzer(s) on background thread");
|
||||
|
||||
Task.Run(() =>
|
||||
{
|
||||
@@ -166,7 +166,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
if (!_initialised) Initialize();
|
||||
if (_analyzers.Count == 0) return;
|
||||
|
||||
_logger.Info($"Running {_analyzers.Count} shutdown analyzer(s) (whiteGlovePart={whiteGlovePart?.ToString() ?? "none"})");
|
||||
_logger.Debug($"Running {_analyzers.Count} shutdown analyzer(s) (whiteGlovePart={whiteGlovePart?.ToString() ?? "none"})");
|
||||
|
||||
foreach (var analyzer in _analyzers)
|
||||
{
|
||||
@@ -202,7 +202,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
|
||||
try
|
||||
{
|
||||
_logger.Info("DeviceSetup complete — running AutoLogonAnalyzer.AnalyzeAtDeviceSetupComplete()");
|
||||
_logger.Debug("DeviceSetup complete — running AutoLogonAnalyzer.AnalyzeAtDeviceSetupComplete()");
|
||||
autoLogonAnalyzer.AnalyzeAtDeviceSetupComplete();
|
||||
}
|
||||
catch (Exception ex)
|
||||
@@ -241,7 +241,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
|
||||
try
|
||||
{
|
||||
_logger.Info("WhiteGlove Part 1 inventory snapshot — running SoftwareInventoryAnalyzer.AnalyzeAtShutdown(whiteGlovePart: 1)");
|
||||
_logger.Debug("WhiteGlove Part 1 inventory snapshot — running SoftwareInventoryAnalyzer.AnalyzeAtShutdown(whiteGlovePart: 1)");
|
||||
softwareAnalyzer.AnalyzeAtShutdown(whiteGlovePart: 1);
|
||||
}
|
||||
catch (Exception ex)
|
||||
|
||||
@@ -136,7 +136,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
{
|
||||
if (_distressReporter != null && Volatile.Read(ref _distressDispatched) == 0)
|
||||
{
|
||||
_logger.Info(
|
||||
_logger.Debug(
|
||||
$"AuthFailureTracker: distress report suppressed for {operation} (http {statusCode}) — " +
|
||||
"endpoint unavailable (platform error page), a report cannot reach a stopped endpoint.");
|
||||
}
|
||||
@@ -212,7 +212,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
$"{operation} http {statusCode} {classification.ForeignReason}; " +
|
||||
$"page \"{classification.PageTitle ?? "(none)"}\"; " +
|
||||
$"server cert issuer \"{classification.ServerCertIssuer ?? "(unknown)"}\"";
|
||||
_logger.Info($"AuthFailureTracker: answer did not come from the backend — not an authentication failure, not counted ({finding}).");
|
||||
_logger.Info($"AuthFailureTracker: answer did not come from the backend — not an authentication failure, not counted ({finding}).", repeatKey: "AuthFailureTracker.notBackend");
|
||||
|
||||
if (_distressReporter == null || Interlocked.CompareExchange(ref _foreignDistressDispatched, 1, 0) != 0)
|
||||
return;
|
||||
|
||||
@@ -17,8 +17,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
/// </summary>
|
||||
/// <param name="thumbprint">Optional specific thumbprint to search for</param>
|
||||
/// <param name="logger">Logger for diagnostic output</param>
|
||||
/// <param name="logNotFound">False where "not found" is expected, e.g. the await-enrollment poll.</param>
|
||||
/// <returns>The MDM certificate, or null if not found</returns>
|
||||
public static X509Certificate2 FindMdmCertificate(string thumbprint = null, AgentLogger logger = null)
|
||||
public static X509Certificate2 FindMdmCertificate(string thumbprint = null, AgentLogger logger = null, bool logNotFound = true)
|
||||
{
|
||||
try
|
||||
{
|
||||
@@ -35,7 +36,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
{
|
||||
store.Open(OpenFlags.ReadOnly);
|
||||
|
||||
logger?.Debug($"Searching for MDM certificate in {storeInfo.Location}\\{storeInfo.Name}");
|
||||
logger?.Trace($"Searching for MDM certificate in {storeInfo.Location}\\{storeInfo.Name}");
|
||||
|
||||
// If thumbprint specified, search by thumbprint
|
||||
if (!string.IsNullOrEmpty(thumbprint))
|
||||
@@ -47,7 +48,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
|
||||
if (cert != null)
|
||||
{
|
||||
logger?.Info($"Found certificate by thumbprint: {thumbprint}");
|
||||
logger?.Debug($"Found certificate by thumbprint: {thumbprint}");
|
||||
return cert;
|
||||
}
|
||||
}
|
||||
@@ -59,14 +60,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
var cert = SelectMdmCertificate(store.Certificates.OfType<X509Certificate2>());
|
||||
if (cert != null)
|
||||
{
|
||||
logger?.Info($"Found MDM certificate: Issuer={cert.Issuer}, Subject={cert.Subject}, Thumbprint={cert.Thumbprint}");
|
||||
logger?.Debug($"Found MDM certificate: Issuer={cert.Issuer}, Subject={cert.Subject}, Thumbprint={cert.Thumbprint}");
|
||||
return cert;
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
logger?.Warning("No MDM certificate found");
|
||||
if (logNotFound) logger?.Warning("No MDM certificate found");
|
||||
return null;
|
||||
}
|
||||
catch (Exception ex)
|
||||
|
||||
@@ -64,7 +64,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
|
||||
watcher.Changed += (sender, args) =>
|
||||
{
|
||||
_logger?.Debug($"CompositeRegistryChangeSignal: {label} change detected.");
|
||||
_logger?.Trace($"CompositeRegistryChangeSignal: {label} change detected.");
|
||||
Changed?.Invoke(this, EventArgs.Empty);
|
||||
};
|
||||
watcher.Error += (sender, ex) =>
|
||||
|
||||
@@ -36,7 +36,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
|
||||
while (!cancellationToken.IsCancellationRequested)
|
||||
{
|
||||
var cert = CertificateHelper.FindMdmCertificate(thumbprint, logger);
|
||||
// Not finding the certificate is the expected answer of most polls; the start, the
|
||||
// minute status and the result below tell the story.
|
||||
var cert = CertificateHelper.FindMdmCertificate(thumbprint, logger, logNotFound: false);
|
||||
|
||||
if (cert != null)
|
||||
{
|
||||
@@ -64,7 +66,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
{
|
||||
var remaining = timeout - totalElapsed;
|
||||
var storeSummary = GetCertificateStoreSummary();
|
||||
logger?.Info($"Await-enrollment: Waiting for MDM certificate... " +
|
||||
logger?.Debug($"Await-enrollment: Waiting for MDM certificate... " +
|
||||
$"(elapsed: {FormatElapsed(totalElapsed)}, remaining: {FormatElapsed(remaining)}, {storeSummary})");
|
||||
lastLogTime = DateTime.UtcNow;
|
||||
}
|
||||
|
||||
@@ -106,7 +106,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
{
|
||||
try
|
||||
{
|
||||
logger.Info($"Registering session with backend (attempt {attempt}/{MaxAttempts})");
|
||||
logger.Debug($"Registering session with backend (attempt {attempt}/{MaxAttempts})");
|
||||
var response = await apiClient.RegisterSessionAsync(registration).ConfigureAwait(false);
|
||||
|
||||
if (response != null && response.Success)
|
||||
@@ -195,7 +195,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
if (attempt < MaxAttempts)
|
||||
{
|
||||
var delaySeconds = (int)Math.Pow(2, attempt); // 2, 4, 8, 16, 32
|
||||
logger.Info($"Retrying session registration in {delaySeconds}s");
|
||||
logger.Debug($"Retrying session registration in {delaySeconds}s");
|
||||
await backoffDelay(attempt).ConfigureAwait(false);
|
||||
}
|
||||
}
|
||||
|
||||
@@ -30,25 +30,46 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
/// Production entry point. Returns the resolved TenantId, or <c>null</c> when
|
||||
/// timed out / cancelled. <paramref name="timeoutSeconds"/> <= 0 short-circuits
|
||||
/// to <c>null</c> immediately (legacy fast-fail behaviour — caller should also
|
||||
/// gate on the same condition).
|
||||
/// gate on the same condition). The caller probes with its logger first, so this
|
||||
/// method only re-checks silently.
|
||||
/// </summary>
|
||||
public static string WaitForTenantId(int timeoutSeconds, AgentLogger logger, CancellationToken ct)
|
||||
public static string WaitForTenantId(int timeoutSeconds, AgentLogger logger, CancellationToken ct) =>
|
||||
WaitForTenantId(
|
||||
timeoutSeconds, logger, ct,
|
||||
resolve: TenantIdResolver.Resolve,
|
||||
signalFactory: () => new CompositeRegistryChangeSignal(logger));
|
||||
|
||||
/// <summary>
|
||||
/// Test-visible body of <see cref="WaitForTenantId(int, AgentLogger, CancellationToken)"/>.
|
||||
/// <paramref name="resolve"/> stands for <see cref="TenantIdResolver.Resolve"/>: a null
|
||||
/// logger probes silently.
|
||||
/// </summary>
|
||||
internal static string WaitForTenantId(
|
||||
int timeoutSeconds,
|
||||
AgentLogger logger,
|
||||
CancellationToken ct,
|
||||
Func<AgentLogger, string> resolve,
|
||||
Func<IRegistryChangeSignal> signalFactory)
|
||||
{
|
||||
if (timeoutSeconds <= 0)
|
||||
return null;
|
||||
|
||||
// Initial probe with the real logger so the resolver emits its source-tag
|
||||
// Info line on hit / its full diagnostic block on miss exactly once.
|
||||
var initial = TenantIdResolver.Resolve(logger);
|
||||
// The caller probed with its logger a moment ago (AgentBootstrap: the source line on a
|
||||
// hit, the full diagnostic block on a miss), so this re-check stays silent and the
|
||||
// block lands once. A hit re-probes with the logger for the source line.
|
||||
var initial = resolve(null);
|
||||
if (!string.IsNullOrWhiteSpace(initial))
|
||||
{
|
||||
resolve(logger);
|
||||
return initial;
|
||||
}
|
||||
|
||||
logger?.Info($"TenantIdAwaiter: TenantId not yet resolvable — waiting up to {timeoutSeconds}s for registry signal.");
|
||||
|
||||
using (var signal = new CompositeRegistryChangeSignal(logger))
|
||||
using (var signal = signalFactory())
|
||||
{
|
||||
var hit = WaitForTenantIdCore(
|
||||
probe: () => TenantIdResolver.Resolve(null), // silent during wait — initial probe already logged
|
||||
probe: () => resolve(null), // silent during the wait
|
||||
signal: signal,
|
||||
timeoutSeconds: timeoutSeconds,
|
||||
periodicReprobeMs: DefaultPeriodicReprobeMs,
|
||||
@@ -61,7 +82,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
// Re-probe once with the real logger so the source-tag Info line
|
||||
// (e.g. "resolved TenantId=… from cloud_domain_join_tenant_info")
|
||||
// lands in the log alongside the awaiter's "resolved after Xs".
|
||||
TenantIdResolver.Resolve(logger);
|
||||
resolve(logger);
|
||||
}
|
||||
return hit;
|
||||
}
|
||||
@@ -127,7 +148,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
}
|
||||
|
||||
if (signalFired)
|
||||
logger?.Debug("TenantIdAwaiter: registry change observed but TenantId still unresolvable.");
|
||||
logger?.Trace("TenantIdAwaiter: registry change observed but TenantId still unresolvable.");
|
||||
}
|
||||
|
||||
logger?.Warning(
|
||||
|
||||
@@ -1,6 +1,7 @@
|
||||
#nullable enable
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals;
|
||||
using AutopilotMonitor.Agent.V2.Core.Orchestration;
|
||||
using AutopilotMonitor.DecisionCore.Engine;
|
||||
@@ -31,6 +32,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
private readonly IClock _clock;
|
||||
private readonly InformationalEventPost _post;
|
||||
private readonly Action? _onRealUserJoined;
|
||||
private readonly AgentLogger? _logger;
|
||||
private bool _fired;
|
||||
private bool _placeholderFired;
|
||||
|
||||
@@ -38,13 +40,15 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
AadJoinWatcher watcher,
|
||||
ISignalIngressSink ingress,
|
||||
IClock clock,
|
||||
Action? onRealUserJoined = null)
|
||||
Action? onRealUserJoined = null,
|
||||
AgentLogger? logger = null)
|
||||
{
|
||||
_watcher = watcher ?? throw new ArgumentNullException(nameof(watcher));
|
||||
_ingress = ingress ?? throw new ArgumentNullException(nameof(ingress));
|
||||
_clock = clock ?? throw new ArgumentNullException(nameof(clock));
|
||||
_post = new InformationalEventPost(ingress, clock);
|
||||
_onRealUserJoined = onRealUserJoined;
|
||||
_logger = logger;
|
||||
|
||||
_watcher.AadUserJoined += OnAadUserJoined;
|
||||
_watcher.PlaceholderUserDetected += OnPlaceholderUserDetected;
|
||||
@@ -117,8 +121,9 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
// Pkt 5 — notify the composition root that a real AAD user has appeared, so the
|
||||
// DesktopArrivalDetector can be reset for the AD-user-after-Hybrid-reboot case.
|
||||
// Fire AFTER the decision signal so reducer-state ordering remains the canonical source.
|
||||
// The callback is best-effort: host wiring must never break the signal post.
|
||||
try { _onRealUserJoined?.Invoke(); }
|
||||
catch { /* callback is best-effort — never let host wiring break the signal post */ }
|
||||
catch (Exception ex) { _logger?.Warning($"AadJoinWatcherAdapter: onRealUserJoined callback threw: {ex.Message}"); }
|
||||
}
|
||||
|
||||
private void EmitPlaceholderInternal(string userEmail)
|
||||
|
||||
@@ -71,7 +71,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
private readonly HashSet<string> _whiteGloveSealingPatternIds;
|
||||
private readonly object _lock = new object();
|
||||
// PR3-D4: optional logger so the largest signal adapter (777 LOC, 0 logger calls
|
||||
// before this PR) gets DEBUG-level visibility into emissions. Null in legacy tests.
|
||||
// before this PR) gets visibility into emissions (mapping lines at Verbose). Null in legacy tests.
|
||||
private readonly AgentLogger? _logger;
|
||||
|
||||
// Previous action-handlers — restored on Dispose so we don't leave a dead callback
|
||||
@@ -104,8 +104,9 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
// Dedup state for DecisionSignals.
|
||||
private string? _lastEspPhase;
|
||||
private bool _userSessionCompletedPosted;
|
||||
// One-shot flag for the user-session-completion deferral trace event — the INFO log
|
||||
// line repeats per suppressed pass, the timeline event fires once per agent run.
|
||||
// One-shot flag for the user-session-completion deferral trace event — the Debug log
|
||||
// line comes per suppressed pass (an identical repeat at Trace), the timeline event once
|
||||
// per agent run.
|
||||
private bool _userSessionDeferralNoted;
|
||||
private bool _sealingPatternPosted;
|
||||
// Fires once per session when a Platform Script stdout contains the Autopilot-Monitor
|
||||
@@ -591,7 +592,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
});
|
||||
}
|
||||
|
||||
_logger?.Debug(
|
||||
_logger?.Verbose(
|
||||
$"ImeAdapter: suppressed historic {eventLabel} for {entityId} "
|
||||
+ $"(source ts {asUtc:o}, age {age.TotalHours:F1}h, suppressed so far: {suppressedSoFar})");
|
||||
return true;
|
||||
@@ -742,7 +743,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
|
||||
/// <summary>
|
||||
/// Observability for the deferred user-session completion (sessions 14690fc2/6cb01530):
|
||||
/// an INFO log line per suppressed pass plus a one-shot <c>agent_trace</c> timeline
|
||||
/// a Debug log line per suppressed pass (an identical repeat at Trace) plus a one-shot <c>agent_trace</c> timeline
|
||||
/// event, so a field session shows WHY <c>ime_user_session_completed</c> arrived late
|
||||
/// (or never) without needing the diagnostics ZIP.
|
||||
/// </summary>
|
||||
@@ -759,8 +760,8 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
var namesJoined = string.Join("; ", names)
|
||||
+ (pendingApps.Count > maxNames ? $" (+{pendingApps.Count - maxNames} more)" : string.Empty);
|
||||
|
||||
_logger?.Info(
|
||||
$"ImeAdapter: IME 'Completed user session' line observed but {pendingApps.Count} required user-ESP app(s) still pending -> deferring ImeUserSessionCompleted (pending: {namesJoined})");
|
||||
_logger?.Debug(
|
||||
$"ImeAdapter: IME 'Completed user session' line observed but {pendingApps.Count} required user-ESP app(s) still pending -> deferring ImeUserSessionCompleted (pending: {namesJoined})", repeatKey: "ImeAdapter.userSessionDeferred");
|
||||
|
||||
lock (_lock)
|
||||
{
|
||||
@@ -907,7 +908,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
// PR5: surface WasAutoDowngradedToSkipped on the same line as the state-transition
|
||||
// log — this is the "why is App X marked Skipped without a download" answer.
|
||||
var autoDowngradeNote = app.WasAutoDowngradedToSkipped ? " auto-downgraded=true (inverse-detection)" : string.Empty;
|
||||
_logger?.Debug(
|
||||
_logger?.Verbose(
|
||||
$"ImeAdapter: app '{app.Name ?? "?"}' ({shortId}) {oldState}->{newState} appType={app.AppType ?? "?"} bytesTotal={app.BytesTotal} terminal={(terminalKind != null)} eventType={eventType}{autoDowngradeNote}");
|
||||
}
|
||||
|
||||
@@ -1109,10 +1110,11 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
data: data,
|
||||
occurredAtUtc: now);
|
||||
|
||||
// PR3-D4: fire-once and useful for compatibility-debugging — INFO level.
|
||||
// PR3-D4: useful for compatibility debugging. IME logs the version on every service start;
|
||||
// an unchanged repeat goes to Trace.
|
||||
_logger?.Info(source.HasData && !string.IsNullOrEmpty(source.DownloadUrl)
|
||||
? $"ImeAdapter: IME agent version detected: {version} (CSP install source: {source.DownloadUrl})"
|
||||
: $"ImeAdapter: IME agent version detected: {version}");
|
||||
: $"ImeAdapter: IME agent version detected: {version}", repeatKey: "ImeAdapter.imeAgentVersion");
|
||||
}
|
||||
|
||||
// IME token-acquisition failure ("Failed to get AAD token ... errorCode = N",
|
||||
@@ -1228,8 +1230,8 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
data: data,
|
||||
occurredAtUtc: now);
|
||||
|
||||
// PR3-D4: per-app DO summary at DEBUG with the headline metrics.
|
||||
_logger?.Debug(
|
||||
// PR3-D4: per-app DO summary at VERBOSE with the headline metrics.
|
||||
_logger?.Verbose(
|
||||
$"ImeAdapter: DO telemetry app='{app.Name ?? "?"}' total={app.DoFileSize} peers={app.DoBytesFromPeers} http={app.DoBytesFromHttp} mode={app.DoDownloadMode}");
|
||||
}
|
||||
|
||||
@@ -1459,9 +1461,9 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
data: data,
|
||||
occurredAtUtc: now);
|
||||
|
||||
// PR3-D4: per-script summary at DEBUG (failures already surface via Severity=Error
|
||||
// PR3-D4: per-script summary at VERBOSE (failures already surface via Severity=Error
|
||||
// in the event itself; the log line carries forensic context for both outcomes).
|
||||
_logger?.Debug(
|
||||
_logger?.Verbose(
|
||||
$"ImeAdapter: script completed policyId={shortId} type={script.ScriptType ?? "?"} result={script.Result ?? "?"} exit={(script.ExitCode.HasValue ? script.ExitCode.Value.ToString() : "n/a")}");
|
||||
|
||||
MaybeEmitBootstrapDetected(script, now);
|
||||
@@ -1640,7 +1642,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
data: data,
|
||||
occurredAtUtc: now);
|
||||
|
||||
_logger?.Debug($"ImeAdapter: script started policyId={shortId} type={info.ScriptType ?? "?"} policyType={info.PolicyType ?? "?"}");
|
||||
_logger?.Verbose($"ImeAdapter: script started policyId={shortId} type={info.ScriptType ?? "?"} policyType={info.PolicyType ?? "?"}");
|
||||
}
|
||||
|
||||
private void EmitScriptRecurrenceSummary(ScriptRecurrenceSummary summary)
|
||||
|
||||
+8
-7
@@ -118,10 +118,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Transport.Telemetry
|
||||
// request produced.
|
||||
var correlationId = Guid.NewGuid().ToString("N");
|
||||
|
||||
// Upload-cadence is pipeline mechanics — keep on Debug so a default Info log
|
||||
// is dominated by lifecycle events. Failures (TIMEOUT/NETWORK/TRANSIENT/PERMANENT)
|
||||
// below stay on Warning/Error so "why didn't my event arrive" surfaces at Info.
|
||||
_logger?.Debug(
|
||||
// The send itself is mechanics (Trace); the success line below is the batch record
|
||||
// (Verbose). Failures (TIMEOUT/NETWORK/TRANSIENT/PERMANENT) stay on Warning/Error so
|
||||
// "why didn't my event arrive" surfaces at Info.
|
||||
_logger?.Trace(
|
||||
$"BackendTelemetryUploader: flushing {items.Count} item(s) (corr={correlationId}, bytes={compressedBody.Length}, firstId={items[0].TelemetryItemId}, lastId={items[items.Count - 1].TelemetryItemId}).");
|
||||
var sw = System.Diagnostics.Stopwatch.StartNew();
|
||||
|
||||
@@ -161,9 +161,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Transport.Telemetry
|
||||
catch (HttpRequestException ex)
|
||||
{
|
||||
sw.Stop();
|
||||
_logger?.Warning($"BackendTelemetryUploader: ingest NETWORK fail after {sw.ElapsedMilliseconds}ms (corr={correlationId}, items={items.Count}): {ex.Message}");
|
||||
var cause = TransportErrorCodes.DescribeSendFailure(ex);
|
||||
_logger?.Warning($"BackendTelemetryUploader: ingest NETWORK fail after {sw.ElapsedMilliseconds}ms (corr={correlationId}, items={items.Count}): {cause}");
|
||||
// DNS failure, socket error, etc. — network-layer is retryable.
|
||||
return UploadResult.Transient($"network: {ex.Message}");
|
||||
return UploadResult.Transient($"network: {cause}");
|
||||
}
|
||||
|
||||
using (response)
|
||||
@@ -173,7 +174,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Transport.Telemetry
|
||||
|
||||
if (result.Success)
|
||||
{
|
||||
_logger?.Debug($"BackendTelemetryUploader: ingest OK (corr={correlationId}, items={items.Count}, durationMs={sw.ElapsedMilliseconds}, status={(int)response.StatusCode}).");
|
||||
_logger?.Verbose($"BackendTelemetryUploader: ingest OK (corr={correlationId}, items={items.Count}, firstId={items[0].TelemetryItemId}, lastId={items[items.Count - 1].TelemetryItemId}, bytes={compressedBody.Length}, durationMs={sw.ElapsedMilliseconds}, status={(int)response.StatusCode}).");
|
||||
}
|
||||
else if (result.IsTransient)
|
||||
{
|
||||
|
||||
@@ -205,10 +205,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Transport.Telemetry
|
||||
if (_pending.Count > _peakPendingCount)
|
||||
_peakPendingCount = _pending.Count;
|
||||
|
||||
// Plan §5 Fix 5 — spool-cadence logging. PR3-A2: VERBOSE (was DEBUG)
|
||||
// because per-item logging hits ~600 lines per session and floods the log
|
||||
// at troubleshoot level. Activate only at micro-repro level.
|
||||
_logger?.Verbose(
|
||||
// Plan §5 Fix 5 — spool-cadence logging. One line per item is mechanics
|
||||
// (well over 1,000 lines per session), so it lives on Trace.
|
||||
_logger?.Trace(
|
||||
$"TelemetrySpool: enqueued itemId={itemId} kind={item.Kind} immediate={item.RequiresImmediateFlush} pending={_pending.Count}.");
|
||||
}
|
||||
|
||||
|
||||
+22
-22
@@ -442,29 +442,17 @@ namespace AutopilotMonitor.Agent.V2.Core.Transport.Telemetry
|
||||
if (pendingPoison != null)
|
||||
{
|
||||
foreach (var poison in pendingPoison)
|
||||
{
|
||||
try { BatchPoisoned?.Invoke(this, poison); }
|
||||
catch { /* handler must not abort the drain result; cursor already advanced */ }
|
||||
}
|
||||
RaiseSafely(nameof(BatchPoisoned), () => BatchPoisoned?.Invoke(this, poison));
|
||||
}
|
||||
|
||||
if (pendingBlockedReason != null)
|
||||
{
|
||||
try { UploadBlocked?.Invoke(this, pendingBlockedReason); }
|
||||
catch { /* handler must not abort the drain result */ }
|
||||
}
|
||||
RaiseSafely(nameof(UploadBlocked), () => UploadBlocked?.Invoke(this, pendingBlockedReason));
|
||||
|
||||
if (pendingSessionGoneReason != null)
|
||||
{
|
||||
try { SessionGone?.Invoke(this, pendingSessionGoneReason); }
|
||||
catch { /* handler must not abort the drain result */ }
|
||||
}
|
||||
RaiseSafely(nameof(SessionGone), () => SessionGone?.Invoke(this, pendingSessionGoneReason));
|
||||
|
||||
if (pendingInterception != null)
|
||||
{
|
||||
try { UploadIntercepted?.Invoke(this, pendingInterception); }
|
||||
catch { /* handler must not abort the drain result */ }
|
||||
}
|
||||
RaiseSafely(nameof(UploadIntercepted), () => UploadIntercepted?.Invoke(this, pendingInterception));
|
||||
|
||||
return result;
|
||||
}
|
||||
@@ -475,15 +463,19 @@ namespace AutopilotMonitor.Agent.V2.Core.Transport.Telemetry
|
||||
/// </summary>
|
||||
private void StartInterceptionPause(ResponseClassification interception)
|
||||
{
|
||||
var firstOfEpisode = _interceptionBackoffStep == 0;
|
||||
var delay = InterceptionBackoffs[Math.Min(_interceptionBackoffStep, InterceptionBackoffs.Count - 1)];
|
||||
_interceptionBackoffStep = Math.Min(_interceptionBackoffStep + 1, InterceptionBackoffs.Count - 1);
|
||||
var now = _clock.UtcNow;
|
||||
Volatile.Write(ref _interceptionWindow, new InterceptionWindow(now, now + delay));
|
||||
|
||||
// The uploader already logged the page finding at Warning; this line adds the schedule.
|
||||
_logger?.Info(
|
||||
// The first pause of an episode is the flow (Info), every re-arm until the path clears is detail.
|
||||
var line =
|
||||
$"TelemetryUploadOrchestrator: upload intercepted ({interception.ForeignReason}, http {interception.StatusCode}) — " +
|
||||
$"batch retained, next attempt not before {now + delay:O} ({delay.TotalSeconds:0}s).");
|
||||
$"batch retained, next attempt not before {now + delay:O} ({delay.TotalSeconds:0}s).";
|
||||
if (firstOfEpisode) _logger?.Info(line);
|
||||
else _logger?.Debug(line);
|
||||
}
|
||||
|
||||
/// <summary>A successful upload ends the interception pause and resets the backoff. Called under the drain guard.</summary>
|
||||
@@ -547,11 +539,19 @@ namespace AutopilotMonitor.Agent.V2.Core.Transport.Telemetry
|
||||
{
|
||||
if (!CarriesSignal(outcome)) return;
|
||||
|
||||
try { ServerResponseReceived?.Invoke(this, outcome); }
|
||||
catch
|
||||
RaiseSafely(nameof(ServerResponseReceived), () => ServerResponseReceived?.Invoke(this, outcome));
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Handler exceptions must not abort the drain result: the upload already happened and the
|
||||
/// cursor has moved. They are still bugs, so the event and the exception get a Warning.
|
||||
/// </summary>
|
||||
private void RaiseSafely(string eventName, Action raise)
|
||||
{
|
||||
try { raise(); }
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Handler exceptions MUST NOT abort the drain loop — the upload itself succeeded,
|
||||
// and the cursor is already forwarded. Swallow + log via the caller's logger chain.
|
||||
_logger?.Warning($"TelemetryUploadOrchestrator: {eventName} handler threw: {ex.Message}");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -287,7 +287,7 @@ namespace AutopilotMonitor.Agent.V2.Runtime
|
||||
{
|
||||
if (!latch.TryEnter())
|
||||
{
|
||||
logger.Debug($"Backend repeated AdminAction={adminAction} — already handled in this process, ignoring.");
|
||||
logger.Debug($"Backend repeated AdminAction={adminAction} — already handled in this process, ignoring.", repeatKey: "ServerControlPlane.repeatedAdminAction");
|
||||
return;
|
||||
}
|
||||
|
||||
|
||||
@@ -0,0 +1,191 @@
|
||||
using Azure.Data.Tables;
|
||||
using AutopilotMonitor.Functions.Services;
|
||||
using AutopilotMonitor.Shared;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Functions.Tests;
|
||||
|
||||
/// <summary>
|
||||
/// D-393: a failed IME app row whose failure event carried no code takes IME's code from the
|
||||
/// registry. The log line that first marks the failure ("Installation is timeout") has no code;
|
||||
/// IME's code follows seconds later in its report and in the registry, but the app is already
|
||||
/// Error, so the agent sends no second event. Pins the pure pieces behind
|
||||
/// <see cref="TableStorageService.ResolveRegistryFailureCodesForSessionAsync"/>: which registry
|
||||
/// code counts (<see cref="TableStorageService.LatestRegistryErrorCodes"/>), which rows may be
|
||||
/// filled (<see cref="TableStorageService.IsRegistryFailureCodeCandidate"/>) and the attempt
|
||||
/// boundary (<see cref="TableStorageService.RegistryFailureCodeFor"/>).
|
||||
/// </summary>
|
||||
public class AppInstallRegistryFailureCodeTests
|
||||
{
|
||||
private static readonly DateTime T0 = new(2026, 10, 29, 21, 15, 0, DateTimeKind.Utc);
|
||||
|
||||
private const string IdA = "aaaaaaaa-1111-2222-3333-444444444444";
|
||||
private const string IdB = "bbbbbbbb-1111-2222-3333-444444444444";
|
||||
|
||||
// Field case 2026-10-29: IME-ERROR-TIMEOUT without a code, the registry 13 s later.
|
||||
private const string ProcessTimeout = "-2016214839"; // 0x87D300C9
|
||||
private const string NotDetectedAfterInstall = "-2016345060"; // 0x87D1041C
|
||||
|
||||
private static EnrollmentEvent Registry(
|
||||
string appId, string enforcementClass, object? errorCode, DateTime at, long sequence = 1)
|
||||
{
|
||||
var data = new Dictionary<string, object>
|
||||
{
|
||||
["appId"] = appId,
|
||||
["enforcementClass"] = enforcementClass,
|
||||
};
|
||||
if (errorCode != null) data["errorCode"] = errorCode;
|
||||
return new EnrollmentEvent
|
||||
{
|
||||
EventType = Constants.EventTypes.RegistryAppState,
|
||||
Timestamp = at,
|
||||
Sequence = sequence,
|
||||
Data = data,
|
||||
};
|
||||
}
|
||||
|
||||
private static TableEntity Row(
|
||||
string? appId = IdA,
|
||||
string status = "Failed",
|
||||
string? failureCode = null,
|
||||
string? source = null,
|
||||
bool collision = false,
|
||||
DateTime? lastAttemptStartedAt = null,
|
||||
DateTime? startedAt = null)
|
||||
{
|
||||
var row = new TableEntity("tenant", "session_App") { ["Status"] = status };
|
||||
if (appId != null) row["AppId"] = appId;
|
||||
if (failureCode != null) row["FailureCode"] = failureCode;
|
||||
if (source != null) row["Source"] = source;
|
||||
if (collision) row["AppIdCollision"] = true;
|
||||
if (lastAttemptStartedAt.HasValue) row["LastAttemptStartedAt"] = new DateTimeOffset(lastAttemptStartedAt.Value);
|
||||
if (startedAt.HasValue) row["StartedAt"] = new DateTimeOffset(startedAt.Value);
|
||||
return row;
|
||||
}
|
||||
|
||||
// ── which registry code counts ──────────────────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public void Codes_LatestErrorPerApp_WinsInAnyInputOrder_AndIsCanonical()
|
||||
{
|
||||
var older = Registry(IdA, "error", ProcessTimeout, T0);
|
||||
var newer = Registry(IdA, "error", NotDetectedAfterInstall, T0.AddMinutes(5));
|
||||
|
||||
foreach (var events in new[] { new[] { older, newer }, new[] { newer, older } })
|
||||
{
|
||||
var codes = TableStorageService.LatestRegistryErrorCodes(events);
|
||||
Assert.Equal(("0x87d1041c", T0.AddMinutes(5)), codes[IdA]);
|
||||
}
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Codes_SameTimestamp_HigherSequenceWins()
|
||||
{
|
||||
var codes = TableStorageService.LatestRegistryErrorCodes(new[]
|
||||
{
|
||||
Registry(IdA, "error", NotDetectedAfterInstall, T0, sequence: 9),
|
||||
Registry(IdA, "error", ProcessTimeout, T0, sequence: 4),
|
||||
});
|
||||
|
||||
Assert.Equal("0x87d1041c", codes[IdA].Code);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Codes_OnlyErrorStatesWithANonZeroCodeCount()
|
||||
{
|
||||
var codes = TableStorageService.LatestRegistryErrorCodes(new[]
|
||||
{
|
||||
Registry(IdA, "inProgress", ProcessTimeout, T0),
|
||||
Registry(IdA, "success", "0", T0),
|
||||
Registry(IdA, "error", null, T0), // WinGet report without a code: the registry has none either
|
||||
Registry(IdA, "error", "0", T0),
|
||||
Registry(IdA, "error", "not-a-code", T0),
|
||||
});
|
||||
|
||||
Assert.Empty(codes);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Codes_ReadNativeNumbers_AndMatchAppIdsCaseInsensitively()
|
||||
{
|
||||
// Stored event data comes back as native .NET values, not only as strings.
|
||||
var codes = TableStorageService.LatestRegistryErrorCodes(new[]
|
||||
{
|
||||
Registry(IdA.ToUpperInvariant(), "error", -2016214839L, T0),
|
||||
});
|
||||
|
||||
Assert.Equal("0x87d300c9", codes[IdA].Code);
|
||||
}
|
||||
|
||||
// ── which rows may be filled ────────────────────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public void Candidate_FailedImeRowWithAppIdAndNoCode()
|
||||
{
|
||||
Assert.True(TableStorageService.IsRegistryFailureCodeCandidate(Row()));
|
||||
Assert.True(TableStorageService.IsRegistryFailureCodeCandidate(Row(source: "ime")));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Candidate_NeverOtherChannelsStatesIdentitiesOrRowsWithACode()
|
||||
{
|
||||
Assert.False(TableStorageService.IsRegistryFailureCodeCandidate(Row(source: "realmjoin")));
|
||||
Assert.False(TableStorageService.IsRegistryFailureCodeCandidate(Row(status: "Succeeded")));
|
||||
Assert.False(TableStorageService.IsRegistryFailureCodeCandidate(Row(status: "Incomplete")));
|
||||
Assert.False(TableStorageService.IsRegistryFailureCodeCandidate(Row(failureCode: "1603"))); // event code stays
|
||||
Assert.False(TableStorageService.IsRegistryFailureCodeCandidate(Row(failureCode: "esp_apps_timeout"))); // failureType stays
|
||||
Assert.False(TableStorageService.IsRegistryFailureCodeCandidate(Row(appId: null)));
|
||||
Assert.False(TableStorageService.IsRegistryFailureCodeCandidate(Row(collision: true)));
|
||||
}
|
||||
|
||||
// ── the attempt boundary ────────────────────────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public void FailureCode_FilledFromTheRegistryErrorOfTheLastAttempt()
|
||||
{
|
||||
var codes = TableStorageService.LatestRegistryErrorCodes(new[]
|
||||
{
|
||||
Registry(IdA, "error", ProcessTimeout, T0.AddMinutes(60)),
|
||||
});
|
||||
|
||||
Assert.Equal("0x87d300c9", TableStorageService.RegistryFailureCodeFor(Row(lastAttemptStartedAt: T0), codes));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void FailureCode_RegistryErrorOfAnEarlierAttempt_IsNotUsed()
|
||||
{
|
||||
var codes = TableStorageService.LatestRegistryErrorCodes(new[]
|
||||
{
|
||||
Registry(IdA, "error", ProcessTimeout, T0),
|
||||
});
|
||||
|
||||
Assert.Null(TableStorageService.RegistryFailureCodeFor(Row(lastAttemptStartedAt: T0.AddMinutes(5)), codes));
|
||||
// Without an attempt anchor the first observation bounds it.
|
||||
Assert.Null(TableStorageService.RegistryFailureCodeFor(Row(startedAt: T0.AddMinutes(5)), codes));
|
||||
Assert.Equal("0x87d300c9", TableStorageService.RegistryFailureCodeFor(Row(startedAt: T0.AddMinutes(-5)), codes));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void FailureCode_NoObservedStart_TakesTheRegistryCode()
|
||||
{
|
||||
var codes = TableStorageService.LatestRegistryErrorCodes(new[]
|
||||
{
|
||||
Registry(IdA, "error", ProcessTimeout, T0),
|
||||
});
|
||||
|
||||
Assert.Equal("0x87d300c9", TableStorageService.RegistryFailureCodeFor(Row(), codes));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void FailureCode_OtherAppOrNonCandidate_StaysEmpty()
|
||||
{
|
||||
var codes = TableStorageService.LatestRegistryErrorCodes(new[]
|
||||
{
|
||||
Registry(IdB, "error", ProcessTimeout, T0),
|
||||
});
|
||||
|
||||
Assert.Null(TableStorageService.RegistryFailureCodeFor(Row(), codes));
|
||||
Assert.Null(TableStorageService.RegistryFailureCodeFor(Row(appId: IdB, failureCode: "0x87d1041c"), codes));
|
||||
}
|
||||
}
|
||||
+3
@@ -149,6 +149,9 @@ namespace AutopilotMonitor.Functions.DataAccess.TableStorage
|
||||
public Task ResolveEspBlockingForSessionAsync(string tenantId, string sessionId)
|
||||
=> _storage.ResolveEspBlockingForSessionAsync(tenantId, sessionId);
|
||||
|
||||
public Task<int> ResolveRegistryFailureCodesForSessionAsync(string tenantId, string sessionId)
|
||||
=> _storage.ResolveRegistryFailureCodesForSessionAsync(tenantId, sessionId);
|
||||
|
||||
public Task<int> CloseOpenAppInstallsForSessionAsync(string tenantId, string sessionId)
|
||||
=> _storage.CloseOpenAppInstallsForSessionAsync(tenantId, sessionId);
|
||||
|
||||
|
||||
+4
@@ -111,6 +111,10 @@ namespace AutopilotMonitor.Functions.DataAccess.TableStorage
|
||||
// complete. Positive evidence only (listed ⇒ EspBlocking=true, absent ⇒ stays
|
||||
// unknown). Idempotent + fail-soft like the counter reconcile above.
|
||||
await _storage.ResolveEspBlockingForSessionAsync(tenantId, sessionId);
|
||||
// D-393: a failed app row whose failure event carried no code takes IME's code
|
||||
// from the registry (same AppId join). Fill only; the shutdown batch and the
|
||||
// sweep re-run it for registry events that land after the verdict.
|
||||
await _storage.ResolveRegistryFailureCodesForSessionAsync(tenantId, sessionId);
|
||||
// Observation end: app rows still InProgress on a terminal session never get a
|
||||
// terminal event — close them as Incomplete (outcome unknown, not a failure).
|
||||
// Early for the ingest path (verdict batch, the agent may still be watching),
|
||||
|
||||
@@ -277,6 +277,8 @@ namespace AutopilotMonitor.Functions.Services
|
||||
// batch; this re-run catches rows opened after the verdict (the IME keeps installing
|
||||
// and the agent keeps watching after enrollment_complete). Non-terminal sessions
|
||||
// (reboot shutdown, WhiteGlove part 1) keep their rows open. Idempotent + fail-soft.
|
||||
// Same re-run for the registry failure codes (D-393): IME's registry code follows a
|
||||
// codeless failure by seconds and often lands after the verdict batch.
|
||||
if (classification.AgentShutdownEvent != null
|
||||
&& snapshot != null
|
||||
&& (snapshot.Status == SessionStatus.Succeeded
|
||||
@@ -284,6 +286,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
|| snapshot.Status == SessionStatus.Incomplete))
|
||||
{
|
||||
await _metricsRepo.CloseOpenAppInstallsForSessionAsync(request.TenantId, request.SessionId);
|
||||
await _metricsRepo.ResolveRegistryFailureCodesForSessionAsync(request.TenantId, request.SessionId);
|
||||
}
|
||||
|
||||
// Auto-analyze fan-out: enqueue a queue message instead of running fire-and-forget
|
||||
|
||||
@@ -334,6 +334,8 @@ namespace AutopilotMonitor.Functions.Services
|
||||
// Same late-batch reasoning: an app row opened after the agent's
|
||||
// shutdown batch was never closed — the sweep is its self-heal.
|
||||
await _metricsRepo.CloseOpenAppInstallsForSessionAsync(session.TenantId, session.SessionId);
|
||||
// And a registry failure code (D-393) that arrived with a late batch.
|
||||
await _metricsRepo.ResolveRegistryFailureCodesForSessionAsync(session.TenantId, session.SessionId);
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
Some files were not shown because too many files have changed in this diff Show More
Reference in New Issue
Block a user