From c73d51328970be3262d5a7b91d16437bca095a03 Mon Sep 17 00:00:00 2001 From: "Chris Ross (ASP.NET)" Date: Wed, 8 Aug 2018 09:44:43 -0700 Subject: [PATCH 1/3] Add Http2 frame logging --- .../Kestrel.Performance/Mocks/MockTrace.cs | 2 ++ samples/Http2SampleApp/Program.cs | 4 +-- .../Internal/Http2/Http2Connection.cs | 4 +-- .../Internal/Http2/Http2Frame.Data.cs | 28 +++++++++++++++++++ .../Internal/Http2/Http2FrameWriter.cs | 15 +++++++++- .../Internal/Infrastructure/IKestrelTrace.cs | 4 +++ .../Internal/Infrastructure/KestrelTrace.cs | 18 ++++++++++++ test/shared/CompositeKestrelTrace.cs | 12 ++++++++ 8 files changed, 82 insertions(+), 5 deletions(-) diff --git a/benchmarks/Kestrel.Performance/Mocks/MockTrace.cs b/benchmarks/Kestrel.Performance/Mocks/MockTrace.cs index cf95b491c9..9841be5826 100644 --- a/benchmarks/Kestrel.Performance/Mocks/MockTrace.cs +++ b/benchmarks/Kestrel.Performance/Mocks/MockTrace.cs @@ -52,5 +52,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Performance public void Http2StreamResetAbort(string traceIdentifier, Http2ErrorCode error, ConnectionAbortedException abortReason) { } 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) { } } } diff --git a/samples/Http2SampleApp/Program.cs b/samples/Http2SampleApp/Program.cs index 0aee02c7a7..842ee9c795 100644 --- a/samples/Http2SampleApp/Program.cs +++ b/samples/Http2SampleApp/Program.cs @@ -44,7 +44,7 @@ namespace Http2SampleApp { listenOptions.Protocols = HttpProtocols.Http1AndHttp2; listenOptions.UseHttps("testCert.pfx", "testPassword"); - listenOptions.UseConnectionLogging(); + // listenOptions.UseConnectionLogging(); listenOptions.ConnectionAdapters.Add(new TlsFilterAdapter()); }); @@ -53,7 +53,7 @@ namespace Http2SampleApp options.Listen(IPAddress.Any, basePort + 5, listenOptions => { listenOptions.Protocols = HttpProtocols.Http2; - listenOptions.UseConnectionLogging(); + // listenOptions.UseConnectionLogging(); }); }) .UseContentRoot(Directory.GetCurrentDirectory()) diff --git a/src/Kestrel.Core/Internal/Http2/Http2Connection.cs b/src/Kestrel.Core/Internal/Http2/Http2Connection.cs index 5832379e26..5d504b4fce 100644 --- a/src/Kestrel.Core/Internal/Http2/Http2Connection.cs +++ b/src/Kestrel.Core/Internal/Http2/Http2Connection.cs @@ -84,7 +84,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 public Http2Connection(Http2ConnectionContext context) { _context = context; - _frameWriter = new Http2FrameWriter(context.Transport.Output, context.Application.Input, _outputFlowControl, this); + _frameWriter = new Http2FrameWriter(context.Transport.Output, context.Application.Input, _outputFlowControl, this, context.ConnectionId, context.ServiceContext.Log); _hpackDecoder = new HPackDecoder((int)_serverSettings.HeaderTableSize); } @@ -186,7 +186,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 { if (Http2FrameReader.ReadFrame(readableBuffer, _incomingFrame, _serverSettings.MaxFrameSize, out consumed, out examined)) { - Log.LogTrace($"Connection id {ConnectionId} received {_incomingFrame.Type} frame with flags 0x{_incomingFrame.Flags:x} and length {_incomingFrame.Length} for stream ID {_incomingFrame.StreamId}"); + Log.Http2FrameReceived(ConnectionId, _incomingFrame); await ProcessFrameAsync(application); } } diff --git a/src/Kestrel.Core/Internal/Http2/Http2Frame.Data.cs b/src/Kestrel.Core/Internal/Http2/Http2Frame.Data.cs index 91f0edb72a..2310db23ad 100644 --- a/src/Kestrel.Core/Internal/Http2/Http2Frame.Data.cs +++ b/src/Kestrel.Core/Internal/Http2/Http2Frame.Data.cs @@ -46,5 +46,33 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 { logger.LogTrace("'DATA' Frame. Flags = {DataFlags}, PadLength = {PadLength}, PayloadLength = {PayloadLength}", DataFlags, DataPadLength, DataPayload.Count); } + + internal object ShowFlags() + { + switch (Type) + { + case Http2FrameType.CONTINUATION: + return ContinuationFlags; + case Http2FrameType.DATA: + return DataFlags; + case Http2FrameType.HEADERS: + return HeadersFlags; + case Http2FrameType.SETTINGS: + return SettingsFlags; + case Http2FrameType.PING: + return PingFlags; + + // Not Implemented + case Http2FrameType.PUSH_PROMISE: + + // No flags defined + case Http2FrameType.PRIORITY: + case Http2FrameType.RST_STREAM: + case Http2FrameType.GOAWAY: + case Http2FrameType.WINDOW_UPDATE: + default: + return $"0x{Flags:x}"; + } + } } } diff --git a/src/Kestrel.Core/Internal/Http2/Http2FrameWriter.cs b/src/Kestrel.Core/Internal/Http2/Http2FrameWriter.cs index 066e88d067..a0a679d15b 100644 --- a/src/Kestrel.Core/Internal/Http2/Http2FrameWriter.cs +++ b/src/Kestrel.Core/Internal/Http2/Http2FrameWriter.cs @@ -13,6 +13,7 @@ using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.FlowControl; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.HPack; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; +using Microsoft.Extensions.Logging; namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 { @@ -27,6 +28,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 private readonly PipeWriter _outputWriter; private readonly PipeReader _outputReader; private readonly OutputFlowControl _connectionOutputFlowControl; + private readonly string _connectionId; + private readonly IKestrelTrace _log; private readonly StreamSafePipeFlusher _flusher; private bool _completed; @@ -35,12 +38,16 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 PipeWriter outputPipeWriter, PipeReader outputPipeReader, OutputFlowControl connectionOutputFlowControl, - ITimeoutControl timeoutControl) + ITimeoutControl timeoutControl, + string connectionId, + IKestrelTrace log) { _outputWriter = outputPipeWriter; _outputReader = outputPipeReader; _connectionOutputFlowControl = connectionOutputFlowControl; + _connectionId = connectionId; + _log = log; _flusher = new StreamSafePipeFlusher(_outputWriter, timeoutControl); } @@ -110,6 +117,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 _outgoingFrame.HeadersFlags = Http2HeadersFrameFlags.END_HEADERS; } + _log.Http2FrameSending(_connectionId, _outgoingFrame); _outputWriter.Write(_outgoingFrame.Raw); while (!done) @@ -124,6 +132,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 _outgoingFrame.ContinuationFlags = Http2ContinuationFrameFlags.END_HEADERS; } + _log.Http2FrameSending(_connectionId, _outgoingFrame); _outputWriter.Write(_outgoingFrame.Raw); } } @@ -170,6 +179,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 current.Span.Slice(0, payload.Length).CopyTo(payload); current = current.Slice(payload.Length); + _log.Http2FrameSending(_connectionId, _outgoingFrame); _outputWriter.Write(_outgoingFrame.Raw); payload = _outgoingFrame.Payload; unwrittenPayloadLength = 0; @@ -189,6 +199,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 } _outgoingFrame.Length = unwrittenPayloadLength; + + _log.Http2FrameSending(_connectionId, _outgoingFrame); _outputWriter.Write(_outgoingFrame.Raw); return _flusher.FlushAsync(); @@ -303,6 +315,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 return Task.CompletedTask; } + _log.Http2FrameSending(_connectionId, _outgoingFrame); _outputWriter.Write(_outgoingFrame.Raw); return _flusher.FlushAsync(); } diff --git a/src/Kestrel.Core/Internal/Infrastructure/IKestrelTrace.cs b/src/Kestrel.Core/Internal/Infrastructure/IKestrelTrace.cs index fd9b2b78a5..9d28cd3804 100644 --- a/src/Kestrel.Core/Internal/Infrastructure/IKestrelTrace.cs +++ b/src/Kestrel.Core/Internal/Infrastructure/IKestrelTrace.cs @@ -66,5 +66,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure void Http2StreamResetAbort(string traceIdentifier, Http2ErrorCode error, ConnectionAbortedException abortReason); void HPackDecodingError(string connectionId, int streamId, HPackDecodingException ex); + + void Http2FrameReceived(string connectionId, Http2Frame frame); + + void Http2FrameSending(string connectionId, Http2Frame frame); } } diff --git a/src/Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs b/src/Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs index 8a489eb939..752759a969 100644 --- a/src/Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs +++ b/src/Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs @@ -99,6 +99,14 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal LoggerMessage.Define(LogLevel.Debug, new EventId(36, nameof(Http2ConnectionClosed)), @"Connection id ""{ConnectionId}"" is closed. The last processed stream ID was {HighestOpenedStreamId}."); + private static readonly Action _http2FrameReceived = + LoggerMessage.Define(LogLevel.Trace, new EventId(37, nameof(Http2FrameReceived)), + @"Connection id ""{ConnectionId}"" received {type} frame for stream ID {id} with length {length} and flags {flags}"); + + private static readonly Action _http2FrameSending = + LoggerMessage.Define(LogLevel.Trace, new EventId(37, nameof(Http2FrameReceived)), + @"Connection id ""{ConnectionId}"" sending {type} frame for stream ID {id} with length {length} and flags {flags}"); + protected readonly ILogger _logger; public KestrelTrace(ILogger logger) @@ -246,6 +254,16 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal _hpackDecodingError(_logger, connectionId, streamId, ex); } + public void Http2FrameReceived(string connectionId, Http2Frame frame) + { + _http2FrameReceived(_logger, connectionId, frame.Type, frame.StreamId, frame.Length, frame.ShowFlags(), null); + } + + public void Http2FrameSending(string connectionId, Http2Frame frame) + { + _http2FrameSending(_logger, connectionId, frame.Type, frame.StreamId, frame.Length, frame.ShowFlags(), 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/test/shared/CompositeKestrelTrace.cs b/test/shared/CompositeKestrelTrace.cs index ff5801f628..ecd82d1a99 100644 --- a/test/shared/CompositeKestrelTrace.cs +++ b/test/shared/CompositeKestrelTrace.cs @@ -206,5 +206,17 @@ namespace Microsoft.AspNetCore.Testing _trace1.Http2ConnectionClosed(connectionId, highestOpenedStreamId); _trace2.Http2ConnectionClosed(connectionId, highestOpenedStreamId); } + + public void Http2FrameReceived(string connectionId, Http2Frame frame) + { + _trace1.Http2FrameReceived(connectionId, frame); + _trace2.Http2FrameReceived(connectionId, frame); + } + + public void Http2FrameSending(string connectionId, Http2Frame frame) + { + _trace1.Http2FrameSending(connectionId, frame); + _trace2.Http2FrameSending(connectionId, frame); + } } } From 5378900e0c5ae8b2a47ef9212b7df414b71daa4c Mon Sep 17 00:00:00 2001 From: "Chris Ross (ASP.NET)" Date: Wed, 8 Aug 2018 09:46:00 -0700 Subject: [PATCH 2/3] Ack settings before window updates #2772 --- samples/Http2SampleApp/Program.cs | 3 --- src/Kestrel.Core/Internal/Http2/Http2Connection.cs | 4 +++- test/Kestrel.Core.Tests/Http2ConnectionTests.cs | 5 +++++ 3 files changed, 8 insertions(+), 4 deletions(-) diff --git a/samples/Http2SampleApp/Program.cs b/samples/Http2SampleApp/Program.cs index 842ee9c795..0825c6e3d5 100644 --- a/samples/Http2SampleApp/Program.cs +++ b/samples/Http2SampleApp/Program.cs @@ -36,7 +36,6 @@ namespace Http2SampleApp options.Listen(IPAddress.Any, basePort, listenOptions => { listenOptions.Protocols = HttpProtocols.Http1; - listenOptions.UseConnectionLogging(); }); // TLS Http/1.1 or HTTP/2 endpoint negotiated via ALPN @@ -44,7 +43,6 @@ namespace Http2SampleApp { listenOptions.Protocols = HttpProtocols.Http1AndHttp2; listenOptions.UseHttps("testCert.pfx", "testPassword"); - // listenOptions.UseConnectionLogging(); listenOptions.ConnectionAdapters.Add(new TlsFilterAdapter()); }); @@ -53,7 +51,6 @@ namespace Http2SampleApp options.Listen(IPAddress.Any, basePort + 5, listenOptions => { listenOptions.Protocols = HttpProtocols.Http2; - // listenOptions.UseConnectionLogging(); }); }) .UseContentRoot(Directory.GetCurrentDirectory()) diff --git a/src/Kestrel.Core/Internal/Http2/Http2Connection.cs b/src/Kestrel.Core/Internal/Http2/Http2Connection.cs index 5d504b4fce..15035a81b4 100644 --- a/src/Kestrel.Core/Internal/Http2/Http2Connection.cs +++ b/src/Kestrel.Core/Internal/Http2/Http2Connection.cs @@ -608,6 +608,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 _clientSettings.ParseFrame(_incomingFrame); + var ackTask = _frameWriter.WriteSettingsAckAsync(); // Ack before we update the windows, they could send data immediately. + // This difference can be negative. var windowSizeDifference = (int)_clientSettings.InitialWindowSize - previousInitialWindowSize; @@ -625,7 +627,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 } } - return _frameWriter.WriteSettingsAckAsync(); + return ackTask; } catch (Http2SettingsParameterOutOfRangeException ex) { diff --git a/test/Kestrel.Core.Tests/Http2ConnectionTests.cs b/test/Kestrel.Core.Tests/Http2ConnectionTests.cs index 497662a2e7..7bf017534b 100644 --- a/test/Kestrel.Core.Tests/Http2ConnectionTests.cs +++ b/test/Kestrel.Core.Tests/Http2ConnectionTests.cs @@ -2328,6 +2328,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests _clientSettings.InitialWindowSize += 1; await SendSettingsAsync(); + await ExpectAsync(Http2FrameType.SETTINGS, + withLength: 0, + withFlags: (byte)Http2SettingsFrameFlags.ACK, + withStreamId: 0); + await WaitForConnectionErrorAsync( ignoreNonGoAwayFrames: false, expectedLastStreamId: 1, From c0557cfca7e9819d69c3be329e1e4f2e85305eda Mon Sep 17 00:00:00 2001 From: Stephen Halter Date: Wed, 8 Aug 2018 11:20:49 -0700 Subject: [PATCH 3/3] Improve exception handling in Http2Connection.ProcessRequestsAsync (#2787) --- .../Internal/Http2/Http2Connection.cs | 10 ++++-- .../Http2ConnectionTests.cs | 31 +++++++++++++++++++ 2 files changed, 39 insertions(+), 2 deletions(-) diff --git a/src/Kestrel.Core/Internal/Http2/Http2Connection.cs b/src/Kestrel.Core/Internal/Http2/Http2Connection.cs index 15035a81b4..7ffa068d88 100644 --- a/src/Kestrel.Core/Internal/Http2/Http2Connection.cs +++ b/src/Kestrel.Core/Internal/Http2/Http2Connection.cs @@ -4,6 +4,7 @@ using System; using System.Buffers; using System.Collections.Concurrent; +using System.IO; using System.IO.Pipelines; using System.Security.Authentication; using System.Text; @@ -14,8 +15,8 @@ using Microsoft.AspNetCore.Connections.Features; using Microsoft.AspNetCore.Hosting.Server; using Microsoft.AspNetCore.Http.Features; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http; -using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.HPack; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.FlowControl; +using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.HPack; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.Extensions.Logging; using Microsoft.Net.Http.Headers; @@ -218,6 +219,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 error = ex; } + catch (IOException ex) + { + Log.RequestProcessingError(ConnectionId, ex); + error = ex; + } catch (Http2ConnectionErrorException ex) { Log.Http2ConnectionError(ConnectionId, ex); @@ -232,9 +238,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 } catch (Exception ex) { + Log.LogWarning(0, ex, CoreStrings.RequestProcessingEndError); error = ex; errorCode = Http2ErrorCode.INTERNAL_ERROR; - throw; } finally { diff --git a/test/Kestrel.Core.Tests/Http2ConnectionTests.cs b/test/Kestrel.Core.Tests/Http2ConnectionTests.cs index 7bf017534b..c20c9ecfc9 100644 --- a/test/Kestrel.Core.Tests/Http2ConnectionTests.cs +++ b/test/Kestrel.Core.Tests/Http2ConnectionTests.cs @@ -21,6 +21,7 @@ using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.HPack; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.AspNetCore.Server.Kestrel.Transport.Abstractions.Internal; using Microsoft.AspNetCore.Testing; +using Microsoft.Extensions.Logging; using Microsoft.Net.Http.Headers; using Moq; using Xunit; @@ -3425,6 +3426,36 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests await WaitForConnectionStopAsync(expectedLastStreamId: 1, ignoreNonGoAwayFrames: false); } + [Fact] + public void IOExceptionDuringFrameProcessingLoggedAsInfo() + { + var ioException = new IOException(); + _pair.Application.Output.Complete(ioException); + + Assert.Equal(TaskStatus.RanToCompletion, _connection.ProcessRequestsAsync(new DummyApplication(_noopApplication)).Status); + + var logMessage = _logger.Messages.Single(); + + Assert.Equal(LogLevel.Information, logMessage.LogLevel); + Assert.Equal("Connection id \"(null)\" request processing ended abnormally.", logMessage.Message); + Assert.Same(ioException, logMessage.Exception); + } + + [Fact] + public void UnexpectedExceptionDuringFrameProcessingLoggedAWarning() + { + var exception = new Exception(); + _pair.Application.Output.Complete(exception); + + Assert.Equal(TaskStatus.RanToCompletion, _connection.ProcessRequestsAsync(new DummyApplication(_noopApplication)).Status); + + var logMessage = _logger.Messages.Single(); + + Assert.Equal(LogLevel.Warning, logMessage.LogLevel); + Assert.Equal(CoreStrings.RequestProcessingEndError, logMessage.Message); + Assert.Same(exception, logMessage.Exception); + } + private async Task InitializeConnectionAsync(RequestDelegate application) { _connectionTask = _connection.ProcessRequestsAsync(new DummyApplication(application));