Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

QUIC logging update #55500

Merged
merged 4 commits into from
Jul 12, 2021
Merged

QUIC logging update #55500

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
00351d9
Update logging to use msquic pointers
CarnaViire Jul 10, 2021
14295b7
Merge branch 'main' into quic-logging-update
CarnaViire Jul 12, 2021
f625a0a
rename LogId -> TraceId
CarnaViire Jul 12, 2021
366b45d
fix
CarnaViire Jul 12, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions src/libraries/System.Net.Quic/src/System.Net.Quic.csproj
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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 @@ internal void SetNegotiatedAlpn(IntPtr alpn, int alpnLength)

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 @@ 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.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
Open in desktop
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
Open in desktop
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