mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-25 13:10:13 +00:00
Compare commits
8 Commits
| Author | SHA1 | Date | |
|---|---|---|---|
| 34fd40c3ad | |||
| a0eb1b9e35 | |||
| 9d677db2a8 | |||
| c728a0bd41 | |||
| 64336c0c89 | |||
| 59c944618b | |||
| 3c25172dfb | |||
| eda61eaade |
@@ -0,0 +1,104 @@
|
||||
---
|
||||
type: concept
|
||||
title: CMTrace Time Resolution — Per-Line Self-Anchoring
|
||||
description: How the agent converts bias-less CMTrace local times to UTC without trusting any process's timezone belief — each provably fresh line anchors its own offset against the agent clock on the 15-minute grid; everything not provably fresh falls back uniformly and says so.
|
||||
resource: src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime
|
||||
tags: [agent, ime, cmtrace, timestamps, timezone, calibration, provenance]
|
||||
timestamp: 2026-08-20
|
||||
---
|
||||
|
||||
# Problem
|
||||
|
||||
A CMTrace line carries local time and no offset — IME 1.104 writes `DateTime.Now.TimeOfDay`
|
||||
in both of its trace listeners. Converting such a line with the reader's own
|
||||
`TimeZoneInfo.Local` silently assumes the writing and reading processes agree on the zone.
|
||||
They do not: each caches its zone at process start and follows neither a later `tzutil` nor
|
||||
a Windows auto-timezone change. The error is `Offset_writer − Offset_reader` — zero only
|
||||
when both believe the same thing, right or wrong. Field measurement over 11,068 sessions
|
||||
found 26 sessions with a real error, from +1 h to −17 h.
|
||||
|
||||
Two designs failed before this one:
|
||||
|
||||
* **Fix the reader's belief** (`TimeZoneInfo.ClearCachedData`, live OS offset): makes the
|
||||
agent isolated-correct and thereby breaks the majority of sessions, where two equally
|
||||
stale beliefs cancel.
|
||||
* **One measured offset per file** (agent 2.0.1410, reverted in `04b1a7c6`): a single log
|
||||
file holds lines from multiple writer *eras*. `AgentExecutor.log` is written by
|
||||
short-lived child processes whose zone belief flips per process — interleaved in one
|
||||
file, and flipping *back* (fixture:
|
||||
`tests/fixtures/cmtrace-logs/agentexecutor-two-writer-eras-v1.cmtrace`). Any cross-line
|
||||
anchor — per file, or nearest-in-write-order — applies one era's offset to the other
|
||||
era's lines. In the field this shifted `script_started` events by −9 h against their
|
||||
correct completions.
|
||||
|
||||
# Schema
|
||||
|
||||
The resolution rule, in order:
|
||||
|
||||
1. **Writer-declared bias** (`+480` suffix): authoritative, used as-is. Never a calibration
|
||||
anchor — it needs no measurement and must not overwrite one.
|
||||
2. **Per-line self-anchoring** — only for lines read in a *provably fresh* pass:
|
||||
|
||||
```
|
||||
offset_line = round((local − agentUtcNow) / 15 min) · 15 min
|
||||
lineUtc = local − offset_line
|
||||
```
|
||||
|
||||
Every real UTC offset is a whole multiple of 15 minutes, so the rounding absorbs poll
|
||||
and flush latency. No cross-line state exists, so interleaved eras resolve line by
|
||||
line — the property the fixture test pins. The line's own timestamp still contributes
|
||||
sub-poll precision and ordering (two lines 6 ms apart stay 6 ms apart; a plain
|
||||
`occurredAt = now` could not do that). Guards: grid residual ≤ 2 min, offset within
|
||||
UTC−12 … UTC+14.
|
||||
3. **Uniform reader-zone fallback** for everything else: wrong in absolute terms whenever
|
||||
the writer held a different belief, but *self-consistent* — both ends of a duration are
|
||||
wrong by the same amount, so derived durations stay right. The revert's core lesson:
|
||||
partially corrected is strictly worse than uniformly wrong.
|
||||
|
||||
**Freshness** is what makes rule 2 sound, and it is strict:
|
||||
|
||||
* Every poll look at a file stamps `LastCheckedUtc` (`LogFilePositionTracker.MarkChecked`),
|
||||
including "no new data" and an empty first sight — so a file first seen empty
|
||||
(`AgentExecutor.log` appearing mid-enrollment) anchors from its very first content.
|
||||
* A pass's lines are fresh only if the file was previously observed *in this process* and
|
||||
the gap since the last look is ≤ `FreshLineMaxAge` (30 s — far above the 100 ms poll,
|
||||
far below the 13-minute zone where a line's *age* could round onto the offset grid).
|
||||
* A restart-restored position bookmark deliberately carries **no** freshness: the first
|
||||
pass after a restart reads downtime backlog and must never anchor.
|
||||
|
||||
**Provenance** (`sourceOffsetOrigin` in event DataJson): `bias` | `line-anchored` |
|
||||
`reader-zone-fallback` (plus retired `calibrated` from 2.0.1410 events). The applied
|
||||
offset is always recorded (`sourceOffsetMinutes`), the raw local time too
|
||||
(`sourceLocalTs`), so any event can be re-derived later. The per-*file* measurement still
|
||||
runs, purely observationally (`measuredWriterOffsetMinutes`, Info log when it disagrees
|
||||
with the process zone).
|
||||
|
||||
# Constraints
|
||||
|
||||
* An anchored line resolves to `now ± 2 min` *by construction*. The accepted edge: a
|
||||
freshly written line carrying a **replayed** old timestamp whose age is exactly
|
||||
N×15 min ± 2 min anchors to ≈now instead of its replayed past — bounded error, and
|
||||
sub-24 h replays are treated as current by the historic-replay guard anyway.
|
||||
* Snapshot readers (`StallProbeCollector`, `LogParserCollector`) cannot tail and therefore
|
||||
cannot prove freshness — they stay on the marked fallback. This is a documented limit,
|
||||
not an omission; sharing the per-file measurement with them would re-apply exactly what
|
||||
the revert removed.
|
||||
* Mixed pairs remain possible across a restart (start resolved from backlog fallback,
|
||||
completion line-anchored) and are recognizable via provenance.
|
||||
|
||||
# Citations
|
||||
|
||||
* `CmTraceOffsetCalibrator.TryMeasureOffset` — the pure grid measurement, shared by
|
||||
anchoring and the observational per-file path.
|
||||
* `ImeLogTracker.LogProcessing.cs` `ResolveEntryUtc` — the resolution order above.
|
||||
* `ImeLogTrackerLineAnchoringTests` — resolves-to-T across writer beliefs, interleaved
|
||||
eras in one chunk, freshness boundaries (first sight, empty first sight, poll gap,
|
||||
restart restore), the grid-replay edge, and the field fixture replayed at production
|
||||
poll cadence.
|
||||
* `CmTraceCalibratorFileIsolationTests` — pins per-file isolation of the observational
|
||||
measurement (session e9753578 logged a cross-file pairing the committed code could not
|
||||
be shown to produce; the mechanism remains open, the resolution path is immune by
|
||||
design, and `CalibrateFrom` logs the anchor timestamp as a tripwire).
|
||||
* `tasks/todo.md` (2026-08-20) — full evidence trail: field measurements, the revert,
|
||||
the two-writer-era fixture, and the disproven foreign-binary hypothesis (the SHA
|
||||
mismatch was the known release race against the 5-minute AdminConfiguration cache).
|
||||
@@ -27,6 +27,7 @@ https://docs.autopilotmonitor.com (separate repository).
|
||||
* [ESP Completion Starvation — the sits-d Cloud-PC complex](agent/post-reboot-completion-recovery.md) - Why a SkipUser=true flow (no user ESP page → no Shell-Core 62407, no AccountSetup registry) left the completion gate satisfied but never evaluated — five Cloud PCs idled six hours at "waiting on: hello_resolution" — and the fix: the observed skip stands in for the final-exit evidence in the IME user-session completion attempt. Plus the two adjacent defects fixed alongside: the edge-only user-apps-settled synthesis (now level-triggered) and the never-wired Shell-Core restart replay (now Hello-wizard-only, with the reasoning why a replayed 62407 must never reach the reducer).
|
||||
* [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.
|
||||
* [Continue-Anyway Observation Mode](agent/continue-anyway-observation.md) - EnableEspContinueAnywayObservation (ConfigVersion 37, operator-set): Device-phase ESP terminal failures on Continue-Anyway profiles get a bounded 60-min observation instead of an immediate hard fail; the DAD-validated real-user desktop + Hello gate detect the true end, the session completes Succeeded + EspSoftFailure (amber "with issues" badge), expiry un-defangs to the original esp_terminal_failure.
|
||||
* [CMTrace Time Resolution](agent/cmtrace-time-resolution.md) - Converting bias-less CMTrace local times to UTC without trusting any process's timezone belief: per-line self-anchoring on the 15-minute offset grid for provably fresh lines, uniform marked reader-zone fallback for backlog, and the provenance vocabulary (bias / line-anchored / reader-zone-fallback) that keeps every event re-derivable.
|
||||
* [Registry App-State Second Pillar](agent/registry-app-state-pillar.md) - IME's authoritative per-app state read straight from the registry (Win32Apps EnforcementStateMessage, EspTrackingWin32Apps, StatusServiceReports) via a snapshot-and-diff watcher; registry/log reconciliation doubles as the built-in IME log-pattern drift alarm.
|
||||
* [WDP Scenario Gates & Completion Backstop](agent/wdp-scenario-gates.md) - How the agent gates Autopilot/ESP-only machinery off on Windows Device Preparation sessions (deterministic ExecutionContext marker, fail-toward-Classic), which noise it suppresses (ZTD probe, esp_config unknown, ModernDeployment 100/417/418/1005, starved sweep), and the WDP completion model: High-confidence seed, desktop-based arm D, and the 30-min device_prep_completion backstop.
|
||||
* [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.
|
||||
|
||||
@@ -2,6 +2,8 @@
|
||||
|
||||
## 2026-08-20
|
||||
|
||||
* **New**: `agent/cmtrace-time-resolution.md` — the era-aware answer to the CMTrace timezone skew: a bias-less line read in a provably fresh pass anchors its own UTC offset against the agent clock (15-minute grid, 2-minute residual), so interleaved writer eras in one file resolve line by line; everything not provably fresh keeps the uniform reader-zone fallback and says so via `sourceOffsetOrigin`. Freshness is a per-file `LastCheckedUtc` stamped on every poll look (empty first sights included) with a 30-second window, never restored across restarts. Replaces the reverted per-file offset application (04b1a7c6); the per-file measurement stays observational, now with the anchor timestamp logged as a tripwire for the still-unexplained e9753578 label/anchor crossing.
|
||||
|
||||
* **Update**: `agent/post-reboot-completion-recovery.md` — retitled to "ESP Completion Starvation — the sits-d Cloud-PC complex" and reframed on the evidence: the reboot was a red herring. The five stuck Cloud PCs carried `SkipUserStatusPage=True` (read 10+ times across three agent processes, `True` every time) and Windows honoured it — no user ESP page, hence no Shell-Core 62407 and no AccountSetup provisioning registry, verified over a six-hour uninterrupted post-reboot run with the watcher armed. Arm B of `ShouldTransitionToAwaitingHello` was open from the bootstrap onward, but every evaluation site hangs off a signal a skip-user flow cannot produce, and the `AdvisoryCompletion` backstop arms exclusively from an `EspExiting` signal — an open gate nobody knocks on. Fix: `HandleImeUserSessionCompletedV1` accepts the observed skip in place of the final-exit evidence (`skipUserExitEquivalent`; anchor + genuine IME completion + real-user desktop stay mandatory, WDP excluded). The knock deliberately lives on the IME edge, not desktop arrival — ordering-robust against Fix 10's AccountSetup bounce-back and semantically "user-phase work finished" rather than mid-install. `ClassicSkipUserEspUserSessionCompletionTests` replays the real 8110e262 ordering end to end. Docs and comments no longer claim an ESP-exit recovery that does not exist (stray duplicate summary in `ShellCoreTracker`, `ImeLogHost` restore-callback comment); the residual `SkipUser=false` exit-in-downtime gap is named honestly and surfaced by `ANALYZE-ESP-005` via `session_stalled` instead of being patched with an unorderable replay.
|
||||
|
||||
## 2026-08-19
|
||||
|
||||
+109
@@ -0,0 +1,109 @@
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using System.IO;
|
||||
using System.Threading;
|
||||
using System.Threading.Tasks;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
{
|
||||
/// <summary>
|
||||
/// Pins the per-FILE isolation of the offset measurement across a full read cycle.
|
||||
///
|
||||
/// <para>
|
||||
/// Background (2026-08-20, session e9753578): the field showed "+02:00 measured for
|
||||
/// IntuneManagementExtension.log" although that file held no +2-era line — the anchor had
|
||||
/// crossed file boundaries. The committed code was proven innocent (this very scenario is
|
||||
/// green here); the leak lived in a binary built from an uncommitted tree. This test keeps
|
||||
/// the property pinned so a real regression of the file scoping can never ship silently
|
||||
/// again — it replays the exact field pass structure: a NEW file appearing mid-run with a
|
||||
/// different writer era than the file already being tailed.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public sealed class CmTraceCalibratorFileIsolationTests
|
||||
{
|
||||
private static readonly DateTime T0 = new DateTime(2026, 8, 20, 12, 13, 0, DateTimeKind.Utc);
|
||||
|
||||
private static List<ImeLogPattern> Patterns() => new List<ImeLogPattern>
|
||||
{
|
||||
new ImeLogPattern
|
||||
{
|
||||
PatternId = "T-MARK", Category = "always", Enabled = true,
|
||||
Pattern = @"marker (?<n>\d+)",
|
||||
Action = "noop",
|
||||
Parameters = new Dictionary<string, string>(),
|
||||
},
|
||||
};
|
||||
|
||||
private static string Line(string message, DateTime utcInstant, TimeSpan writerOffset)
|
||||
{
|
||||
var local = utcInstant + writerOffset;
|
||||
return $"<![LOG[{message}]LOG]!><time=\"{local:HH:mm:ss.fffffff}\" date=\"{local:M-d-yyyy}\" " +
|
||||
"component=\"X\" context=\"\" type=\"1\" thread=\"1\" file=\"\">";
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task NewFileWithOtherEra_MustNotRecalibrateTheOldFile()
|
||||
{
|
||||
var pdt = TimeSpan.FromHours(-7); // IME service era
|
||||
var cest = TimeSpan.FromHours(2); // fresh child-process era
|
||||
|
||||
using var tmp = new TempDirectory();
|
||||
var now = T0;
|
||||
var tracker = new ImeLogTracker(
|
||||
logFolder: tmp.Path,
|
||||
patterns: Patterns(),
|
||||
logger: new AgentLogger(tmp.Path, AgentLogLevel.Info));
|
||||
try
|
||||
{
|
||||
tracker.UtcNowProvider = () => now;
|
||||
var imeLog = Path.Combine(tmp.Path, "IntuneManagementExtension.log");
|
||||
var execLog = Path.Combine(tmp.Path, "AgentExecutor.log");
|
||||
|
||||
// Pass 1: IME.log first sight (no calibration).
|
||||
File.AppendAllText(imeLog, Line("marker 1", now, pdt) + Environment.NewLine);
|
||||
await tracker.CheckLogFilesAsync(CancellationToken.None);
|
||||
|
||||
// Pass 2: IME.log grew -> measures -7.
|
||||
now = T0.AddSeconds(10);
|
||||
File.AppendAllText(imeLog, Line("marker 2", now, pdt) + Environment.NewLine);
|
||||
await tracker.CheckLogFilesAsync(CancellationToken.None);
|
||||
|
||||
TimeSpan imeMeasured;
|
||||
Assert.True(tracker.OffsetCalibrator.TryGetOffset("IntuneManagementExtension.log", out imeMeasured));
|
||||
Assert.Equal(pdt, imeMeasured);
|
||||
|
||||
// Pass 3: AgentExecutor.log appears for the FIRST time with fresh +2-era lines
|
||||
// while IME.log grows too — the exact field pass structure. The +2 anchor must
|
||||
// never land under IME.log's key.
|
||||
now = T0.AddSeconds(20);
|
||||
File.AppendAllText(execLog, Line("marker 3", now, cest) + Environment.NewLine);
|
||||
File.AppendAllText(imeLog, Line("marker 4", now, pdt) + Environment.NewLine);
|
||||
await tracker.CheckLogFilesAsync(CancellationToken.None);
|
||||
|
||||
Assert.True(tracker.OffsetCalibrator.TryGetOffset("IntuneManagementExtension.log", out imeMeasured));
|
||||
Assert.Equal(pdt, imeMeasured);
|
||||
|
||||
// Pass 4: both grow — each file measures its own writer's era.
|
||||
now = T0.AddSeconds(30);
|
||||
File.AppendAllText(execLog, Line("marker 5", now, cest) + Environment.NewLine);
|
||||
File.AppendAllText(imeLog, Line("marker 6", now, pdt) + Environment.NewLine);
|
||||
await tracker.CheckLogFilesAsync(CancellationToken.None);
|
||||
|
||||
TimeSpan execMeasured;
|
||||
Assert.True(tracker.OffsetCalibrator.TryGetOffset("AgentExecutor.log", out execMeasured));
|
||||
Assert.Equal(cest, execMeasured);
|
||||
Assert.True(tracker.OffsetCalibrator.TryGetOffset("IntuneManagementExtension.log", out imeMeasured));
|
||||
Assert.Equal(pdt, imeMeasured);
|
||||
}
|
||||
finally
|
||||
{
|
||||
tracker.Dispose();
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
+441
@@ -0,0 +1,441 @@
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using System.IO;
|
||||
using System.Threading;
|
||||
using System.Threading.Tasks;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
|
||||
using AutopilotMonitor.Shared.Logging;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
{
|
||||
/// <summary>
|
||||
/// Per-line self-anchoring — the era-aware successor to the reverted per-file offset
|
||||
/// application (04b1a7c6).
|
||||
///
|
||||
/// <para>
|
||||
/// The property under test: a line read in a provably FRESH pass resolves to the instant it
|
||||
/// was written, whatever timezone its writer believed — and neighbouring lines from writers
|
||||
/// with DIFFERENT beliefs each resolve to their own era, because no cross-line state is
|
||||
/// involved. That interleaving (fixture: AgentExecutor.log with PDT and CEST children in one
|
||||
/// file, flipping both ways) is exactly what broke every cross-line anchor design.
|
||||
/// </para>
|
||||
///
|
||||
/// <para>
|
||||
/// The freshness boundary is equally load-bearing: backlog (first sight, restart catch-up,
|
||||
/// stalled polls) must NEVER anchor, because an old line's age can round onto the 15-minute
|
||||
/// offset grid. Those paths keep the uniform reader-zone fallback.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public sealed class ImeLogTrackerLineAnchoringTests
|
||||
{
|
||||
private static readonly DateTime T0 = new DateTime(2026, 8, 20, 12, 13, 0, DateTimeKind.Utc);
|
||||
|
||||
private static List<ImeLogPattern> Patterns() => new List<ImeLogPattern>
|
||||
{
|
||||
new ImeLogPattern
|
||||
{
|
||||
PatternId = "T-ALL", Category = "always", Enabled = true,
|
||||
Pattern = @"marker (?<n>\d+)",
|
||||
Action = "noop",
|
||||
Parameters = new Dictionary<string, string>(),
|
||||
},
|
||||
};
|
||||
|
||||
/// <summary>A CMTrace line as a writer holding <paramref name="writerOffset"/> renders instant <paramref name="utcInstant"/>.</summary>
|
||||
private static string Line(string message, DateTime utcInstant, TimeSpan writerOffset)
|
||||
{
|
||||
var local = utcInstant + writerOffset;
|
||||
return $"<![LOG[{message}]LOG]!><time=\"{local:HH:mm:ss.fffffff}\" date=\"{local:M-d-yyyy}\" " +
|
||||
"component=\"X\" context=\"\" type=\"1\" thread=\"1\" file=\"\">";
|
||||
}
|
||||
|
||||
private sealed class Harness : IDisposable
|
||||
{
|
||||
private readonly TempDirectory _tmp = new TempDirectory();
|
||||
public ImeLogTracker Tracker { get; }
|
||||
public DateTime Now { get; set; } = T0;
|
||||
|
||||
public Harness(string? stateDirectory = null)
|
||||
{
|
||||
Tracker = new ImeLogTracker(
|
||||
logFolder: _tmp.Path,
|
||||
patterns: Patterns(),
|
||||
logger: new AgentLogger(_tmp.Path, AgentLogLevel.Info),
|
||||
stateDirectory: stateDirectory);
|
||||
Tracker.UtcNowProvider = () => Now;
|
||||
}
|
||||
|
||||
public string PathOf(string fileName) => Path.Combine(_tmp.Path, fileName);
|
||||
|
||||
public void Append(string fileName, string line)
|
||||
=> File.AppendAllText(PathOf(fileName), line + Environment.NewLine);
|
||||
|
||||
public Task Pass() => Tracker.CheckLogFilesAsync(CancellationToken.None);
|
||||
|
||||
public void Dispose()
|
||||
{
|
||||
Tracker.Dispose();
|
||||
_tmp.Dispose();
|
||||
}
|
||||
}
|
||||
|
||||
[Theory]
|
||||
// The writer's belief. A fresh line must resolve to the instant it was written,
|
||||
// WHATEVER that belief is — including agreement with this process (the majority case,
|
||||
// which a fix to the agent's own zone cache would have broken).
|
||||
[InlineData(2)] // CEST
|
||||
[InlineData(1)] // BST
|
||||
[InlineData(0)] // UTC
|
||||
[InlineData(-7)] // PDT — the OOBE default behind the -9 h and -17 h field cases
|
||||
[InlineData(10)] // E. Australia
|
||||
public async Task FreshLine_ResolvesToItsTrueInstant_ForAnyWriterBelief(int writerOffsetHours)
|
||||
{
|
||||
var writerOffset = TimeSpan.FromHours(writerOffsetHours);
|
||||
using var h = new Harness();
|
||||
|
||||
// First sight: backlog, must not anchor.
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 1", h.Now, writerOffset));
|
||||
await h.Pass();
|
||||
|
||||
h.Now = T0.AddSeconds(10);
|
||||
var writtenAt = h.Now.AddMilliseconds(-80); // written just before the poll sees it
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 2", writtenAt, writerOffset));
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(CmTraceOffsetOrigin.LineAnchored, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
Assert.Equal(writtenAt, h.Tracker.LastMatchedLogTimestamp);
|
||||
Assert.Equal(writerOffsetHours * 60, h.Tracker.LastMatchedSourceOffsetMinutes);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task InterleavedEras_InOneGrowingPass_EachLineResolvesToItsOwnEra()
|
||||
{
|
||||
// The e9753578 file shape: two writer processes with different zone beliefs
|
||||
// interleaved in ONE file. Any per-file offset gets one of them wrong by 9 h;
|
||||
// per-line anchoring must get both right within the same chunk.
|
||||
var pdt = TimeSpan.FromHours(-7);
|
||||
var cest = TimeSpan.FromHours(2);
|
||||
using var h = new Harness();
|
||||
|
||||
h.Append("AgentExecutor.log", Line("marker 1", h.Now, pdt));
|
||||
await h.Pass();
|
||||
|
||||
h.Now = T0.AddSeconds(10);
|
||||
var wrotePdt = h.Now.AddMilliseconds(-90);
|
||||
var wroteCest = h.Now.AddMilliseconds(-50);
|
||||
h.Append("AgentExecutor.log", Line("marker 2", wrotePdt, pdt));
|
||||
h.Append("AgentExecutor.log", Line("marker 3", wroteCest, cest));
|
||||
|
||||
var resolved = new List<(DateTime? Ts, CmTraceOffsetOrigin Origin, int? Offset)>();
|
||||
Action<string> capture = _ => resolved.Add((
|
||||
h.Tracker.LastMatchedLogTimestamp,
|
||||
h.Tracker.LastMatchedSourceOffsetOrigin,
|
||||
h.Tracker.LastMatchedSourceOffsetMinutes));
|
||||
h.Tracker.OnPatternMatched += capture;
|
||||
try
|
||||
{
|
||||
await h.Pass();
|
||||
}
|
||||
finally
|
||||
{
|
||||
h.Tracker.OnPatternMatched -= capture;
|
||||
}
|
||||
|
||||
Assert.Equal(2, resolved.Count);
|
||||
Assert.Equal(wrotePdt, resolved[0].Ts);
|
||||
Assert.Equal(-420, resolved[0].Offset);
|
||||
Assert.Equal(wroteCest, resolved[1].Ts);
|
||||
Assert.Equal(120, resolved[1].Offset);
|
||||
Assert.All(resolved, r => Assert.Equal(CmTraceOffsetOrigin.LineAnchored, r.Origin));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task FirstSightBacklog_FallsBackToReaderZone()
|
||||
{
|
||||
using var h = new Harness();
|
||||
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 1", h.Now.AddHours(-3), TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(CmTraceOffsetOrigin.None, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task FileFirstSeenEmpty_ItsFirstContentIsFresh()
|
||||
{
|
||||
// AgentExecutor.log in the field: the file APPEARS mid-enrollment. Seeing it empty
|
||||
// (or not existing content-wise) counts as an observation, so its very first lines
|
||||
// are provably written between passes and may anchor. This closes the warm-up gap
|
||||
// for exactly the file whose eras flip the most.
|
||||
using var h = new Harness();
|
||||
|
||||
File.WriteAllText(h.PathOf("AgentExecutor.log"), string.Empty);
|
||||
await h.Pass();
|
||||
|
||||
h.Now = T0.AddSeconds(5);
|
||||
var writtenAt = h.Now.AddMilliseconds(-60);
|
||||
h.Append("AgentExecutor.log", Line("marker 1", writtenAt, TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(CmTraceOffsetOrigin.LineAnchored, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
Assert.Equal(writtenAt, h.Tracker.LastMatchedLogTimestamp);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task PollGapBeyondFreshWindow_FallsBack()
|
||||
{
|
||||
// A stalled agent (GC, CPU starvation) re-polls after a long gap: the new bytes span
|
||||
// the whole gap and their age is unbounded, so the pass must not anchor — even
|
||||
// though most of its lines may in fact be recent. Conservative by design.
|
||||
using var h = new Harness();
|
||||
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 1", h.Now, TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
h.Now = T0.AddSeconds(10);
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 2", h.Now, TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
Assert.Equal(CmTraceOffsetOrigin.LineAnchored, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
|
||||
// Gap far beyond FreshLineMaxAge.
|
||||
h.Now = h.Now + ImeLogTracker.FreshLineMaxAge + TimeSpan.FromSeconds(10);
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 3", h.Now, TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(CmTraceOffsetOrigin.None, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
|
||||
// And the very next tight poll is fresh again.
|
||||
h.Now = h.Now.AddSeconds(1);
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 4", h.Now, TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
Assert.Equal(CmTraceOffsetOrigin.LineAnchored, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task RestartWithRestoredBookmark_FirstPassIsBacklog_SecondPassAnchors()
|
||||
{
|
||||
// The persisted position bookmark survives a restart; the freshness guarantee must
|
||||
// not — the first pass after a restart reads the downtime backlog, whose lines can
|
||||
// be arbitrarily old.
|
||||
using var stateDir = new TempDirectory();
|
||||
using var h = new Harness(stateDirectory: stateDir.Path);
|
||||
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 1", h.Now, TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
h.Tracker.SaveStateForTest();
|
||||
|
||||
// "Restart": a second tracker over the same folder restores the bookmark.
|
||||
using var h2 = new HarnessOver(h, stateDir.Path);
|
||||
h2.Tracker.LoadStateForTest();
|
||||
|
||||
// Backlog written during the downtime — 30 min old, exactly on the offset grid,
|
||||
// the nastiest possible backlog shape. Must NOT anchor.
|
||||
h2.Now = T0.AddMinutes(30);
|
||||
h2.Append(Line("marker 2", T0.AddSeconds(20), TimeSpan.FromHours(2)));
|
||||
await h2.Pass();
|
||||
Assert.Equal(CmTraceOffsetOrigin.None, h2.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
|
||||
// The next tight poll is fresh again.
|
||||
h2.Now = h2.Now.AddSeconds(1);
|
||||
var writtenAt = h2.Now.AddMilliseconds(-70);
|
||||
h2.Append(Line("marker 3", writtenAt, TimeSpan.FromHours(2)));
|
||||
await h2.Pass();
|
||||
Assert.Equal(CmTraceOffsetOrigin.LineAnchored, h2.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
Assert.Equal(writtenAt, h2.Tracker.LastMatchedLogTimestamp);
|
||||
}
|
||||
|
||||
/// <summary>Second tracker over the FIRST harness's log folder — the "restarted agent".</summary>
|
||||
private sealed class HarnessOver : IDisposable
|
||||
{
|
||||
private readonly string _logFolder;
|
||||
public ImeLogTracker Tracker { get; }
|
||||
public DateTime Now { get; set; }
|
||||
|
||||
public HarnessOver(Harness original, string stateDirectory)
|
||||
{
|
||||
_logFolder = Path.GetDirectoryName(original.PathOf("x"));
|
||||
Tracker = new ImeLogTracker(
|
||||
logFolder: _logFolder,
|
||||
patterns: Patterns(),
|
||||
logger: new AgentLogger(_logFolder, AgentLogLevel.Info),
|
||||
stateDirectory: stateDirectory);
|
||||
Tracker.UtcNowProvider = () => Now;
|
||||
}
|
||||
|
||||
public void Append(string line)
|
||||
=> File.AppendAllText(Path.Combine(_logFolder, "IntuneManagementExtension.log"), line + Environment.NewLine);
|
||||
|
||||
public Task Pass() => Tracker.CheckLogFilesAsync(CancellationToken.None);
|
||||
|
||||
public void Dispose() => Tracker.Dispose();
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task FreshlyWrittenReplayLine_OnExactGridAge_ResolvesToRoughlyNow()
|
||||
{
|
||||
// Characterization of the one accepted edge: a line freshly WRITTEN but carrying a
|
||||
// REPLAYED timestamp whose age is exactly a grid multiple (here 30 min) measures
|
||||
// that age as an "offset" and resolves to ~now instead of its replayed past. The
|
||||
// error is bounded by construction (an anchored line always lands at now ± 2 min),
|
||||
// and sub-24h replays are treated as current by the historic-replay guard anyway.
|
||||
using var h = new Harness();
|
||||
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 1", h.Now, TimeSpan.Zero));
|
||||
await h.Pass();
|
||||
|
||||
h.Now = T0.AddSeconds(10);
|
||||
var replayedInstant = h.Now.AddMinutes(-30);
|
||||
h.Append("IntuneManagementExtension.log", Line("marker 2", replayedInstant, TimeSpan.Zero));
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(CmTraceOffsetOrigin.LineAnchored, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
Assert.NotNull(h.Tracker.LastMatchedLogTimestamp);
|
||||
var error = (h.Tracker.LastMatchedLogTimestamp!.Value - h.Now).Duration();
|
||||
Assert.True(error <= CmTraceOffsetCalibrator.MaxGridResidual,
|
||||
$"anchored line must resolve to now ± residual, was off by {error}");
|
||||
}
|
||||
|
||||
// =====================================================================
|
||||
// The committed field fixture — session e9753578, ImeLogs/AgentExecutor.log.
|
||||
// One file, two writer eras (PDT hour-05 / CEST hour-14), interleaved, flipping
|
||||
// BOTH ways. Replayed here as the live tail the field agent saw: entry by entry,
|
||||
// with the clock following the true write time.
|
||||
// =====================================================================
|
||||
|
||||
private static string FixturePath()
|
||||
{
|
||||
var dir = AppContext.BaseDirectory;
|
||||
for (int i = 0; i < 12; i++)
|
||||
{
|
||||
if (File.Exists(Path.Combine(dir, "AutopilotMonitor.sln")))
|
||||
return Path.Combine(dir, "tests", "fixtures", "cmtrace-logs",
|
||||
"agentexecutor-two-writer-eras-v1.cmtrace");
|
||||
var parent = Directory.GetParent(dir)?.FullName;
|
||||
if (parent == null || parent == dir) break;
|
||||
dir = parent;
|
||||
}
|
||||
throw new DirectoryNotFoundException(
|
||||
"Could not locate repo root (AutopilotMonitor.sln) walking up from " + AppContext.BaseDirectory);
|
||||
}
|
||||
|
||||
/// <summary>Group the fixture's physical lines into complete CMTrace entries (multiline-safe).</summary>
|
||||
private static List<string> FixtureEntries()
|
||||
{
|
||||
var entries = new List<string>();
|
||||
string? pending = null;
|
||||
foreach (var rawWithBom in File.ReadAllLines(FixturePath()))
|
||||
{
|
||||
// The fixture keeps the original file's BOM verbatim — it sat at the START of
|
||||
// the real AgentExecutor.log, which is mid-file in this excerpt.
|
||||
var raw = rawWithBom.TrimStart('');
|
||||
if (pending == null)
|
||||
{
|
||||
if (raw.Length == 0 || raw[0] == '#') continue;
|
||||
if (!raw.StartsWith("<![LOG[", StringComparison.Ordinal)) continue;
|
||||
if (raw.Contains("]LOG]!>")) { entries.Add(raw); continue; }
|
||||
pending = raw;
|
||||
}
|
||||
else
|
||||
{
|
||||
pending += "\n" + raw;
|
||||
if (raw.Contains("]LOG]!>")) { entries.Add(pending!); pending = null; }
|
||||
}
|
||||
}
|
||||
return entries;
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task TwoWriterEraFixture_EveryLineOfBothErasResolvesToItsTrueInstant()
|
||||
{
|
||||
// The committed fixture is a curated, verbatim excerpt of the transition window
|
||||
// (commit policy: anonymized, versioned) — 20 entries covering both eras and the flip.
|
||||
var entries = FixtureEntries();
|
||||
Assert.True(entries.Count >= 15, $"fixture unexpectedly small: {entries.Count} entries");
|
||||
|
||||
using var h = new Harness();
|
||||
|
||||
// Match every fixture entry.
|
||||
h.Tracker.CompilePatterns(new List<ImeLogPattern>
|
||||
{
|
||||
new ImeLogPattern
|
||||
{
|
||||
PatternId = "T-ANY", Category = "always", Enabled = true,
|
||||
Pattern = ".+", Action = "noop",
|
||||
Parameters = new Dictionary<string, string>(),
|
||||
},
|
||||
});
|
||||
|
||||
// The file exists (empty) before its first content — first sight is the observation
|
||||
// baseline, everything after is a fresh tail, exactly like the field.
|
||||
File.WriteAllText(h.PathOf("AgentExecutor.log"), string.Empty);
|
||||
h.Now = new DateTime(2026, 8, 20, 12, 13, 30, DateTimeKind.Utc);
|
||||
await h.Pass();
|
||||
|
||||
var anchored = 0;
|
||||
var resolvedList = new List<(DateTime Resolved, DateTime Expected)>();
|
||||
Action<string> capture = _ =>
|
||||
{
|
||||
if (h.Tracker.LastMatchedSourceOffsetOrigin == CmTraceOffsetOrigin.LineAnchored)
|
||||
anchored++;
|
||||
if (h.Tracker.LastMatchedLogTimestamp.HasValue && _expectedForCurrentEntry.HasValue)
|
||||
resolvedList.Add((h.Tracker.LastMatchedLogTimestamp.Value, _expectedForCurrentEntry.Value));
|
||||
};
|
||||
h.Tracker.OnPatternMatched += capture;
|
||||
try
|
||||
{
|
||||
foreach (var entry in entries)
|
||||
{
|
||||
CmTraceLogEntry? parsed;
|
||||
Assert.True(CmTraceLogParser.TryParseLine(entry, out parsed), "fixture entry did not parse");
|
||||
|
||||
// Era by local hour: the fixture holds exactly two eras — PDT (UTC-7) lines
|
||||
// render at local hour 05, CEST (UTC+2) lines at hour 14 (fixture header).
|
||||
var eraOffset = parsed.LocalTimestamp.Hour == 14
|
||||
? TimeSpan.FromHours(2)
|
||||
: TimeSpan.FromHours(-7);
|
||||
var trueUtc = DateTime.SpecifyKind(parsed.LocalTimestamp - eraOffset, DateTimeKind.Utc);
|
||||
|
||||
// The clock follows the write; never move backwards (interleaved eras are
|
||||
// written in true-UTC order, but guard against sub-ms jitter).
|
||||
var readAt = trueUtc.AddMilliseconds(120);
|
||||
if (readAt > h.Now) h.Now = readAt;
|
||||
|
||||
// In production the 100 ms poll keeps running through write silences — every
|
||||
// empty look refreshes the freshness window. The fixture's transition window
|
||||
// spans multi-minute write gaps, so replay that cadence with one empty poll
|
||||
// just before each append; without it the NEXT pass would (correctly!)
|
||||
// classify the gap as a stall and refuse to anchor.
|
||||
h.Now = h.Now.AddMilliseconds(-100);
|
||||
await h.Pass();
|
||||
h.Now = readAt;
|
||||
|
||||
_expectedForCurrentEntry = trueUtc;
|
||||
File.AppendAllText(h.PathOf("AgentExecutor.log"), entry + Environment.NewLine);
|
||||
await h.Pass();
|
||||
_expectedForCurrentEntry = null;
|
||||
}
|
||||
}
|
||||
finally
|
||||
{
|
||||
h.Tracker.OnPatternMatched -= capture;
|
||||
}
|
||||
|
||||
// Every matched entry resolved to the instant its writer rendered — across BOTH
|
||||
// eras, including the flips. This is the exact property whose absence produced the
|
||||
// -9 h script durations.
|
||||
Assert.Equal(entries.Count, resolvedList.Count);
|
||||
Assert.All(resolvedList, r => Assert.Equal(r.Expected, r.Resolved));
|
||||
Assert.True(anchored == resolvedList.Count,
|
||||
$"expected every entry line-anchored, got {anchored}/{resolvedList.Count}");
|
||||
|
||||
// Both eras genuinely exercised: PDT entries render at local hour 05, CEST at 14.
|
||||
Assert.Contains(resolvedList, r => (r.Expected + TimeSpan.FromHours(-7)).Hour == 5);
|
||||
Assert.Contains(resolvedList, r => (r.Expected + TimeSpan.FromHours(2)).Hour == 14);
|
||||
}
|
||||
|
||||
private DateTime? _expectedForCurrentEntry;
|
||||
}
|
||||
}
|
||||
+10
-9
@@ -88,13 +88,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
[InlineData(0)] // UTC
|
||||
public async Task MeasuresTheWritersOffsetExactly_ForAnyBelief(int writerOffsetHours)
|
||||
{
|
||||
// NOTE: this used to assert that a line written at T RESOLVES to T. That application
|
||||
// was reverted on 2026-08-20 after session e9753578: one offset per file is wrong when
|
||||
// a file holds two writer eras (IME restarting across a timezone change), which shifted
|
||||
// 5 script_started events by -9 h while their completions stayed correct and inflated
|
||||
// every script duration to ~32,400 s. Until the calibrator is era-aware, the measured
|
||||
// offset is observational and the reader-zone fallback is applied uniformly — wrong in
|
||||
// absolute terms but self-consistent, so derived durations stay right.
|
||||
// NOTE: the per-FILE measurement asserted here is OBSERVATIONAL — its application was
|
||||
// reverted on 2026-08-20 (04b1a7c6) because one offset per file is wrong when a file
|
||||
// holds interleaved writer eras. Resolution now anchors per LINE instead (see
|
||||
// ImeLogTrackerLineAnchoringTests, which restores the "a line written at T resolves
|
||||
// to T" property era-safely). The per-file measurement stays for the Info log and
|
||||
// measuredWriterOffsetMinutes provenance.
|
||||
var writerOffset = TimeSpan.FromHours(writerOffsetHours);
|
||||
using var h = new Harness();
|
||||
|
||||
@@ -222,10 +221,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
h.Append(Line("marker 3", h.Now, writerOffset));
|
||||
await h.Pass();
|
||||
|
||||
// Measured: the writer's actual belief.
|
||||
// Measured: the writer's actual belief, per file.
|
||||
Assert.Equal(-420, h.Tracker.LastMatchedMeasuredWriterOffsetMinutes);
|
||||
|
||||
// Applied: still the reader zone, and reported as such — never as "calibrated".
|
||||
// Applied: the line's OWN anchor (fresh pass), never the per-file "calibrated" value —
|
||||
// the two must stay distinguishable even when they agree numerically.
|
||||
Assert.Equal(CmTraceOffsetOrigin.LineAnchored, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
Assert.NotEqual(CmTraceOffsetOrigin.Calibrated, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
}
|
||||
|
||||
|
||||
+47
-7
@@ -12,8 +12,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// <summary>The writer declared its offset in the line ("+480"). Authoritative.</summary>
|
||||
Bias = 1,
|
||||
|
||||
/// <summary>Offset measured from a freshly appended line. See <see cref="CmTraceOffsetCalibrator"/>.</summary>
|
||||
/// <summary>
|
||||
/// A per-FILE measured offset was applied. Retired by the 2026-08-20 revert (04b1a7c6):
|
||||
/// one offset per file is wrong when a file holds lines from two writer eras. Kept so
|
||||
/// stored events from agent 2.0.1410 remain interpretable.
|
||||
/// </summary>
|
||||
Calibrated = 2,
|
||||
|
||||
/// <summary>
|
||||
/// The line anchored ITSELF: it was read in a pass whose lines are provably fresh
|
||||
/// (written since the previous poll), so its own distance to the agent clock, rounded
|
||||
/// to the 15-minute offset grid, IS the writer's offset — no cross-line state involved.
|
||||
/// Immune to interleaved writer eras by construction. See
|
||||
/// <see cref="CmTraceOffsetCalibrator.TryMeasureOffset"/>.
|
||||
/// </summary>
|
||||
LineAnchored = 3,
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -98,24 +111,51 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// <param name="localTimestamp">The line's local time exactly as written (Kind is ignored).</param>
|
||||
/// <param name="agentUtcNow">The agent's UTC clock at parse time.</param>
|
||||
/// <returns><c>true</c> when the anchor was accepted and the offset updated.</returns>
|
||||
public bool TryCalibrate(string sourceKey, DateTime localTimestamp, DateTime agentUtcNow)
|
||||
/// <summary>
|
||||
/// The pure measurement: the distance between a FRESH line's local time and the agent's
|
||||
/// UTC clock, rounded to the 15-minute offset grid, is the writer's UTC offset.
|
||||
/// <para>
|
||||
/// Freshness is the caller's obligation and is what makes this correct — for a line
|
||||
/// written within the last poll interval, <c>local - now</c> differs from the writer's
|
||||
/// true offset only by seconds, which the grid rounding absorbs. Returns <c>false</c>
|
||||
/// when the residual exceeds <see cref="MaxGridResidual"/> (the line is not fresh, or
|
||||
/// the writer's clock is broken) or the rounded value is not a real timezone offset.
|
||||
/// </para>
|
||||
/// <para>
|
||||
/// Known, accepted edge: a freshly WRITTEN line carrying an old REPLAYED timestamp whose
|
||||
/// age happens to sit within the residual of an exact grid multiple measures that age as
|
||||
/// an "offset" — the line then resolves to roughly the read time instead of its replayed
|
||||
/// past. The error is bounded by construction (an anchored line always resolves to
|
||||
/// now ± <see cref="MaxGridResidual"/>), the case needs an age of exactly N×15 min ± 2 min,
|
||||
/// and sub-24h replays are treated as current by the historic-replay guard anyway.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public static bool TryMeasureOffset(DateTime localTimestamp, DateTime agentUtcNow, out TimeSpan offset)
|
||||
{
|
||||
if (string.IsNullOrEmpty(sourceKey)) return false;
|
||||
|
||||
var candidate = DateTime.SpecifyKind(localTimestamp, DateTimeKind.Unspecified)
|
||||
- DateTime.SpecifyKind(agentUtcNow, DateTimeKind.Unspecified);
|
||||
|
||||
var gridUnits = Math.Round(candidate.TotalMinutes / OffsetGrid.TotalMinutes,
|
||||
MidpointRounding.AwayFromZero);
|
||||
var offset = TimeSpan.FromMinutes(gridUnits * OffsetGrid.TotalMinutes);
|
||||
offset = TimeSpan.FromMinutes(gridUnits * OffsetGrid.TotalMinutes);
|
||||
|
||||
// Off-grid by more than the tolerance: the anchor was not fresh, or the writer's own
|
||||
// clock is broken. Either way it must not become the offset.
|
||||
// Off-grid by more than the tolerance: the line was not fresh, or the writer's own
|
||||
// clock is broken. Either way it must not become an offset.
|
||||
if ((candidate - offset).Duration() > MaxGridResidual) return false;
|
||||
|
||||
// Not a value any real timezone can produce.
|
||||
if (offset < MinOffset || offset > MaxOffset) return false;
|
||||
|
||||
return true;
|
||||
}
|
||||
|
||||
public bool TryCalibrate(string sourceKey, DateTime localTimestamp, DateTime agentUtcNow)
|
||||
{
|
||||
if (string.IsNullOrEmpty(sourceKey)) return false;
|
||||
|
||||
TimeSpan offset;
|
||||
if (!TryMeasureOffset(localTimestamp, agentUtcNow, out offset)) return false;
|
||||
|
||||
lock (_lock)
|
||||
{
|
||||
if (_bySource.TryGetValue(sourceKey, out var existing))
|
||||
|
||||
+88
-22
@@ -77,12 +77,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
var fileInfo = new FileInfo(filePath);
|
||||
if (!fileInfo.Exists) continue;
|
||||
|
||||
// Captured BEFORE GetSafePosition, which creates the entry as a side effect.
|
||||
// Growth measured against a previously observed size is what makes the last
|
||||
// line of this pass a valid "written now" calibration anchor.
|
||||
// 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.
|
||||
var hadPreviousObservation = _positionTracker.HasSeen(filePath);
|
||||
var lastCheckedUtc = _positionTracker.GetLastCheckedUtc(filePath);
|
||||
var passNowUtc = UtcNowProvider();
|
||||
|
||||
var startPos = _positionTracker.GetSafePosition(filePath, fileInfo.Length);
|
||||
|
||||
// Every look counts, including "no new data" and an empty first sight: the
|
||||
// NEXT pass's freshness window is measured from here. Restored bookmarks
|
||||
// deliberately carry no LastCheckedUtc — the first pass after a restart reads
|
||||
// downtime backlog and must never count as fresh.
|
||||
_positionTracker.MarkChecked(filePath, passNowUtc);
|
||||
|
||||
if (startPos >= fileInfo.Length)
|
||||
{
|
||||
// M2: guard the interpolated string so it isn't built every 100 ms tick
|
||||
@@ -95,6 +104,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
_logger.Trace($"ImeLogTracker: reading {Path.GetFileName(filePath)} from pos {startPos} (size={fileInfo.Length}, delta={fileInfo.Length - startPos})");
|
||||
|
||||
_currentSourceFileName = Path.GetFileName(filePath);
|
||||
_currentPassLinesAreFresh = hadPreviousObservation
|
||||
&& lastCheckedUtc > DateTime.MinValue
|
||||
&& (passNowUtc - lastCheckedUtc) <= FreshLineMaxAge;
|
||||
|
||||
// Newest bias-less line of this pass — the calibration anchor. Bias-carrying
|
||||
// lines are skipped: they already state the writer's offset, so they need no
|
||||
@@ -210,7 +222,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// growing pass, during which lines fall back to the reader zone and are
|
||||
// flagged as such.
|
||||
if (hadPreviousObservation && calibrationAnchor != null)
|
||||
CalibrateFrom(_currentSourceFileName, calibrationAnchor);
|
||||
CalibrateFrom(_currentSourceFileName, Path.GetFileName(filePath), calibrationAnchor);
|
||||
}
|
||||
}
|
||||
catch (FileNotFoundException) { }
|
||||
@@ -650,56 +662,110 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
if (!entry.HasTimestamp) return UtcNowProvider();
|
||||
|
||||
// REVERTED 2026-08-20 (session e9753578): the measured offset is NOT applied.
|
||||
// ERA-AWARE RESOLUTION (2026-08-20, second attempt): a FRESH line anchors ITSELF.
|
||||
//
|
||||
// Calibration keeps one offset per FILE, but a single log file can hold lines from
|
||||
// two writer eras — IME restarting across a timezone change leaves older lines in the
|
||||
// old zone and newer ones in the new zone, in the same file. The anchor is the newest
|
||||
// line, so its offset was also applied to the older lines, for which it is wrong. In
|
||||
// the field that shifted 5 script_started events by -9 h while their script_completed
|
||||
// counterparts were resolved correctly, inflating every script duration to ~32,400 s.
|
||||
// The first attempt (e9dba11b, reverted in 04b1a7c6) applied one measured offset per
|
||||
// FILE — wrong, because a single log file holds lines from multiple writer eras:
|
||||
// AgentExecutor.log is written by short-lived child processes whose zone belief
|
||||
// flips per process, interleaved in one file (fixture
|
||||
// tests/fixtures/cmtrace-logs/agentexecutor-two-writer-eras-v1.cmtrace). Any
|
||||
// cross-line anchor — per file, or nearest-in-write-order — inherits that trap.
|
||||
//
|
||||
// The deeper lesson: applying the reader zone uniformly is wrong for ABSOLUTE times
|
||||
// but self-consistent for DERIVED ones — both ends of a duration are wrong by the same
|
||||
// amount, so the duration is right. Correcting only some timestamps produced a mixed
|
||||
// frame INSIDE one session, which is strictly worse. Until the calibrator is era-aware
|
||||
// (see tasks/todo.md), uniform beats partially-correct.
|
||||
//
|
||||
// The measurement itself still runs: it costs nothing, feeds the Info log and the
|
||||
// event provenance, and is the field data the era-aware fix will be built on.
|
||||
// Per-line self-anchoring does not: at a 100 ms poll every line of a growing pass
|
||||
// was written essentially "now", so its own distance to the agent clock IS its
|
||||
// writer's offset, era by era. The line's timestamp still contributes the sub-poll
|
||||
// precision and ordering (two lines 6 ms apart stay 6 ms apart — a plain
|
||||
// occurredAt=now could not do that), while the offset grid absorbs poll latency.
|
||||
// Freshness is load-bearing (see FreshLineMaxAge) — backlog passes, restart
|
||||
// catch-up and replay logs must never anchor, because an old line's AGE can round
|
||||
// onto the grid.
|
||||
if (_currentPassLinesAreFresh)
|
||||
{
|
||||
TimeSpan lineOffset;
|
||||
if (CmTraceOffsetCalibrator.TryMeasureOffset(entry.LocalTimestamp, UtcNowProvider(), out lineOffset))
|
||||
{
|
||||
origin = CmTraceOffsetOrigin.LineAnchored;
|
||||
offsetMinutes = (int)lineOffset.TotalMinutes;
|
||||
return DateTime.SpecifyKind(entry.LocalTimestamp - lineOffset, DateTimeKind.Utc);
|
||||
}
|
||||
}
|
||||
|
||||
// Fallback for everything not provably fresh: assume the reader's zone, UNIFORMLY.
|
||||
// Wrong in absolute terms whenever the writer held a different belief, but
|
||||
// self-consistent — both ends of a duration are wrong by the same amount, so derived
|
||||
// durations stay right. That asymmetry is the lesson of the 04b1a7c6 revert:
|
||||
// partially corrected is strictly worse than uniformly wrong. Origin stays None so
|
||||
// the emitted event says so.
|
||||
var readerZoneOffset = TimeZoneInfo.Local.GetUtcOffset(entry.LocalTimestamp);
|
||||
offsetMinutes = (int)readerZoneOffset.TotalMinutes;
|
||||
return CmTraceLogParser.ResolveUtcAssumingReaderZone(entry.LocalTimestamp);
|
||||
}
|
||||
|
||||
// Field-forensics (tripwire, 2026-08-20): sessions e9753578 and 067797d8 both logged a
|
||||
// measurement whose LABEL and ANCHOR could not have come from the same file iteration —
|
||||
// 067797d8's anchor value (19:51:26.948) does not even exist in ANY log file on the
|
||||
// device, and IntuneManagementExtension.log never produced its expected first
|
||||
// measurement at all. Mechanism unexplained; resolution is immune (per-line anchoring),
|
||||
// but the observational layer must convict the culprit on the next occurrence. Hence:
|
||||
// the stream's file name travels alongside the label (a mismatch is THE smoking gun),
|
||||
// and the first rejected anchor per file becomes visible instead of silent.
|
||||
private readonly HashSet<string> _calibrationRejectLogged = new HashSet<string>(StringComparer.OrdinalIgnoreCase);
|
||||
|
||||
/// <summary>
|
||||
/// Feed the pass's newest bias-less line to the calibrator and report a measured offset
|
||||
/// that disagrees with this process's own zone — that disagreement is precisely the
|
||||
/// condition that used to corrupt every IME-derived timestamp silently.
|
||||
/// </summary>
|
||||
private void CalibrateFrom(string sourceFileName, CmTraceLogEntry anchor)
|
||||
/// <param name="sourceFileName">The calibration key (<c>_currentSourceFileName</c>).</param>
|
||||
/// <param name="streamFileName">The file the enclosing iteration actually read. Must equal
|
||||
/// <paramref name="sourceFileName"/> — logged loudly when it does not (see tripwire note).</param>
|
||||
private void CalibrateFrom(string sourceFileName, string streamFileName, CmTraceLogEntry anchor)
|
||||
{
|
||||
if (!string.Equals(sourceFileName, streamFileName, StringComparison.OrdinalIgnoreCase))
|
||||
{
|
||||
_logger?.Warning(
|
||||
$"ImeLogTracker: CALIBRATION LABEL MISMATCH — key='{sourceFileName}' but the iteration read '{streamFileName}' " +
|
||||
$"(anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fffffff}). Skipping this anchor; see tripwire note.");
|
||||
return;
|
||||
}
|
||||
|
||||
TimeSpan previous;
|
||||
var hadOffset = OffsetCalibrator.TryGetOffset(sourceFileName, out previous);
|
||||
|
||||
if (!OffsetCalibrator.TryCalibrate(sourceFileName, anchor.LocalTimestamp, UtcNowProvider()))
|
||||
{
|
||||
// Once per file: why a file that visibly grows never produces a measurement.
|
||||
// 067797d8 ran 24 s of growing IME.log passes with no measurement at all — this
|
||||
// silence is exactly what made the phenomenon undiagnosable from the log.
|
||||
if (_calibrationRejectLogged.Add(sourceFileName))
|
||||
{
|
||||
_logger?.Debug(
|
||||
$"ImeLogTracker: {sourceFileName} anchor rejected by calibrator " +
|
||||
$"(anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fffffff}, now={UtcNowProvider():HH:mm:ss.fff}Z) — first rejection for this file, further ones stay silent.");
|
||||
}
|
||||
return;
|
||||
}
|
||||
|
||||
TimeSpan measured;
|
||||
if (!OffsetCalibrator.TryGetOffset(sourceFileName, out measured)) return;
|
||||
if (hadOffset && measured == previous) return;
|
||||
|
||||
// The anchor's local timestamp is part of the record ON PURPOSE (tripwire, 2026-08-20):
|
||||
// session e9753578 logged "+02:00 measured for IntuneManagementExtension.log" although
|
||||
// that file provably held no +2-era line — an anchor/label pairing the committed code
|
||||
// could not be shown to produce. Should it ever happen again, the logged anchor value
|
||||
// itself will prove (or refute) the crossing without needing the device's log files.
|
||||
var readerZoneOffset = TimeZoneInfo.Local.GetUtcOffset(UtcNowProvider());
|
||||
if (measured == readerZoneOffset)
|
||||
{
|
||||
_logger?.Debug(
|
||||
$"ImeLogTracker: {sourceFileName} writer offset measured {measured} (matches this process).");
|
||||
$"ImeLogTracker: {sourceFileName} writer offset measured {measured} (matches this process, anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fff}).");
|
||||
return;
|
||||
}
|
||||
|
||||
_logger?.Info(
|
||||
$"ImeLogTracker: {sourceFileName} writer offset measured {measured}, this process believes {readerZoneOffset} " +
|
||||
$"— timestamps from this file are corrected by {(measured - readerZoneOffset).Negate()}.");
|
||||
$"(anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fff}). Measurement is observational — resolution anchors per line.");
|
||||
}
|
||||
|
||||
}
|
||||
|
||||
@@ -103,6 +103,24 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// </summary>
|
||||
private string _currentSourceFileName;
|
||||
|
||||
/// <summary>
|
||||
/// Whether every line of the file iteration currently in flight is provably FRESH —
|
||||
/// written after the previous look at this file, which happened at most
|
||||
/// <see cref="FreshLineMaxAge"/> ago in THIS process. Only then may a line anchor its
|
||||
/// own UTC offset (<see cref="CmTraceOffsetCalibrator.TryMeasureOffset"/>): the grid
|
||||
/// rounding is safe when the line's age is bounded by seconds, and becomes a trap on
|
||||
/// backlog whose age can hit an exact grid multiple. Same single-task justification as
|
||||
/// <see cref="_currentSourceFileName"/>.
|
||||
/// </summary>
|
||||
private bool _currentPassLinesAreFresh;
|
||||
|
||||
/// <summary>
|
||||
/// Maximum gap between two looks at a file for its new bytes to count as fresh. Far
|
||||
/// above the 100 ms poll (rides out GC pauses and ESP CPU starvation), far below the
|
||||
/// 13-minute danger zone where a line's AGE could round onto the 15-minute offset grid.
|
||||
/// </summary>
|
||||
internal static readonly TimeSpan FreshLineMaxAge = TimeSpan.FromSeconds(30);
|
||||
|
||||
internal static DateTime NormalizeUtc(DateTime value) =>
|
||||
value.Kind == DateTimeKind.Utc ? value : DateTime.SpecifyKind(value, DateTimeKind.Utc);
|
||||
|
||||
|
||||
+50
-1
@@ -65,6 +65,42 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
state.LastReadTime = DateTime.UtcNow;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Records that the file was looked at in a poll pass — whether or not it had new data.
|
||||
/// Creates the entry on first sight (position 0), so a file first seen EMPTY counts as
|
||||
/// observed and its first content is provably fresh.
|
||||
/// <para>
|
||||
/// This timestamp is the freshness reference for per-line offset anchoring: bytes found
|
||||
/// in the NEXT pass were written after this instant, so
|
||||
/// <c>now - LastCheckedUtc</c> bounds the age of every line in that pass's chunk.
|
||||
/// The caller supplies the clock (the tracker's <c>UtcNowProvider</c>) so replay/test
|
||||
/// clocks stay consistent with the freshness comparison.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public void MarkChecked(string filePath, DateTime nowUtc)
|
||||
{
|
||||
FilePositionState state;
|
||||
if (!_positions.TryGetValue(filePath, out state))
|
||||
{
|
||||
state = new FilePositionState();
|
||||
_positions[filePath] = state;
|
||||
}
|
||||
|
||||
state.LastCheckedUtc = nowUtc;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// When the file was last looked at, or <see cref="DateTime.MinValue"/> when it never
|
||||
/// was in THIS process — including entries restored from persisted state, whose
|
||||
/// bookmark survives an agent restart but whose freshness deliberately does not
|
||||
/// (the restart gap can hold arbitrarily old backlog).
|
||||
/// </summary>
|
||||
public DateTime GetLastCheckedUtc(string filePath)
|
||||
{
|
||||
FilePositionState state;
|
||||
return _positions.TryGetValue(filePath, out state) ? state.LastCheckedUtc : DateTime.MinValue;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Gets the stored position for a file, or 0 if not tracked.
|
||||
/// Does not perform rollover detection.
|
||||
@@ -89,6 +125,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// <summary>
|
||||
/// Restores a previously persisted position for a file.
|
||||
/// Used on agent restart to continue reading from the last known position.
|
||||
/// <para>
|
||||
/// <see cref="FilePositionState.LastCheckedUtc"/> is deliberately NOT restored: the
|
||||
/// bookmark survives the restart, the freshness guarantee does not — the first pass
|
||||
/// after a restart reads the whole downtime backlog and must never anchor per-line
|
||||
/// offsets on it.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public void RestorePosition(string filePath, long position, long lastKnownSize)
|
||||
{
|
||||
@@ -96,7 +138,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
Position = position,
|
||||
LastKnownSize = lastKnownSize,
|
||||
LastReadTime = DateTime.UtcNow
|
||||
LastReadTime = DateTime.UtcNow,
|
||||
LastCheckedUtc = DateTime.MinValue
|
||||
};
|
||||
}
|
||||
}
|
||||
@@ -106,5 +149,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
public long Position { get; set; }
|
||||
public long LastKnownSize { get; set; }
|
||||
public DateTime LastReadTime { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// When this file was last looked at by a poll pass IN THIS PROCESS. In-memory only —
|
||||
/// never persisted, so a restart resets it (see <see cref="LogFilePositionTracker.RestorePosition"/>).
|
||||
/// </summary>
|
||||
public DateTime LastCheckedUtc { get; set; }
|
||||
}
|
||||
}
|
||||
|
||||
@@ -427,11 +427,14 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
switch (origin)
|
||||
{
|
||||
case CmTraceOffsetOrigin.Bias: return "bias";
|
||||
// Per-FILE offset application, retired by the 2026-08-20 revert (04b1a7c6).
|
||||
// Kept so stored 2.0.1410 events remain interpretable; no current path emits it.
|
||||
case CmTraceOffsetOrigin.Calibrated: return "calibrated";
|
||||
// Unreachable since the 2026-08-20 revert; kept so the vocabulary survives the
|
||||
// era-aware fix rather than being reinvented.
|
||||
// The writer's offset was never measured, so this process's own zone was assumed —
|
||||
// correct only if the writer happens to share it.
|
||||
// The line anchored itself: read provably fresh, its own distance to the agent
|
||||
// clock (grid-rounded) was applied as the writer's offset. Era-safe per line.
|
||||
case CmTraceOffsetOrigin.LineAnchored: return "line-anchored";
|
||||
// The line was not provably fresh (backlog, restart catch-up, replay), so this
|
||||
// process's own zone was assumed — correct only if the writer happens to share it.
|
||||
default: return "reader-zone-fallback";
|
||||
}
|
||||
}
|
||||
|
||||
@@ -200,4 +200,120 @@ public class ReportAgentErrorFunctionTests
|
||||
|
||||
Assert.Empty(h.OpsEvents);
|
||||
}
|
||||
|
||||
// =========================================================================
|
||||
// MaterializeIntegrityMismatchAsync — an IntegrityCheckFailed report becomes an
|
||||
// AgentBinaryIntegrityMismatch ops event, UNLESS it is the known release race
|
||||
// (agents comparing against hash snapshots that don't belong to their own binary;
|
||||
// AdminConfig cache TTL 5 min). e9753578 proved the race: a genuine 1410 exe was
|
||||
// compared against the cached 1409 hash and reported a "mismatch" that cost a day
|
||||
// of mis-attributed root-causing while sitting invisible in App Insights.
|
||||
// =========================================================================
|
||||
|
||||
private const string RunningExeSha = "5fca975e43fa5fca975e43fa5fca975e43fa5fca975e43fa5fca975e43fa0000";
|
||||
private const string PublishedExeSha = "8ebaa060ad348ebaa060ad348ebaa060ad348ebaa060ad348ebaa060ad340000";
|
||||
|
||||
private static AgentErrorReport IntegrityReport(
|
||||
string? sessionId = SessionId, string agentVersion = "2.0.1410", string? actualSha = null) => new()
|
||||
{
|
||||
SessionId = sessionId!,
|
||||
TenantId = TenantId,
|
||||
ErrorType = AgentErrorType.IntegrityCheckFailed,
|
||||
Message = $"Running exe SHA-256 differs from backend-advertised hash. actual={actualSha ?? RunningExeSha}, expected={PublishedExeSha}",
|
||||
AgentVersion = agentVersion,
|
||||
Timestamp = Now,
|
||||
};
|
||||
|
||||
private static Task RunIntegrityAsync(
|
||||
Harness h, AgentErrorReport report,
|
||||
string? latestVersion = "2.0.1410", string? latestExeSha = PublishedExeSha)
|
||||
=> ReportAgentErrorFunction.MaterializeIntegrityMismatchAsync(
|
||||
report, TenantId, h.OpsService, latestVersion, latestExeSha,
|
||||
NullLogger<ReportAgentErrorFunction>.Instance);
|
||||
|
||||
[Fact]
|
||||
public async Task SameVersion_with_unknown_binary_records_ops_event()
|
||||
{
|
||||
// The real signal: an agent claiming the LATEST version whose running exe is NOT
|
||||
// the published one — tamper, stale blob, or a build outside the release pipeline.
|
||||
var h = new Harness();
|
||||
|
||||
await RunIntegrityAsync(h, IntegrityReport());
|
||||
|
||||
var ops = Assert.Single(h.OpsEvents);
|
||||
Assert.Equal("AgentBinaryIntegrityMismatch", ops.EventType);
|
||||
Assert.Equal(TenantId, ops.TenantId);
|
||||
Assert.Contains("actual=5fca", ops.Message);
|
||||
Assert.Contains("2.0.1410", ops.Message);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task RunningHash_equal_to_published_exe_is_suppressed_as_stale_expectation()
|
||||
{
|
||||
// e9753578's exact shape: the device RUNS the published binary; only its cached
|
||||
// expectation was the previous release's hash. Self-heals — must not alert.
|
||||
var h = new Harness();
|
||||
|
||||
await RunIntegrityAsync(h, IntegrityReport(actualSha: PublishedExeSha));
|
||||
|
||||
Assert.Empty(h.OpsEvents);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Older_agent_version_than_latest_is_suppressed_as_update_race()
|
||||
{
|
||||
// The long-known direction: version N agent sees version N+1's hash right after a
|
||||
// release; the forced self-update heals it.
|
||||
var h = new Harness();
|
||||
|
||||
await RunIntegrityAsync(h, IntegrityReport(agentVersion: "2.0.1409+d43cfe2b"), latestVersion: "2.0.1410");
|
||||
|
||||
Assert.Empty(h.OpsEvents);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Version_with_commit_suffix_matches_latest_without_suffix()
|
||||
{
|
||||
// Agent versions carry "+<commit>", AdminConfiguration does not — the comparison
|
||||
// must normalize, otherwise every genuine mismatch would look like a version race.
|
||||
var h = new Harness();
|
||||
|
||||
await RunIntegrityAsync(h, IntegrityReport(agentVersion: "2.0.1410+3b59dab2df6c"));
|
||||
|
||||
Assert.Single(h.OpsEvents);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Missing_latest_config_fails_open_to_recording()
|
||||
{
|
||||
// No published-version info available → visibility wins over suppression.
|
||||
var h = new Harness();
|
||||
|
||||
await RunIntegrityAsync(h, IntegrityReport(), latestVersion: null, latestExeSha: null);
|
||||
|
||||
Assert.Single(h.OpsEvents);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Integrity_mismatch_without_session_id_still_records_ops_event()
|
||||
{
|
||||
// The report can arrive before session registration — the binary evidence must
|
||||
// never be dropped for lack of a session.
|
||||
var h = new Harness();
|
||||
|
||||
await RunIntegrityAsync(h, IntegrityReport(sessionId: null));
|
||||
|
||||
var ops = Assert.Single(h.OpsEvents);
|
||||
Assert.Equal("AgentBinaryIntegrityMismatch", ops.EventType);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Other_error_types_do_not_record_integrity_ops_event()
|
||||
{
|
||||
var h = new Harness();
|
||||
|
||||
await RunIntegrityAsync(h, Report(Now));
|
||||
|
||||
Assert.Empty(h.OpsEvents);
|
||||
}
|
||||
}
|
||||
|
||||
@@ -178,9 +178,90 @@ namespace AutopilotMonitor.Functions.Functions.Ingest
|
||||
|
||||
await MaterializeEmergencyBreakArtifactsAsync(report, tenantId, _sessionRepo, _opsEventService, _logger);
|
||||
|
||||
var adminConfig = await _adminConfigService.GetConfigurationAsync();
|
||||
await MaterializeIntegrityMismatchAsync(
|
||||
report, tenantId, _opsEventService,
|
||||
adminConfig?.LatestAgentV2Version, adminConfig?.LatestAgentV2ExeSha256, _logger);
|
||||
|
||||
return req.CreateResponse(HttpStatusCode.OK);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Regex over OUR OWN report format (AgentRuntimeConfig.VerifyBinaryIntegrity):
|
||||
/// "... actual=<sha256>, expected=<sha256>". Parsed leniently — an unparseable
|
||||
/// message records rather than suppresses.
|
||||
/// </summary>
|
||||
private static readonly System.Text.RegularExpressions.Regex ActualHashRegex =
|
||||
new(@"actual=([0-9a-fA-F]{64})", System.Text.RegularExpressions.RegexOptions.Compiled);
|
||||
|
||||
/// <summary>
|
||||
/// Surfaces an <c>IntegrityCheckFailed</c> report as an <c>AgentBinaryIntegrityMismatch</c>
|
||||
/// ops event. Before 2026-08-20 this report went to App Insights only — session e9753578's
|
||||
/// agent reported a hash mismatch and no product surface showed it, which cost a day of
|
||||
/// mis-attributed root-causing.
|
||||
///
|
||||
/// <para>
|
||||
/// KNOWN, ACCEPTED RACE (must not spam the ops feed): around every release, agents compare
|
||||
/// against a hash snapshot that does not belong to their own binary — a freshly installed
|
||||
/// latest agent can receive the PREVIOUS release's hashes from the 5-minute
|
||||
/// AdminConfiguration cache (e9753578: genuine 1410 exe vs cached 1409 hash), and an
|
||||
/// older agent's next config fetch sees the NEW release's hash. Both self-heal via the
|
||||
/// forced self-update. Suppression, evaluated against the CURRENT config at receive time:
|
||||
/// the reported RUNNING hash equals the published exe (stale expectation), or the
|
||||
/// reporting agent's version is not the latest (update in flight). What remains — an agent
|
||||
/// claiming the latest version whose binary is NOT the published one — is the real signal:
|
||||
/// tamper, stale blob, or a build that never came from the release pipeline.
|
||||
/// </para>
|
||||
///
|
||||
/// <para>
|
||||
/// Ops event only, no timeline event: the report is about the BINARY, not the enrollment,
|
||||
/// and may arrive before the session is registered. No idempotency read: the agent-side
|
||||
/// trigger is single-shot per process. Best-effort — a failure here must never turn the
|
||||
/// always-200 channel into a retry loop.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
internal static async Task MaterializeIntegrityMismatchAsync(
|
||||
AgentErrorReport report,
|
||||
string tenantId,
|
||||
OpsEventService opsEventService,
|
||||
string? latestAgentVersion,
|
||||
string? latestAgentExeSha256,
|
||||
ILogger logger)
|
||||
{
|
||||
if (report.ErrorType != AgentErrorType.IntegrityCheckFailed)
|
||||
{
|
||||
return;
|
||||
}
|
||||
|
||||
try
|
||||
{
|
||||
// "2.0.1410+3b59dab2..." → "2.0.1410" (the manifest/AdminConfig carry no +commit).
|
||||
var reportedVersion = (report.AgentVersion ?? string.Empty).Split('+')[0];
|
||||
if (!string.IsNullOrEmpty(latestAgentVersion)
|
||||
&& !string.IsNullOrEmpty(reportedVersion)
|
||||
&& !string.Equals(reportedVersion, latestAgentVersion, StringComparison.OrdinalIgnoreCase))
|
||||
{
|
||||
return; // older agent vs newer release — the forced self-update heals this.
|
||||
}
|
||||
|
||||
var actualMatch = ActualHashRegex.Match(report.Message ?? string.Empty);
|
||||
if (actualMatch.Success
|
||||
&& !string.IsNullOrEmpty(latestAgentExeSha256)
|
||||
&& string.Equals(actualMatch.Groups[1].Value, latestAgentExeSha256, StringComparison.OrdinalIgnoreCase))
|
||||
{
|
||||
return; // the running binary IS the published one — the agent's expectation was stale.
|
||||
}
|
||||
|
||||
await opsEventService.RecordAgentBinaryIntegrityMismatchAsync(
|
||||
tenantId, report.SessionId, report.AgentVersion, report.Message ?? string.Empty);
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
logger.LogWarning(ex,
|
||||
"ReportAgentError: failed to record AgentBinaryIntegrityMismatch ops event for session {SessionId}", report.SessionId);
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Materializes the agent's silent 48h emergency break as (1) a timeline event so it shows
|
||||
/// in the session and the timeout classifier can see it, (2) the cross-session EventType
|
||||
|
||||
@@ -608,6 +608,20 @@ namespace AutopilotMonitor.Functions.Services
|
||||
$"Agent emergency break on session {sessionId} (agent {agentVersion ?? "?"}): {message}",
|
||||
tenantId, "System.EmergencyChannel", new { sessionId, agentVersion });
|
||||
|
||||
/// <summary>
|
||||
/// An agent reported that its RUNNING exe's SHA-256 differs from the hash the backend
|
||||
/// advertises for its version — the binary in the field is not the published build
|
||||
/// (tamper, stale blob, or a build that never came from a committed tree). Session
|
||||
/// e9753578 (2026-08-20) carried exactly this report, but it landed only in App
|
||||
/// Insights and was invisible to every product surface while the field damage was
|
||||
/// mis-attributed to committed code for hours. Warning-tier so operators can wire a
|
||||
/// Telegram rule; the message carries both hashes verbatim.
|
||||
/// </summary>
|
||||
public Task RecordAgentBinaryIntegrityMismatchAsync(string tenantId, string? sessionId, string? agentVersion, string message)
|
||||
=> WriteAsync(OpsEventCategory.Agent, "AgentBinaryIntegrityMismatch", OpsEventSeverity.Warning,
|
||||
$"Agent binary integrity mismatch on session {sessionId ?? "?"} (agent {agentVersion ?? "?"}): {message}",
|
||||
tenantId, "System.EmergencyChannel", new { sessionId, agentVersion });
|
||||
|
||||
public Task RecordExcessiveSessionEventsAsync(string tenantId, string sessionId, int eventCount, int threshold)
|
||||
=> WriteAsync(OpsEventCategory.Agent, "ExcessiveSessionEvents", OpsEventSeverity.Warning,
|
||||
$"Session {sessionId} has {eventCount} events (threshold {threshold}) — likely agent loop bug",
|
||||
|
||||
@@ -146,6 +146,11 @@ const OPS_EVENT_TYPES: Record<string, string[]> = {
|
||||
// ReportAgentErrorFunction (RecordAgentEmergencyBreakAsync). Dual-register per memory
|
||||
// feedback_ops_event_types_dual_register.
|
||||
"AgentEmergencyBreak",
|
||||
// The running exe's SHA-256 differs from the backend-advertised hash for its version —
|
||||
// the field binary is not the published build (tamper / stale blob / uncommitted-tree
|
||||
// build). Emitted by ReportAgentErrorFunction (RecordAgentBinaryIntegrityMismatchAsync).
|
||||
// Dual-register per memory feedback_ops_event_types_dual_register.
|
||||
"AgentBinaryIntegrityMismatch",
|
||||
],
|
||||
Platform: [
|
||||
// Azure Monitor alerts relayed through POST ops/alert-webhook (Common Alert Schema →
|
||||
|
||||
@@ -315,10 +315,10 @@ export function SectionTenantGroups() {
|
||||
return (
|
||||
<div key={t.groupId} className="border border-gray-200 rounded-lg">
|
||||
{/* Group header */}
|
||||
<div className="px-4 py-2 border-b border-gray-100 bg-gray-50 rounded-t-lg flex items-center justify-between gap-2">
|
||||
<div className="px-4 py-2 border-b border-gray-100 bg-gray-50 rounded-t-lg flex flex-col gap-2 sm:flex-row sm:items-center sm:justify-between">
|
||||
<div className="min-w-0">
|
||||
<span className="font-medium text-gray-900 truncate">{t.name}</span>
|
||||
<span className="ml-2 text-xs text-gray-500">
|
||||
<span className="font-medium text-gray-900 break-words">{t.name}</span>
|
||||
<span className="ml-2 text-xs text-gray-500 whitespace-nowrap">
|
||||
{t.tenantIds.length} tenant{t.tenantIds.length === 1 ? "" : "s"} · {t.assigneeCount} assignee
|
||||
{t.assigneeCount === 1 ? "" : "s"}
|
||||
</span>
|
||||
@@ -341,7 +341,7 @@ export function SectionTenantGroups() {
|
||||
|
||||
<div className="p-4 grid gap-4 md:grid-cols-2">
|
||||
{/* Tenants column */}
|
||||
<div className="space-y-2">
|
||||
<div className="min-w-0 space-y-2">
|
||||
<p className="text-xs font-semibold text-gray-700 uppercase tracking-wide">Tenants</p>
|
||||
{t.tenantIds.length === 0 ? (
|
||||
<p className="text-sm text-gray-400">No tenants yet.</p>
|
||||
@@ -349,11 +349,11 @@ export function SectionTenantGroups() {
|
||||
<ul className="space-y-1">
|
||||
{t.tenantIds.map((id) => (
|
||||
<li key={id} className="flex items-center justify-between gap-2 text-sm">
|
||||
<span className="truncate text-gray-900">{domainOf(id) || id}</span>
|
||||
<span className="min-w-0 truncate text-gray-900">{domainOf(id) || id}</span>
|
||||
<button
|
||||
onClick={() => handleRemoveTenant(t, id)}
|
||||
disabled={busyKey === `rmtenant:${t.groupId}:${id}`}
|
||||
className="text-red-600 hover:text-red-800 disabled:opacity-50 text-xs"
|
||||
className="shrink-0 text-red-600 hover:text-red-800 disabled:opacity-50 text-xs"
|
||||
aria-label={`Remove ${domainOf(id) || id}`}
|
||||
>
|
||||
Remove
|
||||
@@ -378,7 +378,7 @@ export function SectionTenantGroups() {
|
||||
<button
|
||||
onClick={() => handleAddTenant(t)}
|
||||
disabled={!tenantToAdd[t.groupId] || busyKey === `addtenant:${t.groupId}`}
|
||||
className="px-3 py-1.5 text-sm bg-sky-600 text-white rounded-lg hover:bg-sky-700 disabled:opacity-50 transition-colors"
|
||||
className="shrink-0 px-3 py-1.5 text-sm bg-sky-600 text-white rounded-lg hover:bg-sky-700 disabled:opacity-50 transition-colors"
|
||||
>
|
||||
Add
|
||||
</button>
|
||||
@@ -386,24 +386,27 @@ export function SectionTenantGroups() {
|
||||
</div>
|
||||
|
||||
{/* Assignees column */}
|
||||
<div className="space-y-2">
|
||||
<div className="min-w-0 space-y-2">
|
||||
<p className="text-xs font-semibold text-gray-700 uppercase tracking-wide">Assignees</p>
|
||||
{t.assignees.length === 0 ? (
|
||||
<p className="text-sm text-gray-400">No one assigned yet.</p>
|
||||
) : (
|
||||
<ul className="space-y-1">
|
||||
<ul className="space-y-2">
|
||||
{t.assignees.map((a) => (
|
||||
<li key={a.upn} className="flex items-center justify-between gap-2 text-sm">
|
||||
<span className="min-w-0 truncate text-gray-900">
|
||||
{a.upn}
|
||||
<span className="ml-1.5 inline-flex items-center px-1.5 py-0.5 rounded text-xs font-medium bg-sky-100 text-sky-800">
|
||||
{ROLE_LABELS[a.role] ?? a.role}
|
||||
</span>
|
||||
<li
|
||||
key={a.upn}
|
||||
className="flex flex-wrap items-center gap-x-1.5 gap-y-1 text-sm"
|
||||
>
|
||||
{/* Full-width UPN on phones so it is not hyphen-broken; the badge and
|
||||
Remove then share the wrapped line below it. */}
|
||||
<span className="w-full break-all text-gray-900 sm:w-auto sm:min-w-0">{a.upn}</span>
|
||||
<span className="inline-flex items-center px-1.5 py-0.5 rounded text-xs font-medium bg-sky-100 text-sky-800">
|
||||
{ROLE_LABELS[a.role] ?? a.role}
|
||||
</span>
|
||||
<button
|
||||
onClick={() => handleUnassign(t, a.upn)}
|
||||
disabled={busyKey === `unassign:${t.groupId}:${a.upn}`}
|
||||
className="text-red-600 hover:text-red-800 disabled:opacity-50 text-xs shrink-0"
|
||||
className="ml-auto shrink-0 text-red-600 hover:text-red-800 disabled:opacity-50 text-xs"
|
||||
aria-label={`Remove ${a.upn}`}
|
||||
>
|
||||
Remove
|
||||
@@ -412,7 +415,7 @@ export function SectionTenantGroups() {
|
||||
))}
|
||||
</ul>
|
||||
)}
|
||||
<div className="flex gap-2 pt-1">
|
||||
<div className="flex flex-wrap gap-2 pt-1">
|
||||
<input
|
||||
type="email"
|
||||
value={assignUpn[t.groupId] || ""}
|
||||
@@ -425,12 +428,12 @@ export function SectionTenantGroups() {
|
||||
}}
|
||||
placeholder="user@domain.com"
|
||||
autoComplete="off"
|
||||
className="flex-1 min-w-0 px-3 py-1.5 border border-gray-300 rounded-lg text-sm text-gray-900 placeholder-gray-500 focus:outline-none focus:ring-2 focus:ring-sky-500 transition-colors"
|
||||
className="w-full sm:w-auto sm:flex-1 min-w-0 px-3 py-1.5 border border-gray-300 rounded-lg text-sm text-gray-900 placeholder-gray-500 focus:outline-none focus:ring-2 focus:ring-sky-500 transition-colors"
|
||||
/>
|
||||
<select
|
||||
value={assignRole[t.groupId] || "DelegatedReader"}
|
||||
onChange={(e) => setAssignRole((p) => ({ ...p, [t.groupId]: e.target.value }))}
|
||||
className="px-2 py-1.5 border border-gray-300 rounded-lg text-sm text-gray-900 bg-white focus:outline-none focus:ring-2 focus:ring-sky-500 transition-colors"
|
||||
className="flex-1 sm:flex-none min-w-0 px-2 py-1.5 border border-gray-300 rounded-lg text-sm text-gray-900 bg-white focus:outline-none focus:ring-2 focus:ring-sky-500 transition-colors"
|
||||
>
|
||||
<option value="DelegatedReader">Reader</option>
|
||||
<option value="DelegatedAdmin">Admin</option>
|
||||
@@ -438,7 +441,7 @@ export function SectionTenantGroups() {
|
||||
<button
|
||||
onClick={() => handleAssign(t)}
|
||||
disabled={!(assignUpn[t.groupId] || "").trim() || busyKey === `assign:${t.groupId}`}
|
||||
className="px-3 py-1.5 text-sm bg-sky-600 text-white rounded-lg hover:bg-sky-700 disabled:opacity-50 transition-colors"
|
||||
className="shrink-0 px-3 py-1.5 text-sm bg-sky-600 text-white rounded-lg hover:bg-sky-700 disabled:opacity-50 transition-colors"
|
||||
>
|
||||
Assign
|
||||
</button>
|
||||
|
||||
+37
@@ -0,0 +1,37 @@
|
||||
# CMTrace Log Fixtures — committed, anonymized
|
||||
|
||||
Raw CMTrace log lines, kept verbatim, used by parser and offset-calibration unit tests in
|
||||
`src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/`.
|
||||
|
||||
## Why this is a separate corpus from `../enrollment-sessions/`
|
||||
|
||||
`enrollment-sessions/` holds anonymized **DecisionSignal** JSONL replayed through the Replay
|
||||
Harness and the reducer scenario tests — signals that have already been parsed, adapted and
|
||||
evidence-tagged. These files are the layer *below* that: unparsed device log text, the raw input
|
||||
to `CmTraceLogParser`. They cannot satisfy that corpus's schema (no signal shape, no
|
||||
`Evidence.Identifier`, no terminal state to assert) and its category prefixes do not apply.
|
||||
|
||||
Both live under `tests/fixtures/` so committed test data has one home. Test projects must not
|
||||
carry their own fixture directories.
|
||||
|
||||
## Commit policy
|
||||
|
||||
1. **Anonymized.** No tenant IDs, device IDs, serial numbers, user names, UPN prefixes, raw IP
|
||||
addresses, or tenant-scoped object GUIDs (Intune policy/script IDs are tenant-scoped — replace
|
||||
them with `policy-anon-NNNN-0000-0000-0000-000000000000`). The all-zero GUID is a literal in
|
||||
IME's own output and stays. A session ID may stay when it is OUR diagnostic anchor and is
|
||||
already referenced from commit messages and `tasks/todo.md`.
|
||||
2. **Verbatim otherwise.** Timestamps, spacing and the `<![LOG[...]]LOG]!>` envelope are the point
|
||||
of the fixture — the parser is being tested against real formatting, so nothing else is
|
||||
normalised or reflowed.
|
||||
3. **Header comment.** State the source session, the agent version, and precisely which property
|
||||
the fixture exists to pin. A fixture whose purpose is not written down decays into noise.
|
||||
4. **Versioned filename.** `-vN` suffix; never edit a committed fixture in place — a test pinned
|
||||
to it would silently change meaning.
|
||||
5. **Extension `.cmtrace`,** not `.log`: `*.log` is globally gitignored.
|
||||
|
||||
## Fixtures
|
||||
|
||||
| File | Source | Pins |
|
||||
|---|---|---|
|
||||
| `agentexecutor-two-writer-eras-v1.cmtrace` | session `e9753578`, agent 2.0.1410, `ImeLogs/AgentExecutor.log` | One file containing TWO writer eras — 371 lines rendered at local hour 05 by a writer on PDT (UTC-7) and 195 at hour 14 by one already on CEST (UTC+2), nine hours apart, interleaved, no bias suffix on any line. The case that broke per-file offset calibration and forced revert `04b1a7c6`. Any era-aware calibrator must resolve BOTH halves correctly. |
|
||||
@@ -0,0 +1,41 @@
|
||||
# Real CMTrace lines from session e9753578-b1d8-4188-9151-7545be7e1761 (agent 2.0.1410).
|
||||
# ImeLogs/AgentExecutor.log - ONE file, TWO writer eras.
|
||||
#
|
||||
# The device booted on the Pacific OOBE default; the agent set W. Europe at 12:13:22Z.
|
||||
# Lines at local hour 05 were rendered by a writer still on PDT (UTC-7), lines at hour 14
|
||||
# by one already on CEST (UTC+2) - 9 hours apart, interleaved in the same log. No line
|
||||
# carries a bias suffix, so nothing in the file itself says which is which.
|
||||
#
|
||||
# This is the case that broke the per-file calibration: the anchor is the newest line, so
|
||||
# its offset was applied to the older era too. Any era-aware calibrator must resolve BOTH
|
||||
# halves of this file correctly.
|
||||
#
|
||||
# era PDT (local 05:xx): 371 lines in the original, era CEST (local 14:xx): 195
|
||||
|
||||
### --- transition window, verbatim ---
|
||||
<![LOG[ExecutorLog AgentExecutor gets invoked]LOG]!><time="14:13:36.8420339" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Creating command line parser, name delimiter is - and value separator is .]LOG]!><time="14:13:36.8460498" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Getting Ordered Parameters]LOG]!><time="14:13:36.8460498" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Parsing Ordered Parameters.]LOG]!><time="14:13:36.8484892" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Adding argument powershell with value C:\Program Files (x86)\Microsoft Intune Management Extension\Policies\Scripts\00000000-0000-0000-0000-000000000000_policy-anon-0001-0000-0000-0000-000000000000.ps1 to the named argument list.]LOG]!><time="14:13:36.8484892" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Powershell option gets invoked]LOG]!><time="14:13:36.8525204" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
|
||||
### --- additional PDT-era samples ---
|
||||
<![LOG[[Proxy Poller using ExectorLog] AgentExecutor log path : C:\ProgramData\Microsoft\IntuneManagementExtension\Logs\AgentExecutor.log]LOG]!><time="05:17:50.5238897" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="8" file="">
|
||||
<![LOG[[Proxy Poller using ExectorLog] AgentExecutor log path : C:\ProgramData\Microsoft\IntuneManagementExtension\Logs\AgentExecutor.log]LOG]!><time="05:17:50.5258992" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="8" file="">
|
||||
<![LOG[ExecutorLog AgentExecutor gets invoked]LOG]!><time="05:22:41.7798901" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Creating command line parser, name delimiter is - and value separator is .]LOG]!><time="05:22:41.7839044" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Getting Ordered Parameters]LOG]!><time="05:22:41.7859130" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Parsing Ordered Parameters.]LOG]!><time="05:22:41.7859130" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Adding argument powershell with value C:\Program Files (x86)\Microsoft Intune Management Extension\Policies\Scripts\policy-anon-0003-0000-0000-0000-000000000000_policy-anon-0002-0000-0000-0000-000000000000.ps1 to the named argument list.]LOG]!><time="05:22:41.7859130" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Powershell option gets invoked]LOG]!><time="05:22:41.7899258" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
|
||||
### --- additional CEST-era samples ---
|
||||
<![LOG[ExecutorLog AgentExecutor gets invoked]LOG]!><time="14:13:36.8420339" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Creating command line parser, name delimiter is - and value separator is .]LOG]!><time="14:13:36.8460498" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Getting Ordered Parameters]LOG]!><time="14:13:36.8460498" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Parsing Ordered Parameters.]LOG]!><time="14:13:36.8484892" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Adding argument powershell with value C:\Program Files (x86)\Microsoft Intune Management Extension\Policies\Scripts\00000000-0000-0000-0000-000000000000_policy-anon-0001-0000-0000-0000-000000000000.ps1 to the named argument list.]LOG]!><time="14:13:36.8484892" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[Powershell option gets invoked]LOG]!><time="14:13:36.8525204" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[C:\Program Files (x86)\Microsoft Intune Management Extension\Policies\Scripts\00000000-0000-0000-0000-000000000000_policy-anon-0001-0000-0000-0000-000000000000.ps1]LOG]!><time="14:13:36.8545313" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
<![LOG[C:\Program Files (x86)\Microsoft Intune Management Extension\Policies\Results\00000000-0000-0000-0000-000000000000_policy-anon-0001-0000-0000-0000-000000000000.output]LOG]!><time="14:13:36.8545313" date="8-20-2026" component="AgentExecutor" context="" type="1" thread="1" file="">
|
||||
Reference in New Issue
Block a user