Log message when connection reaches maximum concurrent streams (#22452)

Author: JamesNK

src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs

@@ -971,7 +971,13 @@ private void StartStream()
                     throw new Http2StreamErrorException(_currentHeadersStream.StreamId, CoreStrings.Http2ErrorMissingMandatoryPseudoHeaderFields, Http2ErrorCode.PROTOCOL_ERROR);
                 }
 
-                if (_clientActiveStreamCount > _serverSettings.MaxConcurrentStreams)
+                if (_clientActiveStreamCount == _serverSettings.MaxConcurrentStreams)
+                {
+                    // Provide feedback in server logs that the client hit the number of maximum concurrent streams,
+                    // and that the client is likely waiting for existing streams to be completed before it can continue.
+                    Log.Http2MaxConcurrentStreamsReached(_context.ConnectionId);
+                }
+                else if (_clientActiveStreamCount > _serverSettings.MaxConcurrentStreams)
                 {
                     // The protocol default stream limit is infinite so the client can exceed our limit at the start of the connection.
                     // Refused streams can be retried, by which time the client must have received our settings frame with our limit information.

src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs

@@ -74,5 +74,7 @@ internal interface IKestrelTrace : ILogger
         void Http2FrameReceived(string connectionId, Http2Frame frame);
 
         void Http2FrameSending(string connectionId, Http2Frame frame);
+
+        void Http2MaxConcurrentStreamsReached(string connectionId);
     }
 }

src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs

@@ -113,6 +113,10 @@ internal class KestrelTrace : IKestrelTrace
         private static readonly Action<ILogger, string, Exception> _connectionAccepted =
             LoggerMessage.Define<string>(LogLevel.Debug, new EventId(39, nameof(ConnectionAccepted)), @"Connection id ""{ConnectionId}"" accepted.");
 
+        private static readonly Action<ILogger, string, Exception> _http2MaxConcurrentStreamsReached =
+            LoggerMessage.Define<string>(LogLevel.Debug, new EventId(40, nameof(Http2MaxConcurrentStreamsReached)),
+                @"Connection id ""{ConnectionId}"" reached the maximum number of concurrent HTTP/2 streams allowed.");
+
         protected readonly ILogger _logger;
 
         public KestrelTrace(ILogger logger)
@@ -286,6 +290,11 @@ public void Http2FrameSending(string connectionId, Http2Frame frame)
             }
         }
 
+        public void Http2MaxConcurrentStreamsReached(string connectionId)
+        {
+            _http2MaxConcurrentStreamsReached(_logger, connectionId, null);
+        }
+
         public virtual void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
             => _logger.Log(logLevel, eventId, state, exception, formatter);
 

src/Servers/Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs

@@ -55,5 +55,6 @@ public void Http2ConnectionClosing(string connectionId) { }
         public void Http2ConnectionClosed(string connectionId, int highestOpenedStreamId) { }
         public void Http2FrameReceived(string connectionId, Http2Frame frame) { }
         public void Http2FrameSending(string connectionId, Http2Frame frame) { }
+        public void Http2MaxConcurrentStreamsReached(string connectionId) { }
     }
 }

src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs

@@ -229,5 +229,11 @@ public void Http2FrameSending(string connectionId, Http2Frame frame)
             _trace1.Http2FrameSending(connectionId, frame);
             _trace2.Http2FrameSending(connectionId, frame);
         }
+
+        public void Http2MaxConcurrentStreamsReached(string connectionId)
+        {
+            _trace1.Http2MaxConcurrentStreamsReached(connectionId);
+            _trace2.Http2MaxConcurrentStreamsReached(connectionId);
+        }
     }
 }

src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2ConnectionTests.cs

@@ -28,6 +28,28 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests
 {
     public class Http2ConnectionTests : Http2TestBase
     {
+        [Fact]
+        public async Task MaxConcurrentStreamsLogging_ReachLimit_MessageLogged()
+        {
+            await InitializeConnectionAsync(_echoApplication);
+
+            _connection.ServerSettings.MaxConcurrentStreams = 2;
+
+            await StartStreamAsync(1, _browserRequestHeaders, endStream: false);
+            Assert.Equal(0, TestApplicationErrorLogger.Messages.Count(m => m.EventId.Name == "Http2MaxConcurrentStreamsReached"));
+
+            // Log message because we've reached the stream limit
+            await StartStreamAsync(3, _browserRequestHeaders, endStream: false);
+            Assert.Equal(1, TestApplicationErrorLogger.Messages.Count(m => m.EventId.Name == "Http2MaxConcurrentStreamsReached"));
+
+            // This stream will error because it exceeds max concurrent streams
+            await StartStreamAsync(5, _browserRequestHeaders, endStream: true);
+            await WaitForStreamErrorAsync(5, Http2ErrorCode.REFUSED_STREAM, CoreStrings.Http2ErrorMaxStreams);
+            Assert.Equal(1, TestApplicationErrorLogger.Messages.Count(m => m.EventId.Name == "Http2MaxConcurrentStreamsReached"));
+
+            await StopConnectionAsync(expectedLastStreamId: 5, ignoreNonGoAwayFrames: false);
+        }
+
         [Fact]
         public async Task FlowControl_NoAvailability_ResponseHeadersStillFlushed()
         {