ExecutionContext is dropped for HTTP/2 requests, Kestrel connection scope is lost #26282
Description
Describe the bug
ASP .NET Core is dropping the ExecutionContext before it starts the user application's pi[peline for HTTP/2 incoming requests. This results in Kestrel's connection scope (KestrelConnection.BeginConnectionScope()) being lost by the time the application pipeline is executed.
This has caused significant pains while attempting to gather low-level traces and correlating them with high-level application logs.
To Reproduce
- Create a trivial ASP .NET Core 3.1 app using Kestrel
- Use an
ILoggerProviderthat also implementsISupportExternalScope - Enable
Tracelog level for Kestrel events ("Microsoft.AspNetCore": "Trace") - Issue an HTTP/2 request
- Observe that Kestrel's internal events include an instance of
ConnectionLogScopewhen traversing the current scopes - HOWEVER: logs in the application's pipeline have no scopes!
Stack trace from an event missing scopes:
at System.Environment.get_StackTrace()
at IslandGateway.Program.DummyLogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
at Microsoft.Extensions.Logging.Logger.<Log>g__LoggerLog|12_0[TState](LogLevel logLevel, EventId eventId, ILogger logger, Exception exception, Func`3 formatter, List`1& exceptions, TState& state)
at Microsoft.Extensions.Logging.Logger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
at Microsoft.Extensions.Logging.Logger`1.Microsoft.Extensions.Logging.ILogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
at CoreFramework.ActivityLoggerExtensions.ExecuteRootAsync(ILogger logger, EventId eventId, RootExecutionContext rootContext, ActivityType activityType, Func`1 action, IEnumerable`1 additionalCustomProperties)
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at CoreFramework.ActivityLoggerExtensions.ExecuteRootAsync(ILogger logger, EventId eventId, RootExecutionContext rootContext, ActivityType activityType, Func`1 action, IEnumerable`1 additionalCustomProperties)
at CoreFramework.ActivityLoggerExtensions.ExecuteRootAsync(ILogger logger, RootExecutionContext rootContext, ActivityType activityType, Func`1 action, IEnumerable`1 additionalCustomProperties)
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at CoreFramework.ActivityLoggerExtensions.ExecuteRootAsync(ILogger logger, RootExecutionContext rootContext, ActivityType activityType, Func`1 action, IEnumerable`1 additionalCustomProperties)
at CoreFramework.AspNetCore.ExternalWebApiHost.InvokeAsync(HttpContext httpContext, Func`1 next)
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at CoreFramework.AspNetCore.ExternalWebApiHost.InvokeAsync(HttpContext httpContext, Func`1 next)
at Microsoft.AspNetCore.Builder.UseExtensions.<>c__DisplayClass0_1.<Use>b__1(HttpContext context)
at Microsoft.AspNetCore.Builder.UseExtensions.<>c__DisplayClass0_2.<Use>b__2()
at CoreFramework.AspNetCore.UnhandledExceptionLoggingMiddleware.InvokeAsync(HttpContext httpContext, Func`1 next)
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at CoreFramework.AspNetCore.UnhandledExceptionLoggingMiddleware.InvokeAsync(HttpContext httpContext, Func`1 next)
at Microsoft.AspNetCore.Builder.UseExtensions.<>c__DisplayClass0_1.<Use>b__1(HttpContext context)
at Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware.Invoke(HttpContext context)
at Microsoft.AspNetCore.Hosting.HostingApplication.ProcessRequestAsync(Context context)
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequestsAsync[TContext](IHttpApplication`1 application)
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequestsAsync[TContext](IHttpApplication`1 application)
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Stream`1.Execute()
at System.Threading.ThreadPoolWorkQueue.Dispatch()
at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback()
Further technical details
- ASP.NET Core version 3.1.7
- Include the output of
dotnet --info
dotnet --info
.NET Core SDK (reflecting any global.json):
Version: 3.1.401
Commit: 39d17847db
Runtime Environment:
OS Name: Windows
OS Version: 10.0.19041
OS Platform: Windows
RID: win10-x64
Base Path: C:\src\PowerApps\CoreServicesGateway\packages\dotnetsdk\sdk\3.1.401\
Host (useful for support):
Version: 3.1.7
Commit: fcfdef8d6b
.NET Core SDKs installed:
3.1.401 [C:\src\PowerApps\CoreServicesGateway\packages\dotnetsdk\sdk]
.NET Core runtimes installed:
Microsoft.AspNetCore.App 3.1.7 [C:\src\PowerApps\CoreServicesGateway\packages\dotnetsdk\shared\Microsoft.AspNetCore.App]
Microsoft.NETCore.App 3.1.7 [C:\src\PowerApps\CoreServicesGateway\packages\dotnetsdk\shared\Microsoft.NETCore.App]
Microsoft.WindowsDesktop.App 3.1.7 [C:\src\PowerApps\CoreServicesGateway\packages\dotnetsdk\shared\Microsoft.WindowsDesktop.App]
To install additional .NET Core runtimes or SDKs:
https://aka.ms/dotnet-download
Example loggers used in minimal repro:
private class DummyLoggerProvider : ILoggerProvider, ISupportExternalScope
{
public DummyLoggerProvider()
{
}
internal IExternalScopeProvider ScopeProvider { get; private set; }
public ILogger CreateLogger(string categoryName)
{
return new DummyLogger(this);
}
public void Dispose()
{
throw new NotImplementedException();
}
public void SetScopeProvider(IExternalScopeProvider scopeProvider)
{
this.ScopeProvider = scopeProvider;
}
}
private class DummyLogger : ILogger
{
private readonly DummyLoggerProvider parent;
public DummyLogger(DummyLoggerProvider parent)
{
this.parent = parent;
}
public IDisposable BeginScope<TState>(TState state)
{
return this.parent.ScopeProvider?.Push(state) ?? new HttpClient();
}
public bool IsEnabled(LogLevel logLevel)
{
return true;
}
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{
string scopes = string.Empty;
this.parent.ScopeProvider?.ForEachScope(
(scopeObject, _) =>
{
var kvps = scopeObject as IEnumerable<KeyValuePair<string, object>>;
if (kvps != null)
{
scopes = string.Join(", ", kvps.Select(kvp => $"{kvp.Key}='{kvp.Value}'"));
}
},
(string)null);
var msg = formatter(state, exception);
if (scopes == string.Empty && msg.Contains("logged in application pipeline"))
{
// Stack trace collected here
}
Console.WriteLine($"[{scopes}] {msg}");
}
}