huahaofeng
/
aspnetcore
1
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

Add Http2 frame logging

This commit is contained in:
Chris Ross (ASP.NET) 2018-08-08 09:44:43 -07:00
parent 0a28806c17
commit c73d513289
8 changed files with 82 additions and 5 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
benchmarks/Kestrel.Performance/Mocks/MockTrace.cs
View File

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

4
samples/Http2SampleApp/Program.cs
View File

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

4
src/Kestrel.Core/Internal/Http2/Http2Connection.cs
View File

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

28
src/Kestrel.Core/Internal/Http2/Http2Frame.Data.cs
View File

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

15
src/Kestrel.Core/Internal/Http2/Http2FrameWriter.cs
View File

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

4
src/Kestrel.Core/Internal/Infrastructure/IKestrelTrace.cs
View File

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

18
src/Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs
View File

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

12
test/shared/CompositeKestrelTrace.cs
View File

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