Sign in Register
Copied to clipboard

Flag this post as spam?

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


  • Daniel Spanjaard 3 posts 73 karma points
    Nov 15, 2018 @ 13:22
    Daniel Spanjaard
    0

    Cluedo: Umbraco is restarting in the middle of the night. We have no clue!

    We notice that Umbraco is restarting in the middle of the night. After restarting we see unhandled IndexOutOfRangeException which originates from within UmbracoApplicationBase and MiniProfiler. We have no clue where this comes from.

    LOG:

    2018-11-15 03:32:13,426 [P4180/D101/T54] INFO  Umbraco.Core.MainDom - Stopping...
 2018-11-15 03:32:13,441 [P4180/D101/T54] INFO  Umbraco.Web.ExamineStartup - Examine shutting down
 2018-11-15 03:32:13,472 [P4180/D101/T54] INFO  Umbraco.Web.ExamineStartup - Complete (took 29ms)
 2018-11-15 03:32:13,472 [P4180/D101/T54] INFO  Umbraco.Core.MainDom - Released MainDom.
 2018-11-15 03:32:13,472 [P4180/D101/T54] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [Umbraco.Web.Scheduling.IBackgroundTask] Terminating
 2018-11-15 03:32:13,472 [P4180/D101/T54] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [Umbraco.Web.Scheduling.IBackgroundTask] Waiting for tasks to complete
 2018-11-15 03:32:13,472 [P4180/D101/T54] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [KeepAlive] Terminating
 2018-11-15 03:32:13,472 [P4180/D101/T54] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [KeepAlive] Waiting for tasks to complete
 2018-11-15 03:32:13,472 [P4180/D101/T64] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [Umbraco.Web.Scheduling.IBackgroundTask] Tasks completed, terminated
 2018-11-15 03:32:13,472 [P4180/D101/T20] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [KeepAlive] Tasks completed, terminated
 2018-11-15 03:32:13,488 [P4180/D101/T54] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [InstructionProcessing] Terminating
 2018-11-15 03:32:13,488 [P4180/D101/T54] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [InstructionProcessing] Waiting for tasks to complete
 2018-11-15 03:32:13,488 [P4180/D101/T54] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledTasks] Terminating
 2018-11-15 03:32:13,488 [P4180/D101/T54] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledTasks] Waiting for tasks to complete
 2018-11-15 03:32:13,488 [P4180/D101/T54] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [LogScrubber] Terminating
 2018-11-15 03:32:13,488 [P4180/D101/T54] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [LogScrubber] Waiting for tasks to complete
 2018-11-15 03:32:13,488 [P4180/D101/T54] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledPublishing] Terminating
 2018-11-15 03:32:13,488 [P4180/D101/T54] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledPublishing] Waiting for tasks to complete
 2018-11-15 03:32:13,488 [P4180/D101/T54] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [HealthCheckNotifier] Terminating
 2018-11-15 03:32:13,488 [P4180/D101/T54] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [HealthCheckNotifier] Waiting for tasks to complete
 2018-11-15 03:32:13,488 [P4180/D101/T54] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [HealthCheckNotifier] Tasks completed, terminated
 2018-11-15 03:32:13,488 [P4180/D101/T25] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledPublishing] Tasks completed, terminated
 2018-11-15 03:32:13,488 [P4180/D101/T7] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [InstructionProcessing] Tasks completed, terminated
 2018-11-15 03:32:13,488 [P4180/D101/T49] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledTasks] Tasks completed, terminated
 2018-11-15 03:32:13,488 [P4180/D101/T5] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [LogScrubber] Tasks completed, terminated
 2018-11-15 03:32:18,988 [P4180/D103/T16] INFO  Umbraco.Core.CoreBootManager - Umbraco 7.10.4 application starting on UMB-P-VS11334
 2018-11-15 03:32:19,019 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Determining hash of code files on disk
 2018-11-15 03:32:19,035 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Hash determined (took 13ms)
 2018-11-15 03:32:19,097 [P4180/D103/T16] INFO  Umbraco.Core.MainDom - Acquiring MainDom...
 2018-11-15 03:32:19,097 [P4180/D103/T16] INFO  Umbraco.Core.MainDom - Acquired MainDom.
 2018-11-15 03:32:19,097 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolving umbraco.interfaces.IDiscoverable
 2018-11-15 03:32:19,176 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolved umbraco.interfaces.IDiscoverable (took 71ms)
 2018-11-15 03:32:19,176 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolving umbraco.interfaces.IApplicationStartupHandler
 2018-11-15 03:32:19,176 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolved umbraco.interfaces.IApplicationStartupHandler (took 1ms)
 2018-11-15 03:32:19,222 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolving umbraco.interfaces.IDiscoverable
 2018-11-15 03:32:19,222 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolved umbraco.interfaces.IDiscoverable (took 0ms)
 2018-11-15 03:32:19,222 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolving Umbraco.Core.PropertyEditors.IPropertyEditorValueConverter
 2018-11-15 03:32:19,222 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolved Umbraco.Core.PropertyEditors.IPropertyEditorValueConverter (took 0ms)
 2018-11-15 03:32:19,222 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolving umbraco.interfaces.IDiscoverable
 2018-11-15 03:32:19,222 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolved umbraco.interfaces.IDiscoverable (took 0ms)
 2018-11-15 03:32:19,222 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolving Umbraco.Core.PropertyEditors.IPropertyValueConverter
 2018-11-15 03:32:19,222 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolved Umbraco.Core.PropertyEditors.IPropertyValueConverter (took 2ms)
 2018-11-15 03:32:19,238 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolving umbraco.interfaces.IDiscoverable
 2018-11-15 03:32:19,238 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolved umbraco.interfaces.IDiscoverable (took 0ms)
 2018-11-15 03:32:19,238 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolving Umbraco.Web.Mvc.SurfaceController
 2018-11-15 03:32:19,238 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolved Umbraco.Web.Mvc.SurfaceController (took 0ms)
 2018-11-15 03:32:19,238 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolving umbraco.interfaces.IDiscoverable
 2018-11-15 03:32:19,238 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolved umbraco.interfaces.IDiscoverable (took 0ms)
 2018-11-15 03:32:19,238 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolving Umbraco.Web.WebApi.UmbracoApiController
 2018-11-15 03:32:19,238 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolved Umbraco.Web.WebApi.UmbracoApiController (took 1ms)
 2018-11-15 03:32:21,082 [P4180/D103/T16] INFO  Umbraco.Core.DatabaseContext - CanConnect = True
 2018-11-15 03:32:21,254 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolving Umbraco.Core.Models.PublishedContent.PublishedContentModel
 2018-11-15 03:32:21,285 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolved Umbraco.Core.Models.PublishedContent.PublishedContentModel (took 18ms)
 2018-11-15 03:32:21,426 [P4180/D103/T16] INFO  Umbraco.Web.Cache.CacheRefresherEventHandler - Initializing Umbraco internal event handlers for cache refreshing
 2018-11-15 03:32:21,457 [P4180/D103/T16] INFO  Umbraco.Forms.Core.Cache.CacheEventHandler - Initializing Umbraco Forms Events to trigger Cache Refreshers
 2018-11-15 03:32:21,472 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolving umbraco.interfaces.IDiscoverable
 2018-11-15 03:32:21,488 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolved umbraco.interfaces.IDiscoverable (took 0ms)
 2018-11-15 03:32:21,488 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolving [Umbraco.Core.Persistence.Mappers.MapperForAttribute]Umbraco.Core.Persistence.Mappers.BaseMapper
 2018-11-15 03:32:21,488 [P4180/D103/T16] INFO  Umbraco.Core.PluginManager - Resolved [Umbraco.Core.Persistence.Mappers.MapperForAttribute]Umbraco.Core.Persistence.Mappers.BaseMapper (took 0ms)
 2018-11-15 03:32:21,801 [P4180/D103/T16] INFO  Umbraco.Web.Search.ExamineEvents - Initializing Examine and binding to business logic events
 2018-11-15 03:32:21,957 [P4180/D103/T16] INFO  Umbraco.Web.Search.ExamineEvents - Adding examine event handlers for index providers: 9
 2018-11-15 03:32:22,176 [P4180/D103/T16] INFO  Jumoo.uSync.BackOffice.uSyncApplicationEventHandler - Initializing uSync 73
 2018-11-15 03:32:22,191 [P4180/D103/T16] INFO  Jumoo.uSync.BackOffice.uSyncApplicationEventHandler - Firing up uSync
 2018-11-15 03:32:22,301 [P4180/D103/T16] INFO  Jumoo.uSync.Core.uSyncCoreContext - Loading Context (54ms)
 2018-11-15 03:32:22,347 [P4180/D103/T16] INFO  Jumoo.uSync.BackOffice.uSyncBackOfficeContext - Loading up Sync Handlers : 16
 2018-11-15 03:32:22,347 [P4180/D103/T16] INFO  Jumoo.uSync.BackOffice.uSyncApplicationEventHandler - Setting up Events default
 2018-11-15 03:32:22,363 [P4180/D103/T16] INFO  Jumoo.uSync.BackOffice.uSyncAction - ### uSync.BackOffice Processed 0 items with 0 changes ###
 2018-11-15 03:32:22,363 [P4180/D103/T16] INFO  Jumoo.uSync.BackOffice.uSyncApplicationEventHandler - uSync Complete (170ms)
 2018-11-15 03:32:22,394 [P4180/D103/T16] INFO  Umbraco.Core.CoreBootManager - Umbraco application startup complete (took 3532ms)
 2018-11-15 03:32:22,644 [P4180/D103/T62] INFO  Umbraco.Core.Sync.ApplicationUrlHelper - New ApplicationUrl detected: http://10.241.70.157:80/umbraco
 2018-11-15 03:32:22,644 [P4180/D103/T62] INFO  Umbraco.Core.Sync.ApplicationUrlHelper - ApplicationUrl: https://cms.landstedegroep.nl/umbraco (using web.routing/@umbracoApplicationUrl)
 2018-11-15 03:32:23,457 [P4180/D103/T20] INFO  umbraco.content - Load Xml from file...
 2018-11-15 03:32:23,629 [P4180/D103/T20] INFO  umbraco.content - Loaded Xml from file.
 2018-11-15 03:32:24,082 [P4180/D103/T20] ERROR Umbraco.Core.Persistence.UmbracoDatabase - Exception (cb52a403).
