From d766727db87d01c9bdf321565a99d7cfe65d5f6b Mon Sep 17 00:00:00 2001 From: Tomas Weinfurt Date: Sun, 11 Jul 2021 20:32:52 -0700 Subject: [PATCH] make quic tracing easir to correlate with MsQuic (#55483) --- .../MsQuic/MsQuicConnection.cs | 18 ++++++++++--- .../Implementations/MsQuic/MsQuicStream.cs | 27 ++++++++++++------- 2 files changed, 33 insertions(+), 12 deletions(-) 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 dd651ad0ab515..c5df9a21b468b 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 @@ -83,6 +83,7 @@ public void RemoveStream(MsQuicStream? stream) if (releaseHandles) { + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(this, $"{TraceId()} releasing handle after last stream."); Handle?.Dispose(); } } @@ -123,8 +124,15 @@ public void SetClosing() _closing = true; } } + + internal string TraceId() + { + return $"[MsQuicConnection#{this.GetHashCode()}/{Handle?.DangerousGetHandle():x}]"; + } } + 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) { @@ -162,7 +170,7 @@ public MsQuicConnection(IPEndPoint localEndPoint, IPEndPoint remoteEndPoint, Saf if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(_state, $"[Connection#{_state.GetHashCode()}] inbound connection created"); + NetEventSource.Info(_state, $"{TraceId()} inbound connection created"); } } @@ -201,7 +209,7 @@ public MsQuicConnection(QuicClientConnectionOptions options) if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(_state, $"[Connection#{_state.GetHashCode()}] outbound connection created"); + NetEventSource.Info(_state, $"{TraceId()} outbound connection created"); } } @@ -621,7 +629,7 @@ private static uint NativeCallbackHandler( if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(state, $"[Connection#{state.GetHashCode()}] received event {connectionEvent.Type}"); + NetEventSource.Info(state, $"{state.TraceId()} received event {connectionEvent.Type}"); } try @@ -697,6 +705,8 @@ private void Dispose(bool disposing) return; } + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(_state, $"{TraceId()} disposing {disposing}"); + bool releaseHandles = false; lock (_state) { @@ -716,6 +726,8 @@ private void Dispose(bool disposing) _configuration?.Dispose(); if (releaseHandles) { + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(_state, $"{TraceId()} 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/MsQuicStream.cs b/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicStream.cs index fed61e11e5695..f962dbc81fd71 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 @@ -69,6 +69,8 @@ private sealed class State public void Cleanup() { + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(this, $"{TraceId()} releasing handles."); + ShutdownState = ShutdownState.Finished; CleanupSendState(this); Handle?.Dispose(); @@ -77,8 +79,15 @@ 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(); + // inbound. internal MsQuicStream(MsQuicConnection.State connectionState, SafeMsQuicStreamHandle streamHandle, QUIC_STREAM_OPEN_FLAGS flags) { @@ -117,8 +126,8 @@ internal MsQuicStream(MsQuicConnection.State connectionState, SafeMsQuicStreamHa { NetEventSource.Info( _state, - $"[Stream#{_state.GetHashCode()}] inbound {(flags.HasFlag(QUIC_STREAM_OPEN_FLAGS.UNIDIRECTIONAL) ? "uni" : "bi")}directional stream created " + - $"in Connection#{_state.ConnectionState.GetHashCode()}."); + $"{TraceId()} inbound {(flags.HasFlag(QUIC_STREAM_OPEN_FLAGS.UNIDIRECTIONAL) ? "uni" : "bi")}directional stream created " + + $"in {_state.ConnectionState.TraceId()}."); } } @@ -170,8 +179,8 @@ internal MsQuicStream(MsQuicConnection.State connectionState, QUIC_STREAM_OPEN_F { NetEventSource.Info( _state, - $"[Stream#{_state.GetHashCode()}] outbound {(flags.HasFlag(QUIC_STREAM_OPEN_FLAGS.UNIDIRECTIONAL) ? "uni" : "bi")}directional stream created " + - $"in Connection#{_state.ConnectionState.GetHashCode()}."); + $"{TraceId()} outbound {(flags.HasFlag(QUIC_STREAM_OPEN_FLAGS.UNIDIRECTIONAL) ? "uni" : "bi")}directional stream created " + + $"in {_state.ConnectionState.TraceId()}."); } } @@ -647,6 +656,9 @@ private void Dispose(bool disposing) return; } + + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(_state, $"{TraceId()} disposing {disposing}"); + bool callShutdown = false; bool abortRead = false; bool releaseHandles = false; @@ -698,10 +710,7 @@ private void Dispose(bool disposing) _state.Cleanup(); } - if (NetEventSource.Log.IsEnabled()) - { - NetEventSource.Info(_state, $"[Stream#{_state.GetHashCode()}] disposed"); - } + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(_state, $"{TraceId()} disposed"); } private void EnableReceive() @@ -726,7 +735,7 @@ private static uint HandleEvent(State state, ref StreamEvent evt) { if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(state, $"[Stream#{state.GetHashCode()}] received event {evt.Type}"); + NetEventSource.Info(state, $"{state.TraceId()} received event {evt.Type}"); } try