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

System.Net tests failing with System.TimeoutException #54778

Closed
jkotas opened this issue Jun 26, 2021 · 20 comments
Closed

System.Net tests failing with System.TimeoutException #54778

jkotas opened this issue Jun 26, 2021 · 20 comments
Labels
area-System.Net.Http test-run-core Test failures in .NET Core test runs
Milestone

Comments

@jkotas
Copy link
Member

jkotas commented Jun 26, 2021

For example:

  • Test: System.Net.Http.Functional.Tests.SocketsHttpHandler_HttpClientHandler_ConnectionPooling_Test.Http2_SmallConnectionTimeout_SubsequentRequestUsesDifferentConnection
      System.TimeoutException : The operation has timed out.
      Stack Trace:
        /_/src/libraries/Common/tests/System/Net/Http/Http2LoopbackServer.cs(196,0): at System.Net.Test.Common.Http2LoopbackServerFactory.CreateServerAsync(Func`3 funcAsync, Int32 millisecondsTimeout)
        /_/src/libraries/System.Net.Http/tests/FunctionalTests/SocketsHttpHandlerTest.cs(1441,0): at System.Net.Http.Functional.Tests.SocketsHttpHandler_HttpClientHandler_ConnectionPooling_Test.Http2_SmallConnectionTimeout_SubsequentRequestUsesDifferentConnection(String timeoutPropertyName)
        --- End of stack trace from previous location ---
@dotnet-issue-labeler dotnet-issue-labeler bot added area-System.Net.Http untriaged New issue has not been triaged by the area owner labels Jun 26, 2021
@ghost
Copy link

ghost commented Jun 26, 2021

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

Issue Details

For example:

      System.TimeoutException : The operation has timed out.
      Stack Trace:
        /_/src/libraries/Common/tests/System/Net/Http/Http2LoopbackServer.cs(196,0): at System.Net.Test.Common.Http2LoopbackServerFactory.CreateServerAsync(Func`3 funcAsync, Int32 millisecondsTimeout)
        /_/src/libraries/System.Net.Http/tests/FunctionalTests/SocketsHttpHandlerTest.cs(1441,0): at System.Net.Http.Functional.Tests.SocketsHttpHandler_HttpClientHandler_ConnectionPooling_Test.Http2_SmallConnectionTimeout_SubsequentRequestUsesDifferentConnection(String timeoutPropertyName)
        --- End of stack trace from previous location ---
Author: jkotas
Assignees: -
Labels:

area-System.Net.Http, untriaged

Milestone: -

@jkotas jkotas changed the title Random System.Net failing with System.TimeoutException System.Net tests failing with System.TimeoutException Jun 26, 2021
@jkotas
Copy link
Member Author

jkotas commented Jun 26, 2021

Failed in #54656

