From d33f18db70d2ec5c0341e5700a546cba0b6c1ad3 Mon Sep 17 00:00:00 2001 From: Radek Zikmund Date: Thu, 24 Sep 2026 15:53:17 +0200 Subject: [PATCH] Add diagnostics for HTTP/3 cookie redirect failures Capture isolated request, connection, pool, GOAWAY and retry-path chronology without changing cookie assertions or retry semantics. Reuse opt-in HTTP/3 loopback logging from #134413. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../Net/Http/Http3LoopbackConnection.cs | 31 ++++- .../System/Net/Http/Http3LoopbackServer.cs | 20 ++- .../Net/Http/HttpClientHandlerTest.Cookies.cs | 70 ++++++++-- .../HttpConnectionPool.Http3.cs | 6 + .../ConnectionPool/HttpConnectionPool.cs | 4 +- .../SocketsHttpHandler/Http3Connection.cs | 12 +- .../SocketsHttpHandler/Http3RequestStream.cs | 2 + .../FunctionalTests/SocketsHttpHandlerTest.cs | 123 ++++++++++++++++++ 8 files changed, 250 insertions(+), 18 deletions(-) diff --git a/src/libraries/Common/tests/System/Net/Http/Http3LoopbackConnection.cs b/src/libraries/Common/tests/System/Net/Http/Http3LoopbackConnection.cs index 27ebd955072b68..e4ee6cdf57e8a9 100644 --- a/src/libraries/Common/tests/System/Net/Http/Http3LoopbackConnection.cs +++ b/src/libraries/Common/tests/System/Net/Http/Http3LoopbackConnection.cs @@ -34,6 +34,7 @@ public sealed class Http3LoopbackConnection : GenericLoopbackConnection public const long H3_VERSION_FALLBACK = 0x110; private readonly QuicConnection _connection; + private readonly Action _log; // Queue for holding streams we accepted before we managed to accept the control stream private readonly Queue _delayedStreams = new Queue(); @@ -52,9 +53,10 @@ public sealed class Http3LoopbackConnection : GenericLoopbackConnection public Http3LoopbackStream OutboundControlStream => _outboundControlStream ?? throw new Exception("Control stream has not been opened yet"); public Http3LoopbackStream InboundControlStream => _inboundControlStream ?? throw new Exception("Inbound control stream has not been accepted yet"); - public Http3LoopbackConnection(QuicConnection connection) + public Http3LoopbackConnection(QuicConnection connection, Action log = null) { _connection = connection; + _log = log; } public long MaxHeaderListSize { get; private set; } = -1; @@ -64,28 +66,34 @@ public override async ValueTask DisposeAsync() // Close any remaining request streams (but NOT control streams, as these should not be closed while the connection is open) foreach (Http3LoopbackStream stream in _openStreams.Values) { + _log?.Invoke($"{_connection}: Disposing request stream."); await stream.DisposeAsync().ConfigureAwait(false); } foreach (QuicStream stream in _delayedStreams) { + _log?.Invoke($"{_connection}: Disposing delayed stream."); await stream.DisposeAsync().ConfigureAwait(false); } // Dispose the connection // If we already waited for graceful shutdown from the client, then the connection is already closed and this will simply release the handle. // If not, then this will silently abort the connection. + _log?.Invoke($"{_connection}: Disposing connection."); await _connection.DisposeAsync().ConfigureAwait(false); // Dispose control streams so that we release their handles too. if (_inboundControlStream is not null) { + _log?.Invoke($"{_connection}: Disposing inbound control stream."); await _inboundControlStream.DisposeAsync().ConfigureAwait(false); } if (_outboundControlStream is not null) { + _log?.Invoke($"{_connection}: Disposing outbound control stream."); await _outboundControlStream.DisposeAsync().ConfigureAwait(false); } + _log?.Invoke($"{_connection}: Connection and streams disposed."); } public Task CloseAsync(long errorCode) => _connection.CloseAsync(errorCode).AsTask(); @@ -127,7 +135,9 @@ async Task EnsureControlStreamAcceptedInternalAsync() while (true) { + _log?.Invoke($"{_connection}: Accepting inbound stream while waiting for control stream."); QuicStream quicStream = await _connection.AcceptInboundStreamAsync().ConfigureAwait(false); + _log?.Invoke($"{_connection}: Accepted stream {quicStream.Id}, CanWrite={quicStream.CanWrite}."); if (!quicStream.CanWrite) { @@ -141,9 +151,11 @@ async Task EnsureControlStreamAcceptedInternalAsync() _delayedStreams.Enqueue(quicStream); } + _log?.Invoke($"{_connection}: Reading control stream type."); long? streamType = await controlStream.ReadIntegerAsync().ConfigureAwait(false); Assert.Equal(Http3LoopbackStream.ControlStream, streamType); + _log?.Invoke($"{_connection}: Reading client settings."); List<(long settingId, long settingValue)> settings = await controlStream.ReadSettingsAsync().ConfigureAwait(false); (long settingId, long settingValue) = Assert.Single(settings); @@ -151,6 +163,7 @@ async Task EnsureControlStreamAcceptedInternalAsync() MaxHeaderListSize = settingValue; _inboundControlStream = controlStream; + _log?.Invoke($"{_connection}: Client settings read."); } } @@ -161,6 +174,7 @@ public async Task AcceptRequestStreamAsync() if (!_delayedStreams.TryDequeue(out QuicStream quicStream)) { + _log?.Invoke($"{_connection}: Accepting request stream."); quicStream = await _connection.AcceptInboundStreamAsync().ConfigureAwait(false); } @@ -171,6 +185,7 @@ public async Task AcceptRequestStreamAsync() _openStreams.Add(checked((int)quicStream.Id), stream); _currentStream = stream; _currentStreamId = quicStream.Id; + _log?.Invoke($"{_connection}: Request stream {_currentStreamId} accepted."); return stream; } @@ -185,9 +200,13 @@ public async Task AcceptRequestStreamAsync() public async Task EstablishControlStreamAsync(SettingsEntry[] settingsEntries) { + _log?.Invoke($"{_connection}: Opening outbound control stream."); _outboundControlStream = await OpenUnidirectionalStreamAsync().ConfigureAwait(false); + _log?.Invoke($"{_connection}: Sending control stream type."); await _outboundControlStream.SendUnidirectionalStreamTypeAsync(Http3LoopbackStream.ControlStream).ConfigureAwait(false); + _log?.Invoke($"{_connection}: Sending server settings."); await _outboundControlStream.SendSettingsFrameAsync(settingsEntries).ConfigureAwait(false); + _log?.Invoke($"{_connection}: Server settings sent."); } public async Task DisposeCurrentStream() @@ -249,17 +268,22 @@ public override async Task HandleRequestAsync(HttpStatusCode st { Http3LoopbackStream stream = await AcceptRequestStreamAsync().ConfigureAwait(false); + _log?.Invoke($"{_connection}: Reading request on stream {stream.StreamId}."); HttpRequestData request = await stream.ReadRequestDataAsync().ConfigureAwait(false); // We are about to close the connection, after we send the response. // So, send a GOAWAY frame now so the client won't inadvertantly try to reuse the connection. // Note that in HTTP3 (unlike HTTP2) there is no strict ordering between the GOAWAY and the response below; // so the client may race in processing them and we need to handle this. + _log?.Invoke($"{_connection}: Sending GOAWAY, first rejected stream {stream.StreamId + 4}."); await _outboundControlStream.SendGoAwayFrameAsync(stream.StreamId + 4).ConfigureAwait(false); + _log?.Invoke($"{_connection}: Sending response {(int)statusCode} on stream {stream.StreamId}."); await stream.SendResponseAsync(statusCode, headers, content).ConfigureAwait(false); + _log?.Invoke($"{_connection}: Response sent, waiting for client disconnect."); await WaitForClientDisconnectAsync().ConfigureAwait(false); + _log?.Invoke($"{_connection}: Client disconnect handled."); return request; } @@ -310,11 +334,13 @@ public async Task WaitForClientDisconnectAsync(bool refuseNewRequests = true) } catch (QuicException abortException) when (abortException.QuicError == QuicError.ConnectionAborted && abortException.ApplicationErrorCode == H3_NO_ERROR) { + _log?.Invoke($"{_connection}: Received client H3_NO_ERROR close."); break; } await using (stream) { + _log?.Invoke($"{_connection}: Rejecting stream {stream.StreamId} while waiting for client disconnect."); stream.Abort(H3_REQUEST_REJECTED); } } @@ -323,11 +349,14 @@ public async Task WaitForClientDisconnectAsync(bool refuseNewRequests = true) // aborted because the connection was closed (and was not explicitly closed or aborted prior to the connection being closed) if (_inboundControlStream is not null) { + _log?.Invoke($"{_connection}: Checking control stream after client disconnect."); QuicException ex = await Assert.ThrowsAsync(async () => await _inboundControlStream.ReadFrameAsync().ConfigureAwait(false)); Assert.Equal(QuicError.ConnectionAborted, ex.QuicError); } + _log?.Invoke($"{_connection}: Closing connection with H3_NO_ERROR."); await CloseAsync(H3_NO_ERROR).ConfigureAwait(false); + _log?.Invoke($"{_connection}: Connection closed."); } public override async Task WaitForCancellationAsync(bool ignoreIncomingData = true) diff --git a/src/libraries/Common/tests/System/Net/Http/Http3LoopbackServer.cs b/src/libraries/Common/tests/System/Net/Http/Http3LoopbackServer.cs index f6fbdf1f8cc14b..a35ff075d4723f 100644 --- a/src/libraries/Common/tests/System/Net/Http/Http3LoopbackServer.cs +++ b/src/libraries/Common/tests/System/Net/Http/Http3LoopbackServer.cs @@ -15,6 +15,7 @@ public sealed class Http3LoopbackServer : GenericLoopbackServer { private X509Certificate2 _cert; private QuicListener _listener; + private readonly Action _log; public override Uri Address => new Uri($"https://{_listener.LocalEndPoint}/"); @@ -22,6 +23,7 @@ public Http3LoopbackServer(Http3Options options = null) { options ??= new Http3Options(); + _log = options.Log; _cert = options.Certificate ?? Configuration.Certificates.GetServerCertificate(); var listenerOptions = new QuicListenerOptions() @@ -61,14 +63,18 @@ public Http3LoopbackServer(Http3Options options = null) public override void Dispose() { + _log?.Invoke("Disposing listener."); _listener.DisposeAsync().GetAwaiter().GetResult(); _cert.Dispose(); + _log?.Invoke("Listener disposed."); } private async Task EstablishHttp3ConnectionAsync(params SettingsEntry[] settingsEntries) { + _log?.Invoke("Accepting connection."); QuicConnection con = await _listener.AcceptConnectionAsync().ConfigureAwait(false); - Http3LoopbackConnection connection = new Http3LoopbackConnection(con); + _log?.Invoke($"{con}: Connection accepted."); + Http3LoopbackConnection connection = new Http3LoopbackConnection(con, _log); await connection.EstablishControlStreamAsync(settingsEntries).ConfigureAwait(false); return connection; @@ -94,7 +100,15 @@ public override async Task AcceptConnectionAsync(Func HandleRequestAsync(HttpStatusCode statusCode = HttpStatusCode.OK, IList headers = null, string content = "") { await using Http3LoopbackConnection con = await EstablishHttp3ConnectionAsync().ConfigureAwait(false); - return await con.HandleRequestAsync(statusCode, headers, content).ConfigureAwait(false); + try + { + return await con.HandleRequestAsync(statusCode, headers, content).ConfigureAwait(false); + } + catch (Exception exception) when (_log is not null) + { + _log($"Handling request failed before connection disposal: {exception}"); + throw; + } } } @@ -143,6 +157,8 @@ private static Http3Options CreateOptions(GenericLoopbackOptions options) } public class Http3Options : GenericLoopbackOptions { + public Action Log { get; set; } + public int MaxInboundUnidirectionalStreams { get; set; } public int MaxInboundBidirectionalStreams { get; set; } diff --git a/src/libraries/Common/tests/System/Net/Http/HttpClientHandlerTest.Cookies.cs b/src/libraries/Common/tests/System/Net/Http/HttpClientHandlerTest.Cookies.cs index 27e2c8f0ebd060..bf97cbd8440bbb 100644 --- a/src/libraries/Common/tests/System/Net/Http/HttpClientHandlerTest.Cookies.cs +++ b/src/libraries/Common/tests/System/Net/Http/HttpClientHandlerTest.Cookies.cs @@ -296,16 +296,35 @@ await LoopbackServerFactory.CreateServerAsync(async (server, url) => }); } + protected virtual Action CookieRedirectLog => null; + protected virtual GenericLoopbackOptions CookieRedirectOptions => null; + [Fact] [SkipOnPlatform(TestPlatforms.Browser, "CookieContainer is not supported on Browser")] - public async Task GetAsyncWithRedirect_SetCookieContainer_CorrectCookiesSent() + public virtual async Task GetAsyncWithRedirect_SetCookieContainer_CorrectCookiesSent() { const string path1 = "/foo"; const string path2 = "/bar"; const string unusedPath = "/unused"; + Action log = CookieRedirectLog; + Task clientTask = null; + Task serverTask = null; - await LoopbackServerFactory.CreateClientAndServerAsync(async url => + try + { + await LoopbackServerFactory.CreateClientAndServerAsync( + url => clientTask = RunClientAsync(url), + server => serverTask = RunServerAsync(server), + options: CookieRedirectOptions); + } + finally + { + log?.Invoke($"Factory finished: client={clientTask?.Status}, server={serverTask?.Status}. Fault aggregation includes up to 3 seconds of grace after the first fault."); + } + + async Task RunClientAsync(Uri url) { + log?.Invoke("Client: configuring cookies for initial and redirected paths."); Uri url1 = new Uri(url, path1); Uri url2 = new Uri(url, path2); Uri unusedUrl = new Uri(url, unusedPath); @@ -319,17 +338,46 @@ await LoopbackServerFactory.CreateClientAndServerAsync(async url => using (HttpClient client = CreateHttpClient(handler)) { client.DefaultRequestHeaders.ConnectionClose = true; // to avoid issues with connection pooling - await client.GetAsync(url1); + try + { + log?.Invoke("Client: starting initial GET and automatic redirect."); + await client.GetAsync(url1); + log?.Invoke("Client: redirected GET completed."); + } + catch (Exception exception) when (log is not null) + { + log($"Client failed before disposal and combinator grace: {exception}"); + throw; + } + finally + { + log?.Invoke("Client: disposing HttpClient."); + } } - }, - async server => - { - HttpRequestData requestData1 = await server.HandleRequestAsync(HttpStatusCode.Found, new HttpHeaderData[] { new HttpHeaderData("Location", path2) }); - Assert.Equal("cookie1=value1", requestData1.GetSingleHeaderValue("Cookie")); + log?.Invoke("Client: disposed."); + } - HttpRequestData requestData2 = await server.HandleRequestAsync(content: s_simpleContent); - Assert.Equal("cookie2=value2", requestData2.GetSingleHeaderValue("Cookie")); - }); + async Task RunServerAsync(GenericLoopbackServer server) + { + try + { + log?.Invoke("Server: handling initial request with 302."); + HttpRequestData requestData1 = await server.HandleRequestAsync(HttpStatusCode.Found, new HttpHeaderData[] { new HttpHeaderData("Location", path2) }); + log?.Invoke("Server: initial request handled; checking cookie."); + Assert.Equal("cookie1=value1", requestData1.GetSingleHeaderValue("Cookie")); + + log?.Invoke("Server: initial cookie checked; handling redirected request with 200."); + HttpRequestData requestData2 = await server.HandleRequestAsync(content: s_simpleContent); + log?.Invoke("Server: redirected request handled; checking cookie."); + Assert.Equal("cookie2=value2", requestData2.GetSingleHeaderValue("Cookie")); + log?.Invoke("Server: redirected cookie checked."); + } + catch (Exception exception) when (log is not null) + { + log($"Server failed before combinator grace: {exception}"); + throw; + } + } } // diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http3.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http3.cs index 7e3090112591f0..d3942eb81a1f8c 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http3.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http3.cs @@ -144,6 +144,7 @@ private bool TryGetPooledHttp3Connection(HttpRequestMessage request, [NotNullWhe // We have a connection that we can attempt to use. // Validate it below outside the lock, to avoid doing expensive operations while holding the lock. connection = _availableHttp3Connections![availableConnectionCount - 1]; + if (NetEventSource.Log.IsEnabled()) connection.Trace($"Selected pooled connection: requestId={request.GetHashCode()}, availableConnections={availableConnectionCount}"); } else { @@ -428,6 +429,7 @@ private void ReturnHttp3Connection(Http3Connection connection, bool isNewConnect added = true; _availableHttp3Connections ??= new List(); _availableHttp3Connections.Add(connection); + if (NetEventSource.Log.IsEnabled()) connection.Trace($"Added to available list: availableConnections={_availableHttp3Connections.Count}, associatedConnections={_associatedHttp3ConnectionCount}"); } } @@ -435,10 +437,13 @@ private void ReturnHttp3Connection(Http3Connection connection, bool isNewConnect { Debug.Assert(!added); + if (NetEventSource.Log.IsEnabled()) connection.Trace("Publishing connection to request waiter."); if (waiter.TrySignal(connection)) { + if (NetEventSource.Log.IsEnabled()) connection.Trace("Request waiter accepted connection."); break; } + if (NetEventSource.Log.IsEnabled()) connection.Trace("Request waiter declined connection."); // Loop and process the queue again } @@ -545,6 +550,7 @@ public void InvalidateHttp3Connection(Http3Connection connection, bool dispose = } } + if (NetEventSource.Log.IsEnabled()) connection.Trace($"Invalidation: found={found}, dispose={dispose}, availableConnections={_availableHttp3Connections?.Count ?? 0}, associatedConnections={_associatedHttp3ConnectionCount}"); CheckForHttp3ConnectionInjection(); } diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.cs index 57d5c2ec7be48c..7cc1a935bf7708 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.cs @@ -522,7 +522,7 @@ public async ValueTask SendWithVersionDetectionAndRetryAsyn { if (NetEventSource.Log.IsEnabled()) { - Trace($"MaxConnectionFailureRetries limit of {MaxConnectionFailureRetries} hit. Retryable request will not be retried. Exception: {e}"); + Trace($"MaxConnectionFailureRetries limit of {MaxConnectionFailureRetries} hit. Retryable request will not be retried. requestId={request.GetHashCode()}, connectionId={request.ConnectionId}. Exception: {e}"); } throw; @@ -532,7 +532,7 @@ public async ValueTask SendWithVersionDetectionAndRetryAsyn if (NetEventSource.Log.IsEnabled()) { - Trace($"Retry attempt {retryCount} after connection failure. Connection exception: {e}"); + Trace($"Retry attempt {retryCount} after connection failure. requestId={request.GetHashCode()}, connectionId={request.ConnectionId}. Connection exception: {e}"); } // Eat exception and try again. diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3Connection.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3Connection.cs index dc348420a49a95..549a83a371f4cb 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3Connection.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3Connection.cs @@ -133,6 +133,8 @@ private void CheckForShutdown() Debug.Assert(Monitor.IsEntered(SyncObj)); Debug.Assert(ShuttingDown); + if (NetEventSource.Log.IsEnabled()) Trace($"Checking shutdown: activeRequests={_activeRequests.Count}, firstRejectedStreamId={_firstRejectedStreamId}, hasConnection={_connection is not null}"); + if (_activeRequests.Count != 0) { return; @@ -192,7 +194,7 @@ public bool TryReserveStream() // For the single connection case, we allow the counter to go below zero. Debug.Assert(singleConnection || _availableRequestStreamsCount >= 0); - if (NetEventSource.Log.IsEnabled()) Trace($"_availableRequestStreamsCount = {_availableRequestStreamsCount}"); + if (NetEventSource.Log.IsEnabled()) Trace($"_availableRequestStreamsCount = {_availableRequestStreamsCount}, firstRejectedStreamId={_firstRejectedStreamId}, hasConnection={_connection is not null}"); bool streamAvailable = _availableRequestStreamsCount > 0; @@ -266,6 +268,7 @@ public Task WaitForAvailableStreamsAsync() public async Task SendAsync(HttpRequestMessage request, WaitForHttp3ConnectionActivity waitForConnectionActivity, bool streamAvailable, CancellationToken cancellationToken) { request.ConnectionId = Id; + if (NetEventSource.Log.IsEnabled()) Trace($"HTTP3 send start: requestId={request.GetHashCode()}, streamAvailable={streamAvailable}, canceled={cancellationToken.IsCancellationRequested}"); // Allocate an active request QuicStream? quicStream = null; @@ -315,6 +318,7 @@ public async Task SendAsync(HttpRequestMessage request, Wai if (quicStream == null) { + if (NetEventSource.Log.IsEnabled()) Trace($"HTTP3 retry path: no request stream. Suppressed exception: {exception}"); throw new HttpRequestException(HttpRequestError.Unknown, SR.net_http_request_aborted, null, RequestRetryType.RetryOnConnectionFailure); } @@ -324,10 +328,12 @@ public async Task SendAsync(HttpRequestMessage request, Wai lock (SyncObj) { goAway = _firstRejectedStreamId != -1 && requestStream.StreamId >= _firstRejectedStreamId; + if (NetEventSource.Log.IsEnabled()) Trace(requestStream.StreamId, $"Opened request stream: requestId={request.GetHashCode()}, firstRejectedStreamId={_firstRejectedStreamId}, goAway={goAway}"); } if (goAway) { + if (NetEventSource.Log.IsEnabled()) Trace(requestStream.StreamId, "HTTP3 retry path: stream at or above GOAWAY boundary."); throw new HttpRequestException(HttpRequestError.Unknown, SR.net_http_request_aborted, null, RequestRetryType.RetryOnConnectionFailure); } @@ -344,6 +350,7 @@ public async Task SendAsync(HttpRequestMessage request, Wai } catch (QuicException ex) when (ex.QuicError == QuicError.OperationAborted) { + if (NetEventSource.Log.IsEnabled()) Trace($"HTTP3 retry path: local OperationAborted. Exception: {ex}; connection abort: {_abortException}"); // This will happen if we aborted _connection somewhere and we have pending OpenOutboundStreamAsync call. // note that _abortException may be null if we closed the connection in response to a GOAWAY frame throw new HttpRequestException(HttpRequestError.Unknown, SR.net_http_client_execution_error, _abortException, RequestRetryType.RetryOnConnectionFailure); @@ -436,6 +443,7 @@ private void OnServerGoAway(long firstRejectedStreamId) } _firstRejectedStreamId = firstRejectedStreamId; + if (NetEventSource.Log.IsEnabled()) Trace($"Applied GOAWAY boundary: firstRejectedStreamId={_firstRejectedStreamId}, activeRequests={_activeRequests.Count}"); foreach (KeyValuePair request in _activeRequests) { @@ -483,7 +491,7 @@ internal void Trace(long streamId, string message, [CallerMemberName] string? me GetHashCode(), // connection ID (int)streamId, // stream ID memberName, // method name - message); // message + $"connectionId={Id}: {message}"); // message private async Task SendSettingsAsync() { diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs index cca6e545a0d01a..f6bfaf2891c8d2 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs @@ -300,6 +300,7 @@ await Task.WhenAny(sendRequestTask, readResponseTask).ConfigureAwait(false) == s throw new HttpRequestException(HttpRequestError.Unknown, SR.net_http_retry_on_older_version, ex, RequestRetryType.RetryOnLowerHttpVersion); case Http3ErrorCode.RequestRejected: + if (NetEventSource.Log.IsEnabled()) Trace($"HTTP3 retry path: peer H3_REQUEST_REJECTED. Exception: {ex}"); // The server is rejecting the request without processing it, retry it on a different connection. HttpProtocolException rejectedException = HttpProtocolException.CreateHttp3StreamException(code, ex); throw new HttpRequestException(HttpRequestError.HttpProtocolError, SR.net_http_request_aborted, rejectedException, RequestRetryType.RetryOnConnectionFailure); @@ -353,6 +354,7 @@ await Task.WhenAny(sendRequestTask, readResponseTask).ConfigureAwait(false) == s else { Debug.Assert(_requestBodyCancellationSource.IsCancellationRequested); + if (NetEventSource.Log.IsEnabled()) Trace($"HTTP3 retry path: internal cancellation; callerCanceled={cancellationToken.IsCancellationRequested}. Exception: {ex}"); throw new HttpRequestException(HttpRequestError.Unknown, SR.net_http_request_aborted, ex, RequestRetryType.RetryOnConnectionFailure); } } diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/SocketsHttpHandlerTest.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/SocketsHttpHandlerTest.cs index 66088cb47fa4b3..d8738a7425596f 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/SocketsHttpHandlerTest.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/SocketsHttpHandlerTest.cs @@ -4,6 +4,7 @@ using System.Collections.Generic; using System.Collections.Concurrent; using System.Diagnostics; +using System.Diagnostics.Tracing; using System.IO; using System.IO.Pipes; using System.Linq; @@ -6003,8 +6004,130 @@ public SocketsHttpHandlerTest_HttpClientHandlerTest_Http3(ITestOutputHelper outp [ConditionalClass(typeof(HttpClientHandlerTestBase), nameof(IsHttp3Supported))] public sealed class SocketsHttpHandlerTest_Cookies_Http3 : HttpClientHandlerTest_Cookies { + private Action _cookieRedirectLog; + public SocketsHttpHandlerTest_Cookies_Http3(ITestOutputHelper output) : base(output) { } protected override Version UseVersion => HttpVersion.Version30; + protected override Action CookieRedirectLog => _cookieRedirectLog; + protected override GenericLoopbackOptions CookieRedirectOptions => new Http3Options { Log = _cookieRedirectLog }; + + [Fact] + public override async Task GetAsyncWithRedirect_SetCookieContainer_CorrectCookiesSent() + { + if (!RemoteExecutor.IsSupported) + { + // Preserve coverage without enabling process-wide tracing alongside unrelated tests. + await RunCookieRedirectWithDiagnosticsAsync(enableClientTracing: false); + return; + } + + RemoteInvokeHandle handle = RemoteExecutor.Invoke(static async () => + { + using var test = new SocketsHttpHandlerTest_Cookies_Http3(new ConsoleOutputHelper()); + await test.RunCookieRedirectWithDiagnosticsAsync(enableClientTracing: true); + }, new RemoteInvokeOptions + { + StartInfo = new ProcessStartInfo { RedirectStandardOutput = true }, + TimeOut = 2 * LoopbackServerFactory.LoopbackServerTimeoutMilliseconds + }); + + using StreamReader reader = handle.Process.StandardOutput; + Task output = reader.ReadToEndAsync(); + try + { + await handle.DisposeAsync(); + } + finally + { + _output.WriteLine(await output); + } + } + + private async Task RunCookieRedirectWithDiagnosticsAsync(bool enableClientTracing) + { + const int MaximumEvents = 4096; + var events = new ConcurrentQueue(); + long started = Stopwatch.GetTimestamp(); + int eventCount = 0; + void Log(string message) + { + int sequence = Interlocked.Increment(ref eventCount); + if (sequence <= MaximumEvents) + { + events.Enqueue($"{sequence}: {Stopwatch.GetElapsedTime(started).TotalMilliseconds:F3}ms thread={Environment.CurrentManagedThreadId} {message}"); + } + } + + _cookieRedirectLog = Log; + using var listener = new TestEventListener(); + try + { + Log($"Runtime={System.Runtime.InteropServices.RuntimeInformation.FrameworkDescription}; OS={System.Runtime.InteropServices.RuntimeInformation.OSDescription}; architecture={System.Runtime.InteropServices.RuntimeInformation.ProcessArchitecture}; clientTracing={enableClientTracing}"); + Log($"HTTP assembly={typeof(HttpClient).Assembly.GetCustomAttribute()?.InformationalVersion}; QUIC assembly={typeof(QuicConnection).Assembly.GetCustomAttribute()?.InformationalVersion}"); + await listener.RunWithCallbackAsync(CaptureEvent, async () => + { + if (enableClientTracing) + { + listener.AddSource("Private.InternalDiagnostics.System.Net.Http", EventLevel.Verbose); + listener.AddSource("Private.InternalDiagnostics.System.Net.Quic", EventLevel.Verbose); + } + + await base.GetAsyncWithRedirect_SetCookieContainer_CorrectCookiesSent(); + }); + } + finally + { + // Callbacks only enqueue: abandoned server work must not write to a completed xUnit output helper. + foreach (string entry in events.ToArray()) + { + _output.WriteLine(entry); + } + _output.WriteLine($"Diagnostic events beyond limit: {Math.Max(0, Volatile.Read(ref eventCount) - MaximumEvents)}"); + } + + void CaptureEvent(EventWrittenEventArgs data) + { + if (data.EventSource.Name == "Private.InternalDiagnostics.System.Net.Http" && + data.EventName == "HandlerMessage" && data.Payload?.Count == 5 && + data.Payload[3] is string member && data.Payload[4] is string message) + { + if (member == "SendAsync" && message.StartsWith("System.Net.Http.RedirectHandler: Redirecting ", StringComparison.Ordinal)) + { + Log($"HTTP redirect: requestId={data.Payload[2]}; issuing redirected request."); + return; + } + + // Allow lifecycle messages only, not existing request/response dumps containing headers. + bool capture = member switch + { + "SendAsync" => message.Contains("HTTP3 send start:", StringComparison.Ordinal) || + message.Contains("HTTP3 retry path:", StringComparison.Ordinal) || + message.Contains("Opened request stream:", StringComparison.Ordinal), + "SendWithVersionDetectionAndRetryAsync" => message.StartsWith("Retry attempt ", StringComparison.Ordinal) || + message.StartsWith("MaxConnectionFailureRetries ", StringComparison.Ordinal), + "TryGetPooledHttp3Connection" or "ReturnHttp3Connection" or "InvalidateHttp3Connection" or + "CheckForHttp3ConnectionInjection" or "CheckForShutdown" or "OnServerGoAway" or + "TryReserveStream" or "ReleaseStream" or "GoAway" => true, + _ => false + }; + if (capture) + { + Log($"HTTP pool={data.Payload[0]} worker={data.Payload[1]} stream={data.Payload[2]} {member}: {message}"); + } + } + else if (data.EventSource.Name == "Private.InternalDiagnostics.System.Net.Quic" && + data.EventName is "Info" or "ErrorMessage") + { + Log($"QUIC {data.EventName}: {string.Join(" | ", data.Payload)}"); + } + } + } + + private sealed class ConsoleOutputHelper : ITestOutputHelper + { + public void WriteLine(string message) => Console.WriteLine(message); + public void WriteLine(string format, params object[] args) => Console.WriteLine(format, args); + } } [ConditionalClass(typeof(HttpClientHandlerTestBase), nameof(IsHttp3Supported))]