Skip to content

[No review] Add diagnostics for HTTP/3 request reuse test timeouts #134413

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

Open
rzikm wants to merge 1 commit into
base: main
Choose a base branch
from
+111 −30
Open

[No review] Add diagnostics for HTTP/3 request reuse test timeouts #134413

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
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
31 changes: 30 additions & 1 deletion src/libraries/Common/tests/System/Net/Http/Http3LoopbackConnection.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -34,6 +34,7 @@ public sealed class Http3LoopbackConnection : GenericLoopbackConnection
public const long H3_VERSION_FALLBACK = 0x110;

private readonly QuicConnection _connection;
private readonly Action<string> _log;

// Queue for holding streams we accepted before we managed to accept the control stream
private readonly Queue<QuicStream> _delayedStreams = new Queue<QuicStream>();
Expand All @@ -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<string> log = null)
{
_connection = connection;
_log = log;
}

public long MaxHeaderListSize { get; private set; } = -1;
Expand All @@ -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();
Expand Down Expand Up @@ -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)
{
Expand All @@ -141,16 +151,19 @@ 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);

Assert.Equal(Http3LoopbackStream.MaxHeaderListSize, settingId);
MaxHeaderListSize = settingValue;

_inboundControlStream = controlStream;
_log?.Invoke($"{_connection}: Client settings read.");
}
}

Expand All @@ -161,6 +174,7 @@ public async Task<Http3LoopbackStream> AcceptRequestStreamAsync()

if (!_delayedStreams.TryDequeue(out QuicStream quicStream))
{
_log?.Invoke($"{_connection}: Accepting request stream.");
quicStream = await _connection.AcceptInboundStreamAsync().ConfigureAwait(false);
}

Expand All @@ -171,6 +185,7 @@ public async Task<Http3LoopbackStream> AcceptRequestStreamAsync()
_openStreams.Add(checked((int)quicStream.Id), stream);
_currentStream = stream;
_currentStreamId = quicStream.Id;
_log?.Invoke($"{_connection}: Request stream {_currentStreamId} accepted.");

return stream;
}
Expand All @@ -185,9 +200,13 @@ public async Task<Http3LoopbackStream> 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()
Expand Down Expand Up @@ -249,17 +268,22 @@ public override async Task<HttpRequestData> 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;
}
Expand Down Expand Up @@ -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);
}
}
Expand All @@ -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<QuicException>(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)
Expand Down
20 changes: 18 additions & 2 deletions src/libraries/Common/tests/System/Net/Http/Http3LoopbackServer.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,13 +15,15 @@ public sealed class Http3LoopbackServer : GenericLoopbackServer
{
private X509Certificate2 _cert;
private QuicListener _listener;
private readonly Action<string> _log;

public override Uri Address => new Uri($"https://{_listener.LocalEndPoint}/");

public Http3LoopbackServer(Http3Options options = null)
{
options ??= new Http3Options();

_log = options.Log;
_cert = options.Certificate ?? Configuration.Certificates.GetServerCertificate();

var listenerOptions = new QuicListenerOptions()
Expand Down Expand Up @@ -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<Http3LoopbackConnection> 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;
Expand All @@ -94,7 +100,15 @@ public override async Task AcceptConnectionAsync(Func<GenericLoopbackConnection,
public override async Task<HttpRequestData> HandleRequestAsync(HttpStatusCode statusCode = HttpStatusCode.OK, IList<HttpHeaderData> 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;
}
}
}

Expand Down Expand Up @@ -143,6 +157,8 @@ private static Http3Options CreateOptions(GenericLoopbackOptions options)
}
public class Http3Options : GenericLoopbackOptions
{
public Action<string> Log { get; set; }

public int MaxInboundUnidirectionalStreams { get; set; }

public int MaxInboundBidirectionalStreams { get; set; }
Expand Down
90 changes: 63 additions & 27 deletions src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1540,11 +1540,13 @@ await GetFactoryForVersion(useVersion).CreateClientAndServerAsync(
private sealed class SendMultipleTimesHandler : DelegatingHandler
{
private readonly Activity[] _parentActivities;
private readonly Action<string> _log;

public SendMultipleTimesHandler(HttpMessageHandler innerHandler, params Activity[] parentActivities) : base(innerHandler)
public SendMultipleTimesHandler(HttpMessageHandler innerHandler, Action<string> log, params Activity[] parentActivities) : base(innerHandler)
{
Assert.NotEmpty(parentActivities);
_parentActivities = parentActivities;
_log = log;
}

protected override HttpResponseMessage Send(HttpRequestMessage request, CancellationToken cancellationToken)
Expand All @@ -1560,11 +1562,15 @@ private async ValueTask<HttpResponseMessage> 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;
Expand All @@ -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<string>();
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))]
Expand Down
Loading