From ce99fe1362d9e442071938d40027c3efaebdc4dc Mon Sep 17 00:00:00 2001 From: Radek Zikmund Date: Tue, 23 Apr 2024 19:14:33 +0200 Subject: [PATCH 1/6] Add more logging to QuicConnection and QuicStream --- .../Net/Quic/Internal/MsQuicExtensions.cs | 27 ++++++++++++++++--- .../src/System/Net/Quic/QuicConnection.cs | 25 +++++++++++++++++ .../src/System/Net/Quic/QuicStream.cs | 21 +++++++++++++++ 3 files changed, 70 insertions(+), 3 deletions(-) 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 5c079f6528741..231d5b794d94a 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)} = {(IntPtr)NEW_CONNECTION.Connection} }}", _ => 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)} = {(IntPtr)PEER_STREAM_STARTED.Stream} {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)} = {(IntPtr)DATAGRAM_SEND_STATE_CHANGED.ClientContext}, {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)} = {(IntPtr)PEER_CERTIFICATE_RECEIVED.Certificate} }}", + 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 315352d2797bb..395096ca48b3a 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 client connection."); + } + _tlsSecret = MsQuicTlsSecret.Create(_handle); } @@ -278,6 +283,11 @@ internal unsafe QuicConnection(QUIC_HANDLE* handle, QUIC_NEW_CONNECTION_INFO* in throw; } + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Info(this, $"{this} New server connection."); + } + _remoteEndPoint = MsQuicHelpers.QuicAddrToIPEndPoint(info->RemoteAddress); _localEndPoint = MsQuicHelpers.QuicAddrToIPEndPoint(info->LocalAddress); _tlsSecret = MsQuicTlsSecret.Create(_handle); @@ -407,6 +417,11 @@ public async ValueTask OpenOutboundStreamAsync(QuicStreamType type, { ObjectDisposedException.ThrowIf(_disposed == 1, this); + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Info(this, $"{this} Opening {type} stream."); + } + QuicStream? stream = null; try { @@ -482,6 +497,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( @@ -648,6 +668,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/QuicStream.cs b/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicStream.cs index 06515f3310bf7..1ab8aa1fbf9be 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 @@ -180,6 +180,11 @@ internal unsafe QuicStream(MsQuicContextSafeHandle connectionHandle, QuicStreamT _defaultErrorCode = defaultErrorCode; + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Info(this, $"{this} New outgoing {type} stream."); + } + _canRead = type == QuicStreamType.Bidirectional; _canWrite = true; if (!_canRead) @@ -225,6 +230,12 @@ 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; + + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Info(this, $"{this} New incoming {_type} stream, StreamId = {_id}."); + } + _startedTcs.TrySetResult(); } @@ -325,6 +336,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 +706,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) { From 9ade3fca89ea50e16a3b9b597b0be2c6128c1741 Mon Sep 17 00:00:00 2001 From: Radek Zikmund Date: Tue, 23 Apr 2024 19:32:21 +0200 Subject: [PATCH 2/6] Fix ptr format --- .../src/System/Net/Quic/Internal/MsQuicExtensions.cs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) 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 231d5b794d94a..cfc5a09a37171 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 @@ -18,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.Connection)} = {(IntPtr)NEW_CONNECTION.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.Connection)} = 0x{(IntPtr)NEW_CONNECTION.Connection:X11} }}", _ => string.Empty }; } @@ -41,7 +41,7 @@ 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.Stream)} = {(IntPtr)PEER_STREAM_STARTED.Stream} {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 @@ -53,13 +53,13 @@ public override string ToString() 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)} = {(IntPtr)DATAGRAM_SEND_STATE_CHANGED.ClientContext}, {nameof(DATAGRAM_SEND_STATE_CHANGED.State)} = {DATAGRAM_SEND_STATE_CHANGED.State} }}", + => $"{{ {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.Certificate)} = {(IntPtr)PEER_CERTIFICATE_RECEIVED.Certificate} }}", + => $"{{ {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 From 047819952af6f8d7d873f509f813fb73c1d6650b Mon Sep 17 00:00:00 2001 From: Radek Zikmund Date: Tue, 23 Apr 2024 20:20:15 +0200 Subject: [PATCH 3/6] wip --- .../System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs index 64ba4089d5dbc..3efc4c9e25c02 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs @@ -800,6 +800,7 @@ private void BufferBytes(ReadOnlySpan span) while (!Http3Frame.TryReadIntegerPair(_recvBuffer.ActiveSpan, out frameType, out payloadLength, out bytesRead)) { _recvBuffer.EnsureAvailableSpace(VariableLengthIntegerHelper.MaximumEncodedLength * 2); + if (NetEventSource.Log.IsEnabled()) Trace($"Entering read in ReadFrameEnvelopeAsync"); bytesRead = await _stream.ReadAsync(_recvBuffer.AvailableMemory, cancellationToken).ConfigureAwait(false); if (bytesRead != 0) @@ -869,6 +870,7 @@ private async ValueTask ReadHeadersAsync(long headersLength, CancellationToken c { _recvBuffer.EnsureAvailableSpace(1); + if (NetEventSource.Log.IsEnabled()) Trace($"Entering read in ReadHeadersAsync"); int bytesRead = await _stream.ReadAsync(_recvBuffer.AvailableMemory, cancellationToken).ConfigureAwait(false); if (bytesRead != 0) { @@ -1068,6 +1070,7 @@ private async ValueTask SkipUnknownPayloadAsync(long payloadLength, Cancellation if (_recvBuffer.ActiveLength == 0) { _recvBuffer.EnsureAvailableSpace(1); + if (NetEventSource.Log.IsEnabled()) Trace($"Entering read in SkipUnknownPayloadAsync"); int bytesRead = await _stream.ReadAsync(_recvBuffer.AvailableMemory, cancellationToken).ConfigureAwait(false); if (bytesRead != 0) @@ -1205,6 +1208,7 @@ private async ValueTask ReadResponseContentAsync(HttpResponseMessage respon // Receive buffer is empty -- bypass it and read directly into user's buffer. int copyLen = (int)Math.Min(buffer.Length, _responseDataPayloadRemaining); + if (NetEventSource.Log.IsEnabled()) Trace($"Entering read in ReadResponseContentAsync"); int bytesRead = await _stream.ReadAsync(buffer.Slice(0, copyLen), cancellationToken).ConfigureAwait(false); if (bytesRead == 0 && buffer.Length != 0) From 9177ff13e87454a62c851557212ec978d7f7ba92 Mon Sep 17 00:00:00 2001 From: Radek Zikmund Date: Tue, 23 Apr 2024 22:05:26 +0200 Subject: [PATCH 4/6] Add more http3 logging --- .../Net/Http/SocketsHttpHandler/Http3Connection.cs | 13 +++++++++++++ 1 file changed, 13 insertions(+) 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 a4e8efeca6412..75b9d9b1f8a96 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; From 9f09acbf60fa8d5a69b4f07aa6b0e24e6b9881bd Mon Sep 17 00:00:00 2001 From: Radek Zikmund Date: Tue, 23 Apr 2024 22:08:31 +0200 Subject: [PATCH 5/6] fixup! Add more http3 logging --- .../System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs | 4 ---- 1 file changed, 4 deletions(-) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs index 3efc4c9e25c02..64ba4089d5dbc 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs @@ -800,7 +800,6 @@ private void BufferBytes(ReadOnlySpan span) while (!Http3Frame.TryReadIntegerPair(_recvBuffer.ActiveSpan, out frameType, out payloadLength, out bytesRead)) { _recvBuffer.EnsureAvailableSpace(VariableLengthIntegerHelper.MaximumEncodedLength * 2); - if (NetEventSource.Log.IsEnabled()) Trace($"Entering read in ReadFrameEnvelopeAsync"); bytesRead = await _stream.ReadAsync(_recvBuffer.AvailableMemory, cancellationToken).ConfigureAwait(false); if (bytesRead != 0) @@ -870,7 +869,6 @@ private async ValueTask ReadHeadersAsync(long headersLength, CancellationToken c { _recvBuffer.EnsureAvailableSpace(1); - if (NetEventSource.Log.IsEnabled()) Trace($"Entering read in ReadHeadersAsync"); int bytesRead = await _stream.ReadAsync(_recvBuffer.AvailableMemory, cancellationToken).ConfigureAwait(false); if (bytesRead != 0) { @@ -1070,7 +1068,6 @@ private async ValueTask SkipUnknownPayloadAsync(long payloadLength, Cancellation if (_recvBuffer.ActiveLength == 0) { _recvBuffer.EnsureAvailableSpace(1); - if (NetEventSource.Log.IsEnabled()) Trace($"Entering read in SkipUnknownPayloadAsync"); int bytesRead = await _stream.ReadAsync(_recvBuffer.AvailableMemory, cancellationToken).ConfigureAwait(false); if (bytesRead != 0) @@ -1208,7 +1205,6 @@ private async ValueTask ReadResponseContentAsync(HttpResponseMessage respon // Receive buffer is empty -- bypass it and read directly into user's buffer. int copyLen = (int)Math.Min(buffer.Length, _responseDataPayloadRemaining); - if (NetEventSource.Log.IsEnabled()) Trace($"Entering read in ReadResponseContentAsync"); int bytesRead = await _stream.ReadAsync(buffer.Slice(0, copyLen), cancellationToken).ConfigureAwait(false); if (bytesRead == 0 && buffer.Length != 0) From 483bfde382d0779fb1e443f99c29692296471cf1 Mon Sep 17 00:00:00 2001 From: Radek Zikmund Date: Wed, 24 Apr 2024 13:52:56 +0200 Subject: [PATCH 6/6] Code review feedback --- .../src/System/Net/Quic/QuicConnection.cs | 25 +++++++++++-------- .../src/System/Net/Quic/QuicListener.cs | 11 ++++++++ .../src/System/Net/Quic/QuicStream.cs | 10 -------- 3 files changed, 25 insertions(+), 21 deletions(-) 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 395096ca48b3a..e568eeb6f97b7 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 @@ -254,7 +254,7 @@ private unsafe QuicConnection() if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(this, $"{this} New client connection."); + NetEventSource.Info(this, $"{this} New outbound connection."); } _tlsSecret = MsQuicTlsSecret.Create(_handle); @@ -283,11 +283,6 @@ internal unsafe QuicConnection(QUIC_HANDLE* handle, QUIC_NEW_CONNECTION_INFO* in throw; } - if (NetEventSource.Log.IsEnabled()) - { - NetEventSource.Info(this, $"{this} New server connection."); - } - _remoteEndPoint = MsQuicHelpers.QuicAddrToIPEndPoint(info->RemoteAddress); _localEndPoint = MsQuicHelpers.QuicAddrToIPEndPoint(info->LocalAddress); _tlsSecret = MsQuicTlsSecret.Create(_handle); @@ -417,15 +412,16 @@ public async ValueTask OpenOutboundStreamAsync(QuicStreamType type, { ObjectDisposedException.ThrowIf(_disposed == 1, this); - if (NetEventSource.Log.IsEnabled()) - { - NetEventSource.Info(this, $"{this} Opening {type} stream."); - } - QuicStream? stream = null; 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 @@ -571,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()) 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 88ea309054a7d..249f757151913 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 1ab8aa1fbf9be..6af0f5c5c099f 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 @@ -180,11 +180,6 @@ internal unsafe QuicStream(MsQuicContextSafeHandle connectionHandle, QuicStreamT _defaultErrorCode = defaultErrorCode; - if (NetEventSource.Log.IsEnabled()) - { - NetEventSource.Info(this, $"{this} New outgoing {type} stream."); - } - _canRead = type == QuicStreamType.Bidirectional; _canWrite = true; if (!_canRead) @@ -231,11 +226,6 @@ 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; - if (NetEventSource.Log.IsEnabled()) - { - NetEventSource.Info(this, $"{this} New incoming {_type} stream, StreamId = {_id}."); - } - _startedTcs.TrySetResult(); }