From 9851e0168812471e52c4c965a0c0005240f762ba Mon Sep 17 00:00:00 2001 From: David Fowler Date: Sun, 21 Jul 2019 21:14:03 -0700 Subject: [PATCH] Track connection earlier (#12387) - We made a change to dispatch connection execution but that also ended up dispatching the tracking of those connections in the connection manager. While it's not a huge deal most of the time it can affect graceful shutdown as there can be queued connections that are delayed in the thread pool queue which are untracked. This change makes it so we track the KestrelConnection before dispatching. --- .../Kestrel/Core/src/Internal/ConnectionDispatcher.cs | 8 +++++++- .../Core/src/Internal/Infrastructure/IKestrelTrace.cs | 2 ++ .../src/Internal/Infrastructure/KestrelConnection.cs | 2 -- .../Core/src/Internal/Infrastructure/KestrelTrace.cs | 9 ++++++++- .../Kestrel/Core/test/ConnectionDispatcherTests.cs | 3 +++ .../Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs | 1 + src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs | 8 +++++++- 7 files changed, 28 insertions(+), 5 deletions(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs b/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs index 603873646a..df08a8d320 100644 --- a/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs +++ b/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs @@ -51,8 +51,14 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal break; } + // Add the connection to the connection manager before we queue it for execution var id = Interlocked.Increment(ref _lastConnectionId); - var kestrelConnection = new KestrelConnection(id, _serviceContext, _connectionDelegate, connection, _serviceContext.Log); + var kestrelConnection = new KestrelConnection(id, _serviceContext, _connectionDelegate, connection, Log); + + _serviceContext.ConnectionManager.AddConnection(id, kestrelConnection); + + Log.ConnectionAccepted(connection.ConnectionId); + ThreadPool.UnsafeQueueUserWorkItem(kestrelConnection, preferLocal: false); } } diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs index 07dae29f96..1a5815300e 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs @@ -11,6 +11,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure { internal interface IKestrelTrace : ILogger { + void ConnectionAccepted(string connectionId); + void ConnectionStart(string connectionId); void ConnectionStop(string connectionId); diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnection.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnection.cs index c885f80e0a..bec07b018d 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnection.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnection.cs @@ -186,8 +186,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure try { - _serviceContext.ConnectionManager.AddConnection(_id, this); - Logger.ConnectionStart(connectionContext.ConnectionId); KestrelEventSource.Log.ConnectionStart(connectionContext); diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs index 8112f5a2a5..d72aa3c707 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs @@ -5,7 +5,6 @@ using System; using Microsoft.AspNetCore.Connections; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.HPack; -using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.Extensions.Logging; namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure @@ -111,6 +110,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure LoggerMessage.Define(LogLevel.Information, new EventId(38, nameof(HPackEncodingError)), @"Connection id ""{ConnectionId}"": HPACK encoding error while encoding headers for stream ID {StreamId}."); + private static readonly Action _connectionAccepted = + LoggerMessage.Define(LogLevel.Debug, new EventId(39, nameof(ConnectionAccepted)), @"Connection id ""{ConnectionId}"" accepted."); + protected readonly ILogger _logger; public KestrelTrace(ILogger logger) @@ -118,6 +120,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure _logger = logger; } + public virtual void ConnectionAccepted(string connectionId) + { + _connectionAccepted(_logger, connectionId, null); + } + public virtual void ConnectionStart(string connectionId) { _connectionStart(_logger, connectionId, null); diff --git a/src/Servers/Kestrel/Core/test/ConnectionDispatcherTests.cs b/src/Servers/Kestrel/Core/test/ConnectionDispatcherTests.cs index de6f33c28d..1315c24b4b 100644 --- a/src/Servers/Kestrel/Core/test/ConnectionDispatcherTests.cs +++ b/src/Servers/Kestrel/Core/test/ConnectionDispatcherTests.cs @@ -30,6 +30,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests var connection = new Mock { CallBase = true }.Object; connection.ConnectionClosed = new CancellationToken(canceled: true); var kestrelConnection = new KestrelConnection(0, serviceContext, _ => tcs.Task, connection, serviceContext.Log); + serviceContext.ConnectionManager.AddConnection(0, kestrelConnection); var task = kestrelConnection.ExecuteAsync(); @@ -79,6 +80,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests var connection = new Mock { CallBase = true }.Object; connection.ConnectionClosed = new CancellationToken(canceled: true); var kestrelConnection = new KestrelConnection(0, serviceContext, _ => Task.CompletedTask, connection, serviceContext.Log); + serviceContext.ConnectionManager.AddConnection(0, kestrelConnection); var completeFeature = kestrelConnection.TransportConnection.Features.Get(); Assert.NotNull(completeFeature); @@ -99,6 +101,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests var connection = new Mock { CallBase = true }.Object; connection.ConnectionClosed = new CancellationToken(canceled: true); var kestrelConnection = new KestrelConnection(0, serviceContext, _ => Task.CompletedTask, connection, serviceContext.Log); + serviceContext.ConnectionManager.AddConnection(0, kestrelConnection); var completeFeature = kestrelConnection.TransportConnection.Features.Get(); Assert.NotNull(completeFeature); diff --git a/src/Servers/Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs b/src/Servers/Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs index 77132f4b4a..d2514f998f 100644 --- a/src/Servers/Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs +++ b/src/Servers/Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs @@ -15,6 +15,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Performance { public void ApplicationError(string connectionId, string requestId, Exception ex) { } public IDisposable BeginScope(TState state) => null; + public void ConnectionAccepted(string connectionId) { } public void ConnectionBadRequest(string connectionId, BadHttpRequestException ex) { } public void ConnectionDisconnect(string connectionId) { } public void ConnectionError(string connectionId, Exception ex) { } diff --git a/src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs b/src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs index b632cca8ec..f4b55a18a6 100644 --- a/src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs +++ b/src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs @@ -11,7 +11,7 @@ using Microsoft.Extensions.Logging; namespace Microsoft.AspNetCore.Testing { - internal class CompositeKestrelTrace: IKestrelTrace + internal class CompositeKestrelTrace : IKestrelTrace { private readonly IKestrelTrace _trace1; private readonly IKestrelTrace _trace2; @@ -33,6 +33,12 @@ namespace Microsoft.AspNetCore.Testing return _trace1.IsEnabled(logLevel) || _trace2.IsEnabled(logLevel); } + public void ConnectionAccepted(string connectionId) + { + _trace1.ConnectionAccepted(connectionId); + _trace2.ConnectionAccepted(connectionId); + } + public IDisposable BeginScope(TState state) { return _trace1.BeginScope(state);