diff --git a/build/dependencies.props b/build/dependencies.props index 89ef783e51..f0846cd967 100644 --- a/build/dependencies.props +++ b/build/dependencies.props @@ -6,6 +6,7 @@ 1.6.1 2.0.0-* 1.4.2 + 4.4.0-* 15.0.0 7.0.0 1.0.1 diff --git a/src/Microsoft.AspNetCore.Hosting/Internal/HostingApplication.cs b/src/Microsoft.AspNetCore.Hosting/Internal/HostingApplication.cs index 408f43cb6a..cd3e2d9fb2 100644 --- a/src/Microsoft.AspNetCore.Hosting/Internal/HostingApplication.cs +++ b/src/Microsoft.AspNetCore.Hosting/Internal/HostingApplication.cs @@ -3,7 +3,6 @@ using System; using System.Diagnostics; -using System.Runtime.CompilerServices; using System.Threading.Tasks; using Microsoft.AspNetCore.Hosting.Server; using Microsoft.AspNetCore.Http; @@ -14,70 +13,31 @@ namespace Microsoft.AspNetCore.Hosting.Internal { public class HostingApplication : IHttpApplication { - private const string DiagnosticsBeginRequestKey = "Microsoft.AspNetCore.Hosting.BeginRequest"; - private const string DiagnosticsEndRequestKey = "Microsoft.AspNetCore.Hosting.EndRequest"; - private const string DiagnosticsUnhandledExceptionKey = "Microsoft.AspNetCore.Hosting.UnhandledException"; - - private static readonly double TimestampToTicks = TimeSpan.TicksPerSecond / (double)Stopwatch.Frequency; - private readonly RequestDelegate _application; - private readonly ILogger _logger; - private readonly DiagnosticSource _diagnosticSource; private readonly IHttpContextFactory _httpContextFactory; + private HostingApplicationDiagnostics _diagnostics; public HostingApplication( RequestDelegate application, ILogger logger, - DiagnosticSource diagnosticSource, + DiagnosticListener diagnosticSource, IHttpContextFactory httpContextFactory) { _application = application; - _logger = logger; - _diagnosticSource = diagnosticSource; + _diagnostics = new HostingApplicationDiagnostics(logger, diagnosticSource); _httpContextFactory = httpContextFactory; } // Set up the request public Context CreateContext(IFeatureCollection contextFeatures) { + var context = new Context(); var httpContext = _httpContextFactory.Create(contextFeatures); - // These enabled checks are virtual dispatch and used twice and so cache to locals - var diagnoticsEnabled = _diagnosticSource.IsEnabled(DiagnosticsBeginRequestKey); - var loggingEnabled = _logger.IsEnabled(LogLevel.Information); + _diagnostics.BeginRequest(httpContext, ref context); - if (HostingEventSource.Log.IsEnabled()) - { - // To keep the hot path short we defer logging in this function to non-inlines - RecordRequestStartEventLog(httpContext); - } - - // Only make call GetTimestamp if its value will be used, i.e. of the listenters is enabled - var startTimestamp = (diagnoticsEnabled || loggingEnabled) ? Stopwatch.GetTimestamp() : 0; - - // Scope may be relevant for a different level of logging, so we always create it - // see: https://github.com/aspnet/Hosting/pull/944 - var scope = _logger.RequestScope(httpContext); - - if (loggingEnabled) - { - // Non-inline - LogRequestStarting(httpContext); - } - - if (diagnoticsEnabled) - { - // Non-inline - RecordBeginRequestDiagnostics(httpContext, startTimestamp); - } - - // Create and return the request Context - return new Context - { - HttpContext = httpContext, - Scope = scope, // Scope can be null if logging is not on. - StartTimestamp = startTimestamp, - }; + context.HttpContext = httpContext; + return context; } // Execute the request @@ -89,138 +49,10 @@ namespace Microsoft.AspNetCore.Hosting.Internal // Clean up the request public void DisposeContext(Context context, Exception exception) { - // Local cache items resolved multiple items, in order of use so they are primed in cpu pipeline when used - var hostingEventLog = HostingEventSource.Log; - var startTimestamp = context.StartTimestamp; var httpContext = context.HttpContext; - var eventLogEnabled = hostingEventLog.IsEnabled(); - - // If startTimestamp is 0, don't call GetTimestamp, likely don't need the value - var currentTimestamp = (startTimestamp != 0) ? Stopwatch.GetTimestamp() : 0; - - // To keep the hot path short we defer logging to non-inlines - if (exception == null) - { - // No exception was thrown, request was sucessful - if (_diagnosticSource.IsEnabled(DiagnosticsEndRequestKey)) - { - // Diagnostics is enabled for EndRequest, but it may not be for BeginRequest - // so call GetTimestamp if currentTimestamp is zero (from above) - RecordEndRequestDiagnostics( - httpContext, - (currentTimestamp != 0) ? currentTimestamp : Stopwatch.GetTimestamp()); - } - } - else - { - // Exception was thrown from request - if (_diagnosticSource.IsEnabled(DiagnosticsUnhandledExceptionKey)) - { - // Diagnostics is enabled for UnhandledException, but it may not be for BeginRequest - // so call GetTimestamp if currentTimestamp is zero (from above) - RecordUnhandledExceptionDiagnostics( - httpContext, - (currentTimestamp != 0) ? currentTimestamp : Stopwatch.GetTimestamp(), - exception); - } - - if (eventLogEnabled) - { - // Non-inline - hostingEventLog.UnhandledException(); - } - } - - // If startTimestamp was 0, then Information logging wasn't enabled at for this request (and calcuated time will be wildly wrong) - // Is used as proxy to reduce calls to virtual: _logger.IsEnabled(LogLevel.Information) - if (startTimestamp != 0) - { - // Non-inline - LogRequestFinished(httpContext, startTimestamp, currentTimestamp); - } - - // Logging Scope and context are finshed with - context.Scope?.Dispose(); + _diagnostics.RequestEnd(httpContext, exception, context); _httpContextFactory.Dispose(httpContext); - - if (eventLogEnabled) - { - // Non-inline - hostingEventLog.RequestStop(); - } - } - - [MethodImpl(MethodImplOptions.NoInlining)] - private void LogRequestStarting(HttpContext httpContext) - { - // IsEnabled is checked in the caller, so if we are here just log - _logger.Log( - logLevel: LogLevel.Information, - eventId: LoggerEventIds.RequestStarting, - state: new HostingRequestStartingLog(httpContext), - exception: null, - formatter: HostingRequestStartingLog.Callback); - } - - [MethodImpl(MethodImplOptions.NoInlining)] - private void LogRequestFinished(HttpContext httpContext, long startTimestamp, long currentTimestamp) - { - // IsEnabled isn't checked in the caller, startTimestamp > 0 is used as a fast proxy check - // but that may be because diagnostics are enabled, which also uses startTimestamp, so check here - if (_logger.IsEnabled(LogLevel.Information)) - { - var elapsed = new TimeSpan((long)(TimestampToTicks * (currentTimestamp - startTimestamp))); - - _logger.Log( - logLevel: LogLevel.Information, - eventId: LoggerEventIds.RequestFinished, - state: new HostingRequestFinishedLog(httpContext, elapsed), - exception: null, - formatter: HostingRequestFinishedLog.Callback); - } - } - - [MethodImpl(MethodImplOptions.NoInlining)] - private void RecordBeginRequestDiagnostics(HttpContext httpContext, long startTimestamp) - { - _diagnosticSource.Write( - DiagnosticsBeginRequestKey, - new - { - httpContext = httpContext, - timestamp = startTimestamp - }); - } - - [MethodImpl(MethodImplOptions.NoInlining)] - private void RecordEndRequestDiagnostics(HttpContext httpContext, long currentTimestamp) - { - _diagnosticSource.Write( - DiagnosticsEndRequestKey, - new - { - httpContext = httpContext, - timestamp = currentTimestamp - }); - } - - [MethodImpl(MethodImplOptions.NoInlining)] - private void RecordUnhandledExceptionDiagnostics(HttpContext httpContext, long currentTimestamp, Exception exception) - { - _diagnosticSource.Write( - DiagnosticsUnhandledExceptionKey, - new - { - httpContext = httpContext, - timestamp = currentTimestamp, - exception = exception - }); - } - - [MethodImpl(MethodImplOptions.NoInlining)] - private static void RecordRequestStartEventLog(HttpContext httpContext) - { - HostingEventSource.Log.RequestStart(httpContext.Request.Method, httpContext.Request.Path); + _diagnostics.ContextDisposed(context); } public struct Context @@ -228,6 +60,8 @@ namespace Microsoft.AspNetCore.Hosting.Internal public HttpContext HttpContext { get; set; } public IDisposable Scope { get; set; } public long StartTimestamp { get; set; } + public bool EventLogEnabled { get; set; } + public Activity Activity { get; set; } } } } diff --git a/src/Microsoft.AspNetCore.Hosting/Internal/HostingApplicationDiagnostics.cs b/src/Microsoft.AspNetCore.Hosting/Internal/HostingApplicationDiagnostics.cs new file mode 100644 index 0000000000..ba91ad264b --- /dev/null +++ b/src/Microsoft.AspNetCore.Hosting/Internal/HostingApplicationDiagnostics.cs @@ -0,0 +1,273 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. + +using System; +using System.Diagnostics; +using System.Runtime.CompilerServices; +using Microsoft.AspNetCore.Http; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Primitives; +using Microsoft.Net.Http.Headers; + +namespace Microsoft.AspNetCore.Hosting.Internal +{ + internal class HostingApplicationDiagnostics + { + private static readonly double TimestampToTicks = TimeSpan.TicksPerSecond / (double)Stopwatch.Frequency; + + private const string ActivityName = "Microsoft.AspNetCore.Hosting.HttpRequestIn"; + private const string ActivityStartKey = "Microsoft.AspNetCore.Hosting.HttpRequestIn.Start"; + + private const string DeprecatedDiagnosticsBeginRequestKey = "Microsoft.AspNetCore.Hosting.BeginRequest"; + private const string DeprecatedDiagnosticsEndRequestKey = "Microsoft.AspNetCore.Hosting.EndRequest"; + private const string DiagnosticsUnhandledExceptionKey = "Microsoft.AspNetCore.Hosting.UnhandledException"; + + private const string RequestIdHeaderName = "Request-Id"; + private const string CorrelationContextHeaderName = "Correlation-Context"; + + private readonly DiagnosticListener _diagnosticListener; + private readonly ILogger _logger; + + public HostingApplicationDiagnostics(ILogger logger, DiagnosticListener diagnosticListener) + { + _logger = logger; + _diagnosticListener = diagnosticListener; + } + + [MethodImpl(MethodImplOptions.AggressiveInlining)] + public void BeginRequest(HttpContext httpContext, ref HostingApplication.Context context) + { + long startTimestamp = 0; + + if (HostingEventSource.Log.IsEnabled()) + { + context.EventLogEnabled = true; + // To keep the hot path short we defer logging in this function to non-inlines + RecordRequestStartEventLog(httpContext); + } + + + if (_diagnosticListener.IsEnabled()) + { + if (_diagnosticListener.IsEnabled(ActivityName, httpContext)) + { + context.Activity = StartActivity(httpContext); + } + if (_diagnosticListener.IsEnabled(DeprecatedDiagnosticsBeginRequestKey)) + { + startTimestamp = Stopwatch.GetTimestamp(); + RecordBeginRequestDiagnostics(httpContext, startTimestamp); + } + } + + // To avoid allocation, return a null scope if the logger is not on at least to some degree. + if (_logger.IsEnabled(LogLevel.Critical)) + { + // Scope may be relevant for a different level of logging, so we always create it + // see: https://github.com/aspnet/Hosting/pull/944 + // Scope can be null if logging is not on. + context.Scope = _logger.RequestScope(httpContext); + + if (_logger.IsEnabled(LogLevel.Information)) + { + if (startTimestamp == 0) + { + startTimestamp = Stopwatch.GetTimestamp(); + } + + // Non-inline + LogRequestStarting(httpContext); + } + } + + context.StartTimestamp = startTimestamp; + } + + [MethodImpl(MethodImplOptions.AggressiveInlining)] + public void RequestEnd(HttpContext httpContext, Exception exception, HostingApplication.Context context) + { + // Local cache items resolved multiple items, in order of use so they are primed in cpu pipeline when used + var startTimestamp = context.StartTimestamp; + long currentTimestamp = 0; + + // If startTimestamp was 0, then Information logging wasn't enabled at for this request (and calcuated time will be wildly wrong) + // Is used as proxy to reduce calls to virtual: _logger.IsEnabled(LogLevel.Information) + if (startTimestamp != 0) + { + currentTimestamp = Stopwatch.GetTimestamp(); + // Non-inline + LogRequestFinished(httpContext, startTimestamp, currentTimestamp); + } + + if (_diagnosticListener.IsEnabled()) + { + if (currentTimestamp == 0) + { + currentTimestamp = Stopwatch.GetTimestamp(); + } + + if (exception == null) + { + // No exception was thrown, request was sucessful + if (_diagnosticListener.IsEnabled(DeprecatedDiagnosticsEndRequestKey)) + { + // Diagnostics is enabled for EndRequest, but it may not be for BeginRequest + // so call GetTimestamp if currentTimestamp is zero (from above) + RecordEndRequestDiagnostics(httpContext, currentTimestamp); + } + } + else + { + // Exception was thrown from request + if (_diagnosticListener.IsEnabled(DiagnosticsUnhandledExceptionKey)) + { + // Diagnostics is enabled for UnhandledException, but it may not be for BeginRequest + // so call GetTimestamp if currentTimestamp is zero (from above) + RecordUnhandledExceptionDiagnostics(httpContext, currentTimestamp, exception); + } + + } + + var activity = context.Activity; + // Always stop activity if it was started + if (activity != null) + { + StopActivity(httpContext, activity); + } + } + + if (context.EventLogEnabled && exception != null) + { + // Non-inline + HostingEventSource.Log.UnhandledException(); + } + + // Logging Scope is finshed with + context.Scope?.Dispose(); + } + + [MethodImpl(MethodImplOptions.AggressiveInlining)] + public void ContextDisposed(HostingApplication.Context context) + { + if (context.EventLogEnabled) + { + // Non-inline + HostingEventSource.Log.RequestStop(); + } + } + + [MethodImpl(MethodImplOptions.NoInlining)] + private void LogRequestStarting(HttpContext httpContext) + { + // IsEnabled is checked in the caller, so if we are here just log + _logger.Log( + logLevel: LogLevel.Information, + eventId: LoggerEventIds.RequestStarting, + state: new HostingRequestStartingLog(httpContext), + exception: null, + formatter: HostingRequestStartingLog.Callback); + } + + [MethodImpl(MethodImplOptions.NoInlining)] + private void LogRequestFinished(HttpContext httpContext, long startTimestamp, long currentTimestamp) + { + // IsEnabled isn't checked in the caller, startTimestamp > 0 is used as a fast proxy check + // but that may be because diagnostics are enabled, which also uses startTimestamp, so check here + if (_logger.IsEnabled(LogLevel.Information)) + { + var elapsed = new TimeSpan((long)(TimestampToTicks * (currentTimestamp - startTimestamp))); + + _logger.Log( + logLevel: LogLevel.Information, + eventId: LoggerEventIds.RequestFinished, + state: new HostingRequestFinishedLog(httpContext, elapsed), + exception: null, + formatter: HostingRequestFinishedLog.Callback); + } + } + + [MethodImpl(MethodImplOptions.NoInlining)] + private void RecordBeginRequestDiagnostics(HttpContext httpContext, long startTimestamp) + { + _diagnosticListener.Write( + DeprecatedDiagnosticsBeginRequestKey, + new + { + httpContext = httpContext, + timestamp = startTimestamp + }); + } + + [MethodImpl(MethodImplOptions.NoInlining)] + private void RecordEndRequestDiagnostics(HttpContext httpContext, long currentTimestamp) + { + _diagnosticListener.Write( + DeprecatedDiagnosticsEndRequestKey, + new + { + httpContext = httpContext, + timestamp = currentTimestamp + }); + } + + [MethodImpl(MethodImplOptions.NoInlining)] + private void RecordUnhandledExceptionDiagnostics(HttpContext httpContext, long currentTimestamp, Exception exception) + { + _diagnosticListener.Write( + DiagnosticsUnhandledExceptionKey, + new + { + httpContext = httpContext, + timestamp = currentTimestamp, + exception = exception + }); + } + + [MethodImpl(MethodImplOptions.NoInlining)] + private static void RecordRequestStartEventLog(HttpContext httpContext) + { + HostingEventSource.Log.RequestStart(httpContext.Request.Method, httpContext.Request.Path); + } + + [MethodImpl(MethodImplOptions.NoInlining)] + private Activity StartActivity(HttpContext httpContext) + { + var activity = new Activity(ActivityName); + if (httpContext.Request.Headers.TryGetValue(RequestIdHeaderName, out var requestId)) + { + activity.SetParentId(requestId); + + // We expect baggage to be empty by default + // Only very advanced users will be using it in near future, we encouradge them to keep baggage small (few items) + string[] baggage = httpContext.Request.Headers.GetCommaSeparatedValues(CorrelationContextHeaderName); + if (baggage != StringValues.Empty) + { + foreach (var item in baggage) + { + if (NameValueHeaderValue.TryParse(item, out var baggageItem)) + { + activity.AddBaggage(baggageItem.Name, baggageItem.Value); + } + } + } + } + + if (_diagnosticListener.IsEnabled(ActivityStartKey)) + { + _diagnosticListener.StartActivity(activity, new { HttpContext = httpContext }); + } + else + { + activity.Start(); + } + + return activity; + } + + [MethodImpl(MethodImplOptions.NoInlining)] + private void StopActivity(HttpContext httpContext, Activity activity) + { + _diagnosticListener.StopActivity(activity, new { HttpContext = httpContext }); + } + } +} \ No newline at end of file diff --git a/src/Microsoft.AspNetCore.Hosting/Internal/HostingLoggerExtensions.cs b/src/Microsoft.AspNetCore.Hosting/Internal/HostingLoggerExtensions.cs index fb31e1ad2b..b05e70eb62 100644 --- a/src/Microsoft.AspNetCore.Hosting/Internal/HostingLoggerExtensions.cs +++ b/src/Microsoft.AspNetCore.Hosting/Internal/HostingLoggerExtensions.cs @@ -15,12 +15,8 @@ namespace Microsoft.AspNetCore.Hosting.Internal { public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext) { - // To avoid allocation, return a null scope if the logger is not on at least to some degree. - if (logger.IsEnabled(LogLevel.Critical)) - { - return logger.BeginScope(new HostingLogScope(httpContext)); - } - return null; + + return logger.BeginScope(new HostingLogScope(httpContext)); } public static void ApplicationError(this ILogger logger, Exception exception) diff --git a/src/Microsoft.AspNetCore.Hosting/Internal/WebHost.cs b/src/Microsoft.AspNetCore.Hosting/Internal/WebHost.cs index 1dbaf8684a..61653045f3 100644 --- a/src/Microsoft.AspNetCore.Hosting/Internal/WebHost.cs +++ b/src/Microsoft.AspNetCore.Hosting/Internal/WebHost.cs @@ -110,7 +110,7 @@ namespace Microsoft.AspNetCore.Hosting.Internal _applicationLifetime = _applicationServices.GetRequiredService() as ApplicationLifetime; _hostedServiceExecutor = _applicationServices.GetRequiredService(); - var diagnosticSource = _applicationServices.GetRequiredService(); + var diagnosticSource = _applicationServices.GetRequiredService(); var httpContextFactory = _applicationServices.GetRequiredService(); Server.Start(new HostingApplication(_application, _logger, diagnosticSource, httpContextFactory)); diff --git a/src/Microsoft.AspNetCore.Hosting/Microsoft.AspNetCore.Hosting.csproj b/src/Microsoft.AspNetCore.Hosting/Microsoft.AspNetCore.Hosting.csproj index e5ab56e876..f1c8a64a20 100644 --- a/src/Microsoft.AspNetCore.Hosting/Microsoft.AspNetCore.Hosting.csproj +++ b/src/Microsoft.AspNetCore.Hosting/Microsoft.AspNetCore.Hosting.csproj @@ -30,7 +30,7 @@ - + diff --git a/test/Microsoft.AspNetCore.Hosting.Tests/HostingApplicationTests.cs b/test/Microsoft.AspNetCore.Hosting.Tests/HostingApplicationTests.cs index 7c285f1a0e..082685eefc 100644 --- a/test/Microsoft.AspNetCore.Hosting.Tests/HostingApplicationTests.cs +++ b/test/Microsoft.AspNetCore.Hosting.Tests/HostingApplicationTests.cs @@ -2,7 +2,9 @@ // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; +using System.Collections.Generic; using System.Diagnostics; +using System.Reflection; using System.Threading.Tasks; using Microsoft.AspNetCore.Hosting.Internal; using Microsoft.AspNetCore.Http; @@ -20,16 +22,263 @@ namespace Microsoft.AspNetCore.Hosting.Tests public void DisposeContextDoesNotThrowWhenContextScopeIsNull() { // Arrange - var httpContextFactory = new HttpContextFactory(new DefaultObjectPoolProvider(), Options.Create(new FormOptions()), new HttpContextAccessor()); - var hostingApplication = new HostingApplication(ctx => Task.FromResult(0), new NullScopeLogger(), new NoopDiagnosticSource(), httpContextFactory); - var features = new FeatureCollection(); - features.Set(new HttpRequestFeature()); + var hostingApplication = CreateApplication(out var features); var context = hostingApplication.CreateContext(features); // Act/Assert hostingApplication.DisposeContext(context, null); } + [Fact] + public void ActivityIsNotCreatedWhenIsEnabledForActivityIsFalse() + { + var diagnosticSource = new DiagnosticListener("DummySource"); + var hostingApplication = CreateApplication(out var features, diagnosticSource: diagnosticSource); + + bool eventsFired = false; + bool isEnabledActivityFired = false; + bool isEnabledStartFired = false; + + diagnosticSource.Subscribe(new CallbackDiagnosticListener(pair => + { + eventsFired |= pair.Key.StartsWith("Microsoft.AspNetCore.Hosting.HttpRequestIn"); + }), (s, o, arg3) => + { + if (s == "Microsoft.AspNetCore.Hosting.HttpRequestIn") + { + Assert.IsAssignableFrom(o); + isEnabledActivityFired = true; + } + if (s == "Microsoft.AspNetCore.Hosting.HttpRequestIn.Start") + { + isEnabledStartFired = true; + } + return false; + }); + + hostingApplication.CreateContext(features); + Assert.Null(Activity.Current); + Assert.True(isEnabledActivityFired); + Assert.False (isEnabledStartFired); + Assert.False(eventsFired); + } + + [Fact] + public void ActivityIsCreatedButNotLoggedWhenIsEnabledForActivityStartIsFalse() + { + var diagnosticSource = new DiagnosticListener("DummySource"); + var hostingApplication = CreateApplication(out var features, diagnosticSource: diagnosticSource); + + bool eventsFired = false; + bool isEnabledStartFired = false; + bool isEnabledActivityFired = false; + + diagnosticSource.Subscribe(new CallbackDiagnosticListener(pair => + { + eventsFired |= pair.Key.StartsWith("Microsoft.AspNetCore.Hosting.HttpRequestIn"); + }), (s, o, arg3) => + { + if (s == "Microsoft.AspNetCore.Hosting.HttpRequestIn") + { + Assert.IsAssignableFrom(o); + isEnabledActivityFired = true; + return true; + } + + if (s == "Microsoft.AspNetCore.Hosting.HttpRequestIn.Start") + { + isEnabledStartFired = true; + return false; + } + return true; + }); + + hostingApplication.CreateContext(features); + Assert.NotNull(Activity.Current); + Assert.True(isEnabledActivityFired); + Assert.True(isEnabledStartFired); + Assert.False(eventsFired); + } + + [Fact] + public void ActivityIsCreatedAndLogged() + { + var diagnosticSource = new DiagnosticListener("DummySource"); + var hostingApplication = CreateApplication(out var features, diagnosticSource: diagnosticSource); + + bool startCalled = false; + + diagnosticSource.Subscribe(new CallbackDiagnosticListener(pair => + { + if (pair.Key == "Microsoft.AspNetCore.Hosting.HttpRequestIn.Start") + { + startCalled = true; + Assert.NotNull(pair.Value); + Assert.NotNull(Activity.Current); + Assert.Equal("Microsoft.AspNetCore.Hosting.HttpRequestIn", Activity.Current.OperationName); + AssertProperty(pair.Value, "HttpContext"); + } + })); + + hostingApplication.CreateContext(features); + Assert.NotNull(Activity.Current); + Assert.True(startCalled); + } + + [Fact] + public void ActivityIsStoppedDuringStopCall() + { + var diagnosticSource = new DiagnosticListener("DummySource"); + var hostingApplication = CreateApplication(out var features, diagnosticSource: diagnosticSource); + + bool endCalled = false; + diagnosticSource.Subscribe(new CallbackDiagnosticListener(pair => + { + if (pair.Key == "Microsoft.AspNetCore.Hosting.HttpRequestIn.Stop") + { + endCalled = true; + + Assert.NotNull(Activity.Current); + Assert.True(Activity.Current.Duration > TimeSpan.Zero); + Assert.Equal("Microsoft.AspNetCore.Hosting.HttpRequestIn", Activity.Current.OperationName); + AssertProperty(pair.Value, "HttpContext"); + } + })); + + var context = hostingApplication.CreateContext(features); + hostingApplication.DisposeContext(context, null); + Assert.True(endCalled); + } + + [Fact] + public void ActivityIsStoppedDuringUnhandledExceptionCall() + { + var diagnosticSource = new DiagnosticListener("DummySource"); + var hostingApplication = CreateApplication(out var features, diagnosticSource: diagnosticSource); + + bool endCalled = false; + diagnosticSource.Subscribe(new CallbackDiagnosticListener(pair => + { + if (pair.Key == "Microsoft.AspNetCore.Hosting.HttpRequestIn.Stop") + { + endCalled = true; + Assert.NotNull(Activity.Current); + Assert.True(Activity.Current.Duration > TimeSpan.Zero); + Assert.Equal("Microsoft.AspNetCore.Hosting.HttpRequestIn", Activity.Current.OperationName); + AssertProperty(pair.Value, "HttpContext"); + } + })); + + var context = hostingApplication.CreateContext(features); + hostingApplication.DisposeContext(context, new Exception()); + Assert.True(endCalled); + } + + [Fact] + public void ActivityIsAvailableDuringUnhandledExceptionCall() + { + var diagnosticSource = new DiagnosticListener("DummySource"); + var hostingApplication = CreateApplication(out var features, diagnosticSource: diagnosticSource); + + bool endCalled = false; + diagnosticSource.Subscribe(new CallbackDiagnosticListener(pair => + { + if (pair.Key == "Microsoft.AspNetCore.Hosting.UnhandledException") + { + endCalled = true; + Assert.NotNull(Activity.Current); + Assert.Equal("Microsoft.AspNetCore.Hosting.HttpRequestIn", Activity.Current.OperationName); + } + })); + + var context = hostingApplication.CreateContext(features); + hostingApplication.DisposeContext(context, new Exception()); + Assert.True(endCalled); + } + + [Fact] + public void ActivityIsAvailibleDuringRequest() + { + var diagnosticSource = new DiagnosticListener("DummySource"); + var hostingApplication = CreateApplication(out var features, diagnosticSource: diagnosticSource); + + diagnosticSource.Subscribe(new CallbackDiagnosticListener(pair => { }), + s => + { + if (s.StartsWith("Microsoft.AspNetCore.Hosting.HttpRequestIn")) + { + return true; + } + return false; + }); + + hostingApplication.CreateContext(features); + + Assert.NotNull(Activity.Current); + Assert.Equal("Microsoft.AspNetCore.Hosting.HttpRequestIn", Activity.Current.OperationName); + } + + [Fact] + public void ActivityParentIdAndBaggeReadFromHeaders() + { + var diagnosticSource = new DiagnosticListener("DummySource"); + var hostingApplication = CreateApplication(out var features, diagnosticSource: diagnosticSource); + + diagnosticSource.Subscribe(new CallbackDiagnosticListener(pair => { }), + s => + { + if (s.StartsWith("Microsoft.AspNetCore.Hosting.HttpRequestIn")) + { + return true; + } + return false; + }); + + features.Set(new HttpRequestFeature() + { + Headers = new HeaderDictionary() + { + {"Request-Id", "ParentId1"}, + {"Correlation-Context", "Key1=value1, Key2=value2"} + } + }); + hostingApplication.CreateContext(features); + Assert.Equal("Microsoft.AspNetCore.Hosting.HttpRequestIn", Activity.Current.OperationName); + Assert.Equal("ParentId1", Activity.Current.ParentId); + Assert.Contains(Activity.Current.Baggage, pair => pair.Key == "Key1" && pair.Value == "value1"); + Assert.Contains(Activity.Current.Baggage, pair => pair.Key == "Key2" && pair.Value == "value2"); + } + + private static void AssertProperty(object o, string name) + { + Assert.NotNull(o); + var property = o.GetType().GetTypeInfo().GetProperty(name, BindingFlags.Instance | BindingFlags.Public); + Assert.NotNull(property); + var value = property.GetValue(o); + Assert.NotNull(value); + Assert.IsAssignableFrom(value); + } + + private static HostingApplication CreateApplication(out FeatureCollection features, + DiagnosticListener diagnosticSource = null) + { + var httpContextFactory = new HttpContextFactory( + new DefaultObjectPoolProvider(), + Options.Create(new FormOptions()), + new HttpContextAccessor()); + + var hostingApplication = new HostingApplication( + ctx => Task.FromResult(0), + new NullScopeLogger(), + diagnosticSource ?? new NoopDiagnosticSource(), + httpContextFactory); + + features = new FeatureCollection(); + features.Set(new HttpRequestFeature()); + + return hostingApplication; + } + private class NullScopeLogger : ILogger { public IDisposable BeginScope(TState state) => null; @@ -41,13 +290,40 @@ namespace Microsoft.AspNetCore.Hosting.Tests } } - private class NoopDiagnosticSource : DiagnosticSource + private class NoopDiagnosticSource : DiagnosticListener { + public NoopDiagnosticSource() : base("DummyListener") + { + } + public override bool IsEnabled(string name) => true; public override void Write(string name, object value) { } } + + private class CallbackDiagnosticListener : IObserver> + { + private readonly Action> _callback; + + public CallbackDiagnosticListener(Action> callback) + { + _callback = callback; + } + + public void OnNext(KeyValuePair value) + { + _callback(value); + } + + public void OnError(Exception error) + { + } + + public void OnCompleted() + { + } + } } }