Track indicators of excessive stream resets

If the server has to send a lot of ENHANCE_YOUR_CALM messages or the output control flow queue is very large, there are probably a larger than expected number of client-initiated stream resets.

Author: amcasey

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

@@ -46,6 +46,18 @@ internal sealed partial class Http2Connection : IHttp2StreamLifetimeHandler, IHt
     private const int MaxStreamPoolSize = 100;
     private const long StreamPoolExpiryTicks = TimeSpan.TicksPerSecond * 5;
 
+    private const string EnhanceYourCalmMaximumCountProperty = "Microsoft.AspNetCore.Server.Kestrel.Http2.EnhanceYourCalmCount";
+
+    private static readonly int _enhanceYourCalmMaximumCount = AppContext.GetData(EnhanceYourCalmMaximumCountProperty) is int eycMaxCount
+        ? eycMaxCount
+        : 10;
+
+    // Accumulate _enhanceYourCalmCount over the course of EnhanceYourCalmTickWindowCount ticks.
+    // This should make bursts less likely to trigger disconnects.
+    private const int EnhanceYourCalmTickWindowCount = 5;
+
+    private static bool IsEnhanceYourCalmEnabled => _enhanceYourCalmMaximumCount > 0;
+
     private readonly HttpConnectionContext _context;
     private readonly Http2FrameWriter _frameWriter;
     private readonly Pipe _input;
@@ -74,6 +86,9 @@ internal sealed partial class Http2Connection : IHttp2StreamLifetimeHandler, IHt
     private int _clientActiveStreamCount;
     private int _serverActiveStreamCount;
 
+    private int _enhanceYourCalmCount;
+    private int _tickCount;
+
     // The following are the only fields that can be modified outside of the ProcessRequestsAsync loop.
     private readonly ConcurrentQueue<Http2Stream> _completedStreams = new ConcurrentQueue<Http2Stream>();
     private readonly StreamCloseAwaitable _streamCompletionAwaitable = new StreamCloseAwaitable();
@@ -361,13 +376,20 @@ public async Task ProcessRequestsAsync<TContext>(IHttpApplication<TContext> appl
                     stream.Abort(new IOException(CoreStrings.Http2StreamAborted, connectionError));
                 }
 
-                // Use the server _serverActiveStreamCount to drain all requests on the server side.
-                // Can't use _clientActiveStreamCount now as we now decrement that count earlier/
-                // Can't use _streams.Count as we wait for RST/END_STREAM before removing the stream from the dictionary
-                while (_serverActiveStreamCount > 0)
+                // For some reason, this loop doesn't terminate when we're trying to abort.
+                // Since we're making a narrow fix for a patch, we'll bypass it in such scenarios.
+                // TODO: This is probably a bug - something in here should probably detect aborted
+                // connections and short-circuit.
+                if (!IsEnhanceYourCalmEnabled || error is not Http2ConnectionErrorException)
                 {
-                    await _streamCompletionAwaitable;
-                    UpdateCompletedStreams();
+                    // Use the server _serverActiveStreamCount to drain all requests on the server side.
+                    // Can't use _clientActiveStreamCount now as we now decrement that count earlier/
+                    // Can't use _streams.Count as we wait for RST/END_STREAM before removing the stream from the dictionary
+                    while (_serverActiveStreamCount > 0)
+                    {
+                        await _streamCompletionAwaitable;
+                        UpdateCompletedStreams();
+                    }
                 }
 
                 while (StreamPool.TryPop(out var pooledStream))
@@ -1170,6 +1192,20 @@ private void StartStream()
                 // Server is getting hit hard with connection resets.
                 // Tell client to calm down.
                 // TODO consider making when to send ENHANCE_YOUR_CALM configurable?
+
+                if (IsEnhanceYourCalmEnabled && Interlocked.Increment(ref _enhanceYourCalmCount) > EnhanceYourCalmTickWindowCount * _enhanceYourCalmMaximumCount)
+                {
+                    Log.Http2TooManyEnhanceYourCalms(_context.ConnectionId, _enhanceYourCalmMaximumCount);
+
+                    // Now that we've logged a useful message, we can put vague text in the exception
+                    // messages in case they somehow make it back to the client (not expected)
+
+                    // This will close the socket - we want to do that right away
+                    Abort(new ConnectionAbortedException(CoreStrings.Http2ConnectionFaulted));
+                    // Throwing an exception as well will help us clean up on our end more quickly by (e.g.) skipping processing of already-buffered input
+                    throw new Http2ConnectionErrorException(CoreStrings.Http2ConnectionFaulted, Http2ErrorCode.ENHANCE_YOUR_CALM);
+                }
+
                 throw new Http2StreamErrorException(_currentHeadersStream.StreamId, CoreStrings.Http2TellClientToCalmDown, Http2ErrorCode.ENHANCE_YOUR_CALM);
             }
         }
