Runtime: Test failure: Microsoft.Extensions.Hosting.Internal.HostTests.BackgroundServiceAsyncExceptionGetsLogged

Created on 14 Oct 2020 · 16Comments · Source: dotnet/runtime

failed in job: runtime-coreclr libraries-jitstress 20201013.1

net6.0-Linux-Release-x64-CoreCLR_checked-no_tiered_compilation-Ubuntu.1804.Amd64.Open

Error message
~~~
'BackgroundService failed' did not get logged
Expected: True
Actual: False

Stack trace
at Microsoft.Extensions.Hosting.Internal.HostTests.BackgroundServiceAsyncExceptionGetsLogged() in /_/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/Internal/HostTests.cs:line 1256
~~~

area-Extensions-Hosting test bug

Source

v-haren

Most helpful comment

Or is there a race condition between that exception getting thrown on a separate thread and completing the task, before the calling method returns?

Yes. The await Task.Yield() will force the containing async method to complete asynchronously, but callers checking that Task's IsCompleted (either explicitly or as part of awaiting it) may see it completed by the time they check, as (unless there's some ambient context to force serialization / synchronization) it'll complete concurrently on another thread pool thread and race with the calling thread. Simple example of that:
```C#
using System;
using System.Threading.Tasks;

int yes = 0, no = 0;
for (int i = 0; i < 1_000_000; i++)
{
Task t = YieldsAsync();
if (t.IsCompleted) yes++; else no++;
await t;
}
Console.WriteLine($"Yes: {yes:N0} No: {no:N0}");

static async Task YieldsAsync()
{
await Task.Yield();
}

This will obviously yield different results on every execution, but a typical example from my machine:

Yes: 36,196 No: 963,804
```

stephentoub on 19 Nov 2020

👍3

All 16 comments

@kunalspathak PTAL.

JulieLeeMSFT on 14 Oct 2020

Failed again in https://dev.azure.com/dnceng/public/_build/results?buildId=857798&view=ms.vss-test-web.build-test-results-tab&runId=27454930&resultId=102001&paneView=debug.

Configuration: net6.0-Linux-Debug-x64-CoreCLR_checked-Ubuntu.1804.Amd64.Open

Is this actually code gen related?

cc @maryamariyan @eerhardt

ViktorHofer on 19 Oct 2020

I’ll take a look. The timeout might need to be increased because checked builds run so much slower.

eerhardt on 19 Oct 2020

@JulieLeeMSFT @kunalspathak -

This looks really similar to https://github.com/dotnet/runtime/issues/43576. In both cases, the test is waiting for some asynchronous operation to occur for a set amount of time. In this test, it is 5 seconds. In #43576 it is 10 seconds.

Both cases are CoreCLR checked no tiered compilation. Did something recently slow down this configuration? Do we need to increase the timeouts for both?

eerhardt on 19 Oct 2020

@eerhardt - I didn't get chance to investigate. The earliest I will be able to take a look will be tomorrow.

kunalspathak on 20 Oct 2020

Alright, I did some investigation on this. The test failure doesn't fail in JitStress mode, but fails with just tiered compilation off. From the console logs.

+ export __TestEnv=/home/helixbot/work/C0490A08/p/SetStressModes_no_tiered_compilation.sh
+ cat /home/helixbot/work/C0490A08/p/SetStressModes_no_tiered_compilation.sh

In recent test run that happened on 10/20, the test passed. You can check the testresults.xml here for that run in which test passed:

<test name="Microsoft.Extensions.Hosting.Internal.HostTests.BackgroundServiceAsyncExceptionGetsLogged" type="Microsoft.Extensions.Hosting.Internal.HostTests" method="BackgroundServiceAsyncExceptionGetsLogged" time="0.4297531" result="Pass"/>

I also tried reproing it on my local machine with maxThreads=2 and the test passed. So most likely the test depends on the environment and looks flaky. It looks like the test was recently added in https://github.com/dotnet/runtime/pull/42981 , so we might have not got enough runs to conclude that the test is flaky.

So, it doesn't look like codegen issue. I am removing the labels from this issue.

kunalspathak on 21 Oct 2020

