Application Shutdown many times a day.

Hi,

I am facing issues with the application, it stops unexpectedly many times a day and I receive ASP.net error screen. I have checked the log and found the last entries like this:

-----------

info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 GET http://domain.com/fr/processeur-prix-tunisie  
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 0.0983ms 500 text/html; charset=utf-8
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 GET http://domain.com/fr/boitier-dalimentation-tunisie  
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 0.0983ms 500 text/html; charset=utf-8
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 POST http://127.0.0.1:28183/iisintegration  0
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 0.2318ms 500 text/html; charset=utf-8
Application is shutting down...-------------

------------

There are many other exceptions which are too much frequent. Here is the log:
----------

at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Diagnostics.StatusCodePagesMiddleware.<Invoke>d__3.MoveNext()
--- End of stack trace from previous location where exception was thrown ---

What can be the reason? Please help.

Thanks
Faheem

ASP.NET will shut down apps if they have not been accessed for some time (typically 20 minutes is the default).  There is a "Keep alive" scheduled task that you can enable to prevent that.

If you think your shutdowns are more random / cause by errors, ... Do you have access to the Server's Event Log to see more details?

[email protected] wrote:

I have had this exact issue for months as I've developed my staging site, and it's the last problem I need to address before moving to production.  Essentially the Schedule Tasks run correctly for several hours but then the app shuts down anyway at random times.

Seems closely related to:
https://github.com/dotnet/aspnetcore/issues/19509

and it's predecessor that has been opened/closed many times:
https://github.com/dotnet/aspnetcore/issues/3849

more:
https://github.com/dotnet/AspNetCore.Docs/issues/12232

More or less stating that Kestrel fails to restart after a recycle.  I have read every thread for "Schedule Tasks Not Working", however mine do work for a time and the issue feels like it should be an application pool / IIS configuration or setting that I'm missing.

I have App Pool Settings:
Start Mode: Always Running
Idle Timeout: 0
Regular Time Interval: 0

I have also tried :
serverAutoStart="true" on the site
preloadEnabled="true" on the application

Tail of the log below showing the app shutting down after Schedule Tasks run.  I believe the POST to localhost should be the IIS sentry for preload/warmup.  I have HTTPS enforced and have tried this URL Rewrite with no effect on startup:
https://docs.microsoft.com/en-ca/troubleshoot/aspnet/application-fail-ssl-web

info: System.Net.Http.HttpClient.default.LogicalHandler[100]
      Start processing HTTP request POST https://nopstaging.af1racing.com/scheduletask/runtask
