diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Security/BinaryIntegrityVerifierTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Security/BinaryIntegrityVerifierTests.cs index 4a958c72..16ff701c 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Security/BinaryIntegrityVerifierTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Security/BinaryIntegrityVerifierTests.cs @@ -9,6 +9,12 @@ using Xunit; namespace AutopilotMonitor.Agent.V2.Core.Tests.Security { + // PR3 (882fef64 debrief): BinaryIntegrityVerifier holds a process-global static + // `_runtimeSelfUpdateFired` flag. The single-shot guarantee inside + // `Check_mismatch_fires_runtime_self_update_trigger_exactly_once` races with parallel + // tests that may also call Check() with a mismatch and pre-set the flag. Pin to the + // existing serial collection so mismatch-tests don't interleave across classes. + [Collection("SerialThreading")] public sealed class BinaryIntegrityVerifierTests { private static AgentLogger NewLogger(TempDirectory tmp) diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs index 677704f4..b856ede0 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs @@ -18,6 +18,40 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime /// public partial class ImeLogTracker { + // PR3-A2: dedup state for `IME impersonation` lines. ~24 identical per session at + // DEBUG flooded the log; we now emit on user change + a 60s rollup with the count. + private string _lastImpersonationUser; + private int _impersonationRepeatCount; + private DateTime _impersonationLastRollupUtc = DateTime.MinValue; + private static readonly TimeSpan ImpersonationRollupInterval = TimeSpan.FromSeconds(60); + + private void HandleImeImpersonation(string user) + { + var current = string.IsNullOrEmpty(user) ? "(unknown)" : user; + + if (!string.Equals(current, _lastImpersonationUser, StringComparison.Ordinal)) + { + if (_impersonationRepeatCount > 0) + { + _logger.Debug($"IME impersonation: previous '{_lastImpersonationUser}' seen {_impersonationRepeatCount}x before change"); + } + _logger.Debug($"IME impersonation: {current}"); + _lastImpersonationUser = current; + _impersonationRepeatCount = 0; + _impersonationLastRollupUtc = DateTime.UtcNow; + return; + } + + _impersonationRepeatCount++; + var now = DateTime.UtcNow; + if (now - _impersonationLastRollupUtc >= ImpersonationRollupInterval) + { + _logger.Debug($"IME impersonation: same as before (user='{current}', n={_impersonationRepeatCount} since last rollup)"); + _impersonationLastRollupUtc = now; + _impersonationRepeatCount = 0; + } + } + private void HandleDoTelemetry(string json) { try diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs index ba411a0b..b441baf9 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs @@ -197,7 +197,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime case "imesessionchange": var sessionChange = match.Groups["change"]?.Value; - _logger.Debug($"IME session change: {sessionChange}"); + // PR3-A3: lift sessionId + user from match if the regex captures them, so the + // line carries enough context to correlate without cross-referencing. + var sessionChangeSid = match.Groups["sessionId"]?.Value; + var sessionChangeUser = match.Groups["user"]?.Value; + var sessionChangeContext = (!string.IsNullOrEmpty(sessionChangeSid) || !string.IsNullOrEmpty(sessionChangeUser)) + ? $" (sessionId={sessionChangeSid ?? "?"}, user={sessionChangeUser ?? "?"})" + : string.Empty; + _logger.Debug($"IME session change: {sessionChange}{sessionChangeContext}"); OnImeSessionChange?.Invoke(sessionChange); break; @@ -221,7 +228,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime break; case "imeimpersonation": - _logger.Debug($"IME impersonation: {match.Groups["user"]?.Value}"); + // PR3-A2: dedup. The same user triggers ~24 identical lines per session; + // log on first/changed user, otherwise count and emit a single rollup + // every 60s ("same as before (n=…)") so the log stays readable but the + // sequence stays reconstructible. + HandleImeImpersonation(match.Groups["user"]?.Value); break; case "enrollmentcompleted": diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/HelloTracker.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/HelloTracker.cs index ff47ad10..eeb1571e 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/HelloTracker.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/HelloTracker.cs @@ -491,6 +491,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals } } + // PR3-A3: when 358/360 are suppressed below, include eventTime + provider so log readers + // can still tell which exact occurrence was dropped without cross-referencing the eventlog. + private void LogSuppressedSnapshotEvent(int eventId, DateTime timestamp, string providerName, string label) + { + _logger.Debug($"Hello EventID {eventId} ({label}) observed — snapshot only, suppressed (eventTime={timestamp:O}, provider={providerName ?? "(unknown)"})"); + } + internal void ProcessHelloEvent(int eventId, DateTime timestamp, string providerName, bool isBackfill) { string eventType; @@ -509,7 +516,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals // event only fueled UI-timeline noise. Keep the debug log line so the // sequence is still reconstructible from agent-logs during diagnostics, // but do not emit a backend event. - _logger.Debug("Hello EventID 358 (willlaunch) observed — snapshot only, suppressed"); + LogSuppressedSnapshotEvent(eventId, timestamp, providerName, "willlaunch"); return; case EventId_NgcKeyRegistered: // 300 @@ -531,7 +538,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals case EventId_ProvisioningWillNotLaunch: // 360 // Sibling of 358 — also a snapshot flag. DecisionEngine does not treat it // as terminal either, so suppress for the same noise-reduction reason. - _logger.Debug("Hello EventID 360 (willnotlaunch) observed — snapshot only, suppressed"); + LogSuppressedSnapshotEvent(eventId, timestamp, providerName, "willnotlaunch"); return; case EventId_ProvisioningBlocked: // 362 diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DecisionStepProcessor.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DecisionStepProcessor.cs index 6c5e1c6c..20a06a00 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DecisionStepProcessor.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DecisionStepProcessor.cs @@ -1,5 +1,6 @@ #nullable enable using System; +using System.Linq; using System.Threading; using AutopilotMonitor.Agent.V2.Core.Logging; using AutopilotMonitor.Agent.V2.Core.Persistence; @@ -103,6 +104,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration if (step == null) throw new ArgumentNullException(nameof(step)); if (signal == null) throw new ArgumentNullException(nameof(signal)); + // PR3-D1: capture pre-step stage so the post-step log line can show the transition. + var previousStage = _currentState.Stage; + // 1) Journal-Append — einziger Fehler-Pfad der hart wirft + Quarantine eskaliert. try { @@ -200,6 +204,23 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration _currentState = step.NewState; _consecutiveJournalFailures = 0; + // PR3-D1: per-step observability. Stage transitions and effect-bearing steps fire + // at DEBUG (operator-relevant); pure no-op steps (Stage unchanged + no effects) + // fire at VERBOSE so a steady stream of e.g. ClassifierTick + InformationalEvent + // pass-throughs doesn't drown the log. + var newStage = step.NewState.Stage; + if (previousStage != newStage || step.Effects.Count > 0) + { + _logger.Debug( + $"DecisionStep: ord={signal.SessionSignalOrdinal} kind={signal.Kind} " + + $"stage={previousStage}->{newStage} effects=[{string.Join(",", step.Effects.Select(e => e.Kind))}] " + + $"abort={effectResult.SessionMustAbort} failures={effectResult.Failures.Count}"); + } + else + { + _logger.Verbose($"DecisionStep: ord={signal.SessionSignalOrdinal} kind={signal.Kind} stage={previousStage} (no-op)"); + } + // 5) Terminal-stage detection (M4.6.β). Fires exactly once per agent run when the // DecisionEngine transitions the session into a terminal SessionStage — the // orchestrator turns this into the public EnrollmentTerminated event so peripheral diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs index 13183908..f6ce0d45 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs @@ -583,7 +583,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration logger.Info($"ImeLogHost: SimulationMode ENABLED (speedFactor={simulationSpeedFactor}, path={logFolder})"); } - _adapter = new ImeLogTrackerAdapter(_tracker, ingress, clock, whiteGloveSealingPatternIds); + _adapter = new ImeLogTrackerAdapter(_tracker, ingress, clock, whiteGloveSealingPatternIds, logger); var processWatcherPost = new InformationalEventPost(ingress, clock); _processWatcher = new ImeProcessWatcher(sessionId, tenantId, processWatcherPost, logger); diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EffectRunner.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EffectRunner.cs index 7664e6eb..e09e9f63 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EffectRunner.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EffectRunner.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Generic; using System.Threading; using System.Threading.Tasks; +using AutopilotMonitor.Agent.V2.Core.Logging; using AutopilotMonitor.Agent.V2.Core.Persistence; using AutopilotMonitor.DecisionCore.Classifiers; using AutopilotMonitor.DecisionCore.Engine; @@ -35,6 +36,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration private readonly ISnapshotPersistence _snapshot; private readonly IClock _clock; private readonly IReadOnlyList _retryBackoffs; + // PR3-D3: optional logger so transient retries, exhausted retries, critical failures, + // anti-loop skips, and classifier exceptions are visible. Null in legacy unit tests. + private readonly AgentLogger? _logger; public EffectRunner( IDeadlineScheduler scheduler, @@ -43,7 +47,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration IEventTimelineEmitter emitter, ISnapshotPersistence snapshot, IClock clock, - IReadOnlyList? retryBackoffs = null) + IReadOnlyList? retryBackoffs = null, + AgentLogger? logger = null) { _scheduler = scheduler ?? throw new ArgumentNullException(nameof(scheduler)); _classifiers = classifiers ?? throw new ArgumentNullException(nameof(classifiers)); @@ -52,6 +57,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration _snapshot = snapshot ?? throw new ArgumentNullException(nameof(snapshot)); _clock = clock ?? throw new ArgumentNullException(nameof(clock)); _retryBackoffs = retryBackoffs ?? DefaultRetryBackoffs; + _logger = logger; } public async Task RunAsync( @@ -155,6 +161,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration } catch (Exception ex) { + _logger?.Warning( + $"EffectRunner: CRITICAL effect {effect.Kind} failed — session must abort: {ex.GetType().Name}: {ex.Message}"); return new EffectFailure( effectKind: effect.Kind, errorReason: $"{ex.GetType().Name}: {ex.Message}", @@ -198,6 +206,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration !string.IsNullOrEmpty(lastVerdictId) && snapshotHash == lastVerdictId) { + _logger?.Debug( + $"EffectRunner: classifier {effect.ClassifierId} skipped (snapshotHash unchanged: {ShortHash(snapshotHash)})"); return new ClassifierEffectOutcome(invoked: false, skippedByAntiLoop: true, failure: null); } @@ -209,6 +219,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration catch (Exception ex) { // Optional-class failure: emit an Inconclusive verdict instead of aborting. + _logger?.Warning( + $"EffectRunner: classifier {effect.ClassifierId} threw -> emitting Inconclusive: {ex.GetType().Name}: {ex.Message}"); var inconclusive = new ClassifierVerdict( classifierId: effect.ClassifierId!, level: HypothesisLevel.Inconclusive, @@ -272,11 +284,17 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration lastErr = $"{ex.GetType().Name}: {ex.Message}"; if (attempt < _retryBackoffs.Count) { - await _clock.Delay(_retryBackoffs[attempt], cancellationToken).ConfigureAwait(false); + var backoff = _retryBackoffs[attempt]; + _logger?.Debug( + $"EffectRunner: effect {effect.Kind} attempt {attempt + 1}/{_retryBackoffs.Count + 1} failed -> retry in {backoff.TotalMilliseconds:F0}ms: {lastErr}"); + await _clock.Delay(backoff, cancellationToken).ConfigureAwait(false); } } } + _logger?.Warning( + $"EffectRunner: TRANSIENT effect {effect.Kind} exhausted after {_retryBackoffs.Count + 1} attempts: {lastErr ?? "unknown transient error"}"); + failures.Add(new EffectFailure( effect.Kind, lastErr ?? "unknown transient error", @@ -284,6 +302,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration exhaustedRetries: true)); } + // PR3-D3: short hash for log readability — full SHA in the verdict already. + private static string ShortHash(string h) => string.IsNullOrEmpty(h) ? "(empty)" : (h.Length <= 8 ? h : h.Substring(0, 8)); + private readonly struct ClassifierEffectOutcome { public ClassifierEffectOutcome(bool invoked, bool skippedByAntiLoop, EffectFailure? failure) diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs index 36309253..c0d17ddf 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs @@ -482,7 +482,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration ingress: _sinkRelay, emitter: _timelineEmitter, snapshot: _snapshot, - clock: _clock); + clock: _clock, + logger: _logger); // 8) Processor — owns the initial state + journal + snapshot + quarantine hook + // M4.6.β terminal-stage hook (fires Terminated event when the engine reaches a @@ -522,7 +523,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration clock: _clock, backPressureObserver: _backPressureObserver, signalEmitter: _signalEmitter, - channelCapacity: _channelCapacity); + channelCapacity: _channelCapacity, + logger: _logger); // 11) Relay auf den echten Ingress umbiegen. _sinkRelay.Target = _ingress; @@ -695,7 +697,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration _logger.Info($"EnrollmentOrchestrator: max-lifetime watchdog armed ({_agentMaxLifetime.Value.TotalMinutes:F0}min)."); } - _logger.Info("EnrollmentOrchestrator: started."); + // PR3-A3: previous "started." line had zero context. Add the cardinality info that + // tells a forensic reader what the orchestrator is actually running (initial stage, + // collector-host count, short session id) and how long max-lifetime is set for. + var sessionShort = _sessionId != null && _sessionId.Length >= 8 ? _sessionId.Substring(0, 8) : (_sessionId ?? string.Empty); + var initialStage = CurrentState?.Stage.ToString() ?? "Unknown"; + var hostCount = _collectorHosts?.Count ?? 0; + var maxLifetimeMin = _agentMaxLifetime.HasValue ? _agentMaxLifetime.Value.TotalMinutes.ToString("F0") + "min" : "off"; + _logger.Info($"EnrollmentOrchestrator: started (sessionId={sessionShort}, initialStage={initialStage}, hosts={hostCount}, maxLifetime={maxLifetimeMin})."); } /// @@ -840,7 +849,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration if (Volatile.Read(ref _started) == 0) return; if (Interlocked.Exchange(ref _stopRequested, 1) == 1) return; - _logger.Info("EnrollmentOrchestrator: stopping."); + // PR3-A3: include current stage + observed signal count so forensic readers can see + // what the orchestrator was working on at stop time. + var stopStage = CurrentState?.Stage.ToString() ?? "Unknown"; + var stopSignalsApplied = CurrentState?.LastAppliedSignalOrdinal ?? -1; + _logger.Info($"EnrollmentOrchestrator: stopping (currentStage={stopStage}, signalsApplied={stopSignalsApplied + 1})."); // -1) Max-lifetime watchdog stoppen (M4.6.α). Idempotent — safe even if never armed. try { _maxLifetimeTimer?.Dispose(); _maxLifetimeTimer = null; } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/InformationalEventPost.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/InformationalEventPost.cs index 9294d4ee..b07dea44 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/InformationalEventPost.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/InformationalEventPost.cs @@ -1,6 +1,8 @@ #nullable enable using System; using System.Collections.Generic; +using System.Linq; +using AutopilotMonitor.Agent.V2.Core.Logging; using AutopilotMonitor.DecisionCore.Engine; using AutopilotMonitor.DecisionCore.Signals; using AutopilotMonitor.Shared.Models; @@ -42,11 +44,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration private readonly ISignalIngressSink _ingress; private readonly IClock _clock; + // PR3-D5: optional logger so every lifecycle event passing through the single rail + // shows up in the agent log with eventType + source + immediate-flag. Null in legacy + // unit tests; production wires the agent logger via the new ctor overload below. + private readonly AgentLogger? _logger; public InformationalEventPost(ISignalIngressSink ingress, IClock clock) + : this(ingress, clock, logger: null) + { + } + + public InformationalEventPost(ISignalIngressSink ingress, IClock clock, AgentLogger? logger) { _ingress = ingress ?? throw new ArgumentNullException(nameof(ingress)); _clock = clock ?? throw new ArgumentNullException(nameof(clock)); + _logger = logger; } /// @@ -129,6 +141,18 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration evidence: evidence, payload: payload, typedPayload: typedPayload); + + // PR3-D5: lifecycle-event observability — DEBUG so it doesn't dominate at INFO, + // but every event that hits the timeline has a matching agent-log line. First + // 8 payload keys are usually enough to identify the event variant. + if (_logger != null) + { + var keys = string.Join(",", payload.Keys.Take(8)); + _logger.Debug( + $"InformationalEventPost: emit eventType={eventType} source={source} " + + $"immediate={immediateUpload} severity={severity?.ToString() ?? "default"} " + + $"dataKeys=[{keys}]"); + } } /// diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/SignalIngress.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/SignalIngress.cs index 7dba70bd..ee2875de 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/SignalIngress.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/SignalIngress.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Concurrent; using System.Collections.Generic; using System.Threading; +using AutopilotMonitor.Agent.V2.Core.Logging; using AutopilotMonitor.Agent.V2.Core.Persistence; using AutopilotMonitor.Agent.V2.Core.Telemetry.Signals; using AutopilotMonitor.DecisionCore.Engine; @@ -48,6 +49,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration private readonly IClock _clock; private readonly TimeSpan _backPressureThrottle; private readonly int _channelCapacity; + // PR3-D2: optional logger so production wiring gets observability into the previously + // silent paths (SignalLog append failures, DecisionSignal ctor rejections, worker + // faults). Null in unit-test rigs that don't care. + private readonly AgentLogger? _logger; + private long _processedCount; + private long _stopRequestedAtTicks; private readonly BlockingCollection _channel; private readonly Dictionary _lastBackPressureEmittedUtc = @@ -69,7 +76,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration IBackPressureObserver? backPressureObserver = null, TelemetrySignalEmitter? signalEmitter = null, int channelCapacity = DefaultChannelCapacity, - TimeSpan? backPressureThrottle = null) + TimeSpan? backPressureThrottle = null, + AgentLogger? logger = null) { if (channelCapacity <= 0) { @@ -85,6 +93,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration _signalEmitter = signalEmitter; _channelCapacity = channelCapacity; _backPressureThrottle = backPressureThrottle ?? DefaultBackPressureThrottle; + _logger = logger; _channel = new BlockingCollection(boundedCapacity: channelCapacity); _nextSignalOrdinal = signalLog.LastOrdinal + 1; @@ -143,6 +152,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration return; } + var stopStartUtc = _clock.UtcNow; + Interlocked.Exchange(ref _stopRequestedAtTicks, stopStartUtc.Ticks); + var pendingAtStop = _channel.Count; + // CompleteAdding unblockt GetConsumingEnumerable sobald die Queue leer ist. _channel.CompleteAdding(); @@ -152,6 +165,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration worker.Join(); } + // PR3-D2: lifecycle marker so forensic readers see how many items remained queued + // and how long the drain took. Worker fault is logged here (not just thrown) so a + // crash dump catches the message before the exception unwinds. + var drainMs = (long)(_clock.UtcNow - stopStartUtc).TotalMilliseconds; + var lastOrd = LastAssignedSignalOrdinal; + var processedTotal = Interlocked.Read(ref _processedCount); + _logger?.Info($"SignalIngress: stop requested — drained pending={pendingAtStop} items, processedTotal={processedTotal}, lastOrd={lastOrd}, durationMs={drainMs}."); + if (_workerFault != null) { throw new InvalidOperationException( @@ -279,9 +300,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration } catch (Exception ex) { - // Darf nicht passieren — ProcessItem fängt alles ab. Falls doch, für Stop() - // aufheben, damit die Regression sichtbar ist. + // PR3-D2: this branch should never fire — ProcessItem swallows everything. If it + // does, the worker is now stopped and no further signals will be processed. + // Surface that catastrophe explicitly so the agent log shows it before the next + // Post() throws "ingress has been stopped". _workerFault = ex; + _logger?.Error("SignalIngress.Worker faulted unexpectedly — ingress STOPPED. No further signals will be processed.", ex); } } @@ -305,10 +329,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration payload: item.Payload, typedPayload: item.TypedPayload); } - catch + catch (Exception ex) { // DecisionSignal-Ctor validiert Pflichtfelder. Invalid input → überspringen, // Ordinal NICHT verbrauchen (sonst entsteht eine Lücke im SignalLog). + _logger?.Warning( + $"SignalIngress: dropped invalid signal kind={item.Kind} origin={item.SourceOrigin} " + + $"— DecisionSignal ctor threw, ordinal NOT consumed: {ex.Message}"); return; } @@ -316,16 +343,25 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration { _signalLog.Append(signal); } - catch + catch (Exception ex) { // Append fehlgeschlagen (z.B. Disk-Full). Ohne on-disk-Persistenz darf der // Reducer nicht laufen (L.1 Signal-Log-Determinismus). Ordinal bleibt „geplant", // wird beim nächsten Versuch neu vergeben — monoton, da _nextSignalOrdinal // noch nicht inkrementiert wurde. + _logger?.Error( + $"SignalIngress: SignalLog.Append failed for ord={signalOrdinal} kind={item.Kind} " + + $"— ordinal will be re-attempted on next post: {ex.Message}", + ex); return; } _nextSignalOrdinal = signalOrdinal + 1; + // PR3-D2: 1:1 correlation marker for D1 (DecisionStepProcessor logs the same ord + + // kind on the receive side). Verbose because the steady-state happy-path is the + // dominant cardinality. + _logger?.Verbose($"SignalIngress: processed ord={signalOrdinal} kind={item.Kind} origin={item.SourceOrigin}."); + Interlocked.Increment(ref _processedCount); // Project the signal onto the telemetry transport for backend upload. Local // SignalLog is authoritative (§2.7c / L.1); a transport enqueue failure must NOT diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs index 727077af..2506e35c 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs @@ -1,6 +1,7 @@ #nullable enable using System; using System.Collections.Generic; +using AutopilotMonitor.Agent.V2.Core.Logging; using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime; using AutopilotMonitor.Agent.V2.Core.Orchestration; using AutopilotMonitor.DecisionCore.Engine; @@ -57,6 +58,9 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters private readonly InformationalEventPost _post; private readonly HashSet _whiteGloveSealingPatternIds; private readonly object _lock = new object(); + // PR3-D4: optional logger so the largest signal adapter (777 LOC, 0 logger calls + // before this PR) gets DEBUG-level visibility into emissions. Null in legacy tests. + private readonly AgentLogger? _logger; // Previous action-handlers — restored on Dispose so we don't leave a dead callback // hanging on the tracker. @@ -100,12 +104,14 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters ImeLogTracker tracker, ISignalIngressSink ingress, IClock clock, - IReadOnlyCollection? whiteGloveSealingPatternIds = null) + IReadOnlyCollection? whiteGloveSealingPatternIds = null, + AgentLogger? logger = null) { _tracker = tracker ?? throw new ArgumentNullException(nameof(tracker)); _ingress = ingress ?? throw new ArgumentNullException(nameof(ingress)); _clock = clock ?? throw new ArgumentNullException(nameof(clock)); _post = new InformationalEventPost(ingress, clock); + _logger = logger; _whiteGloveSealingPatternIds = whiteGloveSealingPatternIds == null ? new HashSet(StringComparer.Ordinal) @@ -267,6 +273,9 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters phase: mappedPhase == EnrollmentPhase.Unknown ? (EnrollmentPhase?)null : mappedPhase, data: data, occurredAtUtc: now); + + // PR3-D4: phase emissions are decision-relevant — operators want to see them. + _logger?.Debug($"ImeAdapter: EspPhase '{phase}' posted (mappedTo={mappedPhase}, patternId={patternId ?? "(none)"})"); } private void EmitUserSessionCompleted() @@ -306,6 +315,9 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters message: "IME user session completed", data: data, occurredAtUtc: now); + + // PR3-D4: terminal-ish lifecycle marker — INFO so it's visible at the default level. + _logger?.Info($"ImeAdapter: user session completed -> posting ImeUserSessionCompleted (patternId={patternId ?? "(none)"})"); } private void EmitAppState(AppPackageState app, AppInstallationState oldState, AppInstallationState newState) @@ -376,6 +388,13 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters immediateUpload: true, data: BuildAppStatePayload(app, newState, timing), occurredAtUtc: now); + + // PR3-D4: app state transitions are the heaviest cardinality observability target — + // a forensic reader needs (oldState->newState, terminal flag, sub-phase emit) to + // reconstruct why the UI shows what it shows. + var shortId = (app.Id != null && app.Id.Length >= 8) ? app.Id.Substring(0, 8) : (app.Id ?? "?"); + _logger?.Debug( + $"ImeAdapter: app '{app.Name ?? "?"}' ({shortId}) {oldState}->{newState} appType={app.AppType ?? "?"} bytesTotal={app.BytesTotal} terminal={(terminalKind != null)} eventType={eventType}"); } /// @@ -511,6 +530,9 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters { [SignalPayloadKeys.ImePatternId] = patternId, }); + + // PR3-D4: WG Part-1 boundary — INFO-level lifecycle marker, fires at most once. + _logger?.Info($"ImeAdapter: WG sealing pattern '{patternId}' detected -> posting WhiteGloveSealingPatternDetected (Part-1 boundary)"); } private void EmitImeAgentVersion(string version) @@ -531,6 +553,9 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters message: $"IME Agent version: {version}", data: data, occurredAtUtc: _clock.UtcNow); + + // PR3-D4: fire-once and useful for compatibility-debugging — INFO level. + _logger?.Info($"ImeAdapter: IME agent version detected: {version}"); } private void EmitDoTelemetry(AppPackageState app) @@ -578,6 +603,10 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters immediateUpload: true, data: data, occurredAtUtc: _clock.UtcNow); + + // PR3-D4: per-app DO summary at DEBUG with the headline metrics. + _logger?.Debug( + $"ImeAdapter: DO telemetry app='{app.Name ?? "?"}' total={app.DoFileSize} peers={app.DoBytesFromPeers} http={app.DoBytesFromHttp} mode={app.DoDownloadMode}"); } private void EmitScriptCompleted(ScriptExecutionState script) @@ -630,6 +659,11 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters severity: severity, data: data, occurredAtUtc: _clock.UtcNow); + + // PR3-D4: per-script summary at DEBUG (failures already surface via Severity=Error + // in the event itself; the log line carries forensic context for both outcomes). + _logger?.Debug( + $"ImeAdapter: script completed policyId={shortId} type={script.ScriptType ?? "?"} result={script.Result ?? "?"} exit={(script.ExitCode.HasValue ? script.ExitCode.Value.ToString() : "n/a")}"); } private static bool IsRemediation(string? scriptType) => 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 f8a7b685..141a619b 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Transport/Telemetry/TelemetrySpool.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Transport/Telemetry/TelemetrySpool.cs @@ -104,9 +104,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( + // Plan §5 Fix 5 — spool-cadence logging. PR3-A2: VERBOSE (was DEBUG) + // because per-item logging hits ~600 lines per session and floods the log + // at troubleshoot level. Activate only at micro-repro level. + _logger?.Verbose( $"TelemetrySpool: enqueued itemId={itemId} kind={item.Kind} immediate={item.RequiresImmediateFlush} pending={itemId - _lastUploadedItemId}."); } diff --git a/src/Agent/AutopilotMonitor.Agent.V2/Program.InstallMode.cs b/src/Agent/AutopilotMonitor.Agent.V2/Program.InstallMode.cs index 0d44ca35..81ad0725 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2/Program.InstallMode.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2/Program.InstallMode.cs @@ -181,6 +181,10 @@ namespace AutopilotMonitor.Agent.V2 logger.Info($"Executing: {fileName} {arguments}"); + // PR3-A3: prior `Process exit code: 0` line had no context — here we add the + // process name + duration so log readers can correlate the line with the + // command issued without scrolling back. + var sw = System.Diagnostics.Stopwatch.StartNew(); using (var process = Process.Start(psi)) { if (process == null) @@ -189,11 +193,13 @@ namespace AutopilotMonitor.Agent.V2 var stdout = process.StandardOutput.ReadToEnd(); var stderr = process.StandardError.ReadToEnd(); process.WaitForExit(); + sw.Stop(); if (!string.IsNullOrWhiteSpace(stdout)) logger.Info($"Process output: {stdout.Trim()}"); if (!string.IsNullOrWhiteSpace(stderr)) logger.Warning($"Process error output: {stderr.Trim()}"); - logger.Info($"Process exit code: {process.ExitCode}"); + var processName = System.IO.Path.GetFileName(fileName); + logger.Info($"Process completed: {processName} -> exit={process.ExitCode}, durationMs={sw.ElapsedMilliseconds}"); return process.ExitCode; } } diff --git a/src/Agent/AutopilotMonitor.Agent.V2/Program.cs b/src/Agent/AutopilotMonitor.Agent.V2/Program.cs index 0f0a87ca..ceb86a95 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2/Program.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2/Program.cs @@ -152,7 +152,9 @@ namespace AutopilotMonitor.Agent.V2 var logger = new AgentLogger(logDirectory) { EnableConsoleOutput = consoleMode }; logger.Info($"AutopilotMonitor.Agent.V2 starting (version {GetAgentVersion()})."); - logger.Info($"Command line: {FormatArgsForLog(args)}"); + // PR3-A3: empty args looked broken (`Command line: `). Make the no-args case explicit. + var formattedArgs = FormatArgsForLog(args); + logger.Info($"Command line: {(string.IsNullOrEmpty(formattedArgs) ? "(no args)" : formattedArgs)}"); try { @@ -664,7 +666,7 @@ namespace AutopilotMonitor.Agent.V2 // (plan Parity Issue #1). orchestrator.Start(ingress => { - lifecyclePost = new InformationalEventPost(ingress, SystemClock.Instance); + lifecyclePost = new InformationalEventPost(ingress, SystemClock.Instance, logger); EmitAgentStartedEvent(lifecyclePost, agentConfig, previousExit, logger); EmitVersionCheckEventIfAny(lifecyclePost, agentConfig, logger); EmitUnrestrictedModeAuditIfChanged(lifecyclePost, agentConfig, configMergeResult, logger); diff --git a/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt b/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt index e64f24d5..87537f49 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt +++ b/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt @@ -1 +1 @@ -336 +338 diff --git a/src/Agent/AutopilotMonitor.Agent/buildcounter.txt b/src/Agent/AutopilotMonitor.Agent/buildcounter.txt index 1bb44860..0fabf9ba 100644 --- a/src/Agent/AutopilotMonitor.Agent/buildcounter.txt +++ b/src/Agent/AutopilotMonitor.Agent/buildcounter.txt @@ -1 +1 @@ -1163 +1164