Add more logging to HTTP3 and QUIC code (dotnet#101449)

* Add more logging to QuicConnection and QuicStream

* Fix ptr format

* wip

* Add more http3 logging

* fixup! Add more http3 logging

* Code review feedback

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;

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

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<QuicStream> 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))
         {

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

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<ulong>(_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<int> ReadAsync(Memory<byte> 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)
         {