info: System.Net.Http.HttpClient.default.ClientHandler[100]
      Sending HTTP request POST https://nopstaging.af1racing.com/scheduletask/runtask
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 POST http://nopstaging.af1racing.com/scheduletask/runtask application/x-www-form-urlencoded 69
info: Microsoft.EntityFrameworkCore.Infrastructure[10403]
      Entity Framework Core 2.2.4-servicing-10062 initialized 'NopObjectContext' using provider 'Microsoft.EntityFrameworkCore.SqlServer' with options: MaxPoolSize=128 using lazy-loading proxies 
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (0ms) [Parameters=[@__systemName_0='?' (Size = 400)], CommandType='Text', CommandTimeout='30']
      SELECT TOP(1) [c].[Id], [c].[Active], [c].[AdminComment], [c].[AffiliateId], [c].[BillingAddress_Id], [c].[CannotLoginUntilDateUtc], [c].[CreatedOnUtc], [c].[CustomerGuid], [c].[Deleted], [c].[Email], [c].[EmailToRevalidate], [c].[FailedLoginAttempts], [c].[HasShoppingCartItems], [c].[IsSystemAccount], [c].[IsTaxExempt], [c].[LastActivityDateUtc], [c].[LastIpAddress], [c].[LastLoginDateUtc], [c].[RegisteredInStoreId], [c].[RequireReLogin], [c].[ShippingAddress_Id], [c].[SystemName], [c].[Username], [c].[VendorId]
      FROM [Customer] AS [c]
      WHERE [c].[SystemName] = @__systemName_0
      ORDER BY [c].[Id]
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (0ms) [Parameters=[@__entityId_0='?' (DbType = Int32), @__keyGroup_1='?' (Size = 400)], CommandType='Text', CommandTimeout='30']
      SELECT [ga].[Id], [ga].[EntityId], [ga].[Key], [ga].[KeyGroup], [ga].[StoreId], [ga].[Value]
      FROM [GenericAttribute] AS [ga]
      WHERE ([ga].[EntityId] = @__entityId_0) AND ([ga].[KeyGroup] = @__keyGroup_1)
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[3]
      Route matched with {action = "RunTask", controller = "ScheduleTask", area = ""}. Executing controller action with signature Microsoft.AspNetCore.Mvc.IActionResult RunTask(System.String) on controller Nop.Web.Controllers.ScheduleTaskController (Nop.Web).
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Executing action method Nop.Web.Controllers.ScheduleTaskController.RunTask (Nop.Web) - Validation state: Valid
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (0ms) [Parameters=[@__type_0='?' (Size = 4000)], CommandType='Text', CommandTimeout='30']
      SELECT TOP(1) [st].[Id], [st].[Enabled], [st].[LastEndUtc], [st].[LastStartUtc], [st].[LastSuccessUtc], [st].[Name], [st].[Seconds], [st].[StopOnError], [st].[Type]
      FROM [ScheduleTask] AS [st]
      WHERE [st].[Type] = @__type_0
      ORDER BY [st].[Id] DESC
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (0ms) [Parameters=[@p8='?' (DbType = Int32), @p0='?' (DbType = Boolean), @p1='?' (DbType = DateTime2), @p2='?' (DbType = DateTime2), @p3='?' (DbType = DateTime2), @p4='?' (Size = 4000), @p5='?' (DbType = Int32), @p6='?' (DbType = Boolean), @p7='?' (Size = 4000)], CommandType='Text', CommandTimeout='30']
      SET NOCOUNT ON;
      UPDATE [ScheduleTask] SET [Enabled] = @p0, [LastEndUtc] = @p1, [LastStartUtc] = @p2, [LastSuccessUtc] = @p3, [Name] = @p4, [Seconds] = @p5, [StopOnError] = @p6, [Type] = @p7
      WHERE [Id] = @p8;
      SELECT @@ROWCOUNT;
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (0ms) [Parameters=[@__nowUtc_0='?' (DbType = DateTime2), @__maxSendTries_1='?' (DbType = Int32)], CommandType='Text', CommandTimeout='30']
      SELECT COUNT(*)
      FROM [QueuedEmail] AS [qe]
      WHERE ([qe].[SentOnUtc] IS NULL AND ([qe].[DontSendBeforeDateUtc] IS NULL OR ([qe].[DontSendBeforeDateUtc] <= @__nowUtc_0))) AND ([qe].[SentTries] < @__maxSendTries_1)
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (0ms) [Parameters=[@__nowUtc_0='?' (DbType = DateTime2), @__maxSendTries_1='?' (DbType = Int32), @__p_2='?' (DbType = Int32), @__p_3='?' (DbType = Int32)], CommandType='Text', CommandTimeout='30']
      SELECT [qe].[Id], [qe].[AttachedDownloadId], [qe].[AttachmentFileName], [qe].[AttachmentFilePath], [qe].[Bcc], [qe].[Body], [qe].[CC], [qe].[CreatedOnUtc], [qe].[DontSendBeforeDateUtc], [qe].[EmailAccountId], [qe].[From], [qe].[FromName], [qe].[PriorityId], [qe].[ReplyTo], [qe].[ReplyToName], [qe].[SentOnUtc], [qe].[SentTries], [qe].[Subject], [qe].[To], [qe].[ToName]
      FROM [QueuedEmail] AS [qe]
      WHERE ([qe].[SentOnUtc] IS NULL AND ([qe].[DontSendBeforeDateUtc] IS NULL OR ([qe].[DontSendBeforeDateUtc] <= @__nowUtc_0))) AND ([qe].[SentTries] < @__maxSendTries_1)
      ORDER BY [qe].[PriorityId] DESC, [qe].[CreatedOnUtc]
      OFFSET @__p_2 ROWS FETCH NEXT @__p_3 ROWS ONLY
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (0ms) [Parameters=[@p8='?' (DbType = Int32), @p0='?' (DbType = Boolean), @p1='?' (DbType = DateTime2), @p2='?' (DbType = DateTime2), @p3='?' (DbType = DateTime2), @p4='?' (Size = 4000), @p5='?' (DbType = Int32), @p6='?' (DbType = Boolean), @p7='?' (Size = 4000)], CommandType='Text', CommandTimeout='30']
      SET NOCOUNT ON;
      UPDATE [ScheduleTask] SET [Enabled] = @p0, [LastEndUtc] = @p1, [LastStartUtc] = @p2, [LastSuccessUtc] = @p3, [Name] = @p4, [Seconds] = @p5, [StopOnError] = @p6, [Type] = @p7
      WHERE [Id] = @p8;
      SELECT @@ROWCOUNT;
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Executed action method Nop.Web.Controllers.ScheduleTaskController.RunTask (Nop.Web), returned result Microsoft.AspNetCore.Mvc.NoContentResult in 3.343ms.
info: Microsoft.AspNetCore.Mvc.StatusCodeResult[1]
      Executing HttpStatusCodeResult, setting HTTP status code 204
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Executed action Nop.Web.Controllers.ScheduleTaskController.RunTask (Nop.Web) in 4.0942ms
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 7.4895ms 204 
info: System.Net.Http.HttpClient.default.ClientHandler[101]
      Received HTTP response after 11.9196ms - NoContent
