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