Create an activity more often than before (#9361)

- Create an Activity if there's a diagnostic listener attached with the activity name or if logging is enabled.
- Add the activity id to the logging scope (and call the field ActivityId)

src/Hosting/Hosting/src/GenericHost/GenericWebHostedService.cs

@@ -37,7 +37,7 @@ namespace Microsoft.AspNetCore.Hosting.Internal
         {
             Options = options.Value;
             Server = server;
-            Logger = loggerFactory.CreateLogger<GenericWebHostService>();
+            Logger = loggerFactory.CreateLogger("Microsoft.AspNetCore.Hosting.Diagnostics");
             LifetimeLogger = loggerFactory.CreateLogger("Microsoft.Hosting.Lifetime");
             DiagnosticListener = diagnosticListener;
             HttpContextFactory = httpContextFactory;
@@ -49,7 +49,7 @@ namespace Microsoft.AspNetCore.Hosting.Internal
 
         public GenericWebHostServiceOptions Options { get; }
         public IServer Server { get; }
-        public ILogger<GenericWebHostService> Logger { get; }
+        public ILogger Logger { get; }
         // Only for high level lifetime events
         public ILogger LifetimeLogger { get; }
         public DiagnosticListener DiagnosticListener { get; }

src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs

@@ -51,13 +51,13 @@ namespace Microsoft.AspNetCore.Hosting.Internal
             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 @@ namespace Microsoft.AspNetCore.Hosting.Internal
             // 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 @@ namespace Microsoft.AspNetCore.Hosting.Internal
                     LogRequestStarting(httpContext);
                 }
             }
-
             context.StartTimestamp = startTimestamp;
         }
 
@@ -138,13 +131,13 @@ namespace Microsoft.AspNetCore.Hosting.Internal
                     }
 
                 }
+            }
 
