Merge branch 'release/2.2'

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

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

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;
@@ -84,7 +85,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 +187,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);
                             }
                         }
@@ -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
             {
@@ -608,6 +614,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 +633,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2
                     }
                 }
 
-                return _frameWriter.WriteSettingsAckAsync();
+                return ackTask;
             }
             catch (Http2SettingsParameterOutOfRangeException ex)
             {

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}";
+            }
+        }
     }
 }

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

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

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

@@ -99,6 +99,14 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal
             LoggerMessage.Define<string, int>(LogLevel.Debug, new EventId(36, nameof(Http2ConnectionClosed)),
                 @"Connection id ""{ConnectionId}"" is closed. The last processed stream ID was {HighestOpenedStreamId}.");
 
+        private static readonly Action<ILogger, string, Http2FrameType, int, int, object, Exception> _http2FrameReceived =
+            LoggerMessage.Define<string, Http2FrameType, int, int, object>(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<ILogger, string, Http2FrameType, int, int, object, Exception> _http2FrameSending =
+            LoggerMessage.Define<string, Http2FrameType, int, int, object>(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<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
             => _logger.Log(logLevel, eventId, state, exception, formatter);
 

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;
@@ -2328,6 +2329,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<Http2ConnectionErrorException>(
                 ignoreNonGoAwayFrames: false,
                 expectedLastStreamId: 1,
@@ -3420,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));

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