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.

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

CI Test #100951

Closed
wants to merge 51 commits into from
Closed

CI Test #100951

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
51 commits
Select commit Hold shift + click to select a range
ba2536b
Add logging to HTTP/3 test
liveans Apr 12, 2024
503d355
Merge branch 'main' into add_logging_to_http3_test
liveans Apr 12, 2024
272121a
Dispose EventListener and fix version
liveans Apr 12, 2024
4396379
Add logging to SetAfterUse test
liveans Apr 15, 2024
ca2f4fa
Call Dispose for listeners
liveans Apr 15, 2024
34160a1
Remove unnecessary logs for investigation
liveans Apr 16, 2024
3697c87
Add more log to understand which connection is ours
liveans Apr 16, 2024
134fd3d
Add output to loopback connection
liveans Apr 16, 2024
5f02f24
Merge branch 'main' into add_logging_to_http3_test
liveans Apr 16, 2024
393d283
Remove ActiveIssues
liveans Apr 16, 2024
f1b6cc7
Add more logging and WaitAsync
liveans Apr 17, 2024
ad9cf2b
Delete http from logging as well
liveans Apr 17, 2024
03e38e3
Delete WaitAsync
liveans Apr 17, 2024
efbc1e9
Add more logging around stream accepting
liveans Apr 18, 2024
dddf05e
Revert "Run MsQuic tests in parallel again. (#100947)"
liveans Apr 19, 2024
3d9e868
Add more logging even in Http3Loopback
liveans Apr 19, 2024
7a0476c
Enable logging in H3Loopback
liveans Apr 20, 2024
39cc76f
Fail on idle connection
liveans Apr 20, 2024
d3b6620
Crash on failure only if logging is enabled
liveans Apr 20, 2024
d36b894
Add more logging and delete debug fail
liveans Apr 20, 2024
594d3a5
Change GenericConnectionEstablishment to Direct Http3Establishment Me…
liveans Apr 23, 2024
b3ec57a
Merge branch 'main' into add_logging_to_http3_test
liveans Apr 26, 2024
5e260c0
Revert "Disable parallel test execution for QUIC and HTTP/3 (#101569)"
liveans Apr 26, 2024
c31cdb1
Revert "Disable frequently failing tests (#101439)"
liveans Apr 26, 2024
c466dfe
Add WaitAsync on ConnectionEstablishment for H/3 on Loopback Server
liveans Apr 27, 2024
07f8871
Add logging to another test
liveans May 2, 2024
1b54ef0
Add another log and increase timeout
liveans May 2, 2024
c98aca6
Add debug fail to idle case
liveans May 2, 2024
4fc2253
Convert assertion to noop
liveans May 2, 2024
e1d4940
Delete extra logs and enable logging only for H3
liveans May 2, 2024
8c7b78a
Convert crash to log
liveans May 13, 2024
33cac20
Merge branch 'main' into add_logging_to_http3_test
liveans May 13, 2024
9826432
Add logging to other tests
liveans May 14, 2024
164e252
Pass testoutputhelper to other functions as well
liveans May 14, 2024
e337a40
Disable Svc Upgrade to H/3 test
liveans May 20, 2024
9f50213
Add more log
liveans May 20, 2024
62f65db
Http3Connection add trace
liveans May 21, 2024
7436ee8
Disable some test so I can repro another
liveans May 22, 2024
bda7314
Disable AltSvc Tests
liveans May 22, 2024
a468fb5
Add Miha's trick
liveans May 22, 2024
d7218f3
TestEventListener NetworkingEvents revert
liveans May 22, 2024
4479ccf
Add more logging to other tests
liveans May 22, 2024
89f6102
Call Dispose
liveans May 22, 2024
1e54a46
Convert to fail
liveans May 24, 2024
61725c6
Delete errorCode
liveans May 24, 2024
a31d224
Add ConfigureAwait(false) and convert fail to log
liveans May 24, 2024
2f0cce2
Add more ConfigureAwait and a bit logs
liveans May 25, 2024
2d37bb0
Add ConfigureAwait(false) again
liveans May 25, 2024
a770b2a
Add more ConfigureAwait(false) to see if it actually fixes
liveans May 25, 2024
3b5a39d
Add logging to helper function
liveans May 25, 2024
ba32647
Merge branch 'main' into add_logging_to_http3_test
liveans May 26, 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
Original file line number Diff line number Diff line change
Expand Up @@ -77,7 +77,8 @@ public static void Info(object? thisOrContextObject, object? message, [CallerMem
[Event(InfoEventId, Level = EventLevel.Informational, Keywords = Keywords.Default)]
private void Info(string thisOrContextObject, string? memberName, string? message)
{
Debug.Assert(IsEnabled());
//Debug.Assert(IsEnabled());
if (!IsEnabled()) return;
WriteEvent(InfoEventId, thisOrContextObject, memberName ?? MissingMember, message);
}
#endregion
Expand All @@ -102,7 +103,8 @@ public static void Error(object? thisOrContextObject, object message, [CallerMem
[Event(ErrorEventId, Level = EventLevel.Error, Keywords = Keywords.Default)]
private void ErrorMessage(string thisOrContextObject, string? memberName, string? message)
{
Debug.Assert(IsEnabled());
//Debug.Assert(IsEnabled());
if (!IsEnabled()) return;
WriteEvent(ErrorEventId, thisOrContextObject, memberName ?? MissingMember, message);
}
#endregion
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -188,6 +188,7 @@ public class GenericLoopbackOptions
#if !NETSTANDARD2_0 && !NETFRAMEWORK
public SslStreamCertificateContext? CertificateContext { get; set; }
#endif
public Xunit.Abstractions.ITestOutputHelper? TestOutputHelper { get; set; }
}

public struct HttpHeaderData
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -52,9 +52,12 @@ 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)
private Xunit.Abstractions.ITestOutputHelper? _output;

public Http3LoopbackConnection(QuicConnection connection, Xunit.Abstractions.ITestOutputHelper? output)
{
_connection = connection;
_output = output;
}

public long MaxHeaderListSize { get; private set; } = -1;
Expand Down Expand Up @@ -92,12 +95,12 @@ public override async ValueTask DisposeAsync()

public async ValueTask<Http3LoopbackStream> OpenUnidirectionalStreamAsync()
{
return new Http3LoopbackStream(await _connection.OpenOutboundStreamAsync(QuicStreamType.Unidirectional));
return new Http3LoopbackStream(await _connection.OpenOutboundStreamAsync(QuicStreamType.Unidirectional), _output);
}

public async ValueTask<Http3LoopbackStream> OpenBidirectionalStreamAsync()
{
return new Http3LoopbackStream(await _connection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional));
return new Http3LoopbackStream(await _connection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional), _output);
}

