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/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs index f6a843cf21f530..d45543e7fe4fcc 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs @@ -1540,11 +1540,13 @@ await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( private sealed class SendMultipleTimesHandler : DelegatingHandler { private readonly Activity[] _parentActivities; + private readonly Action _log; - public SendMultipleTimesHandler(HttpMessageHandler innerHandler, params Activity[] parentActivities) : base(innerHandler) + public SendMultipleTimesHandler(HttpMessageHandler innerHandler, Action log, params Activity[] parentActivities) : base(innerHandler) { Assert.NotEmpty(parentActivities); _parentActivities = parentActivities; + _log = log; } protected override HttpResponseMessage Send(HttpRequestMessage request, CancellationToken cancellationToken) @@ -1560,11 +1562,15 @@ private async ValueTask SendAsync(HttpRequestMessage reques { parent.Start(); Assert.Equal(ActivityIdFormat.W3C, parent.IdFormat); + _log($"{parent.OperationName}: Sending request."); response = testAsync ? await base.SendAsync(request, cancellationToken) : base.Send(request, cancellationToken); + _log($"{parent.OperationName}: Received response {(int)response.StatusCode}."); parent.Stop(); if (parent != _parentActivities.Last()) { + _log($"{parent.OperationName}: Disposing response."); response.Dispose(); // only keep the last response + _log($"{parent.OperationName}: Response disposed."); } } return response; @@ -1581,34 +1587,64 @@ public async Task SendAsync_ReuseRequestInHandler_ResetsHeadersForEachReuse() const string FirstTraceParent = "00-F"; const string FirstTraceState = "first"; - await GetFactoryForVersion(UseVersion).CreateServerAsync(async (server, uri) => + var log = new ConcurrentQueue(); + long startTime = Environment.TickCount64; + Task clientTask = null; + try { - SendMultipleTimesHandler handler = new SendMultipleTimesHandler(CreateSocketsHttpHandler(allowAllCertificates: true), parent0, parent1, parent2); - using HttpClient client = new HttpClient(handler); - HttpRequestMessage request = CreateRequest(HttpMethod.Get, uri, UseVersion, exactVersion: true); - - request.Headers.Add("traceparent", FirstTraceParent); - request.Headers.Add("tracestate", FirstTraceState); - - Task clientTask = TestAsync ? client.SendAsync(request) : Task.Run(() => client.Send(request)); - - HttpRequestData requestData = await server.AcceptConnectionSendResponseAndCloseAsync(statusCode: HttpStatusCode.InternalServerError); - - // On the first send DiagnosticsHandler should keep user-supplied headers. - string traceparent = GetHeaderValue(requestData, "traceparent"); - string tracestate = GetHeaderValue(requestData, "tracestate"); - Assert.Equal(FirstTraceParent, traceparent); - Assert.Equal(FirstTraceState, tracestate); - - requestData = await server.AcceptConnectionSendResponseAndCloseAsync(statusCode: HttpStatusCode.InternalServerError); - - // Headers should be overridden on each subsequent send. - AssertHeadersAreInjected(requestData, parent1); - requestData = await server.AcceptConnectionSendResponseAndCloseAsync(statusCode: HttpStatusCode.OK); - AssertHeadersAreInjected(requestData, parent2); + await GetFactoryForVersion(UseVersion).CreateServerAsync(async (server, uri) => + { + SendMultipleTimesHandler handler = new SendMultipleTimesHandler(CreateSocketsHttpHandler(allowAllCertificates: true), Log, parent0, parent1, parent2); + using HttpClient client = new HttpClient(handler); + HttpRequestMessage request = CreateRequest(HttpMethod.Get, uri, UseVersion, exactVersion: true); + + request.Headers.Add("traceparent", FirstTraceParent); + request.Headers.Add("tracestate", FirstTraceState); + + Volatile.Write(ref clientTask, TestAsync ? client.SendAsync(request) : Task.Run(() => client.Send(request))); + + Log("Server: Handling request 1."); + HttpRequestData requestData = await server.AcceptConnectionSendResponseAndCloseAsync(statusCode: HttpStatusCode.InternalServerError); + + Log("Server: Checking request 1 headers."); + // On the first send DiagnosticsHandler should keep user-supplied headers. + string traceparent = GetHeaderValue(requestData, "traceparent"); + string tracestate = GetHeaderValue(requestData, "tracestate"); + Assert.Equal(FirstTraceParent, traceparent); + Assert.Equal(FirstTraceState, tracestate); + + Log("Server: Handling request 2."); + requestData = await server.AcceptConnectionSendResponseAndCloseAsync(statusCode: HttpStatusCode.InternalServerError); + + Log("Server: Checking request 2 headers."); + // Headers should be overridden on each subsequent send. + AssertHeadersAreInjected(requestData, parent1); + Log("Server: Handling request 3."); + requestData = await server.AcceptConnectionSendResponseAndCloseAsync(statusCode: HttpStatusCode.OK); + Log("Server: Checking request 3 headers."); + AssertHeadersAreInjected(requestData, parent2); + + Log("Awaiting client task."); + await clientTask; + Log("Client task completed."); + }, options: UseVersion == HttpVersion30 ? new Http3Options { Log = Log } : null); + } + finally + { + // The factory timeout does not stop the callback, so snapshot its diagnostics without writing from that callback to the test output. + Task task = Volatile.Read(ref clientTask); + _output.WriteLine($"Client task status: {task?.Status.ToString() ?? "not started"}"); + if (task?.Exception is Exception exception) + { + _output.WriteLine($"Client task exception: {exception}"); + } + foreach (string message in log.ToArray()) + { + _output.WriteLine(message); + } + } - await clientTask; - }); + void Log(string message) => log.Enqueue($"{Environment.TickCount64 - startTime} ms: {message}"); } [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))]