Examples:

  • Test: System.Net.Http.Functional.Tests.SyncHttpHandler_HttpProtocolTests_Dribble.GetAsync_ResponseHasNormalLineEndings_Success
      System.TimeoutException : The operation has timed out.
      Stack Trace:
        /_/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(49,0): at System.Threading.Tasks.TaskTimeoutExtensions.WhenAllOrAnyFailed(Task[] tasks, Int32 millisecondsTimeout)
        /_/src/libraries/Common/tests/System/Net/Http/HttpProtocolTests.cs(377,0): at System.Net.Http.Functional.Tests.HttpProtocolTests.<>c__DisplayClass19_0.<<GetAsync_ResponseHasNormalLineEndings_Success>b__0>d.MoveNext()
        --- End of stack trace from previous location ---
        /_/src/libraries/Common/tests/System/Net/Http/LoopbackServer.cs(101,0): at System.Net.Test.Common.LoopbackServer.CreateServerAsync(Func`2 funcAsync, Options options)
        /_/src/libraries/Common/tests/System/Net/Http/HttpProtocolTests.cs(369,0): at System.Net.Http.Functional.Tests.HttpProtocolTests.GetAsync_ResponseHasNormalLineEndings_Success(String lineEnding)
        --- End of stack trace from previous location ---
    System.Net.Http.Functional.Tests.SocketsHttpHandler_Http
  • Test: System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_Cookies_Http3_Mock.GetAsync_Redirect_CookiesArePreserved
    System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_Cookies_Http3_Mock.GetAsync_Redirect_CookiesArePreserved [FAIL]
      System.TimeoutException : The operation has timed out.
      Stack Trace:
        /_/src/libraries/Common/tests/System/Net/Http/HttpClientHandlerTest.Cookies.cs(479,0): at System.Net.Http.Functional.Tests.HttpClientHandlerTest_Cookies.GetAsync_Redirect_CookiesArePreserved()
        --- End of stack trace from previous location ---

@jkotas
Copy link
Member Author

jkotas commented Jun 26, 2021

Failed in #54774

Examples:

  • Test: System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_Cookies_Http3_Mock.GetAsyncWithRedirect_SetCookieContainer_CorrectCookiesSent
      System.TimeoutException : The operation has timed out.
      Stack Trace:
        /_/src/libraries/Common/tests/System/Net/Http/HttpClientHandlerTest.Cookies.cs(303,0): at System.Net.Http.Functional.Tests.HttpClientHandlerTest_Cookies.GetAsyncWithRedirect_SetCookieContainer_CorrectCookiesSent()
        --- End of stack trace from previous location ---
  • Test: System.Net.Http.Functional.Tests.SyncHttpHandlerTest_HttpClientHandlerTest_Headers.SendAsync_RequestWithSimpleHeader_ResponseReferencesUnmodifiedRequestHeaders
System.Net.Http.Functional.Tests.SyncHttpHandlerTest_HttpClientHandlerTest_Headers.SendAsync_RequestWithSimpleHeader_ResponseReferencesUnmodifiedRequestHeaders [FAIL]
      System.TimeoutException : The operation has timed out.
      Stack Trace:
        /_/src/libraries/System.Net.Http/tests/FunctionalTests/HttpClientHandlerTest.Headers.cs(30,0): at System.Net.Http.Functional.Tests.HttpClientHandlerTest_Headers.SendAsync_RequestWithSimpleHeader_ResponseReferencesUnmodifiedRequestHeaders()
        --- End of stack trace from previous location ---

@karelz
Copy link
Member

karelz commented Jun 28, 2021

Failures 4/28-6/27 (incl. PRs):

  • 6/8:
  • 6/18:
  • 6/23:
  • 6/24:
  • 6/25:
    • Http2_SmallConnectionTimeout_SubsequentRequestUsesDifferentConnection - 29 failures in PRs - all Linux
    • GetAsync_ResponseHasNormalLineEndings_Success - 15 failures in PRs - all Linux
    • SocketsHttpHandlerTest_Cookies_Http3_Mock.GetAsyncWithRedirect_SetCookieContainer_CorrectCookiesSent - 1 failure in PR HTTP3: Re-enable cookie and cancellation tests #54727 - Windows
    • SendAsync_RequestWithSimpleHeader_ResponseReferencesUnmodifiedRequestHeaders - 19 failures in PRs - all Linux
  • 6/26:
    • Http2_SmallConnectionTimeout_SubsequentRequestUsesDifferentConnection - 12 failures in PRs - all Linux
    • GetAsync_ResponseHasNormalLineEndings_Success - 4 failures in PRs - all Linux
    • SocketsHttpHandlerTest_Cookies_Http3_Mock.GetAsync_Redirect_CookiesArePreserved - 14 failures (8 in Official runs, 6 in PRs) - 2x Windows, 2x OSX, 10x Linux
    • SocketsHttpHandlerTest_Cookies_Http3_Mock.GetAsyncWithRedirect_SetCookieContainer_CorrectCookiesSent - 7 failures (2 in Official runs, 5 in PRs) - 2x Windows, 5x Linux
    • SendAsync_RequestWithSimpleHeader_ResponseReferencesUnmodifiedRequestHeaders - 8 failures in PRs - all Linux
  • 6/27:
    • Http2_SmallConnectionTimeout_SubsequentRequestUsesDifferentConnection - 4 failures in PRs - all Linux
    • GetAsync_ResponseHasNormalLineEndings_Success - 4 failures in PRs - all Linux
    • SocketsHttpHandlerTest_Cookies_Http3_Mock.GetAsync_Redirect_CookiesArePreserved - 5 failures on Official runs - 1 OSX, 4 Linux
    • SocketsHttpHandlerTest_Cookies_Http3_Mock.GetAsyncWithRedirect_SetCookieContainer_CorrectCookiesSent - 3 failures in PRs - 1x Windows, 2x Linux
    • SendAsync_RequestWithSimpleHeader_ResponseReferencesUnmodifiedRequestHeaders - 5 failures in PRs - all Linux
  • 6/28:
    • Http2_SmallConnectionTimeout_SubsequentRequestUsesDifferentConnection - 7 failures in PRs - all Linux
    • SocketsHttpHandlerTest_Cookies_Http3_Mock.GetAsync_Redirect_CookiesArePreserved - 2 failures (1 Official run, 1 PR) - all Linux
    • SocketsHttpHandlerTest_Cookies_Http3_Mock.GetAsyncWithRedirect_SetCookieContainer_CorrectCookiesSent - 2 failures (1 Official run, 1 PR) - all Linux
    • SendAsync_RequestWithSimpleHeader_ResponseReferencesUnmodifiedRequestHeaders - 3 failures in PRs - all Linux

@karelz
Copy link
Member

karelz commented Jun 28, 2021

Looks like a regression around 6/18-6/23 ... @dotnet/ncl any idea what might have caused the regression?

@karelz karelz added the test-run-core Test failures in .NET Core test runs label Jun 28, 2021
@karelz karelz added this to the 6.0.0 milestone Jun 28, 2021
@karelz
Copy link
Member

karelz commented Jun 28, 2021

@geoffkizer 2 of the tests are HTTP/3 Mock cookies tests -- is it perhaps caused by your PR #54727?

@geoffkizer
Copy link
Contributor

Yes, these tests were disabled until that PR.

Looks like these are still flaky, and apparently much flakier on Linux than Windows for whatever reason.

We should disable these again. I'll put up a PR.

@karelz
Copy link
Member

karelz commented Jun 28, 2021

Thanks @geoffkizer! We still have 3 tests not covered by your PR ... we need to figure out what to do about them and likely disable them as well.

@geoffkizer
Copy link
Contributor

I'm seeing a ton of TimeoutExceptions on my PR to disable these tests. For example: https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-54843-merge-5fea1e54014e4d049e/System.Net.Http.Functional.Tests/console.1c5cee98.log?sv=2019-07-07&se=2021-07-18T17%3A51%3A18Z&sr=c&sp=rl&sig=eMv7cbmp3wfyHjUEuXsbeRsXa%2FtVrWqCy%2FPhbk8pVPQ%3D

Not sure what is going on here, but it doesn't look isolated to any particular test(s).

@MihaZupan
Copy link
Member

MihaZupan commented Jun 29, 2021

Top 27 methods by number of failures caused by timeout are all happening on ubuntu.1604.amd64.open.rt.

QueueName MainFailures PrFailures AffectedBranches
ubuntu.1604.amd64.open.rt 36 2671 101
sles.15.amd64.open.rt 3 108 34
ubuntu.1804.amd64.open.rt 6 38 26
osx.1015.amd64.open 2 9 9
windows.10.amd64.serverrs5.open.rt 4 14 7
windows.10.amd64.server19h1.open.rt 2 7 6

@karelz
Copy link
Member

karelz commented Jun 30, 2021

Here's breakdown of main branch per date, demonstrating that something happened on 6/23:

Failures 3/12-6/29 (incl. PRs) - main branch:

Date Number of Timeout failures Details
6/19 2 (2x official run)
6/20 1 (1x official run)
6/21 1 (1x official run)
6/22 2 (2x official run)
6/23 43 (1x official run) PR #54437 - 29, PR #53851 - 7, PR #54618 - 4, PR #54610 - 1, PR #54053 - 1
6/24 81 (0x official run)
6/25 437 (0x official run)
6/26 224 (21x official run)
6/27 134 (8x official run)
6/28 694 (14x official run)
6/29 357 (8x official run) data for 10 hours of 6/29 only

Total 6/23-6/29: 1970 ... out of that 362 are Http3_Mock tests

Top hitter tests breakdown:

Test Count Class
(misc) - addressed in PR #54843 191 System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_Cookies_Http3_Mock
IncompleteResponseStream_ResponseDropped_CancelsRequestToServer 130 System.Net.Http.Functional.Tests.SocketsHttpHandler_HttpClientHandler_Finalization_Http11_Test / System.Net.Http.Functional.Tests.SocketsHttpHandler_HttpClientHandler_Finalization_Http2_Test
GetAsync_AddMultipleCookieHeaders_CookiesSent 130 System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_Cookies_Http2 / System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_Cookies
TestLoopbackAsync 125 System.Net.Http.Functional.Tests.SocksProxyTest_Http2 / System.Net.Http.Functional.Tests.SocksProxyTest_Http1_Async
Http2_SmallConnectionTimeout_SubsequentRequestUsesDifferentConnection 115 System.Net.Http.Functional.Tests.SocketsHttpHandler_HttpClientHandler_ConnectionPooling_Test
GetAsync_MissingExpires_ReturnNull 76 System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_HttpClientHandlerTest_Headers_Http11
GetAsync_SetCookieContainer_CookieSent 72 System.Net.Http.Functional.Tests.SyncHttpHandlerTest_Cookies
ConnectCallback_BindLocalAddress_Success 72 System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_ConnectCallback_Http2
SendAsync_RequestWithSimpleHeader_ResponseReferencesUnmodifiedRequestHeaders 72 System.Net.Http.Functional.Tests.SyncHttpHandlerTest_HttpClientHandlerTest_Headers
PlaintextStreamFilter_ExceptionDuringCallback_ThrowsHttpRequestExceptionWithInnerException 69 System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_PlaintextStreamFilter_Http11
PlaintextStreamFilter_SimpleDelegatingStream_Success 69 System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_PlaintextStreamFilter_Http2
PostAsync_CancelDuringRequestContentSend_TaskCanceledQuickly 67 System.Net.Http.Functional.Tests.SocketsHttpHandler_HttpClientHandler_Cancellation_Test_Http2
HttpClientHandler_MultipleAuthenticateHeaders_WithSameAuth_Succeeds 67 System.Net.Http.Functional.Tests.SocketsHttpHandler_HttpClientHandler_Authentication_Test
SetAfterUse_Throws 67 System.Net.Http.Functional.Tests.SocketsHttpHandler_HttpClientHandler_MaxResponseHeadersLength_Test
SendAsync_WithZeroLengthHeaderName_Throws 66 System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_HttpClientHandlerTest_Headers_Http2
PostAsync_ManyDifferentRequestHeaders_SentCorrectly 65 System.Net.Http.Functional.Tests.SyncHttpHandler_HttpClientHandlerTest
SendAsync_RequestHeaderInResponse_Success 64 System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_HttpClientHandlerTest_Headers_Http3_Mock
ExecutionContext_Suppressed_Success 61 System.Net.Http.Functional.Tests.SocketsHttpHandler_HttpClientHandler_Asynchrony_Test
SendAsync_MultipleExpected100Responses_ReceivesCorrectResponse 60 System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_HttpClientHandlerTest_Http2
SendRequest_UriPathHasReservedChars_ServerReceivedExpectedPath 59 System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_HttpClientHandlerTest_Http3_Mock
DisposeTargetStream_ThrowsObjectDisposedException 56 System.Net.Http.Functional.Tests.SocketsHttpHandler_PostScenarioTest
ReadAsStreamAsync_EmptyResponseBody_HandlerProducesWellBehavedResponseStream 54 System.Net.Http.Functional.Tests.SocketsHttpHandler_HttpClientHandlerTest + 6x *_Http3_Mock
HPack_HeaderEncoding 50 System.Net.Http.Functional.Tests.HPackTest
GetAsync_ResponseHasNormalLineEndings_Success 47 System.Net.Http.Functional.Tests.SyncHttpHandler_HttpProtocolTests_Dribble
GetAsync_CancelDuringResponseHeadersReceived_TaskCanceledQuickly 42 System.Net.Http.Functional.Tests.SocketsHttpHandler_HttpClientHandler_Cancellation_Test_Http3_Mock
ReadAsStreamAsync_EmptyResponseBody_HandlerProducesWellBehavedResponseStream 6 System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_HttpClientHandlerTest_Http3_Mock
Remaining 18 *

@geoffkizer
Copy link
Contributor

Some of these tests are pretty basic -- single request, no delays or timing issue, etc. Strange.

@karelz
Copy link
Member

karelz commented Jun 30, 2021

Yes, it almost feels like something changed in infra ...

@karelz
Copy link
Member

karelz commented Jun 30, 2021

@geoffkizer I updated the table -- there are 4 tests in *_Http3_Mock category. Could they have regressed due to your recent changes?

@MattGal
Copy link
Member

MattGal commented Jun 30, 2021

@karelz it's quite easy for me to re-send a job from > 4 days ago to the current machines and see if it still has the problem, even repeatedly if that's useful. Just pick a "blessed" one and I can send it around.

Some more thoughts:

  • Helix Machines didn't change on the 23rd, the last rollout was on the 24th, so if you're looking at this happening "around 6/18-6/23", the machines did not change.
  • The only linux things that changed in that time were RedHat 7 and SLES 12. Nothing else about, say, the ubuntu.1604.amd64.open.rt image changed in that time frame (image version, artifacts applied, etc).

@MihaZupan
Copy link
Member

The mass failures across all PRs started happening somewhere around 9pm on the 24th (+- a few h) - that is why I am suspicious of c88da29).

@MattGal Would you be able to run CI on the runtime at 1d84e01 (parent of the above commit)?

I've been running CI on a revert of the commit in #54939 and haven't hit a timeout failure yet.

@MattGal
Copy link
Member

MattGal commented Jun 30, 2021

@MattGal Would you be able to run CI on the runtime at 1d84e01 (parent of the above commit)?

Yes but I need some details about what you're interested in, please ping me on Teams?

@geoffkizer
Copy link
Contributor

there are 4 tests in *_Http3_Mock category. Could they have regressed due to your recent changes?

GetAsync_CancelDuringResponseHeadersReceived_TaskCanceledQuickly is a test I enabled for HTTP3 in my PR. so it's possible that this is a separate regression from whatever else is going on here. But it seems like we should figure out the general issue here first.

@MihaZupan
Copy link
Member

Looks like the failures stopped with #55006.

@karelz
Copy link
Member

karelz commented Jul 20, 2021

There are still some occurrences of test Http2_SmallConnectionTimeout_SubsequentRequestUsesDifferentConnection failures after 7/1 when the above was supposed to be addressed, though they seem to be on old PRs likely without the change:

Day Failures
7/2 1x PR #54884 - PR from 6/29
7/5 2x PR #55182 (testing PR for this issue)
7/6 3x PR #55182 (testing PR for this issue)
7/7 1x PR #54949 - PR from 6/30
7/8 4x PR #55292 (testing PR for this issue)
7/20 1x PR #53949 - old PR from 6/9
8/3 1x PR #46500 - old PR with last change on 6/29
8/14 1x PR #57421 - NEW PR from 8/15, looks like unrelated hiccup - see #57421 (comment)
  • Http2_SmallConnectionTimeout_SubsequentRequestUsesDifferentConnection
  • ExecutionContext_Suppressed_Success

@ghost ghost locked as resolved and limited conversation to collaborators Sep 15, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
area-System.Net.Http test-run-core Test failures in .NET Core test runs
Projects
None yet
Development

No branches or pull requests

5 participants