Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException is sometimes failing with Assert.InRange() Failure #44494

wfurt · 2020-11-10T21:53:41Z

This is fork of #40881 where new failure was originally reported. It failed again few times recently in CI.
For master, it was always on Windows7 queue but there are other failures in various PRs (and maybe same root cause)

   System.Net.Tests.HttpWebRequestTest_Async.Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException [FAIL]
      Assert.InRange() Failure
      Range:  (1 - 15000)
      Actual: 0
      Stack Trace:
        /_/src/libraries/System.Net.Requests/tests/HttpWebRequestTest.cs(525,0): at System.Net.Tests.HttpWebRequestTest.<>c.<Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException>b__38_0(LoopbackServer server, Uri url)
        /_/src/libraries/Common/tests/System/Net/Http/LoopbackServer.cs(78,0): at System.Net.Test.Common.LoopbackServer.<>c__DisplayClass12_0.<CreateServerAsync>b__0(LoopbackServer server)
        /_/src/libraries/Common/tests/System/Net/Http/LoopbackServer.cs(72,0): at System.Net.Test.Common.LoopbackServer.CreateServerAsync(Func`2 funcAsync, Options options)
        /_/src/libraries/System.Net.Requests/tests/HttpWebRequestTest.cs(516,0): at System.Net.Tests.HttpWebRequestTest.Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException()
        --- End of stack trace from previous location ---
  Finished:    System.Net.Requests.Tests
=== TEST EXECUTION SUMMARY ===
   System.Net.Requests.Tests  Total: 1107, Errors: 0, Failed: 1, Skipped: 6, Time: 7.189s

The text was updated successfully, but these errors were encountered:

ghost · 2020-11-10T21:53:43Z

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

Issue meta data

Issue content:

This is fork of #40881 where new failure was originally reported. It failed again few times recently in CI. For master, it was always on Windows7 queue but there are other failures in various PRs (and maybe same root cause)

   System.Net.Tests.HttpWebRequestTest_Async.Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException [FAIL]
      Assert.InRange() Failure
      Range:  (1 - 15000)
      Actual: 0
      Stack Trace:
        /_/src/libraries/System.Net.Requests/tests/HttpWebRequestTest.cs(525,0): at System.Net.Tests.HttpWebRequestTest.<>c.<Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException>b__38_0(LoopbackServer server, Uri url)
        /_/src/libraries/Common/tests/System/Net/Http/LoopbackServer.cs(78,0): at System.Net.Test.Common.LoopbackServer.<>c__DisplayClass12_0.<CreateServerAsync>b__0(LoopbackServer server)
        /_/src/libraries/Common/tests/System/Net/Http/LoopbackServer.cs(72,0): at System.Net.Test.Common.LoopbackServer.CreateServerAsync(Func`2 funcAsync, Options options)
        /_/src/libraries/System.Net.Requests/tests/HttpWebRequestTest.cs(516,0): at System.Net.Tests.HttpWebRequestTest.Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException()
        --- End of stack trace from previous location ---
  Finished:    System.Net.Requests.Tests
=== TEST EXECUTION SUMMARY ===
   System.Net.Requests.Tests  Total: 1107, Errors: 0, Failed: 1, Skipped: 6, Time: 7.189s

