BackgroundService cancellation is logged as failure if host is still starting

Description

When a BackgroundService is cancelled while the host is still starting, the OperationCanceledException is logged as an error instead of being ignored. This is because the following code checks for "_stopCalled" which is not set in this case:

runtime/src/libraries/Microsoft.Extensions.Hosting/src/Internal/Host.cs

Line 193 in 8ccb71e

    
           if (_stopCalled && backgroundTask.IsCanceled && ex is OperationCanceledException)

We have seen this happen when an IIS recycle was triggered while the host is still starting. But it can also be reproduced in a console app, see reproduction steps.

Reproduction Steps

using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;

HostApplicationBuilder builder = Host.CreateApplicationBuilder();
builder.Services.AddHostedService<ABackgroundService>();
builder.Services.AddHostedService<ASlowStartService>();
var host = builder.Build();

var lifetime = host.Services.GetRequiredService<IHostApplicationLifetime>();
_ = host.StartAsync();
await Task.Delay(TimeSpan.FromSeconds(1));
lifetime.StopApplication();
await Task.Delay(TimeSpan.FromSeconds(1));
await host.WaitForShutdownAsync();

internal class ABackgroundService : BackgroundService
{
    protected override async Task ExecuteAsync(CancellationToken stoppingToken)
    {
        await Task.Delay(Timeout.Infinite, stoppingToken);
    }
}

internal class ASlowStartService : IHostedService
{
    public async Task StartAsync(CancellationToken cancellationToken)
    {
        await Task.Delay(TimeSpan.FromSeconds(10), CancellationToken.None);
    }

    public Task StopAsync(CancellationToken cancellationToken) => Task.CompletedTask;
}

Expected behavior

Exception is ignored.

Actual behavior

Exception is logged:

fail: Microsoft.Extensions.Hosting.Internal.Host[9]
      BackgroundService failed
      System.Threading.Tasks.TaskCanceledException: A task was canceled.
         at ABackgroundService.ExecuteAsync(CancellationToken stoppingToken)
         at Microsoft.Extensions.Hosting.Internal.Host.TryExecuteBackgroundServiceAsync(BackgroundService backgroundService)
crit: Microsoft.Extensions.Hosting.Internal.Host[10]
      The HostOptions.BackgroundServiceExceptionBehavior is configured to StopHost. A BackgroundService has thrown an unhandled exception, and the IHost instance is stopping. To avoid this behavior, configure this to Ignore; however the BackgroundService will not be restarted.
      System.Threading.Tasks.TaskCanceledException: A task was canceled.
         at ABackgroundService.ExecuteAsync(CancellationToken stoppingToken)
         at Microsoft.Extensions.Hosting.Internal.Host.TryExecuteBackgroundServiceAsync(BackgroundService backgroundService)

Regression?

No response

Known Workarounds

No response

Configuration

.NET 8.0.2
Windows x64

Other information

No response

@eerhardt

The code that contains the _stopcalled check to ignore the logging was done in https://github.com/dotnet/runtime/pull/57005/files. I assume _stopCalled is being checked is to differentiate between an error and a graceful shutdown through StopApplication(), so we would want to continue to support that differentiation. cc @eerhardt

Sample Xunit test that may help addressing:

        [Fact]
        public async Task StopApplicationOnServiceThatHasntFinishedStarting()
        {
            TestLoggerProvider logger = new TestLoggerProvider();
            HostApplicationBuilder builder = Host.CreateEmptyApplicationBuilder(settings: null);

            builder.Services.AddHostedService<ABackgroundService>();
            builder.Services.AddHostedService<ASlowStartService>();
            builder.Logging.AddProvider(logger);
            var host = builder.Build();

            var lifetime = host.Services.GetRequiredService<IHostApplicationLifetime>();
            _ = host.StartAsync();
            await Task.Delay(TimeSpan.FromSeconds(1));
            lifetime.StopApplication();
            await host.WaitForShutdownAsync();

            foreach (LogEvent logEvent in logger.GetEvents())
            {
                Assert.True(logEvent.LogLevel < LogLevel.Error);
                Assert.NotEqual("BackgroundServiceFaulted", logEvent.EventId.Name);
            }
        }

        internal class ABackgroundService : BackgroundService
        {
            protected override async Task ExecuteAsync(CancellationToken stoppingToken)
            {
                await Task.Delay(Timeout.Infinite, stoppingToken);
            }
        }

        internal class ASlowStartService : IHostedService
        {
            public async Task StartAsync(CancellationToken cancellationToken)
            {
                await Task.Delay(TimeSpan.FromSeconds(10), CancellationToken.None);
            }

            public Task StopAsync(CancellationToken cancellationToken) => Task.CompletedTask;
        }

I assume _stopCalled is being checked is to differentiate between an error and a graceful shutdown through StopApplication(), so we would want to continue to support that differentiation.

Correct. See #57005

Is this still up for grabs? If so, I'll attempt a fix.

Don't log error from background service if host is gracefully stopped…

Navigation Menu

Repository navigation

BackgroundService cancellation is logged as failure if host is still starting #98935

Description

Reproduction Steps

Expected behavior

Actual behavior

Regression?

Known Workarounds

Configuration

Other information

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

BackgroundService cancellation is logged as failure if host is still starting #98935

Description

Description

Reproduction Steps

Expected behavior

Actual behavior

Regression?

Known Workarounds

Configuration

Other information

Activity

steveharter commented on Mar 11, 2024

eerhardt commented on Mar 11, 2024

ProsserCJ commented on Mar 19, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions