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

Add more logging to HTTP3 and QUIC code #101449

Merged
merged 7 commits into from
Apr 24, 2024
Merged

Add more logging to HTTP3 and QUIC code #101449

Show file tree
Hide file tree
Changes from 5 commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
ce99fe1
Add more logging to QuicConnection and QuicStream
rzikm Apr 23, 2024
9ade3fc
Fix ptr format
rzikm Apr 23, 2024
0478199
wip
rzikm Apr 23, 2024
9177ff1
Add more http3 logging
rzikm Apr 23, 2024
9f09acb
fixup! Add more http3 logging
rzikm Apr 23, 2024
483bfde
Code review feedback
rzikm Apr 24, 2024
0839ffd
Merge branch 'main' into quic-extra-logging
rzikm Apr 24, 2024
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
13 changes: 13 additions & 0 deletions src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3Connection.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -300,6 +300,11 @@ internal Exception Abort(Exception abortException)

private void OnServerGoAway(long firstRejectedStreamId)
{
if (NetEventSource.Log.IsEnabled())
{
Trace($"GOAWAY received. First rejected stream ID = {firstRejectedStreamId}");
}

// Stop sending requests to this connection.
_pool.InvalidateHttp3Connection(this);

Expand Down Expand Up @@ -649,6 +654,10 @@ private async Task ProcessServerControlStreamAsync(QuicStream stream, ArrayBuffe
case Http3FrameType.ReservedHttp2Ping:
case Http3FrameType.ReservedHttp2WindowUpdate:
case Http3FrameType.ReservedHttp2Continuation:
if (NetEventSource.Log.IsEnabled())
{
Trace($"Received reserved frame: {frameType}");
}
throw HttpProtocolException.CreateHttp3ConnectionException(Http3ErrorCode.UnexpectedFrame);
case Http3FrameType.PushPromise:
case Http3FrameType.CancelPush:
Expand All @@ -663,6 +672,10 @@ private async Task ProcessServerControlStreamAsync(QuicStream stream, ArrayBuffe
}
if (!shuttingDown)
{
if (NetEventSource.Log.IsEnabled())
{
Trace($"Control stream closed by the server.");
}
throw HttpProtocolException.CreateHttp3ConnectionException(Http3ErrorCode.ClosedCriticalStream);
}
return;
Expand Down
27 changes: 24 additions & 3 deletions src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/MsQuicExtensions.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.

using System;
using System.Net.Quic;

namespace Microsoft.Quic;
Expand All @@ -17,7 +18,7 @@ public override string ToString()
=> Type switch
{
QUIC_LISTENER_EVENT_TYPE.NEW_CONNECTION
=> $"{{ {nameof(NEW_CONNECTION.Info)} = {{ {nameof(QUIC_NEW_CONNECTION_INFO.QuicVersion)} = {NEW_CONNECTION.Info->QuicVersion}, {nameof(QUIC_NEW_CONNECTION_INFO.LocalAddress)} = {MsQuicHelpers.QuicAddrToIPEndPoint(NEW_CONNECTION.Info->LocalAddress)}, {nameof(QUIC_NEW_CONNECTION_INFO.RemoteAddress)} = {MsQuicHelpers.QuicAddrToIPEndPoint(NEW_CONNECTION.Info->RemoteAddress)} }} }}",
=> $"{{ {nameof(NEW_CONNECTION.Info)} = {{ {nameof(QUIC_NEW_CONNECTION_INFO.QuicVersion)} = {NEW_CONNECTION.Info->QuicVersion}, {nameof(QUIC_NEW_CONNECTION_INFO.LocalAddress)} = {MsQuicHelpers.QuicAddrToIPEndPoint(NEW_CONNECTION.Info->LocalAddress)}, {nameof(QUIC_NEW_CONNECTION_INFO.RemoteAddress)} = {MsQuicHelpers.QuicAddrToIPEndPoint(NEW_CONNECTION.Info->RemoteAddress)} }}, {nameof(NEW_CONNECTION.Connection)} = 0x{(IntPtr)NEW_CONNECTION.Connection:X11} }}",
_ => string.Empty
};
}
Expand All @@ -40,9 +41,29 @@ public override string ToString()
QUIC_CONNECTION_EVENT_TYPE.PEER_ADDRESS_CHANGED
=> $"{{ {nameof(PEER_ADDRESS_CHANGED.Address)} = {MsQuicHelpers.QuicAddrToIPEndPoint(PEER_ADDRESS_CHANGED.Address)} }}",
QUIC_CONNECTION_EVENT_TYPE.PEER_STREAM_STARTED
=> $"{{ {nameof(PEER_STREAM_STARTED.Flags)} = {PEER_STREAM_STARTED.Flags} }}",
=> $"{{ {nameof(PEER_STREAM_STARTED.Stream)} = 0x{(IntPtr)PEER_STREAM_STARTED.Stream:X11} {nameof(PEER_STREAM_STARTED.Flags)} = {PEER_STREAM_STARTED.Flags} }}",
QUIC_CONNECTION_EVENT_TYPE.STREAMS_AVAILABLE
=> $"{{ {nameof(STREAMS_AVAILABLE.BidirectionalCount)} = {STREAMS_AVAILABLE.BidirectionalCount}, {nameof(STREAMS_AVAILABLE.UnidirectionalCount)} = {STREAMS_AVAILABLE.UnidirectionalCount} }}",
QUIC_CONNECTION_EVENT_TYPE.PEER_NEEDS_STREAMS
=> $"{{ {nameof(PEER_NEEDS_STREAMS.Bidirectional)} = {PEER_NEEDS_STREAMS.Bidirectional} }}",
QUIC_CONNECTION_EVENT_TYPE.IDEAL_PROCESSOR_CHANGED
=> $"{{ {nameof(IDEAL_PROCESSOR_CHANGED.IdealProcessor)} = {IDEAL_PROCESSOR_CHANGED.IdealProcessor}, {nameof(IDEAL_PROCESSOR_CHANGED.PartitionIndex)} = {IDEAL_PROCESSOR_CHANGED.PartitionIndex} }}",
QUIC_CONNECTION_EVENT_TYPE.DATAGRAM_STATE_CHANGED
=> $"{{ {nameof(DATAGRAM_STATE_CHANGED.SendEnabled)} = {DATAGRAM_STATE_CHANGED.SendEnabled}, {nameof(DATAGRAM_STATE_CHANGED.MaxSendLength)} = {DATAGRAM_STATE_CHANGED.MaxSendLength} }}",
QUIC_CONNECTION_EVENT_TYPE.DATAGRAM_RECEIVED
=> $"{{ {nameof(DATAGRAM_RECEIVED.Flags)} = {DATAGRAM_RECEIVED.Flags} }}",
QUIC_CONNECTION_EVENT_TYPE.DATAGRAM_SEND_STATE_CHANGED
=> $"{{ {nameof(DATAGRAM_SEND_STATE_CHANGED.ClientContext)} = 0x{(IntPtr)DATAGRAM_SEND_STATE_CHANGED.ClientContext:X11}, {nameof(DATAGRAM_SEND_STATE_CHANGED.State)} = {DATAGRAM_SEND_STATE_CHANGED.State} }}",
QUIC_CONNECTION_EVENT_TYPE.RESUMED
=> $"{{ {nameof(RESUMED.ResumptionStateLength)} = {RESUMED.ResumptionStateLength} }}",
QUIC_CONNECTION_EVENT_TYPE.RESUMPTION_TICKET_RECEIVED
=> $"{{ {nameof(RESUMPTION_TICKET_RECEIVED.ResumptionTicketLength)} = {RESUMPTION_TICKET_RECEIVED.ResumptionTicketLength} }}",
QUIC_CONNECTION_EVENT_TYPE.PEER_CERTIFICATE_RECEIVED
=> $"{{ {nameof(PEER_CERTIFICATE_RECEIVED.DeferredStatus)} = {PEER_CERTIFICATE_RECEIVED.DeferredStatus}, {nameof(PEER_CERTIFICATE_RECEIVED.DeferredErrorFlags)} = {PEER_CERTIFICATE_RECEIVED.DeferredErrorFlags} }}",
=> $"{{ {nameof(PEER_CERTIFICATE_RECEIVED.DeferredStatus)} = {PEER_CERTIFICATE_RECEIVED.DeferredStatus}, {nameof(PEER_CERTIFICATE_RECEIVED.DeferredErrorFlags)} = {PEER_CERTIFICATE_RECEIVED.DeferredErrorFlags}, {nameof(PEER_CERTIFICATE_RECEIVED.Certificate)} = 0x{(IntPtr)PEER_CERTIFICATE_RECEIVED.Certificate:X11} }}",
QUIC_CONNECTION_EVENT_TYPE.RELIABLE_RESET_NEGOTIATED
=> $"{{ {nameof(RELIABLE_RESET_NEGOTIATED.IsNegotiated)} = {RELIABLE_RESET_NEGOTIATED.IsNegotiated} }}",
QUIC_CONNECTION_EVENT_TYPE.ONE_WAY_DELAY_NEGOTIATED
=> $"{{ {nameof(ONE_WAY_DELAY_NEGOTIATED.SendNegotiated)} = {ONE_WAY_DELAY_NEGOTIATED.SendNegotiated}, {nameof(ONE_WAY_DELAY_NEGOTIATED.ReceiveNegotiated)} = {ONE_WAY_DELAY_NEGOTIATED.ReceiveNegotiated} }}",
_ => string.Empty
};
}
Expand Down
25 changes: 25 additions & 0 deletions src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -252,6 +252,11 @@ private unsafe QuicConnection()
throw;
}

