feat(office): filesystem-watcher completion + drop noisy progress event

Rev 4 of the Office detector, from field session 7da7dead (agent 2.0.980):
early DO-CDN start worked, but there was no completion and the progress
events were useless.

Completion (was never firing):
- The DO-"ended" heuristic is structurally unreliable for Office — many
  parallel CDN jobs churn, finished ones drop out of the list, so the
  aggregate never reaches 100% and the job count never cleanly hits zero.
  onOfficeDownloadEnded never fired, so the completion/binary check never ran.
- Replace it with an OfficeBinaryWatcher: once the InstallationPath is known
  from the registry, a FileSystemWatcher on {InstallationPath} fires when any
  core Office binary (WINWORD/EXCEL/POWERPNT/OUTLOOK.EXE — any-of, products can
  be excluded) appears on disk -> TryFinalizeCompletion emits completed. Initial
  on-arm scan + bounded retry-arm cover armed-late / dir-not-yet-present. The
  whole DO-ended close machinery (host close/settle/probe timer,
  collector onOfficeDownloadEnded) is removed.

Progress (was noise):
- Connected-Cache delivery is near-instant and the multi-job aggregate never
  yields a clean 0..100 bar (7da7dead showed one/five identical 62% events).
- Drop office_install_progress emission entirely. Only started / completed /
  failed now. The valuable Delivery-Optimization data ships ONCE as a doSummary
  on the completed event: total bytes + Cache-Server / peer / pure-CDN split
  (CDN = BytesFromHttp - BytesFromCacheServer on MCC networks) + download mode,
  alongside durationSeconds and versionReached.

Log spam:
- The registry watcher fires on every ClickToRun value churn; 7da7dead logged
  ~4000 "Office install expected" INFO lines. Now OfficeExpected is only raised
  until the lifecycle starts, and NotifyOfficeExpected logs at Debug and only
  when the probe window re-opens from closed.