info: System.Net.Http.HttpClient.default.LogicalHandler[101]
      End processing HTTP request after 11.9848ms - NoContent
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 POST http://127.0.0.1:39214/iisintegration  0
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 0.0519ms 202 
Application is shutting down...

the following hint that Nop 4.2 should be hosted In-Process:
https://stackoverflow.com/questions/57523899/keep-asp-net-core-app-running-all-the-time-in-iis
https://www.nopcommerce.com/en/boards/topic/82665/why-nopcommerce-430-moved-to-in-process-hosting-model-for-aspnetcorehostingmodel

However modifying .csproj and rebuilding had no effect upon app pool recycle:

<AspNetCoreHostingModel>InProcess</AspNetCoreHostingModel>

Thinking that the POST to http://127.0.0.1:39214/iisintegration was suspect since that is not a valid URL that would trigger Nop to compile, there should be a way to set that URL and I came across this:
https://stackoverflow.com/questions/35480661/iis-8-5-application-initialization-not-working

However, adding this to web DOT config still has no effect upon pool recycle:

<applicationInitialization doAppInitAfterRestart="true" skipManagedModules="false">
      <add initializationPage="/Home/Index" />
</applicationInitialization>

Reading the official docs:
https://docs.microsoft.com/en-us/iis/configuration/system.webServer/applicationInitialization/

I overlooked that you can set the hostname, and since I'm running on a subdomain there is a chance the POST is going to the top level domain (MS says the call is unlogged by windows.  Nop logged it last night, yet does not when I recycle the pool manually.  Guess I'll have to wait).  

However, after setting the hostname the app still refuses to restart upon app recycle:

<applicationInitialization doAppInitAfterRestart="true" skipManagedModules="false">
      <add initializationPage="/Home/Index" hostName="nopstaging.af1racing.com" />
</applicationInitialization>

I misunderstood http://127.0.0.1:39214/iisintegration and that is indeed IIS killing the app during a pool recycle:
https://stackoverflow.com/questions/49312291/iis-killing-aspnet-core-app

Thought I was onto something with this:
https://forums.iis.net/t/1235888.aspx?IIS8+Application+Initialization+not+working+after+first+init

it will initialize the application first time and will not re-initialize if I click the recycle when start mode is set to AlwaysRunning. However, if set the start mode to Ondemand, then application will be initialized everytime I click the recycle

However, no luck and the app still does not restart after a recycle.

af1racing wrote:

hey its stops automatically unexpectedly many times, got errors in log file

Possible success?  I uninstalled / reinstalled the Application Initialization Role last night before calling it a day and the app did not shut down last night.  First page load this morning was only a few seconds.