HTTP/3: Log frames and remove frame max size (#29083)

Co-authored-by: Stephen Halter <[email protected]>

src/Servers/Kestrel/Core/src/Internal/Http3/Http3ControlStream.cs

@@ -9,8 +9,10 @@ using System.Net.Http;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Connections;
+using Microsoft.AspNetCore.Connections.Features;
 using Microsoft.AspNetCore.Hosting.Server;
 using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3.QPack;
+using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure;
 
 namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3
 {
@@ -24,6 +26,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3
         private readonly Http3Connection _http3Connection;
         private readonly Http3StreamContext _context;
         private readonly Http3PeerSettings _serverPeerSettings;
+        private readonly IStreamIdFeature _streamIdFeature;
         private readonly Http3RawFrame _incomingFrame = new Http3RawFrame();
         private volatile int _isClosed;
         private int _gracefulCloseInitiator;
@@ -36,6 +39,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3
             _http3Connection = http3Connection;
             _context = context;
             _serverPeerSettings = context.ServerSettings;
+            _streamIdFeature = context.ConnectionFeatures.Get<IStreamIdFeature>()!;
 
             _frameWriter = new Http3FrameWriter(
                 context.Transport.Output,
@@ -44,7 +48,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3
                 httpLimits.MinResponseDataRate,
                 context.ConnectionId,
                 context.MemoryPool,
-                context.ServiceContext.Log);
+                context.ServiceContext.Log,
+                _streamIdFeature);
         }
 
         private void OnStreamClosed()
@@ -53,7 +58,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3
         }
 
         public PipeReader Input => _context.Transport.Input;
