From e47d1c3b4d5bf1d2a836683f5fbd13fd9ee2ba35 Mon Sep 17 00:00:00 2001 From: Martijn Laarman Date: Tue, 2 Jan 2024 12:28:30 +0100 Subject: [PATCH 1/2] Add additional logging to outgoing http call propagation In particular adds logging when - outgoing http call is already otherwise instrumented - Outgoing call is part of an exit span and we don't create a child span for it --- ElasticApmAgent.sln.DotSettings | 1 + .../HttpDiagnosticListenerImplBase.cs | 65 +++++++++++-------- src/Elastic.Apm/Report/PayloadSenderV2.cs | 1 - 3 files changed, 38 insertions(+), 29 deletions(-) diff --git a/ElasticApmAgent.sln.DotSettings b/ElasticApmAgent.sln.DotSettings index 416d6924e..14fff26b1 100644 --- a/ElasticApmAgent.sln.DotSettings +++ b/ElasticApmAgent.sln.DotSettings @@ -565,6 +565,7 @@ See the LICENSE file in the project root for more information False KM False + True True True True diff --git a/src/Elastic.Apm/DiagnosticListeners/HttpDiagnosticListenerImplBase.cs b/src/Elastic.Apm/DiagnosticListeners/HttpDiagnosticListenerImplBase.cs index e3cb24603..836a57b6b 100644 --- a/src/Elastic.Apm/DiagnosticListeners/HttpDiagnosticListenerImplBase.cs +++ b/src/Elastic.Apm/DiagnosticListeners/HttpDiagnosticListenerImplBase.cs @@ -140,8 +140,10 @@ private void ProcessStartEvent(TRequest request, Uri requestUrl) return; } - if (_realAgent?.TracerInternal.CurrentSpan is Span currentSpan && currentSpan.IsExitSpan) + if (_realAgent?.TracerInternal.CurrentSpan is Span { IsExitSpan: true } currentSpan) { + Logger.Trace()? + .Log("Exit span detected: {RequestUrl}, propagating without creating a child span", requestUrl.Sanitize()); PropagateTraceContext(request, transaction, currentSpan); return; } @@ -151,22 +153,20 @@ private void ProcessStartEvent(TRequest request, Uri requestUrl) var suppressSpanCreation = false; if (_configuration?.HasTracers ?? false) { - using (var httpTracers = _configuration.GetTracers()) + using var httpTracers = _configuration.GetTracers(); + foreach (var httpSpanTracer in httpTracers) { - foreach (var httpSpanTracer in httpTracers) + suppressSpanCreation = httpSpanTracer.ShouldSuppressSpanCreation(); + if (suppressSpanCreation) + break; + + if (httpSpanTracer.IsMatch(method, requestUrl, + header => RequestTryGetHeader(request, header, out var value) ? value : null)) { - suppressSpanCreation = httpSpanTracer.ShouldSuppressSpanCreation(); - if (suppressSpanCreation) + span = httpSpanTracer.StartSpan(ApmAgent, method, requestUrl, + header => RequestTryGetHeader(request, header, out var value) ? value : null); + if (span != null) break; - - if (httpSpanTracer.IsMatch(method, requestUrl, - header => RequestTryGetHeader(request, header, out var value) ? value : null)) - { - span = httpSpanTracer.StartSpan(ApmAgent, method, requestUrl, - header => RequestTryGetHeader(request, header, out var value) ? value : null); - if (span != null) - break; - } } } } @@ -223,27 +223,36 @@ private void ProcessStartEvent(TRequest request, Uri requestUrl) private void PropagateTraceContext(TRequest request, ITransaction transaction, ISpan span) { - if (!RequestHeadersContain(request, TraceContext.TraceParentHeaderName)) + if (RequestTryGetHeader(request, TraceContext.TraceParentHeaderName, out var existingParent)) + { + var traceParent = TraceContext.BuildTraceparent(span.OutgoingDistributedTracingData); + Logger.Trace()? + .Log("Skipping adding {HeaderName}: with value {TraceParent} since it already has value: {ExistingParent}", + TraceContext.TraceParentHeaderName, traceParent, existingParent); + } + else + { // We call TraceParent.BuildTraceparent explicitly instead of DistributedTracingData.SerializeToString because // in the future we might change DistributedTracingData.SerializeToString to use some other internal format // but here we want the string to be in W3C 'traceparent' header format. - RequestHeadersAdd(request, TraceContext.TraceParentHeaderName, TraceContext.BuildTraceparent(span.OutgoingDistributedTracingData)); + var traceParent = TraceContext.BuildTraceparent(span.OutgoingDistributedTracingData); + RequestHeadersAdd(request, TraceContext.TraceParentHeaderName, traceParent); + } - if (transaction is Transaction t) + if (transaction is Transaction t + && t.Configuration.UseElasticTraceparentHeader + && !RequestHeadersContain(request, TraceContext.TraceParentHeaderNamePrefixed)) { - if (t.Configuration.UseElasticTraceparentHeader) - { - if (!RequestHeadersContain(request, TraceContext.TraceParentHeaderNamePrefixed)) - { - RequestHeadersAdd(request, TraceContext.TraceParentHeaderNamePrefixed, - TraceContext.BuildTraceparent(span.OutgoingDistributedTracingData)); - } - } + var traceParent = TraceContext.BuildTraceparent(span.OutgoingDistributedTracingData); + RequestHeadersAdd(request, TraceContext.TraceParentHeaderNamePrefixed, traceParent); } - if (!RequestHeadersContain(request, TraceContext.TraceStateHeaderName) && span.OutgoingDistributedTracingData != null - && span.OutgoingDistributedTracingData.HasTraceState) - RequestHeadersAdd(request, TraceContext.TraceStateHeaderName, span.OutgoingDistributedTracingData.TraceState.ToTextHeader()); + if (!RequestHeadersContain(request, TraceContext.TraceStateHeaderName) + && span.OutgoingDistributedTracingData is { HasTraceState: true }) + { + var traceState = TraceContext.BuildTraceparent(span.OutgoingDistributedTracingData); + RequestHeadersAdd(request, TraceContext.TraceStateHeaderName, traceState); + } if (!RequestHeadersContain(request, BaggageHeaderName) && Activity.Current != null && Activity.Current.Baggage.Any()) { diff --git a/src/Elastic.Apm/Report/PayloadSenderV2.cs b/src/Elastic.Apm/Report/PayloadSenderV2.cs index 27f7a446f..65ac6461b 100644 --- a/src/Elastic.Apm/Report/PayloadSenderV2.cs +++ b/src/Elastic.Apm/Report/PayloadSenderV2.cs @@ -474,7 +474,6 @@ private T TryExecuteFilter(List> filters, T item) where T : class { try { - _logger?.Trace()?.Log("Start executing filter on transaction"); var itemAfterFilter = filter(item); if (itemAfterFilter != null) { From 5f03698e54dbf7d9bbfec23ba35cd3a3b6cf0a39 Mon Sep 17 00:00:00 2001 From: Martijn Laarman Date: Tue, 2 Jan 2024 13:09:44 +0100 Subject: [PATCH 2/2] Fix bad copy paste for trace state value --- .../DiagnosticListeners/HttpDiagnosticListenerImplBase.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Elastic.Apm/DiagnosticListeners/HttpDiagnosticListenerImplBase.cs b/src/Elastic.Apm/DiagnosticListeners/HttpDiagnosticListenerImplBase.cs index 836a57b6b..81a0762e2 100644 --- a/src/Elastic.Apm/DiagnosticListeners/HttpDiagnosticListenerImplBase.cs +++ b/src/Elastic.Apm/DiagnosticListeners/HttpDiagnosticListenerImplBase.cs @@ -250,7 +250,7 @@ private void PropagateTraceContext(TRequest request, ITransaction transaction, I if (!RequestHeadersContain(request, TraceContext.TraceStateHeaderName) && span.OutgoingDistributedTracingData is { HasTraceState: true }) { - var traceState = TraceContext.BuildTraceparent(span.OutgoingDistributedTracingData); + var traceState = span.OutgoingDistributedTracingData.TraceState.ToTextHeader(); RequestHeadersAdd(request, TraceContext.TraceStateHeaderName, traceState); }