Skip to content

Commit 32c46c7

Browse files
davidfowldavidfowl
authored
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)
1 parent 92cae6f commit 32c46c7

9 files changed

+100
-75
lines changed

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

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -37,7 +37,7 @@ public GenericWebHostService(IOptions<GenericWebHostServiceOptions> options,
3737
{
3838
Options = options.Value;
3939
Server = server;
40-
Logger = loggerFactory.CreateLogger<GenericWebHostService>();
40+
Logger = loggerFactory.CreateLogger("Microsoft.AspNetCore.Hosting.Diagnostics");
4141
LifetimeLogger = loggerFactory.CreateLogger("Microsoft.Hosting.Lifetime");
4242
DiagnosticListener = diagnosticListener;
4343
HttpContextFactory = httpContextFactory;
@@ -49,7 +49,7 @@ public GenericWebHostService(IOptions<GenericWebHostServiceOptions> options,
4949

5050
public GenericWebHostServiceOptions Options { get; }
5151
public IServer Server { get; }
52-
public ILogger<GenericWebHostService> Logger { get; }
52+
public ILogger Logger { get; }
5353
// Only for high level lifetime events
5454
public ILogger LifetimeLogger { get; }
5555
public DiagnosticListener DiagnosticListener { get; }

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

Lines changed: 12 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -51,13 +51,13 @@ public void BeginRequest(HttpContext httpContext, ref HostingApplication.Context
5151
var diagnosticListenerEnabled = _diagnosticListener.IsEnabled();
5252
var loggingEnabled = _logger.IsEnabled(LogLevel.Critical);
5353

54+
if (loggingEnabled || (diagnosticListenerEnabled && _diagnosticListener.IsEnabled(ActivityName, httpContext)))
55+
{
56+
context.Activity = StartActivity(httpContext);
57+
}
5458

5559
if (diagnosticListenerEnabled)
5660
{
57-
if (_diagnosticListener.IsEnabled(ActivityName, httpContext))
58-
{
59-
context.Activity = StartActivity(httpContext);
60-
}
6161
if (_diagnosticListener.IsEnabled(DeprecatedDiagnosticsBeginRequestKey))
6262
{
6363
startTimestamp = Stopwatch.GetTimestamp();
@@ -68,16 +68,10 @@ public void BeginRequest(HttpContext httpContext, ref HostingApplication.Context
6868
// To avoid allocation, return a null scope if the logger is not on at least to some degree.
6969
if (loggingEnabled)
7070
{
71-
// Get the request ID (first try TraceParent header otherwise Request-ID header
72-
if (!httpContext.Request.Headers.TryGetValue(TraceParentHeaderName, out var correlationId))
73-
{
74-
httpContext.Request.Headers.TryGetValue(RequestIdHeaderName, out correlationId);
75-
}
76-
7771
// Scope may be relevant for a different level of logging, so we always create it
7872
// see: https://github.com/aspnet/Hosting/pull/944
7973
// Scope can be null if logging is not on.
80-
context.Scope = _logger.RequestScope(httpContext, correlationId);
74+
context.Scope = _logger.RequestScope(httpContext, context.Activity.Id);
8175

8276
if (_logger.IsEnabled(LogLevel.Information))
8377
{
@@ -90,7 +84,6 @@ public void BeginRequest(HttpContext httpContext, ref HostingApplication.Context
9084
LogRequestStarting(httpContext);
9185
}
9286
}
93-
9487
context.StartTimestamp = startTimestamp;
9588
}
9689

@@ -138,13 +131,13 @@ public void RequestEnd(HttpContext httpContext, Exception exception, HostingAppl
138131
}
139132

140133
}
134+
}
141135

142-
var activity = context.Activity;
143-
// Always stop activity if it was started
144-
if (activity != null)
145-
{
146-
StopActivity(httpContext, activity);
147-
}
136+
var activity = context.Activity;
137+
// Always stop activity if it was started
138+
if (activity != null)
139+
{
140+
StopActivity(httpContext, activity);
148141
}
149142

150143
if (context.EventLogEnabled && exception != null)
@@ -261,7 +254,7 @@ private Activity StartActivity(HttpContext httpContext)
261254
// We expect baggage to be empty by default
262255
// Only very advanced users will be using it in near future, we encourage them to keep baggage small (few items)
263256
string[] baggage = httpContext.Request.Headers.GetCommaSeparatedValues(CorrelationContextHeaderName);
264-
if (baggage != StringValues.Empty)
257+
if (baggage.Length > 0)
265258
{
266259
foreach (var item in baggage)
267260
{

‎src/Hosting/Hosting/src/Internal/HostingLoggerExtensions.cs

Lines changed: 9 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -13,9 +13,9 @@ namespace Microsoft.AspNetCore.Hosting.Internal
1313
{
1414
internal static class HostingLoggerExtensions
1515
{
16-
public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext, string correlationId)
16+
public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext, string activityId)
1717
{
18-
return logger.BeginScope(new HostingLogScope(httpContext, correlationId));
18+
return logger.BeginScope(new HostingLogScope(httpContext, activityId));
1919
}
2020

2121
public static void ApplicationError(this ILogger logger, Exception exception)
@@ -96,7 +96,7 @@ private class HostingLogScope : IReadOnlyList<KeyValuePair<string, object>>
9696
{
9797
private readonly string _path;
9898
private readonly string _traceIdentifier;
99-
private readonly string _correlationId;
99+
private readonly string _activityId;
100100

101101
private string _cachedToString;
102102

@@ -122,20 +122,20 @@ public KeyValuePair<string, object> this[int index]
122122
}
123123
else if (index == 2)
124124
{
125-
return new KeyValuePair<string, object>("CorrelationId", _correlationId);
125+
return new KeyValuePair<string, object>("ActivityId", _activityId);
126126
}
127127

128128
throw new ArgumentOutOfRangeException(nameof(index));
129129
}
130130
}
131131

132-
public HostingLogScope(HttpContext httpContext, string correlationId)
132+
public HostingLogScope(HttpContext httpContext, string activityId)
133133
{
134134
_traceIdentifier = httpContext.TraceIdentifier;
135135
_path = (httpContext.Request.PathBase.HasValue
136136
? httpContext.Request.PathBase + httpContext.Request.Path
137137
: httpContext.Request.Path).ToString();
138-
_correlationId = correlationId;
138+
_activityId = activityId;
139139
}
140140

141141
public override string ToString()
@@ -144,9 +144,10 @@ public override string ToString()
144144
{
145145
_cachedToString = string.Format(
146146
CultureInfo.InvariantCulture,
147-
"RequestId:{0} RequestPath:{1}",
147+
"RequestPath:{0} RequestId:{1}, ActivityId:{2}",
148+
_path,
148149
_traceIdentifier,
149-
_path);
150+
_activityId);
150151
}
151152

152153
return _cachedToString;

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

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -41,7 +41,7 @@ internal class WebHost : IWebHost, IAsyncDisposable
4141

4242
private IServiceProvider _applicationServices;
4343
private ExceptionDispatchInfo _applicationServicesException;
44-
private ILogger<WebHost> _logger;
44+
private ILogger _logger;
4545

4646
private bool _stopped;
4747

@@ -139,7 +139,7 @@ public void Start()
139139
public virtual async Task StartAsync(CancellationToken cancellationToken = default)
140140
{
141141
HostingEventSource.Log.HostStart();
142-
_logger = _applicationServices.GetRequiredService<ILogger<WebHost>>();
142+
_logger = _applicationServices.GetRequiredService<ILoggerFactory>().CreateLogger("Microsoft.AspNetCore.Hosting.Diagnostics");
143143
_logger.Starting();
144144

145145
var application = BuildApplication();

‎src/Hosting/Hosting/test/HostingApplicationTests.cs

Lines changed: 35 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -30,19 +30,30 @@ public void DisposeContextDoesNotThrowWhenContextScopeIsNull()
3030
}
3131

3232
[Fact]
33-
public void CreateContextSetsCorrelationIdInScope()
33+
public void CreateContextWithDisabledLoggerDoesNotCreateActivity()
3434
{
3535
// Arrange
36-
var logger = new LoggerWithScopes();
36+
var hostingApplication = CreateApplication(out var features);
37+
38+
// Act
39+
hostingApplication.CreateContext(features);
40+
41+
Assert.Null(Activity.Current);
42+
}
43+
44+
[Fact]
45+
public void CreateContextWithEnabledLoggerCreatesActivityAndSetsActivityIdInScope()
46+
{
47+
// Arrange
48+
var logger = new LoggerWithScopes(isEnabled: true);
3749
var hostingApplication = CreateApplication(out var features, logger: logger);
38-
features.Get<IHttpRequestFeature>().Headers["Request-Id"] = "some correlation id";
3950

4051
// Act
4152
var context = hostingApplication.CreateContext(features);
4253

4354
Assert.Single(logger.Scopes);
4455
var pairs = ((IReadOnlyList<KeyValuePair<string, object>>)logger.Scopes[0]).ToDictionary(p => p.Key, p => p.Value);
45-
Assert.Equal("some correlation id", pairs["CorrelationId"].ToString());
56+
Assert.Equal(Activity.Current.Id, pairs["ActivityId"].ToString());
4657
}
4758

4859
[Fact]
@@ -352,7 +363,7 @@ private static HostingApplication CreateApplication(out FeatureCollection featur
352363
httpContextFactory.Setup(s => s.Dispose(It.IsAny<HttpContext>()));
353364

354365
var hostingApplication = new HostingApplication(
355-
ctx => Task.FromResult(0),
366+
ctx => Task.CompletedTask,
356367
logger ?? new NullScopeLogger(),
357368
diagnosticSource ?? new NoopDiagnosticSource(),
358369
httpContextFactory.Object);
@@ -362,9 +373,15 @@ private static HostingApplication CreateApplication(out FeatureCollection featur
362373

363374
private class NullScopeLogger : ILogger
364375
{
376+
private readonly bool _isEnabled;
377+
public NullScopeLogger(bool isEnabled = false)
378+
{
379+
_isEnabled = isEnabled;
380+
}
381+
365382
public IDisposable BeginScope<TState>(TState state) => null;
366383

367-
public bool IsEnabled(LogLevel logLevel) => true;
384+
public bool IsEnabled(LogLevel logLevel) => _isEnabled;
368385

369386
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
370387
{
@@ -373,6 +390,12 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
373390

374391
private class LoggerWithScopes : ILogger
375392
{
393+
private readonly bool _isEnabled;
394+
public LoggerWithScopes(bool isEnabled = false)
395+
{
396+
_isEnabled = isEnabled;
397+
}
398+
376399
public IDisposable BeginScope<TState>(TState state)
377400
{
378401
Scopes.Add(state);
@@ -381,7 +404,7 @@ public IDisposable BeginScope<TState>(TState state)
381404

382405
public List<object> Scopes { get; set; } = new List<object>();
383406

384-
public bool IsEnabled(LogLevel logLevel) => true;
407+
public bool IsEnabled(LogLevel logLevel) => _isEnabled;
385408

386409
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
387410
{
@@ -398,11 +421,14 @@ public void Dispose()
398421

399422
private class NoopDiagnosticSource : DiagnosticListener
400423
{
401-
public NoopDiagnosticSource() : base("DummyListener")
424+
private readonly bool _isEnabled;
425+
426+
public NoopDiagnosticSource(bool isEnabled = false) : base("DummyListener")
402427
{
428+
_isEnabled = isEnabled;
403429
}
404430

405-
public override bool IsEnabled(string name) => true;
431+
public override bool IsEnabled(string name) => _isEnabled;
406432

407433
public override void Write(string name, object value)
408434
{

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

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -81,7 +81,7 @@ await response.Content.ReadAsStringAsync(),
8181
kvp =>
8282
{
8383
Assert.Equal("traceId", kvp.Key);
84-
Assert.Equal(Activity.Current.Id, kvp.Value);
84+
Assert.NotNull(kvp.Value);
8585
});
8686
}
8787
}
@@ -290,7 +290,7 @@ public async Task ClientErrorResultFilterExecutesForStatusCodeResults()
290290
kvp =>
291291
{
292292
Assert.Equal("traceId", kvp.Key);
293-
Assert.Equal(Activity.Current.Id, kvp.Value);
293+
Assert.NotNull(kvp.Value);
294294
});
295295
}
296296
}

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

Lines changed: 7 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,7 @@
1212
using FormatterWebSite.Controllers;
1313
using Microsoft.AspNetCore.Hosting;
1414
using Newtonsoft.Json;
15+
using Newtonsoft.Json.Linq;
1516
using Xunit;
1617

1718
namespace Microsoft.AspNetCore.Mvc.FunctionalTests
@@ -161,15 +162,17 @@ public virtual async Task Formatting_ProblemDetails()
161162
{
162163
using var _ = new ActivityReplacer();
163164

164-
// Arrange
165-
var expected = $"{{\"type\":\"https://tools.ietf.org/html/rfc7231#section-6.5.4\",\"title\":\"Not Found\",\"status\":404,\"traceId\":\"{Activity.Current.Id}\"}}";
166-
167165
// Act
168166
var response = await Client.GetAsync($"/JsonOutputFormatter/{nameof(JsonOutputFormatterController.ProblemDetailsResult)}");
169167

170168
// Assert
171169
await response.AssertStatusCodeAsync(HttpStatusCode.NotFound);
172-
Assert.Equal(expected, await response.Content.ReadAsStringAsync());
170+
171+
var obj = JObject.Parse(await response.Content.ReadAsStringAsync());
172+
Assert.Equal("https://tools.ietf.org/html/rfc7231#section-6.5.4", obj.Value<string>("type"));
173+
Assert.Equal("Not Found", obj.Value<string>("title"));
174+
Assert.Equal("404", obj.Value<string>("status"));
175+
Assert.NotNull(obj.Value<string>("traceId"));
173176
}
174177

175178
[Fact]

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

Lines changed: 16 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@
77
using System.Net.Http;
88
using System.Net.Http.Headers;
99
using System.Threading.Tasks;
10+
using System.Xml.Linq;
1011
using Microsoft.AspNetCore.Hosting;
1112
using Microsoft.AspNetCore.Mvc.Formatters.Xml;
1213
using Microsoft.AspNetCore.Mvc.Testing;
@@ -222,20 +223,18 @@ public async Task ProblemDetails_IsSerialized()
222223
// Arrange
223224
using (new ActivityReplacer())
224225
{
225-
var expected = "<problem xmlns=\"urn:ietf:rfc:7807\">" +
226-
"<status>404</status>" +
227-
"<title>Not Found</title>" +
228-
"<type>https://tools.ietf.org/html/rfc7231#section-6.5.4</type>" +
229-
$"<traceId>{Activity.Current.Id}</traceId>" +
230-
"</problem>";
231-
232226
// Act
233227
var response = await Client.GetAsync("/api/XmlDataContractApi/ActionReturningClientErrorStatusCodeResult");
234228

235229
// Assert
236230
await response.AssertStatusCodeAsync(HttpStatusCode.NotFound);
237231
var content = await response.Content.ReadAsStringAsync();
238-
XmlAssert.Equal(expected, content);
232+
var root = XDocument.Parse(content).Root;
233+
Assert.Equal("404", root.Element(root.Name.Namespace.GetName("status"))?.Value);
234+
Assert.Equal("Not Found", root.Element(root.Name.Namespace.GetName("title"))?.Value);
235+
Assert.Equal("https://tools.ietf.org/html/rfc7231#section-6.5.4", root.Element(root.Name.Namespace.GetName("type"))?.Value);
236+
// Activity is not null
237+
Assert.NotNull(root.Element(root.Name.Namespace.GetName("traceId"))?.Value);
239238
}
240239
}
241240

@@ -266,22 +265,21 @@ public async Task ValidationProblemDetails_IsSerialized()
266265
// Arrange
267266
using (new ActivityReplacer())
268267
{
269-
var expected = "<problem xmlns=\"urn:ietf:rfc:7807\">" +
270-
"<status>400</status>" +
271-
"<title>One or more validation errors occurred.</title>" +
272-
$"<traceId>{Activity.Current.Id}</traceId>" +
273-
"<MVC-Errors>" +
274-
"<State>The State field is required.</State>" +
275-
"</MVC-Errors>" +
276-
"</problem>";
277-
278268
// Act
279269
var response = await Client.GetAsync("/api/XmlDataContractApi/ActionReturningValidationProblem");
280270

281271
// Assert
282272
await response.AssertStatusCodeAsync(HttpStatusCode.BadRequest);
283273
var content = await response.Content.ReadAsStringAsync();
284-
XmlAssert.Equal(expected, content);
274+
var root = XDocument.Parse(content).Root;
275+
276+
Assert.Equal("400", root.Element(root.Name.Namespace.GetName("status"))?.Value);
277+
Assert.Equal("One or more validation errors occurred.", root.Element(root.Name.Namespace.GetName("title"))?.Value);
278+
var mvcErrors = root.Element(root.Name.Namespace.GetName("MVC-Errors"));
279+
Assert.NotNull(mvcErrors);
280+
Assert.Equal("The State field is required.", mvcErrors.Element(root.Name.Namespace.GetName("State"))?.Value);
281+
// Activity is not null
282+
Assert.NotNull(root.Element(root.Name.Namespace.GetName("traceId"))?.Value);
285283
}
286284
}
287285

0 commit comments

Comments
 (0)