Skip to content

Commit

Permalink
QUIC logging update (#55500)
Browse files Browse the repository at this point in the history 
Together with #55483 this updates all logging to use msquic handles instead of hash code - for listeners, connections and streams. The format of handle is the same as msquic one.
  • Loading branch information
@CarnaViire
CarnaViire authored Jul 12, 2021
1 parent 633e044 commit 102fc35
Show file tree
Hide file tree
Showing 5 changed files with 78 additions and 38 deletions.
1 change: 1 addition & 0 deletions src/libraries/System.Net.Quic/src/System.Net.Quic.csproj
View file
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@
<Compile Include="System\Net\Quic\Implementations\MsQuic\Interop\MsQuicNativeMethods.cs" />
<Compile Include="System\Net\Quic\Implementations\MsQuic\Interop\MsQuicStatusCodes.cs" />
<Compile Include="System\Net\Quic\Implementations\MsQuic\Interop\MsQuicStatusHelper.cs" />
<Compile Include="System\Net\Quic\Implementations\MsQuic\Interop\MsQuicTraceHelper.cs" />
<Compile Include="System\Net\Quic\Implementations\MsQuic\Interop\SafeMsQuicConfigurationHandle.cs" />
<Compile Include="System\Net\Quic\Implementations\MsQuic\Interop\SafeMsQuicConnectionHandle.cs" />
<Compile Include="System\Net\Quic\Implementations\MsQuic\Interop\SafeMsQuicListenerHandle.cs" />
Expand Down
30 changes: 30 additions & 0 deletions ...s/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/MsQuicTraceHelper.cs
View file
Original file line number Diff line number Diff line change
@@ -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");
}
}
}
35 changes: 17 additions & 18 deletions src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicConnection.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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).
Expand Down Expand Up @@ -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();
}
}
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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");
}
}

Expand Down Expand Up @@ -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");
}
}

Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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.

Expand Down Expand Up @@ -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)
Expand All @@ -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();
Expand Down
12 changes: 12 additions & 0 deletions src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicListener.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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<MsQuicConnection> AcceptConnectionQueue;
Expand Down Expand Up @@ -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
Expand Down
38 changes: 18 additions & 20 deletions src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicStream.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
Expand All @@ -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)
Expand Down Expand Up @@ -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}.");
}
}

Expand Down Expand Up @@ -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}.");
}
}

Expand Down Expand Up @@ -366,7 +364,7 @@ internal override async ValueTask<int> ReadAsync(Memory<byte> 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)
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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()
Expand All @@ -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
Expand Down Expand Up @@ -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;
}
Expand Down Expand Up @@ -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)
{
Expand Down Expand Up @@ -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)
{
Expand Down Expand Up @@ -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}" : ""));
}

Expand Down

0 comments on commit 102fc35

Please sign in to comment.