From fffd0591defe9be2a464b706537824f3381a45c9 Mon Sep 17 00:00:00 2001 From: Radek Zikmund <32671551+rzikm@users.noreply.github.com> Date: Wed, 24 Apr 2024 17:03:11 +0200 Subject: [PATCH] Add more logging to HTTP3 and QUIC code (#101449) * Add more logging to QuicConnection and QuicStream * Fix ptr format * wip * Add more http3 logging * fixup! Add more http3 logging * Code review feedback --- .../SocketsHttpHandler/Http3Connection.cs | 13 +++++++++ .../Net/Quic/Internal/MsQuicExtensions.cs | 27 ++++++++++++++++-- .../src/System/Net/Quic/QuicConnection.cs | 28 +++++++++++++++++++ .../src/System/Net/Quic/QuicListener.cs | 11 ++++++++ .../src/System/Net/Quic/QuicStream.cs | 11 ++++++++ 5 files changed, 87 insertions(+), 3 deletions(-) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3Connection.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3Connection.cs index a4e8efeca6412e..75b9d9b1f8a964 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3Connection.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3Connection.cs @@ -300,6 +300,11 @@ internal Exception Abort(Exception abortException) private void OnServerGoAway(long firstRejectedStreamId) { + if (NetEventSource.Log.IsEnabled()) + { + Trace($"GOAWAY received. First rejected stream ID = {firstRejectedStreamId}"); + } + // Stop sending requests to this connection. _pool.InvalidateHttp3Connection(this); @@ -649,6 +654,10 @@ private async Task ProcessServerControlStreamAsync(QuicStream stream, ArrayBuffe case Http3FrameType.ReservedHttp2Ping: case Http3FrameType.ReservedHttp2WindowUpdate: case Http3FrameType.ReservedHttp2Continuation: + if (NetEventSource.Log.IsEnabled()) + { + Trace($"Received reserved frame: {frameType}"); + } throw HttpProtocolException.CreateHttp3ConnectionException(Http3ErrorCode.UnexpectedFrame); case Http3FrameType.PushPromise: case Http3FrameType.CancelPush: @@ -663,6 +672,10 @@ private async Task ProcessServerControlStreamAsync(QuicStream stream, ArrayBuffe } if (!shuttingDown) { + if (NetEventSource.Log.IsEnabled()) + { + Trace($"Control stream closed by the server."); + } throw HttpProtocolException.CreateHttp3ConnectionException(Http3ErrorCode.ClosedCriticalStream); } return; diff --git a/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/MsQuicExtensions.cs b/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/MsQuicExtensions.cs index 5c079f65287415..cfc5a09a37171c 100644 --- a/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/MsQuicExtensions.cs +++ b/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/MsQuicExtensions.cs @@ -1,6 +1,7 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using System; using System.Net.Quic; namespace Microsoft.Quic; @@ -17,7 +18,7 @@ public override string ToString() => Type switch { QUIC_LISTENER_EVENT_TYPE.NEW_CONNECTION - => $"{{ {nameof(NEW_CONNECTION.Info)} = {{ {nameof(QUIC_NEW_CONNECTION_INFO.QuicVersion)} = {NEW_CONNECTION.Info->QuicVersion}, {nameof(QUIC_NEW_CONNECTION_INFO.LocalAddress)} = {MsQuicHelpers.QuicAddrToIPEndPoint(NEW_CONNECTION.Info->LocalAddress)}, {nameof(QUIC_NEW_CONNECTION_INFO.RemoteAddress)} = {MsQuicHelpers.QuicAddrToIPEndPoint(NEW_CONNECTION.Info->RemoteAddress)} }} }}", + => $"{{ {nameof(NEW_CONNECTION.Info)} = {{ {nameof(QUIC_NEW_CONNECTION_INFO.QuicVersion)} = {NEW_CONNECTION.Info->QuicVersion}, {nameof(QUIC_NEW_CONNECTION_INFO.LocalAddress)} = {MsQuicHelpers.QuicAddrToIPEndPoint(NEW_CONNECTION.Info->LocalAddress)}, {nameof(QUIC_NEW_CONNECTION_INFO.RemoteAddress)} = {MsQuicHelpers.QuicAddrToIPEndPoint(NEW_CONNECTION.Info->RemoteAddress)} }}, {nameof(NEW_CONNECTION.Connection)} = 0x{(IntPtr)NEW_CONNECTION.Connection:X11} }}", _ => string.Empty }; } @@ -40,9 +41,29 @@ public override string ToString() QUIC_CONNECTION_EVENT_TYPE.PEER_ADDRESS_CHANGED => $"{{ {nameof(PEER_ADDRESS_CHANGED.Address)} = {MsQuicHelpers.QuicAddrToIPEndPoint(PEER_ADDRESS_CHANGED.Address)} }}", QUIC_CONNECTION_EVENT_TYPE.PEER_STREAM_STARTED - => $"{{ {nameof(PEER_STREAM_STARTED.Flags)} = {PEER_STREAM_STARTED.Flags} }}", + => $"{{ {nameof(PEER_STREAM_STARTED.Stream)} = 0x{(IntPtr)PEER_STREAM_STARTED.Stream:X11} {nameof(PEER_STREAM_STARTED.Flags)} = {PEER_STREAM_STARTED.Flags} }}", + QUIC_CONNECTION_EVENT_TYPE.STREAMS_AVAILABLE + => $"{{ {nameof(STREAMS_AVAILABLE.BidirectionalCount)} = {STREAMS_AVAILABLE.BidirectionalCount}, {nameof(STREAMS_AVAILABLE.UnidirectionalCount)} = {STREAMS_AVAILABLE.UnidirectionalCount} }}", + QUIC_CONNECTION_EVENT_TYPE.PEER_NEEDS_STREAMS + => $"{{ {nameof(PEER_NEEDS_STREAMS.Bidirectional)} = {PEER_NEEDS_STREAMS.Bidirectional} }}", + QUIC_CONNECTION_EVENT_TYPE.IDEAL_PROCESSOR_CHANGED + => $"{{ {nameof(IDEAL_PROCESSOR_CHANGED.IdealProcessor)} = {IDEAL_PROCESSOR_CHANGED.IdealProcessor}, {nameof(IDEAL_PROCESSOR_CHANGED.PartitionIndex)} = {IDEAL_PROCESSOR_CHANGED.PartitionIndex} }}", + QUIC_CONNECTION_EVENT_TYPE.DATAGRAM_STATE_CHANGED + => $"{{ {nameof(DATAGRAM_STATE_CHANGED.SendEnabled)} = {DATAGRAM_STATE_CHANGED.SendEnabled}, {nameof(DATAGRAM_STATE_CHANGED.MaxSendLength)} = {DATAGRAM_STATE_CHANGED.MaxSendLength} }}", + QUIC_CONNECTION_EVENT_TYPE.DATAGRAM_RECEIVED + => $"{{ {nameof(DATAGRAM_RECEIVED.Flags)} = {DATAGRAM_RECEIVED.Flags} }}", + QUIC_CONNECTION_EVENT_TYPE.DATAGRAM_SEND_STATE_CHANGED + => $"{{ {nameof(DATAGRAM_SEND_STATE_CHANGED.ClientContext)} = 0x{(IntPtr)DATAGRAM_SEND_STATE_CHANGED.ClientContext:X11}, {nameof(DATAGRAM_SEND_STATE_CHANGED.State)} = {DATAGRAM_SEND_STATE_CHANGED.State} }}", + QUIC_CONNECTION_EVENT_TYPE.RESUMED + => $"{{ {nameof(RESUMED.ResumptionStateLength)} = {RESUMED.ResumptionStateLength} }}", + QUIC_CONNECTION_EVENT_TYPE.RESUMPTION_TICKET_RECEIVED + => $"{{ {nameof(RESUMPTION_TICKET_RECEIVED.ResumptionTicketLength)} = {RESUMPTION_TICKET_RECEIVED.ResumptionTicketLength} }}", QUIC_CONNECTION_EVENT_TYPE.PEER_CERTIFICATE_RECEIVED - => $"{{ {nameof(PEER_CERTIFICATE_RECEIVED.DeferredStatus)} = {PEER_CERTIFICATE_RECEIVED.DeferredStatus}, {nameof(PEER_CERTIFICATE_RECEIVED.DeferredErrorFlags)} = {PEER_CERTIFICATE_RECEIVED.DeferredErrorFlags} }}", + => $"{{ {nameof(PEER_CERTIFICATE_RECEIVED.DeferredStatus)} = {PEER_CERTIFICATE_RECEIVED.DeferredStatus}, {nameof(PEER_CERTIFICATE_RECEIVED.DeferredErrorFlags)} = {PEER_CERTIFICATE_RECEIVED.DeferredErrorFlags}, {nameof(PEER_CERTIFICATE_RECEIVED.Certificate)} = 0x{(IntPtr)PEER_CERTIFICATE_RECEIVED.Certificate:X11} }}", + QUIC_CONNECTION_EVENT_TYPE.RELIABLE_RESET_NEGOTIATED + => $"{{ {nameof(RELIABLE_RESET_NEGOTIATED.IsNegotiated)} = {RELIABLE_RESET_NEGOTIATED.IsNegotiated} }}", + QUIC_CONNECTION_EVENT_TYPE.ONE_WAY_DELAY_NEGOTIATED + => $"{{ {nameof(ONE_WAY_DELAY_NEGOTIATED.SendNegotiated)} = {ONE_WAY_DELAY_NEGOTIATED.SendNegotiated}, {nameof(ONE_WAY_DELAY_NEGOTIATED.ReceiveNegotiated)} = {ONE_WAY_DELAY_NEGOTIATED.ReceiveNegotiated} }}", _ => string.Empty }; } diff --git a/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs b/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs index 315352d2797bb4..e568eeb6f97b7a 100644 --- a/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs +++ b/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs @@ -252,6 +252,11 @@ private unsafe QuicConnection() throw; } + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Info(this, $"{this} New outbound connection."); + } + _tlsSecret = MsQuicTlsSecret.Create(_handle); } @@ -411,6 +416,12 @@ public async ValueTask OpenOutboundStreamAsync(QuicStreamType type, try { stream = new QuicStream(_handle, type, _defaultStreamErrorCode); + + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Info(this, $"{this} New outbound {type} stream {stream}."); + } + await stream.StartAsync(cancellationToken).ConfigureAwait(false); } catch @@ -482,6 +493,11 @@ public ValueTask CloseAsync(long errorCode, CancellationToken cancellationToken if (_shutdownTcs.TryGetValueTask(out ValueTask valueTask, this, cancellationToken)) { + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Info(this, $"{this} Closing connection, Error code = {errorCode}"); + } + unsafe { MsQuicApi.Api.ConnectionShutdown( @@ -551,6 +567,13 @@ private unsafe int HandleEventPeerAddressChanged(ref PEER_ADDRESS_CHANGED_DATA d private unsafe int HandleEventPeerStreamStarted(ref PEER_STREAM_STARTED_DATA data) { QuicStream stream = new QuicStream(_handle, data.Stream, data.Flags, _defaultStreamErrorCode); + + if (NetEventSource.Log.IsEnabled()) + { + QuicStreamType type = data.Flags.HasFlag(QUIC_STREAM_OPEN_FLAGS.UNIDIRECTIONAL) ? QuicStreamType.Unidirectional : QuicStreamType.Bidirectional; + NetEventSource.Info(this, $"{this} New inbound {type} stream {stream}, Id = {stream.Id}."); + } + if (!_acceptQueue.Writer.TryWrite(stream)) { if (NetEventSource.Log.IsEnabled()) @@ -648,6 +671,11 @@ public async ValueTask DisposeAsync() return; } + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Info(this, $"{this} Disposing."); + } + // Check if the connection has been shut down and if not, shut it down. if (_shutdownTcs.TryGetValueTask(out ValueTask valueTask, this)) { diff --git a/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicListener.cs b/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicListener.cs index 88ea309054a7db..249f7571519131 100644 --- a/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicListener.cs +++ b/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicListener.cs @@ -335,6 +335,12 @@ private unsafe int HandleEventNewConnection(ref NEW_CONNECTION_DATA data) } QuicConnection connection = new QuicConnection(data.Connection, data.Info); + + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Info(this, $"{this} New inbound connection {connection}."); + } + SslClientHelloInfo clientHello = new SslClientHelloInfo(data.Info->ServerNameLength > 0 ? Marshal.PtrToStringUTF8((IntPtr)data.Info->ServerName, data.Info->ServerNameLength) : "", SslProtocols.Tls13); // Kicks off the rest of the handshake in the background, the process itself will enqueue the result in the accept queue. @@ -404,6 +410,11 @@ public async ValueTask DisposeAsync() return; } + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Info(this, $"{this} Disposing."); + } + // Check if the listener has been shut down and if not, shut it down. if (_shutdownTcs.TryInitialize(out ValueTask valueTask, this)) { diff --git a/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicStream.cs b/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicStream.cs index 06515f3310bf7f..6af0f5c5c099f3 100644 --- a/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicStream.cs +++ b/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicStream.cs @@ -225,6 +225,7 @@ internal unsafe QuicStream(MsQuicContextSafeHandle connectionHandle, QUIC_HANDLE } _id = (long)GetMsQuicParameter(_handle, QUIC_PARAM_STREAM_ID); _type = flags.HasFlag(QUIC_STREAM_OPEN_FLAGS.UNIDIRECTIONAL) ? QuicStreamType.Unidirectional : QuicStreamType.Bidirectional; + _startedTcs.TrySetResult(); } @@ -325,6 +326,11 @@ public override async ValueTask ReadAsync(Memory buffer, Cancellation } } + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Info(this, $"{this} Stream read '{totalCopied}' bytes."); + } + return totalCopied; } @@ -690,6 +696,11 @@ public override async ValueTask DisposeAsync() return; } + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Info(this, $"{this} Disposing."); + } + // If the stream wasn't started successfully, gracelessly abort it. if (!_startedTcs.IsCompletedSuccessfully) {