diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterTimingTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterTimingTests.cs
new file mode 100644
index 00000000..22972c51
--- /dev/null
+++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterTimingTests.cs
@@ -0,0 +1,188 @@
+using System;
+using System.Collections.Generic;
+using System.Globalization;
+using System.Linq;
+using AutopilotMonitor.Agent.V2.Core.Logging;
+using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
+using AutopilotMonitor.Agent.V2.Core.SignalAdapters;
+using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
+using AutopilotMonitor.Agent.V2.Core.Tests.Orchestration;
+using AutopilotMonitor.DecisionCore.Engine;
+using AutopilotMonitor.DecisionCore.Signals;
+using AutopilotMonitor.Shared.Models;
+using SharedEventTypes = AutopilotMonitor.Shared.Constants.EventTypes;
+using Xunit;
+
+namespace AutopilotMonitor.Agent.V2.Core.Tests.SignalAdapters
+{
+ ///
+ /// Plan §5 Fix 4c — adapter tracks per-app install-lifecycle timing and surfaces it on
+ /// app_install_* event DataJson (startedAt / completedAt /
+ /// durationSeconds) + via the new
+ /// snapshot for downstream consumers (FinalStatusBuilder, app_tracking_summary).
+ ///
+ public sealed class ImeLogTrackerAdapterTimingTests
+ {
+ private static readonly DateTime T0 = new DateTime(2026, 4, 24, 10, 0, 0, DateTimeKind.Utc);
+
+ private sealed class Fixture : IDisposable
+ {
+ public TempDirectory Tmp { get; } = new TempDirectory();
+ public AgentLogger Logger { get; }
+ public ImeLogTracker Tracker { get; }
+ public FakeSignalIngressSink Ingress { get; } = new FakeSignalIngressSink();
+ public VirtualClock Clock { get; } = new VirtualClock(T0);
+
+ public Fixture()
+ {
+ Logger = new AgentLogger(Tmp.Path, AgentLogLevel.Info);
+ Tracker = new ImeLogTracker(
+ logFolder: Tmp.Path,
+ patterns: new List(),
+ logger: Logger);
+ }
+
+ public FakeSignalIngressSink.PostedSignal InfoEvent(string eventType) =>
+ Ingress.Posted.Single(p =>
+ p.Kind == DecisionSignalKind.InformationalEvent
+ && p.Payload != null
+ && p.Payload.TryGetValue(SignalPayloadKeys.EventType, out var et)
+ && et == eventType);
+
+ public void Dispose()
+ {
+ Tracker.Dispose();
+ Tmp.Dispose();
+ }
+ }
+
+ [Fact]
+ public void First_Installing_transition_stamps_StartedAt_on_adapter_and_payload()
+ {
+ using var f = new Fixture();
+ using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
+ var app = new AppPackageState("app-A", 0);
+
+ adapter.TriggerAppStateFromTest(app, AppInstallationState.Unknown, AppInstallationState.Installing);
+
+ var info = f.InfoEvent(SharedEventTypes.AppInstallStart);
+ Assert.Equal(T0.ToString("o"), info.Payload!["startedAt"]);
+ Assert.False(info.Payload.ContainsKey("completedAt"));
+ Assert.False(info.Payload.ContainsKey("durationSeconds"));
+
+ Assert.True(adapter.AppTimings.ContainsKey("app-A"));
+ Assert.Equal(T0, adapter.AppTimings["app-A"].StartedAtUtc);
+ Assert.Null(adapter.AppTimings["app-A"].CompletedAtUtc);
+ }
+
+ [Fact]
+ public void Downloading_transition_also_stamps_StartedAt()
+ {
+ using var f = new Fixture();
+ using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
+ var app = new AppPackageState("app-D", 0);
+
+ adapter.TriggerAppStateFromTest(app, AppInstallationState.Unknown, AppInstallationState.Downloading);
+
+ Assert.Equal(T0, adapter.AppTimings["app-D"].StartedAtUtc);
+ var info = f.InfoEvent(SharedEventTypes.AppDownloadStarted);
+ Assert.Equal(T0.ToString("o"), info.Payload!["startedAt"]);
+ }
+
+ [Fact]
+ public void Terminal_transition_stamps_CompletedAt_and_emits_DurationSeconds()
+ {
+ using var f = new Fixture();
+ using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
+ var app = new AppPackageState("app-T", 0);
+
+ adapter.TriggerAppStateFromTest(app, AppInstallationState.Unknown, AppInstallationState.Installing);
+ f.Clock.Advance(TimeSpan.FromSeconds(42.5));
+ adapter.TriggerAppStateFromTest(app, AppInstallationState.Installing, AppInstallationState.Installed);
+
+ var completeEvent = f.InfoEvent(SharedEventTypes.AppInstallComplete);
+ Assert.Equal(T0.ToString("o"), completeEvent.Payload!["startedAt"]);
+ Assert.Equal(T0.AddSeconds(42.5).ToString("o"), completeEvent.Payload["completedAt"]);
+ Assert.Equal("42.50", completeEvent.Payload["durationSeconds"]);
+
+ var timing = adapter.AppTimings["app-T"];
+ Assert.Equal(T0, timing.StartedAtUtc);
+ Assert.Equal(T0.AddSeconds(42.5), timing.CompletedAtUtc);
+ Assert.Equal(42.5, timing.DurationSeconds);
+ }
+
+ [Fact]
+ public void Error_transition_also_sets_CompletedAt()
+ {
+ using var f = new Fixture();
+ using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
+ var app = new AppPackageState("app-E", 0);
+
+ adapter.TriggerAppStateFromTest(app, AppInstallationState.Unknown, AppInstallationState.Installing);
+ f.Clock.Advance(TimeSpan.FromSeconds(3));
+ adapter.TriggerAppStateFromTest(app, AppInstallationState.Installing, AppInstallationState.Error);
+
+ var failedEvent = f.InfoEvent(SharedEventTypes.AppInstallFailed);
+ Assert.Equal("3.00", failedEvent.Payload!["durationSeconds"]);
+ Assert.NotNull(adapter.AppTimings["app-E"].CompletedAtUtc);
+ }
+
+ [Fact]
+ public void Timing_is_set_once_not_overwritten_by_subsequent_same_state_events()
+ {
+ using var f = new Fixture();
+ using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
+ var app = new AppPackageState("app-Z", 0);
+
+ adapter.TriggerAppStateFromTest(app, AppInstallationState.Unknown, AppInstallationState.Installing);
+ f.Clock.Advance(TimeSpan.FromSeconds(10));
+ adapter.TriggerAppStateFromTest(app, AppInstallationState.Installing, AppInstallationState.Installing);
+ f.Clock.Advance(TimeSpan.FromSeconds(5));
+ adapter.TriggerAppStateFromTest(app, AppInstallationState.Installing, AppInstallationState.Installed);
+
+ var timing = adapter.AppTimings["app-Z"];
+ // StartedAt = first Installing (T0), NOT the second one.
+ Assert.Equal(T0, timing.StartedAtUtc);
+ // CompletedAt = Installed stamp (T0 + 15s).
+ Assert.Equal(T0.AddSeconds(15), timing.CompletedAtUtc);
+ }
+
+ [Fact]
+ public void AppTimings_snapshot_is_an_independent_copy()
+ {
+ using var f = new Fixture();
+ using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
+ adapter.TriggerAppStateFromTest(new AppPackageState("a", 0),
+ AppInstallationState.Unknown, AppInstallationState.Installing);
+
+ var snap1 = adapter.AppTimings;
+
+ f.Clock.Advance(TimeSpan.FromSeconds(5));
+ adapter.TriggerAppStateFromTest(new AppPackageState("a", 0),
+ AppInstallationState.Installing, AppInstallationState.Installed);
+
+ // snap1 captured before terminal — CompletedAt must still be null.
+ Assert.Null(snap1["a"].CompletedAtUtc);
+ // Fresh snap reflects the terminal stamp.
+ Assert.NotNull(adapter.AppTimings["a"].CompletedAtUtc);
+ }
+
+ [Fact]
+ public void DownloadProgress_tick_does_not_regress_StartedAt()
+ {
+ // Fix 1 policy: download_progress is ImmediateUpload=true. Fix 4c must not let a
+ // mid-download progress tick rewrite the earlier Downloading-start stamp.
+ using var f = new Fixture();
+ using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
+ var app = new AppPackageState("app-P", 0);
+
+ adapter.TriggerAppStateFromTest(app, AppInstallationState.Unknown, AppInstallationState.Downloading);
+ var firstStamp = adapter.AppTimings["app-P"].StartedAtUtc;
+
+ f.Clock.Advance(TimeSpan.FromSeconds(9));
+ adapter.TriggerAppStateFromTest(app, AppInstallationState.Downloading, AppInstallationState.Downloading);
+
+ Assert.Equal(firstStamp, adapter.AppTimings["app-P"].StartedAtUtc);
+ }
+ }
+}
diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Termination/EnrollmentTerminationHandlerTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Termination/EnrollmentTerminationHandlerTests.cs
index e2de273d..d17bffb4 100644
--- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Termination/EnrollmentTerminationHandlerTests.cs
+++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Termination/EnrollmentTerminationHandlerTests.cs
@@ -126,6 +126,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Termination
};
}
+ public IReadOnlyDictionary? AppTimingsOverride { get; set; }
+
public EnrollmentTerminationHandler Build(AgentConfiguration? config = null)
{
config ??= BuildConfig();
@@ -156,7 +158,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Termination
// Zero out the timing ceremony for tests — production paths are covered by
// the dedicated V1-parity tests below which opt back in via their own Rig.
lateEventGracePeriod: TimeSpan.Zero,
- spoolDrainPeriod: TimeSpan.Zero);
+ spoolDrainPeriod: TimeSpan.Zero,
+ appTimingsAccessor: () => AppTimingsOverride ?? new Dictionary());
}
public void Dispose() => Tmp.Dispose();
@@ -436,5 +439,141 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Termination
Assert.Equal(0, rig.CleanupService.Invocations);
Assert.DoesNotContain(Constants.EventTypes.AgentShuttingDown, rig.EmittedEventTypes);
}
+
+ // ============================================================================
+ // Plan §5 Fix 4b — app_tracking_summary event
+ // ============================================================================
+
+ /// Reflection helper: AppPackageState.Targeted has a private setter.
+ private static void SetTargeted(AppPackageState pkg, AppTargeted t) =>
+ typeof(AppPackageState).GetProperty(nameof(AppPackageState.Targeted))!.SetValue(pkg, t);
+
+ [Fact]
+ public void Handle_emits_app_tracking_summary_with_counts_and_per_phase_breakdown()
+ {
+ using var rig = new Rig();
+ rig.State = new DecisionStateBuilder(DecisionState.CreateInitial("S1", "T1")) { Stage = SessionStage.Completed }.Build();
+
+ // AppPackageState.UpdateState has an inverse-detection guard: Installed without a
+ // prior DownloadingOrInstallingSeen=true flip is rewritten to Skipped. Seed the
+ // lifecycle via Installing first so the terminal state sticks.
+ var installed = new AppPackageState("app-installed", 0);
+ installed.UpdateState(AppInstallationState.Installing);
+ installed.UpdateState(AppInstallationState.Installed);
+ SetTargeted(installed, AppTargeted.Device);
+ rig.Packages.Add(installed);
+
+ var failed = new AppPackageState("app-failed", 1);
+ failed.UpdateState(AppInstallationState.Error);
+ SetTargeted(failed, AppTargeted.User);
+ rig.Packages.Add(failed);
+
+ var skipped = new AppPackageState("app-skipped", 2);
+ skipped.UpdateState(AppInstallationState.Skipped);
+ SetTargeted(skipped, AppTargeted.User);
+ rig.Packages.Add(skipped);
+
+ rig.Build().Handle(sender: null!,
+ Args(EnrollmentTerminationReason.DecisionTerminalStage, EnrollmentTerminationOutcome.Succeeded, SessionStage.Completed));
+
+ Assert.Contains(Constants.EventTypes.AppTrackingSummary, rig.EmittedEventTypes);
+
+ var data = rig.DataOf(Constants.EventTypes.AppTrackingSummary);
+ Assert.NotNull(data);
+ Assert.Equal(3, Convert.ToInt32(data!["totalApps"]));
+ Assert.Equal(3, Convert.ToInt32(data["completedApps"]));
+ Assert.Equal(1, Convert.ToInt32(data["installedApps"]));
+ Assert.Equal(1, Convert.ToInt32(data["skippedApps"]));
+ Assert.Equal(1, Convert.ToInt32(data["failedApps"]));
+
+ var byPhase = (IReadOnlyDictionary>)data["byPhase"];
+ Assert.Equal(1, byPhase["Device"]["total"]);
+ Assert.Equal(2, byPhase["User"]["total"]);
+ Assert.Equal(1, byPhase["User"]["failed"]);
+ Assert.Equal(1, byPhase["User"]["skipped"]);
+ }
+
+ [Fact]
+ public void Handle_app_tracking_summary_includes_per_app_timing_when_provided()
+ {
+ using var rig = new Rig();
+ rig.State = new DecisionStateBuilder(DecisionState.CreateInitial("S1", "T1")) { Stage = SessionStage.Completed }.Build();
+
+ var app = new AppPackageState("app-1", 0);
+ app.UpdateState(AppInstallationState.Installing);
+ app.UpdateState(AppInstallationState.Installed);
+ SetTargeted(app, AppTargeted.Device);
+ rig.Packages.Add(app);
+
+ rig.AppTimingsOverride = new Dictionary
+ {
+ ["app-1"] = new AppInstallTiming(StartUtc.AddSeconds(30), StartUtc.AddSeconds(90)),
+ };
+
+ rig.Build().Handle(sender: null!,
+ Args(EnrollmentTerminationReason.DecisionTerminalStage, EnrollmentTerminationOutcome.Succeeded, SessionStage.Completed));
+
+ var data = rig.DataOf(Constants.EventTypes.AppTrackingSummary);
+ Assert.NotNull(data);
+ var perApp = (List>)data!["perApp"];
+ var entry = Assert.Single(perApp);
+ Assert.Equal("app-1", entry["appId"]);
+ Assert.Equal("Device", entry["phase"]);
+ Assert.Equal("Installed", entry["finalState"]);
+ Assert.Equal(StartUtc.AddSeconds(30).ToString("o"), entry["startedAt"]);
+ Assert.Equal(StartUtc.AddSeconds(90).ToString("o"), entry["completedAt"]);
+ Assert.Equal(60.0, Convert.ToDouble(entry["durationSeconds"]));
+ }
+
+ [Fact]
+ public void Handle_app_tracking_summary_omits_timing_when_adapter_has_none()
+ {
+ using var rig = new Rig();
+ rig.State = new DecisionStateBuilder(DecisionState.CreateInitial("S1", "T1")) { Stage = SessionStage.Completed }.Build();
+
+ var app = new AppPackageState("untimed", 0);
+ app.UpdateState(AppInstallationState.Installing);
+ app.UpdateState(AppInstallationState.Installed);
+ SetTargeted(app, AppTargeted.Device);
+ rig.Packages.Add(app);
+
+ rig.Build().Handle(sender: null!,
+ Args(EnrollmentTerminationReason.DecisionTerminalStage, EnrollmentTerminationOutcome.Succeeded, SessionStage.Completed));
+
+ var data = rig.DataOf(Constants.EventTypes.AppTrackingSummary);
+ var perApp = (List>)data!["perApp"];
+ var entry = Assert.Single(perApp);
+ Assert.False(entry.ContainsKey("startedAt"));
+ Assert.False(entry.ContainsKey("completedAt"));
+ Assert.False(entry.ContainsKey("durationSeconds"));
+ }
+
+ [Fact]
+ public void Handle_does_not_emit_app_tracking_summary_on_whiteglove_part1_exit()
+ {
+ // Part 1 runs pre-provisioning — no apps have installed yet; the summary event
+ // would be vacuous and misleading.
+ using var rig = new Rig();
+ rig.State = new DecisionStateBuilder(DecisionState.CreateInitial("S1", "T1")) { Stage = SessionStage.WhiteGloveSealed }.Build();
+
+ rig.Build().Handle(sender: null!,
+ Args(EnrollmentTerminationReason.DecisionTerminalStage, EnrollmentTerminationOutcome.Succeeded, SessionStage.WhiteGloveSealed));
+
+ Assert.DoesNotContain(Constants.EventTypes.AppTrackingSummary, rig.EmittedEventTypes);
+ }
+
+ [Fact]
+ public void Handle_app_tracking_summary_marked_immediate_upload()
+ {
+ using var rig = new Rig();
+ rig.State = new DecisionStateBuilder(DecisionState.CreateInitial("S1", "T1")) { Stage = SessionStage.Completed }.Build();
+
+ rig.Build().Handle(sender: null!,
+ Args(EnrollmentTerminationReason.DecisionTerminalStage, EnrollmentTerminationOutcome.Succeeded, SessionStage.Completed));
+
+ var payload = rig.PayloadOf(Constants.EventTypes.AppTrackingSummary);
+ Assert.NotNull(payload);
+ Assert.Equal("true", payload![SignalPayloadKeys.ImmediateUpload]);
+ }
}
}
diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Termination/FinalStatusBuilderTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Termination/FinalStatusBuilderTests.cs
index ebad4d30..4f116e7a 100644
--- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Termination/FinalStatusBuilderTests.cs
+++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Termination/FinalStatusBuilderTests.cs
@@ -172,6 +172,74 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Termination
Assert.Single(status.PackageStatesByPhase["User"]);
}
+ [Fact]
+ public void Build_includes_per_app_timing_when_app_timings_provided()
+ {
+ // Plan §5 Fix 4a — FinalStatusBuilder surfaces StartedAt / CompletedAt /
+ // DurationSeconds on per-app package rows when the adapter's timing snapshot is
+ // available. Null snapshot → timing fields stay null (dialog distinguishes the two).
+ using var tmp = new TempDirectory();
+ var logger = new AgentLogger(tmp.Path, AgentLogLevel.Info);
+ var list = new AppPackageStateList(logger);
+ var installed = new AppPackageState("app-timed", 0);
+ installed.UpdateState(AppInstallationState.Installed);
+ TestHelpers.SetTargeted(installed, AppTargeted.Device);
+ list.Add(installed);
+ var untimed = new AppPackageState("app-untimed", 1);
+ untimed.UpdateState(AppInstallationState.Installed);
+ TestHelpers.SetTargeted(untimed, AppTargeted.Device);
+ list.Add(untimed);
+
+ var timings = new System.Collections.Generic.Dictionary
+ {
+ ["app-timed"] = new AppInstallTiming(StartUtc.AddMinutes(2), StartUtc.AddMinutes(3)),
+ // app-untimed intentionally absent — builder should omit fields
+ };
+
+ var status = FinalStatusBuilder.Build(
+ StateWith(SessionStage.Completed),
+ Args(EnrollmentTerminationReason.DecisionTerminalStage, EnrollmentTerminationOutcome.Succeeded, SessionStage.Completed),
+ packageStates: list,
+ agentStartTimeUtc: StartUtc,
+ appTimings: timings);
+
+ var timedInfo = status.PackageStatesByPhase["Device"].Single(p => p.AppName == "app-timed");
+ Assert.Equal(StartUtc.AddMinutes(2).ToString("o"), timedInfo.StartedAt);
+ Assert.Equal(StartUtc.AddMinutes(3).ToString("o"), timedInfo.CompletedAt);
+ Assert.Equal(60.0, timedInfo.DurationSeconds);
+
+ var untimedInfo = status.PackageStatesByPhase["Device"].Single(p => p.AppName == "app-untimed");
+ Assert.Null(untimedInfo.StartedAt);
+ Assert.Null(untimedInfo.CompletedAt);
+ Assert.Null(untimedInfo.DurationSeconds);
+ }
+
+ [Fact]
+ public void Build_with_null_app_timings_still_produces_package_states()
+ {
+ // Backward-compat: when appTimings is not passed (older call sites / tests), the
+ // builder uses an empty timing map and the timing fields stay null on every row.
+ using var tmp = new TempDirectory();
+ var logger = new AgentLogger(tmp.Path, AgentLogLevel.Info);
+ var list = new AppPackageStateList(logger);
+ var app = new AppPackageState("a", 0);
+ app.UpdateState(AppInstallationState.Installed);
+ TestHelpers.SetTargeted(app, AppTargeted.Device);
+ list.Add(app);
+
+ var status = FinalStatusBuilder.Build(
+ StateWith(SessionStage.Completed),
+ Args(EnrollmentTerminationReason.DecisionTerminalStage, EnrollmentTerminationOutcome.Succeeded, SessionStage.Completed),
+ packageStates: list,
+ agentStartTimeUtc: StartUtc,
+ appTimings: null);
+
+ var info = status.PackageStatesByPhase["Device"].Single();
+ Assert.Null(info.StartedAt);
+ Assert.Null(info.CompletedAt);
+ Assert.Null(info.DurationSeconds);
+ }
+
[Fact]
public void Build_serializes_to_json_with_expected_property_names()
{
diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Transport/BackendTelemetryUploaderLoggingTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Transport/BackendTelemetryUploaderLoggingTests.cs
new file mode 100644
index 00000000..3c0412ac
--- /dev/null
+++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Transport/BackendTelemetryUploaderLoggingTests.cs
@@ -0,0 +1,151 @@
+using System;
+using System.IO;
+using System.Net;
+using System.Net.Http;
+using System.Threading;
+using System.Threading.Tasks;
+using AutopilotMonitor.Agent.V2.Core.Logging;
+using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
+using AutopilotMonitor.Agent.V2.Core.Transport.Telemetry;
+using Xunit;
+
+namespace AutopilotMonitor.Agent.V2.Core.Tests.Transport
+{
+ ///
+ /// Plan §5 Fix 5 — emits upload-cadence log lines
+ /// (flushing / ingest OK / ingest TRANSIENT / ingest PERMANENT) so the agent log is no
+ /// longer silent during the transport path. We assert on log-file content because the
+ /// AgentLogger writes to disk; checking the file is the most faithful production proxy.
+ ///
+ public sealed class BackendTelemetryUploaderLoggingTests
+ {
+ private static readonly DateTime At = new DateTime(2026, 4, 24, 10, 0, 0, DateTimeKind.Utc);
+
+ private static TelemetryItem NewEventItem(long id) =>
+ new TelemetryItem(
+ kind: TelemetryItemKind.Event,
+ partitionKey: "T1_S1",
+ rowKey: id.ToString("D10"),
+ telemetryItemId: id,
+ sessionTraceOrdinal: id,
+ payloadJson: $"{{\"EventType\":\"test\",\"Sequence\":{id}}}",
+ requiresImmediateFlush: false,
+ enqueuedAtUtc: At);
+
+ private static string ReadLogs(string path)
+ {
+ // AgentLogger writes to a dated file; scan the whole dir to stay robust to format.
+ var sb = new System.Text.StringBuilder();
+ foreach (var f in Directory.EnumerateFiles(path, "*.log", SearchOption.AllDirectories))
+ {
+ try
+ {
+ // Opened with ReadWrite share so we don't collide with an in-flight logger.
+ using var fs = new FileStream(f, FileMode.Open, FileAccess.Read, FileShare.ReadWrite);
+ using var reader = new StreamReader(fs);
+ sb.AppendLine(reader.ReadToEnd());
+ }
+ catch { /* best-effort */ }
+ }
+ return sb.ToString();
+ }
+
+ [Fact]
+ public async Task UploadBatch_logs_flush_start_and_ingest_OK_on_success()
+ {
+ using var tmp = new TempDirectory();
+ var logger = new AgentLogger(tmp.Path, AgentLogLevel.Info);
+
+ var handler = new RecordingHttpMessageHandler();
+ handler.QueueStatus(HttpStatusCode.OK);
+ using var http = new HttpClient(handler) { Timeout = TimeSpan.FromSeconds(30) };
+
+ var sut = new BackendTelemetryUploader(
+ httpClient: http,
+ baseUrl: "https://backend.test",
+ tenantId: "T1",
+ logger: logger);
+
+ var result = await sut.UploadBatchAsync(new[] { NewEventItem(1), NewEventItem(2) }, CancellationToken.None);
+ Assert.True(result.Success);
+
+ // AgentLogger writes each line with File.AppendAllText — content is already on disk.
+ var logContent = ReadLogs(tmp.Path);
+ Assert.Contains("BackendTelemetryUploader: flushing 2 item(s)", logContent);
+ Assert.Contains("BackendTelemetryUploader: ingest OK (items=2", logContent);
+ }
+
+ [Fact]
+ public async Task UploadBatch_logs_TRANSIENT_on_5xx()
+ {
+ using var tmp = new TempDirectory();
+ var logger = new AgentLogger(tmp.Path, AgentLogLevel.Info);
+
+ var handler = new RecordingHttpMessageHandler();
+ handler.QueueStatus(HttpStatusCode.InternalServerError);
+ using var http = new HttpClient(handler) { Timeout = TimeSpan.FromSeconds(30) };
+
+ var sut = new BackendTelemetryUploader(
+ httpClient: http,
+ baseUrl: "https://backend.test",
+ tenantId: "T1",
+ logger: logger);
+
+ var result = await sut.UploadBatchAsync(new[] { NewEventItem(1) }, CancellationToken.None);
+ Assert.False(result.Success);
+ Assert.True(result.IsTransient);
+
+ var logContent = ReadLogs(tmp.Path);
+ Assert.Contains("BackendTelemetryUploader: ingest TRANSIENT", logContent);
+ }
+
+ [Fact]
+ public async Task UploadBatch_logs_PERMANENT_on_4xx()
+ {
+ using var tmp = new TempDirectory();
+ var logger = new AgentLogger(tmp.Path, AgentLogLevel.Info);
+
+ var handler = new RecordingHttpMessageHandler();
+ handler.QueueStatus(HttpStatusCode.BadRequest);
+ using var http = new HttpClient(handler) { Timeout = TimeSpan.FromSeconds(30) };
+
+ var sut = new BackendTelemetryUploader(
+ httpClient: http,
+ baseUrl: "https://backend.test",
+ tenantId: "T1",
+ logger: logger);
+
+ var result = await sut.UploadBatchAsync(new[] { NewEventItem(1) }, CancellationToken.None);
+ Assert.False(result.Success);
+ Assert.False(result.IsTransient);
+
+ var logContent = ReadLogs(tmp.Path);
+ Assert.Contains("BackendTelemetryUploader: ingest PERMANENT", logContent);
+ }
+
+ [Fact]
+ public async Task UploadBatch_empty_batch_no_log_no_network()
+ {
+ // Short-circuit empty batch must not burn a log line or an HTTP call.
+ using var tmp = new TempDirectory();
+ var logger = new AgentLogger(tmp.Path, AgentLogLevel.Info);
+
+ var handler = new RecordingHttpMessageHandler();
+ using var http = new HttpClient(handler);
+
+ var sut = new BackendTelemetryUploader(
+ httpClient: http,
+ baseUrl: "https://backend.test",
+ tenantId: "T1",
+ logger: logger);
+
+ var result = await sut.UploadBatchAsync(Array.Empty(), CancellationToken.None);
+ Assert.True(result.Success);
+ Assert.Empty(handler.Captured);
+
+ var logContent = ReadLogs(tmp.Path);
+ Assert.DoesNotContain("flushing", logContent);
+ Assert.DoesNotContain("ingest", logContent);
+ }
+ }
+}
diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/AppInstallTiming.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/AppInstallTiming.cs
new file mode 100644
index 00000000..dc803baf
--- /dev/null
+++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/AppInstallTiming.cs
@@ -0,0 +1,40 @@
+#nullable enable
+using System;
+
+namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
+{
+ ///
+ /// Per-app install-lifecycle timestamps captured by .
+ /// Plan §5 Fix 4 — powers the StartedAt / CompletedAt / DurationSeconds
+ /// fields on app_install_* events, the FinalStatusPackageInfo timing rows, and
+ /// the app_tracking_summary terminal event.
+ ///
+ /// StartedAtUtc is recorded on the first lifecycle transition into Downloading /
+ /// Installing / InProgress. CompletedAtUtc is recorded on the first transition to a
+ /// terminal state (Installed / Skipped / Postponed / Error). Both are "set-once" — subsequent
+ /// identical-state events do not overwrite an earlier stamp.
+ ///
+ ///
+ public sealed class AppInstallTiming
+ {
+ public AppInstallTiming(DateTime? startedAtUtc, DateTime? completedAtUtc)
+ {
+ StartedAtUtc = startedAtUtc;
+ CompletedAtUtc = completedAtUtc;
+ }
+
+ public DateTime? StartedAtUtc { get; }
+
+ public DateTime? CompletedAtUtc { get; }
+
+ ///
+ /// Elapsed time from first Downloading/Installing transition to terminal state, in
+ /// seconds. null when either endpoint is missing (e.g. app still installing,
+ /// or the adapter missed the start event because it came online mid-install).
+ ///
+ public double? DurationSeconds =>
+ StartedAtUtc.HasValue && CompletedAtUtc.HasValue
+ ? (CompletedAtUtc.Value - StartedAtUtc.Value).TotalSeconds
+ : (double?)null;
+ }
+}
diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs
index 0df7c726..bebdfd25 100644
--- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs
+++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs
@@ -73,6 +73,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
///
public Monitoring.Enrollment.Ime.AppPackageStateList? ImePackageStates => _imeLogHost?.PackageStates;
+ ///
+ /// Plan §5 Fix 4c — per-app install-lifecycle timings (StartedAt / CompletedAt /
+ /// DurationSeconds) captured by ImeLogTrackerAdapter. Returns null before
+ /// has been called (Orchestrator start order).
+ ///
+ public System.Collections.Generic.IReadOnlyDictionary? ImeAppTimings => _imeLogHost?.AppTimings;
+
public DefaultComponentFactory(
AgentConfiguration agentConfig,
AgentConfigResponse remoteConfig,
@@ -502,6 +509,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
///
public Monitoring.Enrollment.Ime.AppPackageStateList PackageStates => _tracker.PackageStates;
+ ///
+ /// Plan §5 Fix 4c — per-app install-lifecycle timings captured by the adapter,
+ /// read-only snapshot. Consumed by FinalStatusBuilder (adds StartedAt/
+ /// CompletedAt/DurationSeconds rows) and by the app_tracking_summary
+ /// emission in EnrollmentTerminationHandler.
+ ///
+ public System.Collections.Generic.IReadOnlyDictionary AppTimings => _adapter.AppTimings;
+
///
/// Reference to the wrapped IME tracker for co-collector wiring. Used by
/// DeliveryOptimizationHost to set OnDoTelemetryReceived and to chain
diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs
index a5e8589d..2699150a 100644
--- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs
+++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs
@@ -313,7 +313,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
}
// 3) Telemetry-Transport.
- _spool = new TelemetrySpool(_transportDirectory, _clock);
+ _spool = new TelemetrySpool(_transportDirectory, _clock, _logger);
_transport = new TelemetryUploadOrchestrator(_spool, _uploader, _clock);
// 4) Event-Emitter-Kette. Single-rail (Plan §5.10): der TelemetryEventEmitter wird
diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs
index 3d459db1..727077af 100644
--- a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs
+++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs
@@ -88,6 +88,14 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
// AppsDevice once, "AccountSetup" -> AppsUser once).
private readonly HashSet _subPhaseDeclarationsEmitted = new HashSet(StringComparer.Ordinal);
+ // Plan §5 Fix 4c — per-app install-lifecycle timing captured from state transitions.
+ // StartedAtUtc on first Downloading/Installing/InProgress transition (set-once);
+ // CompletedAtUtc on first terminal transition (Installed/Skipped/Postponed/Error).
+ // Surfaced via to peripheral consumers (FinalStatusBuilder,
+ // app_tracking_summary emission in EnrollmentTerminationHandler).
+ private readonly Dictionary _appTimings =
+ new Dictionary(StringComparer.Ordinal);
+
public ImeLogTrackerAdapter(
ImeLogTracker tracker,
ISignalIngressSink ingress,
@@ -312,6 +320,10 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
// boundary before the app entry inside it.
MaybeEmitSubPhaseDeclaration(now);
+ // Plan §5 Fix 4c — set-once per-app timing. Start stamp on the first Downloading/
+ // Installing/InProgress transition, complete stamp on the first terminal state.
+ var timing = UpdateAppTiming(app.Id, newState, now);
+
// (1) DecisionSignal — terminal states only, once per app.
var terminalKind = ClassifyTerminalState(newState);
if (terminalKind != null)
@@ -362,10 +374,64 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
message: BuildAppStateMessage(app, newState, eventType),
severity: severity,
immediateUpload: true,
- data: BuildAppStatePayload(app, newState),
+ data: BuildAppStatePayload(app, newState, timing),
occurredAtUtc: now);
}
+ ///
+ /// Plan §5 Fix 4c — set-once per-app install-lifecycle timing. Called for every
+ /// state transition, no-op for duplicate stamps. Returns the up-to-date
+ /// so the emitter can inline the values on the
+ /// current event's payload without a second dictionary lookup.
+ ///
+ private AppInstallTiming UpdateAppTiming(string appId, AppInstallationState newState, DateTime now)
+ {
+ lock (_lock)
+ {
+ _appTimings.TryGetValue(appId, out var current);
+
+ // First lifecycle-active transition → record StartedAt.
+ if (current.Started == null && IsLifecycleActive(newState))
+ {
+ current.Started = now;
+ }
+
+ // First terminal transition → record CompletedAt.
+ if (current.Completed == null && IsCompletedState(newState))
+ {
+ current.Completed = now;
+ }
+
+ _appTimings[appId] = current;
+ return new AppInstallTiming(current.Started, current.Completed);
+ }
+ }
+
+ ///
+ /// Snapshot of per-app install timings captured during this agent run. Fire-once
+ /// stamps, safe to read concurrently with adapter emissions.
+ ///
+ public IReadOnlyDictionary AppTimings
+ {
+ get
+ {
+ lock (_lock)
+ {
+ var snapshot = new Dictionary(_appTimings.Count, StringComparer.Ordinal);
+ foreach (var kv in _appTimings)
+ {
+ snapshot[kv.Key] = new AppInstallTiming(kv.Value.Started, kv.Value.Completed);
+ }
+ return snapshot;
+ }
+ }
+ }
+
+ private static bool IsLifecycleActive(AppInstallationState state) =>
+ state == AppInstallationState.Downloading
+ || state == AppInstallationState.Installing
+ || state == AppInstallationState.InProgress;
+
///
/// Plan §5 Fix 2 — emit a phase_transition declaration event the first time we
/// see app activity in a given ESP phase, so the Web UI's PhaseTimeline opens an
@@ -636,8 +702,10 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
private static IReadOnlyDictionary BuildAppStatePayload(
AppPackageState app,
- AppInstallationState newState)
+ AppInstallationState newState,
+ AppInstallTiming timing)
{
+ var culture = System.Globalization.CultureInfo.InvariantCulture;
var data = new Dictionary(StringComparer.Ordinal)
{
["appId"] = app.Id,
@@ -646,18 +714,29 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
["intent"] = app.Intent.ToString(),
["targeted"] = app.Targeted.ToString(),
["runAs"] = app.RunAs.ToString(),
- ["progressPercent"] = (app.ProgressPercent ?? 0).ToString(System.Globalization.CultureInfo.InvariantCulture),
- ["bytesDownloaded"] = app.BytesDownloaded.ToString(System.Globalization.CultureInfo.InvariantCulture),
- ["bytesTotal"] = app.BytesTotal.ToString(System.Globalization.CultureInfo.InvariantCulture),
+ ["progressPercent"] = (app.ProgressPercent ?? 0).ToString(culture),
+ ["bytesDownloaded"] = app.BytesDownloaded.ToString(culture),
+ ["bytesTotal"] = app.BytesTotal.ToString(culture),
["isError"] = (newState == AppInstallationState.Error).ToString().ToLowerInvariant(),
["isCompleted"] = IsCompletedState(newState).ToString().ToLowerInvariant(),
};
if (!string.IsNullOrEmpty(app.AppVersion)) data["appVersion"] = app.AppVersion!;
if (!string.IsNullOrEmpty(app.AppType)) data["appType"] = app.AppType!;
- if (app.AttemptNumber > 0) data["attemptNumber"] = app.AttemptNumber.ToString(System.Globalization.CultureInfo.InvariantCulture);
+ if (app.AttemptNumber > 0) data["attemptNumber"] = app.AttemptNumber.ToString(culture);
if (!string.IsNullOrEmpty(app.DetectionResult)) data["detectionResult"] = app.DetectionResult!;
+ // Plan §5 Fix 4c — per-app install-lifecycle timing. StartedAt appears on the
+ // first Downloading/Installing/InProgress event; CompletedAt + DurationSeconds
+ // light up on the terminal event. Values are omitted when not yet known so the
+ // UI can distinguish "not yet started" from "stamp=epoch".
+ if (timing.StartedAtUtc.HasValue)
+ data["startedAt"] = timing.StartedAtUtc.Value.ToString("o", culture);
+ if (timing.CompletedAtUtc.HasValue)
+ data["completedAt"] = timing.CompletedAtUtc.Value.ToString("o", culture);
+ if (timing.DurationSeconds.HasValue)
+ data["durationSeconds"] = timing.DurationSeconds.Value.ToString("F2", culture);
+
if (newState == AppInstallationState.Error)
{
if (!string.IsNullOrEmpty(app.ErrorPatternId)) data["errorPatternId"] = app.ErrorPatternId!;
diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/EnrollmentTerminationHandler.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/EnrollmentTerminationHandler.cs
index 6b10b690..af2c88cc 100644
--- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/EnrollmentTerminationHandler.cs
+++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/EnrollmentTerminationHandler.cs
@@ -57,6 +57,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination
private readonly DateTime _agentStartTimeUtc;
private readonly Func _currentStateAccessor;
private readonly Func _packageStatesAccessor;
+ private readonly Func> _appTimingsAccessor;
private readonly Func _cleanupServiceFactory;
private readonly Func> _uploadDiagnosticsAsync;
private readonly Action _signalShutdown;
@@ -86,7 +87,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination
SessionIdPersistence sessionPersistence = null,
Action triggerReboot = null,
TimeSpan? lateEventGracePeriod = null,
- TimeSpan? spoolDrainPeriod = null)
+ TimeSpan? spoolDrainPeriod = null,
+ Func> appTimingsAccessor = null)
{
_configuration = configuration ?? throw new ArgumentNullException(nameof(configuration));
_logger = logger ?? throw new ArgumentNullException(nameof(logger));
@@ -94,6 +96,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination
_agentStartTimeUtc = agentStartTimeUtc;
_currentStateAccessor = currentStateAccessor ?? throw new ArgumentNullException(nameof(currentStateAccessor));
_packageStatesAccessor = packageStatesAccessor ?? throw new ArgumentNullException(nameof(packageStatesAccessor));
+ // Plan §5 Fix 4 — optional timing accessor (older call sites / tests without IME
+ // plumbing pass null → empty timings, which is handled below).
+ _appTimingsAccessor = appTimingsAccessor ?? (() => new Dictionary());
_cleanupServiceFactory = cleanupServiceFactory ?? throw new ArgumentNullException(nameof(cleanupServiceFactory));
_uploadDiagnosticsAsync = uploadDiagnosticsAsync ?? throw new ArgumentNullException(nameof(uploadDiagnosticsAsync));
_signalShutdown = signalShutdown ?? throw new ArgumentNullException(nameof(signalShutdown));
@@ -136,6 +141,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination
RunBuildAndLaunchDialog(state, args);
}
+ // Plan §5 Fix 4b — emit app_tracking_summary terminal event before the
+ // late-event grace + diagnostics upload, so the backend has the final per-app
+ // summary even if the diagnostics upload fails. Skipped on WhiteGlove Part 1
+ // (apps haven't installed yet — Part 2 is where user apps land).
+ if (!isWhiteGlovePart1)
+ {
+ EmitAppTrackingSummary();
+ }
+
// WhiteGlove Part-1 exit: keep the session alive, but announce the handoff so
// the timeline clearly marks the transition. The `whiteglove.complete` marker
// lets the next agent boot classify itself as a Part-2 resume.
@@ -198,6 +212,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination
}
}
+ private IReadOnlyDictionary TryGetAppTimings()
+ {
+ try { return _appTimingsAccessor() ?? new Dictionary(); }
+ catch (Exception ex)
+ {
+ _logger.Warning($"EnrollmentTerminationHandler: app timings accessor threw: {ex.Message}");
+ return new Dictionary();
+ }
+ }
+
private void RunShutdownAnalyzers(EnrollmentTerminatedEventArgs args)
{
if (_analyzerManager == null) return;
@@ -220,7 +244,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination
try
{
var packages = TryGetPackageStates();
- var status = FinalStatusBuilder.Build(state, args, packages, _agentStartTimeUtc);
+ var timings = TryGetAppTimings();
+ var status = FinalStatusBuilder.Build(state, args, packages, _agentStartTimeUtc, timings);
SummaryDialogLauncher.WriteAndLaunch(status, _configuration, _stateDirectory, _logger, _dialogExePathOverride);
if (_configuration.ShowEnrollmentSummary)
@@ -251,6 +276,112 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination
}
}
+ ///
+ /// Plan §5 Fix 4b — emit a single app_tracking_summary event at termination time
+ /// with aggregate counts, per-phase breakdown, and per-app install-lifecycle timing.
+ /// Consumed by the Web UI's useSessionDerivedData hook to build authoritative
+ /// per-app durations (matching V1's EnrollmentTracker.Diagnostics.cs:164 behaviour).
+ /// Best-effort: if any accessor throws, we log a warning and skip — the dialog has
+ /// already written final-status.json at this point, so the summary event is
+ /// supplementary observability, not load-bearing.
+ ///
+ private void EmitAppTrackingSummary()
+ {
+ if (_post == null)
+ {
+ // No informational event post (constructed in tests without wiring) — skip.
+ return;
+ }
+
+ try
+ {
+ var packages = TryGetPackageStates();
+ var timings = TryGetAppTimings();
+
+ var totalApps = 0;
+ var installedApps = 0;
+ var skippedApps = 0;
+ var postponedApps = 0;
+ var failedApps = 0;
+ var byPhase = new Dictionary>(StringComparer.Ordinal);
+ var perApp = new List>();
+
+ if (packages != null)
+ {
+ foreach (var pkg in packages)
+ {
+ totalApps++;
+ switch (pkg.InstallationState)
+ {
+ case AppInstallationState.Installed: installedApps++; break;
+ case AppInstallationState.Skipped: skippedApps++; break;
+ case AppInstallationState.Postponed: postponedApps++; break;
+ case AppInstallationState.Error: failedApps++; break;
+ }
+
+ var phaseKey = pkg.Targeted.ToString();
+ if (!byPhase.TryGetValue(phaseKey, out var bucket))
+ {
+ bucket = new Dictionary(StringComparer.Ordinal)
+ {
+ ["total"] = 0, ["installed"] = 0, ["skipped"] = 0, ["postponed"] = 0, ["failed"] = 0,
+ };
+ byPhase[phaseKey] = bucket;
+ }
+ bucket["total"]++;
+ if (pkg.InstallationState == AppInstallationState.Installed) bucket["installed"]++;
+ else if (pkg.InstallationState == AppInstallationState.Skipped) bucket["skipped"]++;
+ else if (pkg.InstallationState == AppInstallationState.Postponed) bucket["postponed"]++;
+ else if (pkg.InstallationState == AppInstallationState.Error) bucket["failed"]++;
+
+ timings.TryGetValue(pkg.Id, out var timing);
+ var appEntry = new Dictionary(StringComparer.Ordinal)
+ {
+ ["appId"] = pkg.Id,
+ ["appName"] = pkg.Name ?? string.Empty,
+ ["phase"] = phaseKey,
+ ["finalState"] = pkg.InstallationState.ToString(),
+ };
+ if (timing?.StartedAtUtc != null) appEntry["startedAt"] = timing.StartedAtUtc.Value.ToString("o");
+ if (timing?.CompletedAtUtc != null) appEntry["completedAt"] = timing.CompletedAtUtc.Value.ToString("o");
+ if (timing?.DurationSeconds != null) appEntry["durationSeconds"] = timing.DurationSeconds.Value;
+ perApp.Add(appEntry);
+ }
+ }
+
+ var completedApps = installedApps + skippedApps + postponedApps + failedApps;
+
+ var data = new Dictionary(StringComparer.Ordinal)
+ {
+ ["totalApps"] = totalApps,
+ ["completedApps"] = completedApps,
+ ["installedApps"] = installedApps,
+ ["skippedApps"] = skippedApps,
+ ["postponedApps"] = postponedApps,
+ ["failedApps"] = failedApps,
+ ["byPhase"] = byPhase,
+ ["perApp"] = perApp,
+ };
+
+ _post.Emit(new EnrollmentEvent
+ {
+ SessionId = _configuration.SessionId,
+ TenantId = _configuration.TenantId,
+ EventType = Constants.EventTypes.AppTrackingSummary,
+ Severity = EventSeverity.Info,
+ Source = "EnrollmentTerminationHandler",
+ Phase = EnrollmentPhase.Unknown,
+ Message = $"App summary: {completedApps}/{totalApps} completed, {failedApps} failed.",
+ Data = data,
+ ImmediateUpload = true,
+ });
+ }
+ catch (Exception ex)
+ {
+ _logger.Warning($"EnrollmentTerminationHandler: app_tracking_summary emit failed: {ex.Message}");
+ }
+ }
+
private void RunUploadDiagnosticsWithEvents(EnrollmentTerminatedEventArgs args)
{
var mode = _configuration.DiagnosticsUploadMode ?? "Off";
diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/FinalStatus.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/FinalStatus.cs
index bac6025b..bfe7d323 100644
--- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/FinalStatus.cs
+++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/FinalStatus.cs
@@ -80,5 +80,17 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination
[JsonProperty("targeted")]
public string Targeted { get; set; }
+
+ // Plan §5 Fix 4a / 4c — per-app install-lifecycle timestamps. Omitted from the
+ // JSON when not yet captured (e.g. agent started mid-install), so the dialog can
+ // distinguish "not tracked" from "stamp=epoch".
+ [JsonProperty("startedAt", NullValueHandling = NullValueHandling.Ignore)]
+ public string StartedAt { get; set; }
+
+ [JsonProperty("completedAt", NullValueHandling = NullValueHandling.Ignore)]
+ public string CompletedAt { get; set; }
+
+ [JsonProperty("durationSeconds", NullValueHandling = NullValueHandling.Ignore)]
+ public double? DurationSeconds { get; set; }
}
}
diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/FinalStatusBuilder.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/FinalStatusBuilder.cs
index 6f76262d..4815ad0b 100644
--- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/FinalStatusBuilder.cs
+++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/FinalStatusBuilder.cs
@@ -28,12 +28,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination
DecisionState state,
EnrollmentTerminatedEventArgs terminated,
AppPackageStateList? packageStates,
- DateTime agentStartTimeUtc)
+ DateTime agentStartTimeUtc,
+ IReadOnlyDictionary? appTimings = null)
{
if (state == null) throw new ArgumentNullException(nameof(state));
if (terminated == null) throw new ArgumentNullException(nameof(terminated));
var uptimeSeconds = Math.Max(0, (terminated.TerminatedAtUtc - agentStartTimeUtc).TotalSeconds);
+ var timings = appTimings ?? new Dictionary();
var status = new FinalStatus
{
@@ -45,7 +47,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination
AgentUptimeSeconds = uptimeSeconds,
SignalsSeen = BuildSignalsSeen(state),
AppSummary = BuildAppSummary(packageStates),
- PackageStatesByPhase = BuildPackageStatesByPhase(packageStates),
+ PackageStatesByPhase = BuildPackageStatesByPhase(packageStates, timings),
};
return status;
@@ -109,7 +111,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination
}
private static Dictionary> BuildPackageStatesByPhase(
- AppPackageStateList? packageStates)
+ AppPackageStateList? packageStates,
+ IReadOnlyDictionary timings)
{
var result = new Dictionary>();
if (packageStates == null) return result;
@@ -123,6 +126,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination
result[phaseKey] = bucket;
}
+ timings.TryGetValue(pkg.Id, out var timing);
+
bucket.Add(new FinalStatusPackageInfo
{
AppName = string.IsNullOrEmpty(pkg.Name) ? pkg.Id : pkg.Name,
@@ -130,6 +135,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination
IsError = pkg.InstallationState == AppInstallationState.Error,
IsCompleted = IsCompleted(pkg.InstallationState),
Targeted = pkg.Targeted.ToString(),
+ StartedAt = timing?.StartedAtUtc?.ToString("o"),
+ CompletedAt = timing?.CompletedAtUtc?.ToString("o"),
+ DurationSeconds = timing?.DurationSeconds,
});
}
diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Transport/Telemetry/BackendTelemetryUploader.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Transport/Telemetry/BackendTelemetryUploader.cs
index d3a60e52..732a4220 100644
--- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Transport/Telemetry/BackendTelemetryUploader.cs
+++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Transport/Telemetry/BackendTelemetryUploader.cs
@@ -48,6 +48,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Transport.Telemetry
private readonly string? _bootstrapToken;
private readonly string? _agentVersion;
private readonly AuthFailureTracker? _authFailureTracker;
+ private readonly Logging.AgentLogger? _logger;
public BackendTelemetryUploader(
HttpClient httpClient,
@@ -58,7 +59,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Transport.Telemetry
string? serialNumber = null,
string? bootstrapToken = null,
string? agentVersion = null,
- AuthFailureTracker? authFailureTracker = null)
+ AuthFailureTracker? authFailureTracker = null,
+ Logging.AgentLogger? logger = null)
{
_httpClient = httpClient ?? throw new ArgumentNullException(nameof(httpClient));
if (string.IsNullOrEmpty(baseUrl)) throw new ArgumentException("BaseUrl is mandatory.", nameof(baseUrl));
@@ -72,6 +74,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Transport.Telemetry
_bootstrapToken = bootstrapToken;
_agentVersion = agentVersion;
_authFailureTracker = authFailureTracker;
+ _logger = logger;
}
public async Task UploadBatchAsync(
@@ -91,6 +94,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Transport.Telemetry
// MtlsHttpClientFactory — we only need to compress outbound here.
var body = SerializeBatch(items);
var compressedBody = CompressWithGzip(body);
+
+ // Plan §5 Fix 5 — upload-cadence logging. First line users see when diagnosing
+ // "why didn't my event arrive" — records batch size + sent-bytes pre-response.
+ _logger?.Info(
+ $"BackendTelemetryUploader: flushing {items.Count} item(s) (bytes={compressedBody.Length}, firstId={items[0].TelemetryItemId}, lastId={items[items.Count - 1].TelemetryItemId}).");
+ var sw = System.Diagnostics.Stopwatch.StartNew();
+
using (var request = new HttpRequestMessage(HttpMethod.Post, _endpointUrl))
{
request.Content = new ByteArrayContent(compressedBody);
@@ -111,19 +121,39 @@ namespace AutopilotMonitor.Agent.V2.Core.Transport.Telemetry
}
catch (TaskCanceledException ex)
{
+ sw.Stop();
+ _logger?.Warning($"BackendTelemetryUploader: ingest TIMEOUT after {sw.ElapsedMilliseconds}ms (items={items.Count}): {ex.Message}");
// HttpClient timeout (not caller cancellation) surfaces as TaskCanceledException
// with cancellationToken.IsCancellationRequested == false.
return UploadResult.Transient($"timeout: {ex.Message}");
}
catch (HttpRequestException ex)
{
+ sw.Stop();
+ _logger?.Warning($"BackendTelemetryUploader: ingest NETWORK fail after {sw.ElapsedMilliseconds}ms (items={items.Count}): {ex.Message}");
// DNS failure, socket error, etc. — network-layer is retryable.
return UploadResult.Transient($"network: {ex.Message}");
}
using (response)
{
- return await MapResponseAsync(response).ConfigureAwait(false);
+ var result = await MapResponseAsync(response).ConfigureAwait(false);
+ sw.Stop();
+
+ if (result.Success)
+ {
+ _logger?.Info($"BackendTelemetryUploader: ingest OK (items={items.Count}, durationMs={sw.ElapsedMilliseconds}, status={(int)response.StatusCode}).");
+ }
+ else if (result.IsTransient)
+ {
+ _logger?.Warning($"BackendTelemetryUploader: ingest TRANSIENT (items={items.Count}, durationMs={sw.ElapsedMilliseconds}, status={(int)response.StatusCode}): {result.ErrorReason}");
+ }
+ else
+ {
+ _logger?.Error($"BackendTelemetryUploader: ingest PERMANENT fail (items={items.Count}, durationMs={sw.ElapsedMilliseconds}, status={(int)response.StatusCode}): {result.ErrorReason}");
+ }
+
+ return result;
}
}
}
diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Transport/Telemetry/TelemetrySpool.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Transport/Telemetry/TelemetrySpool.cs
index dbc90b7b..c3f3dbf6 100644
--- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Transport/Telemetry/TelemetrySpool.cs
+++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Transport/Telemetry/TelemetrySpool.cs
@@ -28,12 +28,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Transport.Telemetry
private readonly string _spoolPath;
private readonly UploadCursorPersistence _cursor;
private readonly IClock _clock;
+ private readonly Logging.AgentLogger? _logger;
private readonly object _lock = new object();
private long _lastAssignedItemId = -1;
private long _lastUploadedItemId = -1;
- public TelemetrySpool(string directoryPath, IClock clock)
+ public TelemetrySpool(string directoryPath, IClock clock, Logging.AgentLogger? logger = null)
{
if (string.IsNullOrEmpty(directoryPath))
{
@@ -41,6 +42,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Transport.Telemetry
}
_clock = clock ?? throw new ArgumentNullException(nameof(clock));
+ _logger = logger;
if (!Directory.Exists(directoryPath))
{
@@ -99,6 +101,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Transport.Telemetry
}
_lastAssignedItemId = itemId;
+ // Plan §5 Fix 5 — spool-cadence logging (DEBUG to avoid noise under heavy
+ // event flows; users can enable at troubleshoot-time).
+ _logger?.Debug(
+ $"TelemetrySpool: enqueued itemId={itemId} kind={item.Kind} immediate={item.RequiresImmediateFlush} pending={itemId - _lastUploadedItemId}.");
return item;
}
}
diff --git a/src/Agent/AutopilotMonitor.Agent.V2/Program.cs b/src/Agent/AutopilotMonitor.Agent.V2/Program.cs
index 1a8c2666..54d1e5d5 100644
--- a/src/Agent/AutopilotMonitor.Agent.V2/Program.cs
+++ b/src/Agent/AutopilotMonitor.Agent.V2/Program.cs
@@ -423,7 +423,8 @@ namespace AutopilotMonitor.Agent.V2
serialNumber: hardwareForReporters.SerialNumber,
bootstrapToken: agentConfig.UseBootstrapTokenAuth ? agentConfig.BootstrapToken : null,
agentVersion: GetAgentVersion(),
- authFailureTracker: authFailureTracker);
+ authFailureTracker: authFailureTracker,
+ logger: logger); // Plan §5 Fix 5 — upload-cadence logging
}
catch (Exception ex)
{
@@ -702,7 +703,10 @@ namespace AutopilotMonitor.Agent.V2
signalShutdown: () => shutdown.Set(),
analyzerManager: analyzerManager,
post: lifecyclePost,
- sessionPersistence: sessionPersistence);
+ sessionPersistence: sessionPersistence,
+ // Plan §5 Fix 4 — per-app timing snapshot for FinalStatusBuilder +
+ // app_tracking_summary emission. Null-safe via the handler's default.
+ appTimingsAccessor: () => componentFactory.ImeAppTimings);
// Single-rail refactor (plan §5.3) — ServerActionDispatcher emits through
// the same InformationalEventPost. Constructed inside this hook so
diff --git a/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt b/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt
index 7f05eede..9183bf03 100644
--- a/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt
+++ b/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt
@@ -1 +1 @@
-244
+256
diff --git a/src/Agent/AutopilotMonitor.Agent/buildcounter.txt b/src/Agent/AutopilotMonitor.Agent/buildcounter.txt
index 1b6d75c8..48728527 100644
--- a/src/Agent/AutopilotMonitor.Agent/buildcounter.txt
+++ b/src/Agent/AutopilotMonitor.Agent/buildcounter.txt
@@ -1 +1 @@
-1115
+1119
diff --git a/src/Shared/AutopilotMonitor.Shared/Constants.cs b/src/Shared/AutopilotMonitor.Shared/Constants.cs
index 7876bb87..61caa862 100644
--- a/src/Shared/AutopilotMonitor.Shared/Constants.cs
+++ b/src/Shared/AutopilotMonitor.Shared/Constants.cs
@@ -217,6 +217,7 @@ namespace AutopilotMonitor.Shared
public const string ImeUserSessionCompleted = "ime_user_session_completed";
public const string DoTelemetry = "do_telemetry";
public const string AllAppsCompleted = "all_apps_completed";
+ public const string AppTrackingSummary = "app_tracking_summary"; // Plan §5 Fix 4b — terminal per-session app summary
// Stall detection (Ebene 2 — StallProbeCollector)
public const string StallProbeCheck = "stall_probe_check"; // Trace heartbeat from Probe 2 (15 min) when no anomaly found