Skip to content

[NO-REVIEW] Add diagnostics for HTTP/3 cookie redirect failures #134591

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
+250 −18
Open

[NO-REVIEW] Add diagnostics for HTTP/3 cookie redirect failures #134591

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
70 changes: 59 additions & 11 deletions src/libraries/Common/tests/System/Net/Http/HttpClientHandlerTest.Cookies.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -296,16 +296,35 @@ await LoopbackServerFactory.CreateServerAsync(async (server, url) =>
});
}

protected virtual Action<string> 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<string> 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);
Expand All @@ -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;
}
}
}

//
Expand Down
6 changes: 6 additions & 0 deletions ...et.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http3.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
{
Expand Down Expand Up @@ -428,17 +429,21 @@ private void ReturnHttp3Connection(Http3Connection connection, bool isNewConnect
added = true;
_availableHttp3Connections ??= new List<Http3Connection>();
_availableHttp3Connections.Add(connection);
if (NetEventSource.Log.IsEnabled()) connection.Trace($"Added to available list: availableConnections={_availableHttp3Connections.Count}, associatedConnections={_associatedHttp3ConnectionCount}");
}
}

if (waiter is not null)
{
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
}
Expand Down Expand Up @@ -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();
}

Expand Down
Loading
Loading