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

This commit is contained in:
James Newton-King 2020-06-03 10:11:06 +12:00 committed by GitHub
parent 7de516e750
commit 8009350176
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
6 changed files with 47 additions and 1 deletions

View File

@ -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.

View File

@ -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);
}
}

View File

@ -113,6 +113,10 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure
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 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure
}
}
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);

View File

@ -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) { }
}
}

View File

@ -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);
}
}
}

View File

@ -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()
{