diff --git a/src/libraries/System.Net.Quic/src/System.Net.Quic.csproj b/src/libraries/System.Net.Quic/src/System.Net.Quic.csproj index 6d8de7f5d6c8a..1cd17da1d873e 100644 --- a/src/libraries/System.Net.Quic/src/System.Net.Quic.csproj +++ b/src/libraries/System.Net.Quic/src/System.Net.Quic.csproj @@ -20,6 +20,7 @@ + diff --git a/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/MsQuicTraceHelper.cs b/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/MsQuicTraceHelper.cs new file mode 100644 index 0000000000000..33ef7b948c9b6 --- /dev/null +++ b/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/MsQuicTraceHelper.cs @@ -0,0 +1,30 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Runtime.InteropServices; + +namespace System.Net.Quic.Implementations.MsQuic.Internal +{ + internal static class MsQuicTraceHelper + { + internal static string GetTraceId(SafeMsQuicStreamHandle handle) + { + return $"[strm][0x{GetIntPtrHex(handle)}]"; + } + + internal static string GetTraceId(SafeMsQuicConnectionHandle handle) + { + return $"[conn][0x{GetIntPtrHex(handle)}]"; + } + + internal static string GetTraceId(SafeMsQuicListenerHandle handle) + { + return $"[list][0x{GetIntPtrHex(handle)}]"; + } + + private static string GetIntPtrHex(SafeHandle handle) + { + return handle.DangerousGetHandle().ToString("X11"); + } + } +} \ No newline at end of file diff --git a/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicConnection.cs b/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicConnection.cs index c5df9a21b468b..ec1710316c125 100644 --- a/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicConnection.cs +++ b/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicConnection.cs @@ -43,6 +43,8 @@ internal sealed class MsQuicConnection : QuicConnectionProvider internal sealed class State { public SafeMsQuicConnectionHandle Handle = null!; // set inside of MsQuicConnection ctor. + public string TraceId = null!; // set inside of MsQuicConnection ctor. + public GCHandle StateGCHandle; // These exists to prevent GC of the MsQuicConnection in the middle of an async op (Connect or Shutdown). @@ -83,7 +85,7 @@ public void RemoveStream(MsQuicStream? stream) if (releaseHandles) { - if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(this, $"{TraceId()} releasing handle after last stream."); + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(this, $"{TraceId} releasing handle after last stream."); Handle?.Dispose(); } } @@ -124,14 +126,9 @@ public void SetClosing() _closing = true; } } - - internal string TraceId() - { - return $"[MsQuicConnection#{this.GetHashCode()}/{Handle?.DangerousGetHandle():x}]"; - } } - internal string TraceId() => _state.TraceId(); + internal string TraceId() => _state.TraceId; // constructor for inbound connections public MsQuicConnection(IPEndPoint localEndPoint, IPEndPoint remoteEndPoint, SafeMsQuicConnectionHandle handle, bool remoteCertificateRequired = false, X509RevocationMode revocationMode = X509RevocationMode.Offline, RemoteCertificateValidationCallback? remoteCertificateValidationCallback = null) @@ -168,9 +165,10 @@ public MsQuicConnection(IPEndPoint localEndPoint, IPEndPoint remoteEndPoint, Saf throw; } + _state.TraceId = MsQuicTraceHelper.GetTraceId(_state.Handle); if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(_state, $"{TraceId()} inbound connection created"); + NetEventSource.Info(_state, $"{TraceId()} Inbound connection created"); } } @@ -207,9 +205,10 @@ public MsQuicConnection(QuicClientConnectionOptions options) throw; } + _state.TraceId = MsQuicTraceHelper.GetTraceId(_state.Handle); if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(_state, $"{TraceId()} outbound connection created"); + NetEventSource.Info(_state, $"{TraceId()} Outbound connection created"); } } @@ -390,7 +389,7 @@ private static uint HandleEventPeerCertificateReceived(State state, ref Connecti if (certificate == null) { - if (NetEventSource.Log.IsEnabled() && connection._remoteCertificateRequired) NetEventSource.Error(state.Connection, "Remote certificate required, but no remote certificate received"); + if (NetEventSource.Log.IsEnabled() && connection._remoteCertificateRequired) NetEventSource.Error(state, $"{state.TraceId} Remote certificate required, but no remote certificate received"); sslPolicyErrors |= SslPolicyErrors.RemoteCertificateNotAvailable; } else @@ -420,18 +419,18 @@ private static uint HandleEventPeerCertificateReceived(State state, ref Connecti { bool success = connection._remoteCertificateValidationCallback(connection, certificate, chain, sslPolicyErrors); if (!success && NetEventSource.Log.IsEnabled()) - NetEventSource.Error(state, $"[Connection#{state.GetHashCode()}] remote certificate rejected by verification callback"); + NetEventSource.Error(state, $"{state.TraceId} Remote certificate rejected by verification callback"); return success ? MsQuicStatusCodes.Success : MsQuicStatusCodes.HandshakeFailure; } if (NetEventSource.Log.IsEnabled()) - NetEventSource.Info(state, $"[Connection#{state.GetHashCode()}] certificate validation for '${certificate?.Subject}' finished with ${sslPolicyErrors}"); + NetEventSource.Info(state, $"{state.TraceId} Certificate validation for '${certificate?.Subject}' finished with ${sslPolicyErrors}"); return (sslPolicyErrors == SslPolicyErrors.None) ? MsQuicStatusCodes.Success : MsQuicStatusCodes.HandshakeFailure; } catch (Exception ex) { - if (NetEventSource.Log.IsEnabled()) NetEventSource.Error(state, $"[Connection#{state.GetHashCode()}] certificate validation failed ${ex.Message}"); + if (NetEventSource.Log.IsEnabled()) NetEventSource.Error(state, $"{state.TraceId} Certificate validation failed ${ex.Message}"); } return MsQuicStatusCodes.InternalError; @@ -629,7 +628,7 @@ private static uint NativeCallbackHandler( if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(state, $"{state.TraceId()} received event {connectionEvent.Type}"); + NetEventSource.Info(state, $"{state.TraceId} Connection received event {connectionEvent.Type}"); } try @@ -658,10 +657,10 @@ private static uint NativeCallbackHandler( { if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Error(state, $"[Connection#{state.GetHashCode()}] Exception occurred during handling {connectionEvent.Type} connection callback: {ex}"); + NetEventSource.Error(state, $"{state.TraceId} Exception occurred during handling {connectionEvent.Type} connection callback: {ex}"); } - Debug.Fail($"[Connection#{state.GetHashCode()}] Exception occurred during handling {connectionEvent.Type} connection callback: {ex}"); + Debug.Fail($"{state.TraceId} Exception occurred during handling {connectionEvent.Type} connection callback: {ex}"); // TODO: trigger an exception on any outstanding async calls. @@ -705,7 +704,7 @@ private void Dispose(bool disposing) return; } - if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(_state, $"{TraceId()} disposing {disposing}"); + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(_state, $"{TraceId()} Stream disposing {disposing}"); bool releaseHandles = false; lock (_state) @@ -726,7 +725,7 @@ private void Dispose(bool disposing) _configuration?.Dispose(); if (releaseHandles) { - if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(_state, $"{TraceId()} releasing handle"); + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(_state, $"{TraceId()} Connection releasing handle"); // We may not be fully initialized if constructor fails. _state.Handle?.Dispose(); diff --git a/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicListener.cs b/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicListener.cs index c5ef5d3fdce36..391d26a93ddd3 100644 --- a/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicListener.cs +++ b/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicListener.cs @@ -29,6 +29,7 @@ private sealed class State { // set immediately in ctor, but we need a GCHandle to State in order to create the handle. public SafeMsQuicListenerHandle Handle = null!; + public string TraceId = null!; // set in ctor. public readonly SafeMsQuicConfigurationHandle ConnectionConfiguration; public readonly Channel AcceptConnectionQueue; @@ -75,7 +76,18 @@ internal MsQuicListener(QuicListenerOptions options) throw; } + _state.TraceId = MsQuicTraceHelper.GetTraceId(_state.Handle); + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Info(_state, $"{_state.TraceId} Listener created"); + } + _listenEndPoint = Start(options); + + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Info(_state, $"{_state.TraceId} Listener started"); + } } internal override IPEndPoint ListenEndPoint diff --git a/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicStream.cs b/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicStream.cs index f66f05fdb1cef..437f81ce7759b 100644 --- a/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicStream.cs +++ b/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicStream.cs @@ -33,6 +33,7 @@ private sealed class State public SafeMsQuicStreamHandle Handle = null!; // set in ctor. public GCHandle StateGCHandle; public MsQuicConnection.State ConnectionState = null!; // set in ctor. + public string TraceId = null!; // set in ctor. public ReadState ReadState; public long ReadErrorCode = -1; @@ -66,7 +67,7 @@ private sealed class State public void Cleanup() { - if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(this, $"{TraceId()} releasing handles."); + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(this, $"{TraceId} releasing handles."); ShutdownState = ShutdownState.Finished; CleanupSendState(this); @@ -76,14 +77,9 @@ public void Cleanup() if (StateGCHandle.IsAllocated) StateGCHandle.Free(); ConnectionState?.RemoveStream(null); } - - internal string TraceId() - { - return $"[MsQuicStream#{this.GetHashCode()}/{Handle?.DangerousGetHandle():x}]"; - } } - internal string TraceId() => _state.TraceId(); + internal string TraceId() => _state.TraceId; // inbound. internal MsQuicStream(MsQuicConnection.State connectionState, SafeMsQuicStreamHandle streamHandle, QUIC_STREAM_OPEN_FLAGS flags) @@ -118,12 +114,13 @@ internal MsQuicStream(MsQuicConnection.State connectionState, SafeMsQuicStreamHa _state.ConnectionState = connectionState; + _state.TraceId = MsQuicTraceHelper.GetTraceId(_state.Handle); if (NetEventSource.Log.IsEnabled()) { NetEventSource.Info( _state, - $"{TraceId()} inbound {(flags.HasFlag(QUIC_STREAM_OPEN_FLAGS.UNIDIRECTIONAL) ? "uni" : "bi")}directional stream created " + - $"in {_state.ConnectionState.TraceId()}."); + $"{TraceId()} Inbound {(flags.HasFlag(QUIC_STREAM_OPEN_FLAGS.UNIDIRECTIONAL) ? "uni" : "bi")}directional stream created " + + $"in connection {_state.ConnectionState.TraceId}."); } } @@ -171,12 +168,13 @@ internal MsQuicStream(MsQuicConnection.State connectionState, QUIC_STREAM_OPEN_F _state.ConnectionState = connectionState; + _state.TraceId = MsQuicTraceHelper.GetTraceId(_state.Handle); if (NetEventSource.Log.IsEnabled()) { NetEventSource.Info( _state, - $"{TraceId()} outbound {(flags.HasFlag(QUIC_STREAM_OPEN_FLAGS.UNIDIRECTIONAL) ? "uni" : "bi")}directional stream created " + - $"in {_state.ConnectionState.TraceId()}."); + $"{_state.TraceId} Outbound {(flags.HasFlag(QUIC_STREAM_OPEN_FLAGS.UNIDIRECTIONAL) ? "uni" : "bi")}directional stream created " + + $"in connection {_state.ConnectionState.TraceId}."); } } @@ -366,7 +364,7 @@ internal override async ValueTask ReadAsync(Memory destination, Cance if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(_state, $"[Stream#{_state.GetHashCode()}] reading into Memory of '{destination.Length}' bytes."); + NetEventSource.Info(_state, $"{TraceId()} Stream reading into Memory of '{destination.Length}' bytes."); } lock (_state) @@ -646,7 +644,7 @@ private void Dispose(bool disposing) } - if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(_state, $"{TraceId()} disposing {disposing}"); + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(_state, $"{TraceId()} Stream disposing {disposing}"); bool callShutdown = false; bool abortRead = false; @@ -699,7 +697,7 @@ private void Dispose(bool disposing) _state.Cleanup(); } - if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(_state, $"{TraceId()} disposed"); + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(_state, $"{TraceId()} Stream disposed"); } private void EnableReceive() @@ -724,7 +722,7 @@ private static uint HandleEvent(State state, ref StreamEvent evt) { if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(state, $"{state.TraceId()} received event {evt.Type}"); + NetEventSource.Info(state, $"{state.TraceId} Stream received event {evt.Type}"); } try @@ -767,10 +765,10 @@ private static uint HandleEvent(State state, ref StreamEvent evt) { if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Error(state, $"[Stream#{state.GetHashCode()}] Exception occurred during handling {evt.Type} event: {ex}"); + NetEventSource.Error(state, $"{state.TraceId} Exception occurred during handling Stream {evt.Type} event: {ex}"); } - Debug.Fail($"[Stream#{state.GetHashCode()}] Exception occurred during handling {evt.Type} event: {ex}"); + Debug.Fail($"{state.TraceId} Exception occurred during handling Stream {evt.Type} event: {ex}"); return MsQuicStatusCodes.InternalError; } @@ -871,7 +869,7 @@ private static uint HandleEventShutdownComplete(State state, ref StreamEvent evt lock (state) { // This event won't occur within the middle of a receive. - if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(state, $"[Stream#{state.GetHashCode()}] completing resettable event source."); + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(state, $"{state.TraceId} Stream completing resettable event source."); if (state.ReadState == ReadState.None) { @@ -950,7 +948,7 @@ private static uint HandleEventPeerSendShutdown(State state) lock (state) { // This event won't occur within the middle of a receive. - if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(state, $"[Stream#{state.GetHashCode()}] completing resettable event source."); + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(state, $"{state.TraceId} Stream completing resettable event source."); if (state.ReadState == ReadState.None) { @@ -1240,7 +1238,7 @@ private static uint HandleEventConnectionClose(State state) long errorCode = state.ConnectionState.AbortErrorCode; if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(state, $"[Stream#{state.GetHashCode()}] handling Connection#{state.ConnectionState.GetHashCode()} close" + + NetEventSource.Info(state, $"{state.TraceId} Stream handling connection {state.ConnectionState.TraceId} close" + (errorCode != -1 ? $" with code {errorCode}" : "")); }