So it sounds like with checked, no tiered compilation the CLR is slow enough that the timeout in the test needs to be increased. Today we are waiting for 5 seconds, which isn't long enough in this "slow" mode.

eerhardt on 21 Oct 2020

So it sounds like with checked, no tiered compilation the CLR is slow enough

It appears that the slowness is only sometimes and not always, which basically means that the test is time sensitivity and might give different result depending on the environment.

kunalspathak on 21 Oct 2020

Tagging subscribers to this area: @eerhardt, @maryamariyan
See info in area-owners.md if you want to be subscribed.

msftbot[bot] on 21 Oct 2020

Seeing this again in: https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-heads-master-5b189d3203124e8a92/Microsoft.Extensions.Hosting.Unit.Tests/console.12434f67.log?sv=2019-07-07&se=2020-11-20T20%3A33%3A29Z&sr=c&sp=rl&sig=eO0uA9S8OKpYDqPO68mN5nDZ5R2A%2FXXt20Htf9QFMNY%3D

  Discovering: Microsoft.Extensions.Hosting.Unit.Tests (method display = ClassAndMethod, method display options = None)
  Discovered:  Microsoft.Extensions.Hosting.Unit.Tests (found 85 test cases)
  Starting:    Microsoft.Extensions.Hosting.Unit.Tests (parallel test collections = on, max threads = 2)
