diff --git a/src/Hosting/Hosting/src/GenericHost/GenericWebHostedService.cs b/src/Hosting/Hosting/src/GenericHost/GenericWebHostedService.cs index 881cb1b2fc66..816f70deb9e7 100644 --- a/src/Hosting/Hosting/src/GenericHost/GenericWebHostedService.cs +++ b/src/Hosting/Hosting/src/GenericHost/GenericWebHostedService.cs @@ -37,7 +37,7 @@ public GenericWebHostService(IOptions options, { Options = options.Value; Server = server; - Logger = loggerFactory.CreateLogger(); + Logger = loggerFactory.CreateLogger("Microsoft.AspNetCore.Hosting.Diagnostics"); LifetimeLogger = loggerFactory.CreateLogger("Microsoft.Hosting.Lifetime"); DiagnosticListener = diagnosticListener; HttpContextFactory = httpContextFactory; @@ -49,7 +49,7 @@ public GenericWebHostService(IOptions options, public GenericWebHostServiceOptions Options { get; } public IServer Server { get; } - public ILogger Logger { get; } + public ILogger Logger { get; } // Only for high level lifetime events public ILogger LifetimeLogger { get; } public DiagnosticListener DiagnosticListener { get; } diff --git a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs index bf09fa4dcbd4..44802f651ecf 100644 --- a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs +++ b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs @@ -51,13 +51,13 @@ public void BeginRequest(HttpContext httpContext, ref HostingApplication.Context var diagnosticListenerEnabled = _diagnosticListener.IsEnabled(); var loggingEnabled = _logger.IsEnabled(LogLevel.Critical); + if (loggingEnabled || (diagnosticListenerEnabled && _diagnosticListener.IsEnabled(ActivityName, httpContext))) + { + context.Activity = StartActivity(httpContext); + } if (diagnosticListenerEnabled) { - if (_diagnosticListener.IsEnabled(ActivityName, httpContext)) - { - context.Activity = StartActivity(httpContext); - } if (_diagnosticListener.IsEnabled(DeprecatedDiagnosticsBeginRequestKey)) { startTimestamp = Stopwatch.GetTimestamp(); @@ -68,16 +68,10 @@ public void BeginRequest(HttpContext httpContext, ref HostingApplication.Context // To avoid allocation, return a null scope if the logger is not on at least to some degree. if (loggingEnabled) { - // Get the request ID (first try TraceParent header otherwise Request-ID header - if (!httpContext.Request.Headers.TryGetValue(TraceParentHeaderName, out var correlationId)) - { - httpContext.Request.Headers.TryGetValue(RequestIdHeaderName, out correlationId); - } - // 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, correlationId); + context.Scope = _logger.RequestScope(httpContext, context.Activity.Id); if (_logger.IsEnabled(LogLevel.Information)) { @@ -90,7 +84,6 @@ public void BeginRequest(HttpContext httpContext, ref HostingApplication.Context LogRequestStarting(httpContext); } } - context.StartTimestamp = startTimestamp; } @@ -138,13 +131,13 @@ public void RequestEnd(HttpContext httpContext, Exception exception, HostingAppl } } + } - var activity = context.Activity; - // Always stop activity if it was started - if (activity != null) - { - StopActivity(httpContext, activity); - } + var activity = context.Activity; + // Always stop activity if it was started + if (activity != null) + { + StopActivity(httpContext, activity); } if (context.EventLogEnabled && exception != null) @@ -261,7 +254,7 @@ private Activity StartActivity(HttpContext httpContext) // We expect baggage to be empty by default // Only very advanced users will be using it in near future, we encourage them to keep baggage small (few items) string[] baggage = httpContext.Request.Headers.GetCommaSeparatedValues(CorrelationContextHeaderName); - if (baggage != StringValues.Empty) + if (baggage.Length > 0) { foreach (var item in baggage) { diff --git a/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs b/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs index e20f8a14ed77..48e5db98183a 100644 --- a/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs +++ b/src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs @@ -13,9 +13,9 @@ namespace Microsoft.AspNetCore.Hosting.Internal { internal static class HostingLoggerExtensions { - public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext, string correlationId) + public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext, string activityId) { - return logger.BeginScope(new HostingLogScope(httpContext, correlationId)); + return logger.BeginScope(new HostingLogScope(httpContext, activityId)); } public static void ApplicationError(this ILogger logger, Exception exception) @@ -96,7 +96,7 @@ private class HostingLogScope : IReadOnlyList> { private readonly string _path; private readonly string _traceIdentifier; - private readonly string _correlationId; + private readonly string _activityId; private string _cachedToString; @@ -122,20 +122,20 @@ public KeyValuePair this[int index] } else if (index == 2) { - return new KeyValuePair("CorrelationId", _correlationId); + return new KeyValuePair("ActivityId", _activityId); } throw new ArgumentOutOfRangeException(nameof(index)); } } - public HostingLogScope(HttpContext httpContext, string correlationId) + public HostingLogScope(HttpContext httpContext, string activityId) { _traceIdentifier = httpContext.TraceIdentifier; _path = (httpContext.Request.PathBase.HasValue ? httpContext.Request.PathBase + httpContext.Request.Path : httpContext.Request.Path).ToString(); - _correlationId = correlationId; + _activityId = activityId; } public override string ToString() @@ -144,9 +144,10 @@ public override string ToString() { _cachedToString = string.Format( CultureInfo.InvariantCulture, - "RequestId:{0} RequestPath:{1}", + "RequestPath:{0} RequestId:{1}, ActivityId:{2}", + _path, _traceIdentifier, - _path); + _activityId); } return _cachedToString; diff --git a/src/Hosting/Hosting/src/Internal/WebHost.cs b/src/Hosting/Hosting/src/Internal/WebHost.cs index 6ddb0ca87157..8dcfa065150c 100644 --- a/src/Hosting/Hosting/src/Internal/WebHost.cs +++ b/src/Hosting/Hosting/src/Internal/WebHost.cs @@ -41,7 +41,7 @@ internal class WebHost : IWebHost, IAsyncDisposable private IServiceProvider _applicationServices; private ExceptionDispatchInfo _applicationServicesException; - private ILogger _logger; + private ILogger _logger; private bool _stopped; @@ -139,7 +139,7 @@ public void Start() public virtual async Task StartAsync(CancellationToken cancellationToken = default) { HostingEventSource.Log.HostStart(); - _logger = _applicationServices.GetRequiredService>(); + _logger = _applicationServices.GetRequiredService().CreateLogger("Microsoft.AspNetCore.Hosting.Diagnostics"); _logger.Starting(); var application = BuildApplication(); diff --git a/src/Hosting/Hosting/test/HostingApplicationTests.cs b/src/Hosting/Hosting/test/HostingApplicationTests.cs index dbb1cb2d23fd..5fbaf5fe7aa5 100644 --- a/src/Hosting/Hosting/test/HostingApplicationTests.cs +++ b/src/Hosting/Hosting/test/HostingApplicationTests.cs @@ -30,19 +30,30 @@ public void DisposeContextDoesNotThrowWhenContextScopeIsNull() } [Fact] - public void CreateContextSetsCorrelationIdInScope() + public void CreateContextWithDisabledLoggerDoesNotCreateActivity() { // Arrange - var logger = new LoggerWithScopes(); + var hostingApplication = CreateApplication(out var features); + + // Act + hostingApplication.CreateContext(features); + + Assert.Null(Activity.Current); + } + + [Fact] + public void CreateContextWithEnabledLoggerCreatesActivityAndSetsActivityIdInScope() + { + // Arrange + var logger = new LoggerWithScopes(isEnabled: true); var hostingApplication = CreateApplication(out var features, logger: logger); - features.Get().Headers["Request-Id"] = "some correlation id"; // Act var context = hostingApplication.CreateContext(features); Assert.Single(logger.Scopes); var pairs = ((IReadOnlyList>)logger.Scopes[0]).ToDictionary(p => p.Key, p => p.Value); - Assert.Equal("some correlation id", pairs["CorrelationId"].ToString()); + Assert.Equal(Activity.Current.Id, pairs["ActivityId"].ToString()); } [Fact] @@ -352,7 +363,7 @@ private static HostingApplication CreateApplication(out FeatureCollection featur httpContextFactory.Setup(s => s.Dispose(It.IsAny())); var hostingApplication = new HostingApplication( - ctx => Task.FromResult(0), + ctx => Task.CompletedTask, logger ?? new NullScopeLogger(), diagnosticSource ?? new NoopDiagnosticSource(), httpContextFactory.Object); @@ -362,9 +373,15 @@ private static HostingApplication CreateApplication(out FeatureCollection featur private class NullScopeLogger : ILogger { + private readonly bool _isEnabled; + public NullScopeLogger(bool isEnabled = false) + { + _isEnabled = isEnabled; + } + public IDisposable BeginScope(TState state) => null; - public bool IsEnabled(LogLevel logLevel) => true; + public bool IsEnabled(LogLevel logLevel) => _isEnabled; public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) { @@ -373,6 +390,12 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except private class LoggerWithScopes : ILogger { + private readonly bool _isEnabled; + public LoggerWithScopes(bool isEnabled = false) + { + _isEnabled = isEnabled; + } + public IDisposable BeginScope(TState state) { Scopes.Add(state); @@ -381,7 +404,7 @@ public IDisposable BeginScope(TState state) public List Scopes { get; set; } = new List(); - public bool IsEnabled(LogLevel logLevel) => true; + public bool IsEnabled(LogLevel logLevel) => _isEnabled; public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) { @@ -398,11 +421,14 @@ public void Dispose() private class NoopDiagnosticSource : DiagnosticListener { - public NoopDiagnosticSource() : base("DummyListener") + private readonly bool _isEnabled; + + public NoopDiagnosticSource(bool isEnabled = false) : base("DummyListener") { + _isEnabled = isEnabled; } - public override bool IsEnabled(string name) => true; + public override bool IsEnabled(string name) => _isEnabled; public override void Write(string name, object value) { diff --git a/src/Mvc/test/Mvc.FunctionalTests/ApiBehaviorTest.cs b/src/Mvc/test/Mvc.FunctionalTests/ApiBehaviorTest.cs index 3e99453d03c8..1005a664f804 100644 --- a/src/Mvc/test/Mvc.FunctionalTests/ApiBehaviorTest.cs +++ b/src/Mvc/test/Mvc.FunctionalTests/ApiBehaviorTest.cs @@ -81,7 +81,7 @@ await response.Content.ReadAsStringAsync(), kvp => { Assert.Equal("traceId", kvp.Key); - Assert.Equal(Activity.Current.Id, kvp.Value); + Assert.NotNull(kvp.Value); }); } } @@ -290,7 +290,7 @@ public async Task ClientErrorResultFilterExecutesForStatusCodeResults() kvp => { Assert.Equal("traceId", kvp.Key); - Assert.Equal(Activity.Current.Id, kvp.Value); + Assert.NotNull(kvp.Value); }); } } diff --git a/src/Mvc/test/Mvc.FunctionalTests/JsonOutputFormatterTestBase.cs b/src/Mvc/test/Mvc.FunctionalTests/JsonOutputFormatterTestBase.cs index 228d078f08c6..c4f7ee9dcc2d 100644 --- a/src/Mvc/test/Mvc.FunctionalTests/JsonOutputFormatterTestBase.cs +++ b/src/Mvc/test/Mvc.FunctionalTests/JsonOutputFormatterTestBase.cs @@ -12,6 +12,7 @@ using FormatterWebSite.Controllers; using Microsoft.AspNetCore.Hosting; using Newtonsoft.Json; +using Newtonsoft.Json.Linq; using Xunit; namespace Microsoft.AspNetCore.Mvc.FunctionalTests @@ -161,15 +162,17 @@ public virtual async Task Formatting_ProblemDetails() { using var _ = new ActivityReplacer(); - // Arrange - var expected = $"{{\"type\":\"https://tools.ietf.org/html/rfc7231#section-6.5.4\",\"title\":\"Not Found\",\"status\":404,\"traceId\":\"{Activity.Current.Id}\"}}"; - // Act var response = await Client.GetAsync($"/JsonOutputFormatter/{nameof(JsonOutputFormatterController.ProblemDetailsResult)}"); // Assert await response.AssertStatusCodeAsync(HttpStatusCode.NotFound); - Assert.Equal(expected, await response.Content.ReadAsStringAsync()); + + var obj = JObject.Parse(await response.Content.ReadAsStringAsync()); + Assert.Equal("https://tools.ietf.org/html/rfc7231#section-6.5.4", obj.Value("type")); + Assert.Equal("Not Found", obj.Value("title")); + Assert.Equal("404", obj.Value("status")); + Assert.NotNull(obj.Value("traceId")); } [Fact] diff --git a/src/Mvc/test/Mvc.FunctionalTests/XmlDataContractSerializerFormattersWrappingTest.cs b/src/Mvc/test/Mvc.FunctionalTests/XmlDataContractSerializerFormattersWrappingTest.cs index a0f5027053df..8c60b18e824c 100644 --- a/src/Mvc/test/Mvc.FunctionalTests/XmlDataContractSerializerFormattersWrappingTest.cs +++ b/src/Mvc/test/Mvc.FunctionalTests/XmlDataContractSerializerFormattersWrappingTest.cs @@ -7,6 +7,7 @@ using System.Net.Http; using System.Net.Http.Headers; using System.Threading.Tasks; +using System.Xml.Linq; using Microsoft.AspNetCore.Hosting; using Microsoft.AspNetCore.Mvc.Formatters.Xml; using Microsoft.AspNetCore.Mvc.Testing; @@ -222,20 +223,18 @@ public async Task ProblemDetails_IsSerialized() // Arrange using (new ActivityReplacer()) { - var expected = "" + - "404" + - "Not Found" + - "https://tools.ietf.org/html/rfc7231#section-6.5.4" + - $"{Activity.Current.Id}" + - ""; - // Act var response = await Client.GetAsync("/api/XmlDataContractApi/ActionReturningClientErrorStatusCodeResult"); // Assert await response.AssertStatusCodeAsync(HttpStatusCode.NotFound); var content = await response.Content.ReadAsStringAsync(); - XmlAssert.Equal(expected, content); + var root = XDocument.Parse(content).Root; + Assert.Equal("404", root.Element(root.Name.Namespace.GetName("status"))?.Value); + Assert.Equal("Not Found", root.Element(root.Name.Namespace.GetName("title"))?.Value); + Assert.Equal("https://tools.ietf.org/html/rfc7231#section-6.5.4", root.Element(root.Name.Namespace.GetName("type"))?.Value); + // Activity is not null + Assert.NotNull(root.Element(root.Name.Namespace.GetName("traceId"))?.Value); } } @@ -266,22 +265,21 @@ public async Task ValidationProblemDetails_IsSerialized() // Arrange using (new ActivityReplacer()) { - var expected = "" + - "400" + - "One or more validation errors occurred." + - $"{Activity.Current.Id}" + - "" + - "The State field is required." + - "" + - ""; - // Act var response = await Client.GetAsync("/api/XmlDataContractApi/ActionReturningValidationProblem"); // Assert await response.AssertStatusCodeAsync(HttpStatusCode.BadRequest); var content = await response.Content.ReadAsStringAsync(); - XmlAssert.Equal(expected, content); + var root = XDocument.Parse(content).Root; + + Assert.Equal("400", root.Element(root.Name.Namespace.GetName("status"))?.Value); + Assert.Equal("One or more validation errors occurred.", root.Element(root.Name.Namespace.GetName("title"))?.Value); + var mvcErrors = root.Element(root.Name.Namespace.GetName("MVC-Errors")); + Assert.NotNull(mvcErrors); + Assert.Equal("The State field is required.", mvcErrors.Element(root.Name.Namespace.GetName("State"))?.Value); + // Activity is not null + Assert.NotNull(root.Element(root.Name.Namespace.GetName("traceId"))?.Value); } } diff --git a/src/Mvc/test/Mvc.FunctionalTests/XmlSerializerFormattersWrappingTest.cs b/src/Mvc/test/Mvc.FunctionalTests/XmlSerializerFormattersWrappingTest.cs index 1fa99687d595..c4623a99cdcd 100644 --- a/src/Mvc/test/Mvc.FunctionalTests/XmlSerializerFormattersWrappingTest.cs +++ b/src/Mvc/test/Mvc.FunctionalTests/XmlSerializerFormattersWrappingTest.cs @@ -7,6 +7,7 @@ using System.Net.Http; using System.Net.Http.Headers; using System.Threading.Tasks; +using System.Xml.Linq; using Microsoft.AspNetCore.Hosting; using Microsoft.AspNetCore.Mvc.Formatters.Xml; using Microsoft.AspNetCore.Mvc.Testing; @@ -210,7 +211,12 @@ public async Task ProblemDetails_IsSerialized() // Assert await response.AssertStatusCodeAsync(HttpStatusCode.NotFound); var content = await response.Content.ReadAsStringAsync(); - XmlAssert.Equal(expected, content); + var root = XDocument.Parse(content).Root; + Assert.Equal("404", root.Element(root.Name.Namespace.GetName("status"))?.Value); + Assert.Equal("Not Found", root.Element(root.Name.Namespace.GetName("title"))?.Value); + Assert.Equal("https://tools.ietf.org/html/rfc7231#section-6.5.4", root.Element(root.Name.Namespace.GetName("type"))?.Value); + // Activity is not null + Assert.NotNull(root.Element(root.Name.Namespace.GetName("traceId"))?.Value); } } @@ -241,22 +247,20 @@ public async Task ValidationProblemDetails_IsSerialized() // Arrange using (new ActivityReplacer()) { - var expected = "" + - "400" + - "One or more validation errors occurred." + - $"{Activity.Current.Id}" + - "" + - "The State field is required." + - "" + - ""; - // Act var response = await Client.GetAsync("/api/XmlSerializerApi/ActionReturningValidationProblem"); // Assert await response.AssertStatusCodeAsync(HttpStatusCode.BadRequest); var content = await response.Content.ReadAsStringAsync(); - XmlAssert.Equal(expected, content); + var root = XDocument.Parse(content).Root; + Assert.Equal("400", root.Element(root.Name.Namespace.GetName("status"))?.Value); + Assert.Equal("One or more validation errors occurred.", root.Element(root.Name.Namespace.GetName("title"))?.Value); + var mvcErrors = root.Element(root.Name.Namespace.GetName("MVC-Errors")); + Assert.NotNull(mvcErrors); + Assert.Equal("The State field is required.", mvcErrors.Element(root.Name.Namespace.GetName("State"))?.Value); + // Activity is not null + Assert.NotNull(root.Element(root.Name.Namespace.GetName("traceId"))?.Value); } }