-                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 @@ namespace Microsoft.AspNetCore.Hosting.Internal
                 // 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)
                     {

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 @@ namespace Microsoft.AspNetCore.Hosting.Internal
         {
             private readonly string _path;
             private readonly string _traceIdentifier;
-            private readonly string _correlationId;
+            private readonly string _activityId;
 
             private string _cachedToString;
 
@@ -122,20 +122,20 @@ namespace Microsoft.AspNetCore.Hosting.Internal
                     }
                     else if (index == 2)
                     {
-                        return new KeyValuePair<string, object>("CorrelationId", _correlationId);
+                        return new KeyValuePair<string, object>("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 @@ namespace Microsoft.AspNetCore.Hosting.Internal
                 {
                     _cachedToString = string.Format(
                         CultureInfo.InvariantCulture,
-                        "RequestId:{0} RequestPath:{1}",
+                        "RequestPath:{0} RequestId:{1}, ActivityId:{2}",
+                        _path,
                         _traceIdentifier,
-                        _path);
+                        _activityId);
                 }
 
                 return _cachedToString;

src/Hosting/Hosting/src/Internal/WebHost.cs

@@ -41,7 +41,7 @@ namespace Microsoft.AspNetCore.Hosting.Internal
 
         private IServiceProvider _applicationServices;
         private ExceptionDispatchInfo _applicationServicesException;
-        private ILogger<WebHost> _logger;
+        private ILogger _logger;
 
         private bool _stopped;
 
@@ -139,7 +139,7 @@ namespace Microsoft.AspNetCore.Hosting.Internal
         public virtual async Task StartAsync(CancellationToken cancellationToken = default)
         {
             HostingEventSource.Log.HostStart();
-            _logger = _applicationServices.GetRequiredService<ILogger<WebHost>>();
+            _logger = _applicationServices.GetRequiredService<ILoggerFactory>().CreateLogger("Microsoft.AspNetCore.Hosting.Diagnostics");
             _logger.Starting();
 
             var application = BuildApplication();

src/Hosting/Hosting/test/HostingApplicationTests.cs

@@ -30,19 +30,30 @@ namespace Microsoft.AspNetCore.Hosting.Tests
         }
 
         [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<IHttpRequestFeature>().Headers["Request-Id"] = "some correlation id";
 
             // Act
             var context = hostingApplication.CreateContext(features);
 
             Assert.Single(logger.Scopes);
             var pairs = ((IReadOnlyList<KeyValuePair<string, object>>)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 @@ namespace Microsoft.AspNetCore.Hosting.Tests
             httpContextFactory.Setup(s => s.Dispose(It.IsAny<HttpContext>()));
 
             var hostingApplication = new HostingApplication(
-                ctx => Task.FromResult(0),
+                ctx => Task.CompletedTask,
                 logger ?? new NullScopeLogger(),
                 diagnosticSource ?? new NoopDiagnosticSource(),
                 httpContextFactory.Object);
@@ -362,9 +373,15 @@ namespace Microsoft.AspNetCore.Hosting.Tests
 
         private class NullScopeLogger : ILogger
         {
+            private readonly bool _isEnabled;
+            public NullScopeLogger(bool isEnabled = false)
+            {
+                _isEnabled = isEnabled;
+            }
+
             public IDisposable BeginScope<TState>(TState state) => null;
 
-            public bool IsEnabled(LogLevel logLevel) => true;
+            public bool IsEnabled(LogLevel logLevel) => _isEnabled;
 
             public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
             {
@@ -373,6 +390,12 @@ namespace Microsoft.AspNetCore.Hosting.Tests
 
         private class LoggerWithScopes : ILogger
         {
+            private readonly bool _isEnabled;
+            public LoggerWithScopes(bool isEnabled = false)
+            {
+                _isEnabled = isEnabled;
+            }
+
             public IDisposable BeginScope<TState>(TState state)
             {
                 Scopes.Add(state);
@@ -381,7 +404,7 @@ namespace Microsoft.AspNetCore.Hosting.Tests
 
             public List<object> Scopes { get; set; } = new List<object>();
 
-            public bool IsEnabled(LogLevel logLevel) => true;
+            public bool IsEnabled(LogLevel logLevel) => _isEnabled;
 
             public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
             {
@@ -398,11 +421,14 @@ namespace Microsoft.AspNetCore.Hosting.Tests
 
         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)
             {

src/Mvc/test/Mvc.FunctionalTests/ApiBehaviorTest.cs

@@ -81,7 +81,7 @@ namespace Microsoft.AspNetCore.Mvc.FunctionalTests
                     kvp =>
                     {
                         Assert.Equal("traceId", kvp.Key);
-                        Assert.Equal(Activity.Current.Id, kvp.Value);
+                        Assert.NotNull(kvp.Value);
                     });
             }
         }
@@ -290,7 +290,7 @@ namespace Microsoft.AspNetCore.Mvc.FunctionalTests
                     kvp =>
                     {
                         Assert.Equal("traceId", kvp.Key);
-                        Assert.Equal(Activity.Current.Id, kvp.Value);
+                        Assert.NotNull(kvp.Value);
                     });
             }
         }

src/Mvc/test/Mvc.FunctionalTests/JsonOutputFormatterTestBase.cs

@@ -12,6 +12,7 @@ using System.Threading.Tasks;
 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 @@ namespace Microsoft.AspNetCore.Mvc.FunctionalTests
         {
             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<string>("type"));
+            Assert.Equal("Not Found", obj.Value<string>("title"));
+            Assert.Equal("404", obj.Value<string>("status"));
+            Assert.NotNull(obj.Value<string>("traceId"));
         }
 
         [Fact]

src/Mvc/test/Mvc.FunctionalTests/XmlDataContractSerializerFormattersWrappingTest.cs

@@ -7,6 +7,7 @@ using System.Net;
 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 @@ namespace Microsoft.AspNetCore.Mvc.FunctionalTests
             // Arrange
             using (new ActivityReplacer())
             {
-                var expected = "<problem xmlns=\"urn:ietf:rfc:7807\">" +
-                    "<status>404</status>" +
-                    "<title>Not Found</title>" +
-                    "<type>https://tools.ietf.org/html/rfc7231#section-6.5.4</type>" +
-                    $"<traceId>{Activity.Current.Id}</traceId>" +
-                    "</problem>";
-
                 // 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 @@ namespace Microsoft.AspNetCore.Mvc.FunctionalTests
             // Arrange
             using (new ActivityReplacer())
             {
-                var expected = "<problem xmlns=\"urn:ietf:rfc:7807\">" +
-                "<status>400</status>" +
-                "<title>One or more validation errors occurred.</title>" +
-                $"<traceId>{Activity.Current.Id}</traceId>" +
-                "<MVC-Errors>" +
-                "<State>The State field is required.</State>" +
-                "</MVC-Errors>" +
-                "</problem>";
-
                 // 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);
             }
         }
 

src/Mvc/test/Mvc.FunctionalTests/XmlSerializerFormattersWrappingTest.cs

@@ -7,6 +7,7 @@ using System.Net;
 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 @@ namespace Microsoft.AspNetCore.Mvc.FunctionalTests
                 // 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 @@ namespace Microsoft.AspNetCore.Mvc.FunctionalTests
             // Arrange
             using (new ActivityReplacer())
             {
-                var expected = "<problem xmlns=\"urn:ietf:rfc:7807\">" +
-               "<status>400</status>" +
-               "<title>One or more validation errors occurred.</title>" +
-               $"<traceId>{Activity.Current.Id}</traceId>" +
-               "<MVC-Errors>" +
-               "<State>The State field is required.</State>" +
-               "</MVC-Errors>" +
-               "</problem>";
-
                 // 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);
             }
         }