public static int GetRequestId(QuicStream stream)
Expand All @@ -124,23 +127,23 @@ private Task EnsureControlStreamAcceptedAsync()
async Task EnsureControlStreamAcceptedInternalAsync()
{
Http3LoopbackStream controlStream;

while (true)
{
_output?.WriteLine($"{this} {_connection} Accepting a new stream");
QuicStream quicStream = await _connection.AcceptInboundStreamAsync().ConfigureAwait(false);

_output?.WriteLine($"{this} {quicStream} Accepted a stream, CanWrite = {quicStream.CanWrite}");
if (!quicStream.CanWrite)
{
// control stream accepted
controlStream = new Http3LoopbackStream(quicStream);
controlStream = new Http3LoopbackStream(quicStream, _output);
break;
}

// control streams are unidirectional, so this must be a request stream
// keep it for later and wait for another stream
_delayedStreams.Enqueue(quicStream);
}

_output?.WriteLine($"{this} {_connection} All streams has been caught, delayed streams count = {_delayedStreams.Count}");
long? streamType = await controlStream.ReadIntegerAsync();
Assert.Equal(Http3LoopbackStream.ControlStream, streamType);

Expand All @@ -157,14 +160,15 @@ async Task EnsureControlStreamAcceptedInternalAsync()
// This will automatically handle the control stream, including validating its contents
public async Task<Http3LoopbackStream> AcceptRequestStreamAsync()
{
_output?.WriteLine($"{this} {_connection} Accepting control stream.");
await EnsureControlStreamAcceptedAsync().ConfigureAwait(false);

if (!_delayedStreams.TryDequeue(out QuicStream quicStream))
{
quicStream = await _connection.AcceptInboundStreamAsync().ConfigureAwait(false);
}

var stream = new Http3LoopbackStream(quicStream);
var stream = new Http3LoopbackStream(quicStream, _output);

Assert.True(quicStream.CanWrite, "Expected writeable stream.");

Expand All @@ -185,9 +189,11 @@ public async Task<Http3LoopbackStream> AcceptRequestStreamAsync()

public async Task EstablishControlStreamAsync(SettingsEntry[] settingsEntries)
{
_outboundControlStream = await OpenUnidirectionalStreamAsync();
await _outboundControlStream.SendUnidirectionalStreamTypeAsync(Http3LoopbackStream.ControlStream);
await _outboundControlStream.SendSettingsFrameAsync(settingsEntries);
_output?.WriteLine($"{this} Establishing control stream");
_outboundControlStream = await OpenUnidirectionalStreamAsync().ConfigureAwait(false);
_output?.WriteLine($"{this} {_outboundControlStream.Stream} Stream opened.");
await _outboundControlStream.SendUnidirectionalStreamTypeAsync(Http3LoopbackStream.ControlStream).ConfigureAwait(false);
await _outboundControlStream.SendSettingsFrameAsync(settingsEntries).ConfigureAwait(false);
}

public async Task DisposeCurrentStream()
Expand Down Expand Up @@ -241,6 +247,7 @@ public override Task SendPartialResponseHeadersAsync(HttpStatusCode statusCode =

public override async Task<HttpRequestData> HandleRequestAsync(HttpStatusCode statusCode = HttpStatusCode.OK, IList<HttpHeaderData> headers = null, string content = "")
{
_output?.WriteLine($"{this} {_connection} HandleRequestAsync triggered.");
Http3LoopbackStream stream = await AcceptRequestStreamAsync().ConfigureAwait(false);

HttpRequestData request = await stream.ReadRequestDataAsync().ConfigureAwait(false);
Expand Down
17 changes: 13 additions & 4 deletions src/libraries/Common/tests/System/Net/Http/Http3LoopbackServer.cs
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@ public sealed class Http3LoopbackServer : GenericLoopbackServer
{
private X509Certificate2 _cert;
private QuicListener _listener;
private Xunit.Abstractions.ITestOutputHelper? _output;

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

Expand Down Expand Up @@ -58,6 +59,8 @@ public Http3LoopbackServer(Http3Options options = null)
ValueTask<QuicListener> valueTask = QuicListener.ListenAsync(listenerOptions);
Debug.Assert(valueTask.IsCompleted);
_listener = valueTask.Result;
_output = options.TestOutputHelper;
_output?.WriteLine($"{this} Http3LoopbackServer created.");
}

public override void Dispose()
Expand All @@ -68,16 +71,19 @@ public override void Dispose()

private async Task<Http3LoopbackConnection> EstablishHttp3ConnectionAsync(params SettingsEntry[] settingsEntries)
{
_output?.WriteLine($"{this} Accepting connection");
QuicConnection con = await _listener.AcceptConnectionAsync().ConfigureAwait(false);
Http3LoopbackConnection connection = new Http3LoopbackConnection(con);
_output?.WriteLine($"{this} Connection accepted: {con}");
Http3LoopbackConnection connection = new Http3LoopbackConnection(con, _output);

await connection.EstablishControlStreamAsync(settingsEntries);
await connection.EstablishControlStreamAsync(settingsEntries).ConfigureAwait(false);
_output?.WriteLine($"{this} {con} Control stream established");
return connection;
}

public override async Task<GenericLoopbackConnection> EstablishGenericConnectionAsync()
{
return await EstablishHttp3ConnectionAsync();
return await EstablishHttp3ConnectionAsync().ConfigureAwait(false);
}

public Task<Http3LoopbackConnection> EstablishConnectionAsync(params SettingsEntry[] settingsEntries)
Expand All @@ -94,7 +100,9 @@ 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 = (Http3LoopbackConnection)await EstablishGenericConnectionAsync().ConfigureAwait(false);
_output?.WriteLine("Establishing HTTP/3 connection.");
await using Http3LoopbackConnection con = await EstablishHttp3ConnectionAsync().ConfigureAwait(false);
_output?.WriteLine($"{con} HTTP/3 Connection established successfully!");
return await con.HandleRequestAsync(statusCode, headers, content).ConfigureAwait(false);
}
}
Expand Down Expand Up @@ -138,6 +146,7 @@ private static Http3Options CreateOptions(GenericLoopbackOptions options)
http3Options.Certificate = options.Certificate;
http3Options.SslProtocols = options.SslProtocols;
http3Options.ListenBacklog = options.ListenBacklog;
http3Options.TestOutputHelper = options.TestOutputHelper;
}
return http3Options;
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -34,13 +34,19 @@ public sealed class Http3LoopbackStream : IAsyncDisposable
public bool CanRead => _stream.CanRead;
public bool CanWrite => _stream.CanWrite;

public Http3LoopbackStream(QuicStream stream)
private Xunit.Abstractions.ITestOutputHelper? _output;

public Http3LoopbackStream(QuicStream stream, Xunit.Abstractions.ITestOutputHelper? output)
{
_stream = stream;
_output = output;
_output?.WriteLine($"Created stream {stream}, Readable: {stream.CanRead}, Writable: {stream.CanWrite}");
}

public ValueTask DisposeAsync() => _stream.DisposeAsync();

public QuicStream Stream => _stream;

public long StreamId => _stream.Id;

public async Task<HttpRequestData> HandleRequestAsync(HttpStatusCode statusCode = HttpStatusCode.OK, IList<HttpHeaderData> headers = null, string content = "")
Expand Down Expand Up @@ -162,7 +168,9 @@ private async Task SendFrameHeaderAsync(long frameType, int payloadLength)
public async Task SendFrameAsync(long frameType, ReadOnlyMemory<byte> framePayload)
{
await SendFrameHeaderAsync(frameType, framePayload.Length).ConfigureAwait(false);
_output?.WriteLine($"Sent {frameType} header");
await _stream.WriteAsync(framePayload).ConfigureAwait(false);
_output?.WriteLine($"Sent {framePayload} - Length: {framePayload.Length} frame");
}

static int EncodeHttpInteger(long longToEncode, Span<byte> buffer)
Expand Down Expand Up @@ -431,9 +439,11 @@ public void Abort(long errorCode)
public async Task<(long? frameType, byte[] payload)> ReadFrameAsync()
{
long? frameType = await ReadIntegerAsync().ConfigureAwait(false);
_output?.WriteLine($"Read frame type: {frameType}");
if (frameType == null) return (null, null);

long? payloadLength = await ReadIntegerAsync().ConfigureAwait(false);
_output?.WriteLine($"Read payload length: {payloadLength}");
if (payloadLength == null) throw new Exception("Unable to read frame; unexpected end of stream.");

byte[] payload = new byte[checked((int)payloadLength)];
Expand All @@ -442,11 +452,13 @@ public void Abort(long errorCode)
while (totalBytesRead != payloadLength)
{
int bytesRead = await _stream.ReadAsync(payload.AsMemory(totalBytesRead)).ConfigureAwait(false);
_output?.WriteLine($"Read {bytesRead} bytes of payload");
if (bytesRead == 0) throw new Exception("Unable to read frame; unexpected end of stream.");

totalBytesRead += bytesRead;
}

_output?.WriteLine($"Read frame payload: {payload}");
return (frameType, payload);
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -44,7 +44,7 @@ private static CookieContainer CreateSingleCookieContainer(Uri uri, string cooki
private static string GetCookieHeaderValue(string cookieName, string cookieValue) => $"{cookieName}={cookieValue}";

[Fact]
public virtual async Task GetAsync_DefaultCoookieContainer_NoCookieSent()
public async Task GetAsync_DefaultCoookieContainer_NoCookieSent()
{
await LoopbackServerFactory.CreateClientAndServerAsync(
async uri =>
Expand Down Expand Up @@ -216,15 +216,10 @@ private string GetCookieValue(HttpRequestData request)
return cookieHeaderValue;
}

[ConditionalFact]
[Fact]
[SkipOnPlatform(TestPlatforms.Browser, "CookieContainer is not supported on Browser")]
public async Task GetAsync_SetCookieContainerAndCookieHeader_BothCookiesSent()
{
if (UseVersion == HttpVersion30)
{
throw new SkipTestException("https://github.com/dotnet/runtime/issues/101377");
}

await LoopbackServerFactory.CreateServerAsync(async (server, url) =>
{
HttpClientHandler handler = CreateHttpClientHandler();
Expand Down Expand Up @@ -318,7 +313,7 @@ await LoopbackServerFactory.CreateClientAndServerAsync(async url =>
using (HttpClient client = CreateHttpClient(handler))
{
client.DefaultRequestHeaders.ConnectionClose = true; // to avoid issues with connection pooling
await client.GetAsync(url1);
await client.GetAsync(url1);
}
},
async server =>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,7 @@
using Microsoft.DotNet.XUnitExtensions;
using Xunit;
using Xunit.Abstractions;
using TestUtilities;

namespace System.Net.Http.Functional.Tests
{
Expand Down Expand Up @@ -56,6 +57,24 @@ public void ValidValue_SetGet_Roundtrips(int validValue)
[Fact]
public async Task SetAfterUse_Throws()
{
AsyncLocal<object> asyncLocal = new();
asyncLocal.Value = new();

TestEventListener? listener = null;
if (UseVersion == HttpVersion30)
{
listener = new TestEventListener(e =>
{
if (asyncLocal.Value is not null)
{
lock (_output)
{
_output.WriteLine($"[SetAfterUse]{e}");
}
}
}, TestEventListener.NetworkingEvents);
}

await LoopbackServerFactory.CreateClientAndServerAsync(async uri =>
{
using HttpClientHandler handler = CreateHttpClientHandler();
Expand All @@ -65,14 +84,33 @@ await LoopbackServerFactory.CreateClientAndServerAsync(async uri =>
(await client.GetStreamAsync(uri)).Dispose();
Assert.Throws<InvalidOperationException>(() => handler.MaxResponseHeadersLength = 1);
},
server => server.AcceptConnectionSendResponseAndCloseAsync());
server => server.AcceptConnectionSendResponseAndCloseAsync(), options: new() { TestOutputHelper = _output });
listener?.Dispose();
}

[Theory]
[InlineData(1)]
[InlineData(15)]
public async Task LargeSingleHeader_ThrowsException(int maxResponseHeadersLength)
{
AsyncLocal<object> asyncLocal = new();
asyncLocal.Value = new();

TestEventListener? listener = null;
if (UseVersion == HttpVersion30)
{
listener = new TestEventListener(e =>
{
if (asyncLocal.Value is not null)
{
lock (_output)
{
_output.WriteLine($"[LargeSingleHeader_ThrowsException]{e}");
}
}
}, TestEventListener.NetworkingEvents);
}

using HttpClientHandler handler = CreateHttpClientHandler();
handler.MaxResponseHeadersLength = maxResponseHeadersLength;

Expand All @@ -88,6 +126,7 @@ await LoopbackServerFactory.CreateClientAndServerAsync(async uri =>
},
async server =>
{
_output.WriteLine($"Listening on {server.Address}");
try
{
await server.HandleRequestAsync(headers: new[] { new HttpHeaderData("Foo", new string('a', handler.MaxResponseHeadersLength * 1024)) });
Expand All @@ -97,7 +136,9 @@ await LoopbackServerFactory.CreateClientAndServerAsync(async uri =>
#if !WINHTTPHANDLER_TEST
catch (QuicException ex) when (ex.QuicError == QuicError.StreamAborted && ex.ApplicationErrorCode == Http3ExcessiveLoad) {}
#endif
});
}, options: new() { TestOutputHelper = _output });

listener?.Dispose();
}

[Theory]
Expand Down
Loading
Loading