Repository navigation
System.Net.Http.Functional - HTTP/3 timeouts (mostly on NativeAOT) #75493
Copy link
Copy link
Closed
Labels
area-System.Net.Httpblocking-clean-ciBlocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms'Blocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms'
Milestone
Description
Frequency in last 30 days via Runfo as of 9/12:
- First occurrence on 9/1 in Rolling run 2661
- As of 9/9 it started hitting significantly Rolling runs
- 9/12 - 24x failures (many Rolling runs), i.e. 2x per day ... mostly arm64-NativeAOT with these exceptions:
Examples of failures
System.Net.Http.Functional.Tests.SocketsHttpHandler_RequestContentLengthMismatchTest_Http3.ContentLength_DoesNotMatchRequestContentLength_Throws(contentLength: 0, bytesSent: 1) [FAIL]
Assert.Contains() Failure
Not found: Content-Length
In value: The connection timed out from inactivity. (127.0.0.1:34178)
Stack Trace:
/_/src/libraries/System.Net.Http/tests/FunctionalTests/SocketsHttpHandlerTest.cs(3701,0): at System.Net.Http.Functional.Tests.SocketsHttpHandler_RequestContentLengthMismatchTest.<>c__DisplayClass1_0.<<ContentLength_DoesNotMatchRequestContentLength_Throws>b__0>d.MoveNext()
--- End of stack trace from previous location ---
/_/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(128,0): at System.Threading.Tasks.TaskTimeoutExtensions.GetRealException(Task task)
--- End of stack trace from previous location ---
/_/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(90,0): at System.Threading.Tasks.TaskTimeoutExtensions.WhenAllOrAnyFailed(Task[] tasks)
/_/src/libraries/Common/tests/System/Net/Http/GenericLoopbackServer.cs(39,0): at System.Net.Test.Common.LoopbackServerFactory.<>c__DisplayClass5_0.<<CreateClientAndServerAsync>b__0>d.MoveNext()
--- End of stack trace from previous location ---
/_/src/libraries/Common/tests/System/Net/Http/Http3LoopbackServer.cs(111,0): at System.Net.Test.Common.Http3LoopbackServerFactory.CreateServerAsync(Func`3 funcAsync, Int32 millisecondsTimeout, GenericLoopbackOptions options)
/_/src/libraries/System.Net.Http/tests/FunctionalTests/SocketsHttpHandlerTest.cs(3693,0): at System.Net.Http.Functional.Tests.SocketsHttpHandler_RequestContentLengthMismatchTest.ContentLength_DoesNotMatchRequestContentLength_Throws(Int32 contentLength, Int32 bytesSent)
--- End of stack trace from previous location ---
Output:
Ignored exception:
System.OperationCanceledException: The operation was canceled.
at System.Net.Quic.ValueTaskSource.TryComplete(Exception exception) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/ValueTaskSource.cs:line 119
at System.Net.Quic.ValueTaskSource.TrySetException(Exception exception) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/ValueTaskSource.cs:line 166
at System.Net.Quic.ValueTaskSource.<>c.<TryInitialize>b__10_0(Object obj, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/ValueTaskSource.cs:line 70
at System.Threading.CancellationTokenSource.Invoke(Delegate d, Object state, CancellationTokenSource source) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs:line 874
at System.Threading.CancellationTokenSource.CallbackNode.ExecuteCallback() in /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs:line 1104
at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs:line 699
at System.Threading.CancellationTokenSource.NotifyCancellation(Boolean throwOnFirstException) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs:line 613
at System.Threading.CancellationTokenSource.TimerCallback(Object state) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs:line 35
at System.Threading.TimerQueueTimer.Fire(Boolean isThreadPool) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Timer.cs:line 666
at System.Threading.TimerQueue.FireNextTimers() in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Timer.cs:line 330
at System.Threading.ThreadPoolWorkQueue.Dispatch() in /_/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPoolWorkQueue.cs:line 919
at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() in /_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.WorkerThread.cs:line 77
at System.Threading.Thread.StartCallback() in /_/src/coreclr/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs:line 105
--- End of stack trace from previous location ---
at System.Net.Quic.ValueTaskSource.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/ValueTaskSource.cs:line 176
at System.Net.Quic.QuicListener.PendingConnection.StartHandshake(QuicConnection connection, SslClientHelloInfo clientHello, Func`4 connectionOptionsCallback) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicListener.PendingConnection.cs:line 61
at System.Net.Quic.QuicListener.PendingConnection.DisposeAsync() in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicListener.PendingConnection.cs:line 99
at System.Net.Quic.QuicListener.AcceptConnectionAsync(CancellationToken cancellationToken) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicListener.cs:line 172
at System.Net.Test.Common.Http3LoopbackServer.EstablishHttp3ConnectionAsync() in /_/src/libraries/Common/tests/System/Net/Http/Http3LoopbackServer.cs:line 71
at System.Net.Test.Common.Http3LoopbackServer.EstablishGenericConnectionAsync() in /_/src/libraries/Common/tests/System/Net/Http/Http3LoopbackServer.cs:line 80
at System.Net.Test.Common.Http3LoopbackServer.HandleRequestAsync(HttpStatusCode statusCode, IList`1 headers, String content) in /_/src/libraries/Common/tests/System/Net/Http/Http3LoopbackServer.cs:line 92
at System.Net.Http.Functional.Tests.SocketsHttpHandler_RequestContentLengthMismatchTest.<>c__DisplayClass1_0.<<ContentLength_DoesNotMatchRequestContentLength_Throws>b__1>d.MoveNext() in /_/src/libraries/System.Net.Http/tests/FunctionalTests/SocketsHttpHandlerTest.cs:line 3712
[FAIL] System.Net.Http.Functional.Tests.SocketsHttpHandler_SocketsHttpHandler_SecurityTest_Http3.SslOptions_InvalidName_Throws
System.TimeoutException : The operation has timed out.
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() + 0x28
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task) + 0x104
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task) + 0x5c
at System.Net.Http.Functional.Tests.SocketsHttpHandler_SecurityTest.<SslOptions_InvalidName_Throws>d__2.MoveNext() + 0x1d4
...
[FAIL] System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_Http2.Http2_StreamResetByServerBeforePrefix_RequestFailsWithGoawayProtocolError
Assert.Fail(): Couldn't find HttpProtocolException with matching error code in exception: System.Net.Http.HttpRequestException: An HTTP/2 connection could not be established because the server did not complete the HTTP/2 handshake.
at System.Exception.SetCurrentStackTrace() + 0x64
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.SetCurrentStackTrace(Exception) + 0x1c
at System.Net.Http.HttpConnectionPool.ReturnHttp2Connection(Http2Connection, Boolean, HttpConnectionPool.HttpConnectionWaiter`1) + 0x5a8
at System.Net.Http.HttpConnectionPool.<AddHttp2ConnectionAsync>d__78.MoveNext() + 0x8a0
...
Console log - Helix timeout
...
[SKIP] System.Net.Http.Functional.Tests.SyncHttpHandler_HttpClientHandler_Authentication_Test.Credentials_DomainJoinedServerUsesKerberos_UseIpAddressAndHostHeader_Success
[SKIP] System.Net.Http.Functional.Tests.SocketsHttpHandler_HttpClientHandler_Authentication_Test.Credentials_DomainJoinedServerUsesKerberos_Success
['System.Net.Http.Functional.Tests' END OF WORK ITEM LOG: Command timed out, and was killed]
Report
Summary
| 24-Hour Hit Count | 7-Day Hit Count | 1-Month Count |
|---|---|---|
| 0 | 0 | 0 |
Metadata
Metadata
Assignees
Labels
area-System.Net.Httpblocking-clean-ciBlocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms'Blocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms'
Activity
karelz commentedon Sep 12, 2022
@LakshanF @MichalStrehovsky looks specific to NativeAOT, can you please take a look?
cc @jkotas
karelz commentedon Sep 12, 2022
There have been 2 similar failures on non-NativeAOT (Debian 10 and 11 arm32) - both in the same PR 11455 - PR #75380 (by @wfurt) -- any idea what that was @wfurt?
jkotas commentedon Sep 13, 2022
#75471 is opened on that.
jkotas commentedon Sep 13, 2022
The failures listed in #75471 are exactly same, so this does not appear to be native aot specific. The frequency just comes and goes due to unrelated changes in timing.
All failing tests seem to be Http3 tests, that means Quic is suspect.
[-]System.Net.Http.Functional - NativeAOT timeouts[/-][+]System.Net.Http.Functional - HTTP/3 timeouts (mostly on NativeAOT)[/+]jkotas commentedon Sep 13, 2022
This has correlation with #74749 and #75163. The first attempt was merged on 9/1 and reverted on 9/2, that aligns with the first occurrence. The second attempt was merged on 9/9, that aligns with when it started hitting significantly.
Take this with grain of salt. The quic unloading change might have just changed the timing such that the problem is hit more often.
wfurt commentedon Sep 13, 2022
note that we never run Quic tests on arm32 before. While the observed failure may be the same, root cause may be different. I think #75471 should be investigated separately -> and closed if we get successful run.
wfurt commentedon Sep 13, 2022
I did another test run on arm32 with #75441 merged.
And it still fails.
https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-75514-merge-992d2626db1c4efaa6/System.Net.Quic.Functional.Tests/1/console.b37eda48.log?helixlogtype=result
karelz commentedon Sep 13, 2022
While it does not happen in 7.0, it is blocking 7.0 fix for #74629 -- so moving it into 7.0 to make sure it is gone from main and we have green light to backport fix for #74629 into 7.0 branch.
rzikm commentedon Sep 14, 2022
This issue seems to reliably happen on arm32 platforms, the connection establishment attempt times out.
Further digging points at potential MsQuic issue on arm32, MsQuic sends only the first datagram and rest of the sends fail with EINVAL
MsQuic trace
Details
rzikm commentedon Sep 14, 2022
Submitted fix for the above (arm32 non-NativeAOT timeouts) for MsQuic microsoft/msquic#3065. I will look at Arm64 failures next.
rzikm commentedon Sep 14, 2022
Not all timeouts occur in HTTP3 tests, e.g. https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-75381-merge-abd43458a4a042cf95/System.Net.Http.Functional.Tests/1/console.d67787ff.log?helixlogtype=result, the first failure occurred before we even got to send HTTP3 request. (it failed during HTTP2 request to get Alt-Svc header).
Another failure in HTTP2 only test https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-heads-main-540330e989f54fc08b/System.Net.Http.Functional.Tests/1/console.95517a16.log?helixlogtype=result
So far not able to reproduce locally by running tests in tight loop :/
rzikm commentedon Sep 20, 2022
The last occurence of the issue on main on NativeAOT is 09-12 according to following Kusto query
There is one OSX timeout on 09-16, but that seems to unrelated (no other Native AOT timeouts in last 3 weeks).
This correlates with merging of #75441 on 09-13.
I think we can close this issue for now, and track the rest of the timeouts in #75611