@@ -1241,6 +1277,10 @@ private void AbortStream(int streamId, IOException error)
     void IRequestProcessor.Tick(DateTimeOffset now)
     {
         Input.CancelPendingRead();
+        if (IsEnhanceYourCalmEnabled && ++_tickCount % EnhanceYourCalmTickWindowCount == 0)
+        {
+            Interlocked.Exchange(ref _enhanceYourCalmCount, 0);
+        }
     }
 
     void IHttp2StreamLifetimeHandler.OnStreamCompleted(Http2Stream stream)

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

@@ -20,6 +20,29 @@ internal sealed class Http2FrameWriter
     // This uses C# compiler's ability to refer to static data directly. For more information see https://vcsjones.dev/2019/02/01/csharp-readonly-span-bytes-static
     private static ReadOnlySpan<byte> ContinueBytes => new byte[] { 0x08, 0x03, (byte)'1', (byte)'0', (byte)'0' };
 
+    private const string MaximumFlowControlQueueSizeProperty = "Microsoft.AspNetCore.Server.Kestrel.Http2.MaxConnectionFlowControlQueueSize";
+
+    private static readonly int? ConfiguredMaximumFlowControlQueueSize = GetConfiguredMaximumFlowControlQueueSize();
+
+    private static int? GetConfiguredMaximumFlowControlQueueSize()
+    {
+        var data = AppContext.GetData(MaximumFlowControlQueueSizeProperty);
+
+        if (data is int count)
+        {
+            return count;
+        }
+
+        if (data is string countStr && int.TryParse(countStr, out var parsed))
+        {
+            return parsed;
+        }
+
+        return null;
+    }
+
+    private readonly int _maximumFlowControlQueueSize;
+
     private readonly object _writeLock = new object();
     private readonly Http2Frame _outgoingFrame;
     private readonly Http2HeadersEnumerator _headersEnumerator = new Http2HeadersEnumerator();
@@ -79,6 +102,16 @@ public Http2FrameWriter(
 
         _hpackEncoder = new DynamicHPackEncoder(serviceContext.ServerOptions.AllowResponseHeaderCompression);
 
+        _maximumFlowControlQueueSize = ConfiguredMaximumFlowControlQueueSize is null
+            ? 4 * maxStreamsPerConnection
+            : (int)ConfiguredMaximumFlowControlQueueSize;
+
+        if (_maximumFlowControlQueueSize < maxStreamsPerConnection)
+        {
+            _log.Http2FlowControlQueueMaximumTooLow(_connectionContext.ConnectionId, maxStreamsPerConnection, _maximumFlowControlQueueSize);
+            _maximumFlowControlQueueSize = maxStreamsPerConnection;
+        }
+
         // This is bounded by the maximum number of concurrent Http2Streams per Http2Connection.
         // This isn't the same as SETTINGS_MAX_CONCURRENT_STREAMS, but typically double (with a floor of 100)
         // which is the max number of Http2Streams that can end up in the Http2Connection._streams dictionary.
@@ -101,7 +134,8 @@ public void Schedule(Http2OutputProducer producer)
     {
         if (!_channel.Writer.TryWrite(producer))
         {
-            // It should not be possible to exceed the bound of the channel.
+            // This can happen if a client resets streams faster than we can clear them out - we end up with a backlog
+            // exceeding the channel size.  Disconnecting seems appropriate in this case.
             var ex = new ConnectionAbortedException("HTTP/2 connection exceeded the output operations maximum queue size.");
             _log.Http2QueueOperationsExceeded(_connectionId, ex);
             _http2Connection.Abort(ex);
@@ -304,7 +338,7 @@ private bool TryQueueProducerForConnectionWindowUpdate(long actual, Http2OutputP
                 }
                 else
                 {
-                    _waitingForMoreConnectionWindow.Enqueue(producer);
+                    EnqueueWaitingForMoreConnectionWindow(producer);
                 }
 
                 return true;
@@ -898,7 +932,7 @@ private void AbortConnectionFlowControl()
                 _lastWindowConsumer = null;
 
                 // Put the consumer of the connection window last
-                _waitingForMoreConnectionWindow.Enqueue(producer);
+                EnqueueWaitingForMoreConnectionWindow(producer);
             }
 
             while (_waitingForMoreConnectionWindow.TryDequeue(out producer))
@@ -927,7 +961,7 @@ public bool TryUpdateConnectionWindow(int bytes)
                 _lastWindowConsumer = null;
 
                 // Put the consumer of the connection window last
-                _waitingForMoreConnectionWindow.Enqueue(producer);
+                EnqueueWaitingForMoreConnectionWindow(producer);
             }
 
             while (_waitingForMoreConnectionWindow.TryDequeue(out producer))
@@ -937,4 +971,16 @@ public bool TryUpdateConnectionWindow(int bytes)
         }
         return true;
     }