-
+        public IKestrelTrace Log => _context.ServiceContext.Log;
 
         public void Abort(ConnectionAbortedException ex)
         {
@@ -193,9 +198,10 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3
                     if (!readableBuffer.IsEmpty)
                     {
                         // need to kick off httpprotocol process request async here.
-                        while (Http3FrameReader.TryReadFrame(ref readableBuffer, _incomingFrame, 16 * 1024, out var framePayload))
+                        while (Http3FrameReader.TryReadFrame(ref readableBuffer, _incomingFrame, out var framePayload))
                         {
-                            //Log.Http2FrameReceived(ConnectionId, _incomingFrame);
+                            Log.Http3FrameReceived(_context.ConnectionId, _streamIdFeature.StreamId, _incomingFrame);
+
                             consumed = examined = framePayload.End;
                             await ProcessHttp3ControlStream(framePayload);
                         }

src/Servers/Kestrel/Core/src/Internal/Http3/Http3FrameReader.cs

@@ -1,6 +1,7 @@
 // Copyright (c) .NET Foundation. All rights reserved.
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
+using System;
 using System.Buffers;
 using System.Net.Http;
 
@@ -19,11 +20,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3
             |                       Frame Payload (*)                     ...
             +-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
         */
-        internal static bool TryReadFrame(ref ReadOnlySequence<byte> readableBuffer, Http3RawFrame frame, uint maxFrameSize, out ReadOnlySequence<byte> framePayload)
+        internal static bool TryReadFrame(ref ReadOnlySequence<byte> readableBuffer, Http3RawFrame frame, out ReadOnlySequence<byte> framePayload)
         {
             framePayload = ReadOnlySequence<byte>.Empty;
-            var consumed = readableBuffer.Start;
-            var examined = readableBuffer.Start;
+            SequencePosition consumed;
+            SequencePosition examined;
 
             var type = VariableLengthIntegerHelper.GetInteger(readableBuffer, out consumed, out examined);
             if (type == -1)

src/Servers/Kestrel/Core/src/Internal/Http3/Http3FrameWriter.cs

@@ -11,6 +11,7 @@ using System.Net.Http.QPack;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Connections;
+using Microsoft.AspNetCore.Connections.Features;
 using Microsoft.AspNetCore.Http;
 using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http;
 using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure;
@@ -27,8 +28,10 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3
         private readonly ConnectionContext _connectionContext;
         private readonly ITimeoutControl _timeoutControl;
         private readonly MinDataRate? _minResponseDataRate;
+        private readonly string _connectionId;
         private readonly MemoryPool<byte> _memoryPool;
         private readonly IKestrelTrace _log;
+        private readonly IStreamIdFeature _streamIdFeature;
         private readonly Http3RawFrame _outgoingFrame;
         private readonly TimingPipeFlusher _flusher;
 
@@ -42,14 +45,16 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3
 
         //private int _unflushedBytes;
 
-        public Http3FrameWriter(PipeWriter output, ConnectionContext connectionContext, ITimeoutControl timeoutControl, MinDataRate? minResponseDataRate, string connectionId, MemoryPool<byte> memoryPool, IKestrelTrace log)
+        public Http3FrameWriter(PipeWriter output, ConnectionContext connectionContext, ITimeoutControl timeoutControl, MinDataRate? minResponseDataRate, string connectionId, MemoryPool<byte> memoryPool, IKestrelTrace log, IStreamIdFeature streamIdFeature)
         {
             _outputWriter = output;
             _connectionContext = connectionContext;
             _timeoutControl = timeoutControl;
             _minResponseDataRate = minResponseDataRate;
+            _connectionId = connectionId;
             _memoryPool = memoryPool;
             _log = log;
+            _streamIdFeature = streamIdFeature;
             _outgoingFrame = new Http3RawFrame();
             _flusher = new TimingPipeFlusher(_outputWriter, timeoutControl, log);
             _headerEncodingBuffer = new byte[_maxFrameSize];
@@ -228,6 +233,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3
 
         private void WriteHeaderUnsynchronized()
         {
+            _log.Http3FrameSending(_connectionId, _streamIdFeature.StreamId, _outgoingFrame);
             var headerLength = WriteHeader(_outgoingFrame, _outputWriter);
 
             // We assume the payload will be written prior to the next flush.

src/Servers/Kestrel/Core/src/Internal/Http3/Http3Stream.cs

@@ -72,7 +72,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3
                 httpLimits.MinResponseDataRate,
                 context.ConnectionId,
                 context.MemoryPool,
-                context.ServiceContext.Log);
+                context.ServiceContext.Log,
+                _streamIdFeature);
 
             // ResponseHeaders aren't set, kind of ugly that we need to reset.
             Reset();
@@ -359,8 +360,10 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3
                     {
                         if (!readableBuffer.IsEmpty)
                         {
-                            while (Http3FrameReader.TryReadFrame(ref readableBuffer, _incomingFrame, 16 * 1024, out var framePayload))
+                            while (Http3FrameReader.TryReadFrame(ref readableBuffer, _incomingFrame, out var framePayload))
                             {
+                                Log.Http3FrameReceived(ConnectionId, _streamIdFeature.StreamId, _incomingFrame);
+
                                 consumed = examined = framePayload.End;
                                 await ProcessHttp3Stream(application, framePayload);
                             }

src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs

@@ -88,5 +88,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure
         void Http3ConnectionClosed(string connectionId, long highestOpenedStreamId);
 
         void Http3StreamAbort(string traceIdentifier, Http3ErrorCode error, ConnectionAbortedException abortReason);
+
+        void Http3FrameReceived(string connectionId, long streamId, Http3RawFrame frame);
+
+        void Http3FrameSending(string connectionId, long streamId, Http3RawFrame frame);
     }
 }

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

@@ -138,6 +138,14 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure
             LoggerMessage.Define<string, Http3ErrorCode>(LogLevel.Debug, new EventId(45, "Http3StreamAbort"),
                 @"Trace id ""{TraceIdentifier}"": HTTP/3 stream error ""{error}"". An abort is being sent to the stream.");
 
+        private static readonly Action<ILogger, string, Http3FrameType, long, long, Exception?> _http3FrameReceived =
+            LoggerMessage.Define<string, Http3FrameType, long, long>(LogLevel.Trace, new EventId(46, "Http3FrameReceived"),
+                @"Connection id ""{ConnectionId}"" received {type} frame for stream ID {id} with length {length}.");
+
+        private static readonly Action<ILogger, string, Http3FrameType, long, long, Exception?> _http3FrameSending =
+            LoggerMessage.Define<string, Http3FrameType, long, long>(LogLevel.Trace, new EventId(47, "Http3FrameSending"),
+                @"Connection id ""{ConnectionId}"" sending {type} frame for stream ID {id} with length {length}.");
+
         protected readonly ILogger _logger;
 
         public KestrelTrace(ILogger logger)
@@ -341,6 +349,16 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure
             _http3StreamAbort(_logger, traceIdentifier, error, abortReason);
         }
 
+        public void Http3FrameReceived(string connectionId, long streamId, Http3RawFrame frame)
+        {
+            _http3FrameReceived(_logger, connectionId, frame.Type, streamId, frame.Length, null);
+        }
+
+        public void Http3FrameSending(string connectionId, long streamId, Http3RawFrame frame)
+        {
+            _http3FrameSending(_logger, connectionId, frame.Type, streamId, frame.Length, 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);
 

src/Servers/Kestrel/Core/test/Http3FrameWriterTests.cs

@@ -6,6 +6,7 @@ using System.Buffers;
 using System.IO.Pipelines;
 using System.Linq;
 using System.Threading.Tasks;
+using Microsoft.AspNetCore.Connections.Features;
 using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3;
 using Moq;
 using Xunit;
@@ -38,7 +39,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests
         public async Task WriteSettings_NoSettingsWrittenWithProtocolDefault()
         {
             var pipe = new Pipe(new PipeOptions(_dirtyMemoryPool, PipeScheduler.Inline, PipeScheduler.Inline));
-            var frameWriter = new Http3FrameWriter(pipe.Writer, null, null, null, null, _dirtyMemoryPool, null);
+            var frameWriter = CreateFrameWriter(pipe);
 
             var settings = new Http3PeerSettings();
             await frameWriter.WriteSettingsAsync(settings.GetNonProtocolDefaults());
@@ -52,7 +53,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests
         public async Task WriteSettings_OneSettingsWrittenWithKestrelDefaults()
         {
             var pipe = new Pipe(new PipeOptions(_dirtyMemoryPool, PipeScheduler.Inline, PipeScheduler.Inline));
-            var frameWriter = new Http3FrameWriter(pipe.Writer, null, null, null, null, _dirtyMemoryPool, null);
+            var frameWriter = CreateFrameWriter(pipe);
 
             var limits = new Http3Limits();
             var settings = new Http3PeerSettings();
@@ -71,7 +72,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests
         public async Task WriteSettings_TwoSettingsWritten()
         {
             var pipe = new Pipe(new PipeOptions(_dirtyMemoryPool, PipeScheduler.Inline, PipeScheduler.Inline));
-            var frameWriter = new Http3FrameWriter(pipe.Writer, null, null, null, null, _dirtyMemoryPool, null);
+            var frameWriter = CreateFrameWriter(pipe);
 
             var settings = new Http3PeerSettings();
             settings.HeaderTableSize = 1234;
@@ -84,5 +85,10 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests
 
             Assert.Equal(new byte[] { 0x04, 0x08, 0x01, 0x44, 0xD2, 0x06, 0x80, 0x08, 0xAA, 0x52 }, payload.ToArray());
         }
+
+        private Http3FrameWriter CreateFrameWriter(Pipe pipe)
+        {
+            return new Http3FrameWriter(pipe.Writer, null, null, null, null, _dirtyMemoryPool, null, Mock.Of<IStreamIdFeature>());
+        }
     }
 }

src/Servers/Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs

@@ -64,5 +64,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Performance
         public void Http3ConnectionClosing(string connectionId) { }
         public void Http3ConnectionClosed(string connectionId, long highestOpenedStreamId) { }
         public void Http3StreamAbort(string traceIdentifier, Http3ErrorCode error, ConnectionAbortedException abortReason) { }
+        public void Http3FrameReceived(string connectionId, long streamId, Http3RawFrame frame) { }
+        public void Http3FrameSending(string connectionId, long streamId, Http3RawFrame frame) { }
     }
 }

src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs

@@ -268,5 +268,17 @@ namespace Microsoft.AspNetCore.Testing
             _trace1.Http3StreamAbort(traceIdentifier, error, abortReason);
             _trace2.Http3StreamAbort(traceIdentifier, error, abortReason);
         }
