From e22d757429d6adffdab99b890324381ec7d37951 Mon Sep 17 00:00:00 2001 From: ancplua Date: Wed, 1 Jul 2026 16:35:08 +0200 Subject: [PATCH] fix(otel): real span duration + honest doc + correct thread-count instrument (CODE RED #1/#2/#10) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit An adversarial OTel-compliance + honesty audit rated this code 3/10. This lands the verified subset of the confirmed HIGH/MEDIUM defects. #1 (HIGH, ~0-duration lie): the HttpClient/AspNetCore/gRPC DiagnosticListeners created their span on the framework's *.Stop event via the 2-arg StartActivity (StartTimeUtc=now) and immediately disposed it, so every emitted span had ~0 duration instead of the real operation latency. New internal QylActivitySource.StartAtAmbientStart(name, kind) stamps the span to the ambient framework Activity's real StartTimeUtc (parented to it for trace correlation), with a now-stamped fallback when there is no ambient activity. All three listeners switched to it. #2 (HIGH, dishonest doc): DiagnosticListenerSubscriber claimed it "publishes the same span shapes" — false while durations were fabricated. Doc now states the actual mechanism (reacts on *.Stop, stamps to ambient start for real duration). #10 (MEDIUM, metrics-semconv): dotnet.thread_pool.thread.count was an unitless ObservableGauge; per OTel semconv it is an (Observable)UpDownCounter with UCUM unit {thread}. Switched instrument type + added unit. Verified: core.slnf Release 0/0; verify-webapi-aot-demo passes (fixture unchanged — the attribute shape is identical; note the fixture is duration-insensitive, which is itself tracked as a separate finding). No PublicAPI change (all internal/private). NOT in this commit (separate verified increments): #3 double-count between the listener and interceptor lanes (+ the fixture that masks it), #4/#11 OTLP Events/Links/Status.Message dropped on ingest, #6 url.scheme, #7 http.request.method_original on the interceptor path, #9 Azure span name ignores methodName. Co-Authored-By: Claude Opus 4.8 (1M context) --- .../AspNetCore/AspNetCoreDiagnosticListener.cs | 2 +- .../DiagnosticListenerSubscriber.cs | 7 +++++-- .../GrpcClient/GrpcClientDiagnosticListener.cs | 2 +- .../HttpClient/HttpClientDiagnosticListener.cs | 2 +- .../QylActivitySource.cs | 17 +++++++++++++++++ .../QylRuntimeProcessMetrics.cs | 7 +++++-- 6 files changed, 30 insertions(+), 7 deletions(-) diff --git a/src/Qyl.OpenTelemetry.AutoInstrumentation.DiagnosticListeners/AspNetCore/AspNetCoreDiagnosticListener.cs b/src/Qyl.OpenTelemetry.AutoInstrumentation.DiagnosticListeners/AspNetCore/AspNetCoreDiagnosticListener.cs index f5731a3..ea3250f 100644 --- a/src/Qyl.OpenTelemetry.AutoInstrumentation.DiagnosticListeners/AspNetCore/AspNetCoreDiagnosticListener.cs +++ b/src/Qyl.OpenTelemetry.AutoInstrumentation.DiagnosticListeners/AspNetCore/AspNetCoreDiagnosticListener.cs @@ -40,7 +40,7 @@ protected override void OnEvent(string name, object? payload) DiagnosticPayloadReader.GetInt32(payload, "http.response.status_code", "http.status_code"); var errorType = DiagnosticPayloadReader.GetString(payload, "error.type", "exception.type"); - using var activity = QylActivitySource.Source.StartActivity(QylActivityNames.HttpServer(method, route), ActivityKind.Server); + using var activity = QylActivitySource.StartAtAmbientStart(QylActivityNames.HttpServer(method, route), ActivityKind.Server); SemanticTagWriter.Set(activity, SemanticAttributes.QylInstrumentationDomain, QylInstrumentationDomains.HttpServer); SemanticTagWriter.Set(activity, SemanticAttributes.HttpRequestMethod, method); diff --git a/src/Qyl.OpenTelemetry.AutoInstrumentation.DiagnosticListeners/DiagnosticListenerSubscriber.cs b/src/Qyl.OpenTelemetry.AutoInstrumentation.DiagnosticListeners/DiagnosticListenerSubscriber.cs index ac9ff2f..23fa612 100644 --- a/src/Qyl.OpenTelemetry.AutoInstrumentation.DiagnosticListeners/DiagnosticListenerSubscriber.cs +++ b/src/Qyl.OpenTelemetry.AutoInstrumentation.DiagnosticListeners/DiagnosticListenerSubscriber.cs @@ -10,8 +10,11 @@ namespace Qyl.OpenTelemetry.AutoInstrumentation.DiagnosticListeners; /// Pre-swap: each library (HttpClient, EFCore, …) was instrumented by an IL-rewriting CallTarget /// integration injected by the substrate's CLR profiler. Post-swap: we subscribe to the same /// libraries' built-in events. DiagnosticSource is a managed BCL -/// primitive that's been AOT-safe since .NET 8, so this layer publishes the same span shapes -/// without any IL rewriting or runtime code generation. +/// primitive that's been AOT-safe since .NET 8, so this layer emits spans without any IL rewriting +/// or runtime code generation. Concrete subscribers react on the completion (*.Stop) event and +/// stamp the span to the ambient framework activity's start (via +/// QylActivitySource.StartAtAmbientStart) so the emitted duration reflects the real operation, +/// not a ~0 span. /// /// public abstract class DiagnosticListenerSubscriber : IObserver>, IDisposable diff --git a/src/Qyl.OpenTelemetry.AutoInstrumentation.DiagnosticListeners/GrpcClient/GrpcClientDiagnosticListener.cs b/src/Qyl.OpenTelemetry.AutoInstrumentation.DiagnosticListeners/GrpcClient/GrpcClientDiagnosticListener.cs index 5fac9dd..c2fc930 100644 --- a/src/Qyl.OpenTelemetry.AutoInstrumentation.DiagnosticListeners/GrpcClient/GrpcClientDiagnosticListener.cs +++ b/src/Qyl.OpenTelemetry.AutoInstrumentation.DiagnosticListeners/GrpcClient/GrpcClientDiagnosticListener.cs @@ -38,7 +38,7 @@ protected override void OnEvent(string name, object? payload) DiagnosticPayloadReader.GetInt32(payload, "grpc.status_code"); var errorType = DiagnosticPayloadReader.GetString(payload, "error.type", "exception.type"); - using var activity = QylActivitySource.Source.StartActivity(QylActivityNames.GrpcClient(service, method), ActivityKind.Client); + using var activity = QylActivitySource.StartAtAmbientStart(QylActivityNames.GrpcClient(service, method), ActivityKind.Client); SemanticTagWriter.Set(activity, SemanticAttributes.QylInstrumentationDomain, QylInstrumentationDomains.RpcGrpc); SemanticTagWriter.Set(activity, SemanticAttributes.RpcSystem, QylSemanticAttributes.RpcSystemGrpc); diff --git a/src/Qyl.OpenTelemetry.AutoInstrumentation.DiagnosticListeners/HttpClient/HttpClientDiagnosticListener.cs b/src/Qyl.OpenTelemetry.AutoInstrumentation.DiagnosticListeners/HttpClient/HttpClientDiagnosticListener.cs index c937ad9..a92f1d7 100644 --- a/src/Qyl.OpenTelemetry.AutoInstrumentation.DiagnosticListeners/HttpClient/HttpClientDiagnosticListener.cs +++ b/src/Qyl.OpenTelemetry.AutoInstrumentation.DiagnosticListeners/HttpClient/HttpClientDiagnosticListener.cs @@ -39,7 +39,7 @@ protected override void OnEvent(string name, object? payload) var statusCode = DiagnosticPayloadReader.GetInt32(payload, "http.response.status_code", "http.status_code"); var errorType = DiagnosticPayloadReader.GetString(payload, "error.type", "exception.type"); - using var activity = QylActivitySource.Source.StartActivity(QylActivityNames.HttpClient(method), ActivityKind.Client); + using var activity = QylActivitySource.StartAtAmbientStart(QylActivityNames.HttpClient(method), ActivityKind.Client); SemanticTagWriter.Set(activity, SemanticAttributes.QylInstrumentationDomain, QylInstrumentationDomains.HttpClient); SemanticTagWriter.Set(activity, SemanticAttributes.HttpRequestMethod, method); diff --git a/src/Qyl.OpenTelemetry.AutoInstrumentation/QylActivitySource.cs b/src/Qyl.OpenTelemetry.AutoInstrumentation/QylActivitySource.cs index d986310..4749073 100644 --- a/src/Qyl.OpenTelemetry.AutoInstrumentation/QylActivitySource.cs +++ b/src/Qyl.OpenTelemetry.AutoInstrumentation/QylActivitySource.cs @@ -25,4 +25,21 @@ internal static bool IsRecordingEnabled => Source.HasListeners() ? Source.StartActivity(operationName, activityKind) : null; + + /// + /// Starts a qyl span stamped to the ambient (framework) 's real start time, + /// so DiagnosticListener bridges that only observe the completion (*.Stop) event emit the + /// operation's TRUE duration instead of a ~0 span. Parents to the current activity to preserve + /// trace correlation; falls back to a now-stamped span when there is no ambient activity. + /// + internal static Activity? StartAtAmbientStart(string operationName, ActivityKind activityKind) + { + if (!Source.HasListeners()) + return null; + + var ambient = Activity.Current; + return ambient is null + ? Source.StartActivity(operationName, activityKind) + : Source.StartActivity(operationName, activityKind, ambient.Context, tags: null, links: null, startTime: ambient.StartTimeUtc); + } } diff --git a/src/Qyl.OpenTelemetry.AutoInstrumentation/QylRuntimeProcessMetrics.cs b/src/Qyl.OpenTelemetry.AutoInstrumentation/QylRuntimeProcessMetrics.cs index 371e11d..78a723c 100644 --- a/src/Qyl.OpenTelemetry.AutoInstrumentation/QylRuntimeProcessMetrics.cs +++ b/src/Qyl.OpenTelemetry.AutoInstrumentation/QylRuntimeProcessMetrics.cs @@ -47,9 +47,12 @@ private static class NetRuntimeMetrics QylMetricNames.ProcessRuntimeDotnetGcObjectsSize, static () => GC.GetTotalMemory(false), "By"); - private static readonly ObservableGauge ThreadPoolThreads = Meter.CreateObservableGauge( + // OTel semconv: dotnet.thread_pool.thread.count is an (Observable)UpDownCounter with unit {thread}, + // not a unitless gauge — the pool size goes up and down, and UCUM units are required. + private static readonly ObservableUpDownCounter ThreadPoolThreads = Meter.CreateObservableUpDownCounter( QylMetricNames.ProcessRuntimeDotnetThreadPoolThreadsCount, - static () => ThreadPool.ThreadCount); + static () => ThreadPool.ThreadCount, + unit: "{thread}"); private static readonly ObservableGauge ThreadPoolQueueLength = Meter.CreateObservableGauge( QylMetricNames.ProcessRuntimeDotnetThreadPoolQueueLength, static () => ThreadPool.PendingWorkItemCount);