```</td>
  </tr>
  <tr>
    <td>Issue author:</td>
    <td>wfurt</td>
  </tr>
  <tr>
    <td>Assignees:</td>
    <td>-</td>
  </tr>
  <tr>
    <td>Milestone:</td>
    <td>-</td>
  </tr>
  </table>
  </details>

wfurt · 2020-11-12T06:32:33Z

This looks like product bug on Windows 7. (where I see all the recent InRange failures)

With the added instrumentation, failure for 8ffcd025-630c-4bef-93de-465a8e4b4921 looks like:

    System.Net.Tests.HttpWebRequestTest_Async.Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException [FAIL]
      Assert.InRange() Failure
      Range:  (1 - 15000)
      Actual: 0
      Stack Trace:
        /_/src/libraries/System.Net.Requests/tests/HttpWebRequestTest.cs(530,0): at System.Net.Tests.HttpWebRequestTest.<Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException>b__38_0(LoopbackServer server, Uri url)
        /_/src/libraries/Common/tests/System/Net/Http/LoopbackServer.cs(78,0): at System.Net.Test.Common.LoopbackServer.<>c__DisplayClass12_0.<CreateServerAsync>b__0(LoopbackServer server)
        /_/src/libraries/Common/tests/System/Net/Http/LoopbackServer.cs(72,0): at System.Net.Test.Common.LoopbackServer.CreateServerAsync(Func`2 funcAsync, Options options)
        /_/src/libraries/System.Net.Requests/tests/HttpWebRequestTest.cs(516,0): at System.Net.Tests.HttpWebRequestTest.Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException()
        --- End of stack trace from previous location ---
      Output:
        System.Net.WebException: The operation has timed out.
           at System.Net.HttpWebRequest.GetResponse() in /_/src/libraries/System.Net.Requests/src/System/Net/HttpWebRequest.cs:line 1025
           at System.Net.Tests.HttpWebRequestTest.<>c__DisplayClass38_0.<Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException>b__1() in /_/src/libraries/System.Net.Requests/tests/HttpWebRequestTest.cs:line 522
           at Xunit.Assert.RecordException(Func`1 testCode) in C:\Dev\xunit\xunit\src\xunit.assert\Asserts\Record.cs:line 58
  Finished:    System.Net.Requests.Tests
=== TEST EXECUTION SUMMARY ===
   System.Net.Requests.Tests  Total: 1107, Errors: 0, Failed: 1, Skipped: 6, Time: 9.545s

However, duration of the test was 0.0012442 e.g. ~ 1ms so we should not get timeout before 10ms. All the successful runs have time in 0.01 - 0.02s.

While looking for any hints of issues with Window7 timers, I did come across this documentation:

When you create a timer, you can specify an amount of time to wait before the first execution of the method (due time), and an amount of time to wait between subsequent executions (period). The Timer class has the same resolution as the system clock. This means that if the period is less than the resolution of the system clock, the TimerCallback delegate will execute at intervals defined by the resolution of the system clock, which is approximately 15 milliseconds on Windows 7 and Windows 8 systems.

That suggests that the time cannot be completely trusted on old Windows for short durations.
I'm wondering if the test should be simply excluded on Windows 7 as too brittle.
Alternatively, we can bump timeout up and move this to Outerloop.
From the description, it seems like Windows 8 should have same issue but I don't see any failures with the InRange assert.

let me know how you want to proceed @stephentoub and @geoffkizer

stephentoub · 2020-11-12T11:10:34Z

I did come across this documentation
That suggests that the time cannot be completely trusted on old Windows for short durations.

That's not just on older Windows. Anything that sleeps or is based on timers will by default end up rounding up to 10-15ms quantums. You can see that with a simple test.

using System;
using System.Diagnostics;
using System.Threading;
using System.Threading.Tasks;

var sw = new Stopwatch();
while (true)
{
    sw.Restart();
    Thread.Sleep(1);
    //await Task.Delay(1);
    Console.WriteLine(sw.Elapsed.TotalMilliseconds);
}

geoffkizer · 2020-11-12T16:34:51Z

Anything that sleeps or is based on timers will by default end up rounding up to 10-15ms

Yep. It's approx 1/60th of a second, or 16.667ms. Thus it has always been, and thus it will always be.

geoffkizer · 2020-11-12T16:35:53Z

I would suggest bumping the timeout up a bit, e.g. 20ms instead of 10ms; that's probably enough to fix this.

wfurt · 2020-11-12T16:37:49Z

ok, I'll give it try.

Anipik · 2020-12-12T01:30:44Z

Failed again here #45944
log https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-45944-merge-7d9e3f552df34fc184/System.Net.Requests.Tests/console.b32af7d0.log?sv=2019-07-07&se=2021-01-01T00%3A59%3A09Z&sr=c&sp=rl&sig=g4x3Zj6vXSMh2Pk2ScMLRNkGbZcCKOPYrDgmwNtwlSU%3D

danmoseley · 2020-12-12T01:37:56Z

@Anipik I usually paste in the console as it vanished after a while


System.Net.Tests.HttpWebRequestTest_Async.Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException [FAIL]
      Assert.InRange() Failure
      Range:  (1 - 15000)
      Actual: 0
      Stack Trace:
        /_/src/libraries/System.Net.Requests/tests/HttpWebRequestTest.cs(525,0): at System.Net.Tests.HttpWebRequestTest.<>c.<Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException>b__38_0(LoopbackServer server, Uri url)
        /_/src/libraries/Common/tests/System/Net/Http/LoopbackServer.cs(77,0): at System.Net.Test.Common.LoopbackServer.<>c__DisplayClass12_0.<CreateServerAsync>b__0(LoopbackServer server)
        /_/src/libraries/Common/tests/System/Net/Http/LoopbackServer.cs(71,0): at System.Net.Test.Common.LoopbackServer.CreateServerAsync(Func`2 funcAsync, Options options)
        /_/src/libraries/System.Net.Requests/tests/HttpWebRequestTest.cs(516,0): at System.Net.Tests.HttpWebRequestTest.Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException()
        --- End of stack trace from previous location ---