V2-only. ConfigVersion unchanged (29). The office_install_progress constant +
MCP/web catalog entries are left in place (now never emitted; optional prune).
V2.Core 1263/1263 green; V2 runtime builds. The FileSystemWatcher itself is
OS-bound and not unit-tested (consistent with the process/registry watchers).

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This commit is contained in:
Oliver Kieselbach
2026-06-08 22:34:59 +02:00
parent 735b27db52
commit e922ab7bf0
6 changed files with 371 additions and 298 deletions
@@ -190,15 +190,19 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Office
Assert.Single(rig.OfficeEvents());
}
// ---------------------------------------------------------------- progress (no heartbeat)
// ---------------------------------------------------------------- no progress events
[Fact]
public void Registry_change_without_real_delta_emits_no_progress_heartbeat()
public void Do_samples_after_start_emit_no_progress_events()
{
// Progress was removed: a per-poll download-% is noise for Office (Connected-Cache delivery
// is near-instant and the multi-job aggregate never yields a clean 0→100 bar — field session
// 7da7dead). DO samples only update the data summarized once on completed.
using var rig = new Rig(ActiveStreaming());
rig.Sut.OnWorkerStarted(); // started
rig.Sut.OnRegistryChanged(); // identical snapshot — must NOT emit progress
rig.Sut.OnOfficeDoSample(new OfficeDoSample { JobCount = 2, FileSize = 1000, TotalBytesDownloaded = 250 });
rig.Sut.OnOfficeDoSample(new OfficeDoSample { JobCount = 3, FileSize = 1000, TotalBytesDownloaded = 620 });
rig.Sut.OnRegistryChanged();
var events = rig.OfficeEvents();
@@ -206,100 +210,27 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Office
Assert.Equal(Constants.EventTypes.OfficeInstallStarted, EventType(events[0]));
}
[Fact]
public void Scenario_value_churn_alone_emits_no_progress_heartbeat()
{
// Field session 58d52632: during an active C2R operation the worker rewrites the
// undocumented Scenario values many times/second and the subtree RegNotify watcher fires on
// each write. Those raw values are NOT a surfaced progress dimension, so churn alone must NOT
// emit progress (it previously produced bursts of identical, frozen-% progress events).
var s1 = ActiveStreaming();
s1.ScenarioValues["INSTALL\\CurrentOperation"] = "Downloading";
using var rig = new Rig(s1);
rig.Sut.OnWorkerStarted(); // started
var s2 = ActiveStreaming();
s2.ScenarioValues["INSTALL\\CurrentOperation"] = "Applying"; // churn only — no version/DO movement
rig.Current = s2;
rig.Sut.OnRegistryChanged();
rig.Sut.OnRegistryChanged();
var events = rig.OfficeEvents();
Assert.Single(events);
Assert.Equal(Constants.EventTypes.OfficeInstallStarted, EventType(events[0]));
}
[Fact]
public void Version_change_emits_one_progress_event()
{
using var rig = new Rig(ActiveStreaming());
rig.Sut.OnWorkerStarted(); // started
var s2 = ActiveStreaming();
s2.VersionToReport = "16.0.20026.20140"; // real forward movement
rig.Current = s2;
rig.Sut.OnRegistryChanged(); // progress
var events = rig.OfficeEvents();
Assert.Equal(2, events.Count);
Assert.Equal(Constants.EventTypes.OfficeInstallProgress, EventType(events[1]));
}
// ---------------------------------------------------------------- DO folding
[Fact]
public void Office_do_sample_folds_download_percent_into_progress()
{
using var rig = new Rig(ActiveStreaming());
rig.Sut.OnWorkerStarted(); // started
rig.Sut.OnOfficeDoSample(new OfficeDoSample
{
JobCount = 2,
FileSize = 1000,
TotalBytesDownloaded = 250,
BytesFromPeers = 100,
BytesFromHttp = 150,
PercentPeerCaching = 40,
DownloadMode = 1,
});
var events = rig.OfficeEvents();
Assert.Equal(2, events.Count);
var progress = events[1];
Assert.Equal(Constants.EventTypes.OfficeInstallProgress, EventType(progress));
var data = Data(progress);
Assert.Equal(250L, data["doTotalBytesDownloaded"]);
Assert.Equal(25, data["downloadPercent"]);
Assert.Equal(2, data["doJobCount"]);
}
[Fact]
public void Repeated_identical_do_sample_emits_no_progress()
{
using var rig = new Rig(ActiveStreaming());
rig.Sut.OnWorkerStarted();
var sample = new OfficeDoSample { JobCount = 1, FileSize = 1000, TotalBytesDownloaded = 250 };
rig.Sut.OnOfficeDoSample(sample); // progress (bytes advanced)
rig.Sut.OnOfficeDoSample(new OfficeDoSample { JobCount = 1, FileSize = 1000, TotalBytesDownloaded = 250 }); // same bytes — no progress
var events = rig.OfficeEvents();
Assert.Equal(2, events.Count); // started + one progress only
}
// ---------------------------------------------------------------- completion (filesystem proof)
[Fact]
public void TryFinalizeCompletion_with_core_binaries_emits_completed()
public void TryFinalizeCompletion_with_core_binaries_emits_completed_with_do_summary()
{
using var rig = new Rig(ActiveStreaming());
rig.Sut.OnWorkerStarted(); // started
// A DO sample during the download — its breakdown is summarized once on completed.
// MCC network: BytesFromHttp includes the cache-server bytes → pure CDN = 1000-800 = 200.
rig.Sut.OnOfficeDoSample(new OfficeDoSample
{
JobCount = 3,
FileSize = 1200,
TotalBytesDownloaded = 1000,
BytesFromCacheServer = 800,
BytesFromHttp = 1000,
BytesFromPeers = 0,
DownloadMode = 1,
});
// Download ended + worker gone; the integrate phase has laid down the binaries on disk.
rig.Current = CompletedIdle(); // InstallationPath-bearing snapshot, no error
rig.Sut.CoreBinariesProbe = _ => true; // a core Office binary exists under root\*
@@ -314,6 +245,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Office
Assert.Equal("Info", Severity(completed));
Assert.Equal(true, Data(completed)["coreBinariesPresent"]);
Assert.Equal("16.0.17628.20144", Data(completed)["versionReached"]);
var summary = Assert.IsType<Dictionary<string, object>>(Data(completed)["doSummary"]);
Assert.Equal(1000L, summary["totalBytesDownloaded"]);
Assert.Equal(800L, summary["bytesFromCacheServer"]);
Assert.Equal(200L, summary["bytesFromCdn"]); // 1000 http - 800 cache
Assert.Equal(0L, summary["bytesFromPeers"]);
Assert.Equal(80, summary["percentFromCacheServer"]);
Assert.Equal(20, summary["percentFromCdn"]);
}
[Fact]
@@ -420,6 +359,32 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Office
Assert.Equal(expected, OfficeInstallDetector.IsNonZeroNumericCode(value!));
}
// ---------------------------------------------------------------- core-binary on-disk probe
[Fact]
public void CoreBinariesPresentOnDisk_true_for_any_core_binary_under_enumerated_version_folder()
{
using var tmp = new TempDirectory();
// {InstallationPath}\root\Office16\EXCEL.EXE — version folder enumerated, not hardcoded.
var versionDir = System.IO.Path.Combine(tmp.Path, "root", "Office16");
System.IO.Directory.CreateDirectory(versionDir);
System.IO.File.WriteAllText(System.IO.Path.Combine(versionDir, "EXCEL.EXE"), "stub");
Assert.True(OfficeInstallDetector.CoreBinariesPresentOnDisk(tmp.Path, NewLogger(tmp.Path)));
}
[Fact]
public void CoreBinariesPresentOnDisk_false_when_absent_or_path_invalid()
{
using var tmp = new TempDirectory();
System.IO.Directory.CreateDirectory(System.IO.Path.Combine(tmp.Path, "root", "Office16")); // no binaries
var logger = NewLogger(tmp.Path);
Assert.False(OfficeInstallDetector.CoreBinariesPresentOnDisk(tmp.Path, logger));
Assert.False(OfficeInstallDetector.CoreBinariesPresentOnDisk(null, logger));
Assert.False(OfficeInstallDetector.CoreBinariesPresentOnDisk(System.IO.Path.Combine(tmp.Path, "does-not-exist"), logger));
}
// ---------------------------------------------------------------- ctor
[Fact]
@@ -0,0 +1,172 @@
#nullable enable
using System;
using System.Collections.Generic;
using System.IO;
using System.Threading;
using AutopilotMonitor.Agent.V2.Core.Logging;
namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office
{
/// <summary>
/// Event-driven completion proof for an Office C2R install: watches the C2R install tree for any of
/// the core Office app binaries (<c>WINWORD.EXE</c> / <c>EXCEL.EXE</c> / <c>POWERPNT.EXE</c> /
/// <c>OUTLOOK.EXE</c>) appearing on disk. C2R lays these down in the integrate phase — their
/// presence is the one reliable "Office is installed" signal (the DO job aggregate is unreliable for
/// completion: multi-job churn never reaches an aggregate 100% and Connected-Cache delivery makes the
/// stream near-instant — field session 7da7dead).
/// <para>
/// <b>Any-of</b> by design: a deployment can exclude products (e.g. Word only, no Outlook), so the
/// first of the four binaries to appear is enough. The watcher fires <see cref="BinaryAppeared"/>
/// exactly once. It is armed only once the <c>InstallationPath</c> is known from the registry (so we
/// watch the correct tree). On a clean enrollment the binaries are absent at arm time and the
/// FileSystemWatcher catches their creation during integrate; an initial scan also completes
/// immediately if they are already present (armed late / update-over-existing).
/// </para>
/// Fail-soft: any failure is logged and the watcher stays quiet (no false completion).
/// </summary>
public sealed class OfficeBinaryWatcher : IDisposable
{
// C2R lays the binaries down under {InstallationPath}\root\OfficeNN\ — the version folder is
// enumerated (IncludeSubdirectories), never hardcoded.
private const int ArmRetryDelaySeconds = 5;
private const int MaxArmRetries = 24; // ~2 min — the InstallationPath dir is normally already present
private readonly string _installationPath;
private readonly HashSet<string> _binaries; // upper-cased leaf names
private readonly AgentLogger _logger;
private readonly object _lock = new object();
private FileSystemWatcher? _fsw;
private Timer? _armRetryTimer;
private int _armAttempts;
private int _fired; // 0/1 — BinaryAppeared raised at most once
private bool _disposed;
/// <summary>Raised once when a core Office binary is present on disk (install complete).</summary>
public event EventHandler? BinaryAppeared;
public OfficeBinaryWatcher(string installationPath, IEnumerable<string> binaries, AgentLogger logger)
{
_installationPath = installationPath ?? throw new ArgumentNullException(nameof(installationPath));
_logger = logger ?? throw new ArgumentNullException(nameof(logger));
_binaries = new HashSet<string>(StringComparer.OrdinalIgnoreCase);
foreach (var b in binaries ?? Array.Empty<string>()) _binaries.Add(b);
}
public void Start()
{
lock (_lock)
{
if (_disposed) return;
TryArm();
}
}
// Caller holds _lock.
private void TryArm()
{
if (_disposed || _fired != 0 || _fsw != null) return;
// Initial scan — the binaries may already be present (armed late / update over existing).
if (CoreBinariesPresent())
{
RaiseOnce();
return;
}
if (!Directory.Exists(_installationPath))
{
// The install root is not there yet (very early). Retry a bounded number of times; the
// registry InstallationPath value normally precedes the directory only briefly.
if (_armAttempts++ < MaxArmRetries)
{
_armRetryTimer?.Dispose();
_armRetryTimer = new Timer(OnArmRetry, null, TimeSpan.FromSeconds(ArmRetryDelaySeconds), Timeout.InfiniteTimeSpan);
}
else
{
_logger.Debug($"[OfficeBinaryWatcher] install path '{_installationPath}' never appeared — giving up (no completion proof)");
}
return;
}
try
{
_fsw = new FileSystemWatcher(_installationPath)
{
IncludeSubdirectories = true,
Filter = "*.exe",
NotifyFilter = NotifyFilters.FileName | NotifyFilters.LastWrite | NotifyFilters.Size,
};
_fsw.Created += OnFileEvent;
_fsw.Changed += OnFileEvent;
_fsw.Renamed += OnFileRenamed;
_fsw.EnableRaisingEvents = true;
_logger.Info($"[OfficeBinaryWatcher] watching '{_installationPath}' for core Office binaries");
// Race: a binary may have appeared between the scan above and arming — re-scan once.
if (CoreBinariesPresent()) RaiseOnce();
}
catch (Exception ex)
{
_logger.Warning($"[OfficeBinaryWatcher] could not watch '{_installationPath}': {ex.Message}");
}
}
private void OnArmRetry(object? state)
{
lock (_lock) { TryArm(); }
}
private void OnFileEvent(object sender, FileSystemEventArgs e) => CheckCandidate(e.Name);
private void OnFileRenamed(object sender, RenamedEventArgs e) => CheckCandidate(e.Name);
private void CheckCandidate(string? relativeName)
{
try
{
if (string.IsNullOrEmpty(relativeName)) return;
var leaf = Path.GetFileName(relativeName);
if (!string.IsNullOrEmpty(leaf) && _binaries.Contains(leaf))
{
_logger.Info($"[OfficeBinaryWatcher] core Office binary appeared: {leaf}");
RaiseOnce();
}
}
catch (Exception ex)
{
_logger.Debug($"[OfficeBinaryWatcher] candidate check error: {ex.Message}");
}
}
private bool CoreBinariesPresent()
=> OfficeInstallDetector.CoreBinariesPresentOnDisk(_installationPath, _logger);
private void RaiseOnce()
{
if (Interlocked.Exchange(ref _fired, 1) != 0) return;
try { BinaryAppeared?.Invoke(this, EventArgs.Empty); }
catch (Exception ex) { _logger.Warning($"[OfficeBinaryWatcher] BinaryAppeared handler threw: {ex.Message}"); }
}
public void Dispose()
{
lock (_lock)
{
if (_disposed) return;
_disposed = true;
_armRetryTimer?.Dispose();
_armRetryTimer = null;
if (_fsw != null)
{
try { _fsw.EnableRaisingEvents = false; } catch { }
try { _fsw.Created -= OnFileEvent; } catch { }
try { _fsw.Changed -= OnFileEvent; } catch { }
try { _fsw.Renamed -= OnFileRenamed; } catch { }
try { _fsw.Dispose(); } catch { }
_fsw = null;
}
}
}
}
}
@@ -62,14 +62,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office
// Core Office app binaries used as the on-disk completion proof. ANY of these present under
// {InstallationPath}\root\* means the C2R lay-down finished — "any of", because a deployment can
// exclude products (e.g. no Outlook), so requiring all would miss legitimate completions.
private static readonly string[] CoreBinaries = { "WINWORD.EXE", "EXCEL.EXE", "POWERPNT.EXE", "OUTLOOK.EXE" };
internal static readonly string[] CoreBinaries = { "WINWORD.EXE", "EXCEL.EXE", "POWERPNT.EXE", "OUTLOOK.EXE" };
private readonly string _sessionId;
private readonly string _tenantId;
private readonly InformationalEventPost _post;
private readonly AgentLogger _logger;
private readonly IClock _clock;
private readonly Action<string?>? _onInstallationPathObserved;
private readonly object _lock = new object();
private bool _pathObservedRaised;
// Test seam: when set, used instead of reading the live registry/process state. Production
// never assigns it. Surfaced to the test assembly via InternalsVisibleTo.
@@ -86,22 +88,36 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office
private DetectorState _state = DetectorState.Idle;
private DateTime? _startedAtUtc;
private string? _lastProgressSignature;
private string? _startedTrigger;
private OfficeDoSample? _lastDo;
private OfficeDoSample? _peakDo; // highest-bytes sample seen — basis for the completed doSummary
public OfficeInstallDetector(
string sessionId,
string tenantId,
InformationalEventPost post,
AgentLogger logger,
IClock clock)
IClock clock,
Action<string?>? onInstallationPathObserved = null)
{
_sessionId = sessionId ?? throw new ArgumentNullException(nameof(sessionId));
_tenantId = tenantId ?? throw new ArgumentNullException(nameof(tenantId));
_post = post ?? throw new ArgumentNullException(nameof(post));
_logger = logger ?? throw new ArgumentNullException(nameof(logger));
_clock = clock ?? throw new ArgumentNullException(nameof(clock));
_onInstallationPathObserved = onInstallationPathObserved;
}
/// <summary>
/// Surfaces the C2R <c>InstallationPath</c> to the host (once) as soon as it is known, so the
/// host can arm the <see cref="OfficeBinaryWatcher"/> on the correct tree. Caller holds the lock.
/// </summary>
private void ObserveInstallationPath(OfficeC2RSnapshot snap)
{
if (_pathObservedRaised || string.IsNullOrEmpty(snap.InstallationPath)) return;
_pathObservedRaised = true;
try { _onInstallationPathObserved?.Invoke(snap.InstallationPath); }
catch (Exception ex) { _logger.Warning($"[{SourceName}] onInstallationPathObserved threw: {ex.Message}"); }
}
// -----------------------------------------------------------------------
@@ -149,8 +165,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office
/// <summary>
/// Latest aggregated Office DO stats. The first sample carrying jobs is the EARLIEST and most
/// reliable start trigger (the Office-CDN download is visible long before the worker process);
/// subsequent samples fold a real download-% into progress.
/// reliable start trigger (the Office-CDN download is visible long before the worker process).
/// Later samples do NOT emit progress events — a per-sample download-% is noise for Office
/// (Connected-Cache delivery is near-instant and the multi-job aggregate never yields a clean
/// 0→100 bar — field session 7da7dead). They only update the DO data that is summarized once on
/// the completed event (bytes + Cache-Server / Peer / CDN split + duration).
/// </summary>
public void OnOfficeDoSample(OfficeDoSample sample)
{
@@ -158,6 +177,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office
lock (_lock)
{
_lastDo = sample;
if (_peakDo == null || sample.TotalBytesDownloaded > _peakDo.TotalBytesDownloaded)
_peakDo = sample;
if (_state == DetectorState.Terminal) return;
if (_state == DetectorState.Idle)
@@ -166,12 +187,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office
var snapStart = ReadSnapshotSafe();
if (snapStart == null) return;
BeginIfIdle("do", snapStart);
return;
}
var snap = ReadSnapshotSafe();
if (snap == null) return;
EvaluateActive(snap);
// Active: no progress event — the sample only updates the DO summary data.
}
}
@@ -237,25 +254,20 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office
_state = DetectorState.Active;
_startedAtUtc = _clock.UtcNow;
_startedTrigger = trigger;
_lastProgressSignature = BuildProgressSignature(snap, _lastDo);
ObserveInstallationPath(snap);
EmitLifecycle(Constants.EventTypes.OfficeInstallStarted, snap, EventSeverity.Info, PhaseOf(snap), isTerminal: false);
}
private void EvaluateActive(OfficeC2RSnapshot snap)
{
// An explicit numeric error code is the one in-flight terminal we trust.
if (!string.IsNullOrEmpty(snap.ErrorCode))
{
FinalizeFailed(snap);
return;
}
// Surface a late-arriving InstallationPath (e.g. when started via a DO job before the
// Configuration key was populated) so the host can arm the binary watcher.
ObserveInstallationPath(snap);
var sig = BuildProgressSignature(snap, _lastDo);
if (!string.Equals(sig, _lastProgressSignature, StringComparison.Ordinal))
{
_lastProgressSignature = sig;
EmitLifecycle(Constants.EventTypes.OfficeInstallProgress, snap, EventSeverity.Info, PhaseOf(snap), isTerminal: false);
}
// An explicit numeric error code is the one in-flight terminal we trust. There is no progress
// event — started + completed/failed only (a per-poll download-% is noise for Office).
if (!string.IsNullOrEmpty(snap.ErrorCode))
FinalizeFailed(snap);
}
private void FinalizeFailed(OfficeC2RSnapshot snap)
@@ -313,47 +325,22 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office
// single "Installing"; the terminal completion uses "Completed".
private static string PhaseOf(OfficeC2RSnapshot snap) => "Installing";
/// <summary>
/// Stable signature of the <b>observable</b> progress dimensions only — the values we actually
/// surface in the payload and that represent real forward movement: the reported version, the
/// active scenario name, and the DO download (bytes / percent). A change in any of these emits
/// one progress event; an unchanged signature emits nothing — keeping the detector heartbeat-free.
/// <para>
/// The raw <c>Scenario</c> value dict is deliberately EXCLUDED. During an active C2R operation
/// the worker rewrites those undocumented values many times per second, and the RegNotify watcher
/// (subtree) fires on each write. Folding that churn into the signature produced bursts of
/// progress events within the same second that all carried an identical, frozen download-% (the
/// 3s DO sample had not advanced) and no surfaced cause — pure noise (field session 58d52632).
/// Progress is therefore tied to observable movement, which naturally paces it to the DO cadence;
/// the registry push still drives error-code discovery (and, later, TasksState phase detection).
/// </para>
/// </summary>
private static string BuildProgressSignature(OfficeC2RSnapshot snap, OfficeDoSample? doSample)
{
var parts = new List<string>
{
"version=" + (snap.VersionToReport ?? string.Empty),
"scenario=" + (snap.ActiveScenarioName ?? string.Empty),
};
if (doSample != null)
{
parts.Add("doBytes=" + doSample.TotalBytesDownloaded);
parts.Add("doPct=" + doSample.DownloadPercent);
}
return string.Join("|", parts);
}
// -----------------------------------------------------------------------
// Payload
// -----------------------------------------------------------------------
private void EmitLifecycle(string eventType, OfficeC2RSnapshot snap, EventSeverity severity, string phase, bool isTerminal, bool coreBinariesPresent = false)
{
var data = BuildPayload(snap, phase, isTerminal, _lastDo);
var data = BuildPayload(snap, phase, isTerminal);
if (!string.IsNullOrEmpty(_startedTrigger)) data["startedTrigger"] = _startedTrigger!;
if (isTerminal && eventType == Constants.EventTypes.OfficeInstallCompleted)
{
data["coreBinariesPresent"] = coreBinariesPresent;
var message = BuildMessage(eventType, snap, phase, _lastDo);
// One-time Delivery-Optimization summary (how Office was delivered) — far more useful than
// a streaming download-% (which is noise under Connected-Cache + multi-job churn).
if (_peakDo != null) data["doSummary"] = BuildDoSummary(_peakDo);
}
var message = BuildMessage(eventType, snap);
_post.Emit(new EnrollmentEvent
{
@@ -369,7 +356,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office
});
}
internal Dictionary<string, object> BuildPayload(OfficeC2RSnapshot snap, string phase, bool isTerminal, OfficeDoSample? doSample)
internal Dictionary<string, object> BuildPayload(OfficeC2RSnapshot snap, string phase, bool isTerminal)
{
var elapsedSeconds = _startedAtUtc.HasValue
? Math.Max(0, (int)(_clock.UtcNow - _startedAtUtc.Value).TotalSeconds)
@@ -391,21 +378,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office
{ "scanErrors", (snap.Errors ?? new List<string>()).ToList() },
};
if (doSample != null)
{
// Delivery Optimization download telemetry for Office's CDN content (folded in to
// avoid creating a phantom app in the backend AppInstallSummary — Office is not an IME app).
data["doJobCount"] = doSample.JobCount;
data["doFileSize"] = doSample.FileSize;
data["doTotalBytesDownloaded"] = doSample.TotalBytesDownloaded;
data["doBytesFromPeers"] = doSample.BytesFromPeers;
data["doBytesFromHttp"] = doSample.BytesFromHttp;
data["doBytesFromCacheServer"] = doSample.BytesFromCacheServer;
data["doPercentPeerCaching"] = doSample.PercentPeerCaching;
data["doDownloadMode"] = doSample.DownloadMode;
if (doSample.DownloadPercent.HasValue)
data["downloadPercent"] = doSample.DownloadPercent.Value;
}
// No per-event download-% (it is noise for Office). The Delivery-Optimization breakdown is
// attached once to the completed event as doSummary (see EmitLifecycle / BuildDoSummary).
if (isTerminal)
data["durationSeconds"] = elapsedSeconds;
@@ -415,16 +389,40 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office
return data;
}
private static string BuildMessage(string eventType, OfficeC2RSnapshot snap, string phase, OfficeDoSample? doSample)
/// <summary>
/// One-time Delivery-Optimization delivery breakdown for the completed event, built from the
/// highest-bytes sample seen. Splits the bytes into Connected-Cache-Server / peer / pure-CDN: on
/// MCC-enabled networks <c>BytesFromHttp</c> includes the cache-server bytes, so pure CDN is
/// <c>BytesFromHttp - BytesFromCacheServer</c> (see project DO-telemetry notes).
/// </summary>
private static Dictionary<string, object> BuildDoSummary(OfficeDoSample d)
{
long total = d.TotalBytesDownloaded;
long cacheServer = d.BytesFromCacheServer;
long peers = d.BytesFromPeers;
long cdn = Math.Max(0, d.BytesFromHttp - d.BytesFromCacheServer);
int Pct(long part) => total > 0 ? (int)Math.Min(100, (part * 100) / total) : 0;
return new Dictionary<string, object>
{
{ "totalBytesDownloaded", total },
{ "aggregateFileSize", d.FileSize },
{ "jobCount", d.JobCount },
{ "bytesFromCacheServer", cacheServer },
{ "bytesFromPeers", peers },
{ "bytesFromCdn", cdn },
{ "percentFromCacheServer", Pct(cacheServer) },
{ "percentFromPeers", Pct(peers) },
{ "percentFromCdn", Pct(cdn) },
{ "downloadMode", d.DownloadMode },
};
}
private static string BuildMessage(string eventType, OfficeC2RSnapshot snap)
{
var product = snap.Products != null && snap.Products.Count > 0 ? string.Join(",", snap.Products) : AppName;
var pct = doSample?.DownloadPercent;
if (eventType == Constants.EventTypes.OfficeInstallStarted)
return $"{SourceName}: {product} install detected (phase={phase})";
if (eventType == Constants.EventTypes.OfficeInstallProgress)
return pct.HasValue
? $"{SourceName}: {product} install progress (phase={phase}, download {pct.Value}%)"
: $"{SourceName}: {product} install progress (phase={phase})";
return $"{SourceName}: {product} install detected";
if (eventType == Constants.EventTypes.OfficeInstallCompleted)
return $"{SourceName}: {product} install completed{(string.IsNullOrEmpty(snap.VersionToReport) ? string.Empty : $" (v{snap.VersionToReport})")}";
return $"{SourceName}: {product} install failed{(string.IsNullOrEmpty(snap.ErrorCode) ? string.Empty : $" (code {snap.ErrorCode})")}";
@@ -44,15 +44,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
// Office is not an IME app, so we deliberately do NOT emit download_progress/do_telemetry for it
// (that would create a phantom app in the backend AppInstallSummary).
private readonly Action<OfficeDoSample> _onOfficeDoSample;
private readonly Action _onOfficeDownloadEnded;
// Keep-awake sources for an Office install (any keeps us polling): the worker process is up
// (_officeActive), an Office-CDN job was seen in the last poll (_officeJobsSeenLastPoll), or the
// registry hinted an install is imminent (_officeExpectedPolls — a bounded probe window so a
// Scenario\INSTALL that never produces a download does not keep us awake forever).
// Completion is NOT derived from the DO aggregate (unreliable: multi-job churn + Connected-Cache
// — see OfficeBinaryWatcher); we only surface started + progress here.
private volatile bool _officeActive;
private bool _officeJobsSeenLastPoll;
private bool _officeEndedNotified;
private int _officeExpectedPolls;
// Bounded probe budget after a registry "Office expected" hint, in polls (~ this × interval).
@@ -82,15 +82,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
Func<AppPackageStateList> getPackageStates,
Action<AppPackageState> onDoTelemetryReceived,
string logDirectory,
Action<OfficeDoSample> onOfficeDoSample = null,
Action onOfficeDownloadEnded = null)
Action<OfficeDoSample> onOfficeDoSample = null)
: base(sessionId, tenantId, post, logger, intervalSeconds)
{
_getPackageStates = getPackageStates ?? throw new ArgumentNullException(nameof(getPackageStates));
_onDoTelemetryReceived = onDoTelemetryReceived;
_logFilePath = Path.Combine(logDirectory, LogFileName);
_onOfficeDoSample = onOfficeDoSample;
_onOfficeDownloadEnded = onOfficeDownloadEnded;
}
/// <summary>Start dormant — timer does not fire until WakeUp() is called.</summary>
@@ -142,8 +140,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
/// </summary>
public void NotifyOfficeExpected()
{
// Re-open the bounded probe window. The registry watcher can fire many times per second on
// ClickToRun value churn, so only log (at Debug) when the window actually (re)opens from
// closed — never a per-fire INFO line (field session 7da7dead logged ~4000 of them).
bool windowWasClosed = _officeExpectedPolls <= 0;
_officeExpectedPolls = OfficeExpectedProbePolls;
Logger.Info("[DeliveryOptimizationCollector] Office install expected (registry Scenario\\INSTALL) — probing DO for Office CDN jobs");
if (windowWasClosed)
Logger.Debug("[DeliveryOptimizationCollector] Office install expected (registry Scenario\\INSTALL) — probing DO for Office CDN jobs");
WakeUp();
}
@@ -468,10 +471,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
}
// Hand aggregated Office DO stats to the OfficeInstallDetector (folded into office_install_*).
// Unconditional now (Rev 3): the first sample with jobs is the detector's start trigger; a
// subsequent disappearance / 100% is the download-ended signal that arms the host's close.
// Unconditional (Rev 3): the first sample with jobs is the detector's start trigger; later
// samples fold a real download-% into progress. Completion is handled separately by the
// OfficeBinaryWatcher (the DO aggregate is unreliable for it), so we do NOT signal "ended".
var officeJobsThisPoll = officeJobCount > 0;
var officeComplete = officeFileSize > 0 && officeTotalBytes >= officeFileSize;
if (officeJobsThisPoll && _onOfficeDoSample != null)
{
@@ -496,17 +499,6 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
}
}
// Download-ended signal (once): Office-CDN jobs were present and have now disappeared, or a
// job reached 100%. Arms the OfficeInstallDetectorHost's close/completion-probe schedule.
var officeDownloadEnded = !_officeEndedNotified &&
((officeJobsThisPoll && officeComplete) || (!officeJobsThisPoll && _officeJobsSeenLastPoll));
if (officeDownloadEnded)
{
_officeEndedNotified = true;
try { _onOfficeDownloadEnded?.Invoke(); }
catch (Exception ex) { Logger.Warning($"[DeliveryOptimizationCollector] onOfficeDownloadEnded threw: {ex.Message}"); }
}
_officeJobsSeenLastPoll = officeJobsThisPoll;
// Decrement the bounded registry-hint probe window only while no Office job is being seen.
if (!officeJobsThisPoll && _officeExpectedPolls > 0) _officeExpectedPolls--;
@@ -52,8 +52,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
catch (Exception ex) { logger.Warning($"DeliveryOptimizationHost: OnDoTelemetryReceived invocation threw: {ex.Message}"); }
},
logDirectory: Environment.ExpandEnvironmentVariables(Constants.LogDirectory),
onOfficeDoSample: officeHost != null ? officeHost.SubmitDoSample : (Action<OfficeDoSample>?)null,
onOfficeDownloadEnded: officeHost != null ? officeHost.NotifyOfficeDownloadEnded : (Action?)null);
onOfficeDoSample: officeHost != null ? officeHost.SubmitDoSample : (Action<OfficeDoSample>?)null);
}
public void Start()
@@ -8,61 +8,53 @@ using AutopilotMonitor.DecisionCore.Engine;
namespace AutopilotMonitor.Agent.V2.Core.Orchestration
{
/// <summary>
/// Lifecycle host for the event-driven <see cref="OfficeInstallDetector"/> (Rev 3). Owns the OS
/// watchers and orchestrates the pure detector core — no idle polling. The anchor is no longer the
/// late, transient <c>OfficeC2RClient.exe</c> worker: the Office-CDN Delivery-Optimization job
/// (surfaced by the DeliveryOptimizationCollector) and the <c>Scenario\INSTALL</c> registry key are
/// caught much earlier, so <c>office_install_started</c> pairs to the real download start.
/// Lifecycle host for the event-driven <see cref="OfficeInstallDetector"/> (Rev 4). Owns the OS
/// watchers and orchestrates the pure detector core — no idle polling. The anchor is the Office-CDN
/// Delivery-Optimization job and the <c>Scenario\INSTALL</c> registry key (caught far earlier than
/// the late, transient <c>OfficeC2RClient.exe</c> worker), so <c>office_install_started</c> pairs to
/// the real download start:
/// <list type="bullet">
/// <item><see cref="RegistryChangeWatcher"/> armed at <see cref="Start"/> (bootstrap fallback
/// handles the not-yet-created ClickToRun key) → <c>OnRegistryChanged</c> (starts on
/// <c>Scenario\INSTALL</c>; progress / error otherwise) AND raises <see cref="OfficeExpected"/>
/// so the DO collector wakes to look for the Office-CDN job.</item>
/// <item><see cref="RegistryChangeWatcher"/> armed at <see cref="Start"/> → <c>OnRegistryChanged</c>
/// (starts on <c>Scenario\INSTALL</c>; progress / error otherwise) AND raises
/// <see cref="OfficeExpected"/> (until the lifecycle starts) so the DO collector wakes to look
/// for the Office-CDN job.</item>
/// <item><see cref="OfficeProcessWatcher"/> Started → <c>OnWorkerStarted</c> (an idempotent start
/// trigger; cancels any pending close — the install is clearly still active). Stopped → arms the
/// close schedule.</item>
/// trigger). The Stopped signal is consumed by the DeliveryOptimizationHost (DO keep-awake), not
/// here.</item>
/// <item><see cref="SubmitDoSample"/> (from the DO collector) → <c>OnOfficeDoSample</c> — the first
/// sample with jobs starts the lifecycle; later samples fold a real download-% into progress.</item>
/// <item><see cref="NotifyOfficeDownloadEnded"/> (from the DO collector) → arms the close schedule.</item>
/// </list>
/// <para>
/// <b>Close + completion probe</b>: once the download has ended AND no worker is running, a settle
/// timer fires <c>TryFinalizeCompletion</c>. Completion is proven by the core Office binaries on disk
/// (C2R lays them down in the integrate phase, which can lag the download end), so a
/// <see cref="OfficeInstallDetector.CompletionOutcome.NotYet"/> result is retried on a bounded probe
/// schedule before the lifecycle is abandoned silently (never a false completed/failed).
/// <b>Completion</b> is driven by an <see cref="OfficeBinaryWatcher"/> — NOT the DO job aggregate,
/// which is unreliable for completion (multi-job churn never reaches an aggregate 100% and
/// Connected-Cache delivery makes the stream near-instant — field session 7da7dead). Once the
/// detector surfaces the <c>InstallationPath</c> (from the registry), the binary watcher fires when a
/// core Office binary appears on disk → <c>TryFinalizeCompletion</c> emits <c>office_install_completed</c>.
/// An explicit error code → failed. No binary ever appears → the lifecycle simply stays open and is
/// abandoned silently on dispose (never a false completed/failed).
/// </para>
/// </summary>
internal sealed class OfficeInstallDetectorHost : ICollectorHost
{
private const string ClickToRunSubKey = @"SOFTWARE\Microsoft\Office\ClickToRun";
// Post-download completion probe schedule (the C2R integrate phase lays the binaries down after
// the stream ends). settleSeconds debounces the first attempt; then up to MaxCompletionProbes
// re-checks at CompletionProbeIntervalSeconds — generous enough for the lay-down, bounded so we
// never probe forever.
private const int CompletionProbeIntervalSeconds = 15;
private const int MaxCompletionProbes = 8;
public string Name => OfficeInstallDetector.SourceName;
private readonly OfficeInstallDetector _detector;
private readonly OfficeProcessWatcher _processWatcher;
private readonly AgentLogger _logger;
private readonly int _settleSeconds;
private readonly object _lock = new object();
private RegistryChangeWatcher? _registryWatcher;
private Timer? _closeTimer;
private bool _downloadEnded;
private bool _workerActive;
private int _probeAttempts;
private OfficeBinaryWatcher? _binaryWatcher;
private bool _pathObserved; // InstallationPath known → stop poking the DO collector
private bool _lifecycleEnded;
private int _disposed;
/// <summary>
/// Raised when a ClickToRun registry change suggests an Office install is imminent/active. The
/// DeliveryOptimizationHost subscribes and wakes its collector to probe for the Office-CDN job.
/// Raised (until the lifecycle has started) when a ClickToRun registry change suggests an Office
/// install is imminent. The DeliveryOptimizationHost subscribes and wakes its collector to probe
/// for the Office-CDN job.
/// </summary>
public event EventHandler? OfficeExpected;
@@ -77,13 +69,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
if (ingress == null) throw new ArgumentNullException(nameof(ingress));
if (clock == null) throw new ArgumentNullException(nameof(clock));
_logger = logger ?? throw new ArgumentNullException(nameof(logger));
_settleSeconds = settleSeconds;
var post = new InformationalEventPost(ingress, clock);
_detector = new OfficeInstallDetector(sessionId, tenantId, post, logger, clock);
_detector = new OfficeInstallDetector(sessionId, tenantId, post, logger, clock,
onInstallationPathObserved: OnInstallationPathObserved);
_processWatcher = new OfficeProcessWatcher(logger, settleSeconds);
_processWatcher.Started += OnWorkerStarted;
_processWatcher.Stopped += OnWorkerStopped;
}
/// <summary>The shared Office worker start/stop signal — the DeliveryOptimizationHost subscribes.</summary>
@@ -93,12 +84,6 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
/// — the first sample with jobs also starts the lifecycle.</summary>
public void SubmitDoSample(OfficeDoSample sample) => _detector.OnOfficeDoSample(sample);
/// <summary>The Office-CDN download has ended (jobs gone / 100%) — arm the close schedule.</summary>
public void NotifyOfficeDownloadEnded()
{
lock (_lock) { _downloadEnded = true; MaybeArmClose(); }
}
public void Start()
{
// Arm the registry watcher up front (not at worker-start) so the early Scenario\INSTALL key
@@ -113,32 +98,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
_processWatcher.Start();
}
private void OnWorkerStarted(object? sender, EventArgs e)
{
lock (_lock)
{
_workerActive = true;
// A worker is running → the install is clearly still active; cancel any pending close.
CancelCloseTimer();
}
_detector.OnWorkerStarted();
}
private void OnWorkerStopped(object? sender, EventArgs e)
{
lock (_lock)
{
_workerActive = false;
MaybeArmClose();
}
}
private void OnWorkerStarted(object? sender, EventArgs e) => _detector.OnWorkerStarted();
private void OnRegistryChanged(object? sender, EventArgs e)
{
_detector.OnRegistryChanged();
// Wake the DO collector to look for the Office-CDN job (until the lifecycle has ended).
// Wake the DO collector to look for the Office-CDN job — only until the lifecycle has started
// (the InstallationPath being observed). After that the collector is already sampling and
// re-poking it on every registry value churn is pure log noise (field session 7da7dead).
bool raise;
lock (_lock) { raise = !_lifecycleEnded; }
lock (_lock) { raise = !_pathObserved && !_lifecycleEnded; }
if (raise)
{
try { OfficeExpected?.Invoke(this, EventArgs.Empty); }
@@ -147,53 +116,29 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
}
// -----------------------------------------------------------------------
// Close + bounded completion probe. All state mutated under _lock.
// Completion: arm the binary watcher once the install path is known.
// -----------------------------------------------------------------------
private void MaybeArmClose()
{
if (_lifecycleEnded || _closeTimer != null) return;
if (!_downloadEnded || _workerActive) return; // close only once download ended AND worker gone
_probeAttempts = 0;
_logger.Debug($"[OfficeInstallDetectorHost] download ended + worker gone — settling {_settleSeconds}s before completion check");
_closeTimer = new Timer(OnCloseTimer, null, TimeSpan.FromSeconds(Math.Max(0, _settleSeconds)), Timeout.InfiniteTimeSpan);
}
private void CancelCloseTimer()
{
_closeTimer?.Dispose();
_closeTimer = null;
}
private void OnCloseTimer(object? state)
private void OnInstallationPathObserved(string? installationPath)
{
lock (_lock)
{
_closeTimer?.Dispose();
_closeTimer = null;
if (_lifecycleEnded || _disposed != 0) return;
// A worker reappeared during settle → the install is still going; stand down.
if (_workerActive) return;
}
_pathObserved = true; // stop raising OfficeExpected (lifecycle has started)
if (_lifecycleEnded || _binaryWatcher != null || string.IsNullOrEmpty(installationPath)) return;
_binaryWatcher = new OfficeBinaryWatcher(installationPath!, OfficeInstallDetector.CoreBinaries, _logger);
_binaryWatcher.BinaryAppeared += OnBinaryAppeared;
_binaryWatcher.Start();
}
}
private void OnBinaryAppeared(object? sender, EventArgs e)
{
var outcome = _detector.TryFinalizeCompletion();
lock (_lock)
{
if (_lifecycleEnded || _disposed != 0) return;
if (outcome == OfficeInstallDetector.CompletionOutcome.NotYet)
{
if (++_probeAttempts <= MaxCompletionProbes)
{
_logger.Debug($"[OfficeInstallDetectorHost] no on-disk completion proof yet — probe {_probeAttempts}/{MaxCompletionProbes} in {CompletionProbeIntervalSeconds}s");
_closeTimer = new Timer(OnCloseTimer, null, TimeSpan.FromSeconds(CompletionProbeIntervalSeconds), Timeout.InfiniteTimeSpan);
return;
}
// Exhausted — stop without emitting a terminal (conservative, no false completed/failed).
_detector.AbandonSilently();
}
_lifecycleEnded = true;
}
DisposeRegistryWatcher();
if (outcome == OfficeInstallDetector.CompletionOutcome.NotYet) return; // FS event but probe disagreed — keep watching
lock (_lock) { _lifecycleEnded = true; }
DisposeWatchers();
}
public void Stop() => Dispose();
@@ -202,16 +147,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
{
if (Interlocked.Exchange(ref _disposed, 1) == 1) return;
try { _processWatcher.Started -= OnWorkerStarted; } catch { }
try { _processWatcher.Stopped -= OnWorkerStopped; } catch { }
try { _processWatcher.Dispose(); } catch { }
lock (_lock)
{
CancelCloseTimer();
}
DisposeRegistryWatcher();
_detector.AbandonSilently(); // latch terminal if still active — no event
DisposeWatchers();
}
private void DisposeRegistryWatcher()
private void DisposeWatchers()
{
lock (_lock)
{
@@ -221,6 +162,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
try { _registryWatcher.Dispose(); } catch { }
_registryWatcher = null;
}
if (_binaryWatcher != null)
{
try { _binaryWatcher.BinaryAppeared -= OnBinaryAppeared; } catch { }
try { _binaryWatcher.Dispose(); } catch { }
_binaryWatcher = null;
}
}
}
}