+
+        public void Http3FrameReceived(string connectionId, long streamId, Http3RawFrame frame)
+        {
+            _trace1.Http3FrameReceived(connectionId, streamId, frame);
+            _trace1.Http3FrameReceived(connectionId, streamId, frame);
+        }
+
+        public void Http3FrameSending(string connectionId, long streamId, Http3RawFrame frame)
+        {
+            _trace1.Http3FrameSending(connectionId, streamId, frame);
+            _trace2.Http3FrameSending(connectionId, streamId, frame);
+        }
     }
 }

src/Servers/Kestrel/test/InMemory.FunctionalTests/Http3/Http3TestBase.cs

@@ -290,7 +290,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests
                 await writableBuffer.FlushAsync().AsTask().DefaultTimeout();
             }
 
-            internal async Task<Http3FrameWithPayload> ReceiveFrameAsync(uint maxFrameSize = 16 * 1024)
+            internal async Task<Http3FrameWithPayload> ReceiveFrameAsync()
             {
                 var frame = new Http3FrameWithPayload();
 
@@ -306,7 +306,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests
                     {
                         Assert.True(buffer.Length > 0);
 
-                        if (Http3FrameReader.TryReadFrame(ref buffer, frame, maxFrameSize, out var framePayload))
+                        if (Http3FrameReader.TryReadFrame(ref buffer, frame, out var framePayload))
                         {
                             consumed = examined = framePayload.End;
                             frame.Payload = framePayload.ToArray();