From 4ebd60fb1e222dadde62469b884cbf7af0dab2bc Mon Sep 17 00:00:00 2001 From: Oliver Kieselbach Date: Tue, 28 Jul 2026 15:59:30 +0200 Subject: [PATCH] =?UTF-8?q?feat:=20EnableGatherRuleDebugLog=20=E2=80=94=20?= =?UTF-8?q?per-tenant=20gather-rule=20debug=20trace=20(ConfigVersion=2036)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Customers cannot tell why a gather rule produces nothing in the timeline (e.g. a logparser rule with emit_mode on_change that never emits). New per-tenant boolean EnableGatherRuleDebugLog (EnableImeMatchLog-style plumbing end to end): when enabled, the agent writes %ProgramData%\AutopilotMonitor\Logs\gather_rules_debug.log with one pipe-delimited line per evaluation decision across all previously silent "produced nothing" exits — disabled rules, interval without intervalSeconds, first-tick-after-one-full-interval, phase-scope skips incl. currentPhase=Unknown, per-(rule, phase) dedup, empty collector results (emitOnlyIfExists), on_change hash suppression (hash prefix + streak), guard blocks, logparser per-file outcomes (position skips, format=text hint when every line fails CMTrace parsing, maxLines and wildcard caps), and full exception stacks the agent log drops. - Backend: ConfigVersion 35 -> 36; TenantConfiguration/AgentConfigResponse field + TableConfigRepository Store+Map - Agent: GatherRuleDebugLog writer (10 MB cap, one .old generation, failures swallowed, optional console echo), GatherRuleContext.DebugLog (null-safe no-op), trace points in executor + collectors; never writes under _scopeLock (reasons captured inside, written after release); merger bool->path projection with --gather-debug-log CLI override tolerance; deliberately NOT in the offline-cache strip lists; --run-gather-rules always traces; zero-rules delivery leaves a one-line file instead of nothing - Side fix: GatherRuleExecutorHost now passes the logger into InformationalEventPost so gather-event emissions hit the DEBUG log - Web: tenant settings toggle (Settings -> Agent) + admin tenant-config report rows - Tests: merger on/off/override, writer format+rotation, executor debug lines, logparser debug lines (agent 2131, backend 3561, tsc green) - Docs: docs/agent/gather-rule-debug-log.md + index/log entries Co-Authored-By: Claude Fable 5 --- docs/agent/gather-rule-debug-log.md | 108 ++++++++++ docs/index.md | 1 + docs/log.md | 4 + .../Configuration/RemoteConfigMergerTests.cs | 48 +++++ .../Gather/GatherRuleDebugLogTests.cs | 104 ++++++++++ .../Gather/GatherRuleExecutorDebugLogTests.cs | 156 +++++++++++++++ .../Gather/LogParserCollectorDebugLogTests.cs | 121 +++++++++++ .../Configuration/AgentConfiguration.cs | 7 + .../Configuration/RemoteConfigMerger.cs | 18 ++ .../Configuration/RemoteConfigService.cs | 1 + .../Gather/Collectors/LogParserCollector.cs | 45 ++++- .../Gather/Collectors/RegistryCollector.cs | 4 + .../Telemetry/Gather/GatherRuleContext.cs | 17 +- .../Telemetry/Gather/GatherRuleDebugLog.cs | 115 +++++++++++ .../Telemetry/Gather/GatherRuleExecutor.cs | 188 +++++++++++++++++- .../Orchestration/DefaultComponentFactory.cs | 11 +- .../Hosts/GatherRuleExecutorHost.cs | 8 +- .../Program.GatherRulesMode.cs | 14 +- .../AutopilotMonitor.Agent.V2/Program.cs | 3 + .../TableStorage/TableConfigRepository.cs | 2 + .../Config/GetAgentConfigFunction.cs | 3 +- .../AutopilotMonitor.Shared/Constants.cs | 7 + .../Models/Config/AgentConfigResponse.cs | 6 + .../Models/Config/TenantConfiguration.cs | 9 + .../sections/SectionTenantConfigReport.tsx | 6 + .../app/settings/TenantConfigContext.tsx | 9 +- .../agent/sections/SectionAgentSettings.tsx | 3 + .../components/AgentSettingsSection.tsx | 19 ++ .../app/settings/types.ts | 1 + 29 files changed, 1017 insertions(+), 21 deletions(-) create mode 100644 docs/agent/gather-rule-debug-log.md create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Gather/GatherRuleDebugLogTests.cs create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Gather/GatherRuleExecutorDebugLogTests.cs create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Gather/LogParserCollectorDebugLogTests.cs create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/GatherRuleDebugLog.cs diff --git a/docs/agent/gather-rule-debug-log.md b/docs/agent/gather-rule-debug-log.md new file mode 100644 index 00000000..6e7948e5 --- /dev/null +++ b/docs/agent/gather-rule-debug-log.md @@ -0,0 +1,108 @@ +--- +type: Concept +title: Gather Rule Debug Log — the per-tenant evaluation trace for rules that produce nothing +description: EnableGatherRuleDebugLog (ConfigVersion 36) makes the agent write a local trace file explaining every gather-rule evaluation decision — scope skips, missing intervalSeconds, on_change suppression, empty collector results, logparser position/parse-mode/no-match outcomes — so customers can self-diagnose rules that never show up in the timeline. +resource: /src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/GatherRuleDebugLog.cs +tags: + - agent + - gather-rules + - diagnostics + - tenant-configuration +timestamp: 2026-07-28T00:00:00+02:00 +--- + +# Gather Rule Debug Log + +## Schema + +### The problem + +A gather rule that produces no timeline events is indistinguishable from a rule that +never ran. The pipeline has many *silent-nothing* exits — before this feature, none of +them were visible to the customer: + +| # | Decision point | Where | +|---|---|---| +| 1 | Rule delivered but `Enabled=false` | `GatherRuleExecutor.UpdateRules` | +| 2 | `trigger=interval` without `intervalSeconds` — never runs | `UpdateRules` timer filter | +| 3 | Interval timer's first tick comes only after one **full** interval | `UpdateRules` timer creation | +| 4 | Out of phase scope (`activePhases` / `activeFromPhase` not latched); incl. `currentPhase=Unknown` before the first phase signal | `IsRuleInScopeLocked` | +| 5 | phase_change / phase_exit dedup — once per (rule, phase) | `OnPhaseChanged` | +| 6 | Collector returned an **empty** result (e.g. `emitOnlyIfExists=true` and target absent) | `ExecuteRule` | +| 7 | `emit_mode=on_change` — result hash unchanged, emit suppressed | `ShouldEmitOnChange` | +| 8 | Guard blocked the target (emits `security_warning`, but the rule yields no data) | `GatherRuleContext.EmitSecurityWarning` | +| 9 | logparser: no files matched, position tracker says nothing new, regex no-match, plain-text file parsed in default `cmtrace` mode, `maxLines` cap, wildcard capped at 20 files | `LogParserCollector` | +| 10 | Rule execution threw (agent log had only the message, no stack) | `ExecuteRule` catch | + +### The setting + +`TenantConfiguration.EnableGatherRuleDebugLog` (`bool?`, default null→false), served to the +agent as `AgentConfigResponse.EnableGatherRuleDebugLog` — **ConfigVersion 36**. Portal: +Settings → Agent → Settings, toggle "Gather Rule Debug Log", stored via the usual +tenant-config roundtrip (`TableConfigRepository` Store+Map). Also shown in the admin +tenant-config report. + +`RemoteConfigMerger` projects the bool onto a runtime path (same pattern as +`EnableImeMatchLog`): `true` → `Constants.GatherRuleDebugLogPath` = +`%ProgramData%\AutopilotMonitor\Logs\gather_rules_debug.log`; `false` → null, unless a +`--gather-debug-log ` CLI override supplied a non-default path. The field is not +security-sensitive and deliberately **survives the offline config cache**. + +### The trace file + +`GatherRuleDebugLog` is an append-only writer held by `GatherRuleExecutor` and exposed +to collectors via `GatherRuleContext.DebugLog(ruleId, stage, message)` (null-safe no-op +when disabled — zero cost on the normal path). Line format: + +``` +2026-07-28T09:15:02.123Z | RULE-ID | stage | message +``` + +Stages: `config` (registration summary per rule, header, zero-rules note), `trigger` +(timer scheduled, phase/event fired, dedup), `scope` (skips with reason incl. current +phase), `exec` (execution start), `collector` (null/empty results with likely cause), +`guard` (allowlist block), `emit` (event emitted, hash change), `suppress` (on_change +suppression with hash prefix + streak), `logparser` (per-file outcome: lines read, +position range, match count, parse failures, regex timeouts, mode; plus the +`format=text` hint when every line fails CMTrace parsing), `error` (full exception +**with stack trace** — the agent log keeps only the message). + +Volume control: 10 MB cap with a single `.old` rotation generation (~20 MB worst case). +Every write failure is swallowed — tracing must never break gathering. The trace never +leaves the device on its own — but because it lives in the agent log folder +(`Constants.LogDirectory`), the diagnostics package (`DiagnosticsPackageService`, +`*.log` pattern, `AgentLogs/` section) picks it up automatically, so a customer-initiated +diagnostics upload hands the trace to support without manual copying. + +### Semantics + +* **No hot-reload** — the flag is consumed once when `DefaultComponentFactory` builds + the `GatherRuleExecutorHost` at session start (per-enrollment lifecycle, same as + `EnableImeMatchLog`). Enable it in the tenant, then the *next* enrollment writes the + trace. +* **Zero-rules case is traced too** — flag on + backend delivered no gather rules → + a one-shot standalone `config` line, so the file is never just absent. +* **`--run-gather-rules` always traces** (operator diagnostic mode; CLI override or + default path) and mirrors every line to the console under `--console`. + +## Examples + +A logparser rule with `emit_mode=on_change` that "delivers nothing" becomes: + +``` +... | LP-01 | config | registered: trigger=interval, collector=logparser, target=C:\...\app.log, unscoped, emitMode=on_change, interval=300s +... | LP-01 | trigger | interval timer scheduled every 300s (first run after one full interval — no immediate execution) +... | LP-01 | exec | executing: collector=logparser, target=C:\...\app.log +... | LP-01 | logparser | app.log: read 1000 lines from position 0->81234, matched 0, parseFailures=1000, regexTimeouts=0, mode=cmtrace +... | LP-01 | logparser | every line failed CMTrace parsing — if this is a plain-text log, set parameter format=text +``` + +— the answer ("plain-text log parsed in CMTrace mode") is in the file. + +## Citations + +* Executor + trace points: `../../src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/GatherRuleExecutor.cs` +* Writer: `../../src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/GatherRuleDebugLog.cs` +* Config projection: `../../src/Agent/AutopilotMonitor.Agent.V2.Core/Configuration/RemoteConfigMerger.cs` +* Backend serve + ConfigVersion: `../../src/Backend/AutopilotMonitor.Functions/Functions/Config/GetAgentConfigFunction.cs` +* Phase scoping / emit mode background: `../rules/gather-rule-phase-scoping.md` diff --git a/docs/index.md b/docs/index.md index 4ec6f67d..f5ca7cdb 100644 --- a/docs/index.md +++ b/docs/index.md @@ -20,6 +20,7 @@ https://docs.autopilotmonitor.com (separate repository). * [V2 Agent](agent/index.md) - How the on-device agent works: [runtime overview](agent/overview.md), [decision engine](agent/decision-engine.md) (reducer, signals, completion arms), [logs & persistence](agent/logs-and-persistence.md) (signal log, snapshot, crash recovery), [Hello wizard un-skip](agent/hello-wizard-unskip.md) (why a single "WHfB disabled" read never decides completion), [Autopilot ZTD diagnostics](agent/autopilot-ztd-diagnostics.md) (event IDs, diagnostic registry, endpoints, error-code map). * [Build Counter Blob](agent/build-counter-blob.md) - How agent build numbers are minted: shared counter blob with ETag-CAS so local and CI builds never collide; CI additionally attests build provenance (Sigstore). * [Agent Endpoint Migration](agent/endpoint-migration.md) - How the backend re-homes agents to a new API base URL via the config channel (backend move or per-tenant region move): live-fetch-only, allowlist-validated on both sides, one hop, kill wins. +* [Gather Rule Debug Log](agent/gather-rule-debug-log.md) - EnableGatherRuleDebugLog (ConfigVersion 36): the per-tenant local trace file that explains every gather-rule evaluation decision — scope skips, on_change suppression, empty collector results, logparser position/parse-mode outcomes — for rules that produce no timeline events. * [MDM Reboot Coalescing](agent/mdm-reboot-coalescing.md) - Attributing the mid-ESP coalesced reboot ("second sign-in") to the device-assigned policy URIs that forced it: aggregated DM-Enterprise 2800 observations (neutral, flush-time watermark) + the ANALYZE-ESP-005 advisory gated on an actually-observed reboot. * [Secure Boot CA-2023 Detection](agent/secureboot-ca2023-detection.md) - Why ANALYZE-SEC-001 v3 reads the UEFI db/KEK variables directly instead of trusting the SecureBoot\Servicing registry, and how the one-sided uefiCa2023FirmwareConfirmed marker plus a not_exists precondition give absence-tolerant suppression across old and new agents. * [ESP Policy-Provider Stall Detection](agent/esp-policy-provider-stall.md) - The EnrollmentStatusTracking CSP's no-timeout Setup/Apps wait is keyed to the Intune-registered "Sidecar" provider by NAME: co-management's "ConfigMgr" parks the user ESP at "Apps (Identifying)" for days even with TrackingPoliciesCreated=1 (issue #106); the always-on two-arm esp_policy_provider_stalled tripwire (provider_incomplete | sidecar_provider_missing) and the SOFTWARE\Microsoft\Windows\Autopilot gather-rule allowlist entry that surface it. diff --git a/docs/log.md b/docs/log.md index 6840732d..86efff99 100644 --- a/docs/log.md +++ b/docs/log.md @@ -1,5 +1,9 @@ # Log +## 2026-07-28 + +* **Creation**: Added `agent/gather-rule-debug-log.md` — the new per-tenant setting `EnableGatherRuleDebugLog` (ConfigVersion 35 → 36, portal toggle under Settings → Agent, `EnableImeMatchLog`-style bool→path projection in `RemoteConfigMerger`). When enabled, the agent writes `%ProgramData%\AutopilotMonitor\Logs\gather_rules_debug.log`: one pipe-delimited line per evaluation decision across ten previously silent "produced nothing" exits — disabled rules, `interval` without `intervalSeconds` (never runs), the first-tick-after-one-full-interval window, phase-scope skips incl. `currentPhase=Unknown`, per-(rule, phase) dedup, empty collector results (`emitOnlyIfExists`), `on_change` hash suppression (hash prefix + streak), guard blocks, logparser per-file outcomes (position skips, parse failures with a `format=text` hint when every line fails CMTrace parsing, `maxLines`/wildcard caps), and full exception stacks that the agent log drops. 10 MB cap + one `.old` generation; no hot-reload (per-enrollment lifecycle); flag survives the offline config cache; `--run-gather-rules` always traces and echoes under `--console`; zero-rules delivery leaves a one-line file instead of nothing. Side fix: `GatherRuleExecutorHost` now passes the logger into `InformationalEventPost`, so gather-event emissions appear in the agent DEBUG log. + ## 2026-07-27 * **Creation**: Added `web/portal-navigation-prefetch.md` (and a `Web Portal` section to the index) — root cause of the minute-long portal freezes. `GlobalSidebar` and `Navbar` render the whole navigation on every page, so the App Router's default viewport prefetch issued one `?_rsc=` request per visible link against `portal.autopilotmonitor.com` (~10,400 in 14 days). That origin serves the document, the route chunks and the RSC payloads over **HTTP/1.1**, so the six-connection-per-origin cap applies; when the Static Web Apps managed runtime queued the prefetches (p50 91 ms, p95 896 ms, but max 234 s / 21 samples over 30 s), the in-flight prefetches held every socket and the navigation the user wanted could not get one. Measured on the 2026-07-27 17:25 CEST incident: `/admin/presence?_rsc=` 151 s, three siblings finishing within 340 ms of each other at ~37.5 s, all `200`, while the backend API answered in 1.6–2.2 s and `browserTimings` showed `networkDuration` 16 ms against `processingDuration` 225 s. Every navigation Link now sets `prefetch={false}` — these routes are client components behind `ProtectedRoute` that fetch their own data, so the prefetched RSC payload carried no benefit. The doc also records that browser telemetry lives in a **separate** App Insights resource (`AUTOPILOT_MONITOR_WEB_APPINSIGHTS_ID`) that the MCP `query_backend_logs` tool cannot reach, which is why the freezes left no trace in the backend logs. diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Configuration/RemoteConfigMergerTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Configuration/RemoteConfigMergerTests.cs index 3f01a1b4..880de320 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Configuration/RemoteConfigMergerTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Configuration/RemoteConfigMergerTests.cs @@ -285,6 +285,54 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Configuration Assert.Equal(@"C:\Temp\custom-ime.log", agent.ImeMatchLogPath); } + [Fact] + public void Merge_maps_enable_gather_rule_debug_log_true_to_default_path() + { + var agent = NewAgentConfig(); + agent.GatherRuleDebugLogPath = null; + + var remote = FullRemote(); + remote.EnableGatherRuleDebugLog = true; + + RemoteConfigMerger.Merge(agent, remote); + + Assert.False(string.IsNullOrEmpty(agent.GatherRuleDebugLogPath)); + Assert.Equal( + Environment.ExpandEnvironmentVariables(Constants.GatherRuleDebugLogPath), + agent.GatherRuleDebugLogPath); + } + + [Fact] + public void Merge_maps_enable_gather_rule_debug_log_false_clears_path() + { + var agent = NewAgentConfig(); + agent.GatherRuleDebugLogPath = Environment.ExpandEnvironmentVariables(Constants.GatherRuleDebugLogPath); + + var remote = FullRemote(); + remote.EnableGatherRuleDebugLog = false; + + RemoteConfigMerger.Merge(agent, remote); + + Assert.Null(agent.GatherRuleDebugLogPath); + } + + [Fact] + public void Merge_preserves_custom_gather_rule_debug_log_path_when_remote_disables() + { + // A dev-time --gather-debug-log override seeds a non-default path on the + // AgentConfiguration. When the tenant remote flips EnableGatherRuleDebugLog off we + // keep the custom path rather than clobbering a deliberate dev override. + var agent = NewAgentConfig(); + agent.GatherRuleDebugLogPath = @"C:\Temp\custom-gather.log"; + + var remote = FullRemote(); + remote.EnableGatherRuleDebugLog = false; + + RemoteConfigMerger.Merge(agent, remote); + + Assert.Equal(@"C:\Temp\custom-gather.log", agent.GatherRuleDebugLogPath); + } + // ============================================================= Null / partial tolerance [Fact] diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Gather/GatherRuleDebugLogTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Gather/GatherRuleDebugLogTests.cs new file mode 100644 index 00000000..cdecd3ff --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Gather/GatherRuleDebugLogTests.cs @@ -0,0 +1,104 @@ +using System; +using System.IO; +using System.Linq; +using AutopilotMonitor.Agent.V2.Core.Logging; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather; +using AutopilotMonitor.Agent.V2.Core.Tests.Harness; +using Xunit; + +namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Gather +{ + /// + /// Writer unit tests for : line format, lazy directory + /// creation, size-cap rotation, and the null-writer no-op path on the context. + /// + public sealed class GatherRuleDebugLogTests : IDisposable + { + private readonly TempDirectory _tmp = new TempDirectory(); + private readonly AgentLogger _logger; + + public GatherRuleDebugLogTests() + { + _logger = new AgentLogger(_tmp.Path, AgentLogLevel.Info); + } + + public void Dispose() => _tmp.Dispose(); + + private string LogPath => Path.Combine(_tmp.Path, "sub", "gather_rules_debug.log"); + + [Fact] + public void Write_produces_pipe_delimited_line_and_creates_directory_lazily() + { + var log = new GatherRuleDebugLog(LogPath, _logger); + Assert.False(File.Exists(LogPath)); // lazy — nothing until the first write + + log.Write("RULE-1", GatherRuleDebugLog.StageScope, "skipped: out of scope"); + + var lines = File.ReadAllLines(LogPath); + Assert.Equal(2, lines.Length); // header + entry + Assert.Contains("| - | config | -- gather rule debug log started --", lines[0]); + var parts = lines[1].Split(new[] { " | " }, StringSplitOptions.None); + Assert.Equal(4, parts.Length); + Assert.Equal("RULE-1", parts[1]); + Assert.Equal("scope", parts[2]); + Assert.Equal("skipped: out of scope", parts[3]); + } + + [Fact] + public void Write_flattens_newlines_except_for_error_stage() + { + var log = new GatherRuleDebugLog(LogPath, _logger); + log.Write("RULE-1", GatherRuleDebugLog.StageCollector, "line1\r\nline2"); + log.Write("RULE-1", GatherRuleDebugLog.StageError, "boom\r\n at Frame()"); + + var content = File.ReadAllText(LogPath); + Assert.Contains("line1 line2", content); + Assert.Contains(" at Frame()", content); // error stage keeps the stack multi-line + } + + [Fact] + public void Write_null_ruleId_renders_dash() + { + var log = new GatherRuleDebugLog(LogPath, _logger); + log.Write(null, GatherRuleDebugLog.StageConfig, "no rules delivered"); + + Assert.Contains(" | - | config | no rules delivered", File.ReadAllText(LogPath)); + } + + [Fact] + public void Write_rotates_once_when_file_exceeds_cap() + { + var log = new GatherRuleDebugLog(LogPath, _logger, maxBytes: 512); + for (int i = 0; i < 20; i++) + log.Write("RULE-1", GatherRuleDebugLog.StageExec, new string('x', 100)); + + var oldPath = Path.Combine(Path.GetDirectoryName(LogPath), "gather_rules_debug.old.log"); + Assert.True(File.Exists(oldPath), "expected one .old rotation generation"); + Assert.True(File.Exists(LogPath)); + Assert.Contains("-- rotated", File.ReadAllText(LogPath) + File.ReadAllText(oldPath)); + // Never more than one .old generation + Assert.Single(Directory.GetFiles(Path.GetDirectoryName(LogPath), "*.old.log")); + } + + [Fact] + public void WriteStandalone_writes_single_config_line() + { + GatherRuleDebugLog.WriteStandalone(LogPath, "no gather rules delivered by backend — nothing to execute", _logger); + + var lines = File.ReadAllLines(LogPath); + Assert.Contains(lines, l => l.Contains("no gather rules delivered by backend")); + } + + [Fact] + public void Context_DebugLog_is_noop_without_writer() + { + var context = new GatherRuleContext( + _logger, "sess", "tenant", _ => { }, null, new LogFilePositionTracker()); + + context.DebugLog("RULE-1", GatherRuleDebugLog.StageScope, "should not throw, should not write"); + + Assert.False(File.Exists(LogPath)); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Gather/GatherRuleExecutorDebugLogTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Gather/GatherRuleExecutorDebugLogTests.cs new file mode 100644 index 00000000..ec207ee8 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Gather/GatherRuleExecutorDebugLogTests.cs @@ -0,0 +1,156 @@ +using System; +using System.Collections.Generic; +using System.IO; +using AutopilotMonitor.Agent.V2.Core.Logging; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather; +using AutopilotMonitor.Agent.V2.Core.Tests.Harness; +using AutopilotMonitor.Shared.Models; +using Xunit; + +namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Gather +{ + /// + /// Debug-trace coverage of (EnableGatherRuleDebugLog): + /// every "silently produced nothing" outcome must leave an explanatory line in the trace + /// file — registration summary, missing interval, scope skips, on_change suppression, + /// empty collector results. + /// + [Collection("SerialThreading")] // startup rules execute on the shared ThreadPool + public sealed class GatherRuleExecutorDebugLogTests : IDisposable + { + private readonly TempDirectory _tmp = new TempDirectory(); + private readonly GatherRuleExecutor _executor; + private readonly string _debugLogPath; + + private const string AbsentPath = + "HKLM\\SOFTWARE\\AutopilotMonitorTests\\DefinitelyAbsent_7e3a1f4b-0000-0000-0000-000000000000"; + + public GatherRuleExecutorDebugLogTests() + { + var logger = new AgentLogger(_tmp.Path, AgentLogLevel.Info); + _debugLogPath = Path.Combine(_tmp.Path, "gather_rules_debug.log"); + _executor = new GatherRuleExecutor( + "sess", "tenant", _ => { }, logger, + debugLogPath: _debugLogPath) + { + UnrestrictedMode = true + }; + } + + public void Dispose() + { + _executor.Dispose(); + _tmp.Dispose(); + } + + private string TraceContent() => File.Exists(_debugLogPath) ? File.ReadAllText(_debugLogPath) : string.Empty; + + private static GatherRule Rule(string id, Action? mutate = null) + { + var rule = new GatherRule + { + RuleId = id, + Title = id, + CollectorType = "registry", + Target = AbsentPath, + Trigger = "startup", + OutputEventType = "gather_test", + Enabled = true, + }; + mutate?.Invoke(rule); + return rule; + } + + [Fact] + public void UpdateRules_writes_registration_summary_per_rule() + { + _executor.UpdateRules(new List + { + Rule("GATHER-REG-001", r => { r.Trigger = "interval"; r.IntervalSeconds = 3600; r.EmitMode = "on_change"; }), + Rule("GATHER-REG-002", r => r.Enabled = false), + }); + _executor.WaitForStartupRules(30); + + var trace = TraceContent(); + Assert.Contains("GATHER-REG-001 | config | registered: trigger=interval, collector=registry", trace); + Assert.Contains("emitMode=on_change", trace); + Assert.Contains("interval=3600s", trace); + Assert.Contains("GATHER-REG-002 | config | rule disabled — will never run", trace); + Assert.Contains("interval timer scheduled every 3600s (first run after one full interval", trace); + } + + [Fact] + public void UpdateRules_flags_interval_rule_without_intervalSeconds() + { + _executor.UpdateRules(new List + { + Rule("GATHER-NOINT-001", r => { r.Trigger = "interval"; r.IntervalSeconds = null; }), + }); + + Assert.Contains("GATHER-NOINT-001 | error | trigger=interval but intervalSeconds is missing — rule will NEVER run", + TraceContent()); + } + + [Fact] + public void ScopedRule_skip_traces_unknown_phase_reason() + { + var rule = Rule("GATHER-SCOPE-001", r => { r.Trigger = "interval"; r.IntervalSeconds = 3600; r.ActivePhases = new List { "DeviceSetup" }; }); + _executor.UpdateRules(new List { rule }); + + // Synchronous internal check mirrors the timer-tick gate; the reason must name Unknown. + string reason; + Assert.False(_executor.IsRuleInScope(rule, out reason)); + Assert.Contains("currentPhase=Unknown", reason); + } + + [Fact] + public void ScopedStartupRule_deferral_is_traced() + { + _executor.UpdateRules(new List + { + Rule("GATHER-DEFER-001", r => r.ActivePhases = new List { "DeviceSetup" }), + }); + + Assert.Contains("GATHER-DEFER-001 | scope | startup rule deferred — currentPhase=Unknown", TraceContent()); + } + + [Fact] + public void OnChange_suppression_and_reemission_are_traced() + { + var rule = Rule("GATHER-OC-001", r => { r.Trigger = "interval"; r.IntervalSeconds = 3600; r.EmitMode = "on_change"; }); + _executor.UpdateRules(new List { rule }); + + string hashPrefix; + int streak; + var first = new Dictionary { ["exists"] = false }; + Assert.True(_executor.ShouldEmitOnChange(rule, first, out hashPrefix, out streak)); + Assert.Equal(0, streak); + Assert.False(string.IsNullOrEmpty(hashPrefix)); + + Assert.False(_executor.ShouldEmitOnChange(rule, new Dictionary { ["exists"] = false }, out hashPrefix, out streak)); + Assert.Equal(1, streak); + Assert.False(_executor.ShouldEmitOnChange(rule, new Dictionary { ["exists"] = false }, out hashPrefix, out streak)); + Assert.Equal(2, streak); + + var changed = new Dictionary { ["exists"] = true }; + Assert.True(_executor.ShouldEmitOnChange(rule, changed, out hashPrefix, out streak)); + Assert.Equal(2, streak); // the streak that just ended + Assert.Equal(2, changed["suppressedPolls"]); + } + + [Fact] + public void EmptyCollectorResult_is_traced_via_startup_execution() + { + _executor.UpdateRules(new List + { + Rule("GATHER-EMPTY-001", r => r.Parameters = new Dictionary { ["emitOnlyIfExists"] = "true" }), + }); + Assert.True(_executor.WaitForStartupRules(30)); + + var trace = TraceContent(); + Assert.Contains("GATHER-EMPTY-001 | exec | executing: collector=registry", trace); + Assert.Contains("GATHER-EMPTY-001 | collector | registry key/value not found", trace); + Assert.Contains("GATHER-EMPTY-001 | collector | collector returned EMPTY result — nothing emitted", trace); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Gather/LogParserCollectorDebugLogTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Gather/LogParserCollectorDebugLogTests.cs new file mode 100644 index 00000000..76ec419f --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Gather/LogParserCollectorDebugLogTests.cs @@ -0,0 +1,121 @@ +using System; +using System.Collections.Generic; +using System.IO; +using AutopilotMonitor.Agent.V2.Core.Logging; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors; +using AutopilotMonitor.Agent.V2.Core.Tests.Harness; +using AutopilotMonitor.Shared.Models; +using Xunit; + +namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Gather +{ + /// + /// Debug-trace coverage of : the classic + /// "rule delivers nothing" cases must be explained in the trace — zero matches, + /// position-tracker skips, and plain-text logs parsed in the default cmtrace mode. + /// + public sealed class LogParserCollectorDebugLogTests : IDisposable + { + private readonly TempDirectory _tmp = new TempDirectory(); + private readonly List _events = new List(); + private readonly GatherRuleContext _context; + private readonly string _debugLogPath; + + // %TEMP% lives under C:\Users (hard-blocked) — parse targets sit beside the + // test assembly instead, admitted via UnrestrictedMode. + private readonly string _outsideUsers = Path.Combine( + AppContext.BaseDirectory, "gather-debug-tests-" + Guid.NewGuid().ToString("N")); + + public LogParserCollectorDebugLogTests() + { + Directory.CreateDirectory(_outsideUsers); + var logger = new AgentLogger(_tmp.Path, AgentLogLevel.Info); + _debugLogPath = Path.Combine(_tmp.Path, "gather_rules_debug.log"); + _context = new GatherRuleContext( + logger, "sess", "tenant", + evt => _events.Add(evt), + null, + new LogFilePositionTracker(), + new GatherRuleDebugLog(_debugLogPath, logger)) + { + UnrestrictedMode = true + }; + } + + public void Dispose() + { + _tmp.Dispose(); + try { Directory.Delete(_outsideUsers, recursive: true); } catch { /* best effort */ } + } + + private string TraceContent() => File.Exists(_debugLogPath) ? File.ReadAllText(_debugLogPath) : string.Empty; + + private static GatherRule Rule(string target, string pattern, string? format = null) => new GatherRule + { + RuleId = "GATHER-LP-DEBUG", + Title = "logparser debug test", + CollectorType = "logparser", + Target = target, + Parameters = format == null + ? new Dictionary { ["pattern"] = pattern } + : new Dictionary { ["pattern"] = pattern, ["format"] = format }, + Trigger = "startup", + OutputEventType = "logparser_debug_test", + }; + + [Fact] + public void ZeroMatches_writes_per_file_outcome_line() + { + var path = Path.Combine(_outsideUsers, "app.log"); + File.WriteAllText(path, "nothing interesting\nstill nothing\n"); + + new LogParserCollector().Execute(Rule(path, "WILL_NEVER_MATCH_[0-9]+", format: "text"), _context); + + Assert.Empty(_events); + var trace = TraceContent(); + Assert.Contains("app.log: read 2 lines", trace); + Assert.Contains("matched 0", trace); + Assert.Contains("mode=text", trace); + } + + [Fact] + public void SecondRun_without_new_content_traces_position_skip() + { + var path = Path.Combine(_outsideUsers, "twice.log"); + File.WriteAllText(path, "one line\n"); + var rule = Rule(path, "one", format: "text"); + + var collector = new LogParserCollector(); + collector.Execute(rule, _context); // reads the file, advances the position + collector.Execute(rule, _context); // nothing new + + Assert.Contains("twice.log: no new content (position", TraceContent()); + } + + [Fact] + public void PlainTextFile_in_default_cmtrace_mode_gets_format_hint() + { + var path = Path.Combine(_outsideUsers, "plain.log"); + File.WriteAllText(path, "plain line one\nplain line two\n"); + + new LogParserCollector().Execute(Rule(path, "plain"), _context); // default = cmtrace mode + + Assert.Empty(_events); + var trace = TraceContent(); + Assert.Contains("parseFailures=2", trace); + Assert.Contains("every line failed CMTrace parsing — if this is a plain-text log, set parameter format=text", trace); + } + + [Fact] + public void MissingFile_traces_no_files_matched() + { + var path = Path.Combine(_outsideUsers, "does-not-exist.log"); + + new LogParserCollector().Execute(Rule(path, "x", format: "text"), _context); + + Assert.Contains("no files matched target", TraceContent()); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Configuration/AgentConfiguration.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Configuration/AgentConfiguration.cs index 83e4ba56..6c93d107 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Configuration/AgentConfiguration.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Configuration/AgentConfiguration.cs @@ -121,6 +121,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Configuration /// public string ImeMatchLogPath { get; set; } + /// + /// Optional path to write a gather-rule evaluation trace (for debugging). + /// If empty, no trace is written. Set from remote config (EnableGatherRuleDebugLog) + /// or the --gather-debug-log CLI override. + /// + public string GatherRuleDebugLogPath { get; set; } + /// /// Path to directory with real IME log files for log replay. /// When set, the agent replays these logs with time compression instead of reading live logs. diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Configuration/RemoteConfigMerger.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Configuration/RemoteConfigMerger.cs index 6d206cf7..ada0f3ac 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Configuration/RemoteConfigMerger.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Configuration/RemoteConfigMerger.cs @@ -135,6 +135,24 @@ namespace AutopilotMonitor.Agent.V2.Core.Configuration } } + // ---------------- GatherRuleDebugLog: same bool→path projection as ImeMatchLog + // above. `true` expands Constants.GatherRuleDebugLogPath, `false` + // nulls the runtime path unless a --gather-debug-log CLI override + // supplied a non-default path. + if (remoteConfig.EnableGatherRuleDebugLog) + { + agentConfig.GatherRuleDebugLogPath = Environment.ExpandEnvironmentVariables(Constants.GatherRuleDebugLogPath); + } + else + { + var defaultGatherDebugPath = Environment.ExpandEnvironmentVariables(Constants.GatherRuleDebugLogPath); + if (string.IsNullOrEmpty(agentConfig.GatherRuleDebugLogPath) + || string.Equals(agentConfig.GatherRuleDebugLogPath, defaultGatherDebugPath, StringComparison.OrdinalIgnoreCase)) + { + agentConfig.GatherRuleDebugLogPath = null; + } + } + // ---------------- Upload interval / batch — direct, V1 parity (no > 0 gate so a // misconfigured tenant can in theory break uploads, but this // surfaces the config bug instead of silently masking it). diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Configuration/RemoteConfigService.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Configuration/RemoteConfigService.cs index b63f4815..24d2e3f2 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Configuration/RemoteConfigService.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Configuration/RemoteConfigService.cs @@ -327,6 +327,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Configuration KeepLogFile = false, EnableGeoLocation = true, EnableImeMatchLog = false, + EnableGatherRuleDebugLog = false, Collectors = CollectorConfiguration.CreateDefault(), GatherRules = new System.Collections.Generic.List(), ImeLogPatterns = new System.Collections.Generic.List() diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/Collectors/LogParserCollector.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/Collectors/LogParserCollector.cs index 9af4e49f..12a6af2f 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/Collectors/LogParserCollector.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/Collectors/LogParserCollector.cs @@ -25,14 +25,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors { var filePath = rule.Target; if (string.IsNullOrEmpty(filePath)) + { + context.DebugLog(rule.RuleId, GatherRuleDebugLog.StageLogParser, "empty target — nothing to parse"); return null; + } // Expand custom tokens (%LOGGED_ON_USER_PROFILE%) and standard environment variables var userProfilePath = UserProfileResolver.ContainsUserProfileToken(filePath) ? UserProfileResolver.GetLoggedOnUserProfilePath() : null; filePath = UserProfileResolver.ExpandCustomTokens(filePath); if (filePath == null) + { + context.DebugLog(rule.RuleId, GatherRuleDebugLog.StageLogParser, + "target contains %LOGGED_ON_USER_PROFILE% but no user is logged on — skipped this run"); return null; // Token present but no user logged on — skip silently + } // Apply IME log path override if set. The override comes from the local // --ime-log-path flag only (never from remote config), so the operator @@ -66,6 +73,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors string.IsNullOrEmpty(patternStr)) { context.Logger.Warning($"LogParser rule {rule.RuleId} has no 'pattern' parameter"); + context.DebugLog(rule.RuleId, GatherRuleDebugLog.StageError, + "missing 'pattern' parameter — rule can never match"); return null; } @@ -93,6 +102,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors catch (Exception ex) { context.Logger.Warning($"LogParser rule {rule.RuleId} has invalid regex: {ex.Message}"); + context.DebugLog(rule.RuleId, GatherRuleDebugLog.StageError, + $"invalid regex pattern — rule can never match: {ex.Message}"); return null; } @@ -101,6 +112,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors if (resolvedPaths.Count == 0) { context.Logger.Debug($"LogParser rule {rule.RuleId}: no files found for: {filePath}"); + context.DebugLog(rule.RuleId, GatherRuleDebugLog.StageLogParser, + $"no files matched target {filePath}" + (HasWildcard(Path.GetFileName(filePath)) ? " (wildcard)" : "") + " — nothing to parse"); return null; } @@ -144,7 +157,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors try { // Return matched files sorted by last write time (newest first), capped at 20 - return Directory.GetFiles(directory, fileNamePart) + var allMatches = Directory.GetFiles(directory, fileNamePart); + if (allMatches.Length > 20) + context.DebugLog(ruleId, GatherRuleDebugLog.StageLogParser, + $"wildcard matched {allMatches.Length} files — capped to the 20 newest"); + return allMatches .OrderByDescending(f => new FileInfo(f).LastWriteTimeUtc) .Take(20) .ToList(); @@ -152,6 +169,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors catch (Exception ex) { context.Logger.Warning($"LogParser rule {ruleId}: wildcard expansion failed for {filePath}: {ex.Message}"); + context.DebugLog(ruleId, GatherRuleDebugLog.StageError, $"wildcard expansion failed for {filePath}: {ex.Message}"); return new List(); } } @@ -168,10 +186,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors // Nothing new to read if (startPosition >= fileInfo.Length) + { + context.DebugLog(rule.RuleId, GatherRuleDebugLog.StageLogParser, + $"{Path.GetFileName(filePath)}: no new content (position {startPosition} >= length {fileInfo.Length}) — trackPosition=true, nothing re-read"); return; + } int matchCount = 0; int linesRead = 0; + int parseFailCount = 0; + int timeoutCount = 0; long endPosition = startPosition; using (var stream = new FileStream(filePath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite)) @@ -195,6 +219,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors } catch (RegexMatchTimeoutException) { + timeoutCount++; continue; } if (!match.Success) @@ -239,7 +264,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors // CMTrace mode: parse line as CMTrace format, match regex against message CmTraceLogEntry entry; if (!CmTraceLogParser.TryParseLine(line, out entry)) + { + parseFailCount++; continue; + } Match match; try @@ -248,6 +276,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors } catch (RegexMatchTimeoutException) { + timeoutCount++; continue; } if (!match.Success) @@ -301,10 +330,24 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors if (matchCount > 0) context.Logger.Debug($"LogParser rule {rule.RuleId}: {matchCount} matches from {linesRead} lines in {Path.GetFileName(filePath)}"); + + // Per-file outcome — always written so a "matched 0" run is visible too. + context.DebugLog(rule.RuleId, GatherRuleDebugLog.StageLogParser, + $"{Path.GetFileName(filePath)}: read {linesRead} lines from position {startPosition}->{endPosition}, " + + $"matched {matchCount}, parseFailures={parseFailCount}, regexTimeouts={timeoutCount}, mode={(isTextMode ? "text" : "cmtrace")}"); + + if (!isTextMode && linesRead > 0 && parseFailCount == linesRead) + context.DebugLog(rule.RuleId, GatherRuleDebugLog.StageLogParser, + "every line failed CMTrace parsing — if this is a plain-text log, set parameter format=text"); + + if (linesRead == maxLines) + context.DebugLog(rule.RuleId, GatherRuleDebugLog.StageLogParser, + $"stopped at maxLines={maxLines} — remaining content is deferred to the next run"); } catch (Exception ex) { context.Logger.Warning($"LogParser rule {rule.RuleId} failed reading {filePath}: {ex.Message}"); + context.DebugLog(rule.RuleId, GatherRuleDebugLog.StageError, $"failed reading {filePath}: {ex}"); } } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/Collectors/RegistryCollector.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/Collectors/RegistryCollector.cs index beff452f..4a752078 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/Collectors/RegistryCollector.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/Collectors/RegistryCollector.cs @@ -113,7 +113,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors // Suppress the "not found" event when the rule only wants a positive signal. if (emitOnlyIfExists) + { + context.DebugLog(rule.RuleId, GatherRuleDebugLog.StageCollector, + $"registry key/value not found: {path} — emitOnlyIfExists=true, empty result"); return new Dictionary(); // empty → executor emits nothing + } data["exists"] = false; data["path"] = path; diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/GatherRuleContext.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/GatherRuleContext.cs index 2d131d55..3b7ced93 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/GatherRuleContext.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/GatherRuleContext.cs @@ -22,13 +22,20 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather public LogFilePositionTracker FilePositionTracker { get; } public bool UnrestrictedMode { get; set; } + /// + /// Optional gather-rule debug trace writer (EnableGatherRuleDebugLog). Null when + /// tracing is disabled — use for null-safe writes. + /// + public GatherRuleDebugLog DebugWriter { get; } + public GatherRuleContext( AgentLogger logger, string sessionId, string tenantId, Action onEventCollected, string imeLogPathOverride, - LogFilePositionTracker filePositionTracker) + LogFilePositionTracker filePositionTracker, + GatherRuleDebugLog debugLog = null) { Logger = logger ?? throw new ArgumentNullException(nameof(logger)); SessionId = sessionId ?? throw new ArgumentNullException(nameof(sessionId)); @@ -36,8 +43,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather OnEventCollected = onEventCollected ?? throw new ArgumentNullException(nameof(onEventCollected)); ImeLogPathOverride = imeLogPathOverride; FilePositionTracker = filePositionTracker ?? throw new ArgumentNullException(nameof(filePositionTracker)); + DebugWriter = debugLog; } + /// + /// Null-safe write to the gather-rule debug trace. No-op when tracing is disabled. + /// + public void DebugLog(string ruleId, string stage, string message) => DebugWriter?.Write(ruleId, stage, message); + /// /// Emits a security_warning event and returns an empty result dictionary. /// Called when a gather rule targets a path/query not on the allowlist. @@ -45,6 +58,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather public Dictionary EmitSecurityWarning(GatherRule rule, string collectorType, string target) { Logger.Warning($"SECURITY: {collectorType} path blocked by guard: {target} (Rule: {rule.RuleId})"); + DebugLog(rule.RuleId, GatherRuleDebugLog.StageGuard, + $"{collectorType} target blocked by allowlist guard: {target} — security_warning emitted, rule produced no data"); var data = new Dictionary { diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/GatherRuleDebugLog.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/GatherRuleDebugLog.cs new file mode 100644 index 00000000..4b72bcb1 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/GatherRuleDebugLog.cs @@ -0,0 +1,115 @@ +using System; +using System.IO; +using AutopilotMonitor.Agent.V2.Core.Logging; + +namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather +{ + /// + /// Append-only trace file for gather-rule evaluation, enabled per tenant via + /// EnableGatherRuleDebugLog (or --gather-debug-log). Explains every evaluation + /// decision — including the outcomes that produce no event — so customers can + /// diagnose rules that never show up in the timeline. Every write failure is + /// swallowed: tracing must never break gathering. + /// + public sealed class GatherRuleDebugLog + { + public const string StageConfig = "config"; + public const string StageTrigger = "trigger"; + public const string StageScope = "scope"; + public const string StageExec = "exec"; + public const string StageCollector = "collector"; + public const string StageGuard = "guard"; + public const string StageEmit = "emit"; + public const string StageSuppress = "suppress"; + public const string StageLogParser = "logparser"; + public const string StageError = "error"; + + private const long DefaultMaxBytes = 10 * 1024 * 1024; + + private readonly string _path; + private readonly long _maxBytes; + private readonly Action _echo; + private readonly object _lock = new object(); + private bool _headerWritten; + + public GatherRuleDebugLog(string path, AgentLogger logger, Action echo = null, long maxBytes = DefaultMaxBytes) + { + if (string.IsNullOrEmpty(path)) throw new ArgumentNullException(nameof(path)); + _path = path; + _maxBytes = maxBytes; + _echo = echo; + logger?.Info($"GatherRuleDebugLog: enabled -> {path}"); + } + + /// + /// Writes one trace line: {utc} | {ruleId} | {stage} | {message}. + /// Newlines in are flattened except for the error + /// stage, where exception stack traces stay multi-line. + /// + public void Write(string ruleId, string stage, string message) + { + try + { + if (stage != StageError && message != null && message.IndexOf('\n') >= 0) + message = message.Replace("\r", "").Replace('\n', ' '); + + var line = $"{DateTime.UtcNow:yyyy-MM-ddTHH:mm:ss.fffZ} | {ruleId ?? "-"} | {stage} | {message}"; + + lock (_lock) + { + EnsureFileReadyLocked(); + File.AppendAllText(_path, line + Environment.NewLine); + } + + _echo?.Invoke(line); + } + catch { } + } + + /// + /// One-shot helper for callers that have no executor (e.g. the flag is on but the + /// backend delivered zero gather rules) — the customer's trace file should explain + /// that too instead of silently not existing. + /// + public static void WriteStandalone(string path, string message, AgentLogger logger) + { + if (string.IsNullOrEmpty(path)) return; + try + { + new GatherRuleDebugLog(path, logger).Write(null, StageConfig, message); + } + catch { } + } + + // Lazy on first write: create the directory and emit a header line. Before every + // append, rotate when the file exceeds maxBytes — keeping exactly one .old + // generation (worst case ~2x maxBytes on disk). + private void EnsureFileReadyLocked() + { + if (!_headerWritten) + { + var dir = Path.GetDirectoryName(_path); + if (!string.IsNullOrEmpty(dir)) + Directory.CreateDirectory(dir); + } + + var info = new FileInfo(_path); + if (info.Exists && info.Length > _maxBytes) + { + var oldPath = Path.ChangeExtension(_path, null) + ".old.log"; + if (File.Exists(oldPath)) + File.Delete(oldPath); + File.Move(_path, oldPath); + File.AppendAllText(_path, + $"{DateTime.UtcNow:yyyy-MM-ddTHH:mm:ss.fffZ} | - | {StageConfig} | -- rotated (previous file exceeded {_maxBytes} bytes) --" + Environment.NewLine); + } + + if (!_headerWritten) + { + File.AppendAllText(_path, + $"{DateTime.UtcNow:yyyy-MM-ddTHH:mm:ss.fffZ} | - | {StageConfig} | -- gather rule debug log started --" + Environment.NewLine); + _headerWritten = true; + } + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/GatherRuleExecutor.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/GatherRuleExecutor.cs index d3fadff4..fac67fcc 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/GatherRuleExecutor.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Gather/GatherRuleExecutor.cs @@ -22,6 +22,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather public class GatherRuleExecutor : IDisposable { private readonly AgentLogger _logger; + private readonly GatherRuleDebugLog _debug; // null unless EnableGatherRuleDebugLog / --gather-debug-log private readonly GatherRuleContext _context; private readonly Dictionary _collectors; @@ -61,7 +62,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather } public GatherRuleExecutor(string sessionId, string tenantId, Action onEventCollected, - AgentLogger logger, string imeLogPathOverride = null) + AgentLogger logger, string imeLogPathOverride = null, string debugLogPath = null, + Action debugEcho = null) { if (sessionId == null) throw new ArgumentNullException(nameof(sessionId)); if (tenantId == null) throw new ArgumentNullException(nameof(tenantId)); @@ -69,9 +71,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather if (logger == null) throw new ArgumentNullException(nameof(logger)); _logger = logger; + _debug = string.IsNullOrEmpty(debugLogPath) ? null : new GatherRuleDebugLog(debugLogPath, logger, debugEcho); var filePositionTracker = new LogFilePositionTracker(); - _context = new GatherRuleContext(logger, sessionId, tenantId, onEventCollected, imeLogPathOverride, filePositionTracker); + _context = new GatherRuleContext(logger, sessionId, tenantId, onEventCollected, imeLogPathOverride, filePositionTracker, _debug); // Register all collector strategies var collectorList = new IGatherRuleCollector[] @@ -96,6 +99,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather _collectors["command"] = _collectors["command_allowlisted"]; } + /// + /// Null-safe write to the gather-rule debug trace. Never call while holding + /// — capture the message under the lock, write after release. + /// + private void DebugLog(string ruleId, string stage, string message) => _debug?.Write(ruleId, stage, message); + /// /// Updates the active rules and starts/stops execution accordingly /// @@ -111,11 +120,43 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather _activeRules = rules.Where(r => r.Enabled).ToList(); + // Registration summary for the debug trace: one line per delivered rule so the + // customer can see exactly what the agent received and how it will be triggered. + if (_debug != null) + { + foreach (var rule in rules) + { + if (!rule.Enabled) + { + DebugLog(rule.RuleId, GatherRuleDebugLog.StageConfig, "rule disabled — will never run"); + continue; + } + + var scope = rule.ActivePhases != null && rule.ActivePhases.Count > 0 + ? $"activePhases=[{string.Join(",", rule.ActivePhases)}]" + : !string.IsNullOrEmpty(rule.ActiveFromPhase) + ? $"activeFromPhase={rule.ActiveFromPhase}" + : "unscoped"; + DebugLog(rule.RuleId, GatherRuleDebugLog.StageConfig, + $"registered: trigger={rule.Trigger}" + + (string.IsNullOrEmpty(rule.TriggerPhase) ? "" : $" triggerPhase={rule.TriggerPhase}") + + (string.IsNullOrEmpty(rule.TriggerEventType) ? "" : $" triggerEventType={rule.TriggerEventType}") + + $", collector={rule.CollectorType}, target={rule.Target}, {scope}" + + $", emitMode={(string.IsNullOrEmpty(rule.EmitMode) ? "always" : rule.EmitMode)}" + + (rule.IntervalSeconds.HasValue ? $", interval={rule.IntervalSeconds}s" : "")); + + if (rule.Trigger == "interval" && !rule.IntervalSeconds.HasValue) + DebugLog(rule.RuleId, GatherRuleDebugLog.StageError, + "trigger=interval but intervalSeconds is missing — rule will NEVER run"); + } + } + // Execute startup rules — track completion via CountdownEvent so callers can wait. // Scoped startup rules that are not yet in scope are deferred: they run once from // OnPhaseChanged when their scope activates (same _startupRulesExecuted dedup — a // rule runs either here or there, never both). Unscoped rules behave as before. List pendingStartup; + var deferredTraces = _debug != null ? new List>() : null; lock (_scopeLock) { // A config refresh may deliver new from-phase rules after their phase was @@ -124,7 +165,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather pendingStartup = _activeRules .Where(r => r.Trigger == "startup" && !_startupRulesExecuted.Contains(r.RuleId)) - .Where(r => IsRuleInScopeLocked(r)) + .Where(r => + { + string reason; + var inScope = IsRuleInScopeLocked(r, out reason); + if (!inScope && deferredTraces != null) + deferredTraces.Add(new KeyValuePair(r.RuleId, + $"startup rule deferred — {reason}; runs once when its scope activates")); + return inScope; + }) .ToList(); foreach (var rule in pendingStartup) @@ -133,6 +182,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather } } + if (deferredTraces != null) + { + foreach (var trace in deferredTraces) + DebugLog(trace.Key, GatherRuleDebugLog.StageScope, trace.Value); + } + if (pendingStartup.Count > 0) { _startupRulesLatch?.Dispose(); @@ -158,8 +213,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather var timer = new Timer( _ => { - if (!IsRuleInScope(intervalRule)) + string skipReason; + if (!IsRuleInScope(intervalRule, out skipReason)) + { + DebugLog(intervalRule.RuleId, GatherRuleDebugLog.StageScope, $"interval tick skipped: {skipReason}"); return; + } ExecuteRule(intervalRule); }, null, @@ -168,6 +227,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather ); _intervalTimers[intervalRule.RuleId] = timer; _logger.Info($" 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)"); } _logger.Info($"GatherRuleExecutor: {_activeRules.Count(r => r.Trigger == "startup")} startup, " + @@ -187,6 +248,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather // _currentPhase moves below. A transition INTO Failed still fires the exit rules of the // phase that failed — that snapshot is the whole point at a failure boundary. List exitRules = null; + var exitTraces = _debug != null ? new List>() : null; lock (_scopeLock) { var previousPhase = _currentPhase; @@ -204,12 +266,22 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather // Scope gate before the dedup add — an out-of-scope pass must not consume // the once-per-(rule, phase) slot. IsRuleInScopeLocked still sees the old phase. - if (!IsRuleInScopeLocked(rule)) continue; + string scopeReason; + if (!IsRuleInScopeLocked(rule, out scopeReason)) + { + if (exitTraces != null) + exitTraces.Add(new KeyValuePair(rule.RuleId, + $"phase_exit of {previousPhaseName} skipped: {scopeReason}")); + continue; + } // "exit:" prefix keeps this key space disjoint from the phase_change keys. if (!_phaseRulesExecuted.Add($"exit:{rule.RuleId}|{previousPhaseName}")) { _logger.Debug($"Phase-exit rule {rule.RuleId} already executed for exit of {previousPhaseName}, skipping"); + if (exitTraces != null) + exitTraces.Add(new KeyValuePair(rule.RuleId, + $"phase_exit already executed for exit of {previousPhaseName} — once per (rule, phase)")); continue; } @@ -219,6 +291,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather } } + if (exitTraces != null) + { + foreach (var trace in exitTraces) + DebugLog(trace.Key, GatherRuleDebugLog.StageScope, trace.Value); + } + if (exitRules != null) { foreach (var rule in exitRules) @@ -252,6 +330,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather { var deferredRule = rule; _logger.Info($"Phase {phaseName} activated deferred startup rule {deferredRule.RuleId}"); + DebugLog(deferredRule.RuleId, GatherRuleDebugLog.StageTrigger, + $"phase {phaseName} activated deferred startup rule"); ThreadPool.QueueUserWorkItem(_ => ExecuteRule(deferredRule)); } @@ -262,18 +342,26 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather { // Scope gate BEFORE the dedup add — an out-of-scope pass must not consume // the once-per-(rule, phase) execution slot. - if (!IsRuleInScope(rule)) + string scopeReason; + if (!IsRuleInScope(rule, out scopeReason)) + { + DebugLog(rule.RuleId, GatherRuleDebugLog.StageScope, + $"phase_change to {phaseName} skipped: {scopeReason}"); continue; + } // Deduplicate: only fire once per (ruleId, phase) combination var deduplicationKey = $"{rule.RuleId}|{phaseName}"; if (!_phaseRulesExecuted.Add(deduplicationKey)) { _logger.Debug($"Phase rule {rule.RuleId} already executed for phase {phaseName}, skipping"); + DebugLog(rule.RuleId, GatherRuleDebugLog.StageTrigger, + $"phase_change already executed for phase {phaseName} — once per (rule, phase)"); continue; } _logger.Info($"Phase change triggered rule {rule.RuleId} (phase: {phaseName})"); + DebugLog(rule.RuleId, GatherRuleDebugLog.StageTrigger, $"phase_change to {phaseName} fired"); ThreadPool.QueueUserWorkItem(_ => ExecuteRule(rule)); } } @@ -288,10 +376,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather { if (string.Equals(rule.TriggerEventType, eventType, StringComparison.OrdinalIgnoreCase)) { - if (!IsRuleInScope(rule)) + string scopeReason; + if (!IsRuleInScope(rule, out scopeReason)) + { + DebugLog(rule.RuleId, GatherRuleDebugLog.StageScope, + $"on_event {eventType} skipped: {scopeReason}"); continue; + } _logger.Info($"Event triggered rule {rule.RuleId} (event: {eventType})"); + DebugLog(rule.RuleId, GatherRuleDebugLog.StageTrigger, $"on_event {eventType} fired"); ThreadPool.QueueUserWorkItem(_ => ExecuteRule(rule)); } } @@ -302,6 +396,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather try { _logger.Info($"Executing gather rule: {rule.RuleId} ({rule.Title})"); + DebugLog(rule.RuleId, GatherRuleDebugLog.StageExec, $"executing: collector={rule.CollectorType}, target={rule.Target}"); var collectorType = rule.CollectorType?.ToLower(); @@ -309,6 +404,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather if (collectorType == null || !_collectors.TryGetValue(collectorType, out collector)) { _logger.Warning($"Unknown collector type: {rule.CollectorType} for rule {rule.RuleId}"); + DebugLog(rule.RuleId, GatherRuleDebugLog.StageError, $"unknown collector type '{rule.CollectorType}' — nothing emitted"); return; } @@ -316,7 +412,19 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather // LogParser (and potentially others) emit events directly and return null if (result == null) + { + DebugLog(rule.RuleId, GatherRuleDebugLog.StageCollector, + collectorType == "logparser" + ? "logparser emits per-match events directly — see logparser lines above for the per-file outcome" + : "collector returned null — nothing emitted"); return; + } + + if (result.Count == 0) + { + DebugLog(rule.RuleId, GatherRuleDebugLog.StageCollector, + "collector returned EMPTY result — nothing emitted (typical causes: target not found with emitOnlyIfExists, or guard block — see guard line if present)"); + } if (result.Count > 0) { @@ -325,8 +433,19 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather // empty result never reaches this point, so an emitOnlyIfExists miss neither // emits nor updates the hash — composing to "one event on appearance, then // only on change". - if (IsOnChangeMode(rule) && !ShouldEmitOnChange(rule, result)) - return; + if (IsOnChangeMode(rule)) + { + string hashPrefix; + int suppressedStreak; + if (!ShouldEmitOnChange(rule, result, out hashPrefix, out suppressedStreak)) + { + DebugLog(rule.RuleId, GatherRuleDebugLog.StageSuppress, + $"result unchanged (hash {hashPrefix}) — emit suppressed (on_change), suppressed streak={suppressedStreak}"); + return; + } + DebugLog(rule.RuleId, GatherRuleDebugLog.StageEmit, + $"result changed (hash {hashPrefix})" + (suppressedStreak > 0 ? $" after {suppressedStreak} suppressed polls" : "")); + } result["ruleId"] = rule.RuleId; result["ruleTitle"] = rule.Title; @@ -357,11 +476,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather Message = $"Gather: {rule.Title}", Data = result }); + DebugLog(rule.RuleId, GatherRuleDebugLog.StageEmit, + $"emitted {eventType} (severity={severity}, {result.Count} fields)"); } } catch (Exception ex) { _logger.Warning($"Gather rule {rule.RuleId} failed: {ex.Message}"); + // Full exception incl. stack trace only in the debug trace — the agent log stays terse. + DebugLog(rule.RuleId, GatherRuleDebugLog.StageError, $"rule execution failed: {ex}"); } } @@ -375,15 +498,33 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather // Internal so the scope matrix is testable synchronously (no timer/ThreadPool races). internal bool IsRuleInScope(GatherRule rule) + { + string reason; + return IsRuleInScope(rule, out reason); + } + + /// + /// Scope gate with a human-readable skip reason for the debug trace. The reason is + /// captured under the lock but must be WRITTEN outside it (never trace under _scopeLock). + /// + internal bool IsRuleInScope(GatherRule rule, out string reason) { lock (_scopeLock) { - return IsRuleInScopeLocked(rule); + return IsRuleInScopeLocked(rule, out reason); } } private bool IsRuleInScopeLocked(GatherRule rule) { + string reason; + return IsRuleInScopeLocked(rule, out reason); + } + + private bool IsRuleInScopeLocked(GatherRule rule, out string reason) + { + reason = null; + if (!HasPhaseScope(rule)) return true; // unscoped — legacy behavior @@ -400,7 +541,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather // No phase signal yet (or scope tokens that never match, e.g. "Unknown"): // scoped rules stay inactive. if (_currentPhase == EnrollmentPhase.Unknown) + { + reason = "currentPhase=Unknown — scoped rules stay inactive until the first phase signal"; return false; + } var phaseName = _currentPhase.ToString(); foreach (var phase in rule.ActivePhases) @@ -408,10 +552,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather if (string.Equals(phase, phaseName, StringComparison.OrdinalIgnoreCase)) return true; } + reason = $"out of scope (currentPhase={phaseName}, activePhases=[{string.Join(",", rule.ActivePhases)}])"; return false; } - return _fromPhaseLatched.Contains(rule.RuleId); + if (_fromPhaseLatched.Contains(rule.RuleId)) + return true; + + reason = $"activeFromPhase={rule.ActiveFromPhase} not latched yet (currentPhase={_currentPhase})"; + return false; } /// @@ -457,8 +606,23 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather /// Internal so the state machine is testable synchronously (no timer/ThreadPool races). /// internal bool ShouldEmitOnChange(GatherRule rule, Dictionary result) + { + string hashPrefix; + int suppressedStreak; + return ShouldEmitOnChange(rule, result, out hashPrefix, out suppressedStreak); + } + + /// + /// Overload exposing the hash prefix and suppression streak for the debug trace: + /// on suppress, is the updated streak count; + /// on emit, it is the streak that just ended (0 when none). + /// + internal bool ShouldEmitOnChange(GatherRule rule, Dictionary result, + out string hashPrefix, out int suppressedStreak) { var hash = ComputeCanonicalHash(result); + hashPrefix = hash.Length > 8 ? hash.Substring(0, 8) : hash; + suppressedStreak = 0; bool emit; lock (_scopeLock) { @@ -469,6 +633,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather _suppressed[rule.RuleId] = _suppressed.TryGetValue(rule.RuleId, out streak) ? (streak.Count + 1, streak.SinceUtc) : (1, DateTime.UtcNow); + suppressedStreak = _suppressed[rule.RuleId].Count; emit = false; } else @@ -479,6 +644,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather { result["suppressedPolls"] = streak.Count; result["suppressedSinceUtc"] = streak.SinceUtc.ToString("o", CultureInfo.InvariantCulture); + suppressedStreak = streak.Count; } _suppressed.Remove(rule.RuleId); emit = true; diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs index 9b744253..343fd976 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs @@ -483,7 +483,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration logger: logger, rules: _remoteConfig.GatherRules, imeLogPathOverride: _agentConfig.ImeLogPathOverride, - unrestrictedMode: _agentConfig.UnrestrictedMode)); + unrestrictedMode: _agentConfig.UnrestrictedMode, + gatherDebugLogPath: _agentConfig.GatherRuleDebugLogPath)); + } + else if (!string.IsNullOrEmpty(_agentConfig.GatherRuleDebugLogPath)) + { + // Debug trace is on but the backend delivered zero gather rules — the trace + // file must say so instead of silently not existing. + Monitoring.Telemetry.Gather.GatherRuleDebugLog.WriteStandalone( + _agentConfig.GatherRuleDebugLogPath, + "no gather rules delivered by backend — nothing to execute", logger); } return new CollectorSurfaces(hosts, imeLogHost, espAndHelloHost, aadJoinHost); diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/GatherRuleExecutorHost.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/GatherRuleExecutorHost.cs index ff5f9888..a9ed0f7c 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/GatherRuleExecutorHost.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/GatherRuleExecutorHost.cs @@ -39,7 +39,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration AgentLogger logger, List rules, string? imeLogPathOverride, - bool unrestrictedMode = false) + bool unrestrictedMode = false, + string? gatherDebugLogPath = null) { if (ingress == null) throw new ArgumentNullException(nameof(ingress)); if (clock == null) throw new ArgumentNullException(nameof(clock)); @@ -55,9 +56,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration // session mode we wrap post.Emit so every session-mode gather event still // flows through the InformationalEvent ingress pipe before hitting the // telemetry spool — Rail-A semantics for ordering / replay determinism. - var post = new InformationalEventPost(ingress, clock); + var post = new InformationalEventPost(ingress, clock, logger); _executor = new Monitoring.Telemetry.Gather.GatherRuleExecutor( - sessionId, tenantId, evt => post.Emit(evt), logger, imeLogPathOverride); + sessionId, tenantId, evt => post.Emit(evt), logger, imeLogPathOverride, + debugLogPath: gatherDebugLogPath); _observableIngress = ingress as SignalIngress; } diff --git a/src/Agent/AutopilotMonitor.Agent.V2/Program.GatherRulesMode.cs b/src/Agent/AutopilotMonitor.Agent.V2/Program.GatherRulesMode.cs index b9ec9093..10e4bfdc 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2/Program.GatherRulesMode.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2/Program.GatherRulesMode.cs @@ -221,8 +221,18 @@ namespace AutopilotMonitor.Agent.V2 }, }); - // Step 4 — run the executor and wait. - using (var executor = new GatherRuleExecutor(sessionId, tenantId, emitEvent, logger, config.ImeLogPathOverride)) + // Step 4 — run the executor and wait. Diagnostic mode always writes the + // gather-rule debug trace (CLI override or default path) and mirrors it + // to the console in --console mode. + var gatherDebugLogPath = !string.IsNullOrEmpty(config.GatherRuleDebugLogPath) + ? config.GatherRuleDebugLogPath + : Environment.ExpandEnvironmentVariables(Constants.GatherRuleDebugLogPath); + logger.Info($"--run-gather-rules: debug trace -> {gatherDebugLogPath}"); + if (consoleMode) Console.WriteLine($"Debug trace: {gatherDebugLogPath}"); + + using (var executor = new GatherRuleExecutor(sessionId, tenantId, emitEvent, logger, config.ImeLogPathOverride, + debugLogPath: gatherDebugLogPath, + debugEcho: consoleMode ? (Action)(line => Console.WriteLine($" {line}")) : null)) { // Diagnostic mode has no enrollment phase context — scoped rules // (activePhases / activeFromPhase) execute unconditionally here. diff --git a/src/Agent/AutopilotMonitor.Agent.V2/Program.cs b/src/Agent/AutopilotMonitor.Agent.V2/Program.cs index f8b9de7d..af8c5bb8 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2/Program.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2/Program.cs @@ -303,6 +303,7 @@ namespace AutopilotMonitor.Agent.V2 var apiBaseUrl = GetArgValue(args, "--api-url", "--backend-api") ?? Constants.ApiBaseUrl; var imeLogPathOverride = GetArgValue(args, "--ime-log-path"); var imeMatchLogPath = GetArgValue(args, "--ime-match-log"); + var gatherDebugLogPath = GetArgValue(args, "--gather-debug-log"); // Dev / test — IME log replay (V1 compat mode). Feeds ImeLogTracker.SimulationMode // + SpeedFactor so recorded raw IME logs are replayed at an accelerated rate; signal @@ -373,6 +374,7 @@ namespace AutopilotMonitor.Agent.V2 EnableGeoLocation = !disableGeoLocation, ImeLogPathOverride = imeLogPathOverride, ImeMatchLogPath = imeMatchLogPath, + GatherRuleDebugLogPath = gatherDebugLogPath, KeepLogFile = keepLogFile, SelfDestructOnComplete = !noCleanup, CommandLineArgs = FormatArgsForLog(args), @@ -485,6 +487,7 @@ namespace AutopilotMonitor.Agent.V2 Console.Out.WriteLine(" --api-url Override backend API base URL (alias: --backend-api)"); Console.Out.WriteLine(" --ime-log-path Override IME logs directory"); Console.Out.WriteLine(" --ime-match-log Write matched IME log lines to file (debug)"); + Console.Out.WriteLine(" --gather-debug-log Write gather-rule evaluation trace to file (debug)"); Console.Out.WriteLine(); Console.Out.WriteLine("Dev / Test:"); Console.Out.WriteLine(" --replay-log-dir Replay IME logs from this directory (simulation mode)"); diff --git a/src/Backend/AutopilotMonitor.Functions/DataAccess/TableStorage/TableConfigRepository.cs b/src/Backend/AutopilotMonitor.Functions/DataAccess/TableStorage/TableConfigRepository.cs index d56e8c5b..b8964380 100644 --- a/src/Backend/AutopilotMonitor.Functions/DataAccess/TableStorage/TableConfigRepository.cs +++ b/src/Backend/AutopilotMonitor.Functions/DataAccess/TableStorage/TableConfigRepository.cs @@ -413,6 +413,7 @@ namespace AutopilotMonitor.Functions.DataAccess.TableStorage { "EnableTimezoneAutoSet", config.EnableTimezoneAutoSet }, { "NtpServer", config.NtpServer }, { "EnableImeMatchLog", config.EnableImeMatchLog }, + { "EnableGatherRuleDebugLog", config.EnableGatherRuleDebugLog }, { "LogLevel", config.LogLevel }, { "MaxBatchSize", config.MaxBatchSize }, { "DiagnosticsBlobSasUrl", config.DiagnosticsBlobSasUrl }, @@ -514,6 +515,7 @@ namespace AutopilotMonitor.Functions.DataAccess.TableStorage EnableTimezoneAutoSet = entity.GetBoolean("EnableTimezoneAutoSet"), NtpServer = string.IsNullOrWhiteSpace(entity.GetString("NtpServer")) ? "time.windows.com" : entity.GetString("NtpServer"), EnableImeMatchLog = entity.GetBoolean("EnableImeMatchLog"), + EnableGatherRuleDebugLog = entity.GetBoolean("EnableGatherRuleDebugLog"), LogLevel = entity.GetString("LogLevel"), MaxBatchSize = entity.GetInt32("MaxBatchSize"), DiagnosticsBlobSasUrl = entity.GetString("DiagnosticsBlobSasUrl"), diff --git a/src/Backend/AutopilotMonitor.Functions/Functions/Config/GetAgentConfigFunction.cs b/src/Backend/AutopilotMonitor.Functions/Functions/Config/GetAgentConfigFunction.cs index 71075ce7..dae9b319 100644 --- a/src/Backend/AutopilotMonitor.Functions/Functions/Config/GetAgentConfigFunction.cs +++ b/src/Backend/AutopilotMonitor.Functions/Functions/Config/GetAgentConfigFunction.cs @@ -270,12 +270,13 @@ namespace AutopilotMonitor.Functions.Functions.Config var response = req.CreateResponse(HttpStatusCode.OK); await response.WriteAsJsonAsync(new AgentConfigResponse { - ConfigVersion = 35, // MDM reboot-policy watcher (mdm_policy_reboot_required / esp_reboot_coalescing) + ConfigVersion = 36, // EnableGatherRuleDebugLog (local gather-rule evaluation trace) UploadIntervalSeconds = 10, SelfDestructOnComplete = tenantConfig.SelfDestructOnComplete ?? true, KeepLogFile = tenantConfig.KeepLogFile ?? false, EnableGeoLocation = tenantConfig.EnableGeoLocation ?? true, EnableImeMatchLog = tenantConfig.EnableImeMatchLog ?? false, + EnableGatherRuleDebugLog = tenantConfig.EnableGatherRuleDebugLog ?? false, MaxAuthFailures = tenantConfig.MaxAuthFailures ?? 5, AuthFailureTimeoutMinutes = tenantConfig.AuthFailureTimeoutMinutes ?? 0, LogLevel = tenantConfig.LogLevel ?? "Info", diff --git a/src/Shared/AutopilotMonitor.Shared/Constants.cs b/src/Shared/AutopilotMonitor.Shared/Constants.cs index 69e09c67..67a2d94c 100644 --- a/src/Shared/AutopilotMonitor.Shared/Constants.cs +++ b/src/Shared/AutopilotMonitor.Shared/Constants.cs @@ -62,6 +62,13 @@ namespace AutopilotMonitor.Shared /// public const string ImeMatchLogPath = @"%ProgramData%\AutopilotMonitor\Logs\ime_pattern_matches.log"; + /// + /// Default path for the gather rule debug trace file (debugging/diagnostics). + /// Written when the tenant enables EnableGatherRuleDebugLog; explains every + /// gather-rule evaluation decision, including outcomes that produce no event. + /// + public const string GatherRuleDebugLogPath = @"%ProgramData%\AutopilotMonitor\Logs\gather_rules_debug.log"; + /// /// Scheduled Task name used to run the agent as SYSTEM /// diff --git a/src/Shared/AutopilotMonitor.Shared/Models/Config/AgentConfigResponse.cs b/src/Shared/AutopilotMonitor.Shared/Models/Config/AgentConfigResponse.cs index 2b03537e..e1dbc989 100644 --- a/src/Shared/AutopilotMonitor.Shared/Models/Config/AgentConfigResponse.cs +++ b/src/Shared/AutopilotMonitor.Shared/Models/Config/AgentConfigResponse.cs @@ -40,6 +40,12 @@ namespace AutopilotMonitor.Shared.Models /// public bool EnableImeMatchLog { get; set; } = false; + /// + /// Whether to write a local gather-rule evaluation trace file. + /// When true, the default path is used: Constants.GatherRuleDebugLogPath. + /// + public bool EnableGatherRuleDebugLog { get; set; } = false; + public CollectorConfiguration Collectors { get; set; } = default!; /// diff --git a/src/Shared/AutopilotMonitor.Shared/Models/Config/TenantConfiguration.cs b/src/Shared/AutopilotMonitor.Shared/Models/Config/TenantConfiguration.cs index 16d1d3b6..74ac7f40 100644 --- a/src/Shared/AutopilotMonitor.Shared/Models/Config/TenantConfiguration.cs +++ b/src/Shared/AutopilotMonitor.Shared/Models/Config/TenantConfiguration.cs @@ -334,6 +334,15 @@ namespace AutopilotMonitor.Shared.Models /// public bool? EnableImeMatchLog { get; set; } + /// + /// Whether the agent writes a local gather-rule evaluation trace file so customers + /// can diagnose rules that produce no timeline events (scope skips, on_change + /// suppression, empty collector results, logparser details). When true, the agent + /// writes to Constants.GatherRuleDebugLogPath. The trace never leaves the device. + /// null = use agent default (false). + /// + public bool? EnableGatherRuleDebugLog { get; set; } + /// /// Log verbosity level override for this tenant's agents. /// null = use agent default ("Info"). Values: "Info", "Debug", "Verbose", "Trace". diff --git a/src/Web/autopilot-monitor-web/app/admin/tenants/sections/SectionTenantConfigReport.tsx b/src/Web/autopilot-monitor-web/app/admin/tenants/sections/SectionTenantConfigReport.tsx index c1657260..7a90cc4c 100644 --- a/src/Web/autopilot-monitor-web/app/admin/tenants/sections/SectionTenantConfigReport.tsx +++ b/src/Web/autopilot-monitor-web/app/admin/tenants/sections/SectionTenantConfigReport.tsx @@ -58,6 +58,7 @@ interface TenantConfig { enableTimezoneAutoSet?: boolean | null; ntpServer?: string | null; enableImeMatchLog?: boolean | null; + enableGatherRuleDebugLog?: boolean | null; logLevel?: string | null; maxBatchSize?: number | null; showEnrollmentSummary?: boolean | null; @@ -130,6 +131,7 @@ const DEFAULTS: Record = { enableTimezoneAutoSet: null, ntpServer: 'time.windows.com', enableImeMatchLog: null, + enableGatherRuleDebugLog: null, logLevel: null, maxBatchSize: null, showEnrollmentSummary: null, @@ -168,6 +170,7 @@ const RUNTIME_DEFAULTS: Record = { enableTimezoneAutoSet: false, ntpServer: 'time.windows.com', enableImeMatchLog: false, + enableGatherRuleDebugLog: false, maxAuthFailures: 5, authFailureTimeoutMinutes: 0, logLevel: 'Info', @@ -296,6 +299,7 @@ function computeRuntime(c: TenantConfig): Record { enableTimezoneAutoSet: c.enableTimezoneAutoSet ?? false, ntpServer: c.ntpServer ?? 'time.windows.com', enableImeMatchLog: c.enableImeMatchLog ?? false, + enableGatherRuleDebugLog: c.enableGatherRuleDebugLog ?? false, maxAuthFailures: c.maxAuthFailures ?? 5, authFailureTimeoutMinutes: c.authFailureTimeoutMinutes ?? 0, logLevel: c.logLevel ?? 'Info', @@ -575,6 +579,7 @@ export function SectionTenantConfigReport() { + @@ -647,6 +652,7 @@ export function SectionTenantConfigReport() { + diff --git a/src/Web/autopilot-monitor-web/app/settings/TenantConfigContext.tsx b/src/Web/autopilot-monitor-web/app/settings/TenantConfigContext.tsx index 8c1ca4e5..ea3f0e2b 100644 --- a/src/Web/autopilot-monitor-web/app/settings/TenantConfigContext.tsx +++ b/src/Web/autopilot-monitor-web/app/settings/TenantConfigContext.tsx @@ -167,6 +167,8 @@ interface TenantConfigContextValue { setEnableTimezoneAutoSet: (v: boolean) => void; enableImeMatchLog: boolean; setEnableImeMatchLog: (v: boolean) => void; + enableGatherRuleDebugLog: boolean; + setEnableGatherRuleDebugLog: (v: boolean) => void; logLevel: string; setLogLevel: (v: string) => void; showScriptOutput: boolean; @@ -384,6 +386,7 @@ export function TenantConfigProvider({ children }: { children: React.ReactNode } const [enableGeoLocation, setEnableGeoLocation] = useState(true); const [enableTimezoneAutoSet, setEnableTimezoneAutoSet] = useState(false); const [enableImeMatchLog, setEnableImeMatchLog] = useState(false); + const [enableGatherRuleDebugLog, setEnableGatherRuleDebugLog] = useState(false); const [logLevel, setLogLevel] = useState("Info"); const [showScriptOutput, setShowScriptOutput] = useState(true); const [showEnrollmentSummary, setShowEnrollmentSummary] = useState(false); @@ -503,6 +506,7 @@ export function TenantConfigProvider({ children }: { children: React.ReactNode } setEnableGeoLocation(data.enableGeoLocation ?? true); setEnableTimezoneAutoSet(data.enableTimezoneAutoSet ?? false); setEnableImeMatchLog(data.enableImeMatchLog ?? false); + setEnableGatherRuleDebugLog(data.enableGatherRuleDebugLog ?? false); setLogLevel(data.logLevel ?? "Info"); setShowScriptOutput(data.showScriptOutput ?? true); setShowEnrollmentSummary(data.showEnrollmentSummary ?? false); @@ -700,6 +704,7 @@ export function TenantConfigProvider({ children }: { children: React.ReactNode } enableGeoLocation, enableTimezoneAutoSet, enableImeMatchLog, + enableGatherRuleDebugLog, logLevel, showScriptOutput, showEnrollmentSummary, @@ -777,7 +782,7 @@ export function TenantConfigProvider({ children }: { children: React.ReactNode } manufacturerWhitelist, modelWhitelist, validateAutopilotDevice, validateCorporateIdentifier, validateDeviceAssociation, dataRetentionDays, sessionTimeoutHours, enablePerformanceCollector, performanceCollectorInterval, helloWaitTimeoutSeconds, selfDestructOnComplete, keepLogFile, rebootOnComplete, rebootDelaySeconds, - contactEmail, enableGeoLocation, enableTimezoneAutoSet, enableImeMatchLog, logLevel, showScriptOutput, showEnrollmentSummary, + contactEmail, enableGeoLocation, enableTimezoneAutoSet, enableImeMatchLog, enableGatherRuleDebugLog, logLevel, showScriptOutput, showEnrollmentSummary, enrollmentSummaryTimeoutSeconds, enrollmentSummaryBrandingImageUrl, enrollmentSummaryLaunchRetrySeconds, notificationChannels, slaTargetSuccessRate, slaTargetMaxDurationMinutes, slaTargetAppInstallSuccessRate, @@ -1113,6 +1118,7 @@ export function TenantConfigProvider({ children }: { children: React.ReactNode } setEnableGeoLocation(config.enableGeoLocation ?? true); setEnableTimezoneAutoSet(config.enableTimezoneAutoSet ?? false); setEnableImeMatchLog(config.enableImeMatchLog ?? false); + setEnableGatherRuleDebugLog(config.enableGatherRuleDebugLog ?? false); setLogLevel(config.logLevel ?? "Info"); setShowScriptOutput(config.showScriptOutput ?? true); setShowEnrollmentSummary(config.showEnrollmentSummary ?? false); @@ -1542,6 +1548,7 @@ export function TenantConfigProvider({ children }: { children: React.ReactNode } enableGeoLocation, setEnableGeoLocation, enableTimezoneAutoSet, setEnableTimezoneAutoSet, enableImeMatchLog, setEnableImeMatchLog, + enableGatherRuleDebugLog, setEnableGatherRuleDebugLog, logLevel, setLogLevel, showScriptOutput, setShowScriptOutput, showEnrollmentSummary, setShowEnrollmentSummary, diff --git a/src/Web/autopilot-monitor-web/app/settings/agent/sections/SectionAgentSettings.tsx b/src/Web/autopilot-monitor-web/app/settings/agent/sections/SectionAgentSettings.tsx index a3297cb9..254efc32 100644 --- a/src/Web/autopilot-monitor-web/app/settings/agent/sections/SectionAgentSettings.tsx +++ b/src/Web/autopilot-monitor-web/app/settings/agent/sections/SectionAgentSettings.tsx @@ -17,6 +17,7 @@ export function SectionAgentSettings() { enableGeoLocation, setEnableGeoLocation, enableTimezoneAutoSet, setEnableTimezoneAutoSet, enableImeMatchLog, setEnableImeMatchLog, + enableGatherRuleDebugLog, setEnableGatherRuleDebugLog, logLevel, setLogLevel, showScriptOutput, setShowScriptOutput, showEnrollmentSummary, setShowEnrollmentSummary, @@ -51,6 +52,8 @@ export function SectionAgentSettings() { setEnableTimezoneAutoSet={setEnableTimezoneAutoSet} enableImeMatchLog={enableImeMatchLog} setEnableImeMatchLog={setEnableImeMatchLog} + enableGatherRuleDebugLog={enableGatherRuleDebugLog} + setEnableGatherRuleDebugLog={setEnableGatherRuleDebugLog} logLevel={logLevel} setLogLevel={setLogLevel} showScriptOutput={showScriptOutput} diff --git a/src/Web/autopilot-monitor-web/app/settings/components/AgentSettingsSection.tsx b/src/Web/autopilot-monitor-web/app/settings/components/AgentSettingsSection.tsx index bc8b08b3..f38ac48a 100644 --- a/src/Web/autopilot-monitor-web/app/settings/components/AgentSettingsSection.tsx +++ b/src/Web/autopilot-monitor-web/app/settings/components/AgentSettingsSection.tsx @@ -24,6 +24,8 @@ interface AgentSettingsSectionProps { setEnableTimezoneAutoSet: (value: boolean) => void; enableImeMatchLog: boolean; setEnableImeMatchLog: (value: boolean) => void; + enableGatherRuleDebugLog: boolean; + setEnableGatherRuleDebugLog: (value: boolean) => void; logLevel: string; setLogLevel: (value: string) => void; showScriptOutput: boolean; @@ -64,6 +66,8 @@ export default function AgentSettingsSection({ setEnableTimezoneAutoSet, enableImeMatchLog, setEnableImeMatchLog, + enableGatherRuleDebugLog, + setEnableGatherRuleDebugLog, logLevel, setLogLevel, showScriptOutput, @@ -199,6 +203,21 @@ export default function AgentSettingsSection({ + {/* Gather Rule Debug Log */} +
+
+

Gather Rule Debug Log

+

+ Trace gather rule evaluation to a local file to diagnose rules that produce no timeline events. The trace never leaves the device. + {enableGatherRuleDebugLog && %ProgramData%\AutopilotMonitor\Logs\gather_rules_debug.log} +

+
+ +
+ {/* Show Script Output */}
diff --git a/src/Web/autopilot-monitor-web/app/settings/types.ts b/src/Web/autopilot-monitor-web/app/settings/types.ts index 36f8c0bf..26155b9e 100644 --- a/src/Web/autopilot-monitor-web/app/settings/types.ts +++ b/src/Web/autopilot-monitor-web/app/settings/types.ts @@ -60,6 +60,7 @@ export interface TenantConfiguration { enableGeoLocation?: boolean; enableTimezoneAutoSet?: boolean; enableImeMatchLog?: boolean; + enableGatherRuleDebugLog?: boolean; logLevel?: string; // Teams notifications (legacy) teamsWebhookUrl?: string;