From 99d179441f6c974677b581defee810fb8855744d Mon Sep 17 00:00:00 2001 From: Martijn Laarman Date: Tue, 10 Oct 2023 17:32:20 +0200 Subject: [PATCH 1/3] Support OnExecuteRequestStep available in new .NET versions for IIS modules. This more aggressively logs and attempts to restore HttpContext items. This also more gracefully exits if we detect the module running under classic pipeline mode --- .../ElasticApmModule.cs | 83 +++++++++++++++++++ ...ontextCurrentExecutionSegmentsContainer.cs | 6 +- 2 files changed, 86 insertions(+), 3 deletions(-) diff --git a/src/integrations/Elastic.Apm.AspNetFullFramework/ElasticApmModule.cs b/src/integrations/Elastic.Apm.AspNetFullFramework/ElasticApmModule.cs index 8d4c9bc3a..92fbb4299 100644 --- a/src/integrations/Elastic.Apm.AspNetFullFramework/ElasticApmModule.cs +++ b/src/integrations/Elastic.Apm.AspNetFullFramework/ElasticApmModule.cs @@ -8,6 +8,7 @@ using System.Collections.Specialized; using System.Data.SqlClient; using System.Linq; +using System.Reflection; using System.Security.Claims; using System.Threading; using System.Web; @@ -34,6 +35,8 @@ public class ElasticApmModule : IHttpModule // ReSharper disable once RedundantDefaultMemberInitializer private static readonly DbgInstanceNameGenerator DbgInstanceNameGenerator = new(); private static readonly LazyContextualInit InitOnceHelper = new(); + private static readonly MethodInfo OnExecuteRequestStepMethodInfo = typeof(HttpApplication).GetMethod("OnExecuteRequestStep"); + private readonly string _dbgInstanceName; private HttpApplication _application; @@ -45,6 +48,7 @@ public class ElasticApmModule : IHttpModule private Func _routeDataTemplateGetter; private Func _routePrecedenceGetter; + public ElasticApmModule() => // ReSharper disable once ImpureMethodCallOnReadonlyValueField _dbgInstanceName = DbgInstanceNameGenerator.Generate($"{nameof(ElasticApmModule)}.#"); @@ -101,6 +105,15 @@ private void InitImpl(HttpApplication application) if (!Agent.Config.Enabled) return; + if (!HttpRuntime.UsingIntegratedPipeline) + { + _logger.Error() + ?.Log("Skipping Initialization. Elastic APM Module requires the application pool to run under an Integrated Pipeline." + + " .NET runtime: {DotNetRuntimeDescription}; IIS: {IisVersion}", + PlatformDetection.DotNetRuntimeDescription, HttpRuntime.IISVersion); + return; + } + if (isInitedByThisCall) { _logger.Debug() @@ -114,6 +127,76 @@ private void InitImpl(HttpApplication application) _application.BeginRequest += OnBeginRequest; _application.EndRequest += OnEndRequest; _application.Error += OnError; + + if (OnExecuteRequestStepMethodInfo != null) + { + // OnExecuteRequestStep is available starting with 4.7.1 + try + { + OnExecuteRequestStepMethodInfo.Invoke(application, new object[] { (Action)OnExecuteRequestStep }); + } + catch (Exception e) + { + _logger.Error() + ?.LogException(e, "Failed to invoke OnExecuteRequestStep. .NET runtime: {DotNetRuntimeDescription}; IIS: {IisVersion}", + PlatformDetection.DotNetRuntimeDescription, HttpRuntime.IISVersion); + } + } + } + + private void RestoreContextIfNeeded(HttpContextBase context) + { + string EventName() => Enum.GetName(typeof(RequestNotification), context.CurrentNotification); + + if (Agent.Instance == null) + { + _logger.Trace()?.Log($"Agent.Instance is null during {nameof(OnExecuteRequestStep)}:{EventName()}."); + return; + } + if (Agent.Instance.Tracer == null) + { + _logger.Trace()?.Log($"Agent.Instance.Tracer is null during {nameof(OnExecuteRequestStep)}:{EventName()}."); + return; + } + + var transaction = Agent.Instance?.Tracer?.CurrentTransaction; + if (transaction != null) return; + + var transactionInCurrent = HttpContext.Current?.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentTransactionKey] is not null; + var transactionInApplicationInstance = context.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentTransactionKey] is not null; + var spanInCurrent = HttpContext.Current?.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentSpanKey] is not null; + var spanInApplicationInstance = context.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentSpanKey] is not null; + + _logger.Trace()? + .Log($"{nameof(ITracer.CurrentTransaction)} is null during {nameof(OnExecuteRequestStep)}:{EventName()}. " + + $"(HttpContext.Current Span: {spanInCurrent}, Transaction: {transactionInCurrent})" + + $"(ApplicationContext Span: {spanInApplicationInstance}, Transaction: {transactionInApplicationInstance})"); + + if (HttpContext.Current == null) + { + _logger.Trace()?.Log($"HttpContext.Current is null during {nameof(OnExecuteRequestStep)}:{EventName()}. Unable to attempt to restore transaction"); + return; + } + + if (!transactionInCurrent && transactionInApplicationInstance) + { + HttpContext.Current.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentTransactionKey] = + context.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentTransactionKey]; + _logger.Trace()?.Log($"Restored transaction to HttpContext.Current.Items {nameof(OnExecuteRequestStep)}:{EventName()}"); + } + if (!spanInCurrent && spanInApplicationInstance) + { + HttpContext.Current.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentSpanKey] = + context.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentSpanKey]; + _logger.Trace()?.Log($"Restored span to HttpContext.Current.Items {nameof(OnExecuteRequestStep)}:{EventName()}"); + } + + } + + private void OnExecuteRequestStep(HttpContextBase context, Action step) + { + RestoreContextIfNeeded(context); + step(); } private void OnBeginRequest(object sender, EventArgs e) diff --git a/src/integrations/Elastic.Apm.AspNetFullFramework/HttpContextCurrentExecutionSegmentsContainer.cs b/src/integrations/Elastic.Apm.AspNetFullFramework/HttpContextCurrentExecutionSegmentsContainer.cs index 2e7288c0a..046e35e4f 100644 --- a/src/integrations/Elastic.Apm.AspNetFullFramework/HttpContextCurrentExecutionSegmentsContainer.cs +++ b/src/integrations/Elastic.Apm.AspNetFullFramework/HttpContextCurrentExecutionSegmentsContainer.cs @@ -15,10 +15,10 @@ namespace Elastic.Apm.AspNetFullFramework /// internal sealed class HttpContextCurrentExecutionSegmentsContainer : ICurrentExecutionSegmentsContainer { - private readonly AsyncLocal _currentSpan = new AsyncLocal(); - private readonly AsyncLocal _currentTransaction = new AsyncLocal(); + private readonly AsyncLocal _currentSpan = new(); + private readonly AsyncLocal _currentTransaction = new(); - private const string CurrentSpanKey = "Elastic.Apm.Agent.CurrentSpan"; + internal const string CurrentSpanKey = "Elastic.Apm.Agent.CurrentSpan"; internal const string CurrentTransactionKey = "Elastic.Apm.Agent.CurrentTransaction"; public ISpan CurrentSpan From cce24652d9582b6108461c4ccf1866eac88f40d1 Mon Sep 17 00:00:00 2001 From: Martijn Laarman Date: Thu, 12 Oct 2023 10:15:11 +0200 Subject: [PATCH 2/3] dotnet format --- .../Elastic.Apm.AspNetFullFramework/ElasticApmModule.cs | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/src/integrations/Elastic.Apm.AspNetFullFramework/ElasticApmModule.cs b/src/integrations/Elastic.Apm.AspNetFullFramework/ElasticApmModule.cs index 92fbb4299..817ea5cca 100644 --- a/src/integrations/Elastic.Apm.AspNetFullFramework/ElasticApmModule.cs +++ b/src/integrations/Elastic.Apm.AspNetFullFramework/ElasticApmModule.cs @@ -137,9 +137,9 @@ private void InitImpl(HttpApplication application) } catch (Exception e) { - _logger.Error() - ?.LogException(e, "Failed to invoke OnExecuteRequestStep. .NET runtime: {DotNetRuntimeDescription}; IIS: {IisVersion}", - PlatformDetection.DotNetRuntimeDescription, HttpRuntime.IISVersion); + _logger.Error() + ?.LogException(e, "Failed to invoke OnExecuteRequestStep. .NET runtime: {DotNetRuntimeDescription}; IIS: {IisVersion}", + PlatformDetection.DotNetRuntimeDescription, HttpRuntime.IISVersion); } } } @@ -160,7 +160,8 @@ private void RestoreContextIfNeeded(HttpContextBase context) } var transaction = Agent.Instance?.Tracer?.CurrentTransaction; - if (transaction != null) return; + if (transaction != null) + return; var transactionInCurrent = HttpContext.Current?.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentTransactionKey] is not null; var transactionInApplicationInstance = context.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentTransactionKey] is not null; From a89d7c730ed642a6da0c4763e68bd0e22459ba8e Mon Sep 17 00:00:00 2001 From: Martijn Laarman Date: Tue, 17 Oct 2023 16:58:47 +0200 Subject: [PATCH 3/3] add url to logging --- .../ElasticApmModule.cs | 37 +++++++++++++++---- 1 file changed, 30 insertions(+), 7 deletions(-) diff --git a/src/integrations/Elastic.Apm.AspNetFullFramework/ElasticApmModule.cs b/src/integrations/Elastic.Apm.AspNetFullFramework/ElasticApmModule.cs index 817ea5cca..8137c2452 100644 --- a/src/integrations/Elastic.Apm.AspNetFullFramework/ElasticApmModule.cs +++ b/src/integrations/Elastic.Apm.AspNetFullFramework/ElasticApmModule.cs @@ -148,20 +148,27 @@ private void RestoreContextIfNeeded(HttpContextBase context) { string EventName() => Enum.GetName(typeof(RequestNotification), context.CurrentNotification); + var urlPath = TryGetUrlPath(context); + var ignoreUrls = Agent.Instance?.Configuration.TransactionIgnoreUrls; + if (urlPath != null && ignoreUrls != null && WildcardMatcher.IsAnyMatch(ignoreUrls, urlPath)) + return; + + if (Agent.Instance == null) { - _logger.Trace()?.Log($"Agent.Instance is null during {nameof(OnExecuteRequestStep)}:{EventName()}."); + _logger.Trace()?.Log($"Agent.Instance is null during {nameof(OnExecuteRequestStep)}:{EventName()}. url: {urlPath}"); return; } if (Agent.Instance.Tracer == null) { - _logger.Trace()?.Log($"Agent.Instance.Tracer is null during {nameof(OnExecuteRequestStep)}:{EventName()}."); + _logger.Trace()?.Log($"Agent.Instance.Tracer is null during {nameof(OnExecuteRequestStep)}:{EventName()}. url: {urlPath}"); return; } - var transaction = Agent.Instance?.Tracer?.CurrentTransaction; if (transaction != null) return; + if (Agent.Config.LogLevel <= LogLevel.Trace) + return; var transactionInCurrent = HttpContext.Current?.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentTransactionKey] is not null; var transactionInApplicationInstance = context.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentTransactionKey] is not null; @@ -169,13 +176,14 @@ private void RestoreContextIfNeeded(HttpContextBase context) var spanInApplicationInstance = context.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentSpanKey] is not null; _logger.Trace()? - .Log($"{nameof(ITracer.CurrentTransaction)} is null during {nameof(OnExecuteRequestStep)}:{EventName()}. " + .Log($"{nameof(ITracer.CurrentTransaction)} is null during {nameof(OnExecuteRequestStep)}:{EventName()}. url: {urlPath} " + $"(HttpContext.Current Span: {spanInCurrent}, Transaction: {transactionInCurrent})" + $"(ApplicationContext Span: {spanInApplicationInstance}, Transaction: {transactionInApplicationInstance})"); if (HttpContext.Current == null) { - _logger.Trace()?.Log($"HttpContext.Current is null during {nameof(OnExecuteRequestStep)}:{EventName()}. Unable to attempt to restore transaction"); + _logger.Trace()? + .Log($"HttpContext.Current is null during {nameof(OnExecuteRequestStep)}:{EventName()}. Unable to attempt to restore transaction. url: {urlPath}"); return; } @@ -183,19 +191,34 @@ private void RestoreContextIfNeeded(HttpContextBase context) { HttpContext.Current.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentTransactionKey] = context.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentTransactionKey]; - _logger.Trace()?.Log($"Restored transaction to HttpContext.Current.Items {nameof(OnExecuteRequestStep)}:{EventName()}"); + _logger.Trace()?.Log($"Restored transaction to HttpContext.Current.Items {nameof(OnExecuteRequestStep)}:{EventName()}. url: {urlPath}"); } if (!spanInCurrent && spanInApplicationInstance) { HttpContext.Current.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentSpanKey] = context.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentSpanKey]; - _logger.Trace()?.Log($"Restored span to HttpContext.Current.Items {nameof(OnExecuteRequestStep)}:{EventName()}"); + _logger.Trace()?.Log($"Restored span to HttpContext.Current.Items {nameof(OnExecuteRequestStep)}:{EventName()}. url: {urlPath}"); + } + + } + + private string TryGetUrlPath(HttpContextBase context) + { + try + { + return context.Request.Unvalidated.Path; + } + catch + { + //ignore + return string.Empty; } } private void OnExecuteRequestStep(HttpContextBase context, Action step) { + RestoreContextIfNeeded(context); step(); }