System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at StackExchange.Profiling.Timing.AddSqlTiming(SqlTiming sqlTiming) in c:\Code\github\SamSaffron\MiniProfiler\StackExchange.Profiling\Timing.cs:line 364
   at StackExchange.Profiling.MiniProfiler.AddSqlTiming(SqlTiming stats) in c:\Code\github\SamSaffron\MiniProfiler\StackExchange.Profiling\MiniProfiler.IDbProfiler.cs:line 92
   at StackExchange.Profiling.SqlTiming..ctor(IDbCommand command, ExecuteType type, MiniProfiler profiler) in c:\Code\github\SamSaffron\MiniProfiler\StackExchange.Profiling\SqlTiming.cs:line 72
   at StackExchange.Profiling.SqlProfiler.ExecuteStartImpl(IDbCommand command, ExecuteType type) in c:\Code\github\SamSaffron\MiniProfiler\StackExchange.Profiling\SqlProfiler.cs:line 53
   at StackExchange.Profiling.Data.ProfiledDbCommand.ExecuteDbDataReader(CommandBehavior behavior) in c:\Code\github\SamSaffron\MiniProfiler\StackExchange.Profiling\Data\ProfiledDbCommand.cs:line 238
   at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader()
   at Umbraco.Core.Persistence.PetaPocoCommandExtensions.<>c__DisplayClass5_0.<ExecuteReaderWithRetry>b__0()
   at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func`1 func)
   at Umbraco.Core.Persistence.Database.<Query>d__115`1.MoveNext()
 2018-11-15 03:32:24,082 [P4180/D103/T20] ERROR Umbraco.Core.UmbracoApplicationBase - An unhandled exception occurred