+
+    private void EnqueueWaitingForMoreConnectionWindow(Http2OutputProducer producer)
+    {
+        _waitingForMoreConnectionWindow.Enqueue(producer);
+        // This is re-entrant because abort will cause a final enqueue.
+        // Easier to check for that condition than to make each enqueuer reason about what to call.
+        if (!_aborted && _maximumFlowControlQueueSize > 0 && _waitingForMoreConnectionWindow.Count > _maximumFlowControlQueueSize)
+        {
+            _log.Http2FlowControlQueueOperationsExceeded(_connectionId, _maximumFlowControlQueueSize);
+            _http2Connection.Abort(new ConnectionAbortedException("HTTP/2 connection exceeded the outgoing flow control maximum queue size."));
+        }
+    }
 }

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

@@ -85,6 +85,21 @@ public void Http2UnexpectedConnectionQueueError(string connectionId, Exception e
         Http2Log.Http2UnexpectedConnectionQueueError(_http2Logger, connectionId, ex);
     }
 
+    public void Http2TooManyEnhanceYourCalms(string connectionId, int count)
+    {
+        Http2Log.Http2TooManyEnhanceYourCalms(_http2Logger, connectionId, count);
+    }
+
+    public void Http2FlowControlQueueOperationsExceeded(string connectionId, int count)
+    {
+        Http2Log.Http2FlowControlQueueOperationsExceeded(_http2Logger, connectionId, count);
+    }
+
+    public void Http2FlowControlQueueMaximumTooLow(string connectionId, int expected, int actual)
+    {
+        Http2Log.Http2FlowControlQueueMaximumTooLow(_http2Logger, connectionId, expected, actual);
+    }
+
     private static partial class Http2Log
     {
         [LoggerMessage(29, LogLevel.Debug, @"Connection id ""{ConnectionId}"": HTTP/2 connection error.", EventName = "Http2ConnectionError")]
@@ -130,5 +145,14 @@ private static partial class Http2Log
         public static partial void Http2UnexpectedConnectionQueueError(ILogger logger, string connectionId, Exception ex);
 
         // Highest shared ID is 63. New consecutive IDs start at 64
+
+        [LoggerMessage(64, LogLevel.Error, @"Connection id ""{ConnectionId}"" aborted since at least ""{Count}"" ENHANCE_YOUR_CALM responses were required per second.", EventName = "Http2TooManyEnhanceYourCalms")]
+        public static partial void Http2TooManyEnhanceYourCalms(ILogger logger, string connectionId, int count);
+
+        [LoggerMessage(65, LogLevel.Error, @"Connection id ""{ConnectionId}"" exceeded the output flow control maximum queue size of ""{Count}"".", EventName = "Http2FlowControlQueueOperationsExceeded")]
+        public static partial void Http2FlowControlQueueOperationsExceeded(ILogger logger, string connectionId, int count);
+
+        [LoggerMessage(66, LogLevel.Trace, @"Connection id ""{ConnectionId}"" configured maximum flow control queue size ""{Actual}"" is less than the maximum streams per connection ""{Expected}"" - increasing to match.", EventName = "Http2FlowControlQueueMaximumTooLow")]
+        public static partial void Http2FlowControlQueueMaximumTooLow(ILogger logger, string connectionId, int expected, int actual);
     }
 }

src/Servers/Kestrel/samples/Http2SampleApp/Http2SampleApp.csproj

@@ -1,4 +1,4 @@
-<Project Sdk="Microsoft.NET.Sdk.Web">
+<Project Sdk="Microsoft.NET.Sdk.Web">
 
   <PropertyGroup>
     <TargetFramework>$(DefaultNetCoreTargetFramework)</TargetFramework>