Copied to clipboard

Flag this post as spam?

This post will be reported to the moderators as potential spam to be looked at


  • Mike 13 posts 103 karma points
    14 days ago
    Mike
    0

    Random HTTP Error 500.37 on v10

    Umbraco version: 10.1.1 IIS 10

    I've recently been running a v10 upgraded site for a couple weeks. Over the weekend we had an outage: HTTP Error 500.37 - ASP.NET Core app failed to start within startup time limit.

    There really wasn't much in the Umbraco logs. Just a random stop notification, with nothing for hours before it.

    This issue was reconciled by rebooting the server.

    We only have 2 .net core apps running on this machine and there were no CPU/memory spikes at the time of the outage. Are there any other recommendations on how to diagnose the cause? Or should I look into increasing the ANCM startup time limit?

    {"@t":"2022-09-11T02:00:41.1491731Z","@mt":"Stopping ({SignalSource})","SignalSource":"environment","SourceContext":"Umbraco.Cms.Core.Runtime.MainDom","ProcessId":19816,"ProcessName":"w3wp","ThreadId":190,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO "}
    {"@t":"2022-09-11T02:00:41.1628988Z","@mt":"Released from MainDom","SourceContext":"Umbraco.Cms.Infrastructure.PublishedCache.PublishedSnapshotService","ProcessId":19816,"ProcessName":"w3wp","ThreadId":190,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO "}
    {"@t":"2022-09-11T02:00:41.1633185Z","@mt":"Released ({SignalSource})","SignalSource":"environment","SourceContext":"Umbraco.Cms.Core.Runtime.MainDom","ProcessId":19816,"ProcessName":"w3wp","ThreadId":190,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO "}
    {"@t":"2022-09-11T02:00:41.1640756Z","@mt":"Application is shutting down...","SourceContext":"Microsoft.Hosting.Lifetime","ProcessId":19816,"ProcessName":"w3wp","ThreadId":190,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO "}
    {"@t":"2022-09-11T02:00:41.1659641Z","@mt":"Queued Hosted Service is stopping.","SourceContext":"Umbraco.Cms.Infrastructure.HostedServices.QueuedHostedService","ProcessId":19816,"ProcessName":"w3wp","ThreadId":203,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO "}
    {"@t":"2022-09-11T02:41:15.4176264Z","@mt":"Acquiring MainDom.","SourceContext":"Umbraco.Cms.Core.Runtime.MainDom","ProcessId":5436,"ProcessName":"w3wp","ThreadId":1,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO "}
    {"@t":"2022-09-11T02:41:15.4831404Z","@mt":"Acquired MainDom.","SourceContext":"Umbraco.Cms.Core.Runtime.MainDom","ProcessId":5436,"ProcessName":"w3wp","ThreadId":1,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO "}
    {"@t":"2022-09-11T02:41:16.6951931Z","@mt":"Starting '{MigrationName}'...","MigrationName":"UrlTracker","SourceContext":"Umbraco.Cms.Infrastructure.Migrations.MigrationPlanExecutor","ProcessId":5436,"ProcessName":"w3wp","ThreadId":1,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO "}
    {"@t":"2022-09-11T02:41:16.6953293Z","@mt":"At {OrigState}","OrigState":"2.1","SourceContext":"Umbraco.Cms.Infrastructure.Migrations.MigrationPlanExecutor","ProcessId":5436,"ProcessName":"w3wp","ThreadId":1,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO "}
    {"@t":"2022-09-11T02:41:16.6967792Z","@mt":"Done (pending scope completion).","SourceContext":"Umbraco.Cms.Infrastructure.Migrations.MigrationPlanExecutor","ProcessId":5436,"ProcessName":"w3wp","ThreadId":1,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO "}
    {"@t":"2022-09-11T02:41:16.7084097Z","@mt":"Profiler is VoidProfiler, not profiling (must run debug mode to profile).","SourceContext":"Umbraco.Cms.Web.Common.Profiler.InitializeWebProfiling","ProcessId":5436,"ProcessName":"w3wp","ThreadId":1,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO "}
    {"@t":"2022-09-11T02:41:17.8645511Z","@mt":"Application started. Press Ctrl+C to shut down.","SourceContext":"Microsoft.Hosting.Lifetime","ProcessId":5436,"ProcessName":"w3wp","ThreadId":1,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO "}
    {"@t":"2022-09-11T02:41:17.8646355Z","@mt":"Hosting environment: {envName}","envName":"Production","SourceContext":"Microsoft.Hosting.Lifetime","ProcessId":5436,"ProcessName":"w3wp","ThreadId":1,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO "}
    {"@t":"2022-09-11T02:41:17.8646671Z","@mt":"Content root path: {contentRoot}","contentRoot":"C:\\inetpub\\thecurestartsnow.org_10","SourceContext":"Microsoft.Hosting.Lifetime","ProcessId":5436,"ProcessName":"w3wp","ThreadId":1,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO "}
    {"@t":"2022-09-11T02:41:18.4162501Z","@mt":"Registered with MainDom, localContentDbExists? {LocalContentDbExists}, localMediaDbExists? {LocalMediaDbExists}","LocalContentDbExists":true,"LocalMediaDbExists":true,"SourceContext":"Umbraco.Cms.Infrastructure.PublishedCache.PublishedSnapshotService","RequestId":"80000006-0000-e900-b63f-84710c7967bb","RequestPath":"/dipg-facts/what-is-dipg/","ProcessId":5436,"ProcessName":"w3wp","ThreadId":13,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO ","HttpRequestId":"7b4b698d-8f96-4ecf-8c57-3afe3ea5be3d","HttpRequestNumber":1,"HttpSessionId":"0"}
    {"@t":"2022-09-11T02:41:18.4210675Z","@mt":"Creating the content store, localContentDbExists? {LocalContentDbExists}","LocalContentDbExists":true,"SourceContext":"Umbraco.Cms.Infrastructure.PublishedCache.PublishedSnapshotService","RequestId":"80000006-0000-e900-b63f-84710c7967bb","RequestPath":"/dipg-facts/what-is-dipg/","ProcessId":5436,"ProcessName":"w3wp","ThreadId":13,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO ","HttpRequestId":"7b4b698d-8f96-4ecf-8c57-3afe3ea5be3d","HttpRequestNumber":1,"HttpSessionId":"0"}
    {"@t":"2022-09-11T02:41:18.4348747Z","@mt":"Creating the media store, localMediaDbExists? {LocalMediaDbExists}","LocalMediaDbExists":true,"SourceContext":"Umbraco.Cms.Infrastructure.PublishedCache.PublishedSnapshotService","RequestId":"80000006-0000-e900-b63f-84710c7967bb","RequestPath":"/dipg-facts/what-is-dipg/","ProcessId":5436,"ProcessName":"w3wp","ThreadId":13,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO ","HttpRequestId":"7b4b698d-8f96-4ecf-8c57-3afe3ea5be3d","HttpRequestNumber":1,"HttpSessionId":"0"}
    {"@t":"2022-09-11T02:41:19.4808586Z","@mt":"{StartMessage} [Timing {TimingId}]","StartMessage":"Loading content from local cache file","TimingId":"fd7f795","SourceContext":"Umbraco.Cms.Core.Logging.ProfilingLogger","RequestId":"80000006-0000-e900-b63f-84710c7967bb","RequestPath":"/dipg-facts/what-is-dipg/","ProcessId":5436,"ProcessName":"w3wp","ThreadId":13,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO ","HttpRequestId":"7b4b698d-8f96-4ecf-8c57-3afe3ea5be3d","HttpRequestNumber":1,"HttpSessionId":"0"}
    {"@t":"2022-09-11T02:41:20.0112126Z","@mt":"{EndMessage} ({Duration}ms) [Timing {TimingId}]","EndMessage":"Completed.","Duration":530,"TimingId":"fd7f795","SourceContext":"Umbraco.Cms.Core.Logging.ProfilingLogger","RequestId":"80000006-0000-e900-b63f-84710c7967bb","RequestPath":"/dipg-facts/what-is-dipg/","ProcessId":5436,"ProcessName":"w3wp","ThreadId":13,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO ","HttpRequestId":"7b4b698d-8f96-4ecf-8c57-3afe3ea5be3d","HttpRequestNumber":1,"HttpSessionId":"0"}
    {"@t":"2022-09-11T02:41:20.0289668Z","@mt":"{StartMessage} [Timing {TimingId}]","StartMessage":"Loading media from local cache file","TimingId":"8a7bf83","SourceContext":"Umbraco.Cms.Core.Logging.ProfilingLogger","RequestId":"80000006-0000-e900-b63f-84710c7967bb","RequestPath":"/dipg-facts/what-is-dipg/","ProcessId":5436,"ProcessName":"w3wp","ThreadId":13,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO ","HttpRequestId":"7b4b698d-8f96-4ecf-8c57-3afe3ea5be3d","HttpRequestNumber":1,"HttpSessionId":"0"}
    {"@t":"2022-09-11T02:41:20.4034002Z","@mt":"{EndMessage} ({Duration}ms) [Timing {TimingId}]","EndMessage":"Completed.","Duration":374,"TimingId":"8a7bf83","SourceContext":"Umbraco.Cms.Core.Logging.ProfilingLogger","RequestId":"80000006-0000-e900-b63f-84710c7967bb","RequestPath":"/dipg-facts/what-is-dipg/","ProcessId":5436,"ProcessName":"w3wp","ThreadId":13,"ApplicationId":"e9d8132d4c00605df5279d0626cc80ccc0f9f2cb","MachineName":"CSNWEB1","Log4NetLevel":"INFO ","HttpRequestId":"7b4b698d-8f96-4ecf-8c57-3afe3ea5be3d","HttpRequestNumber":1,"HttpSessionId":"0"}
    
  • Roy Berris 53 posts 411 karma points
    1 week ago
    Roy Berris
    0

    You should go to the advanced settings of your App pool and set the Idle Time-out (minutes) to 0. This will prevent IIS on shutting down the application when there is no trafic. This will prevent a random startup issue from happening.

    To try and fix the actual problem, I recommend searching for errors logs in the "Event Viewer".

    According to the MSDN for 500.37.

    This error can occur when starting a large number of apps on the same machine. Check for CPU/Memory usage spikes on the server during startup. You may need to stagger the startup process of multiple apps.

    Your server might simply be overloaded to handle the startup of the app at that time. With above settings it shouldn't shut down out of of itself.

  • Mike 13 posts 103 karma points
    1 week ago
    Mike
    0

    Thanks for your response Roy.

    The server was not under high load during this timeframe and this occurred during an app recycle, not a server startup.

    Pertinent event viewer logs are below:

    10:00:26 A worker process with process id of '19816' serving application pool 'X' has requested a recycle because the worker process reached its allowed processing time limit.
    10:03:46 An ISAPI reported an unhealthy condition to its worker process. Therefore, the worker process with process id of '11376' serving application pool 'X' has requested a recycle.
    10:06:57 An ISAPI reported an unhealthy condition to its worker process. Therefore, the worker process with process id of '21392' serving application pool 'X' has requested a recycle.
    10:09:54 An ISAPI reported an unhealthy condition to its worker process. Therefore, the worker process with process id of '15756' serving application pool 'X' has requested a recycle.
    10:12:56 An ISAPI reported an unhealthy condition to its worker process. Therefore, the worker process with process id of '15472' serving application pool 'X' has requested a recycle.
    10:15:58 An ISAPI reported an unhealthy condition to its worker process. Therefore, the worker process with process id of '19768' serving application pool 'X' has requested a recycle.
    

    The ISAPI error kept repeating until I manually rebooted the server.

    The app recycling obviously through it into a bad state, but I'd prefer not to turn off recycling entirely. I did a few searches online about how to diagnose the ISAPI errors, but there was nothing particularly helpful.

    Any other suggesions?

Please Sign in or register to post replies

Write your reply to:

Draft