System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at Umbraco.Core.Cache.HttpRequestCacheProvider.GetCacheItem(String cacheKey, Func`1 getCacheItem)
   at Umbraco.Web.PublishedCache.XmlPublishedCache.XmlPublishedContent.Get(XmlNode node, Boolean isPreviewing)
   at Umbraco.Web.PublishedCache.XmlPublishedCache.PublishedContentCache.GetById(UmbracoContext umbracoContext, Boolean preview, Int32 nodeId)
   at Umbraco.Web.PublishedCache.XmlPublishedCache.PublishedContentCache.GetByRoute(UmbracoContext umbracoContext, Boolean preview, String route, Nullable`1 hideTopLevelNode)
   at Umbraco.Web.Routing.ContentFinderByNiceUrl.FindContent(PublishedContentRequest docreq, String route)
   at Umbraco.Web.Routing.ContentFinderByNiceUrl.TryFindContent(PublishedContentRequest docRequest)
   at System.Linq.Enumerable.Any[TSource](IEnumerable`1 source, Func`2 predicate)
   at Umbraco.Web.Routing.PublishedContentRequestEngine.FindPublishedContent()
   at Umbraco.Web.Routing.PublishedCon...
    Copy Link
  • Dan Diplo 1554 posts 6205 karma points MVP 6x c-trib
    Nov 15, 2018 @ 13:43
    Dan Diplo
    1

    Could it be in any way related to an application pool timeout? IIS can shut-down an app pool when it is had been idle for some time, and this can result in a restart generated by the next request:

    https://aspnetfaq.com/iis7-application-pool-idle-time-out-settings/

    Copy Link
  • Daniel Spanjaard 3 posts 73 karma points
    Nov 15, 2018 @ 16:07
    Daniel Spanjaard
    0

    Hi Dan,

    The restart is expected behavior, but does the error on UmbracoApplicationBase and MiniProfiler make any sense to you? See at the end of this LOG.

    We have a load balanced environment (1 CMS NODE and 2 PUB NODES).

    Copy Link
  • Bharani Dharan Jayasuri 12 posts 126 karma points c-trib
    Nov 15, 2018 @ 13:47
    Bharani Dharan Jayasuri
    1

    Hi Daniel,

    The AppPool process also recycles every 1740 minutes (29 hours) by default. Does the restart always happen around the same time in the night or is it staggered?

    Copy Link
  • Daniel Spanjaard 3 posts 73 karma points
    Nov 15, 2018 @ 15:08
    Daniel Spanjaard
    0

    Hi Bharani,

    Yes, the restart is every 29 hours. So it's not at the same time in the night or staggered.

    Does the error on UmbracoApplicationBase and MiniProfiler make any sense to you? See at the end of this LOG.

    We have a load balanced environment (1 CMS NODE and 2 PUB NODES).

    I hope some has a clue.

    Copy Link
  • Dan Diplo 1554 posts 6205 karma points MVP 6x c-trib
    Nov 15, 2018 @ 16:14
    Dan Diplo
    0

    Sorry, it's not an error I'm familiar with, though it could be a symptom of load balancing.

    Have you everything set up like the documentation recommends:

    https://our.umbraco.com/Documentation/Getting-Started/Setup/Server-Setup/Load-Balancing/flexible

    Also, I note you have uSync installed - could that have any affect? Are you able to disable it to see?

    Copy Link
  • Bharani Dharan Jayasuri 12 posts 126 karma points c-trib
    Nov 15, 2018 @ 19:48
    Bharani Dharan Jayasuri
    0

    Daniel,

    That is exactly the set up we have as well. One back office server and two frond ends load balanced. We also explicitly register the back office server as the master server on application start up so the scheduling server always remains the same.

    I am afraid I have not seen that exception before, if you are using flexible load balancing, perhaps, you could explicitly register one server as the master server and see if that fixes the issue.

    https://our.umbraco.com/Documentation/Getting-Started/Setup/Server-Setup/Load-Balancing/flexible-advanced#explicit-master-scheduling-server

    Copy Link
  • Pavel 11 posts 82 karma points
    Aug 26, 2019 @ 03:44
    Pavel
    0

    Hi, I'm having similar issue with 7.12 version where it sometimes throws the same error

    System.IndexOutOfRangeException: Index was outside the bounds of the array. at StackExchange.Profiling.Timing.AddSqlTiming(SqlTiming sqlTiming) in c:\Code\github\SamSaffron\MiniProfiler\StackExchange.Profiling\Timing.cs:line 364 at StackExchange.Profiling.MiniProfiler.AddSqlTiming(SqlTiming stats)

    in one particular case on Umbraco.TagQuery.GetAllContentTags

    Has there been any resolution on it? Thanks Pavel

    Copy Link
Please Sign in or register to post replies

Write your reply to:

Draft