mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-24 12:42:38 +00:00
fix(v2): 882fef64 PR3 — kernel-path observability (A2 + A3 + D1-D5)
Session 882fef64's 12-min agent log carried only `EnrollmentOrchestrator: started.`
and `decision terminal stage reached` between the first event and termination — no
stage-transition trail, no signal cadence, no effect failures. PR3 wires logging
into the kernel hot path so every Decision-Stage transition, every signal accept/
reject, every effect retry/critical-failure, and every IME app state change leaves
a trace at the right severity.
A2 — noise reduction:
- TelemetrySpool `enqueued itemId=...` DEBUG -> VERBOSE (600+ lines/session before)
- IME `impersonation` lines deduplicated by user with 60s rollup
A3 — strengthened existing weak lines:
- `Command line:` shows `(no args)` instead of empty
- `Process exit code: 0` -> `Process completed: <name> -> exit=N, durationMs=T`
- IME session change now carries sessionId+user
- HelloTracker 358/360 suppression includes eventTime+provider
- EnrollmentOrchestrator started/stopping carry sessionId/stage/hosts/signals
D1-D5 — observability into the silent kernel components:
- DecisionStepProcessor: per-step DEBUG (stage transitions + effects) + VERBOSE for no-ops
- SignalIngress: 5 strategic log lines (drop, append-fail, worker-fault, stop summary, processed)
- EffectRunner: 5 strategic log lines (retry, exhausted, critical, anti-loop, classifier throw)
- ImeLogTrackerAdapter: 7 emit-site log lines covering all 7 emission paths
- InformationalEventPost: per-emit DEBUG with eventType/source/immediate/severity/dataKeys
All log statements are null-safe (_logger?.Debug); legacy unit-test rigs without a
logger keep working. New ctor overloads on InformationalEventPost / SignalIngress /
EffectRunner / ImeLogTrackerAdapter are backwards-compatible (logger param defaults
null).
Side fix: BinaryIntegrityVerifierTests pinned to [Collection("SerialThreading")].
Process-global `_runtimeSelfUpdateFired` static raced with parallel mismatch tests;
PR3's logging shifted thread timing enough to surface the race consistently.
Tests: V2.Core 727, DecisionCore 231, Functions 736, vitest 179, solution build 0/0.
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
Oliver Kieselbach
+6
@@ -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)
|
||||
|
||||
+34
@@ -18,6 +18,40 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// </summary>
|
||||
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
|
||||
|
||||
+13
-2
@@ -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":
|
||||
|
||||
+9
-2
@@ -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
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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);
|
||||
|
||||
@@ -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<TimeSpan> _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<TimeSpan>? retryBackoffs = null)
|
||||
IReadOnlyList<TimeSpan>? 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<EffectRunResult> 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)
|
||||
|
||||
@@ -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}).");
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -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; }
|
||||
|
||||
@@ -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;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -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}]");
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
|
||||
@@ -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<IngressItem> _channel;
|
||||
private readonly Dictionary<string, DateTime> _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<IngressItem>(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
|
||||
|
||||
@@ -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<string> _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<string>? whiteGloveSealingPatternIds = null)
|
||||
IReadOnlyCollection<string>? 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<string>(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}");
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -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) =>
|
||||
|
||||
@@ -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}.");
|
||||
}
|
||||
|
||||
|
||||
@@ -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;
|
||||
}
|
||||
}
|
||||
|
||||
@@ -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);
|
||||
|
||||
@@ -1 +1 @@
|
||||
336
|
||||
338
|
||||
|
||||
@@ -1 +1 @@
|
||||
1163
|
||||
1164
|
||||
|
||||
Reference in New Issue
Block a user