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
elastic · Jan 2, 2024 · e47d1c3 · e47d1c3
1 parent 038ece7
commit e47d1c3
Show file tree

Hide file tree

Showing 3 changed files with 38 additions and 29 deletions.
diff --git a/ElasticApmAgent.sln.DotSettings b/ElasticApmAgent.sln.DotSettings
@@ -565,6 +565,7 @@ See the LICENSE file in the project root for more information</s:String>
 	<s:Boolean x:Key="/Default/CodeStyle/LiveTemplatesUseVar/UseVar/@EntryValue">False</s:Boolean>
 	<s:String x:Key="/Default/CodeStyle/Naming/CSharpNaming/Abbreviations/=KM/@EntryIndexedValue">KM</s:String>
 	<s:Boolean x:Key="/Default/CodeStyle/Naming/CSharpNaming/ApplyAutoDetectedRules/@EntryValue">False</s:Boolean>
+	<s:Boolean x:Key="/Default/Environment/SettingsMigration/IsMigratorApplied/=JetBrains_002EReSharper_002EFeature_002EServices_002ECodeCleanup_002EFileHeader_002EFileHeaderSettingsMigrate/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/Environment/SettingsMigration/IsMigratorApplied/=JetBrains_002EReSharper_002EPsi_002ECSharp_002ECodeStyle_002ECSharpFileLayoutPatternsUpgrade/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/Environment/SettingsMigration/IsMigratorApplied/=JetBrains_002EReSharper_002EPsi_002ECSharp_002ECodeStyle_002ECSharpKeepExistingMigration/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/Environment/SettingsMigration/IsMigratorApplied/=JetBrains_002EReSharper_002EPsi_002ECSharp_002ECodeStyle_002ECSharpPlaceEmbeddedOnSameLineMigration/@EntryIndexedValue">True</s:Boolean>

diff --git 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
@@ -474,7 +474,6 @@ private T TryExecuteFilter<T>(List<Func<T, T>> filters, T item) where T : class
 			{
 				try
 				{
-					_logger?.Trace()?.Log("Start executing filter on transaction");
 					var itemAfterFilter = filter(item);
 					if (itemAfterFilter != null)
 					{
-Original file line number
+Diff line change
@@ Expand Up @@
     			{
     				try
     				{
-    					_logger?.Trace()?.Log("Start executing filter on transaction");
     					var itemAfterFilter = filter(item);
     					if (itemAfterFilter != null)
     					{
@@ Expand Down @@