Timeout_SetTenMillisecondsOnLoopback_ThrowsWebException is sometimes failing with Assert.InRange() Failure

[wfurt]

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

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

Details

---

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]

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]

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]

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]

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

[wfurt]

ok, I'll give it try.

[Anipik]

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