From 00351d9d0c4d597fd5e7dced6d896a6dbd3d1e7c Mon Sep 17 00:00:00 2001 From: Natalia Kondratyeva Date: Sat, 10 Jul 2021 22:19:45 +0200 Subject: [PATCH 1/3] Update logging to use msquic pointers --- .../src/System.Net.Quic.csproj | 1 + .../MsQuic/Interop/MsQuicLogHelper.cs | 30 +++++++++++++++++++ .../MsQuic/MsQuicConnection.cs | 22 ++++++++------ .../Implementations/MsQuic/MsQuicListener.cs | 12 ++++++++ .../Implementations/MsQuic/MsQuicStream.cs | 27 +++++++++-------- 5 files changed, 71 insertions(+), 21 deletions(-) create mode 100644 src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/MsQuicLogHelper.cs 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..e7c4a82fb13e3 100644 --- a/src/libraries/System.Net.Quic/src/System.Net.Quic.csproj +++ b/src/libraries/System.Net.Quic/src/System.Net.Quic.csproj @@ -17,6 +17,7 @@ + diff --git a/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/MsQuicLogHelper.cs b/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/MsQuicLogHelper.cs new file mode 100644 index 0000000000000..7fd698fb5a41a --- /dev/null +++ b/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/MsQuicLogHelper.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 MsQuicLogHelper + { + internal static string GetLogId(SafeMsQuicStreamHandle handle) + { + return $"[strm][0x{GetIntPtrHex(handle)}]"; + } + + internal static string GetLogId(SafeMsQuicConnectionHandle handle) + { + return $"[conn][0x{GetIntPtrHex(handle)}]"; + } + + internal static string GetLogId(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 a90f03467b0a0..6c8f1ccb24754 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 LogId = 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). @@ -149,9 +151,10 @@ public MsQuicConnection(IPEndPoint localEndPoint, IPEndPoint remoteEndPoint, Saf throw; } + _state.LogId = MsQuicLogHelper.GetLogId(_state.Handle); if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(_state, $"[Connection#{_state.GetHashCode()}] inbound connection created"); + NetEventSource.Info(_state, $"{_state.LogId} Inbound connection created"); } } @@ -188,9 +191,10 @@ public MsQuicConnection(QuicClientConnectionOptions options) throw; } + _state.LogId = MsQuicLogHelper.GetLogId(_state.Handle); if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(_state, $"[Connection#{_state.GetHashCode()}] outbound connection created"); + NetEventSource.Info(_state, $"{_state.LogId} Outbound connection created"); } } @@ -366,7 +370,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.LogId} Remote certificate required, but no remote certificate received"); sslPolicyErrors |= SslPolicyErrors.RemoteCertificateNotAvailable; } else @@ -396,18 +400,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.LogId} 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.LogId} 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.LogId} Certificate validation failed ${ex.Message}"); } return MsQuicStatusCodes.InternalError; @@ -605,7 +609,7 @@ internal void SetNegotiatedAlpn(IntPtr alpn, int alpnLength) if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(state, $"[Connection#{state.GetHashCode()}] received event {connectionEvent.Type}"); + NetEventSource.Info(state, $"{state.LogId} Connection received event {connectionEvent.Type}"); } try @@ -634,10 +638,10 @@ internal void SetNegotiatedAlpn(IntPtr alpn, int alpnLength) { if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Error(state, $"[Connection#{state.GetHashCode()}] Exception occurred during handling {connectionEvent.Type} connection callback: {ex}"); + NetEventSource.Error(state, $"{state.LogId} 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.LogId} Exception occurred during handling {connectionEvent.Type} connection callback: {ex}"); // TODO: trigger an exception on any outstanding async calls. 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 97c1973e081c2..1993ce9bdd72f 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 @@ -28,6 +28,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 LogId = null!; // set in ctor. public readonly SafeMsQuicConfigurationHandle ConnectionConfiguration; public readonly Channel AcceptConnectionQueue; @@ -64,7 +65,18 @@ internal MsQuicListener(QuicListenerOptions options) throw; } + _state.LogId = MsQuicLogHelper.GetLogId(_state.Handle); + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Info(_state, $"{_state.LogId} Listener created"); + } + _listenEndPoint = Start(options); + + if (NetEventSource.Log.IsEnabled()) + { + NetEventSource.Info(_state, $"{_state.LogId} 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 8260dfdd68fa7..35b48a8dd606b 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 LogId = null!; // set in ctor. public ReadState ReadState; public long ReadErrorCode = -1; @@ -108,12 +109,13 @@ internal MsQuicStream(MsQuicConnection.State connectionState, SafeMsQuicStreamHa _state.ConnectionState = connectionState; + _state.LogId = MsQuicLogHelper.GetLogId(_state.Handle); if (NetEventSource.Log.IsEnabled()) { NetEventSource.Info( _state, - $"[Stream#{_state.GetHashCode()}] inbound {(flags.HasFlag(QUIC_STREAM_OPEN_FLAGS.UNIDIRECTIONAL) ? "uni" : "bi")}directional stream created " + - $"in Connection#{_state.ConnectionState.GetHashCode()}."); + $"{_state.LogId} Inbound {(flags.HasFlag(QUIC_STREAM_OPEN_FLAGS.UNIDIRECTIONAL) ? "uni" : "bi")}directional stream created " + + $"in connection {_state.ConnectionState.LogId}."); } } @@ -158,12 +160,13 @@ internal MsQuicStream(MsQuicConnection.State connectionState, QUIC_STREAM_OPEN_F _state.ConnectionState = connectionState; + _state.LogId = MsQuicLogHelper.GetLogId(_state.Handle); if (NetEventSource.Log.IsEnabled()) { NetEventSource.Info( _state, - $"[Stream#{_state.GetHashCode()}] outbound {(flags.HasFlag(QUIC_STREAM_OPEN_FLAGS.UNIDIRECTIONAL) ? "uni" : "bi")}directional stream created " + - $"in Connection#{_state.ConnectionState.GetHashCode()}."); + $"{_state.LogId} Outbound {(flags.HasFlag(QUIC_STREAM_OPEN_FLAGS.UNIDIRECTIONAL) ? "uni" : "bi")}directional stream created " + + $"in connection {_state.ConnectionState.LogId}."); } } @@ -349,7 +352,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, $"{_state.LogId} Stream reading into Memory of '{destination.Length}' bytes."); } lock (_state) @@ -681,7 +684,7 @@ private void Dispose(bool disposing) if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(_state, $"[Stream#{_state.GetHashCode()}] disposed"); + NetEventSource.Info(_state, $"{_state.LogId} Stream disposed"); } } @@ -707,7 +710,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.LogId} Stream received event {evt.Type}"); } try @@ -750,12 +753,12 @@ private static uint HandleEvent(State state, ref StreamEvent evt) { if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Error(state, $"[Stream#{state.GetHashCode()}] Exception occurred during handling {(QUIC_STREAM_EVENT_TYPE)evt.Type} event: {ex}"); + NetEventSource.Error(state, $"{state.LogId} Exception occurred during handling {(QUIC_STREAM_EVENT_TYPE)evt.Type} stream event: {ex}"); } // This is getting hit currently // See https://github.com/dotnet/runtime/issues/55302 - //Debug.Fail($"[Stream#{state.GetHashCode()}] Exception occurred during handling {(QUIC_STREAM_EVENT_TYPE)evt.Type} event: {ex}"); + //Debug.Fail($"{state.LogId} Exception occurred during handling {(QUIC_STREAM_EVENT_TYPE)evt.Type} stream event: {ex}"); return MsQuicStatusCodes.InternalError; } @@ -868,7 +871,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.LogId} Stream completing resettable event source."); if (state.ReadState == ReadState.None) { @@ -947,7 +950,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.LogId} Stream completing resettable event source."); if (state.ReadState == ReadState.None) { @@ -1237,7 +1240,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.LogId} Stream handling connection {state.ConnectionState.LogId} close" + (errorCode != -1 ? $" with code {errorCode}" : "")); } From f625a0a2fe6eef4b64923d77202499d7d91e4280 Mon Sep 17 00:00:00 2001 From: Natalia Kondratyeva Date: Mon, 12 Jul 2021 12:11:26 +0200 Subject: [PATCH 2/3] rename LogId -> TraceId --- .../src/System.Net.Quic.csproj | 2 +- ...sQuicLogHelper.cs => MsQuicTraceHelper.cs} | 8 +++--- .../MsQuic/MsQuicConnection.cs | 24 ++++++++-------- .../Implementations/MsQuic/MsQuicListener.cs | 8 +++--- .../Implementations/MsQuic/MsQuicStream.cs | 28 +++++++++---------- 5 files changed, 35 insertions(+), 35 deletions(-) rename src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/{MsQuicLogHelper.cs => MsQuicTraceHelper.cs} (72%) 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 e7c4a82fb13e3..1cd17da1d873e 100644 --- a/src/libraries/System.Net.Quic/src/System.Net.Quic.csproj +++ b/src/libraries/System.Net.Quic/src/System.Net.Quic.csproj @@ -17,10 +17,10 @@ - + diff --git a/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/MsQuicLogHelper.cs b/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/MsQuicTraceHelper.cs similarity index 72% rename from src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/MsQuicLogHelper.cs rename to src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/MsQuicTraceHelper.cs index 7fd698fb5a41a..33ef7b948c9b6 100644 --- a/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/MsQuicLogHelper.cs +++ b/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/MsQuicTraceHelper.cs @@ -5,19 +5,19 @@ namespace System.Net.Quic.Implementations.MsQuic.Internal { - internal static class MsQuicLogHelper + internal static class MsQuicTraceHelper { - internal static string GetLogId(SafeMsQuicStreamHandle handle) + internal static string GetTraceId(SafeMsQuicStreamHandle handle) { return $"[strm][0x{GetIntPtrHex(handle)}]"; } - internal static string GetLogId(SafeMsQuicConnectionHandle handle) + internal static string GetTraceId(SafeMsQuicConnectionHandle handle) { return $"[conn][0x{GetIntPtrHex(handle)}]"; } - internal static string GetLogId(SafeMsQuicListenerHandle handle) + internal static string GetTraceId(SafeMsQuicListenerHandle handle) { return $"[list][0x{GetIntPtrHex(handle)}]"; } 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 294680dd852aa..cf4aa16c27269 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,7 +43,7 @@ internal sealed class MsQuicConnection : QuicConnectionProvider internal sealed class State { public SafeMsQuicConnectionHandle Handle = null!; // set inside of MsQuicConnection ctor. - public string LogId = null!; // set inside of MsQuicConnection ctor. + public string TraceId = null!; // set inside of MsQuicConnection ctor. public GCHandle StateGCHandle; @@ -85,7 +85,7 @@ public void RemoveStream(MsQuicStream? stream) if (releaseHandles) { - if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(this, $"{LogId} releasing handle after last stream."); + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(this, $"{TraceId} releasing handle after last stream."); Handle?.Dispose(); } } @@ -128,7 +128,7 @@ public void SetClosing() } } - internal string TraceId() => _state.LogId; + 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) @@ -165,7 +165,7 @@ public MsQuicConnection(IPEndPoint localEndPoint, IPEndPoint remoteEndPoint, Saf throw; } - _state.LogId = MsQuicLogHelper.GetLogId(_state.Handle); + _state.TraceId = MsQuicLogHelper.GetTraceId(_state.Handle); if (NetEventSource.Log.IsEnabled()) { NetEventSource.Info(_state, $"{TraceId()} Inbound connection created"); @@ -205,7 +205,7 @@ public MsQuicConnection(QuicClientConnectionOptions options) throw; } - _state.LogId = MsQuicLogHelper.GetLogId(_state.Handle); + _state.TraceId = MsQuicLogHelper.GetTraceId(_state.Handle); if (NetEventSource.Log.IsEnabled()) { NetEventSource.Info(_state, $"{TraceId()} Outbound connection created"); @@ -389,7 +389,7 @@ private static uint HandleEventPeerCertificateReceived(State state, ref Connecti if (certificate == null) { - if (NetEventSource.Log.IsEnabled() && connection._remoteCertificateRequired) NetEventSource.Error(state, $"{state.LogId} 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 @@ -419,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, $"{state.LogId} 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, $"{state.LogId} 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, $"{state.LogId} Certificate validation failed ${ex.Message}"); + if (NetEventSource.Log.IsEnabled()) NetEventSource.Error(state, $"{state.TraceId} Certificate validation failed ${ex.Message}"); } return MsQuicStatusCodes.InternalError; @@ -628,7 +628,7 @@ internal void SetNegotiatedAlpn(IntPtr alpn, int alpnLength) if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(state, $"{state.LogId} Connection received event {connectionEvent.Type}"); + NetEventSource.Info(state, $"{state.TraceId} Connection received event {connectionEvent.Type}"); } try @@ -657,10 +657,10 @@ internal void SetNegotiatedAlpn(IntPtr alpn, int alpnLength) { if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Error(state, $"{state.LogId} 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($"{state.LogId} 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. 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 c95bdeb8054ae..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,7 +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 LogId = null!; // set in ctor. + public string TraceId = null!; // set in ctor. public readonly SafeMsQuicConfigurationHandle ConnectionConfiguration; public readonly Channel AcceptConnectionQueue; @@ -76,17 +76,17 @@ internal MsQuicListener(QuicListenerOptions options) throw; } - _state.LogId = MsQuicLogHelper.GetLogId(_state.Handle); + _state.TraceId = MsQuicTraceHelper.GetTraceId(_state.Handle); if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(_state, $"{_state.LogId} Listener created"); + NetEventSource.Info(_state, $"{_state.TraceId} Listener created"); } _listenEndPoint = Start(options); if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(_state, $"{_state.LogId} Listener started"); + NetEventSource.Info(_state, $"{_state.TraceId} Listener started"); } } 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 c2d6e4c5debf5..12bc39586b110 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,7 +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 LogId = null!; // set in ctor. + public string TraceId = null!; // set in ctor. public ReadState ReadState; public long ReadErrorCode = -1; @@ -67,7 +67,7 @@ private sealed class State public void Cleanup() { - if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(this, $"{LogId} releasing handles."); + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(this, $"{TraceId} releasing handles."); ShutdownState = ShutdownState.Finished; CleanupSendState(this); @@ -79,7 +79,7 @@ public void Cleanup() } } - internal string TraceId() => _state.LogId; + internal string TraceId() => _state.TraceId; // inbound. internal MsQuicStream(MsQuicConnection.State connectionState, SafeMsQuicStreamHandle streamHandle, QUIC_STREAM_OPEN_FLAGS flags) @@ -114,13 +114,13 @@ internal MsQuicStream(MsQuicConnection.State connectionState, SafeMsQuicStreamHa _state.ConnectionState = connectionState; - _state.LogId = MsQuicLogHelper.GetLogId(_state.Handle); + _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 connection {_state.ConnectionState.LogId}."); + $"in connection {_state.ConnectionState.TraceId}."); } } @@ -168,13 +168,13 @@ internal MsQuicStream(MsQuicConnection.State connectionState, QUIC_STREAM_OPEN_F _state.ConnectionState = connectionState; - _state.LogId = MsQuicLogHelper.GetLogId(_state.Handle); + _state.TraceId = MsQuicTraceHelper.GetTraceId(_state.Handle); if (NetEventSource.Log.IsEnabled()) { NetEventSource.Info( _state, - $"{_state.LogId} Outbound {(flags.HasFlag(QUIC_STREAM_OPEN_FLAGS.UNIDIRECTIONAL) ? "uni" : "bi")}directional stream created " + - $"in connection {_state.ConnectionState.LogId}."); + $"{_state.TraceId} Outbound {(flags.HasFlag(QUIC_STREAM_OPEN_FLAGS.UNIDIRECTIONAL) ? "uni" : "bi")}directional stream created " + + $"in connection {_state.ConnectionState.TraceId}."); } } @@ -722,7 +722,7 @@ private static uint HandleEvent(State state, ref StreamEvent evt) { if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(state, $"{state.LogId} Stream received event {evt.Type}"); + NetEventSource.Info(state, $"{state.TraceId} Stream received event {evt.Type}"); } try @@ -765,10 +765,10 @@ private static uint HandleEvent(State state, ref StreamEvent evt) { if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Error(state, $"{state.LogId} Exception occurred during handling Stream {evt.Type} event: {ex}"); + NetEventSource.Error(state, $"{state.TraceId} Exception occurred during handling Stream {evt.Type} event: {ex}"); } - Debug.Fail($"{state.LogId} Exception occurred during handling Stream {evt.Type} event: {ex}"); + Debug.Fail($"{state.TraceId} Exception occurred during handling Stream {evt.Type} event: {ex}"); return MsQuicStatusCodes.InternalError; } @@ -869,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, $"{state.LogId} Stream completing resettable event source."); + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(state, $"{state.TraceId} Stream completing resettable event source."); if (state.ReadState == ReadState.None) { @@ -948,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, $"{state.LogId} Stream completing resettable event source."); + if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(state, $"{state.TraceId} Stream completing resettable event source."); if (state.ReadState == ReadState.None) { @@ -1238,7 +1238,7 @@ private static uint HandleEventConnectionClose(State state) long errorCode = state.ConnectionState.AbortErrorCode; if (NetEventSource.Log.IsEnabled()) { - NetEventSource.Info(state, $"{state.LogId} Stream handling connection {state.ConnectionState.LogId} close" + + NetEventSource.Info(state, $"{state.TraceId} Stream handling connection {state.ConnectionState.TraceId} close" + (errorCode != -1 ? $" with code {errorCode}" : "")); } From 366b45db53e5ecd08bc8773a24fe502977524a70 Mon Sep 17 00:00:00 2001 From: Natalia Kondratyeva Date: Mon, 12 Jul 2021 12:32:23 +0200 Subject: [PATCH 3/3] fix --- .../Net/Quic/Implementations/MsQuic/MsQuicConnection.cs | 8 ++++---- .../Net/Quic/Implementations/MsQuic/MsQuicStream.cs | 2 +- 2 files changed, 5 insertions(+), 5 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 cf4aa16c27269..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 @@ -165,7 +165,7 @@ public MsQuicConnection(IPEndPoint localEndPoint, IPEndPoint remoteEndPoint, Saf throw; } - _state.TraceId = MsQuicLogHelper.GetTraceId(_state.Handle); + _state.TraceId = MsQuicTraceHelper.GetTraceId(_state.Handle); if (NetEventSource.Log.IsEnabled()) { NetEventSource.Info(_state, $"{TraceId()} Inbound connection created"); @@ -205,7 +205,7 @@ public MsQuicConnection(QuicClientConnectionOptions options) throw; } - _state.TraceId = MsQuicLogHelper.GetTraceId(_state.Handle); + _state.TraceId = MsQuicTraceHelper.GetTraceId(_state.Handle); if (NetEventSource.Log.IsEnabled()) { NetEventSource.Info(_state, $"{TraceId()} Outbound connection created"); @@ -704,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) @@ -725,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/MsQuicStream.cs b/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicStream.cs index 12bc39586b110..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 @@ -644,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;