From 8009350176386b6caefbcc5a9926f177d51d3f52 Mon Sep 17 00:00:00 2001 From: James Newton-King Date: Wed, 3 Jun 2020 10:11:06 +1200 Subject: [PATCH] Log message when connection reaches maximum concurrent streams (#22452) --- .../src/Internal/Http2/Http2Connection.cs | 8 ++++++- .../Internal/Infrastructure/IKestrelTrace.cs | 2 ++ .../Internal/Infrastructure/KestrelTrace.cs | 9 ++++++++ .../Kestrel.Performance/Mocks/MockTrace.cs | 1 + .../shared/test/CompositeKestrelTrace.cs | 6 +++++ .../Http2/Http2ConnectionTests.cs | 22 +++++++++++++++++++ 6 files changed, 47 insertions(+), 1 deletion(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs index cfbc209af2..fc97e00068 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs @@ -971,7 +971,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 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. diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs index 54a8392fae..72442fa962 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs @@ -74,5 +74,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure void Http2FrameReceived(string connectionId, Http2Frame frame); void Http2FrameSending(string connectionId, Http2Frame frame); + + void Http2MaxConcurrentStreamsReached(string connectionId); } } diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs index 6edaf7b599..5a85007aab 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs @@ -113,6 +113,10 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure private static readonly Action _connectionAccepted = LoggerMessage.Define(LogLevel.Debug, new EventId(39, nameof(ConnectionAccepted)), @"Connection id ""{ConnectionId}"" accepted."); + private static readonly Action _http2MaxConcurrentStreamsReached = + LoggerMessage.Define(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 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure } } + public void Http2MaxConcurrentStreamsReached(string connectionId) + { + _http2MaxConcurrentStreamsReached(_logger, connectionId, null); + } + public virtual void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) => _logger.Log(logLevel, eventId, state, exception, formatter); diff --git a/src/Servers/Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs b/src/Servers/Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs index 76a5c9443d..a8e1b76a9b 100644 --- a/src/Servers/Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs +++ b/src/Servers/Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs @@ -55,5 +55,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Performance 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) { } } } diff --git a/src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs b/src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs index 363da59c9d..f22ebc810b 100644 --- a/src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs +++ b/src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs @@ -229,5 +229,11 @@ namespace Microsoft.AspNetCore.Testing _trace1.Http2FrameSending(connectionId, frame); _trace2.Http2FrameSending(connectionId, frame); } + + public void Http2MaxConcurrentStreamsReached(string connectionId) + { + _trace1.Http2MaxConcurrentStreamsReached(connectionId); + _trace2.Http2MaxConcurrentStreamsReached(connectionId); + } } } diff --git a/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2ConnectionTests.cs b/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2ConnectionTests.cs index 452ad4bb90..2517a55b15 100644 --- a/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2ConnectionTests.cs +++ b/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() {