Graceful shutdown for Azure web app

[clement911]

We have an azure web app running asp.net core 3.1, configured with azure auto scale.

Whenever the web app is stopped by the auto scaler, we see a whole bunch of errors in the log (in particular System.ObjectDisposedException: Cannot access a disposed object).

This pollutes our logs / alerts and we'd like to implement a graceful shutdown to stop logging errors that happens because of a shutdown.

Is IApplicationLifetime.ApplicationStopped the right hook? Does it fire on auto scale down? What if the app is manually stopped via the portal? Because of other reasons? Is it possible to get the reason why the shutdown was initiated?

[shirhatti]

azure web app running asp.net core 3.1

Windows/Linux?

we see a whole bunch of errors in the log

Could you share the logs or a minimal repro?

Is IApplicationLifetime.ApplicationStopped the right hook?

Yes

Does it fire on auto scale down? What if the app is manually stopped via the portal?

Yes on Windows. @anurse to answer what happens on Linux. I believe he was investigating something similar.

Because of other reasons?

Yes. You're moving to answer physical host on Antares. On free tiers, you may be shutdown due to inactivity/limits reached.

Is it possible to get the reason why the shutdown was initiated?

Not sure. @bradygaster do you know?

[shirhatti]

Is IApplicationLifetime.ApplicationStopped the right hook?

No. It's ApplicationStopping

[clement911]

Windows/Linux?

I'm 99% sure the app service runs on windows but I went to the azure portal to double check and I can't even find where to check the OS?

Could you share the logs or a minimal repro?

I could spend some time build a minimal repro but I don't see the point given I fully expect some errors since the process is shutting down. Here is a stack trace if that helps:

