From a12356e6adb68331a72ee6e2c226534b20a7a5c9 Mon Sep 17 00:00:00 2001 From: fabbrik <22822543+fabbrik@users.noreply.github.com> Date: Tue, 22 Sep 2026 20:17:45 -0300 Subject: [PATCH] Instrument the experience learning loop (story 4.1) Add OpenTelemetry-compatible spans and metrics to the fourteen operations of the experience learning loop, emitted through System.Diagnostics only. The library emits; the host owns exporters. No project gains a PackageReference: ActivitySource and Meter ship in the net10.0 shared framework, so all four exact-pinned dependency-boundary assertions stay byte-identical and OpenTelemetry remains forbidden in Core and Abstractions. Traces carry run, attempt, record, event and feedback identifiers plus the host's correlation id. Metrics carry only bounded dimensions: operation, outcome, error class, and whether the call was nested inside another instrumented operation. Task text, record payload, private reasoning and raw exception messages never reach telemetry on either channel, and a test sweeps every span tag and every measurement for a planted marker to keep that honest. Exception objects are never handed to telemetry. A failing span records the exception's type name and a four-value error class; a driver message that could quote SQL text and parameters is never exported. Instrumentation cannot affect the caller: tagging and metric writes sit outside the guarded region and swallow internally, so a disposed Meter or a throwing listener can never turn a committed lifecycle transition into a reported failure. With no listener registered, operations allocate no Activity and return identical results. A deadline this library imposes classifies as Timeout, not as Cancelled, so a hung embedding provider inside the post-commit indexing hook raises a failure count instead of looking like a caller who asked to stop. Co-Authored-By: Claude Opus 5 (1M context) --- .../InMemoryExperienceCaptureService.cs | 95 +- .../Diagnostics/ExperienceDiagnostics.cs | 470 ++++++ .../ExperienceOperationErrorClass.cs | 52 + .../Diagnostics/ExperienceOperationNames.cs | 54 + .../ExperienceReuseFeedbackService.cs | 35 + .../ExperienceFinalizationService.cs | 76 + .../Indexing/ExperienceIndexingService.cs | 114 ++ .../Lifecycle/ExperienceLifecycleService.cs | 93 ++ .../Reflections/DefaultExperienceReflector.cs | 34 +- .../Retrieval/ExperienceRetrievalService.cs | 33 + .../Verification/VerificationAggregator.cs | 42 + .../Diagnostics/InjectionDiagnostics.cs | 403 +++++ .../Injection/ExperienceContextProvider.cs | 127 +- .../Diagnostics/ExperienceLoop.cs | 526 +++++++ .../Diagnostics/ExperienceTelemetryTests.cs | 1374 +++++++++++++++++ .../Diagnostics/TelemetryProbe.cs | 262 ++++ .../Diagnostics/TelemetrySourceScanTests.cs | 230 +++ .../IndexingTestDoubles.cs | 20 +- .../DependencyBoundaryTests.cs | 125 ++ .../Diagnostics/DiagnosticsAgreementTests.cs | 159 ++ .../Diagnostics/InjectionTelemetryTests.cs | 707 +++++++++ .../Diagnostics/TelemetryProbe.cs | 205 +++ 22 files changed, 5200 insertions(+), 36 deletions(-) create mode 100644 src/AgentExperience.Core/Diagnostics/ExperienceDiagnostics.cs create mode 100644 src/AgentExperience.Core/Diagnostics/ExperienceOperationErrorClass.cs create mode 100644 src/AgentExperience.Core/Diagnostics/ExperienceOperationNames.cs create mode 100644 src/AgentExperience.MicrosoftAgentFramework/Diagnostics/InjectionDiagnostics.cs create mode 100644 tests/AgentExperience.Core.Tests/Diagnostics/ExperienceLoop.cs create mode 100644 tests/AgentExperience.Core.Tests/Diagnostics/ExperienceTelemetryTests.cs create mode 100644 tests/AgentExperience.Core.Tests/Diagnostics/TelemetryProbe.cs create mode 100644 tests/AgentExperience.Core.Tests/Diagnostics/TelemetrySourceScanTests.cs create mode 100644 tests/AgentExperience.MicrosoftAgentFramework.Tests/DependencyBoundaryTests.cs create mode 100644 tests/AgentExperience.MicrosoftAgentFramework.Tests/Diagnostics/DiagnosticsAgreementTests.cs create mode 100644 tests/AgentExperience.MicrosoftAgentFramework.Tests/Diagnostics/InjectionTelemetryTests.cs create mode 100644 tests/AgentExperience.MicrosoftAgentFramework.Tests/Diagnostics/TelemetryProbe.cs diff --git a/src/AgentExperience.Core/Capture/InMemoryExperienceCaptureService.cs b/src/AgentExperience.Core/Capture/InMemoryExperienceCaptureService.cs index 1096c11..4534629 100644 --- a/src/AgentExperience.Core/Capture/InMemoryExperienceCaptureService.cs +++ b/src/AgentExperience.Core/Capture/InMemoryExperienceCaptureService.cs @@ -3,6 +3,7 @@ using System.Diagnostics.CodeAnalysis; using System.Text.Json; using AgentExperience.Abstractions; +using AgentExperience.Core.Diagnostics; namespace AgentExperience.Core.Capture; @@ -93,6 +94,39 @@ public StartRunResult StartRun( EnvironmentFingerprint environment, Provenance provenance, DateTimeOffset startedAt) + { + // The span wraps the whole call, argument validation included, so a malformed call is visible + // as a failure rather than as a missing operation. Nothing below it reads the span back, and + // the run's task description is never written to it. + using var operation = ExperienceDiagnostics.Start(ExperienceOperationNames.CaptureStartRun, CancellationToken.None); + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.RunIdAttribute, runId.ToString("D")); + + // Only the call itself is guarded. Tagging and the metric writes happen outside it, so a + // throw from telemetry can never be mistaken for -- or turned into -- a failure of the run. + StartRunResult result; + try + { + result = StartRunCore(runId, taskId, taskDescription, scope, environment, provenance, startedAt); + } + catch (Exception ex) + { + ExperienceDiagnostics.Faulted(operation, ExperienceOperationNames.CaptureStartRun, ex); + throw; + } + + ExperienceDiagnostics.Succeeded(operation, ExperienceOperationNames.CaptureStartRun, result.Outcome.ToString()); + return result; + } + + /// The body of , unchanged by instrumentation: it neither reads nor writes a span. + private StartRunResult StartRunCore( + Guid runId, + string taskId, + string? taskDescription, + Scope scope, + EnvironmentFingerprint environment, + Provenance provenance, + DateTimeOffset startedAt) { ArgumentNullException.ThrowIfNull(taskId); ArgumentNullException.ThrowIfNull(scope); @@ -141,6 +175,38 @@ public async Task AppendAttemptAsync( Guid runId, AppendAttemptRequest request, CancellationToken cancellationToken = default) + { + using var operation = ExperienceDiagnostics.Start(ExperienceOperationNames.CaptureAppendAttempt, cancellationToken); + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.RunIdAttribute, runId.ToString("D")); + + AppendAttemptResult result; + try + { + // Both identifiers come off the request, so both are on the span before the call: a span + // that records a failure is worth far less if it cannot say which attempt failed. The + // argument check is restated ahead of the tag so that a null request is still the + // ArgumentNullException the body would have thrown, never a NullReferenceException from + // instrumentation -- and is still recorded as this operation's failure. + ArgumentNullException.ThrowIfNull(request); + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.AttemptIdAttribute, request.AttemptId.ToString("D")); + + result = await AppendAttemptCoreAsync(runId, request, cancellationToken).ConfigureAwait(false); + } + catch (Exception ex) + { + ExperienceDiagnostics.Faulted(operation, ExperienceOperationNames.CaptureAppendAttempt, ex); + throw; + } + + ExperienceDiagnostics.Succeeded(operation, ExperienceOperationNames.CaptureAppendAttempt, result.Outcome.ToString()); + return result; + } + + /// The body of , unchanged by instrumentation: it neither reads nor writes a span. + private async Task AppendAttemptCoreAsync( + Guid runId, + AppendAttemptRequest request, + CancellationToken cancellationToken) { ArgumentNullException.ThrowIfNull(request); ArgumentNullException.ThrowIfNull(request.ToolCalls); @@ -277,13 +343,40 @@ public async Task AppendAttemptAsync( } /// -#pragma warning disable CS1998 // Deliberately async with no internal await: this captures a synchronous ThrowIfCancellationRequested() throw into the returned Task (matching AppendAttemptAsync's contract) instead of letting it escape synchronously at the call site. public async Task CompleteRunAsync( Guid runId, Guid completionEventId, RunExecutionStatus executionStatus, DateTimeOffset endedAt, CancellationToken cancellationToken = default) + { + using var operation = ExperienceDiagnostics.Start(ExperienceOperationNames.CaptureCompleteRun, cancellationToken); + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.RunIdAttribute, runId.ToString("D")); + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.EventIdAttribute, completionEventId.ToString("D")); + + CompleteRunResult result; + try + { + result = await CompleteRunCoreAsync(runId, completionEventId, executionStatus, endedAt, cancellationToken).ConfigureAwait(false); + } + catch (Exception ex) + { + ExperienceDiagnostics.Faulted(operation, ExperienceOperationNames.CaptureCompleteRun, ex); + throw; + } + + ExperienceDiagnostics.Succeeded(operation, ExperienceOperationNames.CaptureCompleteRun, result.Outcome.ToString()); + return result; + } + + /// The body of , unchanged by instrumentation: it neither reads nor writes a span. +#pragma warning disable CS1998 // Deliberately async with no internal await: this captures a synchronous ThrowIfCancellationRequested() throw into the returned Task (matching AppendAttemptAsync's contract) instead of letting it escape synchronously at the call site. + private async Task CompleteRunCoreAsync( + Guid runId, + Guid completionEventId, + RunExecutionStatus executionStatus, + DateTimeOffset endedAt, + CancellationToken cancellationToken) #pragma warning restore CS1998 { cancellationToken.ThrowIfCancellationRequested(); diff --git a/src/AgentExperience.Core/Diagnostics/ExperienceDiagnostics.cs b/src/AgentExperience.Core/Diagnostics/ExperienceDiagnostics.cs new file mode 100644 index 0000000..7de980d --- /dev/null +++ b/src/AgentExperience.Core/Diagnostics/ExperienceDiagnostics.cs @@ -0,0 +1,470 @@ +using System.Diagnostics; +using System.Diagnostics.Metrics; +using System.Reflection; +using AgentExperience.Abstractions; + +namespace AgentExperience.Core.Diagnostics; + +/// +/// Core's one emission seam: the and named +/// AgentExperience.Core, the three instruments every instrumented operation writes to, and the +/// helpers that close a span and record its measurements. The library emits; the host exports. +/// +/// +/// +/// The BCL and nothing else. and ship in the +/// net10.0 shared framework, so instrumenting Core costs no package reference and Core's +/// dependency boundary (AD-1) is unchanged. Nothing here constructs a tracer provider, a meter +/// provider, an exporter, an , or a : a host +/// subscribes with AddSource("AgentExperience.*") and AddMeter("AgentExperience.*"), and +/// until it does, every call below is a handful of predictable branches that allocate no +/// and record no measurement. +/// +/// +/// Execution never depends on a listener. opens no +/// at all when nobody is listening or when a sampler declined, and every write +/// site is activity?.SetTag(...); every metric write is guarded by the instrument's own +/// Enabled. An instrumented operation therefore returns exactly what the uninstrumented one +/// would, whatever is or is not subscribed. +/// +/// +/// Exception objects never reach telemetry. A failing span records the exception's type name +/// (error.type) and a four-valued , never +/// , never , and never through +/// Activity.AddException -- because a driver or HTTP client message can quote SQL text, +/// parameters, or caller data, which is exactly what must not leave the process through an exporter. +/// +/// +/// Identifiers are span attributes; metrics carry four dimensions and no more. Run, attempt, +/// record, event, feedback, and host-supplied correlation identifiers are unbounded, so they are +/// written to spans only. The instruments below accept exactly operation, outcome, +/// error.class, and nested, each of which is a closed set. +/// +/// +/// Nesting is a dimension, not a reason to stop emitting. Several operations are steps of a +/// larger one: a finalization verifies, reflects, commits the record's initial lifecycle event, and +/// indexes it; a reuse-feedback submission applies confidence evidence per exposed record. Each of +/// those inner calls goes through its own public, instrumented entry point, so it emits its own span +/// and its own measurements -- which is the only way a hung embedding provider inside a post-commit +/// hook can reach agentexperience.operation.failures at all. +/// then lets an operator ask the two different questions separately: sum by (operation) over +/// nested=false is what the host asked for, and the unfiltered sum is what the library did. +/// Spans need no such dimension, because a span already carries its parent. +/// +/// +/// Nesting is read from ambient state, never from a parameter. No public signature changes to +/// carry it: records the outermost call in an for the +/// duration of that call, and an operation is nested exactly when one was already in flight. The flag +/// flows across await boundaries with the execution context and is restored in the scope's +/// Dispose, on the faulted path as well as the returning one. It does not leak out of +/// an async method either: the state machine's own builder restores the execution context +/// around the synchronous part of the method, so two operations started side by side and awaited +/// together are each other's siblings rather than each other's parents. +/// +/// +internal static class ExperienceDiagnostics +{ + /// The and name this assembly emits under. Assembly-scoped, so a text-only host can subscribe to Core without pulling the MAF adapter into its telemetry configuration. + internal const string SourceName = "AgentExperience.Core"; + + /// The prefix an operation's span name carries, so a span name is always derivable from its operation value. + internal const string SpanNamePrefix = "agentexperience."; + + /// The operation metric dimension: one of . + internal const string OperationDimension = "operation"; + + /// The outcome metric dimension: an enum member name from the operation's own bounded outcome enum, or . + internal const string OutcomeDimension = "outcome"; + + /// The error.class metric dimension: an member name. + internal const string ErrorClassDimension = "error.class"; + + /// + /// The nested metric dimension: when the host called the operation + /// directly, when another instrumented operation called it. + /// + internal const string NestedDimension = "nested"; + + /// The operation span attribute, so a span can be sliced the same way its measurements are. + internal const string OperationAttribute = "agentexperience.operation"; + + /// The outcome span attribute. Documented content-free at every declaration site that produces one. + internal const string OutcomeAttribute = "agentexperience.outcome"; + + /// The bounded failure classification, on the span as well as on the failure counter. + internal const string ErrorClassAttribute = "agentexperience.error.class"; + + /// The failing exception's type name, and only its type name. Never a metric dimension: third-party type names are not a bounded set. + internal const string ErrorTypeAttribute = "error.type"; + + /// The captured run an operation acted on. + internal const string RunIdAttribute = "agentexperience.run_id"; + + /// The attempt an append acted on. + internal const string AttemptIdAttribute = "agentexperience.attempt_id"; + + /// The lifecycle or completion event an operation stamped. + internal const string EventIdAttribute = "agentexperience.event_id"; + + /// The Experience Record an operation acted on. + internal const string ExperienceIdAttribute = "agentexperience.experience_id"; + + /// The reflection an operation produced. + internal const string ReflectionIdAttribute = "agentexperience.reflection_id"; + + /// The reuse-feedback submission an operation recorded. + internal const string FeedbackIdAttribute = "agentexperience.feedback_id"; + + /// The host-supplied correlation identifier, echoed on every outcome including a timeout. Omitted entirely, never written as an empty string, when the host supplied none. + internal const string CorrelationIdAttribute = "agentexperience.correlation_id"; + + /// The FinalizationStage a finalization ended at. Documented content-free at its declaration site. + internal const string StageAttribute = "agentexperience.stage"; + + /// The outcome value every faulted path reports, so a thrown operation is still counted and timed alongside the ones that returned. + internal const string FaultedOutcome = "Faulted"; + + /// The name of the counter every instrumented operation increments exactly once. + internal const string OperationCountInstrument = "agentexperience.operation.count"; + + /// The name of the histogram every instrumented operation's wall-clock duration, in seconds, is recorded to. + internal const string OperationDurationInstrument = "agentexperience.operation.duration"; + + /// The name of the counter only a thrown operation increments, dimensioned by . + internal const string OperationFailuresInstrument = "agentexperience.operation.failures"; + + /// + /// The assembly's informational version, carried by both the source and the meter so a host can + /// tell which build produced a signal. + /// + private static readonly string? InstrumentationVersion = typeof(ExperienceDiagnostics).Assembly + .GetCustomAttribute()?.InformationalVersion; + + private static readonly ActivitySource Source = new(SourceName, InstrumentationVersion); + + private static readonly Meter Meter = new(SourceName, InstrumentationVersion); + + private static readonly Counter Operations = Meter.CreateCounter( + OperationCountInstrument, + "{operation}", + "Instrumented Experience operations, by operation and by the outcome they reached."); + + private static readonly Histogram Durations = Meter.CreateHistogram( + OperationDurationInstrument, + "s", + "How long each instrumented Experience operation took, by operation and by the outcome it reached."); + + private static readonly Counter Failures = Meter.CreateCounter( + OperationFailuresInstrument, + "{failure}", + "Instrumented Experience operations that threw, by operation and by bounded failure class."); + + /// + /// The boxed nested dimension values. A entry is an + /// , and .NET boxes a afresh every time, so the two + /// possible values are boxed once here instead of on every measurement. + /// + private static readonly object Nested = true; + + private static readonly object NotNested = false; + + /// + /// The outermost instrumented operation currently in flight on this execution context, or + /// when the next operation to start will be one the host called directly. + /// + /// + /// Written only by , and only by the outermost call: an operation that finds a + /// value here is nested by definition and leaves it alone, which also means a deeply nested call + /// costs no allocation. What it holds is the host's cancellation token, which is what + /// keeps a deadline this library imposed on an inner step -- the post-commit indexing budget -- + /// from being reported as the caller having cancelled. + /// + private static readonly AsyncLocal InFlight = new(); + + /// + /// Starts : marks it in flight, records whether it is nested, takes its + /// start timestamp, and opens its span when a listener wants one. The + /// check comes first so an unsubscribed process does not + /// even pay for composing the span name. + /// + /// One of . + /// The token this operation was handed. For an outermost call it is the host's own; for a nested one it may be a token this library derived, which is why the host's is remembered separately. + /// The scope to tag, to report through, and to dispose when the operation ends. + internal static ExperienceOperationScope Start(string operation, CancellationToken cancellationToken) + { + var ambient = InFlight.Value; + var outermost = ambient is null; + + if (outermost) + { + ambient = new HostCall(cancellationToken); + InFlight.Value = ambient; + } + + Activity? activity = null; + if (Source.HasListeners()) + { + activity = Source.StartActivity(SpanNamePrefix + operation, ActivityKind.Internal); + activity?.SetTag(OperationAttribute, operation); + } + + return new ExperienceOperationScope( + activity, + Stopwatch.GetTimestamp(), + nested: !outermost, + cancellationToken, + ambient!.Token, + entered: outermost); + } + + /// + /// Ends the outermost operation's ambient mark, so the caller's execution context is left exactly + /// as it was found. Called from , on every path. + /// + internal static void Leave() => InFlight.Value = null; + + /// + /// Writes one span attribute, and never lets writing it become the caller's problem. + /// + /// + /// Every tag site in the library goes through here rather than calling SetTag directly, so + /// that frozen rule 6 -- "instrumentation failure is never propagated to the caller" -- holds by + /// construction instead of by inspection. A listener's ActivityStopped callback, a sampler, + /// or a future tag expression that threw would otherwise be able to turn an operation that already + /// ran -- in the worst case one that already committed a durable write -- into an exception. + /// + /// The scope produced. + /// The attribute name. One of the *Attribute constants above. + /// The attribute value, or to write nothing at all. + internal static void Tag(in ExperienceOperationScope scope, string name, object? value) + { + if (scope.Activity is not { } activity || value is null) + { + return; + } + + try + { + activity.SetTag(name, value); + } + catch (Exception) + { + // Frozen rule 6. Telemetry is a side effect of the operation, never a precondition of it. + } + } + + /// + /// Closes a span that returned -- including one that returned a rejection, which is a + /// decision rather than a failure and is therefore still -- + /// and records its count and duration under the outcome it reached. + /// + /// + /// Called from outside the wrapper's guarded region, and guarded again here, so an + /// already-returned operation can never be reported to its caller as having thrown. + /// + /// The scope produced. + /// One of . + /// The operation's own outcome enum member name, verbatim. + internal static void Succeeded(in ExperienceOperationScope scope, string operation, string outcome) + { + try + { + scope.Activity?.SetTag(OutcomeAttribute, outcome); + scope.Activity?.SetStatus(ActivityStatusCode.Ok); + Record(operation, outcome, scope.StartTimestamp, scope.Nested); + } + catch (Exception) + { + // Frozen rule 6. + } + } + + /// + /// Closes a span whose operation threw, classifying the exception into the four bounded values an + /// operator can alert on. The exception object itself is never handed to telemetry: only its type + /// name and its classification are written. + /// + /// The scope produced. + /// One of . + /// The exception about to propagate unchanged to the caller. + internal static void Faulted(in ExperienceOperationScope scope, string operation, Exception exception) + { + try + { + var errorClass = Classify(exception, scope.OperationToken, scope.HostToken); + var activity = scope.Activity; + + activity?.SetTag(ErrorTypeAttribute, exception.GetType().FullName); + activity?.SetTag(ErrorClassAttribute, Name(errorClass)); + activity?.SetTag(OutcomeAttribute, FaultedOutcome); + activity?.SetStatus(ActivityStatusCode.Error); + + Record(operation, FaultedOutcome, scope.StartTimestamp, scope.Nested); + + if (Failures.Enabled) + { + Failures.Add(1, new TagList + { + { OperationDimension, operation }, + { ErrorClassDimension, Name(errorClass) }, + { NestedDimension, scope.Nested ? Nested : NotNested }, + }); + } + } + catch (Exception) + { + // Frozen rule 6, and here it matters most: this runs inside a `catch` that is about to + // rethrow, so a throw from telemetry would replace the caller's own failure with ours. + } + } + + /// + /// Classifies a failure into the four values that may become a metric dimension. + /// + /// + /// + /// An the caller did not ask for is + /// rather than + /// , mirroring the storage adapter's own + /// infrastructure-failure rule: a driver-side or HTTP-client timeout surfaces as a cancellation + /// with the caller's token untouched, and reporting it as "the caller cancelled" would hide a + /// dependency that is down. + /// + /// + /// Two tokens, because a cancelled token is not automatically the caller's. An inner step + /// can be handed a token this library derived -- the post-commit indexing hook runs on a linked + /// source with the library's own budget on it -- and that token being cancelled means a deadline + /// expired, not that anyone gave up. A hung embedding provider is the case that matters: reporting + /// it as , the one class documented as + /// normally not alertable, is precisely how the vector channel dies without paging anybody. So + /// only the host's token makes a cancellation the caller's; this operation's own token + /// makes it a . For an operation the host + /// called directly the two tokens are the same, and this collapses to the rule above. + /// + /// + /// The failure to classify. + /// The token this operation itself was handed. + /// The token the outermost operation was handed, which is the host's own. + /// The bounded classification. + internal static ExperienceOperationErrorClass Classify( + Exception exception, + CancellationToken operationToken, + CancellationToken hostToken) => exception switch + { + OperationCanceledException when hostToken.IsCancellationRequested => ExperienceOperationErrorClass.Cancelled, + OperationCanceledException when operationToken.IsCancellationRequested => ExperienceOperationErrorClass.Timeout, + OperationCanceledException => ExperienceOperationErrorClass.Infrastructure, + TimeoutException => ExperienceOperationErrorClass.Timeout, + ExperienceStoreException => ExperienceOperationErrorClass.Infrastructure, + _ => ExperienceOperationErrorClass.Unexpected, + }; + + /// + /// The member name of as a compile-time constant, so a dimension + /// value costs no allocation and cannot drift from the enum it names. + /// + internal static string Name(ExperienceOperationErrorClass errorClass) => errorClass switch + { + ExperienceOperationErrorClass.Cancelled => nameof(ExperienceOperationErrorClass.Cancelled), + ExperienceOperationErrorClass.Timeout => nameof(ExperienceOperationErrorClass.Timeout), + ExperienceOperationErrorClass.Infrastructure => nameof(ExperienceOperationErrorClass.Infrastructure), + _ => nameof(ExperienceOperationErrorClass.Unexpected), + }; + + /// + /// Records one operation's count and duration. Both writes are guarded by the instrument's own + /// Enabled, so an unsubscribed process composes no tags and records nothing. + /// + private static void Record(string operation, string outcome, long startTimestamp, bool nested) + { + var counting = Operations.Enabled; + var timing = Durations.Enabled; + if (!counting && !timing) + { + return; + } + + var tags = new TagList + { + { OperationDimension, operation }, + { OutcomeDimension, outcome }, + { NestedDimension, nested ? Nested : NotNested }, + }; + + if (counting) + { + Operations.Add(1, tags); + } + + if (timing) + { + Durations.Record(Stopwatch.GetElapsedTime(startTimestamp).TotalSeconds, tags); + } + } + + /// The outermost instrumented operation on one execution context: what makes everything under it nested, and whose cancellation token is the host's. + /// The token the host handed the outermost operation. + private sealed class HostCall(CancellationToken token) + { + /// The token the host handed the outermost operation. + internal CancellationToken Token { get; } = token; + } +} + +/// +/// One instrumented operation in flight: its span if a listener wanted one, the timestamp its duration +/// is measured from, whether another instrumented operation called it, and the two tokens its failure +/// classification is decided by. +/// +/// +/// A , so an operation nobody is listening to costs no allocation here at all, +/// and , so nothing about a live operation can be changed after it started. +/// Disposing it ends the span and the ambient mark together, which is why every wrapper holds it in a +/// using rather than closing it by hand on each path. +/// +/// The started span, or when nobody is listening or a sampler declined it. +/// The taken when the operation began. +/// Whether another instrumented operation was already in flight when this one started. +/// The token this operation itself was handed. +/// The token the outermost operation was handed. +/// Whether this operation is the outermost one, and so the one that must clear the ambient mark. +internal readonly struct ExperienceOperationScope( + Activity? activity, + long startTimestamp, + bool nested, + CancellationToken operationToken, + CancellationToken hostToken, + bool entered) : IDisposable +{ + /// The started span, or when nobody is listening or a sampler declined it. + internal Activity? Activity { get; } = activity; + + /// The taken when the operation began. + internal long StartTimestamp { get; } = startTimestamp; + + /// Whether another instrumented operation called this one. + internal bool Nested { get; } = nested; + + /// The token this operation itself was handed, which may be one this library derived. + internal CancellationToken OperationToken { get; } = operationToken; + + /// The token the host handed the outermost operation. + internal CancellationToken HostToken { get; } = hostToken; + + private bool Entered { get; } = entered; + + /// + /// Ends the span and, for an outermost operation, the ambient mark that made everything under it + /// nested. Runs on the faulted path as well as the returning one, so a throw cannot leave a stale + /// mark behind for the next operation on this execution context to read. + /// + public void Dispose() + { + Activity?.Dispose(); + + if (Entered) + { + ExperienceDiagnostics.Leave(); + } + } +} diff --git a/src/AgentExperience.Core/Diagnostics/ExperienceOperationErrorClass.cs b/src/AgentExperience.Core/Diagnostics/ExperienceOperationErrorClass.cs new file mode 100644 index 0000000..84a9325 --- /dev/null +++ b/src/AgentExperience.Core/Diagnostics/ExperienceOperationErrorClass.cs @@ -0,0 +1,52 @@ +namespace AgentExperience.Core.Diagnostics; + +/// +/// The bounded classification a failed Experience operation is reported under. It is the only +/// failure detail that ever becomes a metric dimension, and it is deliberately four closed values: +/// an alert rule can be written against it once and never has to be widened, and no third-party +/// exception type name can turn a counter into an unbounded label set. +/// +/// +/// +/// Content-free by construction. A member name is all that is emitted -- never the exception's +/// message, its stack, its inner exceptions, or anything a driver put in them. A driver or HTTP +/// client message can quote SQL text, parameters, or caller data, so no exception object ever reaches +/// telemetry; the failing span carries this classification and the exception's type name +/// (error.type) and nothing else. +/// +/// +/// It classifies, it does not diagnose. The classification answers "is this worth paging +/// someone about, and who" -- not "what exactly went wrong". The typed results this library already +/// returns (Outcome, Reason, Detail, Failure) remain the place a host +/// looks for that, and they are available with no exporter and no listener registered at all. +/// +/// +public enum ExperienceOperationErrorClass +{ + /// + /// The caller's own cancellation token was cancelled. Expected under load shedding and shutdown, + /// and normally not alertable: the caller asked for this. + /// + Cancelled, + + /// + /// A bound was exceeded and reported as a . Distinct from + /// because nobody asked for it, and distinct from + /// because the dependency may be up and merely slow. + /// + Timeout, + + /// + /// Storage, an embedding provider, or another infrastructure dependency failed -- including a + /// cancellation the caller never requested, which is how a driver-side or HTTP-client timeout + /// usually surfaces. This is the class a host's "my memory layer is down" alert watches. + /// + Infrastructure, + + /// + /// Anything else: a programming error, a malformed request that reached a port, or a dependency + /// throwing something this library does not recognize. A non-zero rate here is a bug to + /// investigate, not a capacity signal. + /// + Unexpected, +} diff --git a/src/AgentExperience.Core/Diagnostics/ExperienceOperationNames.cs b/src/AgentExperience.Core/Diagnostics/ExperienceOperationNames.cs new file mode 100644 index 0000000..e409ea3 --- /dev/null +++ b/src/AgentExperience.Core/Diagnostics/ExperienceOperationNames.cs @@ -0,0 +1,54 @@ +namespace AgentExperience.Core.Diagnostics; + +/// +/// The closed set of operation dimension values this library emits, one per instrumented +/// call. They are literals rather than derived from a type or method name on purpose: a rename or a +/// refactor must not silently re-label an operator's dashboards, and the set a metric can be sliced +/// by has to be enumerable by reading one file. +/// +/// +/// The span name for each is the value prefixed with agentexperience., which is why the +/// operation and the span name never have to be kept in step by hand. Adding a value here is a +/// deliberate change: it widens the cardinality of every instrument at once. +/// +internal static class ExperienceOperationNames +{ + /// Starting a captured run (InMemoryExperienceCaptureService.StartRun). + public const string CaptureStartRun = "capture.start_run"; + + /// Appending one attempt to a captured run (InMemoryExperienceCaptureService.AppendAttemptAsync). + public const string CaptureAppendAttempt = "capture.append_attempt"; + + /// Finalizing a captured run's completion (InMemoryExperienceCaptureService.CompleteRunAsync). + public const string CaptureCompleteRun = "capture.complete_run"; + + /// Aggregating evidence into a verification verdict (VerificationAggregator.Aggregate). + public const string Verify = "verify"; + + /// Turning an evaluated run into a reflection (DefaultExperienceReflector.ReflectAsync). + public const string Reflect = "reflect"; + + /// Turning a captured run into a durable Experience Record (ExperienceFinalizationService.FinalizeAsync). + public const string Finalize = "finalize"; + + /// Committing a lifecycle transition (ExperienceLifecycleService.CommitAsync). + public const string LifecycleCommit = "lifecycle.commit"; + + /// Applying one piece of confidence evidence (ExperienceLifecycleService.ApplyEvidenceAsync). + public const string ConfidenceApply = "confidence.apply"; + + /// Retrieving experience applicable to a task (ExperienceRetrievalService.RetrieveAsync). + public const string Retrieve = "retrieve"; + + /// Embedding one record's retrieval summary (ExperienceIndexingService.IndexAsync). + public const string Index = "index"; + + /// Removing one record's stored vector (ExperienceIndexingService.RemoveAsync). + public const string Deindex = "deindex"; + + /// Running one scoped re-index pass (ExperienceIndexingService.ReindexAsync). + public const string Reindex = "reindex"; + + /// Recording reuse feedback for a run (ExperienceReuseFeedbackService.RecordAsync). + public const string ReuseFeedback = "reuse_feedback"; +} diff --git a/src/AgentExperience.Core/Feedback/ExperienceReuseFeedbackService.cs b/src/AgentExperience.Core/Feedback/ExperienceReuseFeedbackService.cs index a4ec05d..d7aa638 100644 --- a/src/AgentExperience.Core/Feedback/ExperienceReuseFeedbackService.cs +++ b/src/AgentExperience.Core/Feedback/ExperienceReuseFeedbackService.cs @@ -1,6 +1,7 @@ using System.Globalization; using System.Security.Cryptography; using AgentExperience.Abstractions; +using AgentExperience.Core.Diagnostics; using AgentExperience.Core.Lifecycle; namespace AgentExperience.Core.Feedback; @@ -180,6 +181,37 @@ public async Task RecordAsync( AuthorizationContext authorization, ExperienceReuseFeedback feedback, CancellationToken cancellationToken) + { + using var operation = ExperienceDiagnostics.Start(ExperienceOperationNames.ReuseFeedback, cancellationToken); + + ExperienceReuseFeedbackResult result; + try + { + // The submission's own identifier and the run it is about are both on the request, so both + // are on the span before the call and survive a throw. + ArgumentNullException.ThrowIfNull(feedback); + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.FeedbackIdAttribute, feedback.FeedbackId.ToString("D")); + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.RunIdAttribute, feedback.RunId.ToString("D")); + + result = await RecordCoreAsync(authorization, feedback, cancellationToken).ConfigureAwait(false); + } + catch (Exception ex) + { + ExperienceDiagnostics.Faulted(operation, ExperienceOperationNames.ReuseFeedback, ex); + throw; + } + + // Per-record dispositions stay on the typed result: they are a list whose length is the + // submission's, which is exactly the kind of thing a span attribute must not become. + ExperienceDiagnostics.Succeeded(operation, ExperienceOperationNames.ReuseFeedback, result.Outcome.ToString()); + return result; + } + + /// The body of , unchanged by instrumentation: it neither reads nor writes a span. + private async Task RecordCoreAsync( + AuthorizationContext authorization, + ExperienceReuseFeedback feedback, + CancellationToken cancellationToken) { ArgumentNullException.ThrowIfNull(authorization); ArgumentNullException.ThrowIfNull(feedback); @@ -361,6 +393,9 @@ private async Task SubmitEvidenceAsync( ApplyConfidenceEvidenceResult applied; try { + // The public, instrumented sibling: a submission exposing five records really does apply + // confidence evidence five times, and an operator who cannot see those five -- or the one + // of them that failed -- cannot tell a working feedback loop from a stuck one. applied = await _lifecycleService.ApplyEvidenceAsync(authorization, request, cancellationToken).ConfigureAwait(false); } catch (ExperienceStoreException ex) diff --git a/src/AgentExperience.Core/Finalization/ExperienceFinalizationService.cs b/src/AgentExperience.Core/Finalization/ExperienceFinalizationService.cs index a580104..5a25db3 100644 --- a/src/AgentExperience.Core/Finalization/ExperienceFinalizationService.cs +++ b/src/AgentExperience.Core/Finalization/ExperienceFinalizationService.cs @@ -3,6 +3,7 @@ using AgentExperience.Abstractions; using AgentExperience.Core.Capture; using AgentExperience.Core.Confidence; +using AgentExperience.Core.Diagnostics; using AgentExperience.Core.Indexing; using AgentExperience.Core.Lifecycle; using AgentExperience.Core.Reflections; @@ -223,6 +224,59 @@ public ExperienceFinalizationService( public async Task FinalizeAsync( FinalizeExperienceRequest request, CancellationToken cancellationToken = default) + { + using var operation = ExperienceDiagnostics.Start(ExperienceOperationNames.Finalize, cancellationToken); + + // Where the body had got to. A finalization that threw -- which in practice means a caller who + // cancelled -- otherwise leaves an operator with a failing span that cannot say whether the + // record was written before it stopped. + var cursor = new StageCursor(); + + FinalizeExperienceResult result; + try + { + // Request-derived, so it is on the span before anything runs and survives a throw. + ArgumentNullException.ThrowIfNull(request); + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.RunIdAttribute, request.RunId.ToString("D")); + + result = await FinalizeCoreAsync(request, cursor, cancellationToken).ConfigureAwait(false); + } + catch (Exception ex) + { + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.StageAttribute, cursor.Stage.ToString()); + ExperienceDiagnostics.Faulted(operation, ExperienceOperationNames.Finalize, ex); + throw; + } + + if (result.Record is { } finalized) + { + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.ExperienceIdAttribute, finalized.ExperienceId.ToString("D")); + } + + // The stage is on the span for every outcome, not only a failure: knowing that a refused + // finalization stopped at Authorize rather than at CommitInitialEvent is the whole point of + // the stage, and it is a bounded enum, so it costs no cardinality on the span. + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.StageAttribute, result.Stage.ToString()); + + ExperienceDiagnostics.Succeeded(operation, ExperienceOperationNames.Finalize, result.Outcome.ToString()); + return result; + } + + /// + /// Which stage of a finalization is in flight, so a span that records a throw can still say where + /// the run got to. It exists only for that: nothing reads it back, and no decision depends on it. + /// + private sealed class StageCursor + { + /// The stage currently in flight. Argument validation precedes stage 1, so it starts at . + internal FinalizationStage Stage { get; set; } = FinalizationStage.Load; + } + + /// The body of , unchanged by instrumentation beyond marking which stage it has reached. + private async Task FinalizeCoreAsync( + FinalizeExperienceRequest request, + StageCursor cursor, + CancellationToken cancellationToken) { ArgumentNullException.ThrowIfNull(request); ArgumentNullException.ThrowIfNull(request.Authorization, $"{nameof(request)}.{nameof(request.Authorization)}"); @@ -249,6 +303,8 @@ public async Task FinalizeAsync( cancellationToken.ThrowIfCancellationRequested(); + cursor.Stage = FinalizationStage.Load; + // Stage 1 -- Load. An unknown or unfinished run is an expected condition, not an exception. ExperienceRun? run; try @@ -285,11 +341,15 @@ public async Task FinalizeAsync( // re-derived event byte-for-byte identical to the stored one. var finalizedAt = TruncateToMicroseconds(request.FinalizedAt); + cursor.Stage = FinalizationStage.Evaluate; + // Stage 2 -- Evaluate, against this run's own closed round and evidence. No caller-supplied // evaluation is accepted, so an evaluation from another run cannot be substituted. VerificationResult evaluation; try { + // The public, instrumented sibling: verifying is a real operation whichever caller asked + // for it, and a finalization that verifies is a `verify` span nested in a `finalize` one. evaluation = VerificationAggregator.Aggregate( request.Evidence, request.RequiredChecks, @@ -316,6 +376,8 @@ public async Task FinalizeAsync( evaluation: null); } + cursor.Stage = FinalizationStage.Authorize; + // Stage 3 -- Authorize, then read the host's storage decision. Both are decided before any // store call *and before the reflector is called*, so a refused run is never handed to the // model-backed reflection seam and nothing at all is written. @@ -337,6 +399,8 @@ public async Task FinalizeAsync( evaluation: evaluation); } + cursor.Stage = FinalizationStage.Reflect; + // Stage 4 -- Reflect, but only on a verified run: a quarantined record must never carry an // unreflected lesson, so an unverified run is not reflected on at all. Reflection? reflection = null; @@ -387,6 +451,8 @@ public async Task FinalizeAsync( Exception: null); } + cursor.Stage = FinalizationStage.CreateRecord; + // Stage 5 -- Create the record, as a Candidate. Attempts are copied unchanged: capture already // rejected anything unsafe, and finalization never sanitizes. var record = new ExperienceRecord( @@ -465,6 +531,8 @@ public async Task FinalizeAsync( evaluation); } + cursor.Stage = FinalizationStage.CommitInitialEvent; + // Stage 6 -- Commit the record's initial lifecycle event, which performs the real transition. return await CommitInitialEventAsync(request, run, record, evaluation, failure, cancellationToken).ConfigureAwait(false); } @@ -558,6 +626,8 @@ private async Task CommitInitialEventAsync( CommitLifecycleTransitionResult commit; try { + // The public, instrumented sibling: this commit is the transition that makes the record + // durable, and it is counted, timed, and classified like any other -- as `nested`. commit = await _lifecycleService.CommitAsync(request.Authorization, transition, cancellationToken).ConfigureAwait(false); } catch (OperationCanceledException) @@ -678,6 +748,12 @@ private async Task CommitInitialEventAsync( try { + // The public, instrumented sibling, handed this library's own budget rather than the + // caller's token. That is deliberate on both counts: a hung embedding provider here is + // exactly the failure an operator must be paged for, so it has to reach the failure + // counter -- and the wrapper classifies the budget expiring as a Timeout rather than as + // the caller cancelling, because it compares this token against the host's, not against + // whether any token was cancelled. return await _indexingService .IndexAsync(request.Authorization, committed.Scope, committed.ExperienceId, indexing.Token) .ConfigureAwait(false); diff --git a/src/AgentExperience.Core/Indexing/ExperienceIndexingService.cs b/src/AgentExperience.Core/Indexing/ExperienceIndexingService.cs index 7dbf048..73b34dd 100644 --- a/src/AgentExperience.Core/Indexing/ExperienceIndexingService.cs +++ b/src/AgentExperience.Core/Indexing/ExperienceIndexingService.cs @@ -1,4 +1,5 @@ using AgentExperience.Abstractions; +using AgentExperience.Core.Diagnostics; using AgentExperience.Core.Retrieval; namespace AgentExperience.Core.Indexing; @@ -169,6 +170,41 @@ public async Task IndexAsync( Scope scope, Guid experienceId, CancellationToken cancellationToken = default) + { + using var operation = ExperienceDiagnostics.Start(ExperienceOperationNames.Index, cancellationToken); + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.ExperienceIdAttribute, experienceId.ToString("D")); + + ExperienceIndexingResult result; + try + { + result = await IndexCoreAsync(authorization, scope, experienceId, cancellationToken).ConfigureAwait(false); + } + catch (Exception ex) + { + ExperienceDiagnostics.Faulted(operation, ExperienceOperationNames.Index, ex); + throw; + } + + ExperienceDiagnostics.Succeeded(operation, ExperienceOperationNames.Index, result.Outcome.ToString()); + return result; + } + + /// + /// The body of , unchanged by instrumentation: it neither reads nor writes + /// a span. It exists so that the wrapper's own tagging and metric writes sit outside the region that + /// guards the call, and it is because every caller -- the finalization + /// service's post-commit hook included -- goes through the instrumented entry point. + /// + /// What the host has established the caller may do. + /// The scope the record belongs to. + /// The record to index. + /// Cancels the operation. + /// What the one-record pass produced. + private async Task IndexCoreAsync( + AuthorizationContext authorization, + Scope scope, + Guid experienceId, + CancellationToken cancellationToken) { ArgumentNullException.ThrowIfNull(authorization); ArgumentNullException.ThrowIfNull(scope); @@ -177,6 +213,11 @@ public async Task IndexAsync( throw new ArgumentException("ExperienceId must not be an empty GUID.", nameof(experienceId)); } + // The public, instrumented sibling: indexing a single record is implemented as a one-record + // pass, and that pass does the provider call and the conditional write that can fail. It is + // emitted as a `reindex` nested inside this `index`, so an operator who filters on + // `nested=false` sees one index per index and one pass per pass, while the unfiltered sum + // still accounts for every provider call the library made. var pass = await ReindexAsync( authorization, new ReindexExperienceRequest(scope, [experienceId], Limit: 1), @@ -225,6 +266,44 @@ public async Task RemoveAsync( Scope scope, Guid experienceId, CancellationToken cancellationToken = default) + { + using var operation = ExperienceDiagnostics.Start(ExperienceOperationNames.Deindex, cancellationToken); + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.ExperienceIdAttribute, experienceId.ToString("D")); + + // Removal reports a cancellation rather than throwing it, so this span is Ok with outcome + // Failed where every other operation would be a faulted one. That is the method's contract, + // not a gap: by the time it runs the transition it follows is already durable. + ExperienceDeindexingResult result; + try + { + result = await RemoveCoreAsync(authorization, scope, experienceId, cancellationToken).ConfigureAwait(false); + } + catch (Exception ex) + { + ExperienceDiagnostics.Faulted(operation, ExperienceOperationNames.Deindex, ex); + throw; + } + + ExperienceDiagnostics.Succeeded(operation, ExperienceOperationNames.Deindex, result.Outcome.ToString()); + return result; + } + + /// + /// The body of , unchanged by instrumentation: it neither reads nor writes + /// a span. It exists so that the wrapper's own tagging and metric writes sit outside the region that + /// guards the call, and it is because every caller -- the lifecycle + /// service's post-commit de-indexing hook included -- goes through the instrumented entry point. + /// + /// What the host has established the caller may do. + /// The scope the record belongs to. + /// The record whose vector is removed. + /// Cancels the operation. + /// What the removal produced. + private async Task RemoveCoreAsync( + AuthorizationContext authorization, + Scope scope, + Guid experienceId, + CancellationToken cancellationToken) { ArgumentNullException.ThrowIfNull(authorization); ArgumentNullException.ThrowIfNull(scope); @@ -297,6 +376,41 @@ public async Task ReindexAsync( AuthorizationContext authorization, ReindexExperienceRequest request, CancellationToken cancellationToken = default) + { + using var operation = ExperienceDiagnostics.Start(ExperienceOperationNames.Reindex, cancellationToken); + + // No per-record identifiers on this span: a pass is bounded by its own limit, not by one, + // and a span attribute is not a place to put a list that grows with the scope. + ExperienceReindexResult result; + try + { + result = await ReindexCoreAsync(authorization, request, cancellationToken).ConfigureAwait(false); + } + catch (Exception ex) + { + ExperienceDiagnostics.Faulted(operation, ExperienceOperationNames.Reindex, ex); + throw; + } + + ExperienceDiagnostics.Succeeded(operation, ExperienceOperationNames.Reindex, result.Outcome.ToString()); + return result; + } + + /// + /// The body of , unchanged by instrumentation: it neither reads nor + /// writes a span. It exists so that the wrapper's own tagging and metric writes sit outside the + /// region that guards the call, and it is because every caller -- + /// , which runs a one-record pass, included -- goes through the + /// instrumented entry point. + /// + /// What the host has established the caller may do. + /// The pass to run. + /// Cancels the operation. + /// What the pass produced. + private async Task ReindexCoreAsync( + AuthorizationContext authorization, + ReindexExperienceRequest request, + CancellationToken cancellationToken) { ArgumentNullException.ThrowIfNull(authorization); ArgumentNullException.ThrowIfNull(request); diff --git a/src/AgentExperience.Core/Lifecycle/ExperienceLifecycleService.cs b/src/AgentExperience.Core/Lifecycle/ExperienceLifecycleService.cs index bc74081..826cedc 100644 --- a/src/AgentExperience.Core/Lifecycle/ExperienceLifecycleService.cs +++ b/src/AgentExperience.Core/Lifecycle/ExperienceLifecycleService.cs @@ -1,6 +1,7 @@ using System.Globalization; using AgentExperience.Abstractions; using AgentExperience.Core.Confidence; +using AgentExperience.Core.Diagnostics; using AgentExperience.Core.Indexing; using AgentExperience.Core.Retrieval; @@ -215,6 +216,51 @@ public async Task CommitAsync( AuthorizationContext authorization, CommitLifecycleTransitionRequest request, CancellationToken cancellationToken) + { + using var operation = ExperienceDiagnostics.Start(ExperienceOperationNames.LifecycleCommit, cancellationToken); + + CommitLifecycleTransitionResult result; + try + { + // Both identifiers are in hand before the call, so a commit that threw still says which + // record and which event it was committing -- which is exactly the span an operator opens + // first. The argument check is restated ahead of the tag so that a null request is still + // the ArgumentNullException the body would have thrown. + ArgumentNullException.ThrowIfNull(request); + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.ExperienceIdAttribute, request.ExperienceId.ToString("D")); + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.EventIdAttribute, request.EventId.ToString("D")); + + result = await CommitCoreAsync(authorization, request, cancellationToken).ConfigureAwait(false); + } + catch (Exception ex) + { + ExperienceDiagnostics.Faulted(operation, ExperienceOperationNames.LifecycleCommit, ex); + throw; + } + + // Outside the guarded region on purpose. By this line the transition is durable, and frozen + // rule 6 says a throw from a tag expression or a metric write must never report it as failed. + // A refused transition is a decision, not a failure: the span stays Ok and only the outcome + // says the record did not move. + ExperienceDiagnostics.Succeeded(operation, ExperienceOperationNames.LifecycleCommit, result.Outcome.ToString()); + return result; + } + + /// + /// The body of , unchanged by instrumentation: it neither reads nor writes + /// a span. It exists so that the wrapper's own tagging and metric writes sit outside the region that + /// guards the call, and it is because every caller -- the finalization + /// service, which commits a record's initial lifecycle event, included -- goes through the + /// instrumented entry point and is counted there as a nested operation. + /// + /// What the host has established the caller may do. + /// The transition to commit. + /// Cancels the operation. + /// The store's outcome, surfaced unchanged, or the refusal Core reached before calling it. + private async Task CommitCoreAsync( + AuthorizationContext authorization, + CommitLifecycleTransitionRequest request, + CancellationToken cancellationToken) { ArgumentNullException.ThrowIfNull(authorization); ArgumentNullException.ThrowIfNull(request); @@ -334,6 +380,47 @@ public async Task ApplyEvidenceAsync( AuthorizationContext authorization, ApplyConfidenceEvidenceRequest request, CancellationToken cancellationToken) + { + using var operation = ExperienceDiagnostics.Start(ExperienceOperationNames.ConfidenceApply, cancellationToken); + + ApplyConfidenceEvidenceResult result; + try + { + // Request-derived, so tagged before the call and present on a faulted span too. + ArgumentNullException.ThrowIfNull(request); + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.ExperienceIdAttribute, request.ExperienceId.ToString("D")); + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.EventIdAttribute, request.EventId.ToString("D")); + + result = await ApplyEvidenceCoreAsync(authorization, request, cancellationToken).ConfigureAwait(false); + } + catch (Exception ex) + { + ExperienceDiagnostics.Faulted(operation, ExperienceOperationNames.ConfidenceApply, ex); + throw; + } + + // The evidence's own Detail is not written here: it is content-free by contract, but it is + // also of no use to an operator, and the fewer free-form values a span carries the less + // there is for a future change to get wrong. + ExperienceDiagnostics.Succeeded(operation, ExperienceOperationNames.ConfidenceApply, result.Outcome.ToString()); + return result; + } + + /// + /// The body of , unchanged by instrumentation: it neither reads nor + /// writes a span. It exists so that the wrapper's own tagging and metric writes sit outside the + /// region that guards the call, and it is because every caller -- the + /// reuse-feedback service, which applies one piece of evidence per exposed record, included -- + /// goes through the instrumented entry point. + /// + /// What the host has established the caller may do. + /// The evidence to apply. + /// Cancels the operation. + /// What happened, and the confidence movement as the transaction stored it. + private async Task ApplyEvidenceCoreAsync( + AuthorizationContext authorization, + ApplyConfidenceEvidenceRequest request, + CancellationToken cancellationToken) { ArgumentNullException.ThrowIfNull(authorization); ArgumentNullException.ThrowIfNull(request); @@ -708,6 +795,12 @@ private static List ValidateEvidenceShape(ApplyConfidenceE try { + // The public, instrumented sibling, handed this library's own budget rather than the + // caller's token. A vector this hook fails to remove is a record that stays searchable + // after it stopped being eligible, so the hook has to be visible as a `deindex` of its own + // -- nested in the transition that asked for it -- rather than silently absorbed into it. + // The budget expiring classifies as a Timeout, not as the caller cancelling: the wrapper + // compares this token against the host's. return await _indexingService .RemoveAsync(authorization, scope, experienceId, deindexing.Token) .ConfigureAwait(false); diff --git a/src/AgentExperience.Core/Reflections/DefaultExperienceReflector.cs b/src/AgentExperience.Core/Reflections/DefaultExperienceReflector.cs index 6ce0734..3a5b347 100644 --- a/src/AgentExperience.Core/Reflections/DefaultExperienceReflector.cs +++ b/src/AgentExperience.Core/Reflections/DefaultExperienceReflector.cs @@ -1,5 +1,6 @@ using System.Globalization; using AgentExperience.Abstractions; +using AgentExperience.Core.Diagnostics; namespace AgentExperience.Core.Reflections; @@ -43,10 +44,37 @@ public sealed class DefaultExperienceReflector : IExperienceReflector /// public Task ReflectAsync(ReflectionRequest request, CancellationToken cancellationToken = default) { - Validate(request); - cancellationToken.ThrowIfCancellationRequested(); + using var operation = ExperienceDiagnostics.Start(ExperienceOperationNames.Reflect, cancellationToken); - return Task.FromResult(Build(request, cancellationToken)); + Reflection reflection; + try + { + Validate(request); + + // Both identifiers are request-derived, so both are on the span before the work runs: a + // reflection that threw should still say which run it was reflecting on and which + // reflection ID the caller asked it to stamp. After Validate, so instrumentation is never + // the thing that rejects a malformed request. + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.RunIdAttribute, request.Run.RunId.ToString("D")); + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.ReflectionIdAttribute, request.ReflectionId.ToString("D")); + + cancellationToken.ThrowIfCancellationRequested(); + + reflection = Build(request, cancellationToken); + } + catch (Exception ex) + { + ExperienceDiagnostics.Faulted(operation, ExperienceOperationNames.Reflect, ex); + throw; + } + + // Identifiers only. The lesson, the approaches, the warnings, and the reuse guidance are all + // built from captured text and none of them is ever a telemetry value. + // + // A reflector has no outcome enum of its own: the verification status it reflected on is + // the bounded decision this call reached, and it is what an operator slices reflections by. + ExperienceDiagnostics.Succeeded(operation, ExperienceOperationNames.Reflect, reflection.VerificationStatus.ToString()); + return Task.FromResult(reflection); } private static Reflection Build(ReflectionRequest request, CancellationToken cancellationToken) diff --git a/src/AgentExperience.Core/Retrieval/ExperienceRetrievalService.cs b/src/AgentExperience.Core/Retrieval/ExperienceRetrievalService.cs index fccfe18..323cfee 100644 --- a/src/AgentExperience.Core/Retrieval/ExperienceRetrievalService.cs +++ b/src/AgentExperience.Core/Retrieval/ExperienceRetrievalService.cs @@ -1,4 +1,5 @@ using AgentExperience.Abstractions; +using AgentExperience.Core.Diagnostics; namespace AgentExperience.Core.Retrieval; @@ -208,6 +209,38 @@ public ExperienceRetrievalService( public async Task RetrieveAsync( RetrieveExperienceRequest request, CancellationToken cancellationToken = default) + { + using var operation = ExperienceDiagnostics.Start(ExperienceOperationNames.Retrieve, cancellationToken); + + ExperienceRetrievalResult result; + try + { + // Read from the request, not from the result, so it really is echoed on every outcome -- a + // timeout and a thrown retrieval included. A retrieval that threw is precisely the one an + // operator needs to tie back to the invocation that asked for it, and it has no result to + // read the identifier off. Omitted rather than written as an empty string when the host + // supplied none: an absent attribute and a blank one do not mean the same thing to a query. + ArgumentNullException.ThrowIfNull(request); + ExperienceDiagnostics.Tag(operation, ExperienceDiagnostics.CorrelationIdAttribute, request.CorrelationId); + + result = await RetrieveCoreAsync(request, cancellationToken).ConfigureAwait(false); + } + catch (Exception ex) + { + ExperienceDiagnostics.Faulted(operation, ExperienceOperationNames.Retrieve, ex); + throw; + } + + // The task text this searched on, the records it ranked, and their lessons are never + // telemetry values -- only the bounded outcome is. + ExperienceDiagnostics.Succeeded(operation, ExperienceOperationNames.Retrieve, result.Outcome.ToString()); + return result; + } + + /// The body of , unchanged by instrumentation: it neither reads nor writes a span. + private async Task RetrieveCoreAsync( + RetrieveExperienceRequest request, + CancellationToken cancellationToken) { ArgumentNullException.ThrowIfNull(request); ArgumentNullException.ThrowIfNull(request.Authorization, $"{nameof(request)}.{nameof(request.Authorization)}"); diff --git a/src/AgentExperience.Core/Verification/VerificationAggregator.cs b/src/AgentExperience.Core/Verification/VerificationAggregator.cs index ab95502..06e3986 100644 --- a/src/AgentExperience.Core/Verification/VerificationAggregator.cs +++ b/src/AgentExperience.Core/Verification/VerificationAggregator.cs @@ -1,4 +1,5 @@ using AgentExperience.Abstractions; +using AgentExperience.Core.Diagnostics; namespace AgentExperience.Core.Verification; @@ -84,6 +85,47 @@ public static VerificationResult Aggregate( string currentArtifactRevision, DateTimeOffset evaluatedAt, CancellationToken cancellationToken = default) + { + // A static ActivitySource instruments a static pure function without giving it a constructor, + // a container, or a seam -- emission is listener-driven, so nothing about calling Aggregate + // changes when nobody is subscribed. + using var operation = ExperienceDiagnostics.Start(ExperienceOperationNames.Verify, cancellationToken); + + VerificationResult result; + try + { + result = AggregateCore(evidence, requiredChecks, closedRound, currentArtifactRevision, evaluatedAt, cancellationToken); + } + catch (Exception ex) + { + ExperienceDiagnostics.Faulted(operation, ExperienceOperationNames.Verify, ex); + throw; + } + + ExperienceDiagnostics.Succeeded(operation, ExperienceOperationNames.Verify, result.Outcome.Status.ToString()); + return result; + } + + /// + /// The body of , unchanged by instrumentation: it neither reads nor writes + /// a span. It exists so that the wrapper's own tagging and metric writes sit outside the region + /// that guards the call, and it is because every caller -- this library's + /// own finalization included -- goes through the instrumented entry point. + /// + /// The evidence to aggregate. + /// The checks the round must satisfy. + /// The host-closed verification round, if any. + /// The artifact revision the evidence must match. + /// When the aggregation was performed. + /// Cancels the operation. + /// The verification verdict. + private static VerificationResult AggregateCore( + IReadOnlyList evidence, + IReadOnlyList requiredChecks, + ClosedVerificationRound? closedRound, + string currentArtifactRevision, + DateTimeOffset evaluatedAt, + CancellationToken cancellationToken) { ArgumentNullException.ThrowIfNull(evidence); ArgumentNullException.ThrowIfNull(requiredChecks); diff --git a/src/AgentExperience.MicrosoftAgentFramework/Diagnostics/InjectionDiagnostics.cs b/src/AgentExperience.MicrosoftAgentFramework/Diagnostics/InjectionDiagnostics.cs new file mode 100644 index 0000000..6e38f2e --- /dev/null +++ b/src/AgentExperience.MicrosoftAgentFramework/Diagnostics/InjectionDiagnostics.cs @@ -0,0 +1,403 @@ +using System.Diagnostics; +using System.Diagnostics.Metrics; +using System.Reflection; +using AgentExperience.Abstractions; +using AgentExperience.Core.Diagnostics; + +namespace AgentExperience.MicrosoftAgentFramework.Diagnostics; + +/// +/// The MAF adapter's one emission seam: the and +/// named AgentExperience.MicrosoftAgentFramework, the same three instruments Core emits, and +/// the one operation this assembly owns -- inject. +/// +/// +/// +/// Assembly-scoped names, on purpose. Core emits under AgentExperience.Core and this +/// adapter under its own name, so a text-only host can subscribe to Core without pulling the MAF +/// adapter into its telemetry configuration, and a host that wants both pays nothing for the second +/// name: AddSource("AgentExperience.*") and AddMeter("AgentExperience.*") take them +/// together. +/// +/// +/// The wire names below are restated, not shared. Core's holder is +/// to Core, and it stays that way: granting this assembly access to every Core internal to +/// reach a dozen strings would be a large, permanent coupling bought for a small convenience -- and it +/// would not even buy what it looks like it buys, because the values are and +/// are therefore baked into this assembly at compile time. Core and the adapter ship as independent +/// packages and can be mixed at different versions, so the two tables can drift either way. They are +/// duplicated here deliberately, and a test asserts the two tables agree, which makes that drift +/// visible as a failing build rather than as two dashboards that quietly stop lining up. +/// +/// +/// One span per injection, and no second pipeline. This is the only place the adapter +/// starts an activity. The capture wrapper deliberately opens none around RunAsync or +/// RunStreamingAsync -- it continues to read so a +/// captured run can carry the host's trace ID as its provenance correlation, and nothing more. MAF's +/// own agent, model, and tool spans are MAF's to emit; duplicating them here would double every +/// operator's trace for no added fact. +/// +/// +/// inject is never a nested operation. Core's holder reads an ambient flag to tell an +/// operation the host called directly from one another instrumented operation called. This assembly +/// emits exactly one operation, and nothing in this library calls it -- ProvideAIContextAsync +/// is invoked by the agent pipeline, which is the host. So nested is a constant +/// here rather than an ambient flag that could only ever read +/// : a dimension a test can pin is worth more than a mechanism with an +/// unreachable branch. The dimension is present at all so that a host summing across both meters does +/// not have to special-case which one a series came from. +/// +/// +/// The retrieval this injection performs reports itself to Core's meter, not to this one. It is +/// a retrieve on AgentExperience.Core, and Core sees it as a call from its own host -- +/// which, from Core's side, the adapter is. The two assemblies ship as independent packages with +/// independently named meters and no shared ambient state, and inventing a process-wide slot to link +/// them would be the same trade the InternalsVisibleTo grant was reverted for. An operator who +/// sums nested=false across both meters therefore sees the injection and the retrieval inside +/// it; the Core meter alone still answers "what was asked of Core". +/// +/// +/// The injected block is never a telemetry value. Neither the Historical Reference text, nor a +/// record's lesson, nor the task text the retrieval matched on is ever written to a span or a +/// measurement. An injection reports its bounded InjectionOutcome, the host's own correlation +/// identifier, and how many ranked records were left out -- a count, never the reasons' content. +/// +/// +internal static class InjectionDiagnostics +{ + /// The and name this assembly emits under. + internal const string SourceName = "AgentExperience.MicrosoftAgentFramework"; + + /// The only operation value this assembly emits. Core owns the other thirteen. + internal const string Inject = "inject"; + + /// How many ranked records this injection left out. A count: the omission reasons themselves stay on the typed result. + internal const string OmittedCountAttribute = "agentexperience.omitted_count"; + + // --------------------------------------------------------------------------------------------- + // Restated from Core. Every one of these is asserted equal to Core's own value by + // AgentExperience.MicrosoftAgentFramework.Tests' diagnostics-agreement test. + // --------------------------------------------------------------------------------------------- + + /// The prefix an operation's span name carries. + internal const string SpanNamePrefix = "agentexperience."; + + /// The operation metric dimension. + internal const string OperationDimension = "operation"; + + /// The outcome metric dimension. + internal const string OutcomeDimension = "outcome"; + + /// The error.class metric dimension. + internal const string ErrorClassDimension = "error.class"; + + /// The nested metric dimension: whether another instrumented operation called this one. + internal const string NestedDimension = "nested"; + + /// The operation span attribute. + internal const string OperationAttribute = "agentexperience.operation"; + + /// The outcome span attribute. + internal const string OutcomeAttribute = "agentexperience.outcome"; + + /// The bounded failure classification, on the span as well as on the failure counter. + internal const string ErrorClassAttribute = "agentexperience.error.class"; + + /// The failing exception's type name, and only its type name. + internal const string ErrorTypeAttribute = "error.type"; + + /// The host-supplied correlation identifier, echoed on every outcome including a timeout. + internal const string CorrelationIdAttribute = "agentexperience.correlation_id"; + + /// The outcome value every faulted path reports. + internal const string FaultedOutcome = "Faulted"; + + /// The name of the counter every instrumented operation increments exactly once. + internal const string OperationCountInstrument = "agentexperience.operation.count"; + + /// The name of the histogram every instrumented operation's wall-clock duration, in seconds, is recorded to. + internal const string OperationDurationInstrument = "agentexperience.operation.duration"; + + /// The name of the counter only a thrown operation increments. + internal const string OperationFailuresInstrument = "agentexperience.operation.failures"; + + /// + /// The assembly's informational version, carried by both the source and the meter so a host can + /// tell which build of the adapter produced a signal. + /// + private static readonly string? InstrumentationVersion = typeof(InjectionDiagnostics).Assembly + .GetCustomAttribute()?.InformationalVersion; + + private static readonly ActivitySource Source = new(SourceName, InstrumentationVersion); + + private static readonly Meter Meter = new(SourceName, InstrumentationVersion); + + private static readonly Counter Operations = Meter.CreateCounter( + OperationCountInstrument, + "{operation}", + "Instrumented Experience operations, by operation and by the outcome they reached."); + + private static readonly Histogram Durations = Meter.CreateHistogram( + OperationDurationInstrument, + "s", + "How long each instrumented Experience operation took, by operation and by the outcome it reached."); + + private static readonly Counter Failures = Meter.CreateCounter( + OperationFailuresInstrument, + "{failure}", + "Instrumented Experience operations that threw, by operation and by bounded failure class."); + + /// + /// The nested dimension every measurement from this assembly carries. Boxed once: a + /// entry is an , and .NET boxes a + /// afresh every time. + /// + /// + /// Always , and by construction rather than by luck: inject is the + /// only operation this assembly emits, and the only thing that calls it is the agent pipeline. + /// + private static readonly object NotNested = false; + + /// + /// Starts the span for one injection, or returns a trace carrying no span at all when no listener + /// wants it. The check comes first so an unsubscribed + /// process does not even pay for composing the span name. + /// + /// The trace to thread through the call and hand back to or . + internal static InjectionTrace Start() + { + if (!Source.HasListeners()) + { + return new InjectionTrace(null, Stopwatch.GetTimestamp()); + } + + var activity = Source.StartActivity(SpanNamePrefix + Inject, ActivityKind.Internal); + activity?.SetTag(OperationAttribute, Inject); + return new InjectionTrace(activity, Stopwatch.GetTimestamp()); + } + + /// + /// Writes one span attribute, and never lets writing it become the invocation's problem. The same + /// rule Core applies: telemetry is a side effect of the operation, never a precondition of it. + /// + /// The trace produced. + /// The attribute name. + /// The attribute value, or to write nothing at all. + internal static void Tag(InjectionTrace trace, string name, object? value) + { + if (trace.Activity is not { } activity || value is null) + { + return; + } + + try + { + activity.SetTag(name, value); + } + catch (Exception) + { + // Frozen rule 6: instrumentation failure is never propagated to the caller. + } + } + + /// + /// Closes a span whose injection returned -- including one that injected nothing, which is a + /// decision rather than a failure and is therefore still . + /// + /// The trace produced. + /// The InjectionOutcome member name, verbatim. + internal static void Succeeded(InjectionTrace trace, string outcome) + { + trace.Reported = true; + + try + { + trace.Activity?.SetTag(OutcomeAttribute, outcome); + trace.Activity?.SetStatus(ActivityStatusCode.Ok); + Record(outcome, trace.StartTimestamp); + } + catch (Exception) + { + // Frozen rule 6. + } + } + + /// + /// Closes a span whose injection threw. Only cancellation of the invocation itself escapes + /// ProvideAIContextAsync, so in practice this classifies that -- but it classifies whatever + /// arrives, and it hands telemetry the exception's type name and nothing else. + /// + /// The trace produced. + /// The exception about to propagate unchanged to the caller. + /// The invocation's token, which is what distinguishes from . + internal static void Faulted(InjectionTrace trace, Exception exception, CancellationToken cancellationToken) + { + trace.Reported = true; + + try + { + // The same token twice: this adapter imposes no deadline of its own on an injection, so + // the token it was handed is the host's. Core's holder, which does impose one on its + // post-commit hooks, is what the two-token form of this rule exists for. + Failed(trace, Classify(exception, cancellationToken, cancellationToken), exception.GetType().FullName); + } + catch (Exception) + { + // Frozen rule 6, and here it matters most: this runs inside a `catch` that is about to + // rethrow, so a throw from telemetry would replace the caller's own failure with ours. + } + } + + /// + /// Closes an injection that reached neither nor , so + /// that "every injection is counted exactly once" is enforced rather than merely intended. + /// + /// + /// Nothing in the provider reaches here today: every exit runs through the single report site. It + /// exists because a future early return added to the injection body would otherwise emit a + /// span with no outcome, no count, and no duration -- a silent hole in exactly the operation an + /// operator alerts on, and one no assertion about the paths that do report could catch. + /// An injection that got here is a bug in this library rather than a failure of a dependency, which + /// is why it is classified and carries no + /// error.type: no exception was involved. + /// + /// The trace produced. + internal static void Closed(InjectionTrace trace) + { + if (trace.Reported) + { + return; + } + + trace.Reported = true; + + try + { + Failed(trace, ExperienceOperationErrorClass.Unexpected, errorType: null); + } + catch (Exception) + { + // Frozen rule 6. + } + } + + /// + /// The same classification Core applies, restated here rather than shared, because Core's holder is + /// internal to Core and an emission seam is per-assembly by design. An + /// the caller did not ask for is + /// , not + /// ; one that a deadline this library imposed + /// caused is . A test asserts arm for arm that + /// this table and Core's agree. + /// + /// The failure to classify. + /// The token this operation itself was handed. + /// The token the outermost operation was handed, which is the host's own. For an injection the two are the same token. + /// The bounded classification. + internal static ExperienceOperationErrorClass Classify( + Exception exception, + CancellationToken operationToken, + CancellationToken hostToken) => exception switch + { + OperationCanceledException when hostToken.IsCancellationRequested => ExperienceOperationErrorClass.Cancelled, + OperationCanceledException when operationToken.IsCancellationRequested => ExperienceOperationErrorClass.Timeout, + OperationCanceledException => ExperienceOperationErrorClass.Infrastructure, + TimeoutException => ExperienceOperationErrorClass.Timeout, + ExperienceStoreException => ExperienceOperationErrorClass.Infrastructure, + _ => ExperienceOperationErrorClass.Unexpected, + }; + + /// The member name of as a compile-time constant, so a dimension value costs no allocation. + /// The classification to name. + /// The enum member name. + internal static string Name(ExperienceOperationErrorClass errorClass) => errorClass switch + { + ExperienceOperationErrorClass.Cancelled => nameof(ExperienceOperationErrorClass.Cancelled), + ExperienceOperationErrorClass.Timeout => nameof(ExperienceOperationErrorClass.Timeout), + ExperienceOperationErrorClass.Infrastructure => nameof(ExperienceOperationErrorClass.Infrastructure), + _ => nameof(ExperienceOperationErrorClass.Unexpected), + }; + + /// Writes the failing span's attributes, its count, its duration, and the failure counter. + private static void Failed(InjectionTrace trace, ExperienceOperationErrorClass errorClass, string? errorType) + { + var activity = trace.Activity; + + if (errorType is not null) + { + activity?.SetTag(ErrorTypeAttribute, errorType); + } + + activity?.SetTag(ErrorClassAttribute, Name(errorClass)); + activity?.SetTag(OutcomeAttribute, FaultedOutcome); + activity?.SetStatus(ActivityStatusCode.Error); + + Record(FaultedOutcome, trace.StartTimestamp); + + if (Failures.Enabled) + { + Failures.Add(1, new TagList + { + { OperationDimension, Inject }, + { ErrorClassDimension, Name(errorClass) }, + { NestedDimension, NotNested }, + }); + } + } + + /// + /// Records the injection's count and duration. Both writes are guarded by the instrument's own + /// Enabled, so an unsubscribed process composes no tags and records nothing. + /// + private static void Record(string outcome, long startTimestamp) + { + var counting = Operations.Enabled; + var timing = Durations.Enabled; + if (!counting && !timing) + { + return; + } + + var tags = new TagList + { + { OperationDimension, Inject }, + { OutcomeDimension, outcome }, + { NestedDimension, NotNested }, + }; + + if (counting) + { + Operations.Add(1, tags); + } + + if (timing) + { + Durations.Record(Stopwatch.GetElapsedTime(startTimestamp).TotalSeconds, tags); + } + } +} + +/// +/// One injection's span, if any, the timestamp its duration is measured from, and whether its outcome +/// has been reported yet. +/// +/// +/// Created per invocation and threaded through the call rather than stashed on the provider, because a +/// single ExperienceContextProvider serves every concurrent invocation of the agent it is +/// attached to. It is a class rather than a struct so that -- which +/// ProvideAIContextAsync's finally reads to enforce that every injection is counted +/// exactly once -- is the same flag the report site set, whichever frame set it. +/// +/// The started span, or when nobody is listening or a sampler declined it. +/// The taken when the injection began. +internal sealed class InjectionTrace(Activity? activity, long startTimestamp) +{ + /// The started span, or when nobody is listening or a sampler declined it. + internal Activity? Activity { get; } = activity; + + /// The taken when the injection began. + internal long StartTimestamp { get; } = startTimestamp; + + /// Whether this injection's outcome has already been reported. Set by every close. + internal bool Reported { get; set; } +} diff --git a/src/AgentExperience.MicrosoftAgentFramework/Injection/ExperienceContextProvider.cs b/src/AgentExperience.MicrosoftAgentFramework/Injection/ExperienceContextProvider.cs index f8adf5c..32e97e5 100644 --- a/src/AgentExperience.MicrosoftAgentFramework/Injection/ExperienceContextProvider.cs +++ b/src/AgentExperience.MicrosoftAgentFramework/Injection/ExperienceContextProvider.cs @@ -1,5 +1,6 @@ using AgentExperience.Abstractions; using AgentExperience.Core.Retrieval; +using AgentExperience.MicrosoftAgentFramework.Diagnostics; using Microsoft.Agents.AI; using Microsoft.Extensions.AI; @@ -128,6 +129,47 @@ public ExperienceContextProvider( protected override async ValueTask ProvideAIContextAsync( InvokingContext context, CancellationToken cancellationToken = default) + { + // The one span this adapter opens. It wraps the injection decision only -- never the agent's + // own RunAsync/RunStreamingAsync delegation, which MAF instruments itself and which this + // library deliberately adds nothing to. + var trace = InjectionDiagnostics.Start(); + try + { + return await InjectAsync(context, trace, cancellationToken).ConfigureAwait(false); + } + catch (Exception ex) + { + // Only the invocation's own cancellation escapes the body below; everything else is already + // a reported InjectionOutcome. Whatever arrives, it propagates unchanged. + InjectionDiagnostics.Faulted(trace, ex, cancellationToken); + throw; + } + finally + { + // "Report is the one place inject is counted" is enforced here rather than assumed. An exit + // that reported nothing -- a future early return added to the body below -- would otherwise + // leave a span with no outcome, no count, and no duration, which is a silent hole in the one + // operation an operator alerts on. Closing it is a no-op for every path that did report. + InjectionDiagnostics.Closed(trace); + + // Restores the caller's Activity.Current exactly as it was, so the invocation MAF is about + // to run sees the parent it would have seen with no instrumentation at all. + trace.Activity?.Dispose(); + } + } + + /// + /// The body of , unchanged by instrumentation beyond threading + /// to the single place every outcome is reported from. + /// + /// The invocation MAF is about to run. + /// This injection's span and start timestamp. + /// Cancels the operation. + private async ValueTask InjectAsync( + InvokingContext context, + InjectionTrace trace, + CancellationToken cancellationToken) { ArgumentNullException.ThrowIfNull(context); @@ -142,6 +184,7 @@ protected override async ValueTask ProvideAIContextAsync( catch (Exception ex) { return Nothing( + trace, InjectionOutcome.Failed, NoOmissions, retrieved: null, @@ -152,9 +195,14 @@ protected override async ValueTask ProvideAIContextAsync( if (request is null) { // The host opted this invocation out. Not a failure, and nothing to report beyond that. - return Nothing(InjectionOutcome.Skipped, NoOmissions, retrieved: null, correlationId: null, failure: null); + return Nothing(trace, InjectionOutcome.Skipped, NoOmissions, retrieved: null, correlationId: null, failure: null); } + // From the request, not from a result: the host's correlation identifier is then on the span for + // every outcome below -- a retrieval that timed out, one that was denied, one that threw -- and + // not only for the ones that produced a result to read it back off. + InjectionDiagnostics.Tag(trace, InjectionDiagnostics.CorrelationIdAttribute, request.CorrelationId); + ExperienceRetrievalResult retrieved; try { @@ -169,6 +217,7 @@ protected override async ValueTask ProvideAIContextAsync( catch (Exception ex) { return Nothing( + trace, InjectionOutcome.RetrievalFailed, NoOmissions, retrieved: null, @@ -179,6 +228,7 @@ protected override async ValueTask ProvideAIContextAsync( if (retrieved.Outcome is not RetrievalOutcome.Completed) { return Nothing( + trace, retrieved.Outcome switch { RetrievalOutcome.TimedOut => InjectionOutcome.RetrievalTimedOut, @@ -195,7 +245,7 @@ protected override async ValueTask ProvideAIContextAsync( var selected = Select(retrieved.Records, omitted); if (selected.Count == 0) { - return Nothing(InjectionOutcome.NothingToInject, omitted, retrieved, retrieved.CorrelationId, failure: null); + return Nothing(trace, InjectionOutcome.NothingToInject, omitted, retrieved, retrieved.CorrelationId, failure: null); } CheckOutcome recheck; @@ -212,6 +262,7 @@ protected override async ValueTask ProvideAIContextAsync( // Nothing below the per-record handling is expected to throw; if it somehow does, the // invocation still runs, with no context at all rather than a partly checked one. return Nothing( + trace, InjectionOutcome.Failed, omitted, retrieved, @@ -223,12 +274,12 @@ protected override async ValueTask ProvideAIContextAsync( { // The check ran out of time. Nothing is injected rather than injecting the part of it that // had been re-checked before the bound was reached. - return Nothing(InjectionOutcome.Failed, omitted, retrieved, retrieved.CorrelationId, checkFailure); + return Nothing(trace, InjectionOutcome.Failed, omitted, retrieved, retrieved.CorrelationId, checkFailure); } if (recheck.Injectable.Count == 0) { - return Nothing(InjectionOutcome.NothingToInject, omitted, retrieved, retrieved.CorrelationId, failure: null); + return Nothing(trace, InjectionOutcome.NothingToInject, omitted, retrieved, retrieved.CorrelationId, failure: null); } HistoricalReferencePayload payload; @@ -239,6 +290,7 @@ protected override async ValueTask ProvideAIContextAsync( catch (Exception ex) { return Nothing( + trace, InjectionOutcome.Failed, omitted, retrieved, @@ -250,24 +302,13 @@ protected override async ValueTask ProvideAIContextAsync( if (payload.IsEmpty) { - return Nothing(InjectionOutcome.NothingToInject, omitted, retrieved, retrieved.CorrelationId, failure: null); + return Nothing(trace, InjectionOutcome.NothingToInject, omitted, retrieved, retrieved.CorrelationId, failure: null); } - Report(new ExperienceInjectionResult( - InjectionOutcome.Injected, - payload.ExperienceIds, - omitted, - retrieved.Excluded, - retrieved.Truncated, - retrieved.EnvironmentUnrestricted, - payload.ByteCount, - retrieved.CorrelationId, - Failure: null, - retrieved.VectorFallback)); - // A user-role message, not a system one: the block is reference material the model may read, - // never an instruction from the host. MAF merges it with the invocation's own messages. - return new AIContext + // never an instruction from the host. MAF merges it with the invocation's own messages. Built + // before the report so that nothing which could throw remains after the span has been closed. + var injected = new AIContext { Messages = [ @@ -280,6 +321,20 @@ protected override async ValueTask ProvideAIContextAsync( }, ], }; + + Report(trace, new ExperienceInjectionResult( + InjectionOutcome.Injected, + payload.ExperienceIds, + omitted, + retrieved.Excluded, + retrieved.Truncated, + retrieved.EnvironmentUnrestricted, + payload.ByteCount, + retrieved.CorrelationId, + Failure: null, + retrieved.VectorFallback)); + + return injected; } /// @@ -515,13 +570,14 @@ private async Task CheckAsync( /// Reports the attempt and returns an that adds nothing to the invocation. private AIContext Nothing( + InjectionTrace trace, InjectionOutcome outcome, IReadOnlyList omitted, ExperienceRetrievalResult? retrieved, string? correlationId, InjectionFailure? failure) { - Report(new ExperienceInjectionResult( + Report(trace, new ExperienceInjectionResult( outcome, NoIds, omitted, @@ -547,9 +603,32 @@ private readonly record struct CheckOutcome(List Injectable, I Exception: null)); } - /// Hands the result to the host. A callback that throws must not become the invocation's problem. - private void Report(ExperienceInjectionResult result) + /// + /// Closes this injection's span and hands the result to the host. Every non-throwing exit runs + /// through here exactly once, which is what makes it the one place the inject operation is + /// counted and timed. + /// + /// + /// + /// The span carries the bounded outcome, the host's own correlation identifier (omitted, never + /// blank, when the host supplied none), and how many ranked records were left out. It never + /// carries the injected block, a record's lesson, an omission's reason text, or the task text the + /// retrieval matched on. + /// + /// + /// The duration is recorded after the host callback, not before it. The span stops in + /// ProvideAIContextAsync's finally, which is after the callback, so measuring before + /// it would leave span p99 and histogram p99 disagreeing by whatever the host's callback costs -- + /// and Core, which has no callback, has no such gap. A callback that throws is caught, so it can + /// still never cost the operation its measurement. + /// + /// + /// This injection's span and start timestamp. + /// What the attempt ended as. + private void Report(InjectionTrace trace, ExperienceInjectionResult result) { + InjectionDiagnostics.Tag(trace, InjectionDiagnostics.OmittedCountAttribute, result.Omitted.Count); + try { _options.OnContextInjected?.Invoke(result); @@ -558,5 +637,9 @@ private void Report(ExperienceInjectionResult result) { // Reporting is diagnostics. It can never change what the caller of the agent observes. } + finally + { + InjectionDiagnostics.Succeeded(trace, result.Outcome.ToString()); + } } } diff --git a/tests/AgentExperience.Core.Tests/Diagnostics/ExperienceLoop.cs b/tests/AgentExperience.Core.Tests/Diagnostics/ExperienceLoop.cs new file mode 100644 index 0000000..66c7706 --- /dev/null +++ b/tests/AgentExperience.Core.Tests/Diagnostics/ExperienceLoop.cs @@ -0,0 +1,526 @@ +using AgentExperience.Core.Feedback; +using AgentExperience.Core.Finalization; +using AgentExperience.Core.Indexing; +using AgentExperience.Core.Lifecycle; +using AgentExperience.Core.Retrieval; + +namespace AgentExperience.Core.Tests.Diagnostics; + +/// +/// The whole Core learning loop wired from the real services, with only the ports that would be a +/// database or a model provider replaced: capture, verification, reflection, finalization, indexing, +/// lifecycle, retrieval, and reuse feedback all run their shipping code. +/// +/// +/// +/// Everything it can carry is poisoned with . The task description, each +/// attempt's result and error, every tool call's arguments, result and error, the retrieval summary +/// the index embeds, and the task text retrieval matches on all contain it -- and the reflection the +/// library builds quotes several of them back. So a single drive of this loop is enough to prove +/// that nothing a run said reaches a span attribute or a metric dimension. +/// +/// +/// The sanitizer is deliberately permissive: a sanitizer that stripped the marker would make the +/// marker sweep pass for the wrong reason. +/// +/// +internal sealed class ExperienceLoop +{ + /// + /// A string that appears nowhere in this library and cannot be produced by accident, planted in + /// every piece of captured content the loop touches. + /// + internal const string Marker = "Q7-CANARY-9f3d-DO-NOT-EXPORT"; + + /// The host-supplied correlation identifier, which telemetry is allowed to echo. + internal const string CorrelationId = "corr-4242"; + + internal const string ArtifactRevision = "rev-1"; + + internal static readonly DateTimeOffset Now = new(2026, 9, 22, 12, 0, 0, TimeSpan.Zero); + + internal static readonly Scope Scope = new("tenant-1", "app-1", "project-1"); + + internal static readonly AuthorizationContext Authorization = new("tenant-1", "host-principal", ["experience:write"], Now); + + internal static readonly ClosedVerificationRound Round = new(Guid.Parse("11111111-1111-1111-1111-111111111111"), ArtifactRevision); + + private static readonly SanitizationOptions Permissive = new(new Dictionary(StringComparer.Ordinal) + { + ["ToolArguments"] = new SanitizationPolicy( + AllowedFieldNames: new HashSet(StringComparer.Ordinal) { "query" }, + SecretFieldNames: new HashSet(StringComparer.Ordinal), + MaxDepth: 3, + MaxFieldCount: 10, + MaxValueLength: 1_000, + MaxFieldNameLength: 100), + ["ToolResult"] = new SanitizationPolicy( + AllowedFieldNames: new HashSet(StringComparer.Ordinal) { "value" }, + SecretFieldNames: new HashSet(StringComparer.Ordinal), + MaxDepth: 2, + MaxFieldCount: 5, + MaxValueLength: 1_000, + MaxFieldNameLength: 100), + }); + + internal ExperienceLoop() + { + Capture = new InMemoryExperienceCaptureService(new DefaultSanitizer(Permissive), new CaptureLimits(8, 8, 1_000, 1_000)); + Indexing = new ExperienceIndexingService(Index, Generator); + Lifecycle = new ExperienceLifecycleService(Store, Indexing); + Finalization = new ExperienceFinalizationService(Capture, new DefaultExperienceReflector(), Store, Lifecycle, Indexing); + Retrieval = new ExperienceRetrievalService(Candidates, RetrievalPolicy.Default, RankingWeights.Default, TimeProvider.System); + FeedbackService = new ExperienceReuseFeedbackService(FeedbackStore, Lifecycle); + } + + internal LoopRecordStore Store { get; } = new(); + + internal LoopCandidateSource Candidates { get; } = new(); + + internal LoopFeedbackStore FeedbackStore { get; } = new(); + + internal FakeEmbeddingIndex Index { get; } = new(); + + internal FakeEmbeddingGenerator Generator { get; } = new(); + + internal InMemoryExperienceCaptureService Capture { get; } + + internal ExperienceIndexingService Indexing { get; } + + internal ExperienceLifecycleService Lifecycle { get; } + + internal ExperienceFinalizationService Finalization { get; } + + internal ExperienceRetrievalService Retrieval { get; } + + internal ExperienceReuseFeedbackService FeedbackService { get; } + + /// + /// Drives capture, verification, reflection, finalization, indexing, retrieval, reuse feedback and + /// the confidence update it triggers, then de-indexes -- one call per operation in the frozen + /// table, all of them succeeding. + /// + /// Threaded into every call so a cancelled drive is a realistic one. + /// What the drive produced, for a caller that wants to assert on the results as well as on the telemetry. + internal async Task DriveAsync(CancellationToken cancellationToken = default) + { + var runId = Guid.NewGuid(); + + var started = Capture.StartRun( + runId, + "task-1", + $"Summarize the incident report for {Marker}", + Scope, + new EnvironmentFingerprint("host-1", "net10.0", "linux", "1.0.0", new Dictionary { ["region"] = "eu-west-1" }), + new Provenance("tests", "1.0.0", Now, CorrelationId), + Now); + + var appended = await Capture.AppendAttemptAsync( + runId, + new AppendAttemptRequest( + AttemptId: Guid.NewGuid(), + StartedAt: Now, + Duration: TimeSpan.FromSeconds(1), + ToolCalls: + [ + new RawToolCall( + ToolCallId: Guid.NewGuid(), + ToolName: "search", + Arguments: new Dictionary { ["query"] = $"find {Marker}" }, + StartedAt: Now, + Duration: TimeSpan.FromMilliseconds(50), + Result: $"tool result mentioning {Marker}", + Error: $"tool error mentioning {Marker}"), + ], + Result: $"attempt result mentioning {Marker}", + Error: null), + cancellationToken).ConfigureAwait(false); + + // A second attempt that failed, so the reflection has a failed approach to quote the marker + // into as well as a successful one. + await Capture.AppendAttemptAsync( + runId, + new AppendAttemptRequest( + AttemptId: Guid.NewGuid(), + StartedAt: Now.AddSeconds(1), + Duration: TimeSpan.FromSeconds(1), + ToolCalls: [], + Result: null, + Error: $"attempt error mentioning {Marker}"), + cancellationToken).ConfigureAwait(false); + + var completed = await Capture + .CompleteRunAsync(runId, Guid.NewGuid(), RunExecutionStatus.Completed, Now.AddSeconds(3), cancellationToken) + .ConfigureAwait(false); + + // verify, driven directly, so the drive has one `verify` the host asked for alongside the one + // the finalization below performs as a step of its own. The evidence it aggregates carries the + // marker in both of its free-form fields. + var verified = VerificationAggregator.Aggregate( + [Evidence()], + [new RequiredCheck("tests")], + Round, + ArtifactRevision, + Now, + cancellationToken); + + var experienceId = ExperienceFinalizationService.ExperienceIdFor(runId); + + // Seeded at the revision the initial lifecycle event will leave the record at, with a summary + // that carries the marker: the post-commit indexing hook then really embeds poisoned text. + Index.Records[experienceId] = new FakeEmbeddingIndex.Row(1, $"retrieval summary mentioning {Marker}"); + + var finalized = await Finalization.FinalizeAsync( + new FinalizeExperienceRequest( + RunId: runId, + Authorization: Authorization, + ClosedRound: Round, + RequiredChecks: [new RequiredCheck("tests")], + Evidence: [Evidence()], + CurrentArtifactRevision: ArtifactRevision, + StorageDecision: StorageDecision.Permit, + FinalizedAt: Now.AddMinutes(1)), + cancellationToken).ConfigureAwait(false); + + // lifecycle.commit, driven directly, for the same reason -- and with the marker in the two + // free-form fields a transition carries, so the content sweep covers them too. The + // finalization above committed the record's initial event, which is the nested counterpart. + var transitioned = await Lifecycle.CommitAsync( + Authorization, + new CommitLifecycleTransitionRequest( + EventId: Guid.NewGuid(), + ExperienceId: experienceId, + Scope: Scope, + PriorStatus: ExperienceStatus.Validated, + CurrentStatus: ExperienceStatus.Reinforced, + Reason: $"reuse of the lesson about {Marker} succeeded again", + Producer: $"tests-{Marker}", + OccurredAt: Now.AddMinutes(1), + ExpectedRevision: 1), + cancellationToken).ConfigureAwait(false); + + // confidence.apply, driven directly. The reuse-feedback submission below applies evidence once + // per exposed record, so the drive covers both the direct call and the nested one. + var confidence = await Lifecycle.ApplyEvidenceAsync( + Authorization, + new ApplyConfidenceEvidenceRequest( + EventId: Guid.NewGuid(), + ExperienceId: experienceId, + Scope: Scope, + EvidenceId: Guid.NewGuid(), + Kind: ConfidenceEvidenceKind.Supporting, + Source: ConfidenceEvidenceSource.Machine, + RunId: runId, + VerificationRoundId: Round.RoundId, + Reason: $"a later run reused the lesson about {Marker}", + Producer: $"tests-{Marker}", + OccurredAt: Now.AddMinutes(1), + Detail: $"observed while handling {Marker}"), + cancellationToken).ConfigureAwait(false); + + // Everything the loop retrieves is the record the transitions above left behind, marker and all. + if (Store.Find(experienceId) is { } committed) + { + Candidates.Candidates = [new ExperienceCandidate(committed, Relevance: 0.9)]; + } + + var retrieved = await Retrieval.RetrieveAsync( + new RetrieveExperienceRequest( + Authorization, + Scope, + $"another incident like {Marker}", + RequiredEnvironmentAttributes: null, + CorrelationId: CorrelationId), + cancellationToken).ConfigureAwait(false); + + var feedback = await FeedbackService.RecordAsync( + Authorization, + new ExperienceReuseFeedback( + FeedbackId: Guid.NewGuid(), + RunId: Guid.NewGuid(), + Scope: Scope, + ExposedExperienceIds: [experienceId], + RunOutcome: TaskVerificationStatus.Verified, + Measure: new ReuseMeasure("task-success", 1), + ObservedAt: Now.AddMinutes(2)) + { + HumanAssessment = new HumanReuseAssessment( + Guid.NewGuid(), + ExperienceReuseBenefit.Improved, + [experienceId], + $"the lesson about {Marker} applied", + Now.AddMinutes(2)), + }, + cancellationToken).ConfigureAwait(false); + + // The record moved on -- two lifecycle events since finalization embedded it -- so the stored + // vector is stale and the explicit index pass below has real work to do rather than reporting + // that nothing changed. Its summary carries the marker, so what is embedded is poisoned text. + Index.Records[experienceId] = new FakeEmbeddingIndex.Row(3, $"reinforced retrieval summary mentioning {Marker}"); + + // index, driven directly. Finalization's post-commit hook indexed the record too, on this + // library's own budget rather than the caller's token -- which is the nested `index` the call + // table pins, and the one whose failures an operator is paged for. + var indexed = await Indexing + .IndexAsync(Authorization, Scope, experienceId, cancellationToken) + .ConfigureAwait(false); + + var reindexed = await Indexing + .ReindexAsync(Authorization, new ReindexExperienceRequest(Scope, [experienceId], Limit: 1), cancellationToken) + .ConfigureAwait(false); + + var deindexed = await Indexing + .RemoveAsync(Authorization, Scope, experienceId, cancellationToken) + .ConfigureAwait(false); + + return new LoopResults( + runId, + experienceId, + started, + appended, + completed, + verified, + finalized, + transitioned, + confidence, + retrieved, + feedback, + indexed, + reindexed, + deindexed); + } + + /// + /// One passing piece of evidence in the host-closed round, so the run verifies and is reflected on. + /// + /// + /// Both of its free-form fields carry . verify otherwise receives no + /// marker-bearing input at all, which would leave the content guarantee proven for the operations + /// that happen to handle captured text and merely assumed for the ones that do not. + /// + /// The check result this evidence reports. + /// The evidence. + internal static Evidence Evidence(CheckResult result = CheckResult.Pass) => new( + EvidenceId: Guid.NewGuid(), + VerificationRoundId: Round.RoundId, + ArtifactRevision: ArtifactRevision, + CheckId: "tests", + Kind: "TestResult", + Result: result, + Producer: $"ci-{Marker}", + Detail: $"the suite reported {Marker}", + CapturedAt: Now); +} + +/// What one drive of produced, so a test can assert the loop really worked before asserting on its telemetry. +/// The captured run. +/// The record finalization derived for that run. +/// The start-run result. +/// The first append-attempt result. +/// The complete-run result. +/// The explicit verification verdict. +/// The finalization result. +/// The explicit lifecycle transition's result. +/// The explicit confidence-evidence result. +/// The retrieval result. +/// The reuse-feedback result. +/// The explicit one-record indexing result. +/// The explicit re-index pass's result. +/// The explicit de-index result. +internal sealed record LoopResults( + Guid RunId, + Guid ExperienceId, + StartRunResult Started, + AppendAttemptResult Appended, + CompleteRunResult Completed, + VerificationResult Verified, + FinalizeExperienceResult Finalized, + CommitLifecycleTransitionResult Transitioned, + ApplyConfidenceEvidenceResult Confidence, + ExperienceRetrievalResult Retrieved, + ExperienceReuseFeedbackResult Feedback, + ExperienceIndexingResult Indexed, + ExperienceReindexResult Reindexed, + ExperienceDeindexingResult Deindexed); + +/// +/// An in-memory with just enough of the port's real contract for +/// the loop: create-once inserts, scope-exact reads, and event-ID-idempotent, revision-checked, +/// prior-status-guarded lifecycle commits that apply a confidence update when one is carried. +/// +internal sealed class LoopRecordStore : IExperienceRecordStore +{ + private readonly Dictionary _records = []; + private readonly Dictionary _events = []; + + /// When set, every call throws this, which is how an infrastructure failure is driven through the loop. + internal Func? Throws { get; set; } + + /// + /// Runs at the start of every store call, from inside whichever Core operation is in flight. It is + /// where "the caller's Activity.Current is untouched" is actually observed -- at the bottom + /// of the call stack, not from the test method. + /// + internal Action? OnCall { get; set; } + + /// The record as it now stands, or when nothing was ever created for that ID. + /// The record to read. + internal ExperienceRecord? Find(Guid experienceId) => _records.GetValueOrDefault(experienceId); + + public Task CreateAsync(AuthorizationContext authorization, ExperienceRecord record, CancellationToken cancellationToken) + { + Fail(cancellationToken); + + if (_records.ContainsKey(record.ExperienceId)) + { + return Task.FromResult(new ExperienceRecordCreateResult(ExperienceStoreOutcome.Conflict, [])); + } + + if (!authorization.Permits(record.Scope)) + { + return Task.FromResult(new ExperienceRecordCreateResult(ExperienceStoreOutcome.Denied, [])); + } + + _records[record.ExperienceId] = record; + return Task.FromResult(new ExperienceRecordCreateResult(ExperienceStoreOutcome.Created, [])); + } + + public Task GetAsync(AuthorizationContext authorization, Scope scope, Guid experienceId, CancellationToken cancellationToken) + { + Fail(cancellationToken); + + return Task.FromResult(_records.TryGetValue(experienceId, out var record) && record.Scope == scope + ? new ExperienceRecordGetResult(ExperienceStoreOutcome.Found, record, []) + : new ExperienceRecordGetResult(ExperienceStoreOutcome.NotFound, null, [])); + } + + public Task CommitLifecycleEventAsync( + AuthorizationContext authorization, + Scope scope, + LifecycleEvent lifecycleEvent, + CancellationToken cancellationToken) + { + Fail(cancellationToken); + + if (_events.TryGetValue(lifecycleEvent.EventId, out var stored)) + { + return Task.FromResult(stored.Event == lifecycleEvent + ? new ExperienceLifecycleCommitResult(ExperienceStoreOutcome.Committed, stored.Revision, null, []) + : new ExperienceLifecycleCommitResult(ExperienceStoreOutcome.Conflict, 0, null, [])); + } + + if (!_records.TryGetValue(lifecycleEvent.ExperienceRecordId, out var record) || record.Scope != scope) + { + return Task.FromResult(new ExperienceLifecycleCommitResult(ExperienceStoreOutcome.NotFound, 0, null, [])); + } + + if (record.Revision != lifecycleEvent.ExpectedRevision) + { + return Task.FromResult(new ExperienceLifecycleCommitResult(ExperienceStoreOutcome.StaleRevision, record.Revision, null, [])); + } + + if (lifecycleEvent.PriorStatus is { } prior && record.Status != prior) + { + return Task.FromResult(new ExperienceLifecycleCommitResult(ExperienceStoreOutcome.StatusMismatch, record.Revision, record.Status, [])); + } + + var revision = lifecycleEvent.ExpectedRevision + 1; + var confidence = lifecycleEvent.Confidence; + + _records[record.ExperienceId] = record with + { + Status = lifecycleEvent.CurrentStatus, + Revision = revision, + UpdatedAt = lifecycleEvent.OccurredAt, + ReuseConfidence = confidence?.NewReuseConfidence ?? record.ReuseConfidence, + SupportingValidations = confidence?.NewSupportingValidations ?? record.SupportingValidations, + Contradictions = confidence?.NewContradictions ?? record.Contradictions, + }; + + _events[lifecycleEvent.EventId] = (lifecycleEvent, revision); + + return Task.FromResult(new ExperienceLifecycleCommitResult( + ExperienceStoreOutcome.Committed, + revision, + lifecycleEvent.CurrentStatus, + [], + confidence)); + } + + public Task QueryAsync(AuthorizationContext authorization, ExperienceRecordQuery query, CancellationToken cancellationToken) => + throw new NotSupportedException("The telemetry loop never queries records."); + + public Task GetHistoryAsync(AuthorizationContext authorization, ExperienceRecordHistoryQuery query, CancellationToken cancellationToken) => + throw new NotSupportedException("The telemetry loop never reads history."); + + public Task CheckSupersessionAsync(AuthorizationContext authorization, Scope scope, Guid experienceId, Guid replacementExperienceId, CancellationToken cancellationToken) => + throw new NotSupportedException("The telemetry loop never supersedes a record."); + + /// + /// The scripted exception is checked before the token, so a test that cancels the caller + /// and scripts an still gets back the exact instance it + /// supplied -- which is what lets the classification table assert identity rather than type. + /// + private void Fail(CancellationToken cancellationToken) + { + OnCall?.Invoke(); + + if (Throws is { } thrower) + { + throw thrower(); + } + + cancellationToken.ThrowIfCancellationRequested(); + } +} + +/// A candidate source that answers with whatever the loop last committed. +internal sealed class LoopCandidateSource : IExperienceCandidateSource +{ + /// What the next search returns. + internal IReadOnlyList Candidates { get; set; } = []; + + /// The outcome the next search reports. Anything but Found is a refusal to answer. + internal ExperienceStoreOutcome Outcome { get; set; } = ExperienceStoreOutcome.Found; + + /// When set, every search throws this. + internal Func? Throws { get; set; } + + public Task SearchAsync(AuthorizationContext authorization, ExperienceCandidateQuery query, CancellationToken cancellationToken) + { + cancellationToken.ThrowIfCancellationRequested(); + + if (Throws is { } thrower) + { + throw thrower(); + } + + return Task.FromResult(new ExperienceCandidateSearchResult(Outcome, Candidates, [])); + } +} + +/// A reuse-feedback ledger that records every submission and reports it recorded. +internal sealed class LoopFeedbackStore : IExperienceReuseFeedbackStore +{ + /// Every submission the ledger was handed, in order. + internal List Submissions { get; } = []; + + /// When set, every write throws this. + internal Func? Throws { get; set; } + + public Task RecordAsync( + AuthorizationContext authorization, + RecordedExperienceReuseFeedback feedback, + CancellationToken cancellationToken) + { + cancellationToken.ThrowIfCancellationRequested(); + + if (Throws is { } thrower) + { + throw thrower(); + } + + Submissions.Add(feedback); + return Task.FromResult(new ExperienceReuseFeedbackStoreResult(ExperienceReuseFeedbackStoreOutcome.Recorded, feedback, [])); + } +} diff --git a/tests/AgentExperience.Core.Tests/Diagnostics/ExperienceTelemetryTests.cs b/tests/AgentExperience.Core.Tests/Diagnostics/ExperienceTelemetryTests.cs new file mode 100644 index 0000000..5dfb6f9 --- /dev/null +++ b/tests/AgentExperience.Core.Tests/Diagnostics/ExperienceTelemetryTests.cs @@ -0,0 +1,1374 @@ +using System.Diagnostics; +using AgentExperience.Core.Diagnostics; +using AgentExperience.Core.Feedback; +using AgentExperience.Core.Finalization; +using AgentExperience.Core.Indexing; +using AgentExperience.Core.Lifecycle; +using AgentExperience.Core.Retrieval; + +namespace AgentExperience.Core.Tests.Diagnostics; + +/// +/// What a host actually receives when it subscribes to AgentExperience.*: one span and one +/// count/duration pair per instrumented operation, a failure counter that only a thrown operation +/// moves, four metric dimensions and no more, a pinned set of span attributes, and -- the point of +/// the whole story -- not one byte of captured content anywhere in any of them. +/// +/// +/// Listeners are process-wide, so this class runs in the telemetry collection, on its own. Every test +/// asserts against the listener's own collected data rather than against the library's internals: if +/// an exporter would not see it, neither does a test here. +/// +[Collection(TelemetryCollection.Name)] +public class ExperienceTelemetryTests +{ + private const string CountInstrument = "agentexperience.operation.count"; + private const string DurationInstrument = "agentexperience.operation.duration"; + private const string FailuresInstrument = "agentexperience.operation.failures"; + + private const string OperationDimension = "operation"; + private const string OutcomeDimension = "outcome"; + private const string ErrorClassDimension = "error.class"; + private const string NestedDimension = "nested"; + + private const string OperationAttribute = "agentexperience.operation"; + private const string OutcomeAttribute = "agentexperience.outcome"; + private const string ErrorClassAttribute = "agentexperience.error.class"; + private const string ErrorTypeAttribute = "error.type"; + private const string StageAttribute = "agentexperience.stage"; + private const string CorrelationIdAttribute = "agentexperience.correlation_id"; + + private const string CoreSource = "AgentExperience.Core"; + + private const string Faulted = "Faulted"; + + /// + /// The frozen operation table: the operation dimension value, the span name it must carry, + /// and the outcome a fully successful drive of the loop reaches for it. Restated here as literals + /// rather than read from the library, so a rename in the library is a failing test rather than a + /// silently re-labelled dashboard. + /// + private static readonly (string Operation, string SpanName, string Outcome)[] FrozenTable = + [ + ("capture.start_run", "agentexperience.capture.start_run", nameof(StartRunOutcome.Started)), + ("capture.append_attempt", "agentexperience.capture.append_attempt", nameof(AppendAttemptOutcome.Recorded)), + ("capture.complete_run", "agentexperience.capture.complete_run", nameof(CompleteRunOutcome.Recorded)), + ("verify", "agentexperience.verify", nameof(TaskVerificationStatus.Verified)), + ("reflect", "agentexperience.reflect", nameof(TaskVerificationStatus.Verified)), + ("finalize", "agentexperience.finalize", nameof(FinalizationOutcome.Validated)), + ("lifecycle.commit", "agentexperience.lifecycle.commit", nameof(LifecycleTransitionOutcome.Committed)), + ("confidence.apply", "agentexperience.confidence.apply", nameof(ConfidenceUpdateOutcome.Applied)), + ("retrieve", "agentexperience.retrieve", nameof(RetrievalOutcome.Completed)), + ("index", "agentexperience.index", nameof(ExperienceIndexingOutcome.Indexed)), + ("deindex", "agentexperience.deindex", nameof(ExperienceDeindexingOutcome.Removed)), + ("reindex", "agentexperience.reindex", nameof(ExperienceReindexOutcome.Completed)), + ("reuse_feedback", "agentexperience.reuse_feedback", nameof(ExperienceReuseFeedbackOutcome.Recorded)), + ]; + + /// + /// Every span attribute this library is allowed to write, and nothing else. This is the span-side + /// counterpart of the exact metric-dimension set: the marker sweep can only prove that the content + /// one drive happened to carry stayed off a span, whereas an exact key set is what makes adding an + /// attribute that carries host free text a deliberate, reviewed act. + /// + private static readonly string[] AllowedSpanAttributes = + [ + ErrorClassAttribute, + CorrelationIdAttribute, + "agentexperience.attempt_id", + "agentexperience.event_id", + "agentexperience.experience_id", + OperationAttribute, + OutcomeAttribute, + "agentexperience.reflection_id", + "agentexperience.run_id", + StageAttribute, + ErrorTypeAttribute, + "agentexperience.feedback_id", + ]; + + /// + /// Where each documented identifier attribute must actually appear. Deleting the library's + /// SetTag calls used to leave every test passing, because the attributes were swept for the + /// marker and never asserted present. + /// + private static readonly (string SpanName, string Attribute)[] DocumentedIdentifiers = + [ + ("agentexperience.capture.start_run", "agentexperience.run_id"), + ("agentexperience.capture.append_attempt", "agentexperience.run_id"), + ("agentexperience.capture.append_attempt", "agentexperience.attempt_id"), + ("agentexperience.capture.complete_run", "agentexperience.run_id"), + ("agentexperience.capture.complete_run", "agentexperience.event_id"), + ("agentexperience.reflect", "agentexperience.run_id"), + ("agentexperience.reflect", "agentexperience.reflection_id"), + ("agentexperience.finalize", "agentexperience.run_id"), + ("agentexperience.finalize", "agentexperience.experience_id"), + ("agentexperience.finalize", StageAttribute), + ("agentexperience.lifecycle.commit", "agentexperience.experience_id"), + ("agentexperience.lifecycle.commit", "agentexperience.event_id"), + ("agentexperience.confidence.apply", "agentexperience.experience_id"), + ("agentexperience.confidence.apply", "agentexperience.event_id"), + ("agentexperience.retrieve", CorrelationIdAttribute), + ("agentexperience.index", "agentexperience.experience_id"), + ("agentexperience.deindex", "agentexperience.experience_id"), + ("agentexperience.reuse_feedback", "agentexperience.feedback_id"), + ("agentexperience.reuse_feedback", "agentexperience.run_id"), + ]; + + // --------------------------------------------------------------------------------------------- + // What a successful operation emits + // --------------------------------------------------------------------------------------------- + + [Fact] + public async Task Record_outcome_reaches_the_counter_and_histogram() + { + using var probe = TelemetryProbe.All(); + var loop = new ExperienceLoop(); + + var results = await loop.DriveAsync(); + + // The loop really did run end to end; otherwise an operation with no measurement would be + // indistinguishable from an operation that never happened. + Assert.Equal(FinalizationOutcome.Validated, results.Finalized.Outcome); + Assert.Equal(RetrievalOutcome.Completed, results.Retrieved.Outcome); + Assert.Equal(ExperienceReuseFeedbackOutcome.Recorded, results.Feedback.Outcome); + Assert.Equal(ExperienceDeindexingOutcome.Removed, results.Deindexed.Outcome); + + foreach (var (operation, spanName, outcome) in FrozenTable) + { + var counted = probe.For(CountInstrument, operation); + var timed = probe.For(DurationInstrument, operation); + + Assert.NotEmpty(counted); + Assert.NotEmpty(timed); + + // Every measurement for this operation carries the operation's own outcome enum member + // name, verbatim -- not a description, not a lower-cased alias, not "ok". + Assert.All(counted, measurement => + { + Assert.Equal(1d, measurement.Value); + Assert.Equal(outcome, Assert.IsType(measurement.Tags[OutcomeDimension])); + Assert.Equal(CoreSource, measurement.Meter); + }); + + Assert.All(timed, measurement => + { + Assert.True(measurement.Value >= 0d, $"'{operation}' recorded a negative duration."); + Assert.Equal(outcome, Assert.IsType(measurement.Tags[OutcomeDimension])); + }); + + var spans = probe.LibraryActivities.Where(activity => activity.OperationName == spanName).ToList(); + Assert.NotEmpty(spans); + Assert.All(spans, span => + { + Assert.Equal(ActivityStatusCode.Ok, span.Status); + Assert.Equal(operation, span.GetTagItem(OperationAttribute)); + Assert.Equal(outcome, span.GetTagItem(OutcomeAttribute)); + }); + } + + // Nothing threw, so the failure counter was never touched at all. + Assert.Empty(probe.For(FailuresInstrument)); + } + + [Fact] + public async Task Every_library_span_is_named_from_the_frozen_table() + { + using var probe = TelemetryProbe.All(); + + await new ExperienceLoop().DriveAsync(); + + var allowed = FrozenTable.Select(entry => entry.SpanName).ToHashSet(StringComparer.Ordinal); + Assert.NotEmpty(probe.LibraryActivities); + Assert.All(probe.LibraryActivities, activity => + Assert.True(allowed.Contains(activity.OperationName), $"'{activity.OperationName}' is not in the frozen operation table.")); + } + + /// + /// The exact call table one drive of the loop produces, nesting included. Several operations are + /// steps of a larger one -- a finalization verifies, reflects, commits the record's initial + /// lifecycle event and indexes it; a reuse-feedback submission applies confidence evidence per + /// exposed record; a one-record index runs a one-record re-index pass -- and every one of them is + /// emitted, because an inner step that emits nothing is an inner step whose failures reach no + /// alert. nested is what keeps the two questions apart, so this pins both halves: how many + /// calls the host made, and how many the library made under them. + /// + [Fact] + public async Task One_call_to_an_operation_is_one_count_and_one_duration() + { + using var probe = TelemetryProbe.All(); + var loop = new ExperienceLoop(); + + var results = await loop.DriveAsync(); + Assert.Equal(FinalizationOutcome.Validated, results.Finalized.Outcome); + + // "operation nested=x" -> how many counts carried it. Written out in full rather than as a + // per-operation total, so that moving a call between the direct and the nested column is a + // failing test rather than an invisible re-labelling of somebody's dashboard. + var expected = new[] + { + "capture.append_attempt nested=False x2", + "capture.complete_run nested=False x1", + "capture.start_run nested=False x1", + "confidence.apply nested=False x1", + "confidence.apply nested=True x1", + "deindex nested=False x1", + "finalize nested=False x1", + "index nested=False x1", + "index nested=True x1", + "lifecycle.commit nested=False x1", + "lifecycle.commit nested=True x1", + "reflect nested=True x1", + "reindex nested=False x1", + "reindex nested=True x2", + "retrieve nested=False x1", + "reuse_feedback nested=False x1", + "verify nested=False x1", + "verify nested=True x1", + }; + + Assert.Equal(expected, Calls(probe, CountInstrument)); + + // The histogram is written from the same tag list as the counter, so one call is one count and + // one duration under the same dimensions -- not merely the same number of them. + Assert.Equal(expected, Calls(probe, DurationInstrument)); + + // `reflect` is no longer an exception to anything. The reflector is an injected port called + // from inside a finalization, and it reports exactly what the private-sibling siblings report: + // one nested operation, which is the real call graph. + Assert.Empty(probe.For(CountInstrument, "reflect", nested: false)); + Assert.Single(probe.For(CountInstrument, "reflect", nested: true)); + } + + /// + /// The nested dimension itself: the same operation, called by the host and called by + /// another instrumented operation, is one series an operator can split. Without it, the only way + /// to stop a finalization from counting as seven operations was to stop emitting six of them. + /// + [Fact] + public async Task A_direct_call_is_not_nested_and_the_same_operation_inside_finalize_is() + { + using var probe = TelemetryProbe.All(); + var loop = new ExperienceLoop(); + + var results = await loop.DriveAsync(); + Assert.Equal(FinalizationOutcome.Validated, results.Finalized.Outcome); + + // Every operation the drive calls directly is exactly that -- whatever else it does inside. + foreach (var operation in new[] { "capture.start_run", "finalize", "retrieve", "reuse_feedback", "deindex" }) + { + Assert.NotEmpty(probe.For(CountInstrument, operation, nested: false)); + Assert.Empty(probe.For(CountInstrument, operation, nested: true)); + } + + // And the four the drive calls both ways are on both sides of the dimension: one direct call + // from the test, one from inside the operation that contains it. + foreach (var operation in new[] { "verify", "lifecycle.commit", "index", "confidence.apply" }) + { + Assert.Single(probe.For(CountInstrument, operation, nested: false)); + Assert.Single(probe.For(CountInstrument, operation, nested: true)); + } + + // The nested ones really are children of the operation that called them, so the trace says the + // same thing the dimension does -- which is why `nested` is a metric dimension only. + var finalize = Assert.Single(probe.LibraryActivities, a => a.OperationName == "agentexperience.finalize"); + var nested = probe.LibraryActivities + .Where(a => a.Parent is not null && a.Parent.Id == finalize.Id) + .Select(a => a.OperationName) + .Order(StringComparer.Ordinal); + + Assert.Equal( + new[] + { + "agentexperience.index", + "agentexperience.lifecycle.commit", + "agentexperience.reflect", + "agentexperience.verify", + }, + nested); + } + + [Fact] + public async Task The_span_carries_the_host_correlation_id_and_omits_it_when_there_is_none() + { + using var probe = TelemetryProbe.SpansOnly(); + var loop = new ExperienceLoop(); + await loop.DriveAsync(); + + var withId = Assert.Single(probe.LibraryActivities, a => a.OperationName == "agentexperience.retrieve"); + Assert.Equal(ExperienceLoop.CorrelationId, withId.GetTagItem(CorrelationIdAttribute)); + + await loop.Retrieval.RetrieveAsync( + new RetrieveExperienceRequest(ExperienceLoop.Authorization, ExperienceLoop.Scope, "a task with no correlation id")); + + var withoutId = probe.LibraryActivities.Last(a => a.OperationName == "agentexperience.retrieve"); + + // Omitted, not blank: an absent attribute and an empty one do not mean the same thing. + Assert.Null(withoutId.GetTagItem(CorrelationIdAttribute)); + Assert.DoesNotContain(withoutId.TagObjects, tag => tag.Key == CorrelationIdAttribute); + } + + /// + /// Matrix row 11: a retrieval that ran out of time is a returned decision, and the correlation ID + /// is on its span -- which is the whole point of reading the identifier off the request + /// rather than off a result that a slow or throwing retrieval may never produce. + /// + [Fact] + public async Task A_timed_out_retrieval_still_echoes_the_correlation_id() + { + using var probe = TelemetryProbe.All(); + + var released = new TaskCompletionSource(); + var candidates = new SlowCandidateSource(released); + var retrieval = new ExperienceRetrievalService( + candidates, + RetrievalPolicy.Default with { Timeout = TimeSpan.FromMilliseconds(20) }, + RankingWeights.Default, + TimeProvider.System); + + var result = await retrieval.RetrieveAsync(new RetrieveExperienceRequest( + ExperienceLoop.Authorization, + ExperienceLoop.Scope, + "a task whose candidate source never answers", + RequiredEnvironmentAttributes: null, + CorrelationId: ExperienceLoop.CorrelationId)); + + released.TrySetResult(); + + Assert.Equal(RetrievalOutcome.TimedOut, result.Outcome); + + var span = Assert.Single(probe.LibraryActivities, a => a.OperationName == "agentexperience.retrieve"); + Assert.Equal(ExperienceLoop.CorrelationId, span.GetTagItem(CorrelationIdAttribute)); + + // A timeout is a decision, not a failure: Ok status, the real outcome name, no failure count. + Assert.Equal(ActivityStatusCode.Ok, span.Status); + Assert.Equal(nameof(RetrievalOutcome.TimedOut), span.GetTagItem(OutcomeAttribute)); + Assert.Equal( + nameof(RetrievalOutcome.TimedOut), + Assert.Single(probe.For(CountInstrument, "retrieve")).Tags[OutcomeDimension]); + Assert.Empty(probe.For(FailuresInstrument)); + + // ...and it is on the span only, never on a measurement: the host owns that string. + Assert.DoesNotContain(ExperienceLoop.CorrelationId, probe.EveryMeasurementTagValue); + } + + /// + /// A retrieval that threw carries the correlation ID too. Before it was read from the request, + /// exactly the span an operator opens first -- the one that failed -- was the one that could not + /// say which invocation it belonged to. + /// + [Fact] + public async Task A_thrown_retrieval_still_echoes_the_correlation_id() + { + using var probe = TelemetryProbe.All(); + var loop = new ExperienceLoop(); + + using var cancellation = new CancellationTokenSource(); + await cancellation.CancelAsync(); + + await Assert.ThrowsAnyAsync(() => loop.Retrieval.RetrieveAsync( + new RetrieveExperienceRequest( + ExperienceLoop.Authorization, + ExperienceLoop.Scope, + "a task the caller gave up on", + RequiredEnvironmentAttributes: null, + CorrelationId: ExperienceLoop.CorrelationId), + cancellation.Token)); + + var span = Assert.Single(probe.LibraryActivities, a => a.OperationName == "agentexperience.retrieve"); + Assert.Equal(ActivityStatusCode.Error, span.Status); + Assert.Equal(ExperienceLoop.CorrelationId, span.GetTagItem(CorrelationIdAttribute)); + } + + // --------------------------------------------------------------------------------------------- + // The span attribute set + // --------------------------------------------------------------------------------------------- + + [Fact] + public async Task Span_attributes_are_only_the_documented_keys() + { + using var probe = TelemetryProbe.All(); + var loop = new ExperienceLoop(); + + await loop.DriveAsync(); + + // Plus one thrown operation, so error.type and error.class have been written by the time the + // keys are collected and the exact set below is not an accident of the happy path. + loop.Store.Throws = () => new ExperienceStoreException("the database is unreachable"); + await Assert.ThrowsAsync(() => loop.Lifecycle.CommitAsync( + ExperienceLoop.Authorization, + new CommitLifecycleTransitionRequest( + Guid.NewGuid(), Guid.NewGuid(), ExperienceLoop.Scope, ExperienceStatus.Candidate, + ExperienceStatus.Validated, "initial", "tests", ExperienceLoop.Now, 0), + CancellationToken.None)); + + // Exactly these, no more: a new attribute has to be added here on purpose. + Assert.Equal( + AllowedSpanAttributes.Order(StringComparer.Ordinal), + probe.EverySpanTagKey.Order(StringComparer.Ordinal)); + + // And every documented identifier is really written where it is documented, with a value. + // Without this half, deleting every identifier SetTag call in the library passes. + foreach (var (spanName, attribute) in DocumentedIdentifiers) + { + var span = probe.LibraryActivities.FirstOrDefault(activity => activity.OperationName == spanName); + Assert.True(span is not null, $"No '{spanName}' span was emitted at all."); + + var value = span!.GetTagItem(attribute) as string; + Assert.True( + !string.IsNullOrWhiteSpace(value), + $"'{spanName}' carries no '{attribute}'."); + } + } + + // --------------------------------------------------------------------------------------------- + // A decision is not a failure + // --------------------------------------------------------------------------------------------- + + [Fact] + public async Task Rejection_outcomes_do_not_increment_failures() + { + using var probe = TelemetryProbe.All(); + var loop = new ExperienceLoop(); + + // A retrieval refused before either channel is touched. RetrievalOutcome has no + // "NoCandidates" member (the spec's example names one that does not exist); Denied and Failed + // are the two returned-rather-than-thrown refusals this service actually produces. + var denied = await loop.Retrieval.RetrieveAsync(new RetrieveExperienceRequest( + new AuthorizationContext("tenant-2", "other-principal", ["experience:read"], ExperienceLoop.Now), + ExperienceLoop.Scope, + "a task in a scope the host does not cover")); + + loop.Candidates.Outcome = ExperienceStoreOutcome.Denied; + var failed = await loop.Retrieval.RetrieveAsync(new RetrieveExperienceRequest( + ExperienceLoop.Authorization, + ExperienceLoop.Scope, + "a task whose candidate source refuses to answer")); + + // A transition the table refuses: Core never calls the store at all. + var refused = await loop.Lifecycle.CommitAsync( + ExperienceLoop.Authorization, + new CommitLifecycleTransitionRequest( + EventId: Guid.NewGuid(), + ExperienceId: Guid.NewGuid(), + Scope: ExperienceLoop.Scope, + PriorStatus: ExperienceStatus.Revoked, + CurrentStatus: ExperienceStatus.Validated, + Reason: "a revoked record cannot be validated again", + Producer: "tests", + OccurredAt: ExperienceLoop.Now, + ExpectedRevision: 3), + CancellationToken.None); + + Assert.Equal(RetrievalOutcome.Denied, denied.Outcome); + Assert.Equal(RetrievalOutcome.Failed, failed.Outcome); + Assert.Equal(LifecycleTransitionOutcome.TransitionNotAllowed, refused.Outcome); + + // The decisions are counted and timed under their own outcome names... + Assert.Contains(probe.For(CountInstrument, "retrieve"), m => Equals(m.Tags[OutcomeDimension], nameof(RetrievalOutcome.Denied))); + Assert.Contains(probe.For(CountInstrument, "retrieve"), m => Equals(m.Tags[OutcomeDimension], nameof(RetrievalOutcome.Failed))); + Assert.Contains(probe.For(DurationInstrument, "lifecycle.commit"), m => Equals(m.Tags[OutcomeDimension], nameof(LifecycleTransitionOutcome.TransitionNotAllowed))); + + // ...their spans are Ok, because a refusal is an answer... + Assert.All(probe.LibraryActivities, activity => Assert.Equal(ActivityStatusCode.Ok, activity.Status)); + + // ...and nothing anywhere was recorded as a failure. + Assert.Empty(probe.For(FailuresInstrument)); + Assert.All(probe.Measurements, m => Assert.False(m.Tags.ContainsKey(ErrorClassDimension))); + } + + /// + /// The outcome dimension is the operation's own enum member, on the paths that did + /// not succeed as well as on the ones that did. Verified only on success, three + /// hardcoded success literals in place of result.Outcome.ToString() went undetected. + /// + /// The operation whose rejection is driven. + [Theory] + [InlineData("capture.start_run")] + [InlineData("capture.append_attempt")] + [InlineData("capture.complete_run")] + [InlineData("verify")] + [InlineData("reflect")] + [InlineData("finalize")] + [InlineData("lifecycle.commit")] + [InlineData("confidence.apply")] + [InlineData("retrieve")] + [InlineData("index")] + [InlineData("deindex")] + [InlineData("reindex")] + [InlineData("reuse_feedback")] + public async Task A_rejection_is_reported_under_its_own_outcome_name(string operation) + { + var loop = new ExperienceLoop(); + + // Arranged before anything is listening, so the only measurements collected are the rejection's. + var arranged = await loop.DriveAsync(); + + using var probe = TelemetryProbe.All(); + var rejected = await RejectAsync(loop, arranged, operation); + + var success = FrozenTable.Single(entry => entry.Operation == operation).Outcome; + Assert.NotEqual(success, rejected); + + var counted = Assert.Single(probe.For(CountInstrument, operation)); + Assert.Equal(rejected, Assert.IsType(counted.Tags[OutcomeDimension])); + Assert.Equal(rejected, Assert.Single(probe.For(DurationInstrument, operation)).Tags[OutcomeDimension]); + + var span = Assert.Single(probe.LibraryActivities, a => a.OperationName == "agentexperience." + operation); + Assert.Equal(ActivityStatusCode.Ok, span.Status); + Assert.Equal(rejected, span.GetTagItem(OutcomeAttribute)); + + // A decision, however unwelcome, is never a failure. + Assert.Empty(probe.For(FailuresInstrument)); + } + + // --------------------------------------------------------------------------------------------- + // Failures + // --------------------------------------------------------------------------------------------- + + /// + /// Matrix rows 6-10, per operation. Covering only lifecycle.commit left twelve of thirteen + /// fault paths entirely unexercised: making Faulted a no-op everywhere else passed. + /// + /// The operation to make throw. + /// How to make it throw. port-* kinds script an exception instance into a port. + /// The bounded class the failure must be reported under. + [Theory] + [InlineData("capture.start_run", "argument", nameof(ExperienceOperationErrorClass.Unexpected))] + [InlineData("capture.append_attempt", "argument", nameof(ExperienceOperationErrorClass.Unexpected))] + [InlineData("capture.append_attempt", "cancelled", nameof(ExperienceOperationErrorClass.Cancelled))] + [InlineData("capture.complete_run", "cancelled", nameof(ExperienceOperationErrorClass.Cancelled))] + [InlineData("verify", "argument", nameof(ExperienceOperationErrorClass.Unexpected))] + [InlineData("verify", "cancelled", nameof(ExperienceOperationErrorClass.Cancelled))] + [InlineData("reflect", "argument", nameof(ExperienceOperationErrorClass.Unexpected))] + [InlineData("reflect", "cancelled", nameof(ExperienceOperationErrorClass.Cancelled))] + [InlineData("finalize", "argument", nameof(ExperienceOperationErrorClass.Unexpected))] + [InlineData("finalize", "cancelled", nameof(ExperienceOperationErrorClass.Cancelled))] + [InlineData("finalize", "port-cancelled-by-nobody", nameof(ExperienceOperationErrorClass.Infrastructure))] + [InlineData("lifecycle.commit", "cancelled", nameof(ExperienceOperationErrorClass.Cancelled))] + [InlineData("lifecycle.commit", "port-store", nameof(ExperienceOperationErrorClass.Infrastructure))] + [InlineData("lifecycle.commit", "port-cancelled-by-nobody", nameof(ExperienceOperationErrorClass.Infrastructure))] + [InlineData("lifecycle.commit", "port-timeout", nameof(ExperienceOperationErrorClass.Timeout))] + [InlineData("lifecycle.commit", "port-unexpected", nameof(ExperienceOperationErrorClass.Unexpected))] + [InlineData("confidence.apply", "cancelled", nameof(ExperienceOperationErrorClass.Cancelled))] + [InlineData("confidence.apply", "port-store", nameof(ExperienceOperationErrorClass.Infrastructure))] + [InlineData("confidence.apply", "port-timeout", nameof(ExperienceOperationErrorClass.Timeout))] + [InlineData("confidence.apply", "port-unexpected", nameof(ExperienceOperationErrorClass.Unexpected))] + [InlineData("retrieve", "argument", nameof(ExperienceOperationErrorClass.Unexpected))] + [InlineData("retrieve", "cancelled", nameof(ExperienceOperationErrorClass.Cancelled))] + [InlineData("index", "argument", nameof(ExperienceOperationErrorClass.Unexpected))] + [InlineData("index", "cancelled", nameof(ExperienceOperationErrorClass.Cancelled))] + [InlineData("index", "port-cancelled-by-nobody", nameof(ExperienceOperationErrorClass.Infrastructure))] + [InlineData("deindex", "argument", nameof(ExperienceOperationErrorClass.Unexpected))] + [InlineData("reindex", "argument", nameof(ExperienceOperationErrorClass.Unexpected))] + [InlineData("reindex", "cancelled", nameof(ExperienceOperationErrorClass.Cancelled))] + [InlineData("reindex", "port-cancelled-by-nobody", nameof(ExperienceOperationErrorClass.Infrastructure))] + [InlineData("reuse_feedback", "cancelled", nameof(ExperienceOperationErrorClass.Cancelled))] + [InlineData("reuse_feedback", "port-store", nameof(ExperienceOperationErrorClass.Infrastructure))] + [InlineData("reuse_feedback", "port-timeout", nameof(ExperienceOperationErrorClass.Timeout))] + [InlineData("reuse_feedback", "port-unexpected", nameof(ExperienceOperationErrorClass.Unexpected))] + public async Task Error_classification_table(string operation, string kind, string expectedErrorClass) + { + var loop = new ExperienceLoop(); + + // Arranged unlistened, so the only telemetry collected below belongs to the failure. + var arranged = await loop.DriveAsync(); + + using var cancellation = new CancellationTokenSource(); + if (kind == "cancelled") + { + await cancellation.CancelAsync(); + } + + var scripted = Scripted(kind); + Arm(loop, kind, scripted); + + using var probe = TelemetryProbe.All(); + + var propagated = await Assert.ThrowsAnyAsync( + () => FaultAsync(loop, arranged, operation, kind, cancellation.Token)); + + if (scripted is not null) + { + // The wrapper observed the failure and rethrew the very same object: no wrapping, no + // re-creation, no swallowing. + Assert.Same(scripted, propagated); + } + + var failure = Assert.Single(probe.For(FailuresInstrument, operation)); + Assert.Equal(1d, failure.Value); + Assert.Equal(expectedErrorClass, Assert.IsType(failure.Tags[ErrorClassDimension])); + + // A faulted operation is still counted and timed, under the literal "Faulted". + Assert.Equal(Faulted, Assert.Single(probe.For(CountInstrument, operation)).Tags[OutcomeDimension]); + Assert.Single(probe.For(DurationInstrument, operation)); + + var span = Assert.Single(probe.LibraryActivities, a => a.OperationName == "agentexperience." + operation); + Assert.Equal(ActivityStatusCode.Error, span.Status); + Assert.Equal(expectedErrorClass, span.GetTagItem(ErrorClassAttribute)); + Assert.Equal(propagated.GetType().FullName, span.GetTagItem(ErrorTypeAttribute)); + Assert.Equal(Faulted, span.GetTagItem(OutcomeAttribute)); + } + + /// + /// The identifiers a failing span carries. They are read from the request, before the call, so a + /// span that records a throw can still say what it was operating on. + /// + [Fact] + public async Task A_faulted_span_still_identifies_what_it_was_operating_on() + { + using var probe = TelemetryProbe.SpansOnly(); + var loop = new ExperienceLoop(); + + var experienceId = Guid.NewGuid(); + var eventId = Guid.NewGuid(); + loop.Store.Throws = () => new ExperienceStoreException("the database is unreachable"); + + await Assert.ThrowsAsync(() => loop.Lifecycle.CommitAsync( + ExperienceLoop.Authorization, + new CommitLifecycleTransitionRequest( + eventId, experienceId, ExperienceLoop.Scope, ExperienceStatus.Candidate, + ExperienceStatus.Validated, "initial", "tests", ExperienceLoop.Now, 0), + CancellationToken.None)); + + var span = Assert.Single(probe.LibraryActivities); + Assert.Equal(ActivityStatusCode.Error, span.Status); + Assert.Equal(experienceId.ToString("D"), span.GetTagItem("agentexperience.experience_id")); + Assert.Equal(eventId.ToString("D"), span.GetTagItem("agentexperience.event_id")); + } + + /// + /// A finalization that threw says which stage was in flight. Written on success only, an operator + /// looking at the one span that mattered could not tell whether the record had been written before + /// the call stopped. + /// + [Fact] + public async Task A_faulted_finalization_carries_the_stage_it_reached() + { + var loop = new ExperienceLoop(); + var arranged = await loop.DriveAsync(); + + using var probe = TelemetryProbe.All(); + + // The store cancels for its own reasons at the CreateRecord stage: the caller never asked, so + // the stage the span reports is the one the body had actually got to. + loop.Store.Throws = () => new OperationCanceledException("a driver-side timeout nobody asked for"); + + await Assert.ThrowsAnyAsync(() => loop.Finalization.FinalizeAsync( + FinalizeRequest(arranged.RunId), + CancellationToken.None)); + + var span = Assert.Single(probe.LibraryActivities, a => a.OperationName == "agentexperience.finalize"); + Assert.Equal(ActivityStatusCode.Error, span.Status); + Assert.Equal(nameof(FinalizationStage.CreateRecord), span.GetTagItem(StageAttribute)); + Assert.Equal(arranged.RunId.ToString("D"), span.GetTagItem("agentexperience.run_id")); + Assert.Equal( + nameof(ExperienceOperationErrorClass.Infrastructure), + Assert.Single(probe.For(FailuresInstrument, "finalize")).Tags[ErrorClassDimension]); + } + + [Fact] + public async Task A_failing_span_carries_the_exception_type_but_nothing_the_exception_said() + { + using var probe = TelemetryProbe.All(); + var loop = new ExperienceLoop(); + + const string secret = "connection string: Host=db;Password=hunter2"; + loop.Store.Throws = () => new ExperienceStoreException(secret); + + await Assert.ThrowsAsync(() => loop.Lifecycle.CommitAsync( + ExperienceLoop.Authorization, + new CommitLifecycleTransitionRequest( + Guid.NewGuid(), Guid.NewGuid(), ExperienceLoop.Scope, ExperienceStatus.Candidate, + ExperienceStatus.Validated, "initial", "tests", ExperienceLoop.Now, 0), + CancellationToken.None)); + + Assert.Equal("AgentExperience.Abstractions.ExperienceStoreException", Assert.Single(probe.LibraryActivities).GetTagItem(ErrorTypeAttribute)); + Assert.DoesNotContain(probe.EverySpanTagValue, value => value.Contains("hunter2", StringComparison.Ordinal)); + Assert.DoesNotContain(probe.EveryMeasurementTagValue, value => value.Contains("hunter2", StringComparison.Ordinal)); + + // And no exception event was attached to the span either: Activity.AddException would have + // carried the message onto it as an event rather than as a tag. + Assert.Empty(Assert.Single(probe.LibraryActivities).Events); + } + + /// + /// A hung embedding provider inside the post-commit indexing hook is the failure this whole + /// dimension exists for. The hook runs on a budget this library imposed, not on the caller's + /// token, so the wrapper must report the budget expiring as a + /// -- never as + /// , the one class whose own documentation + /// says it is normally not alertable -- and it must report it at all, which routing the + /// hook past the instrumented entry point silently stopped it doing. + /// + [Fact] + public async Task A_library_imposed_indexing_budget_is_never_reported_as_caller_cancellation() + { + using var probe = TelemetryProbe.All(); + + var gate = new TaskCompletionSource(); + var generator = new FakeEmbeddingGenerator { Gate = gate }; + var index = new FakeEmbeddingIndex(); + var indexing = new ExperienceIndexingService(index, generator); + var store = new LoopRecordStore(); + var lifecycle = new ExperienceLifecycleService(store, indexing); + var capture = new InMemoryExperienceCaptureService( + new DefaultSanitizer(SanitizationOptions.Empty), + new CaptureLimits(8, 8, 1_000, 1_000)); + var finalization = new ExperienceFinalizationService( + capture, + new DefaultExperienceReflector(), + store, + lifecycle, + indexing, + indexingTimeout: TimeSpan.FromMilliseconds(30)); + + var runId = Guid.NewGuid(); + capture.StartRun( + runId, + "task-1", + "a task", + ExperienceLoop.Scope, + new EnvironmentFingerprint("host-1", "net10.0", "linux", "1.0.0", new Dictionary()), + new Provenance("tests", "1.0.0", ExperienceLoop.Now, null), + ExperienceLoop.Now); + await capture.AppendAttemptAsync( + runId, + new AppendAttemptRequest(Guid.NewGuid(), ExperienceLoop.Now, TimeSpan.FromSeconds(1), [], "done", null)); + await capture.CompleteRunAsync(runId, Guid.NewGuid(), RunExecutionStatus.Completed, ExperienceLoop.Now.AddSeconds(3)); + + var experienceId = ExperienceFinalizationService.ExperienceIdFor(runId); + index.Records[experienceId] = new FakeEmbeddingIndex.Row(1, "a retrieval summary"); + + var finalized = await finalization.FinalizeAsync(FinalizeRequest(runId), CancellationToken.None); + gate.TrySetResult(); + + // The record is durable and the hung provider was abandoned on this library's own budget... + Assert.Equal(FinalizationOutcome.Validated, finalized.Outcome); + Assert.Equal(ExperienceIndexingOutcome.IndexFailed, finalized.Indexing!.Outcome); + + // ...the failure reached the counter, as a nested operation, which is the signal a host pages + // on. Routing the hook past the wrapper removed it entirely: not misclassified, uncounted. + var failures = probe.For(FailuresInstrument); + Assert.NotEmpty(failures); + Assert.All(failures, failure => + { + Assert.Equal(true, failure.Tags[NestedDimension]); + Assert.Equal(nameof(ExperienceOperationErrorClass.Timeout), failure.Tags[ErrorClassDimension]); + }); + + Assert.Single(probe.For(FailuresInstrument, "index", nested: true)); + Assert.Single(probe.For(FailuresInstrument, "reindex", nested: true)); + + // ...and nothing anywhere was reported as the caller having cancelled, because the caller + // never did. The finalization it happened inside succeeded, and is counted as a success. + Assert.DoesNotContain( + nameof(ExperienceOperationErrorClass.Cancelled), + probe.EveryMeasurementTagValue); + Assert.Equal( + nameof(FinalizationOutcome.Validated), + Assert.Single(probe.For(CountInstrument, "finalize")).Tags[OutcomeDimension]); + } + + /// + /// The other half of the same signal: a provider that throws rather than hangs is a + /// returned failure, so it never touches the failure counter -- but the nested index + /// is still counted and timed under the outcome it reached, which is the only way an operator sees + /// that the vector channel stopped working behind a finalization that keeps reporting success. + /// + [Fact] + public async Task A_throwing_embedding_provider_inside_the_post_commit_hook_is_still_a_nested_operation() + { + var loop = new ExperienceLoop(); + + using var probe = TelemetryProbe.All(); + loop.Generator.Throws = FakeEmbeddingGenerator.ThrownException; + + var results = await loop.DriveAsync(); + + // The record was written and the caller was told finalization worked, because it did: an + // embedding is derived data and a provider being down never fails a canonical write. + Assert.Equal(FinalizationOutcome.Validated, results.Finalized.Outcome); + Assert.Equal(ExperienceIndexingOutcome.ProviderFailed, results.Finalized.Indexing!.Outcome); + + var hook = Assert.Single(probe.For(CountInstrument, "index", nested: true)); + Assert.Equal(nameof(ExperienceIndexingOutcome.ProviderFailed), hook.Tags[OutcomeDimension]); + Assert.Single(probe.For(DurationInstrument, "index", nested: true)); + + // A reported outcome is a decision, not a throw, so the failure counter stays untouched -- + // and the operator's alert is the ProviderFailed rate, which now exists. + Assert.Empty(probe.For(FailuresInstrument)); + } + + // --------------------------------------------------------------------------------------------- + // Execution never depends on a listener + // --------------------------------------------------------------------------------------------- + + [Fact] + public async Task No_listener_produces_identical_results() + { + var unlistened = new ExperienceLoop(); + var observedWithoutListener = new List(); + unlistened.Store.OnCall = () => observedWithoutListener.Add(Activity.Current); + + Assert.Null(Activity.Current); + var without = await unlistened.DriveAsync(); + Assert.Null(Activity.Current); + + // Nothing was listening, so nothing was created -- observed from the bottom of the call stack, + // inside the store, not from out here. + Assert.NotEmpty(observedWithoutListener); + Assert.All(observedWithoutListener, Assert.Null); + + var listened = new ExperienceLoop(); + var observedWithListener = new List(); + listened.Store.OnCall = () => observedWithListener.Add(Activity.Current); + + LoopResults with; + using (var probe = TelemetryProbe.All()) + { + with = await listened.DriveAsync(); + + // The check above is not vacuous: with a listener the very same observation point sees a + // live span. + Assert.Contains(observedWithListener, activity => activity is not null); + Assert.NotEmpty(probe.LibraryActivities); + Assert.NotEmpty(probe.Measurements); + } + + // And the span was closed behind us, leaving the caller's ambient activity exactly as it was. + Assert.Null(Activity.Current); + + // The whole result of every operation, compared structurally rather than field by hand. A + // hand-picked subset is what let rewriting the retrieval result under a listener pass: the + // listener-independence claim is this story's headline invariant and nothing about a result + // may differ, not just the fields somebody thought to list. + Assert.Equal(Normalize(without), Normalize(with)); + } + + [Fact] + public async Task An_activity_listener_alone_produces_spans_and_no_measurements() + { + using var spansOnly = TelemetryProbe.SpansOnly(); + + var results = await new ExperienceLoop().DriveAsync(); + + Assert.Equal(FinalizationOutcome.Validated, results.Finalized.Outcome); + Assert.NotEmpty(spansOnly.LibraryActivities); + Assert.Empty(spansOnly.Measurements); + + // The positive control the emptiness above needs. A probe with no MeterListener collects no + // measurements whatever the library does, so on its own that assertion cannot fail. With a + // MeterListener registered, the very same drive of the very same instruments does produce + // them -- so the emptiness is the absent listener, not an instrument nothing ever writes to. + using var full = TelemetryProbe.All(); + var again = await new ExperienceLoop().DriveAsync(); + + Assert.Equal(FinalizationOutcome.Validated, again.Finalized.Outcome); + Assert.NotEmpty(full.Measurements); + Assert.NotEmpty(full.LibraryActivities); + } + + [Fact] + public async Task A_meter_listener_alone_produces_measurements_and_no_spans() + { + var loop = new ExperienceLoop(); + var observed = new List(); + loop.Store.OnCall = () => observed.Add(Activity.Current); + + using (var metricsOnly = TelemetryProbe.MetricsOnly()) + { + var results = await loop.DriveAsync(); + + Assert.Equal(FinalizationOutcome.Validated, results.Finalized.Outcome); + Assert.NotEmpty(metricsOnly.Measurements); + + // Not "the probe collected no spans" -- which a probe with no ActivityListener cannot fail + // to report -- but "the library started none", observed from the bottom of the call stack + // where an Activity would have been ambient had one been created. + Assert.NotEmpty(observed); + Assert.All(observed, Assert.Null); + Assert.Empty(metricsOnly.Activities); + } + + // The positive control: the same observation point, with an ActivityListener registered, sees + // a live span. So the nulls above are the absent listener and not a dead observation hook. + var listened = new ExperienceLoop(); + var withListener = new List(); + listened.Store.OnCall = () => withListener.Add(Activity.Current); + + using var full = TelemetryProbe.All(); + await listened.DriveAsync(); + + Assert.Contains(withListener, activity => activity is not null); + Assert.NotEmpty(full.LibraryActivities); + } + + [Fact] + public async Task A_sampler_that_declines_still_records_measurements() + { + using var probe = TelemetryProbe.Declining(); + + var results = await new ExperienceLoop().DriveAsync(); + + // StartActivity returned null for every operation, so every ?.SetTag was a no-op... + Assert.Empty(probe.Activities); + + // ...and neither the measurements nor the results noticed. + Assert.NotEmpty(probe.For(CountInstrument)); + Assert.Equal(FinalizationOutcome.Validated, results.Finalized.Outcome); + Assert.Equal(RetrievalOutcome.Completed, results.Retrieved.Outcome); + } + + [Fact] + public async Task The_meter_publishes_exactly_the_three_frozen_instruments() + { + using var probe = TelemetryProbe.All(); + + await new ExperienceLoop().DriveAsync(); + + var published = probe.PublishedInstruments + .Where(instrument => instrument.Meter.Name == CoreSource) + .ToList(); + + Assert.Equal( + new[] { CountInstrument, DurationInstrument, FailuresInstrument }, + published.Select(instrument => instrument.Name).Order(StringComparer.Ordinal)); + + // Per-operation instrument names are deliberately not used: cardinality is identical either + // way, and one closed dimension cannot drift where fourteen instrument names can. + Assert.Equal("s", published.Single(instrument => instrument.Name == DurationInstrument).Unit); + Assert.Equal("{operation}", published.Single(instrument => instrument.Name == CountInstrument).Unit); + Assert.Equal("{failure}", published.Single(instrument => instrument.Name == FailuresInstrument).Unit); + } + + // --------------------------------------------------------------------------------------------- + // The content guarantee + // --------------------------------------------------------------------------------------------- + + [Fact] + public async Task Telemetry_never_contains_captured_content() + { + using var probe = TelemetryProbe.All(); + var loop = new ExperienceLoop(); + + var results = await loop.DriveAsync(); + + // First prove the marker really did travel the whole loop. Without this the sweep below would + // pass just as happily against a loop that captured nothing at all. + var record = Assert.IsType(results.Finalized.Record); + Assert.Contains(ExperienceLoop.Marker, record.TaskSummary!, StringComparison.Ordinal); + Assert.Contains(record.Attempts, attempt => attempt.Result?.Contains(ExperienceLoop.Marker, StringComparison.Ordinal) == true); + Assert.Contains(record.Attempts, attempt => attempt.Error?.Contains(ExperienceLoop.Marker, StringComparison.Ordinal) == true); + Assert.Contains( + record.Attempts.SelectMany(attempt => attempt.ToolCalls), + call => call.Result?.Contains(ExperienceLoop.Marker, StringComparison.Ordinal) == true); + Assert.Contains(ExperienceLoop.Marker, record.Reflection!.FailedApproaches[0], StringComparison.Ordinal); + Assert.Contains(ExperienceLoop.Marker, loop.Generator.Requests[0], StringComparison.Ordinal); + + // And that it reached the four operations that handle no captured text at all, through the + // free-form fields they do carry. Without these, five of thirteen operations were swept for a + // marker that was never anywhere near them. + Assert.Contains(ExperienceLoop.Marker, results.Verified.Outcome.Evidence[0].Detail!, StringComparison.Ordinal); + Assert.Contains(ExperienceLoop.Marker, results.Verified.Outcome.Evidence[0].Producer, StringComparison.Ordinal); + Assert.Contains(ExperienceLoop.Marker, results.Transitioned.Event!.Reason, StringComparison.Ordinal); + Assert.Contains(ExperienceLoop.Marker, results.Transitioned.Event!.Producer, StringComparison.Ordinal); + Assert.Contains(ExperienceLoop.Marker, results.Confidence.Event!.Reason, StringComparison.Ordinal); + Assert.Contains(ExperienceLoop.Marker, loop.Generator.Requests[^1], StringComparison.Ordinal); + Assert.Contains(ExperienceLoop.Marker, loop.FeedbackStore.Submissions[0].Rationale!, StringComparison.Ordinal); + + // Now sweep every value an exporter would ever see. + Assert.NotEmpty(probe.EverySpanTagValue); + Assert.NotEmpty(probe.EveryMeasurementTagValue); + + foreach (var value in probe.EverySpanTagValue.Concat(probe.EveryMeasurementTagValue)) + { + Assert.DoesNotContain(ExperienceLoop.Marker, value, StringComparison.Ordinal); + } + + // Including the parts of a span that are not tags at all. + Assert.All(probe.Activities, activity => + { + Assert.DoesNotContain(ExperienceLoop.Marker, activity.DisplayName, StringComparison.Ordinal); + Assert.Null(activity.StatusDescription); + Assert.Empty(activity.Events); + Assert.Empty(activity.Baggage); + }); + } + + [Fact] + public async Task Metric_dimensions_are_only_operation_outcome_error_class_and_nested() + { + using var probe = TelemetryProbe.All(); + + // A full successful drive, then a thrown operation, so every dimension the library can write + // has actually been written by the time the keys are collected. + var loop = new ExperienceLoop(); + await loop.DriveAsync(); + + loop.Store.Throws = () => new ExperienceStoreException("the database is unreachable"); + await Assert.ThrowsAsync(() => loop.Lifecycle.CommitAsync( + ExperienceLoop.Authorization, + new CommitLifecycleTransitionRequest( + Guid.NewGuid(), Guid.NewGuid(), ExperienceLoop.Scope, ExperienceStatus.Candidate, + ExperienceStatus.Validated, "initial", "tests", ExperienceLoop.Now, 0), + CancellationToken.None)); + + var keys = probe.EveryMeasurementTagKey; + + // All four appear, so the exact assertion below cannot pass by emitting nothing... + Assert.Contains(OperationDimension, keys); + Assert.Contains(OutcomeDimension, keys); + Assert.Contains(ErrorClassDimension, keys); + Assert.Contains(NestedDimension, keys); + + // ...and nothing else does. No run ID, no record ID, no correlation ID, no reason. A fifth + // dimension has to be added here, on purpose, by whoever adds it -- which is the point: every + // dimension is a cardinality multiplier on every series, and an unbounded one is a bill. + Assert.Equal( + new[] { ErrorClassDimension, NestedDimension, OperationDimension, OutcomeDimension }, + keys.Order(StringComparer.Ordinal)); + + // `nested` is a bool and takes both values in this drive, so it is a dimension rather than a + // constant that happens to be attached to everything. + Assert.All(probe.Measurements, measurement => Assert.IsType(measurement.Tags[NestedDimension])); + Assert.Contains(probe.Measurements, measurement => Equals(measurement.Tags[NestedDimension], true)); + Assert.Contains(probe.Measurements, measurement => Equals(measurement.Tags[NestedDimension], false)); + + // Every dimension value is a closed-set member too: an operation from the frozen table, an + // outcome or "Faulted", or an error class. + var operations = FrozenTable.Select(entry => entry.Operation).ToHashSet(StringComparer.Ordinal); + Assert.All(probe.Measurements, measurement => + Assert.True( + operations.Contains(Assert.IsType(measurement.Tags[OperationDimension])), + $"'{measurement.Tags[OperationDimension]}' is not in the frozen operation table.")); + + Assert.All( + probe.For(FailuresInstrument), + measurement => Assert.True(Enum.TryParse( + Assert.IsType(measurement.Tags[ErrorClassDimension]), out _))); + } + + // --------------------------------------------------------------------------------------------- + // Drivers + // --------------------------------------------------------------------------------------------- + + private static FinalizeExperienceRequest FinalizeRequest(Guid runId) => new( + RunId: runId, + Authorization: ExperienceLoop.Authorization, + ClosedRound: ExperienceLoop.Round, + RequiredChecks: [new RequiredCheck("tests")], + Evidence: [ExperienceLoop.Evidence()], + CurrentArtifactRevision: ExperienceLoop.ArtifactRevision, + StorageDecision: StorageDecision.Permit, + FinalizedAt: ExperienceLoop.Now.AddMinutes(1)); + + /// The exception a port-* kind scripts into a port, or when the kind scripts none. + private static Exception? Scripted(string kind) => kind switch + { + "port-store" => new ExperienceStoreException("the database is unreachable"), + "port-timeout" => new TimeoutException("the statement exceeded its bound"), + "port-cancelled-by-nobody" => new OperationCanceledException("a driver-side timeout, arriving as a cancellation nobody asked for"), + "port-unexpected" => new InvalidOperationException("something nobody classified"), + _ => null, + }; + + /// Arms every port the loop owns with , so whichever one the operation reaches throws it. + private static void Arm(ExperienceLoop loop, string kind, Exception? scripted) + { + if (scripted is null) + { + return; + } + + _ = kind; + loop.Store.Throws = () => scripted; + loop.FeedbackStore.Throws = () => scripted; + loop.Index.ScanThrows = scripted; + loop.Index.WriteThrows = scripted; + loop.Index.RemoveThrows = scripted; + loop.Candidates.Throws = () => scripted; + loop.Generator.Throws = scripted; + } + + /// Calls in a way that makes it throw. + private static Task FaultAsync( + ExperienceLoop loop, + LoopResults arranged, + string operation, + string kind, + CancellationToken cancellationToken) + { + var missing = Guid.NewGuid(); + + return (operation, kind) switch + { + ("capture.start_run", _) => Task.Run( + () => loop.Capture.StartRun( + Guid.NewGuid(), + "task-1", + null, + scope: null!, + new EnvironmentFingerprint("host-1", "net10.0", "linux", "1.0.0", new Dictionary()), + new Provenance("tests", "1.0.0", ExperienceLoop.Now, null), + ExperienceLoop.Now), + CancellationToken.None), + + ("capture.append_attempt", "argument") => loop.Capture.AppendAttemptAsync(arranged.RunId, request: null!), + ("capture.append_attempt", _) => loop.Capture.AppendAttemptAsync( + arranged.RunId, + new AppendAttemptRequest(Guid.NewGuid(), ExperienceLoop.Now, TimeSpan.FromSeconds(1), [], "done", null), + cancellationToken), + + ("capture.complete_run", _) => loop.Capture.CompleteRunAsync( + arranged.RunId, Guid.NewGuid(), RunExecutionStatus.Completed, ExperienceLoop.Now, cancellationToken), + + ("verify", "argument") => Task.Run( + () => VerificationAggregator.Aggregate( + evidence: null!, [], ExperienceLoop.Round, ExperienceLoop.ArtifactRevision, ExperienceLoop.Now), + CancellationToken.None), + ("verify", _) => Task.Run( + () => VerificationAggregator.Aggregate( + [ExperienceLoop.Evidence()], + [new RequiredCheck("tests")], + ExperienceLoop.Round, + ExperienceLoop.ArtifactRevision, + ExperienceLoop.Now, + cancellationToken), + CancellationToken.None), + + ("reflect", "argument") => new DefaultExperienceReflector().ReflectAsync(request: null!), + ("reflect", _) => new DefaultExperienceReflector().ReflectAsync( + new ReflectionRequest( + arranged.Finalized.Record is null + ? throw new InvalidOperationException("The arranged drive produced no record.") + : Run(loop, arranged.RunId), + arranged.Verified, + Guid.NewGuid(), + ExperienceLoop.Now), + cancellationToken), + + ("finalize", "argument") => loop.Finalization.FinalizeAsync(request: null!), + ("finalize", _) => loop.Finalization.FinalizeAsync(FinalizeRequest(arranged.RunId), cancellationToken), + + ("lifecycle.commit", _) => loop.Lifecycle.CommitAsync( + ExperienceLoop.Authorization, + new CommitLifecycleTransitionRequest( + Guid.NewGuid(), arranged.ExperienceId, ExperienceLoop.Scope, ExperienceStatus.Validated, + ExperienceStatus.Reinforced, "again", "tests", ExperienceLoop.Now, 1), + cancellationToken), + + ("confidence.apply", _) => loop.Lifecycle.ApplyEvidenceAsync( + ExperienceLoop.Authorization, + new ApplyConfidenceEvidenceRequest( + Guid.NewGuid(), + arranged.ExperienceId, + ExperienceLoop.Scope, + Guid.NewGuid(), + ConfidenceEvidenceKind.Supporting, + ConfidenceEvidenceSource.Machine, + arranged.RunId, + ExperienceLoop.Round.RoundId, + "a later run reused it", + "tests", + ExperienceLoop.Now), + cancellationToken), + + ("retrieve", "argument") => loop.Retrieval.RetrieveAsync(request: null!), + ("retrieve", _) => loop.Retrieval.RetrieveAsync( + new RetrieveExperienceRequest(ExperienceLoop.Authorization, ExperienceLoop.Scope, "a task"), cancellationToken), + + ("index", "argument") => loop.Indexing.IndexAsync(ExperienceLoop.Authorization, scope: null!, missing), + ("index", _) => loop.Indexing.IndexAsync(ExperienceLoop.Authorization, ExperienceLoop.Scope, arranged.ExperienceId, cancellationToken), + + ("deindex", _) => loop.Indexing.RemoveAsync(ExperienceLoop.Authorization, scope: null!, missing), + + ("reindex", "argument") => loop.Indexing.ReindexAsync(ExperienceLoop.Authorization, request: null!), + ("reindex", _) => loop.Indexing.ReindexAsync( + ExperienceLoop.Authorization, + new ReindexExperienceRequest(ExperienceLoop.Scope, [arranged.ExperienceId], Limit: 1), + cancellationToken), + + ("reuse_feedback", _) => loop.FeedbackService.RecordAsync( + ExperienceLoop.Authorization, + new ExperienceReuseFeedback( + Guid.NewGuid(), + Guid.NewGuid(), + ExperienceLoop.Scope, + [arranged.ExperienceId], + TaskVerificationStatus.Verified, + new ReuseMeasure("task-success", 1), + ExperienceLoop.Now), + cancellationToken), + + _ => throw new InvalidOperationException($"No fault driver for '{operation}'/'{kind}'."), + }; + } + + /// Calls in a way that makes it return a rejection rather than its success outcome. + private static async Task RejectAsync(ExperienceLoop loop, LoopResults arranged, string operation) + { + var outsider = new AuthorizationContext("tenant-2", "other-principal", ["experience:write"], ExperienceLoop.Now); + var missing = Guid.NewGuid(); + + switch (operation) + { + case "capture.start_run": + // The run ID is already taken, so this is a second start for the same run. + return loop.Capture.StartRun( + arranged.RunId, + "task-1", + null, + ExperienceLoop.Scope, + new EnvironmentFingerprint("host-1", "net10.0", "linux", "1.0.0", new Dictionary()), + new Provenance("tests", "1.0.0", ExperienceLoop.Now, null), + ExperienceLoop.Now).Outcome.ToString(); + + case "capture.append_attempt": + // The run was completed by the arranged drive, so it accepts no further attempts. + return (await loop.Capture.AppendAttemptAsync( + arranged.RunId, + new AppendAttemptRequest(Guid.NewGuid(), ExperienceLoop.Now, TimeSpan.FromSeconds(1), [], "late", null))) + .Outcome.ToString(); + + case "capture.complete_run": + return (await loop.Capture.CompleteRunAsync( + arranged.RunId, Guid.NewGuid(), RunExecutionStatus.Completed, ExperienceLoop.Now.AddSeconds(4))) + .Outcome.ToString(); + + case "verify": + return VerificationAggregator.Aggregate( + [ExperienceLoop.Evidence(CheckResult.Fail)], + [new RequiredCheck("tests")], + ExperienceLoop.Round, + ExperienceLoop.ArtifactRevision, + ExperienceLoop.Now).Outcome.Status.ToString(); + + case "reflect": + return (await new DefaultExperienceReflector().ReflectAsync(new ReflectionRequest( + Run(loop, arranged.RunId), + VerificationAggregator.Aggregate( + [ExperienceLoop.Evidence(CheckResult.Fail)], + [new RequiredCheck("tests")], + ExperienceLoop.Round, + ExperienceLoop.ArtifactRevision, + ExperienceLoop.Now), + Guid.NewGuid(), + ExperienceLoop.Now))).VerificationStatus.ToString(); + + case "finalize": + // The run was finalized by the arranged drive; a second call writes nothing. + return (await loop.Finalization.FinalizeAsync(FinalizeRequest(arranged.RunId))).Outcome.ToString(); + + case "lifecycle.commit": + return (await loop.Lifecycle.CommitAsync( + ExperienceLoop.Authorization, + new CommitLifecycleTransitionRequest( + Guid.NewGuid(), arranged.ExperienceId, ExperienceLoop.Scope, ExperienceStatus.Revoked, + ExperienceStatus.Validated, "a revoked record cannot be validated again", "tests", + ExperienceLoop.Now, 3), + CancellationToken.None)).Outcome.ToString(); + + case "confidence.apply": + return (await loop.Lifecycle.ApplyEvidenceAsync( + ExperienceLoop.Authorization, + new ApplyConfidenceEvidenceRequest( + Guid.NewGuid(), + missing, + ExperienceLoop.Scope, + Guid.NewGuid(), + ConfidenceEvidenceKind.Supporting, + ConfidenceEvidenceSource.Machine, + arranged.RunId, + ExperienceLoop.Round.RoundId, + "about a record that does not exist", + "tests", + ExperienceLoop.Now), + CancellationToken.None)).Outcome.ToString(); + + case "retrieve": + return (await loop.Retrieval.RetrieveAsync(new RetrieveExperienceRequest( + outsider, ExperienceLoop.Scope, "a task in a scope the host does not cover"))).Outcome.ToString(); + + case "index": + return (await loop.Indexing.IndexAsync(ExperienceLoop.Authorization, ExperienceLoop.Scope, missing)).Outcome.ToString(); + + case "deindex": + return (await loop.Indexing.RemoveAsync(ExperienceLoop.Authorization, ExperienceLoop.Scope, missing)).Outcome.ToString(); + + case "reindex": + return (await loop.Indexing.ReindexAsync( + outsider, new ReindexExperienceRequest(ExperienceLoop.Scope, [arranged.ExperienceId], Limit: 1))).Outcome.ToString(); + + case "reuse_feedback": + return (await loop.FeedbackService.RecordAsync( + outsider, + new ExperienceReuseFeedback( + Guid.NewGuid(), + Guid.NewGuid(), + ExperienceLoop.Scope, + [arranged.ExperienceId], + TaskVerificationStatus.Verified, + new ReuseMeasure("task-success", 1), + ExperienceLoop.Now), + CancellationToken.None)).Outcome.ToString(); + + default: + throw new InvalidOperationException($"No rejection driver for '{operation}'."); + } + } + + /// + /// Every call one instrument recorded, as "<operation> nested=<bool> x<count>" + /// lines in a stable order, so a whole call table is one assertion with a readable diff. + /// + /// The probe that collected the drive. + /// The instrument to tabulate. + /// One line per operation and nesting combination. + private static IReadOnlyList Calls(TelemetryProbe probe, string instrument) => + [.. probe.For(instrument) + .GroupBy( + measurement => $"{measurement.Tags[OperationDimension]} nested={measurement.Tags[NestedDimension]}", + StringComparer.Ordinal) + .Select(group => $"{group.Key} x{group.Count()}") + .Order(StringComparer.Ordinal)]; + + private static ExperienceRun Run(ExperienceLoop loop, Guid runId) + { + Assert.True(loop.Capture.TryGetRun(runId, out var run)); + return run!; + } + + /// + /// One drive's results with the parts that cannot be equal between two drives -- freshly generated + /// identifiers and measured elapsed times -- normalized away, so everything else is compared. + /// + private static string Normalize(LoopResults results) + { + var text = results.ToString(); + + // Every GUID in the drive is freshly generated per run, or derived from one that is. + text = System.Text.RegularExpressions.Regex.Replace( + text, + "[0-9a-fA-F]{8}-[0-9a-fA-F]{4}-[0-9a-fA-F]{4}-[0-9a-fA-F]{4}-[0-9a-fA-F]{12}", + ""); + + // Retrieval reports how long it took, which is wall clock and never repeats. + text = System.Text.RegularExpressions.Regex.Replace(text, @"Elapsed = [^,}]*", "Elapsed = "); + + return text; + } + + /// A candidate source that does not answer until it is released, so retrieval hits its own timeout. + private sealed class SlowCandidateSource(TaskCompletionSource released) : IExperienceCandidateSource + { + public async Task SearchAsync( + AuthorizationContext authorization, + ExperienceCandidateQuery query, + CancellationToken cancellationToken) + { + await released.Task.WaitAsync(cancellationToken).ConfigureAwait(false); + return new ExperienceCandidateSearchResult(ExperienceStoreOutcome.Found, [], []); + } + } +} diff --git a/tests/AgentExperience.Core.Tests/Diagnostics/TelemetryProbe.cs b/tests/AgentExperience.Core.Tests/Diagnostics/TelemetryProbe.cs new file mode 100644 index 0000000..5957379 --- /dev/null +++ b/tests/AgentExperience.Core.Tests/Diagnostics/TelemetryProbe.cs @@ -0,0 +1,262 @@ +using System.Diagnostics; +using System.Diagnostics.Metrics; + +namespace AgentExperience.Core.Tests.Diagnostics; + +/// +/// One measurement a saw, flattened so a test can assert on the +/// instrument, the value, and the dimension keys and values without caring which numeric type the +/// instrument happened to be. +/// +/// The instrument's name, e.g. agentexperience.operation.count. +/// The meter that published the instrument, which is the emitting assembly's source name. +/// The recorded value, widened to . +/// The measurement's dimensions. +internal sealed record ProbedMeasurement( + string Instrument, + string Meter, + double Value, + IReadOnlyDictionary Tags); + +/// +/// A host, in miniature: it registers the and +/// the library itself is forbidden to create, and collects everything +/// that arrives. Every telemetry assertion in this folder is made against what a real exporter would +/// have been handed, not against the library's internals. +/// +/// +/// +/// The two listeners are registered independently, so a test can subscribe to spans only, to +/// measurements only, or to neither -- which is how the "execution never depends on a listener" rows +/// of the story's matrix are actually exercised rather than assumed. +/// +/// +/// By default it listens to AgentExperience.* only. widens +/// the span listener to every source in the process, which is what proves the library adds no agent, +/// model, or tool spans of its own on top of the ones MAF already emits. +/// +/// +internal sealed class TelemetryProbe : IDisposable +{ + /// The prefix a host subscribes with (AddSource("AgentExperience.*")). + internal const string SourcePrefix = "AgentExperience."; + + private readonly object _gate = new(); + private readonly List _activities = []; + private readonly List _measurements = []; + private readonly List _instruments = []; + private readonly ActivityListener? _activityListener; + private readonly MeterListener? _meterListener; + + private TelemetryProbe(bool spans, bool metrics, bool everySource, ActivitySamplingResult sampling) + { + if (spans) + { + _activityListener = new ActivityListener + { + ShouldListenTo = source => everySource || source.Name.StartsWith(SourcePrefix, StringComparison.Ordinal), + Sample = (ref ActivityCreationOptions _) => sampling, + SampleUsingParentId = (ref ActivityCreationOptions _) => sampling, + ActivityStarted = activity => + { + lock (_gate) + { + Started?.Invoke(activity); + } + }, + + // Collected on stop, not on start: an operation's outcome tag is written just before + // the span is disposed, so a probe that snapshotted it on start would assert on a span + // nothing had finished filling in. + ActivityStopped = activity => + { + lock (_gate) + { + _activities.Add(activity); + } + }, + }; + + ActivitySource.AddActivityListener(_activityListener); + } + + if (metrics) + { + _meterListener = new MeterListener + { + InstrumentPublished = (instrument, listener) => + { + if (!instrument.Meter.Name.StartsWith(SourcePrefix, StringComparison.Ordinal)) + { + return; + } + + lock (_gate) + { + _instruments.Add(instrument); + } + + listener.EnableMeasurementEvents(instrument); + }, + }; + + _meterListener.SetMeasurementEventCallback( + (instrument, measurement, tags, _) => Add(instrument, measurement, tags)); + _meterListener.SetMeasurementEventCallback( + (instrument, measurement, tags, _) => Add(instrument, measurement, tags)); + _meterListener.Start(); + } + } + + /// Runs for every activity the moment it starts, before the operation it wraps has done anything. + internal Action? Started { get; set; } + + /// Spans and measurements from AgentExperience.*, which is what a host subscribes to. + internal static TelemetryProbe All() => new(spans: true, metrics: true, everySource: false, ActivitySamplingResult.AllDataAndRecorded); + + /// Spans only: no is registered at all. + internal static TelemetryProbe SpansOnly() => new(spans: true, metrics: false, everySource: false, ActivitySamplingResult.AllDataAndRecorded); + + /// Measurements only: no is registered at all. + internal static TelemetryProbe MetricsOnly() => new(spans: false, metrics: true, everySource: false, ActivitySamplingResult.AllDataAndRecorded); + + /// Spans from every source in the process, not just this library's. + internal static TelemetryProbe EverySource() => new(spans: true, metrics: true, everySource: true, ActivitySamplingResult.AllDataAndRecorded); + + /// + /// Listening, but declining every sample: StartActivity returns , so + /// every ?.SetTag in the library is a no-op while the measurements still have to arrive. + /// + internal static TelemetryProbe Declining() => new(spans: true, metrics: true, everySource: false, ActivitySamplingResult.None); + + /// Every finished activity, in the order it stopped. + internal IReadOnlyList Activities + { + get + { + lock (_gate) + { + return [.. _activities]; + } + } + } + + /// The finished activities this library emitted, ignoring any the rest of the process produced. + internal IReadOnlyList LibraryActivities => + [.. Activities.Where(activity => activity.Source.Name.StartsWith(SourcePrefix, StringComparison.Ordinal))]; + + /// Every measurement, in the order it was recorded. + internal IReadOnlyList Measurements + { + get + { + lock (_gate) + { + return [.. _measurements]; + } + } + } + + /// The measurements recorded to one instrument. + /// The instrument name. + internal IReadOnlyList For(string instrument) => + [.. Measurements.Where(measurement => string.Equals(measurement.Instrument, instrument, StringComparison.Ordinal))]; + + /// The measurements recorded to one instrument for one operation dimension value. + /// The instrument name. + /// The operation dimension value. + internal IReadOnlyList For(string instrument, string operation) => + [.. For(instrument).Where(measurement => + measurement.Tags.TryGetValue("operation", out var value) && Equals(value, operation))]; + + /// The measurements recorded to one instrument for one operation, split by whether another instrumented operation called it. + /// The instrument name. + /// The operation dimension value. + /// The nested dimension value to match. + internal IReadOnlyList For(string instrument, string operation, bool nested) => + [.. For(instrument, operation).Where(measurement => + measurement.Tags.TryGetValue("nested", out var value) && Equals(value, nested))]; + + /// Every tag value written to any collected span, as strings, so a marker sweep can look at all of them at once. + internal IReadOnlyList EverySpanTagValue => + [.. Activities + .SelectMany(activity => activity.TagObjects) + .Select(tag => tag.Value?.ToString()) + .Concat(Activities.Select(activity => activity.StatusDescription)) + .Concat(Activities.Select(activity => activity.DisplayName)) + .Where(value => value is not null) + .Select(value => value!)]; + + /// Every dimension value written to any collected measurement, as strings. + internal IReadOnlyList EveryMeasurementTagValue => + [.. Measurements + .SelectMany(measurement => measurement.Tags.Values) + .Select(value => value?.ToString()) + .Where(value => value is not null) + .Select(value => value!)]; + + /// Every dimension key written to any collected measurement. + internal IReadOnlyList EveryMeasurementTagKey => + [.. Measurements.SelectMany(measurement => measurement.Tags.Keys).Distinct(StringComparer.Ordinal)]; + + /// + /// Every attribute key written to any span this library emitted. + /// + /// + /// The marker sweep proves that no value this drive produced reached a span. That is a + /// statement about the content the drive happened to carry, and it cannot catch an attribute that + /// carries host free text the drive never poisoned. Pinning the key set exactly -- the way the + /// metric dimension set is pinned -- does: a new attribute has to be added to the allow-list, on + /// purpose, with whoever adds it having to say what it carries. + /// + internal IReadOnlyList EverySpanTagKey => + [.. LibraryActivities.SelectMany(activity => activity.TagObjects).Select(tag => tag.Key).Distinct(StringComparer.Ordinal)]; + + /// Every instrument this probe's meter listener was offered, whether or not it enabled it. + internal IReadOnlyList PublishedInstruments + { + get + { + lock (_gate) + { + return [.. _instruments]; + } + } + } + + /// Drains the measurement callbacks, then unregisters both listeners. + public void Dispose() + { + _meterListener?.Dispose(); + _activityListener?.Dispose(); + } + + private void Add(Instrument instrument, double value, ReadOnlySpan> tags) + { + // Copied out of the span before it goes away: the callback's tags are only valid for the + // duration of the call. + var copied = new Dictionary(tags.Length, StringComparer.Ordinal); + foreach (var tag in tags) + { + copied[tag.Key] = tag.Value; + } + + lock (_gate) + { + _measurements.Add(new ProbedMeasurement(instrument.Name, instrument.Meter.Name, value, copied)); + } + } +} + +/// +/// Telemetry listeners are process-wide, so a probe registered by one test would otherwise collect +/// whatever a concurrently running test happened to emit. Every test that registers a probe -- and +/// every test that asserts nothing at all was emitted -- belongs to this collection, which xUnit runs +/// on its own. +/// +[CollectionDefinition(Name, DisableParallelization = true)] +public sealed class TelemetryCollection +{ + /// The collection name to put on a test class with . + public const string Name = "AgentExperience telemetry (process-wide listeners)"; +} diff --git a/tests/AgentExperience.Core.Tests/Diagnostics/TelemetrySourceScanTests.cs b/tests/AgentExperience.Core.Tests/Diagnostics/TelemetrySourceScanTests.cs new file mode 100644 index 0000000..552281f --- /dev/null +++ b/tests/AgentExperience.Core.Tests/Diagnostics/TelemetrySourceScanTests.cs @@ -0,0 +1,230 @@ +using System.Runtime.CompilerServices; +using System.Text.RegularExpressions; + +namespace AgentExperience.Core.Tests.Diagnostics; + +/// +/// Reads the shipping source itself, because some of this story's guarantees are about what the +/// library must never contain, and no amount of running it can prove an absence. +/// +/// +/// +/// The library emits and the host exports (AD-11, AD-12). A library that registered a listener, built +/// a provider, or flipped a framework's sensitive-data switch would be taking the host's decision for +/// it -- silently, and in the one direction that cannot be undone once the data has left the process. +/// +/// +/// String literals are stripped first, then comments. The diagnostics holders legitimately +/// document what they do not do, with <see cref="ActivityListener"/> and +/// friends; the rule is about code, not prose. The order is what makes the scan honest: stripping +/// comments first means a line-comment regex starts at the // inside a URL literal and deletes +/// the rest of that line -- so a forbidden call sharing a line with a URL simply disappears, and a +/// block-comment regex can swallow everything up to the next */ anywhere in the file. +/// +/// +public partial class TelemetrySourceScanTests +{ + /// + /// Identifiers that must not appear anywhere in src/: three that would make the library an + /// exporter, two that would make it a listener, and one that would turn on another framework's + /// sensitive-data capture on the host's behalf. + /// + private static readonly string[] Forbidden = + [ + "AppContext.SetSwitch", + "EnableSensitiveData", + "ActivityListener", + "MeterListener", + "TracerProvider", + "MeterProvider", + ]; + + /// + /// Ways an exception object can reach telemetry. A driver or HTTP client message can quote SQL + /// text and parameters, so none of these may appear on an instrumented path -- and the simplest + /// way to keep that true is for them not to appear at all. + /// + private static readonly string[] ForbiddenOnInstrumentedPaths = + [ + "AddException", + "RecordException", + ]; + + [Fact] + public void Library_never_enables_sensitive_data_or_registers_a_listener() + { + var sources = SourceFiles(); + + // The scan found the source tree at all: an empty sweep would otherwise "pass". + Assert.True(sources.Count > 20, $"Only {sources.Count} source files were scanned; the source tree was probably not found."); + + foreach (var (path, code) in sources) + { + foreach (var forbidden in Forbidden) + { + Assert.False( + code.Contains(forbidden, StringComparison.Ordinal), + $"'{path}' contains '{forbidden}'; the library emits, the host exports."); + } + } + } + + [Fact] + public void Library_never_hands_an_exception_object_to_telemetry() + { + var sources = SourceFiles(); + + // The same sanity guard its sibling has: an empty sweep would otherwise "pass". + Assert.True(sources.Count > 20, $"Only {sources.Count} source files were scanned; the source tree was probably not found."); + + foreach (var (path, code) in sources) + { + foreach (var forbidden in ForbiddenOnInstrumentedPaths) + { + Assert.False( + code.Contains(forbidden, StringComparison.Ordinal), + $"'{path}' contains '{forbidden}'; a span records an exception's type name and nothing else."); + } + } + } + + [Fact] + public void Library_references_no_OpenTelemetry_assembly() + { + // System.Diagnostics.ActivitySource and System.Diagnostics.Metrics.Meter are the BCL; the + // OpenTelemetry SDK is a host concern and is referenced by nothing that ships. + foreach (var assembly in new[] + { + typeof(DefaultSanitizer).Assembly, + typeof(ExperienceRecord).Assembly, + }) + { + Assert.DoesNotContain( + assembly.GetReferencedAssemblies(), + reference => reference.Name?.Contains("OpenTelemetry", StringComparison.OrdinalIgnoreCase) == true); + } + } + + /// + /// Every metric write is guarded by the instrument's own Enabled. + /// + /// + /// This is a source-level assertion on purpose, and it is the only kind available. + /// Counter<T>.Add and Histogram<T>.Record are already no-ops when nothing + /// has enabled the instrument, so removing the guard changes what an unsubscribed process + /// spends -- composing a TagList, reading a Stopwatch -- and nothing a + /// listener can ever observe. The guard is a cost contract rather than a behavioural one, so a + /// repository-hygiene test is what can hold it, exactly as for the forbidden identifiers above. + /// + [Fact] + public void Every_metric_write_is_guarded_by_the_instruments_own_Enabled() + { + var holders = SourceFiles() + .Where(file => file.Path.EndsWith("Diagnostics.cs", StringComparison.Ordinal)) + .ToList(); + + // Core's holder and the adapter's. A third would have to be added here deliberately. + Assert.Equal(2, holders.Count); + + foreach (var (path, code) in holders) + { + foreach (var guard in new[] { "Operations.Enabled", "Durations.Enabled", "Failures.Enabled" }) + { + Assert.True( + code.Contains(guard, StringComparison.Ordinal), + $"'{path}' writes a measurement without consulting '{guard}'; an unsubscribed process must compose no tags and read no clock."); + } + } + } + + /// + /// Proves the stripper itself: a forbidden identifier that shares a line with a URL literal is + /// still found, and one that appears only in prose or only inside a string is not. + /// + [Fact] + public void The_stripper_removes_literals_before_comments() + { + // The bug this exists to prevent: stripping comments first starts at the `//` inside the URL + // and deletes the forbidden call along with it. + var code = Strip("""Register("https://example.test/docs"); AppContext.SetSwitch("x", true);"""); + Assert.Contains("AppContext.SetSwitch", code, StringComparison.Ordinal); + Assert.DoesNotContain("example.test", code, StringComparison.Ordinal); + + // Prose is still prose, and a name that only ever appears inside a string is not a call. + Assert.DoesNotContain("ActivityListener", Strip("// never registers an ActivityListener"), StringComparison.Ordinal); + Assert.DoesNotContain("MeterListener", Strip("""var name = "MeterListener";"""), StringComparison.Ordinal); + + // A block comment stops at its own terminator rather than at one inside a literal. + var afterBlock = Strip(""" + var pattern = "/*"; + AppContext.SetSwitch("x", true); + /* a real comment */ + """); + Assert.Contains("AppContext.SetSwitch", afterBlock, StringComparison.Ordinal); + Assert.DoesNotContain("a real comment", afterBlock, StringComparison.Ordinal); + } + + /// Every shipping C# file, with its string literals and then its comments removed. + private static List<(string Path, string Code)> SourceFiles([CallerFilePath] string testSourceFilePath = "") + { + var repositoryRoot = Path.GetFullPath(Path.Combine(Path.GetDirectoryName(testSourceFilePath)!, "..", "..", "..")); + var sourceRoot = Path.Combine(repositoryRoot, "src"); + Assert.True(Directory.Exists(sourceRoot), $"Could not locate the source tree at '{sourceRoot}'."); + + return + [ + .. Directory + .EnumerateFiles(sourceRoot, "*.cs", SearchOption.AllDirectories) + .Where(path => !path.Contains($"{Path.DirectorySeparatorChar}obj{Path.DirectorySeparatorChar}", StringComparison.Ordinal) + && !path.Contains($"{Path.DirectorySeparatorChar}bin{Path.DirectorySeparatorChar}", StringComparison.Ordinal)) + .Select(path => (Path.GetRelativePath(repositoryRoot, path), Strip(File.ReadAllText(path)))) + ]; + } + + /// + /// Removes what is not code: string literals first, then comments. + /// + /// + /// + /// Literals go first because a // or a /* inside one is not a comment, and a + /// comment-first pass would delete real code that merely shared a line with a URL. Raw strings go + /// before verbatim ones and verbatim before ordinary ones, because each is a special case of the + /// next and matching the general form first would end a literal in the middle of itself. + /// + /// + /// This is textual, not a parser. An unbalanced quote inside a comment can still pair with another + /// quote -- but only on the same line, because the ordinary-string pattern does not cross a line + /// break, so the blast radius of the remaining imprecision is one line of prose rather than the + /// rest of the file. + /// + /// + /// The source text. + /// The text with literals and comments blanked out. + private static string Strip(string code) + { + var withoutLiterals = RawStrings().Replace(code, " "); + withoutLiterals = VerbatimStrings().Replace(withoutLiterals, " "); + withoutLiterals = OrdinaryStrings().Replace(withoutLiterals, " "); + withoutLiterals = CharLiterals().Replace(withoutLiterals, " "); + + return LineComments().Replace(BlockComments().Replace(withoutLiterals, " "), string.Empty); + } + + [GeneratedRegex(@"""{3,}.*?""{3,}", RegexOptions.Singleline)] + private static partial Regex RawStrings(); + + [GeneratedRegex(@"@""(?:[^""]|"""")*""", RegexOptions.Singleline)] + private static partial Regex VerbatimStrings(); + + [GeneratedRegex(@"""(?:\\.|[^""\\\r\n])*""")] + private static partial Regex OrdinaryStrings(); + + [GeneratedRegex(@"'(?:\\.|[^'\\\r\n])'")] + private static partial Regex CharLiterals(); + + [GeneratedRegex(@"/\*.*?\*/", RegexOptions.Singleline)] + private static partial Regex BlockComments(); + + [GeneratedRegex(@"//[^\r\n]*")] + private static partial Regex LineComments(); +} diff --git a/tests/AgentExperience.Core.Tests/IndexingTestDoubles.cs b/tests/AgentExperience.Core.Tests/IndexingTestDoubles.cs index 16f13d3..8a1b93f 100644 --- a/tests/AgentExperience.Core.Tests/IndexingTestDoubles.cs +++ b/tests/AgentExperience.Core.Tests/IndexingTestDoubles.cs @@ -18,8 +18,8 @@ internal sealed class FakeEmbeddingGenerator : IExperienceEmbeddingGenerator public int Dimension { get; init; } = 4; - /// When set, every call throws this instead of embedding. - public Exception? Throws { get; init; } + /// When set, every call throws this instead of embedding. Settable, so a test can script an outage part-way through a drive. + public Exception? Throws { get; set; } /// When set, the returned vector has this many components instead of . public int? ReturnDimension { get; init; } @@ -117,14 +117,14 @@ public sealed record Row( /// Every vector search this index was asked for, in order. public List Queries { get; } = []; - /// When set, every scan throws this. - public Exception? ScanThrows { get; init; } + /// When set, every scan throws this. Settable, so a test can script an outage part-way through a drive. + public Exception? ScanThrows { get; set; } - /// When set, every write throws this. - public Exception? WriteThrows { get; init; } + /// When set, every write throws this. Settable, so a test can script an outage part-way through a drive. + public Exception? WriteThrows { get; set; } - /// When set, every search throws this. - public Exception? SearchThrows { get; init; } + /// When set, every search throws this. Settable, so a test can script an outage part-way through a drive. + public Exception? SearchThrows { get; set; } /// When set, every scan returns this outcome instead of listing anything. public ExperienceStoreOutcome? ScanOutcome { get; init; } @@ -138,8 +138,8 @@ public sealed record Row( /// Every removal this index was asked for, in order -- including the ones that found nothing. public List<(Scope Scope, Guid ExperienceId)> Removals { get; } = []; - /// When set, every removal throws this. - public Exception? RemoveThrows { get; init; } + /// When set, every removal throws this. Settable, so a test can script an outage part-way through a drive. + public Exception? RemoveThrows { get; set; } /// When set, runs before a removal is applied -- the seam for a removal that hangs or is cancelled. public Action? BeforeRemove { get; init; } diff --git a/tests/AgentExperience.MicrosoftAgentFramework.Tests/DependencyBoundaryTests.cs b/tests/AgentExperience.MicrosoftAgentFramework.Tests/DependencyBoundaryTests.cs new file mode 100644 index 0000000..9200217 --- /dev/null +++ b/tests/AgentExperience.MicrosoftAgentFramework.Tests/DependencyBoundaryTests.cs @@ -0,0 +1,125 @@ +using System.Runtime.CompilerServices; +using System.Xml.Linq; +using AgentExperience.MicrosoftAgentFramework.Injection; + +namespace AgentExperience.MicrosoftAgentFramework.Tests; + +/// +/// Proves the MAF adapter takes exactly one package -- Microsoft.Agents.AI, at the exact +/// version its compatibility is verified against -- and that instrumenting it added none. Mirrors the +/// same assertion in AgentExperience.Core.Tests, AgentExperience.Abstractions.Tests, +/// and the two storage adapters' test projects. +/// +/// +/// +/// This file exists because story 4.1 gave the adapter an ActivitySource and a Meter, +/// and the obvious way to do that would have been to reach for the OpenTelemetry SDK. Both types +/// ship in the net10.0 shared framework instead, so the adapter's declared package set is +/// unchanged -- and this test is what keeps it that way when the next story adds an exporter-shaped +/// temptation. +/// +/// +/// The library emits; the host exports (AD-11, AD-12). An OpenTelemetry.* reference here would +/// force every consumer onto the SDK's version of it, which is the host's choice to make. +/// +/// +public class DependencyBoundaryTests +{ + /// + /// Case-insensitive substrings that must never appear in a referenced assembly name, or in a + /// declared PackageReference, of AgentExperience.MicrosoftAgentFramework. MAF itself + /// is of course allowed here -- this is the adapter -- so the list is the storage and telemetry + /// SDKs plus the model providers an adapter has no business binding to. + /// + private static readonly string[] ForbiddenAssemblyNameSubstrings = + [ + "OpenTelemetry", + "Microsoft.EntityFrameworkCore", + "Npgsql", + "dbup", + "Microsoft.SemanticKernel", + "OpenAI", + "Azure.AI", + "Anthropic", + "Microsoft.Extensions.Logging", + ]; + + [Fact] + public void AgentExperience_MicrosoftAgentFramework_does_not_reference_OpenTelemetry_a_database_or_a_model_provider_assembly() + { + var referenced = typeof(ExperienceContextProvider).Assembly.GetReferencedAssemblies(); + Assert.NotEmpty(referenced); + + foreach (var assemblyName in referenced) + { + var name = assemblyName.Name ?? string.Empty; + foreach (var forbidden in ForbiddenAssemblyNameSubstrings) + { + Assert.False( + name.Contains(forbidden, StringComparison.OrdinalIgnoreCase), + $"AgentExperience.MicrosoftAgentFramework references '{name}', which matches forbidden dependency '{forbidden}'."); + } + } + } + + [Fact] + public void AgentExperience_MicrosoftAgentFramework_csproj_declares_no_forbidden_PackageReference() + { + // GetReferencedAssemblies() only reports what the compiled output actually binds to, so a + // declared-but-not-yet-used package would pass the check above in silence. + foreach (var include in DeclaredPackageReferences().Select(element => element.Attribute("Include")?.Value ?? string.Empty)) + { + foreach (var forbidden in ForbiddenAssemblyNameSubstrings) + { + Assert.False( + include.Contains(forbidden, StringComparison.OrdinalIgnoreCase), + $"AgentExperience.MicrosoftAgentFramework.csproj declares PackageReference '{include}', which matches forbidden dependency '{forbidden}'."); + } + } + } + + [Fact] + public void AgentExperience_MicrosoftAgentFramework_csproj_declares_exactly_the_allowed_PackageReferences() + { + // The forbidden-substring checks above cannot catch a package that is merely unwanted rather + // than forbidden. Pinning the whole declared set makes every future addition a deliberate, + // reviewed change to this list -- which is exactly what "instrumentation costs no package" + // means in practice. + var declared = DeclaredPackageReferences() + .Select(element => $"{element.Attribute("Include")?.Value} {element.Attribute("Version")?.Value}") + .Order(StringComparer.Ordinal) + .ToList(); + + Assert.Equal(["Microsoft.Agents.AI [1.20.0]"], declared); + } + + [Fact] + public void ActivitySource_and_Meter_come_from_the_shared_framework() + { + // The reason no package was needed: both live in an assembly the net10.0 shared framework + // already carries, so using them is using the BCL, not taking a dependency. + foreach (var type in new[] { typeof(System.Diagnostics.ActivitySource), typeof(System.Diagnostics.Metrics.Meter) }) + { + Assert.Equal("System.Diagnostics.DiagnosticSource", type.Assembly.GetName().Name); + } + } + + private static IEnumerable DeclaredPackageReferences() + { + var csprojPath = GetAdapterCsprojPath(); + Assert.True(File.Exists(csprojPath), $"Could not locate AgentExperience.MicrosoftAgentFramework.csproj at '{csprojPath}'."); + return XDocument.Load(csprojPath).Descendants("PackageReference"); + } + + private static string GetAdapterCsprojPath([CallerFilePath] string testSourceFilePath = "") + { + var testsProjectDirectory = Path.GetDirectoryName(testSourceFilePath)!; + return Path.GetFullPath(Path.Combine( + testsProjectDirectory, + "..", + "..", + "src", + "AgentExperience.MicrosoftAgentFramework", + "AgentExperience.MicrosoftAgentFramework.csproj")); + } +} diff --git a/tests/AgentExperience.MicrosoftAgentFramework.Tests/Diagnostics/DiagnosticsAgreementTests.cs b/tests/AgentExperience.MicrosoftAgentFramework.Tests/Diagnostics/DiagnosticsAgreementTests.cs new file mode 100644 index 0000000..b369e21 --- /dev/null +++ b/tests/AgentExperience.MicrosoftAgentFramework.Tests/Diagnostics/DiagnosticsAgreementTests.cs @@ -0,0 +1,159 @@ +using System.Reflection; +using AgentExperience.Core.Diagnostics; +using AgentExperience.MicrosoftAgentFramework.Diagnostics; + +namespace AgentExperience.MicrosoftAgentFramework.Tests.Diagnostics; + +/// +/// Core and the adapter emit under different source names but must write byte-identical instrument +/// names, dimension keys, attribute keys, and failure classifications. Core's holder is internal to +/// Core and stays that way, so the adapter restates those values rather than being handed access to +/// every Core internal for the sake of a dozen strings. This is what makes that restatement safe. +/// +/// +/// +/// The grant would not have prevented the drift anyway. The shared values are +/// , so they are baked into the referencing assembly at compile time; Core and +/// the adapter ship as independent packages and can be restored at different versions, which means a +/// value changed in one and not the other diverges either way. What an InternalsVisibleTo buys +/// is the appearance of a single definition; what this test buys is the divergence showing up as a +/// failing build. +/// +/// +/// Core's holder is reached by reflection, deliberately: the point is to read the shipping value, +/// from the shipping assembly, without widening anything to get at it. +/// +/// +public class DiagnosticsAgreementTests +{ + /// + /// Every value the adapter restates from Core. The names are identical on both holders, which is + /// also the convention that keeps a new restated constant from being missed here. + /// + private static readonly string[] Restated = + [ + "SpanNamePrefix", + "OperationDimension", + "OutcomeDimension", + "ErrorClassDimension", + "NestedDimension", + "OperationAttribute", + "OutcomeAttribute", + "ErrorClassAttribute", + "ErrorTypeAttribute", + "CorrelationIdAttribute", + "FaultedOutcome", + "OperationCountInstrument", + "OperationDurationInstrument", + "OperationFailuresInstrument", + ]; + + private static readonly Type CoreHolder = + typeof(ExperienceOperationErrorClass).Assembly.GetType("AgentExperience.Core.Diagnostics.ExperienceDiagnostics", throwOnError: true)!; + + private static readonly Type AdapterHolder = typeof(InjectionDiagnostics); + + [Fact] + public void The_two_holders_agree_on_every_restated_wire_name() + { + // The sanity guard: a typo in the list above, or a Core rename, must not make this pass by + // comparing nothing. + Assert.Equal(14, Restated.Length); + + foreach (var name in Restated) + { + var core = Constant(CoreHolder, name); + var adapter = Constant(AdapterHolder, name); + + Assert.False(string.IsNullOrWhiteSpace(core), $"Core defines no constant '{name}'."); + Assert.Equal(core, adapter); + } + } + + [Fact] + public void The_two_holders_deliberately_disagree_on_the_source_name() + { + // Assembly-scoped names are the one thing that must differ: a text-only host subscribes to + // Core without pulling the adapter into its telemetry configuration, and AgentExperience.* + // takes both for a host that wants them together. + Assert.Equal("AgentExperience.Core", Constant(CoreHolder, "SourceName")); + Assert.Equal("AgentExperience.MicrosoftAgentFramework", InjectionDiagnostics.SourceName); + Assert.StartsWith(Constant(CoreHolder, "SpanNamePrefix"), "agentexperience.inject", StringComparison.Ordinal); + } + + /// + /// The classification tables agree, arm for arm. Replacing the adapter's whole switch with + /// => Cancelled used to leave every adapter test passing. + /// + /// Which failure to classify. + /// Whether the token the host handed the outermost operation was cancelled. + /// Whether the token the operation itself was handed was cancelled. + [Theory] + [InlineData("cancelled-by-caller", true, true)] + [InlineData("cancelled-by-a-library-budget", false, true)] + [InlineData("cancelled-by-nobody", false, false)] + [InlineData("timeout", false, false)] + [InlineData("store", false, false)] + [InlineData("anything-else", false, false)] + public void The_two_holders_classify_a_failure_identically(string kind, bool hostCancelled, bool operationCancelled) + { + // Both tokens, so the arm that separates a deadline this library imposed on an inner step from + // the caller having given up is compared too. The adapter passes the same token twice in + // production -- it imposes no budget of its own -- but its table must still be Core's. + using var host = new CancellationTokenSource(); + using var operationCancellation = new CancellationTokenSource(); + if (hostCancelled) + { + host.Cancel(); + } + + if (operationCancelled) + { + operationCancellation.Cancel(); + } + + var failure = kind switch + { + "cancelled-by-caller" or "cancelled-by-a-library-budget" => + new OperationCanceledException("a cancelled token", operationCancellation.Token), + "cancelled-by-nobody" => new OperationCanceledException("a cancellation nobody asked for"), + "timeout" => (Exception)new TimeoutException("the call exceeded its bound"), + "store" => new ExperienceStoreException("the database is unreachable"), + _ => new InvalidOperationException("something nobody classified"), + }; + + var core = Classify(failure, operationCancellation.Token, host.Token); + var adapter = InjectionDiagnostics.Classify(failure, operationCancellation.Token, host.Token); + + Assert.Equal(core, adapter); + Assert.Equal(Name(core), InjectionDiagnostics.Name(adapter)); + } + + [Fact] + public void The_two_holders_name_every_error_class_identically() + { + foreach (var errorClass in Enum.GetValues()) + { + Assert.Equal(errorClass.ToString(), InjectionDiagnostics.Name(errorClass)); + Assert.Equal(Name(errorClass), InjectionDiagnostics.Name(errorClass)); + } + } + + private static string Constant(Type holder, string name) => + (string)holder + .GetField(name, BindingFlags.Static | BindingFlags.Public | BindingFlags.NonPublic)! + .GetValue(null)!; + + private static ExperienceOperationErrorClass Classify( + Exception exception, + CancellationToken operationToken, + CancellationToken hostToken) => + (ExperienceOperationErrorClass)CoreHolder + .GetMethod("Classify", BindingFlags.Static | BindingFlags.Public | BindingFlags.NonPublic)! + .Invoke(null, [exception, operationToken, hostToken])!; + + private static string Name(ExperienceOperationErrorClass errorClass) => + (string)CoreHolder + .GetMethod("Name", BindingFlags.Static | BindingFlags.Public | BindingFlags.NonPublic)! + .Invoke(null, [errorClass])!; +} diff --git a/tests/AgentExperience.MicrosoftAgentFramework.Tests/Diagnostics/InjectionTelemetryTests.cs b/tests/AgentExperience.MicrosoftAgentFramework.Tests/Diagnostics/InjectionTelemetryTests.cs new file mode 100644 index 0000000..cd42e01 --- /dev/null +++ b/tests/AgentExperience.MicrosoftAgentFramework.Tests/Diagnostics/InjectionTelemetryTests.cs @@ -0,0 +1,707 @@ +using System.Diagnostics; +using System.Runtime.CompilerServices; +using System.Text.Json; +using AgentExperience.Core.Diagnostics; +using AgentExperience.Core.Retrieval; +using AgentExperience.MicrosoftAgentFramework.Diagnostics; +using AgentExperience.MicrosoftAgentFramework.Injection; +using Microsoft.Agents.AI; +using Microsoft.Extensions.AI; + +namespace AgentExperience.MicrosoftAgentFramework.Tests.Diagnostics; + +/// +/// The adapter's side of the story: one inject span and one count/duration pair per +/// invocation, the host's own correlation ID and an omission count on the span, nothing of +/// the block that was injected anywhere -- and, the negative claim that matters most, no span at all +/// around the agent's own delegation. +/// +[Collection(TelemetryCollection.Name)] +public class InjectionTelemetryTests +{ + private const string CountInstrument = "agentexperience.operation.count"; + private const string DurationInstrument = "agentexperience.operation.duration"; + private const string FailuresInstrument = "agentexperience.operation.failures"; + private const string InjectSpan = "agentexperience.inject"; + private const string AdapterSource = "AgentExperience.MicrosoftAgentFramework"; + + /// A string that cannot occur by accident, planted in the lesson the block would carry. + private const string Marker = "W2-CANARY-71bc-DO-NOT-EXPORT"; + + private static readonly Scope TestScope = new("tenant-1", "app-1", "project-1"); + + private static readonly AuthorizationContext Authorization = new("tenant-1", "host", ["experience:read"], DateTimeOffset.UnixEpoch); + + /// + /// The name of the control span the stub agent opens inside its own RunAsync body. + /// + private const string DelegationControlSpan = "tests.delegation_control"; + + /// + /// A test-owned source under the prefix a host subscribes to, so a span it starts is collected by + /// exactly the filter the library's own spans go through. Nothing in the library emits from it. + /// + private static readonly ActivitySource Control = new("AgentExperience.Tests.DelegationControl"); + + [Fact] + public async Task An_injection_reports_its_outcome_correlation_id_and_omitted_count() + { + using var probe = TelemetryProbe.Start(); + var harness = new Harness { Limits = ExperienceInjectionLimits.Default with { MaxRecords = 1 } }; + harness.World.Publish(InjectionRecords.Record(InjectionRecords.Id(1), TestScope), relevance: 1d); + harness.World.Publish(InjectionRecords.Record(InjectionRecords.Id(2), TestScope), relevance: 0.5d); + + await harness.Agent().RunAsync("refund ticket stuck on a lock"); + + var reported = Assert.Single(harness.Results); + Assert.Equal(InjectionOutcome.Injected, reported.Outcome); + Assert.Single(reported.Omitted); + + var span = Assert.Single(probe.LibraryActivities, activity => activity.OperationName == InjectSpan); + Assert.Equal(ActivityStatusCode.Ok, span.Status); + Assert.Equal("inject", span.GetTagItem("agentexperience.operation")); + Assert.Equal(nameof(InjectionOutcome.Injected), span.GetTagItem("agentexperience.outcome")); + Assert.Equal("corr-1", span.GetTagItem("agentexperience.correlation_id")); + + // A count, not the reasons: how many records were left out is a number an operator can graph, + // while why each one was left out belongs to the typed result. + Assert.Equal(1, span.GetTagItem("agentexperience.omitted_count")); + + var counted = Assert.Single(probe.For(CountInstrument, "inject")); + Assert.Equal(AdapterSource, counted.Meter); + Assert.Equal("inject", counted.Tags["operation"]); + Assert.Equal(nameof(InjectionOutcome.Injected), counted.Tags["outcome"]); + Assert.Equal(1d, counted.Value); + + // An injection is never nested: this adapter emits one operation and the only thing that calls + // it is the agent pipeline, which is the host. The dimension is still written, so a host + // summing across both meters does not have to special-case which one a series came from. + Assert.Equal(false, counted.Tags["nested"]); + Assert.Single(probe.For(CountInstrument, "inject", nested: false)); + Assert.Empty(probe.For(CountInstrument, "inject", nested: true)); + + var timed = Assert.Single(probe.For(DurationInstrument, "inject")); + Assert.True(timed.Value >= 0d); + Assert.Equal(nameof(InjectionOutcome.Injected), timed.Tags["outcome"]); + + Assert.Empty(probe.For(FailuresInstrument, "inject")); + } + + [Fact] + public async Task An_injection_that_injects_nothing_is_a_decision_not_a_failure() + { + using var probe = TelemetryProbe.Start(); + var harness = new Harness(); + + // Nothing published, so retrieval completes with no records at all. + await harness.Agent().RunAsync("refund ticket stuck on a lock"); + + Assert.Equal(InjectionOutcome.NothingToInject, Assert.Single(harness.Results).Outcome); + + var span = Assert.Single(probe.LibraryActivities, activity => activity.OperationName == InjectSpan); + Assert.Equal(ActivityStatusCode.Ok, span.Status); + Assert.Equal(nameof(InjectionOutcome.NothingToInject), span.GetTagItem("agentexperience.outcome")); + Assert.Equal(nameof(InjectionOutcome.NothingToInject), Assert.Single(probe.For(CountInstrument, "inject")).Tags["outcome"]); + Assert.Empty(probe.For(FailuresInstrument, "inject")); + } + + [Fact] + public async Task A_host_opt_out_still_reports_an_outcome() + { + using var probe = TelemetryProbe.Start(); + var harness = new Harness { Resolve = _ => null }; + + await harness.Agent().RunAsync("refund ticket stuck on a lock"); + + Assert.Equal(nameof(InjectionOutcome.Skipped), Assert.Single(probe.For(CountInstrument, "inject")).Tags["outcome"]); + } + + [Fact] + public async Task Caller_cancellation_is_classified_and_propagates_unchanged() + { + using var probe = TelemetryProbe.Start(); + using var cancellation = new CancellationTokenSource(); + + // The invocation is cancelled before it starts, so retrieval -- the one call in this provider + // whose cancellation is allowed out -- throws on the caller's own token. Everything else the + // provider can catch is already a reported InjectionOutcome, which is why this is the only + // faulted path it has. + await cancellation.CancelAsync(); + + var harness = new Harness(); + harness.World.Publish(InjectionRecords.Record(InjectionRecords.Id(1), TestScope)); + + await Assert.ThrowsAnyAsync( + () => harness.Agent().RunAsync("refund ticket stuck on a lock", cancellationToken: cancellation.Token)); + + var span = Assert.Single(probe.LibraryActivities, activity => activity.OperationName == InjectSpan); + Assert.Equal(ActivityStatusCode.Error, span.Status); + Assert.Equal(nameof(ExperienceOperationErrorClass.Cancelled), span.GetTagItem("agentexperience.error.class")); + Assert.Equal("System.OperationCanceledException", span.GetTagItem("error.type")); + Assert.Equal("Faulted", span.GetTagItem("agentexperience.outcome")); + + var failure = Assert.Single(probe.For(FailuresInstrument, "inject")); + Assert.Equal("inject", failure.Tags["operation"]); + Assert.Equal(nameof(ExperienceOperationErrorClass.Cancelled), failure.Tags["error.class"]); + Assert.Equal(false, failure.Tags["nested"]); + + // Faulted is still counted and timed, and the host callback never ran. + Assert.Equal("Faulted", Assert.Single(probe.For(CountInstrument, "inject")).Tags["outcome"]); + Assert.Single(probe.For(DurationInstrument, "inject")); + Assert.Empty(harness.Results); + } + + /// + /// The four outcomes an operator would actually alert on. Every one of them could emit no span + /// close, no count and no duration without a single test noticing. + /// + /// The InjectionOutcome to drive. + [Theory] + [InlineData(nameof(InjectionOutcome.RetrievalTimedOut))] + [InlineData(nameof(InjectionOutcome.RetrievalDenied))] + [InlineData(nameof(InjectionOutcome.RetrievalFailed))] + [InlineData(nameof(InjectionOutcome.Failed))] + public async Task Every_reported_outcome_closes_its_span_and_records_its_measurements(string outcome) + { + using var probe = TelemetryProbe.Start(); + + var released = new TaskCompletionSource(); + var harness = Harnessed(outcome, released); + harness.World.Publish(InjectionRecords.Record(InjectionRecords.Id(1), TestScope)); + + var response = await harness.Agent().RunAsync("refund ticket stuck on a lock"); + released.TrySetResult(); + + // The invocation ran regardless: nothing about a failing injection reaches the agent. + Assert.NotNull(response); + Assert.Equal(outcome, Assert.Single(harness.Results).Outcome.ToString()); + + var span = Assert.Single(probe.LibraryActivities, activity => activity.OperationName == InjectSpan); + + // A reported outcome is a decision, however unwelcome, so the span is Ok and the failure + // counter is untouched -- the operator alerts on the outcome dimension, not on error.class. + Assert.Equal(ActivityStatusCode.Ok, span.Status); + Assert.Equal(outcome, span.GetTagItem("agentexperience.outcome")); + Assert.Equal(outcome, Assert.Single(probe.For(CountInstrument, "inject")).Tags["outcome"]); + Assert.Equal(outcome, Assert.Single(probe.For(DurationInstrument, "inject")).Tags["outcome"]); + Assert.Empty(probe.For(FailuresInstrument, "inject")); + + // And the host's correlation identifier is there for all of them but the one whose request + // never resolved -- which is the point of reading it off the request rather than off a result + // these outcomes may not have. + if (outcome != nameof(InjectionOutcome.Failed)) + { + Assert.Equal("corr-1", span.GetTagItem("agentexperience.correlation_id")); + } + } + + [Fact] + public async Task Span_attributes_are_only_the_documented_keys() + { + using var probe = TelemetryProbe.Start(); + + var harness = new Harness { Limits = ExperienceInjectionLimits.Default with { MaxRecords = 1 } }; + harness.World.Publish(InjectionRecords.Record(InjectionRecords.Id(1), TestScope), relevance: 1d); + harness.World.Publish(InjectionRecords.Record(InjectionRecords.Id(2), TestScope), relevance: 0.5d); + await harness.Agent().RunAsync("refund ticket stuck on a lock"); + + // Plus an outcome that carries an InjectionFailure -- whose Reason is host- and driver-derived + // free text, and is exactly the kind of value an attribute added in good faith would carry. + var failing = new Harness { World = { SearchThrows = new ExperienceStoreException("Host=db;Password=hunter2") } }; + failing.World.Publish(InjectionRecords.Record(InjectionRecords.Id(1), TestScope)); + await failing.Agent().RunAsync("refund ticket stuck on a lock"); + Assert.NotNull(Assert.Single(failing.Results).Failure); + + // Plus a faulted injection, so error.type and error.class have been written too. + using var cancellation = new CancellationTokenSource(); + await cancellation.CancelAsync(); + var faulting = new Harness(); + faulting.World.Publish(InjectionRecords.Record(InjectionRecords.Id(1), TestScope)); + await Assert.ThrowsAnyAsync( + () => faulting.Agent().RunAsync("refund ticket stuck on a lock", cancellationToken: cancellation.Token)); + + // Exactly these, no more. The marker sweep can only prove that the content one run happened to + // carry stayed off a span; an exact key set is what makes adding an attribute that carries + // host free text a deliberate, reviewed act. + Assert.Equal( + new[] + { + "agentexperience.correlation_id", + "agentexperience.error.class", + "agentexperience.omitted_count", + "agentexperience.operation", + "agentexperience.outcome", + "error.type", + }, + probe.EverySpanTagKey.Order(StringComparer.Ordinal)); + } + + /// Builds the harness that drives one of the four alertable outcomes. + private static Harness Harnessed(string outcome, TaskCompletionSource released) => outcome switch + { + nameof(InjectionOutcome.RetrievalTimedOut) => new Harness + { + // A real clock and a short budget, so retrieval reaches its own timeout rather than a + // frozen provider's timer that never fires. + Clock = TimeProvider.System, + Policy = RetrievalPolicy.Default with { Timeout = TimeSpan.FromMilliseconds(20) }, + World = { SearchDelay = token => released.Task.WaitAsync(token) }, + }, + + nameof(InjectionOutcome.RetrievalDenied) => new Harness + { + // The resolver asks in a scope the host-established authorization does not cover, so + // retrieval refuses before either channel is touched. + Asking = new AuthorizationContext("tenant-2", "host", ["experience:read"], DateTimeOffset.UnixEpoch), + }, + + nameof(InjectionOutcome.RetrievalFailed) => new Harness + { + World = { SearchThrows = new ExperienceStoreException("the database is unreachable") }, + }, + + nameof(InjectionOutcome.Failed) => new Harness + { + Resolve = _ => throw new InvalidOperationException("the host's resolver threw"), + }, + + _ => throw new InvalidOperationException($"No harness for '{outcome}'."), + }; + + [Fact] + public async Task Injection_telemetry_never_contains_the_block_it_injected() + { + using var probe = TelemetryProbe.Start(); + var harness = new Harness(); + harness.World.Publish(InjectionRecords.Record(InjectionRecords.Id(1), TestScope, lesson: $"Check the {Marker} table first.")); + + await harness.Agent().RunAsync($"a refund ticket about {Marker}"); + + // The marker really did reach the model, so the sweep below is about something. + var injected = harness.InjectedText(); + Assert.NotNull(injected); + Assert.Contains(Marker, injected, StringComparison.Ordinal); + + Assert.NotEmpty(probe.EverySpanTagValue); + Assert.NotEmpty(probe.EveryMeasurementTagValue); + + foreach (var value in probe.EverySpanTagValue.Concat(probe.EveryMeasurementTagValue)) + { + Assert.DoesNotContain(Marker, value, StringComparison.Ordinal); + } + + Assert.All(probe.LibraryActivities, activity => + { + Assert.Empty(activity.Events); + Assert.Null(activity.StatusDescription); + }); + } + + [Fact] + public async Task Metric_dimensions_are_only_operation_outcome_error_class_and_nested() + { + using var probe = TelemetryProbe.Start(); + using var cancellation = new CancellationTokenSource(); + + var injecting = new Harness(); + injecting.World.Publish(InjectionRecords.Record(InjectionRecords.Id(1), TestScope)); + await injecting.Agent().RunAsync("refund ticket stuck on a lock"); + + await cancellation.CancelAsync(); + var faulting = new Harness(); + faulting.World.Publish(InjectionRecords.Record(InjectionRecords.Id(1), TestScope)); + await Assert.ThrowsAnyAsync( + () => faulting.Agent().RunAsync("refund ticket stuck on a lock", cancellationToken: cancellation.Token)); + + var keys = probe.EveryMeasurementTagKey; + + Assert.Contains("operation", keys); + Assert.Contains("outcome", keys); + Assert.Contains("error.class", keys); + Assert.Contains("nested", keys); + + // Exactly these, so a fifth dimension has to be added here on purpose. The probe subscribes to + // AgentExperience.* rather than to this adapter alone, so this pins Core's retrieval + // measurements as well as the adapter's own -- the two meters must not drift apart. + Assert.Equal(new[] { "error.class", "nested", "operation", "outcome" }, keys.Order(StringComparer.Ordinal)); + + // The correlation ID is on the span and only on the span: it is the host's string, so it is + // exactly the kind of value that must never become a metric label. + Assert.DoesNotContain("corr-1", probe.EveryMeasurementTagValue); + Assert.Contains("corr-1", probe.EverySpanTagValue); + } + + [Fact] + public async Task Library_adds_no_agent_model_or_tool_spans() + { + // The one test that watches every source in the process: its claim is that nothing this + // library emits is agent-, model-, or tool-shaped, which means looking at everything. + using var probe = TelemetryProbe.EverySource(); + + var delegating = false; + var duringDelegation = new List(); + probe.Started = activity => + { + if (delegating && activity.Source.Name.StartsWith(TelemetryProbe.SourcePrefix, StringComparison.Ordinal)) + { + duringDelegation.Add(activity.OperationName); + } + }; + + var capture = new InMemoryExperienceCaptureService( + new DefaultSanitizer(SanitizationOptions.Empty), + new CaptureLimits(10, 10, 1_000, 1_000)); + + var inner = new WindowedAgent(open => delegating = open); + var wrapped = inner.AsBuilder().UseExperienceCapture(capture, new ExperienceCaptureOptions + { + NewId = Guid.NewGuid, + ResolveRun = context => new ExperienceRunDescriptor(context.Messages.Last().Text, TestScope, "captured by tests"), + FinalizationTimeout = TimeSpan.FromSeconds(5), + + // Tool-call capture installs MAF's own function-invocation middleware, which needs a + // function-invoking chat client underneath. This stub agent is not one, and tool calls are + // beside the point here: what matters is what happens around the delegation. + CaptureToolCalls = false, + }).Build(); + + var response = await wrapped.RunAsync("do the thing"); + + // The wrapper did its job... + Assert.Equal("windowed agent reply", response.Text); + Assert.True(inner.Ran); + + // ...and every span this library emitted is one of its own operations, named from the frozen + // table. Nothing agent-, model-, or tool-shaped: MAF owns those and they are not duplicated. + var frozen = new[] + { + "agentexperience.capture.start_run", + "agentexperience.capture.append_attempt", + "agentexperience.capture.complete_run", + "agentexperience.verify", + "agentexperience.reflect", + "agentexperience.finalize", + "agentexperience.lifecycle.commit", + "agentexperience.confidence.apply", + "agentexperience.retrieve", + "agentexperience.index", + "agentexperience.deindex", + "agentexperience.reindex", + "agentexperience.reuse_feedback", + InjectSpan, + }; + + // The control span is under the same prefix on purpose -- that is what makes it a control for + // the window below -- so it is excluded here by source rather than by name. + var emitted = probe.LibraryActivities + .Where(activity => activity.Source.Name != Control.Name) + .ToList(); + + Assert.NotEmpty(emitted); + Assert.All(emitted, activity => + Assert.True(frozen.Contains(activity.OperationName, StringComparer.Ordinal), $"'{activity.OperationName}' is not in the frozen operation table.")); + + // Exactly the operations the wrapped run performed, each exactly once. The frozen-name check + // above is a set membership test, so a span opened around the delegation that reused a + // frozen name would satisfy it: this counts them instead. One invocation, one captured run. + Assert.Equal( + new[] + { + "agentexperience.capture.append_attempt", + "agentexperience.capture.complete_run", + "agentexperience.capture.start_run", + }, + emitted.Select(activity => activity.OperationName).Order(StringComparer.Ordinal)); + + // And the delegation itself -- the window in which the wrapped agent's own RunAsync body runs + // -- produced none of this library's spans. Capture brackets the run; it never wraps it in a + // span. + // + // The window has a positive control: the agent opens one span of its own, from a source under + // the same prefix a host subscribes to, while its body is running. So the window really does + // catch what is started inside it, and "empty except the control" is a claim that can fail -- + // which it did not when the window could never be non-empty at all. + Assert.Equal([DelegationControlSpan], duringDelegation); + } + + /// + /// Matrix row 15's other half. The capture wrapper reads to stamp + /// the run's provenance correlation, and this is the one row where the adapter's new + /// inject span could plausibly have changed existing behaviour: it opens and closes an + /// activity on the very path that harvest runs on. + /// + [Fact] + public async Task Capture_still_harvests_the_ambient_trace_id_while_injection_runs() + { + using var probe = TelemetryProbe.Start(); + + var harness = new Harness(); + harness.World.Publish(InjectionRecords.Record(InjectionRecords.Id(1), TestScope)); + + var capture = new InMemoryExperienceCaptureService( + new DefaultSanitizer(SanitizationOptions.Empty), + new CaptureLimits(10, 10, 1_000, 1_000)); + + var runId = Guid.NewGuid(); + var wrapped = harness.Agent().AsBuilder().UseExperienceCapture(capture, new ExperienceCaptureOptions + { + NewId = () => runId, + ResolveRun = context => new ExperienceRunDescriptor(context.Messages.Last().Text, TestScope, "captured by tests"), + FinalizationTimeout = TimeSpan.FromSeconds(5), + CaptureToolCalls = false, + }).Build(); + + using var ambient = Control.StartActivity("host.invocation", ActivityKind.Internal); + Assert.NotNull(ambient); + Assert.Same(ambient, Activity.Current); + + await wrapped.RunAsync("refund ticket stuck on a lock"); + + // The injection really did happen on this path, so the harvest below ran with the inject span + // having been opened and closed underneath it. + Assert.Single(probe.LibraryActivities, activity => activity.OperationName == InjectSpan); + + Assert.True(capture.TryGetRun(runId, out var run)); + Assert.Equal(ambient.TraceId.ToHexString(), run!.Provenance.CorrelationId); + + // And the caller's ambient activity is exactly the one it started: the inject span was closed + // behind it, not left current. + Assert.Same(ambient, Activity.Current); + } + + /// + /// Every arm of the adapter's classification table. It is restated rather than shared with Core, + /// and replacing the whole switch with => Cancelled used to leave every adapter test + /// passing -- a dead copy whose own doc comment warned of exactly the drift nothing checked. + /// + /// Which failure to classify. + /// Whether the token the host handed the outermost operation was cancelled. + /// Whether the token this operation itself was handed was cancelled. + /// The bounded class the adapter must report. + [Theory] + [InlineData("cancelled-by-caller", true, true, nameof(ExperienceOperationErrorClass.Cancelled))] + [InlineData("cancelled-by-a-library-budget", false, true, nameof(ExperienceOperationErrorClass.Timeout))] + [InlineData("cancelled-by-nobody", false, false, nameof(ExperienceOperationErrorClass.Infrastructure))] + [InlineData("timeout", false, false, nameof(ExperienceOperationErrorClass.Timeout))] + [InlineData("store", false, false, nameof(ExperienceOperationErrorClass.Infrastructure))] + [InlineData("anything-else", false, false, nameof(ExperienceOperationErrorClass.Unexpected))] + public void The_adapter_classification_table(string kind, bool hostCancelled, bool operationCancelled, string expected) + { + // Two tokens, because a cancelled token is not automatically the caller's: an inner step can + // run on a deadline this library imposed, and a deadline expiring is a Timeout rather than + // somebody giving up. An injection always passes the same token for both -- this adapter + // imposes no budget of its own -- but the table it applies has to be Core's, arm for arm. + using var host = new CancellationTokenSource(); + using var operationCancellation = new CancellationTokenSource(); + if (hostCancelled) + { + host.Cancel(); + } + + if (operationCancelled) + { + operationCancellation.Cancel(); + } + + var failure = Failure(kind, operationCancellation.Token); + var classified = InjectionDiagnostics.Classify(failure, operationCancellation.Token, host.Token); + + Assert.Equal(expected, classified.ToString()); + Assert.Equal(expected, InjectionDiagnostics.Name(classified)); + } + + /// + /// The adapter's failure path carries whatever arrives, not only the cancellation that is the one + /// thing able to escape the injection body today. + /// + [Fact] + public void A_faulted_injection_records_whatever_class_the_failure_falls_into() + { + using var probe = TelemetryProbe.Start(); + + var trace = InjectionDiagnostics.Start(); + InjectionDiagnostics.Faulted(trace, new TimeoutException("the bound was exceeded"), CancellationToken.None); + trace.Activity?.Dispose(); + + var span = Assert.Single(probe.LibraryActivities, activity => activity.OperationName == InjectSpan); + Assert.Equal(ActivityStatusCode.Error, span.Status); + Assert.Equal(nameof(ExperienceOperationErrorClass.Timeout), span.GetTagItem("agentexperience.error.class")); + Assert.Equal("System.TimeoutException", span.GetTagItem("error.type")); + + Assert.Equal( + nameof(ExperienceOperationErrorClass.Timeout), + Assert.Single(probe.For(FailuresInstrument, "inject")).Tags["error.class"]); + Assert.Equal("Faulted", Assert.Single(probe.For(CountInstrument, "inject")).Tags["outcome"]); + Assert.Single(probe.For(DurationInstrument, "inject")); + } + + /// + /// "Report is the one place inject is counted" is enforced, not merely intended. A future + /// early return in the injection body would otherwise emit a span with no outcome, no count + /// and no duration -- a silent hole in the operation an operator alerts on. + /// + [Fact] + public void An_injection_that_reported_nothing_is_still_counted() + { + using var probe = TelemetryProbe.Start(); + + var unreported = InjectionDiagnostics.Start(); + InjectionDiagnostics.Closed(unreported); + unreported.Activity?.Dispose(); + + var span = Assert.Single(probe.LibraryActivities, activity => activity.OperationName == InjectSpan); + Assert.Equal(ActivityStatusCode.Error, span.Status); + Assert.Equal("Faulted", span.GetTagItem("agentexperience.outcome")); + + // An exit with no outcome is this library's bug, not a dependency's, and no exception was + // involved -- so the class is Unexpected and there is no error.type to report. + Assert.Equal(nameof(ExperienceOperationErrorClass.Unexpected), span.GetTagItem("agentexperience.error.class")); + Assert.Null(span.GetTagItem("error.type")); + + Assert.Single(probe.For(CountInstrument, "inject")); + Assert.Single(probe.For(DurationInstrument, "inject")); + Assert.Single(probe.For(FailuresInstrument, "inject")); + } + + [Fact] + public async Task An_injection_that_reported_its_outcome_is_not_counted_twice() + { + using var probe = TelemetryProbe.Start(); + var harness = new Harness(); + harness.World.Publish(InjectionRecords.Record(InjectionRecords.Id(1), TestScope)); + + await harness.Agent().RunAsync("refund ticket stuck on a lock"); + + // The finally's invariant check ran on a trace that had already reported, and did nothing: + // one injection, one count, one duration, and no failure at all. + Assert.Equal(nameof(InjectionOutcome.Injected), Assert.Single(probe.For(CountInstrument, "inject")).Tags["outcome"]); + Assert.Single(probe.For(DurationInstrument, "inject")); + Assert.Empty(probe.For(FailuresInstrument, "inject")); + } + + private static Exception Failure(string kind, CancellationToken cancellationToken) => kind switch + { + "cancelled-by-caller" or "cancelled-by-a-library-budget" => new OperationCanceledException("a cancelled token", cancellationToken), + "cancelled-by-nobody" => new OperationCanceledException("a client-side timeout, arriving as a cancellation nobody asked for"), + "timeout" => new TimeoutException("the call exceeded its bound"), + "store" => new ExperienceStoreException("the database is unreachable"), + _ => new InvalidOperationException("something nobody classified"), + }; + + /// + /// A minimal that reports when its own RunAsync body is executing, so + /// a listener can tell "around the delegation" from "during the delegation". + /// + private sealed class WindowedAgent(Action window) : AIAgent + { + /// Whether the agent's body ever ran, so an empty delegation window cannot pass by never opening. + public bool Ran { get; private set; } + + protected override ValueTask CreateSessionCoreAsync(CancellationToken cancellationToken = default) => + new(new WindowedSession()); + + protected override ValueTask SerializeSessionCoreAsync(AgentSession session, JsonSerializerOptions? jsonSerializerOptions = null, CancellationToken cancellationToken = default) => + new(session.StateBag.Serialize()); + + protected override ValueTask DeserializeSessionCoreAsync(JsonElement serializedState, JsonSerializerOptions? jsonSerializerOptions = null, CancellationToken cancellationToken = default) => + new(new WindowedSession()); + + protected override async Task RunCoreAsync(IEnumerable messages, AgentSession? session = null, AgentRunOptions? options = null, CancellationToken cancellationToken = default) + { + window(true); + try + { + Ran = true; + + // The window's positive control: one span, from a source under the prefix a host + // subscribes to, started while the delegation is in flight. Without it "the window was + // empty" is a sentence that cannot be false. + using (Control.StartActivity(DelegationControlSpan, ActivityKind.Internal)) + { + await Task.Yield(); + } + + return new AgentResponse(new ChatMessage(ChatRole.Assistant, "windowed agent reply")); + } + finally + { + window(false); + } + } + + protected override async IAsyncEnumerable RunCoreStreamingAsync(IEnumerable messages, AgentSession? session = null, AgentRunOptions? options = null, [EnumeratorCancellation] CancellationToken cancellationToken = default) + { + window(true); + Ran = true; + await Task.Yield(); + yield return new AgentResponseUpdate(ChatRole.Assistant, "windowed"); + window(false); + } + + private sealed class WindowedSession : AgentSession; + } + + /// The same shape the injection tests use: a real agent, a real retrieval service, a fake world. + private sealed class Harness + { + private readonly List _results = []; + + public FakeExperienceWorld World { get; } = new(); + + public RecordingChatClient Client { get; } = new(); + + public TimeProvider Clock { get; init; } = new FrozenTimeProvider(InjectionRecords.Now); + + /// The retrieval policy the provider's own retrieval service runs under, so a test can give it a real, short timeout. + public RetrievalPolicy Policy { get; init; } = RetrievalPolicy.Default; + + /// The authorization the default resolver asks with, so a test can ask in a scope the host does not cover. + public AuthorizationContext Asking { get; init; } = Authorization; + + public ExperienceInjectionLimits Limits { get; init; } = ExperienceInjectionLimits.Default; + + public Func? Resolve { get; init; } + + public Func? Decide { get; init; } + + public IReadOnlyList Results + { + get + { + lock (_results) + { + return [.. _results]; + } + } + } + + public ChatClientAgent Agent() => new(Client, new ChatClientAgentOptions { AIContextProviders = [Provider()] }); + + public string? InjectedText() => Client.LastMessages + ?.FirstOrDefault(m => m.AdditionalProperties?.ContainsKey(ExperienceContextProvider.HistoricalReferenceKey) == true) + ?.Text; + + public ExperienceContextProvider Provider() => new( + new ExperienceRetrievalService(World, Policy, RankingWeights.Default, Clock), + World, + new ExperienceInjectionOptions + { + ResolveRequest = Resolve ?? (context => new RetrieveExperienceRequest( + Asking, + TestScope, + context.Messages.LastOrDefault(m => m.Role == ChatRole.User && !string.IsNullOrWhiteSpace(m.Text))?.Text + ?? "refund ticket stuck on a lock", + CorrelationId: "corr-1")), + Limits = Limits, + DecideInjection = Decide, + TimeProvider = Clock, + OnContextInjected = result => + { + lock (_results) + { + _results.Add(result); + } + }, + }); + } +} diff --git a/tests/AgentExperience.MicrosoftAgentFramework.Tests/Diagnostics/TelemetryProbe.cs b/tests/AgentExperience.MicrosoftAgentFramework.Tests/Diagnostics/TelemetryProbe.cs new file mode 100644 index 0000000..23be0b7 --- /dev/null +++ b/tests/AgentExperience.MicrosoftAgentFramework.Tests/Diagnostics/TelemetryProbe.cs @@ -0,0 +1,205 @@ +using System.Diagnostics; +using System.Diagnostics.Metrics; + +namespace AgentExperience.MicrosoftAgentFramework.Tests.Diagnostics; + +/// One measurement a saw, flattened for assertions. +/// The instrument's name. +/// The meter that published it, which is the emitting assembly's source name. +/// The recorded value, widened to . +/// The measurement's dimensions. +internal sealed record ProbedMeasurement( + string Instrument, + string Meter, + double Value, + IReadOnlyDictionary Tags); + +/// +/// The host, in miniature, for the adapter's side of the story: it registers the listeners the +/// library is forbidden to create and collects what arrives. +/// +/// +/// It listens to AgentExperience.* only. The content sweeps assert that no tag value on +/// any collected span carries captured text; run over every source in the process, they would be +/// asserting that about MAF's own gen_ai spans too, and a live MAF instrumentation that put the +/// prompt on its own span would fail this library's test for someone else's tags. +/// widens the span listener, and exactly one test uses it: the one whose +/// claim is that nothing agent-, model-, or tool-shaped comes from an AgentExperience.* source +/// while MAF's delegation runs. +/// +internal sealed class TelemetryProbe : IDisposable +{ + /// The prefix a host subscribes with. + internal const string SourcePrefix = "AgentExperience."; + + private readonly object _gate = new(); + private readonly List _activities = []; + private readonly List _measurements = []; + private readonly ActivityListener _activityListener; + private readonly MeterListener _meterListener; + + private TelemetryProbe(bool everySource) + { + _activityListener = new ActivityListener + { + ShouldListenTo = source => everySource || source.Name.StartsWith(SourcePrefix, StringComparison.Ordinal), + Sample = static (ref ActivityCreationOptions _) => ActivitySamplingResult.AllDataAndRecorded, + SampleUsingParentId = static (ref ActivityCreationOptions _) => ActivitySamplingResult.AllDataAndRecorded, + ActivityStarted = activity => + { + lock (_gate) + { + Started?.Invoke(activity); + } + }, + ActivityStopped = activity => + { + lock (_gate) + { + _activities.Add(activity); + } + }, + }; + + ActivitySource.AddActivityListener(_activityListener); + + _meterListener = new MeterListener + { + InstrumentPublished = (instrument, listener) => + { + if (instrument.Meter.Name.StartsWith(SourcePrefix, StringComparison.Ordinal)) + { + listener.EnableMeasurementEvents(instrument); + } + }, + }; + + _meterListener.SetMeasurementEventCallback((instrument, measurement, tags, _) => Add(instrument, measurement, tags)); + _meterListener.SetMeasurementEventCallback((instrument, measurement, tags, _) => Add(instrument, measurement, tags)); + _meterListener.Start(); + } + + /// Runs for every activity the moment it starts, whatever source it came from. + internal Action? Started { get; set; } + + /// Starts listening to this library's own sources and meters, which is what a host subscribes to. + internal static TelemetryProbe Start() => new(everySource: false); + + /// Starts listening to every source in the process, for the non-duplication proof only. + internal static TelemetryProbe EverySource() => new(everySource: true); + + /// Every finished activity, from every source, in the order it stopped. + internal IReadOnlyList Activities + { + get + { + lock (_gate) + { + return [.. _activities]; + } + } + } + + /// The finished activities this library emitted. + internal IReadOnlyList LibraryActivities => + [.. Activities.Where(activity => activity.Source.Name.StartsWith(SourcePrefix, StringComparison.Ordinal))]; + + /// Every measurement, in the order it was recorded. + internal IReadOnlyList Measurements + { + get + { + lock (_gate) + { + return [.. _measurements]; + } + } + } + + /// The measurements recorded to one instrument. + /// The instrument name. + internal IReadOnlyList For(string instrument) => + [.. Measurements.Where(measurement => string.Equals(measurement.Instrument, instrument, StringComparison.Ordinal))]; + + /// The measurements recorded to one instrument for one operation dimension value. + /// The instrument name. + /// The operation dimension value. + internal IReadOnlyList For(string instrument, string operation) => + [.. For(instrument).Where(measurement => + measurement.Tags.TryGetValue("operation", out var value) && Equals(value, operation))]; + + /// The measurements recorded to one instrument for one operation, split by whether another instrumented operation called it. + /// The instrument name. + /// The operation dimension value. + /// The nested dimension value to match. + internal IReadOnlyList For(string instrument, string operation, bool nested) => + [.. For(instrument, operation).Where(measurement => + measurement.Tags.TryGetValue("nested", out var value) && Equals(value, nested))]; + + /// + /// Every tag value, display name and status description on any span this library emitted. + /// Scoped to the library on purpose: what MAF's own spans carry is MAF's business, and sweeping it + /// here would make this library's content guarantee fail on someone else's tags. + /// + internal IReadOnlyList EverySpanTagValue => + [.. LibraryActivities + .SelectMany(activity => activity.TagObjects) + .Select(tag => tag.Value?.ToString()) + .Concat(LibraryActivities.Select(activity => activity.StatusDescription)) + .Concat(LibraryActivities.Select(activity => activity.DisplayName)) + .Where(value => value is not null) + .Select(value => value!)]; + + /// + /// Every attribute key on any span this library emitted, pinned exactly the way the + /// metric dimension set is pinned. A marker sweep only proves that the content one drive happened + /// to carry stayed off a span; an exact key set is what stops a new attribute carrying host free + /// text from being added without anyone having to say what it carries. + /// + internal IReadOnlyList EverySpanTagKey => + [.. LibraryActivities.SelectMany(activity => activity.TagObjects).Select(tag => tag.Key).Distinct(StringComparer.Ordinal)]; + + /// Every dimension value on any collected measurement. + internal IReadOnlyList EveryMeasurementTagValue => + [.. Measurements + .SelectMany(measurement => measurement.Tags.Values) + .Select(value => value?.ToString()) + .Where(value => value is not null) + .Select(value => value!)]; + + /// Every dimension key on any collected measurement. + internal IReadOnlyList EveryMeasurementTagKey => + [.. Measurements.SelectMany(measurement => measurement.Tags.Keys).Distinct(StringComparer.Ordinal)]; + + /// Unregisters both listeners. + public void Dispose() + { + _meterListener.Dispose(); + _activityListener.Dispose(); + } + + private void Add(Instrument instrument, double value, ReadOnlySpan> tags) + { + var copied = new Dictionary(tags.Length, StringComparer.Ordinal); + foreach (var tag in tags) + { + copied[tag.Key] = tag.Value; + } + + lock (_gate) + { + _measurements.Add(new ProbedMeasurement(instrument.Name, instrument.Meter.Name, value, copied)); + } + } +} + +/// +/// Telemetry listeners are process-wide, so every test that registers one runs here, on its own, +/// rather than collecting whatever a concurrent test happened to emit. +/// +[CollectionDefinition(Name, DisableParallelization = true)] +public sealed class TelemetryCollection +{ + /// The collection name to put on a test class with . + public const string Name = "AgentExperience telemetry (process-wide listeners)"; +}