if (NetEventSource.Log.IsEnabled())
{
NetEventSource.Info(this, $"{this} New client connection.");
}

_tlsSecret = MsQuicTlsSecret.Create(_handle);
}

Expand All @@ -278,6 +283,11 @@ internal unsafe QuicConnection(QUIC_HANDLE* handle, QUIC_NEW_CONNECTION_INFO* in
throw;
}

if (NetEventSource.Log.IsEnabled())
{
NetEventSource.Info(this, $"{this} New server connection.");
rzikm marked this conversation as resolved.
Show resolved Hide resolved
}

_remoteEndPoint = MsQuicHelpers.QuicAddrToIPEndPoint(info->RemoteAddress);
_localEndPoint = MsQuicHelpers.QuicAddrToIPEndPoint(info->LocalAddress);
_tlsSecret = MsQuicTlsSecret.Create(_handle);
Expand Down Expand Up @@ -407,6 +417,11 @@ public async ValueTask<QuicStream> OpenOutboundStreamAsync(QuicStreamType type,
{
ObjectDisposedException.ThrowIf(_disposed == 1, this);

if (NetEventSource.Log.IsEnabled())
{
NetEventSource.Info(this, $"{this} Opening {type} stream.");
}

QuicStream? stream = null;
try
{
Expand Down Expand Up @@ -482,6 +497,11 @@ public ValueTask CloseAsync(long errorCode, CancellationToken cancellationToken

if (_shutdownTcs.TryGetValueTask(out ValueTask valueTask, this, cancellationToken))
{
if (NetEventSource.Log.IsEnabled())
{
NetEventSource.Info(this, $"{this} Closing connection, Error code = {errorCode}");
}

unsafe
{
MsQuicApi.Api.ConnectionShutdown(
Expand Down Expand Up @@ -648,6 +668,11 @@ public async ValueTask DisposeAsync()
return;
}

if (NetEventSource.Log.IsEnabled())
{
NetEventSource.Info(this, $"{this} Disposing.");
}

// Check if the connection has been shut down and if not, shut it down.
if (_shutdownTcs.TryGetValueTask(out ValueTask valueTask, this))
{
Expand Down
21 changes: 21 additions & 0 deletions src/libraries/System.Net.Quic/src/System/Net/Quic/QuicStream.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -180,6 +180,11 @@ internal unsafe QuicStream(MsQuicContextSafeHandle connectionHandle, QuicStreamT

_defaultErrorCode = defaultErrorCode;

if (NetEventSource.Log.IsEnabled())
{
NetEventSource.Info(this, $"{this} New outgoing {type} stream.");
}

_canRead = type == QuicStreamType.Bidirectional;
_canWrite = true;
if (!_canRead)
Expand Down Expand Up @@ -225,6 +230,12 @@ internal unsafe QuicStream(MsQuicContextSafeHandle connectionHandle, QUIC_HANDLE
}
_id = (long)GetMsQuicParameter<ulong>(_handle, QUIC_PARAM_STREAM_ID);
_type = flags.HasFlag(QUIC_STREAM_OPEN_FLAGS.UNIDIRECTIONAL) ? QuicStreamType.Unidirectional : QuicStreamType.Bidirectional;

if (NetEventSource.Log.IsEnabled())
{
NetEventSource.Info(this, $"{this} New incoming {_type} stream, StreamId = {_id}.");
}

_startedTcs.TrySetResult();
}

Expand Down Expand Up @@ -325,6 +336,11 @@ public override async ValueTask<int> ReadAsync(Memory<byte> buffer, Cancellation
}
}

if (NetEventSource.Log.IsEnabled())
{
NetEventSource.Info(this, $"{this} Stream read '{totalCopied}' bytes.");
}

return totalCopied;
}

Expand Down Expand Up @@ -690,6 +706,11 @@ public override async ValueTask DisposeAsync()
return;
}

if (NetEventSource.Log.IsEnabled())
rzikm marked this conversation as resolved.
Show resolved Hide resolved
{
NetEventSource.Info(this, $"{this} Disposing.");
}

// If the stream wasn't started successfully, gracelessly abort it.
if (!_startedTcs.IsCompletedSuccessfully)
{
Expand Down
Loading