wfurt · 2020-12-12T04:42:33Z

It is interesting that this test no longe exist in master. Is your branch waaaaay behind @Anipik ??? (it was renamed to reflect new values)

Anipik · 2020-12-12T06:20:40Z

It’s the release/5.0 branch

karelz · 2020-12-17T16:55:24Z

Triage: If the failure rate in 5.0 is significant, we can backport it. Not worth tracking one off release/5.0 test failures.

wfurt added area-System.Net.Http test-run-core Test failures in .NET Core test runs labels Nov 10, 2020

wfurt mentioned this issue Nov 11, 2020

log exception if Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException test fails #44509

Merged

maryamariyan added the untriaged New issue has not been triaged by the area owner label Nov 11, 2020

wfurt mentioned this issue Nov 12, 2020

increase timeout on WebRequest timeout test #44612

Merged

stephentoub closed this as completed in #44612 Nov 13, 2020

GrabYourPitchforks mentioned this issue Nov 25, 2020

[release/5.0] Skip some PKCS9 tests on NetFx #45213

Merged

Anipik reopened this Dec 12, 2020

karelz closed this as completed Dec 17, 2020

karelz added this to the 6.0.0 milestone Dec 17, 2020

ghost locked as resolved and limited conversation to collaborators Jan 16, 2021

karelz removed the untriaged New issue has not been triaged by the area owner label Oct 20, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException is sometimes failing with Assert.InRange() Failure #44494

Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException is sometimes failing with Assert.InRange() Failure #44494

wfurt commented Nov 10, 2020

ghost commented Nov 10, 2020

wfurt commented Nov 12, 2020

stephentoub commented Nov 12, 2020 •

edited

Loading

geoffkizer commented Nov 12, 2020

geoffkizer commented Nov 12, 2020

wfurt commented Nov 12, 2020

Anipik commented Dec 12, 2020

danmoseley commented Dec 12, 2020

wfurt commented Dec 12, 2020

Anipik commented Dec 12, 2020

karelz commented Dec 17, 2020

Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException is sometimes failing with Assert.InRange() Failure #44494

Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException is sometimes failing with Assert.InRange() Failure #44494

Comments

wfurt commented Nov 10, 2020

ghost commented Nov 10, 2020

wfurt commented Nov 12, 2020

stephentoub commented Nov 12, 2020 • edited Loading

geoffkizer commented Nov 12, 2020

geoffkizer commented Nov 12, 2020

wfurt commented Nov 12, 2020

Anipik commented Dec 12, 2020

danmoseley commented Dec 12, 2020

wfurt commented Dec 12, 2020

Anipik commented Dec 12, 2020

karelz commented Dec 17, 2020

stephentoub commented Nov 12, 2020 •

edited

Loading