dotnet / dotnet/aspnetcore

Unpredictable execution of "StopAsync"

Open
#22,831 12 comments 1 reaction 0 assignees View on GitHub
affected-very-few area-networking bug feature-iis investigate severity-nice-to-have
Dominant language
C#
Stars
38.4k
Forks
10.9k
Avg merge
2d 6h
Merged PRs (30d)
290

Description

Hello,
I'm trying to achieve something complex, which forced me to look under the hood, only to discover that things don't work as expected (or advertised).

My final aim is beyond the scope of this issue, but will describe it to give you some context. We have a two-clients app, which uses CSLA business objects. Old version is phasing out, based on Silverlight. Sometimes, we need to run procedures that can last long (minutes, even 30 or more). In the old version, we do this via `HostingEnvironment.QueueBackgroundWorkItem(cancellationToken => MethodThatCouldTakeLong(cancellationToken));`.
If cancellation is happening (IIS recycling the App Pool) this gives the method a chance to terminate gracefully in mid-flight, which is good!

The newer version of the App uses DotNet Core 2.1, MVC and an Angular client, in between, we use the same CSLA business object (we share the same code, with occasional changes when DotNet standard and Core differ, done via compiler directives). ``HostingEnvironment.QueueBackgroundWorkItem()` isn't available in DotNet Core, so I looked into `IHostedService` to achieve the same aim: let the long lasting method "learn" when the overall app is shutting down, so to cancel it gracefully (and hopefully, by using "compiler directives" as little as possible).

In order to succeed, I need two things:
[1] A system that allows me to run some code only when the app is trying to shut down (the StopAsync method).
[2] A system to "reach" the business object so that it "learns" that [1] happened.

The `IHostedService` feature promises to give me [1], but I can't make it work. I actually implemented [2] in many ways, only to eventually discover that it wasn't working because [1] wasn't happening.
Ignoring problem [2], here is what I see about [1], using a minimal implementation, based on the `TimedHostedService` example.

```
internal class TimedHostedService : IHostedService, IDisposable
{
private Timer _timer;
private int ID = new Random().Next();
public TimedHostedService(){ }
public Task StartAsync(CancellationToken cancellationToken)
{
Console.WriteLine("Timed Background Service is starting, with ID: " + ID );
_timer = new Timer(DoWork, null, TimeSpan.Zero,
TimeSpan.FromSeconds(5));
return Task.CompletedTask;
}
private void DoWork(object state)
{
Console.WriteLine("Timed Background Service is working, with ID: " + ID);
}
public Task StopAsync(CancellationToken cancellationToken)
{
Console.WriteLine("Timed Background Service is stopping, with ID: " + ID);
_timer?.Change(Timeout.Infinite, 0);
return Task.CompletedTask;
}
public void Dispose()
{
_timer?.Dispose();
}
}
```
This is marginally different from the example code: I initialise with an (int)ID, to follow the evolution of concurrent instances and I log to Console, so that I can see in realtime what happens via the Output window in VS ("ASP.NET Core Web Server" channel).
I register the TimedHostedService like this:
```
services.AddHostedService();
```
(Side note: it took me I don't know how long to make the compiler find the AddHostedService method, and I have no idea of how I've finally made it work.)
I have configured VS to start the app using my local IIS, and the relevant app pool to recycle every 7 requests, so that I can experiment with the TimedHostedService behaviour (by asking 7 times to login with the wrong password from the client, so by generating exactly 7 requests, whenever I want and only when I want).

What I would expect, from a standstill (my comment in square brackets):
```
MyApp> Timed Background Service is starting, with ID: 1316790599
MyApp> Timed Background Service is working, with ID: 1316790599
MyApp> Hosting environment: Development
MyApp> Content root path: [path]\MyApp
MyApp> Now listening on: http://localhost:13355
MyApp> Application started. Press Ctrl+C to shut down.
MyApp> Timed Background Service is working, with ID: 1316790599
MyApp> Timed Background Service is working, with ID: 1316790599
MyApp> Timed Background Service is working, with ID: 1316790599
[Recycle happens]
MyApp> Timed Background Service is starting, with ID: 1886756708
MyApp> Timed Background Service is working, with ID: 1886756708
MyApp> Hosting environment: Development
MyApp> Content root path: [path]\MyApp
MyApp> Now listening on: http://localhost:33020
MyApp> Application started. Press Ctrl+C to shut down.
MyApp> Timed Background Service is stopping, with ID: 1316790599
MyApp> Application is shutting down...
MyApp> Timed Background Service is working, with ID: 1886756708
MyApp> Timed Background Service is working, with ID: 1886756708
MyApp> Timed Background Service is working, with ID: 1886756708
```
What I get is **very different** and, if I read it correctly, it means that this system isn't working and I can't use it. Perhaps I'm doing something wrong, but I have no idea of where to start looking, as this implementation is the simplest I could find.

Actual output (in square brackets are my comments):
```
MyApp> Timed Background Service is working, with ID: 921976706
MyApp> Timed Background Service is working, with ID: 921976706
MyApp> Timed Background Service is working, with ID: 921976706
[Recycle 1 happens]
MyApp> Timed Background Service is starting, with ID: 1316790599
MyApp> Timed Background Service is working, with ID: 1316790599
MyApp> Hosting environment: Development
MyApp> Content root path: [path]\MyApp
MyApp> Now listening on: http://localhost:13355
MyApp> Application started. Press Ctrl+C to shut down.
MyApp> Timed Background Service is working, with ID: 921976706
MyApp> Timed Background Service is stopping, with ID: 1316790599
MyApp> Application is shutting down...
[Uh? Why is 1316790599 stopping? 921976706 should be the one]
MyApp> Timed Background Service is working, with ID: 921976706
MyApp> Timed Background Service is working, with ID: 921976706
MyApp> Timed Background Service is working, with ID: 921976706
[Recycle 2 happens]
MyApp> Timed Background Service is starting, with ID: 1886756708
MyApp> Timed Background Service is working, with ID: 1886756708
MyApp> Hosting environment: Development
MyApp> Content root path: [path]\MyApp
MyApp> Now listening on: http://localhost:33020
MyApp> Application started. Press Ctrl+C to shut down.
MyApp> Timed Background Service is stopping, with ID: 1886756708
[Whoops, it did it again (stopping the new instance)]
MyApp> Application is shutting down...
MyApp> Timed Background Service is working, with ID: 921976706
[Recycle 3 happens]
MyApp> Timed Background Service is starting, with ID: 1221835851
MyApp> Timed Background Service is working, with ID: 1221835851
MyApp> Hosting environment: Development
MyApp> Content root path: [path]\MyApp
MyApp> Now listening on: http://localhost:34109
MyApp> Application started. Press Ctrl+C to shut down.
MyApp> Timed Background Service is working, with ID: 1221835851
MyApp> Timed Background Service is working, with ID: 1221835851
MyApp> Timed Background Service is working, with ID: 1221835851
[Hang on, where did 921976706 go?]
[Was it killed without executing StopAsync?]
MyApp> Timed Background Service is working, with ID: 1221835851
MyApp> Timed Background Service is working, with ID: 1221835851
MyApp> Timed Background Service is working, with ID: 1221835851
[Recycle 4 happens]
MyApp> Timed Background Service is starting, with ID: 1930822523
MyApp> Timed Background Service is working, with ID: 1930822523
MyApp> Hosting environment: Development
MyApp> Content root path: [path]\MyApp
MyApp> Now listening on: http://localhost:37641
MyApp> Application started. Press Ctrl+C to shut down.
MyApp> Timed Background Service is working, with ID: 1221835851
MyApp> Timed Background Service is working, with ID: 1930822523
MyApp> Timed Background Service is working, with ID: 1221835851
MyApp> Timed Background Service is working, with ID: 1930822523
[Now we have both 122x and 193x happily co-existing]
[Repeat last 2 lines x15]
MyApp> Timed Background Service is working, with ID: 1930822523
MyApp> Timed Background Service is working, with ID: 1930822523
MyApp> Timed Background Service is working, with ID: 1930822523
MyApp> Timed Background Service is working, with ID: 1930822523
[So now 122x is dead, but never executed StopAsync]
```
What we're seeing here appears to show the following:
1st recycle - StopAsync is triggered for the wrong (newer) instance 1316790599, which stops gracefully, but should not have stopped. Instance 921976706 remains alive, but should have been stopped.
2nd recycle - 921976706 is still alive. 1886756708 starts, and then once gain StopAsync is triggered for the wrong (newer) instance 1886756708. Instance 921976706 remains unscathed.
3rd recycle - 1221835851 is born, 921976706 disappears without a sound.
4th recycle - having lost 921976706, only 1221835851 remains; 1930822523 enters the scene. For quite a while (17*5s) 1221835851 and 1930822523 coexist, until 1221835851 dies another sudden (ungraceful) death.

In my various attempts, I've seen the above patterns mix and match, with no logic I could find in their order (I'm pretty sure I did also see the right thing happening, but I'm not 100% sure).
What seems to be regular is that after recycle 4, the same pattern seem to stabilise (coexistence and sudden death of the older instance).

My (informed by ignorance) explanation: **this system isn't working and I can't use it for anything**.
Otherwise: do you have a possible explanation of what I'm doing wrong and/or how I could try to find out what's wrong?
Thanks!

---
#### Document Details

⚠ *Do not edit this section. It is required for docs.microsoft.com ➟ GitHub issue linking.*

* ID: c3460b0d-9c60-3a06-ac63-18cf990e53c3
* Version Independent ID: b2dece1f-15b8-03af-6d52-7cc070432b4b
* Content: [Background tasks with hosted services in ASP.NET Core](https://docs.microsoft.com/en-us/aspnet/core/fundamentals/host/hosted-services?view=aspnetcore-2.1&tabs=visual-studio)
* Content Source: [aspnetcore/fundamentals/host/hosted-services.md](https://github.com/dotnet/AspNetCore.Docs/blob/master/aspnetcore/fundamentals/host/hosted-services.md)
* Product: **aspnet-core**
* Technology: **aspnetcore-fundamentals**
* GitHub Login: @Rick-Anderson
* Microsoft Alias: **riande**

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.