From f3e71e980680bf9c5875e12471793f017978fc09 Mon Sep 17 00:00:00 2001 From: David Fowler Date: Fri, 8 May 2020 23:20:59 -0700 Subject: [PATCH 01/10] Added some kestrel event counters - Connection queue length - This is the amount of connections accepted and queued in the thread pool. - Connection count - The number of connections - Total connections - The total number of connections ever connected. - Connection Rate - Connections per second Contributes to #4769 --- .../Core/src/Internal/ConnectionDispatcher.cs | 1 + .../Infrastructure/KestrelConnectionOfT.cs | 2 + .../Infrastructure/KestrelEventSource.cs | 120 ++++++++++++++++-- 3 files changed, 113 insertions(+), 10 deletions(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs b/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs index 66964340ff19..62d2d843b59d 100644 --- a/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs +++ b/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs @@ -61,6 +61,7 @@ async Task AcceptConnectionsAsync() _transportConnectionManager.AddConnection(id, kestrelConnection); Log.ConnectionAccepted(connection.ConnectionId); + KestrelEventSource.Log.ConnectionQueued(connection); ThreadPool.UnsafeQueueUserWorkItem(kestrelConnection, preferLocal: false); } diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnectionOfT.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnectionOfT.cs index 465440ee00ac..6f1ac28855b0 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnectionOfT.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnectionOfT.cs @@ -40,6 +40,8 @@ internal async Task ExecuteAsync() try { + KestrelEventSource.Log.ConnectionDequeued(connectionContext); + Logger.ConnectionStart(connectionContext.ConnectionId); KestrelEventSource.Log.ConnectionStart(connectionContext); diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs index 19afb9af715c..1e053a4d0265 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs @@ -1,8 +1,10 @@ // Copyright (c) .NET Foundation. All rights reserved. // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. +using System; using System.Diagnostics.Tracing; using System.Runtime.CompilerServices; +using System.Threading; using Microsoft.AspNetCore.Connections; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http; @@ -13,6 +15,15 @@ internal sealed class KestrelEventSource : EventSource { public static readonly KestrelEventSource Log = new KestrelEventSource(); + private IncrementingPollingCounter _connectionsPerSecondCounter; + private PollingCounter _totalConnectionsCounter; + private PollingCounter _currentConnectionsCounter; + private PollingCounter _connectionQueueLengthCounter; + + private long _totalConnections; + private long _currentConnections; + private long _connectionQueueLength; + private KestrelEventSource() { } @@ -29,6 +40,9 @@ private KestrelEventSource() public void ConnectionStart(BaseConnectionContext connection) { // avoid allocating strings unless this event source is enabled + Interlocked.Increment(ref _totalConnections); + Interlocked.Increment(ref _currentConnections); + if (IsEnabled()) { ConnectionStart( @@ -55,6 +69,7 @@ private void ConnectionStart(string connectionId, [NonEvent] public void ConnectionStop(BaseConnectionContext connection) { + Interlocked.Decrement(ref _currentConnections); if (IsEnabled()) { ConnectionStop(connection.ConnectionId); @@ -68,16 +83,6 @@ private void ConnectionStop(string connectionId) WriteEvent(2, connectionId); } - [MethodImpl(MethodImplOptions.NoInlining)] - [Event(5, Level = EventLevel.Verbose)] - public void ConnectionRejected(string connectionId) - { - if (IsEnabled()) - { - WriteEvent(5, connectionId); - } - } - [NonEvent] public void RequestStart(HttpProtocol httpProtocol) { @@ -111,5 +116,100 @@ private void RequestStop(string connectionId, string requestId) { WriteEvent(4, connectionId, requestId); } + + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(5, Level = EventLevel.Verbose)] + public void ConnectionRejected(string connectionId) + { + if (IsEnabled()) + { + WriteEvent(5, connectionId); + } + } + + [NonEvent] + public void ConnectionQueued(BaseConnectionContext connection) + { + Interlocked.Increment(ref _connectionQueueLength); + if (IsEnabled()) + { + ConnectionQueued( + connection.ConnectionId, + connection.LocalEndPoint?.ToString(), + connection.RemoteEndPoint?.ToString()); + } + } + + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(6, Level = EventLevel.Verbose)] + private void ConnectionQueued(string connectionId, + string localEndPoint, + string remoteEndPoint) + { + WriteEvent( + 6, + connectionId, + localEndPoint, + remoteEndPoint + ); + } + + [NonEvent] + public void ConnectionDequeued(BaseConnectionContext connection) + { + Interlocked.Decrement(ref _connectionQueueLength); + if (IsEnabled()) + { + ConnectionDequeued( + connection.ConnectionId, + connection.LocalEndPoint?.ToString(), + connection.RemoteEndPoint?.ToString()); + } + } + + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(7, Level = EventLevel.Verbose)] + private void ConnectionDequeued(string connectionId, + string localEndPoint, + string remoteEndPoint) + { + WriteEvent( + 7, + connectionId, + localEndPoint, + remoteEndPoint + ); + } + + + protected override void OnEventCommand(EventCommandEventArgs command) + { + if (command.Command == EventCommand.Enable) + { + // This is the convention for initializing counters in the RuntimeEventSource (lazily on the first enable command). + // They aren't disabled afterwards... + + _connectionsPerSecondCounter ??= new IncrementingPollingCounter("requests-per-second", this, () => _totalConnections) + { + DisplayName = "Connection Rate", + DisplayRateTimeScale = TimeSpan.FromSeconds(1) + }; + + _totalConnectionsCounter ??= new PollingCounter("total-connections", this, () => _totalConnections) + { + DisplayName = "Total Connections", + }; + + _currentConnectionsCounter ??= new PollingCounter("current-connections", this, () => _currentConnections) + { + DisplayName = "Current Connections" + }; + + _connectionQueueLengthCounter ??= new PollingCounter("connection-queue-length", this, () => _connectionQueueLength) + { + DisplayName = "Connection Queue Length" + }; + } + } } } From 16e91a9a6291999b793e675e63a19fa269c79588 Mon Sep 17 00:00:00 2001 From: David Fowler Date: Fri, 8 May 2020 23:22:23 -0700 Subject: [PATCH 02/10] Copy pasta --- .../Core/src/Internal/Infrastructure/KestrelEventSource.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs index 1e053a4d0265..e1b32bce9fea 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs @@ -189,7 +189,7 @@ protected override void OnEventCommand(EventCommandEventArgs command) // This is the convention for initializing counters in the RuntimeEventSource (lazily on the first enable command). // They aren't disabled afterwards... - _connectionsPerSecondCounter ??= new IncrementingPollingCounter("requests-per-second", this, () => _totalConnections) + _connectionsPerSecondCounter ??= new IncrementingPollingCounter("connections-per-second", this, () => _totalConnections) { DisplayName = "Connection Rate", DisplayRateTimeScale = TimeSpan.FromSeconds(1) From ff24716561f3e2ae8ccd23045d735b3bcd9f828c Mon Sep 17 00:00:00 2001 From: David Fowler Date: Sat, 9 May 2020 00:05:43 -0700 Subject: [PATCH 03/10] Added TLS counters - Current TLS handshakes - Total TLS handshakes - Failed TLS handshakes - TLS handshake per second --- .../Infrastructure/KestrelEventSource.cs | 52 +++++++++++++++++++ .../Middleware/HttpsConnectionMiddleware.cs | 11 +++- 2 files changed, 62 insertions(+), 1 deletion(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs index e1b32bce9fea..e1a40e20ac25 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs @@ -16,13 +16,20 @@ internal sealed class KestrelEventSource : EventSource public static readonly KestrelEventSource Log = new KestrelEventSource(); private IncrementingPollingCounter _connectionsPerSecondCounter; + private IncrementingPollingCounter _tlsHandshakesPerSecondCounter; private PollingCounter _totalConnectionsCounter; private PollingCounter _currentConnectionsCounter; + private PollingCounter _totalTlsHandshakesCounter; + private PollingCounter _currentTlsHandshakesCounter; + private PollingCounter _failedTlsHandshakesCounter; private PollingCounter _connectionQueueLengthCounter; private long _totalConnections; private long _currentConnections; private long _connectionQueueLength; + private long _totalTlsHandshakes; + private long _currentTlsHandshakes; + private long _failedTlsHandshakes; private KestrelEventSource() { @@ -181,6 +188,30 @@ private void ConnectionDequeued(string connectionId, ); } + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(8, Level = EventLevel.Verbose)] + public void TlsHandshakeStart(string connectionId) + { + Interlocked.Increment(ref _currentTlsHandshakes); + Interlocked.Increment(ref _totalTlsHandshakes); + WriteEvent(8, connectionId); + } + + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(9, Level = EventLevel.Verbose)] + public void TlsHandshakeStop(string connectionId) + { + Interlocked.Decrement(ref _currentTlsHandshakes); + WriteEvent(9, connectionId); + } + + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(10, Level = EventLevel.Verbose)] + public void TlsHandshakeFailed(string connectionId) + { + Interlocked.Increment(ref _failedTlsHandshakes); + WriteEvent(10, connectionId); + } protected override void OnEventCommand(EventCommandEventArgs command) { @@ -200,6 +231,27 @@ protected override void OnEventCommand(EventCommandEventArgs command) DisplayName = "Total Connections", }; + _tlsHandshakesPerSecondCounter ??= new IncrementingPollingCounter("tls-handshakes-per-second", this, () => _totalTlsHandshakes) + { + DisplayName = "TLS Handshake Rate", + DisplayRateTimeScale = TimeSpan.FromSeconds(1) + }; + + _totalTlsHandshakesCounter ??= new PollingCounter("total-tls-handshakes", this, () => _totalTlsHandshakes) + { + DisplayName = "Total TLS Handshakes", + }; + + _currentTlsHandshakesCounter ??= new PollingCounter("current-tls-handshakes", this, () => _currentTlsHandshakes) + { + DisplayName = "Current TLS Handshakes" + }; + + _failedTlsHandshakesCounter ??= new PollingCounter("failed-tls-handshakes", this, () => _failedTlsHandshakes) + { + DisplayName = "Failed TLS Handshakes" + }; + _currentConnectionsCounter ??= new PollingCounter("current-connections", this, () => _currentConnections) { DisplayName = "Current Connections" diff --git a/src/Servers/Kestrel/Core/src/Middleware/HttpsConnectionMiddleware.cs b/src/Servers/Kestrel/Core/src/Middleware/HttpsConnectionMiddleware.cs index 388d45abf53f..e3673b8dc63e 100644 --- a/src/Servers/Kestrel/Core/src/Middleware/HttpsConnectionMiddleware.cs +++ b/src/Servers/Kestrel/Core/src/Middleware/HttpsConnectionMiddleware.cs @@ -11,13 +11,13 @@ using System.Security.Cryptography.X509Certificates; using System.Threading; using System.Threading.Tasks; -using Microsoft.AspNetCore.Certificates.Generation; using Microsoft.AspNetCore.Connections; using Microsoft.AspNetCore.Connections.Features; using Microsoft.AspNetCore.Http.Features; using Microsoft.AspNetCore.Server.Kestrel.Core; using Microsoft.AspNetCore.Server.Kestrel.Core.Features; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal; +using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; @@ -204,27 +204,36 @@ public async Task OnConnectionAsync(ConnectionContext context) _options.OnAuthenticate?.Invoke(context, sslOptions); + KestrelEventSource.Log.TlsHandshakeStart(context.ConnectionId); + await sslStream.AuthenticateAsServerAsync(sslOptions, cancellationTokeSource.Token); } catch (OperationCanceledException) { + KestrelEventSource.Log.TlsHandshakeFailed(context.ConnectionId); _logger.LogDebug(2, CoreStrings.AuthenticationTimedOut); await sslStream.DisposeAsync(); return; } catch (IOException ex) { + KestrelEventSource.Log.TlsHandshakeFailed(context.ConnectionId); _logger.LogDebug(1, ex, CoreStrings.AuthenticationFailed); await sslStream.DisposeAsync(); return; } catch (AuthenticationException ex) { + KestrelEventSource.Log.TlsHandshakeFailed(context.ConnectionId); _logger.LogDebug(1, ex, CoreStrings.AuthenticationFailed); await sslStream.DisposeAsync(); return; } + finally + { + KestrelEventSource.Log.TlsHandshakeStop(context.ConnectionId); + } } feature.ApplicationProtocol = sslStream.NegotiatedApplicationProtocol.Protocol; From dbed2e23b02af19d7cf54d498a7438d33491f098 Mon Sep 17 00:00:00 2001 From: David Fowler Date: Sat, 9 May 2020 00:41:32 -0700 Subject: [PATCH 04/10] Added HTTP/2 queue length counter --- .../src/Internal/Http2/Http2Connection.cs | 1 + .../Core/src/Internal/Http2/Http2StreamOfT.cs | 2 + .../Infrastructure/KestrelEventSource.cs | 43 +++++++++++++++++++ 3 files changed, 46 insertions(+) diff --git a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs index 3bc267e8c770..878507480322 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs @@ -1002,6 +1002,7 @@ private void StartStream() throw; } + KestrelEventSource.Log.RequestQueued(_currentHeadersStream); // Must not allow app code to block the connection handling loop. ThreadPool.UnsafeQueueUserWorkItem(_currentHeadersStream, preferLocal: false); } diff --git a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2StreamOfT.cs b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2StreamOfT.cs index 2ba223f43cbc..38689ba4f8ae 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2StreamOfT.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2StreamOfT.cs @@ -4,6 +4,7 @@ using Microsoft.AspNetCore.Hosting.Server; using Microsoft.AspNetCore.Hosting.Server.Abstractions; +using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 { @@ -19,6 +20,7 @@ public Http2Stream(IHttpApplication application, Http2StreamContext co public override void Execute() { + KestrelEventSource.Log.RequestDequeued(this); // REVIEW: Should we store this in a field for easy debugging? _ = ProcessRequestsAsync(_application); } diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs index e1a40e20ac25..a0e54e07caca 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs @@ -23,6 +23,7 @@ internal sealed class KestrelEventSource : EventSource private PollingCounter _currentTlsHandshakesCounter; private PollingCounter _failedTlsHandshakesCounter; private PollingCounter _connectionQueueLengthCounter; + private PollingCounter _http2RequestQueueLengthCounter; private long _totalConnections; private long _currentConnections; @@ -30,6 +31,7 @@ internal sealed class KestrelEventSource : EventSource private long _totalTlsHandshakes; private long _currentTlsHandshakes; private long _failedTlsHandshakes; + private long _http2RequestQueueLength; private KestrelEventSource() { @@ -213,6 +215,42 @@ public void TlsHandshakeFailed(string connectionId) WriteEvent(10, connectionId); } + [NonEvent] + public void RequestQueued(HttpProtocol httpProtocol) + { + Interlocked.Increment(ref _http2RequestQueueLength); + // avoid allocating the trace identifier unless logging is enabled + if (IsEnabled()) + { + RequestQueued(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier); + } + } + + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(11, Level = EventLevel.Verbose)] + private void RequestQueued(string connectionId, string requestId) + { + WriteEvent(11, connectionId, requestId); + } + + [NonEvent] + public void RequestDequeued(HttpProtocol httpProtocol) + { + Interlocked.Decrement(ref _http2RequestQueueLength); + // avoid allocating the trace identifier unless logging is enabled + if (IsEnabled()) + { + RequestDequeued(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier); + } + } + + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(12, Level = EventLevel.Verbose)] + private void RequestDequeued(string connectionId, string requestId) + { + WriteEvent(12, connectionId, requestId); + } + protected override void OnEventCommand(EventCommandEventArgs command) { if (command.Command == EventCommand.Enable) @@ -261,6 +299,11 @@ protected override void OnEventCommand(EventCommandEventArgs command) { DisplayName = "Connection Queue Length" }; + + _http2RequestQueueLengthCounter ??= new PollingCounter("http2-request-queue-length", this, () => _http2RequestQueueLength) + { + DisplayName = "HTTP/2 Request Queue Length" + }; } } } From 9be15e47c05a52a9af506819ec107572cd9c0692 Mon Sep 17 00:00:00 2001 From: David Fowler Date: Sat, 9 May 2020 09:30:18 -0700 Subject: [PATCH 05/10] Improve the event information - Add TLS version to handshake events - Add HTTP version to request queue events - Renamed HTTP/2 request queue length to http request queue --- .../src/Internal/Http2/Http2Connection.cs | 2 +- .../Core/src/Internal/Http2/Http2StreamOfT.cs | 2 +- .../src/Internal/Http3/Http3Connection.cs | 1 + .../Core/src/Internal/Http3/Http3StreamOfT.cs | 3 + .../Infrastructure/KestrelEventSource.cs | 64 +++++++++++++------ .../Middleware/HttpsConnectionMiddleware.cs | 14 ++-- 6 files changed, 58 insertions(+), 28 deletions(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs index 878507480322..19fc71d8f3ef 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs @@ -1002,7 +1002,7 @@ private void StartStream() throw; } - KestrelEventSource.Log.RequestQueued(_currentHeadersStream); + KestrelEventSource.Log.RequestQueued(_currentHeadersStream, AspNetCore.Http.HttpProtocol.Http2); // Must not allow app code to block the connection handling loop. ThreadPool.UnsafeQueueUserWorkItem(_currentHeadersStream, preferLocal: false); } diff --git a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2StreamOfT.cs b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2StreamOfT.cs index 38689ba4f8ae..1f773adf4c5f 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2StreamOfT.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2StreamOfT.cs @@ -20,7 +20,7 @@ public Http2Stream(IHttpApplication application, Http2StreamContext co public override void Execute() { - KestrelEventSource.Log.RequestDequeued(this); + KestrelEventSource.Log.RequestDequeued(this, AspNetCore.Http.HttpProtocol.Http2); // REVIEW: Should we store this in a field for easy debugging? _ = ProcessRequestsAsync(_application); } diff --git a/src/Servers/Kestrel/Core/src/Internal/Http3/Http3Connection.cs b/src/Servers/Kestrel/Core/src/Internal/Http3/Http3Connection.cs index 3aa7d990a310..7e98a4c3dbf6 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http3/Http3Connection.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http3/Http3Connection.cs @@ -243,6 +243,7 @@ internal async Task InnerProcessRequestsAsync(IHttpApplication application, Http3Connection conne public override void Execute() { + KestrelEventSource.Log.RequestDequeued(this, AspNetCore.Http.HttpProtocol.Http3); + if (_requestHeaderParsingState == Http3Stream.RequestHeaderParsingState.Ready) { _ = ProcessRequestAsync(_application); diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs index a0e54e07caca..03d6ab83cb98 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs @@ -3,7 +3,9 @@ using System; using System.Diagnostics.Tracing; +using System.Net.Security; using System.Runtime.CompilerServices; +using System.Text; using System.Threading; using Microsoft.AspNetCore.Connections; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http; @@ -23,7 +25,7 @@ internal sealed class KestrelEventSource : EventSource private PollingCounter _currentTlsHandshakesCounter; private PollingCounter _failedTlsHandshakesCounter; private PollingCounter _connectionQueueLengthCounter; - private PollingCounter _http2RequestQueueLengthCounter; + private PollingCounter _httpRequestQueueLengthCounter; private long _totalConnections; private long _currentConnections; @@ -31,7 +33,7 @@ internal sealed class KestrelEventSource : EventSource private long _totalTlsHandshakes; private long _currentTlsHandshakes; private long _failedTlsHandshakes; - private long _http2RequestQueueLength; + private long _httpRequestQueueLength; private KestrelEventSource() { @@ -190,21 +192,41 @@ private void ConnectionDequeued(string connectionId, ); } - [MethodImpl(MethodImplOptions.NoInlining)] - [Event(8, Level = EventLevel.Verbose)] - public void TlsHandshakeStart(string connectionId) + [NonEvent] + public void TlsHandshakeStart(BaseConnectionContext connectionContext, SslServerAuthenticationOptions sslOptions) { Interlocked.Increment(ref _currentTlsHandshakes); Interlocked.Increment(ref _totalTlsHandshakes); - WriteEvent(8, connectionId); + if (IsEnabled()) + { + TlsHandshakeStart(connectionContext.ConnectionId, sslOptions.EnabledSslProtocols.ToString()); + } } [MethodImpl(MethodImplOptions.NoInlining)] - [Event(9, Level = EventLevel.Verbose)] - public void TlsHandshakeStop(string connectionId) + [Event(8, Level = EventLevel.Verbose)] + private void TlsHandshakeStart(string connectionId, string sslProtocols) + { + WriteEvent(8, connectionId, sslProtocols); + } + + [NonEvent] + public void TlsHandshakeStop(BaseConnectionContext connectionContext, TlsConnectionFeature feature) { Interlocked.Decrement(ref _currentTlsHandshakes); - WriteEvent(9, connectionId); + if (IsEnabled()) + { + // TODO: Write this without a string allocation using WriteEventData + var applicationProtocol = feature == null ? null : Encoding.UTF8.GetString(feature.ApplicationProtocol.Span); + TlsHandshakeStop(connectionContext.ConnectionId, feature?.Protocol.ToString(), applicationProtocol); + } + } + + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(9, Level = EventLevel.Verbose)] + private void TlsHandshakeStop(string connectionId, string applicationProtocol, string sslProtocols) + { + WriteEvent(9, connectionId, sslProtocols, applicationProtocol); } [MethodImpl(MethodImplOptions.NoInlining)] @@ -216,39 +238,39 @@ public void TlsHandshakeFailed(string connectionId) } [NonEvent] - public void RequestQueued(HttpProtocol httpProtocol) + public void RequestQueued(HttpProtocol httpProtocol, string httpVersion) { - Interlocked.Increment(ref _http2RequestQueueLength); + Interlocked.Increment(ref _httpRequestQueueLength); // avoid allocating the trace identifier unless logging is enabled if (IsEnabled()) { - RequestQueued(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier); + RequestQueued(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpVersion); } } [MethodImpl(MethodImplOptions.NoInlining)] [Event(11, Level = EventLevel.Verbose)] - private void RequestQueued(string connectionId, string requestId) + private void RequestQueued(string connectionId, string requestId, string httpVersion) { - WriteEvent(11, connectionId, requestId); + WriteEvent(11, connectionId, requestId, httpVersion); } [NonEvent] - public void RequestDequeued(HttpProtocol httpProtocol) + public void RequestDequeued(HttpProtocol httpProtocol, string httpVersion) { - Interlocked.Decrement(ref _http2RequestQueueLength); + Interlocked.Decrement(ref _httpRequestQueueLength); // avoid allocating the trace identifier unless logging is enabled if (IsEnabled()) { - RequestDequeued(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier); + RequestDequeued(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpVersion); } } [MethodImpl(MethodImplOptions.NoInlining)] [Event(12, Level = EventLevel.Verbose)] - private void RequestDequeued(string connectionId, string requestId) + private void RequestDequeued(string connectionId, string requestId, string httpVersion) { - WriteEvent(12, connectionId, requestId); + WriteEvent(12, connectionId, requestId, httpVersion); } protected override void OnEventCommand(EventCommandEventArgs command) @@ -300,9 +322,9 @@ protected override void OnEventCommand(EventCommandEventArgs command) DisplayName = "Connection Queue Length" }; - _http2RequestQueueLengthCounter ??= new PollingCounter("http2-request-queue-length", this, () => _http2RequestQueueLength) + _httpRequestQueueLengthCounter ??= new PollingCounter("request-queue-length", this, () => _httpRequestQueueLength) { - DisplayName = "HTTP/2 Request Queue Length" + DisplayName = "Request Queue Length" }; } } diff --git a/src/Servers/Kestrel/Core/src/Middleware/HttpsConnectionMiddleware.cs b/src/Servers/Kestrel/Core/src/Middleware/HttpsConnectionMiddleware.cs index e3673b8dc63e..bd91037096ab 100644 --- a/src/Servers/Kestrel/Core/src/Middleware/HttpsConnectionMiddleware.cs +++ b/src/Servers/Kestrel/Core/src/Middleware/HttpsConnectionMiddleware.cs @@ -204,13 +204,15 @@ public async Task OnConnectionAsync(ConnectionContext context) _options.OnAuthenticate?.Invoke(context, sslOptions); - KestrelEventSource.Log.TlsHandshakeStart(context.ConnectionId); + KestrelEventSource.Log.TlsHandshakeStart(context, sslOptions); await sslStream.AuthenticateAsServerAsync(sslOptions, cancellationTokeSource.Token); } catch (OperationCanceledException) { KestrelEventSource.Log.TlsHandshakeFailed(context.ConnectionId); + KestrelEventSource.Log.TlsHandshakeStop(context, null); + _logger.LogDebug(2, CoreStrings.AuthenticationTimedOut); await sslStream.DisposeAsync(); return; @@ -218,6 +220,8 @@ public async Task OnConnectionAsync(ConnectionContext context) catch (IOException ex) { KestrelEventSource.Log.TlsHandshakeFailed(context.ConnectionId); + KestrelEventSource.Log.TlsHandshakeStop(context, null); + _logger.LogDebug(1, ex, CoreStrings.AuthenticationFailed); await sslStream.DisposeAsync(); return; @@ -225,15 +229,13 @@ public async Task OnConnectionAsync(ConnectionContext context) catch (AuthenticationException ex) { KestrelEventSource.Log.TlsHandshakeFailed(context.ConnectionId); + KestrelEventSource.Log.TlsHandshakeStop(context, null); + _logger.LogDebug(1, ex, CoreStrings.AuthenticationFailed); await sslStream.DisposeAsync(); return; } - finally - { - KestrelEventSource.Log.TlsHandshakeStop(context.ConnectionId); - } } feature.ApplicationProtocol = sslStream.NegotiatedApplicationProtocol.Protocol; @@ -247,6 +249,8 @@ public async Task OnConnectionAsync(ConnectionContext context) feature.KeyExchangeStrength = sslStream.KeyExchangeStrength; feature.Protocol = sslStream.SslProtocol; + KestrelEventSource.Log.TlsHandshakeStop(context, feature); + var originalTransport = context.Transport; try From cb3f353651d4a4bb4ff9f6454397a467fd24dbba Mon Sep 17 00:00:00 2001 From: David Fowler Date: Sat, 9 May 2020 09:40:41 -0700 Subject: [PATCH 06/10] Add the host name to the TLS handshake stop --- .../Core/src/Internal/Infrastructure/KestrelEventSource.cs | 6 +++--- .../Kestrel/Core/src/Internal/TlsConnectionFeature.cs | 2 ++ .../Core/src/Middleware/HttpsConnectionMiddleware.cs | 1 + 3 files changed, 6 insertions(+), 3 deletions(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs index 03d6ab83cb98..29eb4b2d5fa0 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs @@ -218,15 +218,15 @@ public void TlsHandshakeStop(BaseConnectionContext connectionContext, TlsConnect { // TODO: Write this without a string allocation using WriteEventData var applicationProtocol = feature == null ? null : Encoding.UTF8.GetString(feature.ApplicationProtocol.Span); - TlsHandshakeStop(connectionContext.ConnectionId, feature?.Protocol.ToString(), applicationProtocol); + TlsHandshakeStop(connectionContext.ConnectionId, feature?.Protocol.ToString(), applicationProtocol, feature?.HostName); } } [MethodImpl(MethodImplOptions.NoInlining)] [Event(9, Level = EventLevel.Verbose)] - private void TlsHandshakeStop(string connectionId, string applicationProtocol, string sslProtocols) + private void TlsHandshakeStop(string connectionId, string applicationProtocol, string sslProtocols, string hostName) { - WriteEvent(9, connectionId, sslProtocols, applicationProtocol); + WriteEvent(9, connectionId, sslProtocols, applicationProtocol, hostName); } [MethodImpl(MethodImplOptions.NoInlining)] diff --git a/src/Servers/Kestrel/Core/src/Internal/TlsConnectionFeature.cs b/src/Servers/Kestrel/Core/src/Internal/TlsConnectionFeature.cs index 3db33011d7f2..64a5027f1582 100644 --- a/src/Servers/Kestrel/Core/src/Internal/TlsConnectionFeature.cs +++ b/src/Servers/Kestrel/Core/src/Internal/TlsConnectionFeature.cs @@ -16,6 +16,8 @@ internal class TlsConnectionFeature : ITlsConnectionFeature, ITlsApplicationProt { public X509Certificate2 ClientCertificate { get; set; } + public string HostName { get; set; } + public ReadOnlyMemory ApplicationProtocol { get; set; } public SslProtocols Protocol { get; set; } diff --git a/src/Servers/Kestrel/Core/src/Middleware/HttpsConnectionMiddleware.cs b/src/Servers/Kestrel/Core/src/Middleware/HttpsConnectionMiddleware.cs index bd91037096ab..eef77ef82389 100644 --- a/src/Servers/Kestrel/Core/src/Middleware/HttpsConnectionMiddleware.cs +++ b/src/Servers/Kestrel/Core/src/Middleware/HttpsConnectionMiddleware.cs @@ -169,6 +169,7 @@ public async Task OnConnectionAsync(ConnectionContext context) { selector = (sender, name) => { + feature.HostName = name; context.Features.Set(sslStream); var cert = _serverCertificateSelector(context, name); if (cert != null) From 537878477a7a0ddf982970b39a1002d63096c61c Mon Sep 17 00:00:00 2001 From: David Fowler Date: Sat, 9 May 2020 10:07:26 -0700 Subject: [PATCH 07/10] Clean up - Event sources don't like null values - Make the level information for most events --- .../Infrastructure/KestrelEventSource.cs | 32 ++++++++++--------- 1 file changed, 17 insertions(+), 15 deletions(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs index 29eb4b2d5fa0..d546732733b4 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs @@ -64,7 +64,7 @@ public void ConnectionStart(BaseConnectionContext connection) } [MethodImpl(MethodImplOptions.NoInlining)] - [Event(1, Level = EventLevel.Verbose)] + [Event(1, Level = EventLevel.Informational)] private void ConnectionStart(string connectionId, string localEndPoint, string remoteEndPoint) @@ -88,7 +88,7 @@ public void ConnectionStop(BaseConnectionContext connection) } [MethodImpl(MethodImplOptions.NoInlining)] - [Event(2, Level = EventLevel.Verbose)] + [Event(2, Level = EventLevel.Informational)] private void ConnectionStop(string connectionId) { WriteEvent(2, connectionId); @@ -105,7 +105,7 @@ public void RequestStart(HttpProtocol httpProtocol) } [MethodImpl(MethodImplOptions.NoInlining)] - [Event(3, Level = EventLevel.Verbose)] + [Event(3, Level = EventLevel.Informational)] private void RequestStart(string connectionId, string requestId) { WriteEvent(3, connectionId, requestId); @@ -122,14 +122,14 @@ public void RequestStop(HttpProtocol httpProtocol) } [MethodImpl(MethodImplOptions.NoInlining)] - [Event(4, Level = EventLevel.Verbose)] + [Event(4, Level = EventLevel.Informational)] private void RequestStop(string connectionId, string requestId) { WriteEvent(4, connectionId, requestId); } [MethodImpl(MethodImplOptions.NoInlining)] - [Event(5, Level = EventLevel.Verbose)] + [Event(5, Level = EventLevel.Informational)] public void ConnectionRejected(string connectionId) { if (IsEnabled()) @@ -152,7 +152,7 @@ public void ConnectionQueued(BaseConnectionContext connection) } [MethodImpl(MethodImplOptions.NoInlining)] - [Event(6, Level = EventLevel.Verbose)] + [Event(6, Level = EventLevel.Informational)] private void ConnectionQueued(string connectionId, string localEndPoint, string remoteEndPoint) @@ -179,7 +179,7 @@ public void ConnectionDequeued(BaseConnectionContext connection) } [MethodImpl(MethodImplOptions.NoInlining)] - [Event(7, Level = EventLevel.Verbose)] + [Event(7, Level = EventLevel.Informational)] private void ConnectionDequeued(string connectionId, string localEndPoint, string remoteEndPoint) @@ -204,7 +204,7 @@ public void TlsHandshakeStart(BaseConnectionContext connectionContext, SslServer } [MethodImpl(MethodImplOptions.NoInlining)] - [Event(8, Level = EventLevel.Verbose)] + [Event(8, Level = EventLevel.Informational)] private void TlsHandshakeStart(string connectionId, string sslProtocols) { WriteEvent(8, connectionId, sslProtocols); @@ -217,20 +217,22 @@ public void TlsHandshakeStop(BaseConnectionContext connectionContext, TlsConnect if (IsEnabled()) { // TODO: Write this without a string allocation using WriteEventData - var applicationProtocol = feature == null ? null : Encoding.UTF8.GetString(feature.ApplicationProtocol.Span); - TlsHandshakeStop(connectionContext.ConnectionId, feature?.Protocol.ToString(), applicationProtocol, feature?.HostName); + var applicationProtocol = feature == null ? string.Empty : Encoding.UTF8.GetString(feature.ApplicationProtocol.Span); + var sslProtocols = feature?.Protocol.ToString() ?? string.Empty; + var hostName = feature?.HostName ?? string.Empty; + TlsHandshakeStop(connectionContext.ConnectionId, sslProtocols, applicationProtocol, hostName); } } [MethodImpl(MethodImplOptions.NoInlining)] - [Event(9, Level = EventLevel.Verbose)] - private void TlsHandshakeStop(string connectionId, string applicationProtocol, string sslProtocols, string hostName) + [Event(9, Level = EventLevel.Informational)] + private void TlsHandshakeStop(string connectionId, string sslProtocols, string applicationProtocol, string hostName) { WriteEvent(9, connectionId, sslProtocols, applicationProtocol, hostName); } [MethodImpl(MethodImplOptions.NoInlining)] - [Event(10, Level = EventLevel.Verbose)] + [Event(10, Level = EventLevel.Error)] public void TlsHandshakeFailed(string connectionId) { Interlocked.Increment(ref _failedTlsHandshakes); @@ -249,7 +251,7 @@ public void RequestQueued(HttpProtocol httpProtocol, string httpVersion) } [MethodImpl(MethodImplOptions.NoInlining)] - [Event(11, Level = EventLevel.Verbose)] + [Event(11, Level = EventLevel.Informational)] private void RequestQueued(string connectionId, string requestId, string httpVersion) { WriteEvent(11, connectionId, requestId, httpVersion); @@ -267,7 +269,7 @@ public void RequestDequeued(HttpProtocol httpProtocol, string httpVersion) } [MethodImpl(MethodImplOptions.NoInlining)] - [Event(12, Level = EventLevel.Verbose)] + [Event(12, Level = EventLevel.Informational)] private void RequestDequeued(string connectionId, string requestId, string httpVersion) { WriteEvent(12, connectionId, requestId, httpVersion); From 01376ec23e7ecac2a5c2be0c433f4e1f3442d8a6 Mon Sep 17 00:00:00 2001 From: David Fowler Date: Sat, 9 May 2020 10:52:52 -0700 Subject: [PATCH 08/10] Added counter for upgraded connections --- .../Core/src/Internal/Http/Http1Connection.cs | 7 ++++ .../Http/HttpProtocol.FeatureCollection.cs | 2 + .../Core/src/Internal/HttpConnection.cs | 7 ---- .../Infrastructure/KestrelEventSource.cs | 41 +++++++++++++++++++ 4 files changed, 50 insertions(+), 7 deletions(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/Http/Http1Connection.cs b/src/Servers/Kestrel/Core/src/Internal/Http/Http1Connection.cs index 145568af7218..a5d573aa2e94 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http/Http1Connection.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http/Http1Connection.cs @@ -82,6 +82,13 @@ protected override void OnRequestProcessingEnded() Reset(); _http1Output.Dispose(); + + if (IsUpgraded) + { + KestrelEventSource.Log.RequestUpgradedStop(this); + + ServiceContext.ConnectionManager.UpgradedConnectionCount.ReleaseOne(); + } } public void OnInputOrOutputCompleted() diff --git a/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.FeatureCollection.cs b/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.FeatureCollection.cs index 8841be09fa35..1f2e1adfa294 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.FeatureCollection.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.FeatureCollection.cs @@ -293,6 +293,8 @@ async Task IHttpUpgradeFeature.UpgradeAsync() IsUpgraded = true; + KestrelEventSource.Log.RequestUpgradedStart(this); + ConnectionFeatures.Get()?.ReleaseConnection(); StatusCode = StatusCodes.Status101SwitchingProtocols; diff --git a/src/Servers/Kestrel/Core/src/Internal/HttpConnection.cs b/src/Servers/Kestrel/Core/src/Internal/HttpConnection.cs index a00f6002a485..46b70c3942b7 100644 --- a/src/Servers/Kestrel/Core/src/Internal/HttpConnection.cs +++ b/src/Servers/Kestrel/Core/src/Internal/HttpConnection.cs @@ -107,13 +107,6 @@ public async Task ProcessRequestsAsync(IHttpApplication http { Log.LogCritical(0, ex, $"Unexpected exception in {nameof(HttpConnection)}.{nameof(ProcessRequestsAsync)}."); } - finally - { - if (_http1Connection?.IsUpgraded == true) - { - _context.ServiceContext.ConnectionManager.UpgradedConnectionCount.ReleaseOne(); - } - } } // For testing only diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs index d546732733b4..c42ba79e9a8c 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs @@ -26,6 +26,7 @@ internal sealed class KestrelEventSource : EventSource private PollingCounter _failedTlsHandshakesCounter; private PollingCounter _connectionQueueLengthCounter; private PollingCounter _httpRequestQueueLengthCounter; + private PollingCounter _currrentUpgradedHttpRequestsCounter; private long _totalConnections; private long _currentConnections; @@ -34,6 +35,7 @@ internal sealed class KestrelEventSource : EventSource private long _currentTlsHandshakes; private long _failedTlsHandshakes; private long _httpRequestQueueLength; + private long _currentUpgradedHttpRequests; private KestrelEventSource() { @@ -275,6 +277,40 @@ private void RequestDequeued(string connectionId, string requestId, string httpV WriteEvent(12, connectionId, requestId, httpVersion); } + [NonEvent] + public void RequestUpgradedStart(HttpProtocol httpProtocol) + { + Interlocked.Increment(ref _currentUpgradedHttpRequests); + if (IsEnabled()) + { + RequestUpgradedStart(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier); + } + } + + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(13, Level = EventLevel.Informational)] + private void RequestUpgradedStart(string connectionId, string requestId) + { + WriteEvent(13, connectionId, requestId); + } + + [NonEvent] + public void RequestUpgradedStop(HttpProtocol httpProtocol) + { + Interlocked.Decrement(ref _currentUpgradedHttpRequests); + if (IsEnabled()) + { + RequestUpgradedStop(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier); + } + } + + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(14, Level = EventLevel.Informational)] + private void RequestUpgradedStop(string connectionId, string requestId) + { + WriteEvent(14, connectionId, requestId); + } + protected override void OnEventCommand(EventCommandEventArgs command) { if (command.Command == EventCommand.Enable) @@ -328,6 +364,11 @@ protected override void OnEventCommand(EventCommandEventArgs command) { DisplayName = "Request Queue Length" }; + + _currrentUpgradedHttpRequestsCounter ??= new PollingCounter("current-upgraded-requests", this, () => _currentUpgradedHttpRequests) + { + DisplayName = "Current Upgraded Requests (WebSockets)" + }; } } } From a52b20c14a429d5e8b0672651cac04de12d67820 Mon Sep 17 00:00:00 2001 From: David Fowler Date: Sat, 9 May 2020 11:27:46 -0700 Subject: [PATCH 09/10] More tweaks - Add more data to request events --- .../Core/src/Internal/Http/Http1Connection.cs | 14 +++++------ .../Core/src/Internal/Http/HttpProtocol.cs | 1 + .../Infrastructure/KestrelEventSource.cs | 24 +++++++++---------- 3 files changed, 20 insertions(+), 19 deletions(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/Http/Http1Connection.cs b/src/Servers/Kestrel/Core/src/Internal/Http/Http1Connection.cs index a5d573aa2e94..4b85e26aca7c 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http/Http1Connection.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http/Http1Connection.cs @@ -76,19 +76,19 @@ public Http1Connection(HttpConnectionContext context) protected override void OnRequestProcessingEnded() { - TimeoutControl.StartDrainTimeout(MinResponseDataRate, ServerOptions.Limits.MaxResponseBufferSize); - - // Prevent RequestAborted from firing. Free up unneeded feature references. - Reset(); - - _http1Output.Dispose(); - if (IsUpgraded) { KestrelEventSource.Log.RequestUpgradedStop(this); ServiceContext.ConnectionManager.UpgradedConnectionCount.ReleaseOne(); } + + TimeoutControl.StartDrainTimeout(MinResponseDataRate, ServerOptions.Limits.MaxResponseBufferSize); + + // Prevent RequestAborted from firing. Free up unneeded feature references. + Reset(); + + _http1Output.Dispose(); } public void OnInputOrOutputCompleted() diff --git a/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs b/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs index 9a38dadf44cd..acc5ff485b66 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs @@ -136,6 +136,7 @@ public string TraceIdentifier public int LocalPort { get; set; } public string Scheme { get; set; } public HttpMethod Method { get; set; } + public string MethodText => ((IHttpRequestFeature)this).Method; public string PathBase { get; set; } public string Path { get; set; } diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs index c42ba79e9a8c..269b2a6f6b93 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs @@ -102,15 +102,15 @@ public void RequestStart(HttpProtocol httpProtocol) // avoid allocating the trace identifier unless logging is enabled if (IsEnabled()) { - RequestStart(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier); + RequestStart(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpProtocol.HttpVersion, httpProtocol.Path, httpProtocol.MethodText); } } [MethodImpl(MethodImplOptions.NoInlining)] [Event(3, Level = EventLevel.Informational)] - private void RequestStart(string connectionId, string requestId) + private void RequestStart(string connectionId, string requestId, string httpVersion, string path, string method) { - WriteEvent(3, connectionId, requestId); + WriteEvent(3, connectionId, requestId, httpVersion, path, method); } [NonEvent] @@ -119,15 +119,15 @@ public void RequestStop(HttpProtocol httpProtocol) // avoid allocating the trace identifier unless logging is enabled if (IsEnabled()) { - RequestStop(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier); + RequestStop(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpProtocol.HttpVersion, httpProtocol.Path, httpProtocol.MethodText); } } [MethodImpl(MethodImplOptions.NoInlining)] [Event(4, Level = EventLevel.Informational)] - private void RequestStop(string connectionId, string requestId) + private void RequestStop(string connectionId, string requestId, string httpVersion, string path, string method) { - WriteEvent(4, connectionId, requestId); + WriteEvent(4, connectionId, requestId, httpVersion, path, method); } [MethodImpl(MethodImplOptions.NoInlining)] @@ -283,15 +283,15 @@ public void RequestUpgradedStart(HttpProtocol httpProtocol) Interlocked.Increment(ref _currentUpgradedHttpRequests); if (IsEnabled()) { - RequestUpgradedStart(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier); + RequestUpgradedStart(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpProtocol.HttpVersion, httpProtocol.Path, httpProtocol.MethodText); } } [MethodImpl(MethodImplOptions.NoInlining)] [Event(13, Level = EventLevel.Informational)] - private void RequestUpgradedStart(string connectionId, string requestId) + private void RequestUpgradedStart(string connectionId, string requestId, string httpVersion, string path, string method) { - WriteEvent(13, connectionId, requestId); + WriteEvent(13, connectionId, requestId, httpVersion, path, method); } [NonEvent] @@ -300,15 +300,15 @@ public void RequestUpgradedStop(HttpProtocol httpProtocol) Interlocked.Decrement(ref _currentUpgradedHttpRequests); if (IsEnabled()) { - RequestUpgradedStop(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier); + RequestUpgradedStop(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpProtocol.HttpVersion, httpProtocol.Path, httpProtocol.MethodText); } } [MethodImpl(MethodImplOptions.NoInlining)] [Event(14, Level = EventLevel.Informational)] - private void RequestUpgradedStop(string connectionId, string requestId) + private void RequestUpgradedStop(string connectionId, string requestId, string httpVersion, string path, string method) { - WriteEvent(14, connectionId, requestId); + WriteEvent(14, connectionId, requestId, httpVersion, path, method); } protected override void OnEventCommand(EventCommandEventArgs command) From 980d7509f869edfa62d2f7aa551c3ff65c258258 Mon Sep 17 00:00:00 2001 From: David Fowler Date: Mon, 11 May 2020 22:46:13 -0700 Subject: [PATCH 10/10] PR feedback --- .../Core/src/Internal/ConnectionDispatcher.cs | 2 +- .../src/Internal/Http2/Http2Connection.cs | 2 +- .../Core/src/Internal/Http2/Http2StreamOfT.cs | 2 +- .../src/Internal/Http3/Http3Connection.cs | 2 +- .../Core/src/Internal/Http3/Http3StreamOfT.cs | 2 +- .../Infrastructure/KestrelConnectionOfT.cs | 2 +- .../Infrastructure/KestrelEventSource.cs | 24 +++++++++---------- 7 files changed, 18 insertions(+), 18 deletions(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs b/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs index 62d2d843b59d..2cf50a6352cf 100644 --- a/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs +++ b/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs @@ -61,7 +61,7 @@ async Task AcceptConnectionsAsync() _transportConnectionManager.AddConnection(id, kestrelConnection); Log.ConnectionAccepted(connection.ConnectionId); - KestrelEventSource.Log.ConnectionQueued(connection); + KestrelEventSource.Log.ConnectionQueuedStart(connection); ThreadPool.UnsafeQueueUserWorkItem(kestrelConnection, preferLocal: false); } diff --git a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs index 19fc71d8f3ef..cfbc209af201 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs @@ -1002,7 +1002,7 @@ private void StartStream() throw; } - KestrelEventSource.Log.RequestQueued(_currentHeadersStream, AspNetCore.Http.HttpProtocol.Http2); + KestrelEventSource.Log.RequestQueuedStart(_currentHeadersStream, AspNetCore.Http.HttpProtocol.Http2); // Must not allow app code to block the connection handling loop. ThreadPool.UnsafeQueueUserWorkItem(_currentHeadersStream, preferLocal: false); } diff --git a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2StreamOfT.cs b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2StreamOfT.cs index 1f773adf4c5f..544013c7cd9a 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2StreamOfT.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2StreamOfT.cs @@ -20,7 +20,7 @@ public Http2Stream(IHttpApplication application, Http2StreamContext co public override void Execute() { - KestrelEventSource.Log.RequestDequeued(this, AspNetCore.Http.HttpProtocol.Http2); + KestrelEventSource.Log.RequestQueuedStop(this, AspNetCore.Http.HttpProtocol.Http2); // REVIEW: Should we store this in a field for easy debugging? _ = ProcessRequestsAsync(_application); } diff --git a/src/Servers/Kestrel/Core/src/Internal/Http3/Http3Connection.cs b/src/Servers/Kestrel/Core/src/Internal/Http3/Http3Connection.cs index 7e98a4c3dbf6..92fb441dda5f 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http3/Http3Connection.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http3/Http3Connection.cs @@ -243,7 +243,7 @@ internal async Task InnerProcessRequestsAsync(IHttpApplication application, Http3Connection conne public override void Execute() { - KestrelEventSource.Log.RequestDequeued(this, AspNetCore.Http.HttpProtocol.Http3); + KestrelEventSource.Log.RequestQueuedStop(this, AspNetCore.Http.HttpProtocol.Http3); if (_requestHeaderParsingState == Http3Stream.RequestHeaderParsingState.Ready) { diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnectionOfT.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnectionOfT.cs index 6f1ac28855b0..b6496f2c3944 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnectionOfT.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnectionOfT.cs @@ -40,7 +40,7 @@ internal async Task ExecuteAsync() try { - KestrelEventSource.Log.ConnectionDequeued(connectionContext); + KestrelEventSource.Log.ConnectionQueuedStop(connectionContext); Logger.ConnectionStart(connectionContext.ConnectionId); KestrelEventSource.Log.ConnectionStart(connectionContext); diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs index 269b2a6f6b93..898376d5df97 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs @@ -141,12 +141,12 @@ public void ConnectionRejected(string connectionId) } [NonEvent] - public void ConnectionQueued(BaseConnectionContext connection) + public void ConnectionQueuedStart(BaseConnectionContext connection) { Interlocked.Increment(ref _connectionQueueLength); if (IsEnabled()) { - ConnectionQueued( + ConnectionQueuedStart( connection.ConnectionId, connection.LocalEndPoint?.ToString(), connection.RemoteEndPoint?.ToString()); @@ -155,7 +155,7 @@ public void ConnectionQueued(BaseConnectionContext connection) [MethodImpl(MethodImplOptions.NoInlining)] [Event(6, Level = EventLevel.Informational)] - private void ConnectionQueued(string connectionId, + private void ConnectionQueuedStart(string connectionId, string localEndPoint, string remoteEndPoint) { @@ -168,12 +168,12 @@ private void ConnectionQueued(string connectionId, } [NonEvent] - public void ConnectionDequeued(BaseConnectionContext connection) + public void ConnectionQueuedStop(BaseConnectionContext connection) { Interlocked.Decrement(ref _connectionQueueLength); if (IsEnabled()) { - ConnectionDequeued( + ConnectionQueuedStop( connection.ConnectionId, connection.LocalEndPoint?.ToString(), connection.RemoteEndPoint?.ToString()); @@ -182,7 +182,7 @@ public void ConnectionDequeued(BaseConnectionContext connection) [MethodImpl(MethodImplOptions.NoInlining)] [Event(7, Level = EventLevel.Informational)] - private void ConnectionDequeued(string connectionId, + private void ConnectionQueuedStop(string connectionId, string localEndPoint, string remoteEndPoint) { @@ -242,37 +242,37 @@ public void TlsHandshakeFailed(string connectionId) } [NonEvent] - public void RequestQueued(HttpProtocol httpProtocol, string httpVersion) + public void RequestQueuedStart(HttpProtocol httpProtocol, string httpVersion) { Interlocked.Increment(ref _httpRequestQueueLength); // avoid allocating the trace identifier unless logging is enabled if (IsEnabled()) { - RequestQueued(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpVersion); + RequestQueuedStart(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpVersion); } } [MethodImpl(MethodImplOptions.NoInlining)] [Event(11, Level = EventLevel.Informational)] - private void RequestQueued(string connectionId, string requestId, string httpVersion) + private void RequestQueuedStart(string connectionId, string requestId, string httpVersion) { WriteEvent(11, connectionId, requestId, httpVersion); } [NonEvent] - public void RequestDequeued(HttpProtocol httpProtocol, string httpVersion) + public void RequestQueuedStop(HttpProtocol httpProtocol, string httpVersion) { Interlocked.Decrement(ref _httpRequestQueueLength); // avoid allocating the trace identifier unless logging is enabled if (IsEnabled()) { - RequestDequeued(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpVersion); + RequestQueuedStop(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpVersion); } } [MethodImpl(MethodImplOptions.NoInlining)] [Event(12, Level = EventLevel.Informational)] - private void RequestDequeued(string connectionId, string requestId, string httpVersion) + private void RequestQueuedStop(string connectionId, string requestId, string httpVersion) { WriteEvent(12, connectionId, requestId, httpVersion); }