[40m[32minfo[39m[22m[49m: Microsoft.Extensions.Hosting.Tests.HostTests[0]
      Request starting
    Microsoft.Extensions.Hosting.Internal.HostTests.BackgroundServiceAsyncExceptionGetsLogged [FAIL]
      System.Exception : Background Exception
      Stack Trace:
        /_/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/Internal/HostTests.cs(1377,0): at Microsoft.Extensions.Hosting.Internal.HostTests.AsyncThrowingService.ExecuteAsync(CancellationToken stoppingToken)
        /_/src/libraries/Microsoft.Extensions.Hosting/src/Internal/Host.cs(54,0): at Microsoft.Extensions.Hosting.Internal.Host.StartAsync(CancellationToken cancellationToken)
        /_/src/libraries/Microsoft.Extensions.Hosting.Abstractions/src/HostingAbstractionsHostBuilderExtensions.cs(30,0): at Microsoft.Extensions.Hosting.HostingAbstractionsHostBuilderExtensions.StartAsync(IHostBuilder hostBuilder, CancellationToken cancellationToken)
        /_/src/libraries/Microsoft.Extensions.Hosting.Abstractions/src/HostingAbstractionsHostBuilderExtensions.cs(18,0): at Microsoft.Extensions.Hosting.HostingAbstractionsHostBuilderExtensions.Start(IHostBuilder hostBuilder)
        /_/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/Internal/HostTests.cs(1231,0): at Microsoft.Extensions.Hosting.Internal.HostTests.BackgroundServiceAsyncExceptionGetsLogged()
        --- End of stack trace from previous location ---
  Finished:    Microsoft.Extensions.Hosting.Unit.Tests
=== TEST EXECUTION SUMMARY ===
   Microsoft.Extensions.Hosting.Unit.Tests  Total: 85, Errors: 0, Failed: 1, Skipped: 0, Time: 5.418s

ViktorHofer on 5 Nov 2020

@ViktorHofer - that error trace is actually different than the original bug, but we can continue to use this issue to track the new problem.

What PR and leg was this run on?

It looks like the issue is that the "background" exception is not being thrown on the background - but instead synchronously.

https://github.com/dotnet/runtime/blob/8ed2e953f6b2142cbdef25c157c6425f508b373f/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/Internal/HostTests.cs#L1371-L1378

Since there is a Task.Delay(1) in there, the exception shouldn't be occurring inline - but according to the above stacktrace, it is occurring inline.

eerhardt on 5 Nov 2020

@eerhardt sorry took me a bit longer. Santi helped me to find the build id.

Here's the build: https://dnceng.visualstudio.com/public/_build/results?buildId=872294&view=ms.vss-test-web.build-test-results-tab.

Configuration: net6.0-Linux-Release-x64-CoreCLR_checked-(Alpine.312.Amd64.Open)[email protected]/dotnet-buildtools/prereqs:alpine-3.12-helix-20200602002622-e06dc59

ViktorHofer on 11 Nov 2020

Happened again in windows x86 Debug: helix logs (on top of 7 hours old master - 21f32f08097d15020298689b687ff0296b3f039e)

C:\h\w\B71509CA\w\AB5E0927\e>"C:\h\w\B71509CA\p\dotnet.exe" exec --runtimeconfig Microsoft.Extensions.Hosting.Unit.Tests.runtimeconfig.json --depsfile Microsoft.Extensions.Hosting.Unit.Tests.deps.json xunit.console.dll Microsoft.Extensions.Hosting.Unit.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing  
  Discovering: Microsoft.Extensions.Hosting.Unit.Tests (method display = ClassAndMethod, method display options = None)
  Discovered:  Microsoft.Extensions.Hosting.Unit.Tests (found 86 test cases)
  Starting:    Microsoft.Extensions.Hosting.Unit.Tests (parallel test collections = on, max threads = 2)
    Microsoft.Extensions.Hosting.Internal.HostTests.BackgroundServiceAsyncExceptionGetsLogged [FAIL]
      System.Exception : Background Exception
      Stack Trace:
        /_/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/Internal/HostTests.cs(1377,0): at Microsoft.Extensions.Hosting.Internal.HostTests.AsyncThrowingService.ExecuteAsync(CancellationToken stoppingToken)
        /_/src/libraries/Microsoft.Extensions.Hosting/src/Internal/Host.cs(54,0): at Microsoft.Extensions.Hosting.Internal.Host.StartAsync(CancellationToken cancellationToken)
        /_/src/libraries/Microsoft.Extensions.Hosting.Abstractions/src/HostingAbstractionsHostBuilderExtensions.cs(30,0): at Microsoft.Extensions.Hosting.HostingAbstractionsHostBuilderExtensions.StartAsync(IHostBuilder hostBuilder, CancellationToken cancellationToken)
        /_/src/libraries/Microsoft.Extensions.Hosting.Abstractions/src/HostingAbstractionsHostBuilderExtensions.cs(18,0): at Microsoft.Extensions.Hosting.HostingAbstractionsHostBuilderExtensions.Start(IHostBuilder hostBuilder)
        /_/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/Internal/HostTests.cs(1231,0): at Microsoft.Extensions.Hosting.Internal.HostTests.BackgroundServiceAsyncExceptionGetsLogged()
        --- End of stack trace from previous location ---
info: Microsoft.Extensions.Hosting.Tests.HostTests[0]

am11 on 19 Nov 2020

@stephentoub - do you have any idea how this exception could be thrown inline? We are awaiting Task.Yield:

https://github.com/dotnet/runtime/blob/cb8c8ec6435f3db3e982382ca2e82017271d0a0a/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/Internal/HostTests.cs#L1373-L1377

Or is there a race condition between that exception getting thrown on a separate thread and completing the task, before the calling method returns?

And then when the below code runs, the Task is already completed, so the exception just "looks" like it is being thrown inline (because that's how we are formatting exceptions from completed Tasks):

https://github.com/dotnet/runtime/blob/1821d9c14b970d58e0768256de138b6c0287e07d/src/libraries/Microsoft.Extensions.Hosting.Abstractions/src/BackgroundService.cs#L44-L50

eerhardt on 19 Nov 2020

Or is there a race condition between that exception getting thrown on a separate thread and completing the task, before the calling method returns?

int yes = 0, no = 0;
for (int i = 0; i < 1_000_000; i++)
{
Task t = YieldsAsync();
if (t.IsCompleted) yes++; else no++;
await t;
}
Console.WriteLine($"Yes: {yes:N0} No: {no:N0}");

static async Task YieldsAsync()
{
await Task.Yield();
}

This will obviously yield different results on every execution, but a typical example from my machine:

Yes: 36,196 No: 963,804
```

stephentoub on 19 Nov 2020

👍3

Thanks, this makes sense.

I'll switch this test code back to using Task.Delay and increase the delay time to 50ms, which should be long enough that the task shouldn't complete before the calling code can check it, but still short enough that the test runs quickly.

eerhardt on 19 Nov 2020

Was this page helpful?

0 / 5 - 0 ratings