Exception: System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'LoggerFactory'.
   at Microsoft.Extensions.Logging.LoggerFactory.CreateLogger(String categoryName)
   at Microsoft.EntityFrameworkCore.Internal.ScopedLoggerFactory.CreateLogger(String categoryName)
   at Microsoft.EntityFrameworkCore.Internal.DiagnosticsLogger`1..ctor(ILoggerFactory loggerFactory, ILoggingOptions loggingOptions, DiagnosticSource diagnosticSource, LoggingDefinitions loggingDefinitions, IInterceptors interceptors)
   at ResolveService(ILEmitResolverBuilderRuntimeContext , ServiceProviderEngineScope )
   at ResolveService(ILEmitResolverBuilderRuntimeContext , ServiceProviderEngineScope )
   at ResolveService(ILEmitResolverBuilderRuntimeContext , ServiceProviderEngineScope )
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngine.GetService(Type serviceType, ServiceProviderEngineScope serviceProviderEngineScope)
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngineScope.GetService(Type serviceType)
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService(IServiceProvider provider, Type serviceType)
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService[T](IServiceProvider provider)
   at Microsoft.EntityFrameworkCore.DbContext.get_DbContextDependencies()
   at Microsoft.EntityFrameworkCore.DbContext.get_InternalServiceProvider()
   at Microsoft.EntityFrameworkCore.DbContext.Microsoft.EntityFrameworkCore.Infrastructure.IInfrastructure.get_Instance()
   at Microsoft.EntityFrameworkCore.Infrastructure.Internal.InfrastructureExtensions.GetService[TService](IInfrastructure`1 accessor)
   at Microsoft.EntityFrameworkCore.Infrastructure.AccessorExtensions.GetService[TService](IInfrastructure`1 accessor)
   at Microsoft.EntityFrameworkCore.Infrastructure.DatabaseFacade.get_Dependencies()
   at Microsoft.EntityFrameworkCore.Infrastructure.DatabaseFacade.Microsoft.EntityFrameworkCore.Internal.IDatabaseFacadeDependenciesAccessor.get_Dependencies()
   at Microsoft.EntityFrameworkCore.RelationalDatabaseFacadeExtensions.GetFacadeDependencies(DatabaseFacade databaseFacade)
   at Microsoft.EntityFrameworkCore.RelationalDatabaseFacadeExtensions.SetCommandTimeout(DatabaseFacade databaseFacade, TimeSpan timeout)

I should precise that we are running some background jobs in the asp.net core process, so even if all requests complete, our jobs will need to be killed and that's why we expect errors. The only sensible thing to do that I can think of is to detect when the ApplicationStopped is fired and stop the logging / alerting code to avoid raising unnecessary alerts.

So just to confirm, you're saying that ApplicationStopped will fire regardless of the reason (auto scale down, manual stop, other shutdowns by Azure, etc...)? That's good news, we will be trying it out.

It would be great if someone could confirm if it is possible to get the reason for the shutdown. That is one thing that we would like to log.

Also, the doc states:

ApplicationStopping: Triggered when the application host is performing a graceful shutdown. Requests may still be in flight. Shutdown will block until this event completes.

It says shutdown will block, but I'm assuming there is a timeout after which the process is killed anyway even if the event is not completed yet?

[analogrelay]

Here is a stack trace if that helps:

Are you doing anything off the default path for logging? The fact that the logger is being disposed to early often indicates you've set up some custom logging, or weird background service lifetimes, and the lifecycle isn't quite lining up.

It says shutdown will block, but I'm assuming there is a timeout after which the process is killed anyway even if the event is not completed yet?

Correct, 5 seconds is the default, though it is configurable.

[clement911]

Yes we do have a custom logger to log to our database. At the time I couldn't find much docs on how to do that. Here is the implementation of the ILoggerProvider.

public class NcLoggerProvider : ILoggerProvider, ISupportExternalScope
    {
        private readonly IServiceProvider _serviceProvider;
        private IExternalScopeProvider _scopeProvider;

        public NcLoggerProvider(IServiceProvider serviceProvider)
        {
            _serviceProvider = serviceProvider;
        }

        public ILogger CreateLogger(string categoryName)
        {
            var logger = _serviceProvider.GetRequiredService<NcLogger>();
            //transient logger allows each logger to have its own category
            logger.CategoryName = categoryName;
            logger.ScopeProvider = _scopeProvider;
            return logger;
        }

        public void Dispose()
        {
        }

        public void SetScopeProvider(IExternalScopeProvider scopeProvider)
        {
            _scopeProvider = scopeProvider;
        }
    }

public static ILoggerFactory AddNcLogger(this ILoggerFactory builder, IServiceProvider serviceProvider)
        {
            builder.AddProvider(new NcLoggerProvider(serviceProvider));
            return builder;
        }

NcLogger is registered with transient lifetime.

So just to confirm, you're saying that ApplicationStopped will fire regardless of the reason (auto scale down, manual stop, other shutdowns by Azure, etc...)? Is it not possible to get the reason?

[analogrelay]

So just to confirm, you're saying that ApplicationStopped will fire regardless of the reason (auto scale down, manual stop, other shutdowns by Azure, etc...)?

It should fire for any shutdown situation we can hook. If the process is killed by the OS ("End Task" in the Task Manager, for example), then there's no stopping it and we can't give you any warning. When IIS shuts down gracefully though (which is what Azure App Service does when "Stop" is used) it should signal this token.

Registering using ILoggerFactory isn't recommended anymore if you can avoid it, it's still there for legacy reasons, but in general we recommend using DI to handle your logger provider. Resolve any services you need from the container in the logger provider and just new-up a logger, passing in the services that way. Some psuedo-code:

    public class NcLoggerProvider : ILoggerProvider, ISupportExternalScope
    {
        private readonly IServiceA _serviceA;
        private readonly IServiceB _serviceB;
        private IExternalScopeProvider _scopeProvider;

        public NcLoggerProvider(IServiceA serviceA, IServiceB serviceB)
        {
            _serviceA = serviceA;
            _serviceB = serviceB;
        }

        public ILogger CreateLogger(string categoryName)
        {
            var logger = new NcLogger(serviceA, serviceB);
            //transient logger allows each logger to have its own category
            logger.CategoryName = categoryName;
            logger.ScopeProvider = _scopeProvider;
            return logger;
        }

        public void Dispose()
        {
        }

        public void SetScopeProvider(IExternalScopeProvider scopeProvider)
        {
            _scopeProvider = scopeProvider;
        }
    }

Then register it with ILoggingBuilder (which is just a wrapper around IServiceCollection designed for adding extension methods).

    public static ILoggerFactory AddNcLogger(this ILoggingBuilder builder)
    {
        builder.Services.AddSingleton<ILoggerProvider, NcLoggerProvider>();
        return builder;
    }

And use it in the .ConfigureLogging method in your host builder:

Host.CreateDefaultBuilder(args)
    .ConfigureLogging(logging => logging.AddNcLogger())
    // ... other configuration ...

That may actually be related to the source of your error. The logging factory you have isn't coming from DI, which means it may be living longer than the DI container and when you go to set up logging it throws the ObjectDisposedException.

In general, that exception is indicating something is living longer than the DI container, and that something is trying to access a DI service (and since the container has been disposed, it throws the exception).

[clement911]

Thanks, I made the change. Hopefully that will fix the issue.

Speaking of DI, I wonder if it could also be related to the following code that we use to get a transient instance of our DbContext.

public class NcDbContextFactory
    {
        private readonly IServiceScopeFactory _serviceScopeFactory;

        public NcDbContextFactory(IServiceScopeFactory serviceScopeFactory)
        {
            _serviceScopeFactory = serviceScopeFactory;
        }

        public NcDbContext CreateTransientContext()
        {
            return _serviceScopeFactory.CreateScope().ServiceProvider.GetRequiredService<NcDbContext>();
        }
    }

...

services.AddSingleton<NcDbContextFactory>()

We need to create db context instances on the fly in our methods, sometimes multiple at a time. But we resolve it with DI so that dependencies are injected. Is that a good way of doing it?

[analogrelay]

It depends if you are using that NcDbContextFactory after the DI container is disposed. If you are, then you’ll get an ODE (ObjectDisposedException). Are you capturing references to that type anywhere? Shoving them in static fields, etc.?

[clement911]

Yes we do use the NcDbContextFactory in background jobs that run forever. We figured it was ok since it is registered as a singleton. Should our background job also hook into IApplicationLifetime.ApplicationStopping

[bradygaster]

Yes. You're moving to answer physical host on Antares. On free tiers, you may be shutdown due to inactivity/limits reached.

Is it possible to get the reason why the shutdown was initiated?

Not sure. @bradygaster do you know?

Unless the reason for the shutdown appears in the logs I don't know for sure if there's another App Servcie-specific way of ascertaining why a site shut down. cc @btardif - could you let us know if there's a special App Service-specific shutdown interrogation ability?

[analogrelay]

Yes we do use the NcDbContextFactory in background jobs that run forever. We figured it was ok since it is registered as a singleton. Should our background job also hook into IApplicationLifetime.ApplicationStopping

It's OK to use singletons in background jobs, as long as either:

1. You stop the background job when IApplicationLifetime.ApplicationStopping is triggered. Or,
2. You're OK with the ODEs being thrown (you can catch them and shutdown the background job, for example; maybe also checking that IApplicationLifetime.ApplicationStopped is set to make sure you know why the ODE was thrown)

When the Host shuts down, the DI container is disposed and almost* every existing service is disposed (if it's IDisposable). So if you hold any references to DI services and try to access them after shutdown, that's what you'll get.

If you want a background job that shuts down when the app shuts down, check out IHostedService. You can implement that interface (or derive from the BackgroundService base class which does it for you and handles Start/Stop automatically via calling an ExecuteAsync method and using a CancellationToken to signal shutdown) and you'll be explicitly told when the app is shutting down:

public class MyBackgroundService: BackgroundService
{
    // This class is activated by DI, so you can have a constructor that takes in any DI services you need

    protected override async Task ExecuteAsync(CancellationToken stoppingToken)
    {
        while(!stoppingToken.IsCancellationRequested)
        {
            // Do stuff, and keep checking stoppingToken, and passing it in to async code to find out when the app is shutting down
        }
    }
}

// Then in ConfigureServices:

services.AddHostedService<MyBackgroundService>();

There are some docs here (they refer to the Worker Service template, but apply to Web apps just the same): https://docs.microsoft.com/en-us/aspnet/core/fundamentals/host/hosted-services?view=aspnetcore-3.1&tabs=visual-studio#ihostedservice-interface

[mars-boy]

Is there a way to graceful shutdown application thats using Background service hosted in IIS and Azure as I am using some logic for Stop and Start Service. Thanks

[mars-boy]

Hi @anurse I have implemented the same, working all fine in iis but issue is with Azure instance, I have written logs to checks whats going on, no unhandled exceptions it's getting stopped after a while. I have kept always on setting in azure still its the same. Please really appreciate ur response on this.

[analogrelay]

Hey @mars-boy , I'm actually no longer with the team. @shirhatti can probably help out, or ping someone who can.

[mars-boy]

Hey @anurse sure thanks

[mars-boy]

Hey @shirhatti any possible solution or workaround please.

[bradygaster]

I think this issue and #22272 have the same root cause or are essentially the same class of issue, so i'm linking these together here.

[ghost]

Thank you for contacting us. Due to a lack of activity on this discussion issue we're closing it in an effort to keep our backlog clean. If you believe there is a concern related to the ASP.NET Core framework, which hasn't been addressed yet, please file a new issue.

This issue will be locked after 30 more days of inactivity. If you still wish to discuss this subject after then, please create a new issue!