diff --git a/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs b/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs index 66964340ff19..2cf50a6352cf 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.ConnectionQueuedStart(connection); ThreadPool.UnsafeQueueUserWorkItem(kestrelConnection, preferLocal: false); } diff --git a/src/Servers/Kestrel/Core/src/Internal/Http/Http1Connection.cs b/src/Servers/Kestrel/Core/src/Internal/Http/Http1Connection.cs index 145568af7218..4b85e26aca7c 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http/Http1Connection.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http/Http1Connection.cs @@ -76,6 +76,13 @@ public Http1Connection(HttpConnectionContext context) protected override void OnRequestProcessingEnded() { + 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. 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/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/Http2/Http2Connection.cs b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs index 3bc267e8c770..cfbc209af201 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.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 2ba223f43cbc..544013c7cd9a 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.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 3aa7d990a310..92fb441dda5f 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.RequestQueuedStop(this, AspNetCore.Http.HttpProtocol.Http3); + if (_requestHeaderParsingState == Http3Stream.RequestHeaderParsingState.Ready) { _ = ProcessRequestAsync(_application); 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/KestrelConnectionOfT.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnectionOfT.cs index 465440ee00ac..b6496f2c3944 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.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 19afb9af715c..898376d5df97 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs @@ -1,8 +1,12 @@ // 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.Net.Security; using System.Runtime.CompilerServices; +using System.Text; +using System.Threading; using Microsoft.AspNetCore.Connections; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http; @@ -13,6 +17,26 @@ 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 PollingCounter _httpRequestQueueLengthCounter; + private PollingCounter _currrentUpgradedHttpRequestsCounter; + + private long _totalConnections; + private long _currentConnections; + private long _connectionQueueLength; + private long _totalTlsHandshakes; + private long _currentTlsHandshakes; + private long _failedTlsHandshakes; + private long _httpRequestQueueLength; + private long _currentUpgradedHttpRequests; + private KestrelEventSource() { } @@ -29,6 +53,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( @@ -39,7 +66,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) @@ -55,6 +82,7 @@ private void ConnectionStart(string connectionId, [NonEvent] public void ConnectionStop(BaseConnectionContext connection) { + Interlocked.Decrement(ref _currentConnections); if (IsEnabled()) { ConnectionStop(connection.ConnectionId); @@ -62,14 +90,48 @@ 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); } + [NonEvent] + public void RequestStart(HttpProtocol httpProtocol) + { + // avoid allocating the trace identifier unless logging is enabled + if (IsEnabled()) + { + 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, string httpVersion, string path, string method) + { + WriteEvent(3, connectionId, requestId, httpVersion, path, method); + } + + [NonEvent] + public void RequestStop(HttpProtocol httpProtocol) + { + // avoid allocating the trace identifier unless logging is enabled + if (IsEnabled()) + { + RequestStop(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpProtocol.HttpVersion, httpProtocol.Path, httpProtocol.MethodText); + } + } + [MethodImpl(MethodImplOptions.NoInlining)] - [Event(5, Level = EventLevel.Verbose)] + [Event(4, Level = EventLevel.Informational)] + private void RequestStop(string connectionId, string requestId, string httpVersion, string path, string method) + { + WriteEvent(4, connectionId, requestId, httpVersion, path, method); + } + + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(5, Level = EventLevel.Informational)] public void ConnectionRejected(string connectionId) { if (IsEnabled()) @@ -79,37 +141,235 @@ public void ConnectionRejected(string connectionId) } [NonEvent] - public void RequestStart(HttpProtocol httpProtocol) + public void ConnectionQueuedStart(BaseConnectionContext connection) + { + Interlocked.Increment(ref _connectionQueueLength); + if (IsEnabled()) + { + ConnectionQueuedStart( + connection.ConnectionId, + connection.LocalEndPoint?.ToString(), + connection.RemoteEndPoint?.ToString()); + } + } + + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(6, Level = EventLevel.Informational)] + private void ConnectionQueuedStart(string connectionId, + string localEndPoint, + string remoteEndPoint) + { + WriteEvent( + 6, + connectionId, + localEndPoint, + remoteEndPoint + ); + } + + [NonEvent] + public void ConnectionQueuedStop(BaseConnectionContext connection) + { + Interlocked.Decrement(ref _connectionQueueLength); + if (IsEnabled()) + { + ConnectionQueuedStop( + connection.ConnectionId, + connection.LocalEndPoint?.ToString(), + connection.RemoteEndPoint?.ToString()); + } + } + + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(7, Level = EventLevel.Informational)] + private void ConnectionQueuedStop(string connectionId, + string localEndPoint, + string remoteEndPoint) + { + WriteEvent( + 7, + connectionId, + localEndPoint, + remoteEndPoint + ); + } + + [NonEvent] + public void TlsHandshakeStart(BaseConnectionContext connectionContext, SslServerAuthenticationOptions sslOptions) + { + Interlocked.Increment(ref _currentTlsHandshakes); + Interlocked.Increment(ref _totalTlsHandshakes); + if (IsEnabled()) + { + TlsHandshakeStart(connectionContext.ConnectionId, sslOptions.EnabledSslProtocols.ToString()); + } + } + + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(8, Level = EventLevel.Informational)] + private void TlsHandshakeStart(string connectionId, string sslProtocols) + { + WriteEvent(8, connectionId, sslProtocols); + } + + [NonEvent] + public void TlsHandshakeStop(BaseConnectionContext connectionContext, TlsConnectionFeature feature) + { + Interlocked.Decrement(ref _currentTlsHandshakes); + if (IsEnabled()) + { + // TODO: Write this without a string allocation using WriteEventData + 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.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.Error)] + public void TlsHandshakeFailed(string connectionId) { + Interlocked.Increment(ref _failedTlsHandshakes); + WriteEvent(10, connectionId); + } + + [NonEvent] + public void RequestQueuedStart(HttpProtocol httpProtocol, string httpVersion) + { + Interlocked.Increment(ref _httpRequestQueueLength); // avoid allocating the trace identifier unless logging is enabled if (IsEnabled()) { - RequestStart(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier); + RequestQueuedStart(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpVersion); } } [MethodImpl(MethodImplOptions.NoInlining)] - [Event(3, Level = EventLevel.Verbose)] - private void RequestStart(string connectionId, string requestId) + [Event(11, Level = EventLevel.Informational)] + private void RequestQueuedStart(string connectionId, string requestId, string httpVersion) { - WriteEvent(3, connectionId, requestId); + WriteEvent(11, connectionId, requestId, httpVersion); } [NonEvent] - public void RequestStop(HttpProtocol httpProtocol) + public void RequestQueuedStop(HttpProtocol httpProtocol, string httpVersion) { + Interlocked.Decrement(ref _httpRequestQueueLength); // avoid allocating the trace identifier unless logging is enabled if (IsEnabled()) { - RequestStop(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier); + RequestQueuedStop(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpVersion); + } + } + + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(12, Level = EventLevel.Informational)] + private void RequestQueuedStop(string connectionId, string requestId, string httpVersion) + { + WriteEvent(12, connectionId, requestId, httpVersion); + } + + [NonEvent] + public void RequestUpgradedStart(HttpProtocol httpProtocol) + { + Interlocked.Increment(ref _currentUpgradedHttpRequests); + if (IsEnabled()) + { + 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, string httpVersion, string path, string method) + { + WriteEvent(13, connectionId, requestId, httpVersion, path, method); + } + + [NonEvent] + public void RequestUpgradedStop(HttpProtocol httpProtocol) + { + Interlocked.Decrement(ref _currentUpgradedHttpRequests); + if (IsEnabled()) + { + RequestUpgradedStop(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpProtocol.HttpVersion, httpProtocol.Path, httpProtocol.MethodText); } } [MethodImpl(MethodImplOptions.NoInlining)] - [Event(4, Level = EventLevel.Verbose)] - private void RequestStop(string connectionId, string requestId) + [Event(14, Level = EventLevel.Informational)] + private void RequestUpgradedStop(string connectionId, string requestId, string httpVersion, string path, string method) + { + WriteEvent(14, connectionId, requestId, httpVersion, path, method); + } + + protected override void OnEventCommand(EventCommandEventArgs command) { - WriteEvent(4, connectionId, requestId); + 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("connections-per-second", this, () => _totalConnections) + { + DisplayName = "Connection Rate", + DisplayRateTimeScale = TimeSpan.FromSeconds(1) + }; + + _totalConnectionsCounter ??= new PollingCounter("total-connections", this, () => _totalConnections) + { + 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" + }; + + _connectionQueueLengthCounter ??= new PollingCounter("connection-queue-length", this, () => _connectionQueueLength) + { + DisplayName = "Connection Queue Length" + }; + + _httpRequestQueueLengthCounter ??= new PollingCounter("request-queue-length", this, () => _httpRequestQueueLength) + { + DisplayName = "Request Queue Length" + }; + + _currrentUpgradedHttpRequestsCounter ??= new PollingCounter("current-upgraded-requests", this, () => _currentUpgradedHttpRequests) + { + DisplayName = "Current Upgraded Requests (WebSockets)" + }; + } } } } 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 388d45abf53f..eef77ef82389 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; @@ -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) @@ -204,22 +205,33 @@ public async Task OnConnectionAsync(ConnectionContext context) _options.OnAuthenticate?.Invoke(context, sslOptions); + 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; } catch (IOException ex) { + KestrelEventSource.Log.TlsHandshakeFailed(context.ConnectionId); + KestrelEventSource.Log.TlsHandshakeStop(context, null); + _logger.LogDebug(1, ex, CoreStrings.AuthenticationFailed); await sslStream.DisposeAsync(); return; } catch (AuthenticationException ex) { + KestrelEventSource.Log.TlsHandshakeFailed(context.ConnectionId); + KestrelEventSource.Log.TlsHandshakeStop(context, null); + _logger.LogDebug(1, ex, CoreStrings.AuthenticationFailed); await sslStream.DisposeAsync(); @@ -238,6 +250,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