From 8fe75a0f4e7652c8d806e962207cad042acc3bef Mon Sep 17 00:00:00 2001 From: Oliver Kieselbach Date: Fri, 24 Apr 2026 02:24:04 +0200 Subject: [PATCH] =?UTF-8?q?v2=20single-rail=2012:=20first-session-fixes=20?= =?UTF-8?q?PR=204=20=E2=80=94=20data=20completeness=20+=20operability=20(F?= =?UTF-8?q?ixes=204+5)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Closes the "final-status.json shows only 3 apps", "every app ~30 s" and "agent log silent during uploads" gaps observed in session 30410cd7. Fix 4c — Per-app install-lifecycle timing. New AppInstallTiming model (StartedAtUtc / CompletedAtUtc / DurationSeconds). ImeLogTrackerAdapter tracks timing in a set-once dictionary (first Downloading/Installing/ InProgress stamps StartedAt; first terminal stamps CompletedAt) and exposes it via a new public AppTimings snapshot. app_install_* DataJson carries startedAt / completedAt / durationSeconds when known; omitted otherwise so the UI can distinguish "not tracked" from "stamp=epoch". Fix 4a — FinalStatusBuilder uses timings. Optional appTimings param on Build(); FinalStatusPackageInfo gets StartedAt / CompletedAt / DurationSeconds with NullValueHandling.Ignore. Existing per-targeted phase bucketing preserved — that was correct. Fix 4b — app_tracking_summary terminal event. EnrollmentTerminationHandler. EmitAppTrackingSummary runs once at termination before diagnostics upload with aggregate counts, per-phase breakdown, and per-app records (appId/name/phase/finalState/optional timing). ImmediateUpload=true, Phase=Unknown (feedback_phase_strategy). Skipped on WhiteGlove Part 1 (apps haven't installed yet). Fix 5 — Upload-cadence logging. BackendTelemetryUploader + TelemetrySpool gained optional AgentLogger params. Uploader logs INFO flushing/ingest OK, WARN ingest TRANSIENT (5xx/timeout/network), ERROR ingest PERMANENT (4xx), with items + durationMs. Spool logs DEBUG per-enqueue with kind + immediate flag + pending count. Empty-batch path stays silent (short-circuit). Plumbing: ImeLogHost.AppTimings → DefaultComponentFactory.ImeAppTimings → Program.cs wires appTimingsAccessor into EnrollmentTerminationHandler; logger flows into uploader (Program.cs) and spool (EnrollmentOrchestrator). All new ctor params are nullable-default → zero breakage for existing call sites and tests. Tests: +18 new (7 adapter timing, 2 builder timing, 5 handler summary, 4 uploader logging). DecisionCore 139, Agent.V2.Core 630, Functions 727, Web vitest 168 — all green. Web typecheck clean. Solution build 0/0. Co-Authored-By: Claude Opus 4.7 (1M context) --- .../ImeLogTrackerAdapterTimingTests.cs | 188 ++++++++++++++++++ .../EnrollmentTerminationHandlerTests.cs | 141 ++++++++++++- .../Termination/FinalStatusBuilderTests.cs | 68 +++++++ .../BackendTelemetryUploaderLoggingTests.cs | 151 ++++++++++++++ .../Enrollment/Ime/AppInstallTiming.cs | 40 ++++ .../Orchestration/DefaultComponentFactory.cs | 15 ++ .../Orchestration/EnrollmentOrchestrator.cs | 2 +- .../SignalAdapters/ImeLogTrackerAdapter.cs | 91 ++++++++- .../EnrollmentTerminationHandler.cs | 135 ++++++++++++- .../Termination/FinalStatus.cs | 12 ++ .../Termination/FinalStatusBuilder.cs | 14 +- .../Telemetry/BackendTelemetryUploader.cs | 34 +++- .../Transport/Telemetry/TelemetrySpool.cs | 8 +- .../AutopilotMonitor.Agent.V2/Program.cs | 8 +- .../buildcounter.txt | 2 +- .../AutopilotMonitor.Agent/buildcounter.txt | 2 +- .../AutopilotMonitor.Shared/Constants.cs | 1 + 17 files changed, 892 insertions(+), 20 deletions(-) create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterTimingTests.cs create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Transport/BackendTelemetryUploaderLoggingTests.cs create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/AppInstallTiming.cs 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