Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

On /bin change models fail to compile and end up in an unhandled exception/YSOD #127

Open
Shazwazza opened this issue Jan 3, 2017 · 9 comments
Open

On /bin change models fail to compile and end up in an unhandled exception/YSOD #127

Shazwazza opened this issue Jan 3, 2017 · 9 comments
Assignees
@zpqrtbnk
Labels
type/bug Bug

Comments

@Shazwazza
Copy link
Collaborator

Not sure how to replicate but seen it on my site a few times when deploying and something in the /bin changes.

Here's the log which shows the initial /bin change, then it will YSOD, i changed the web.config debug to 'true', then it got 'stuck' for about 5 mins, assuming it's waiting for MainDom, then eventually it boots.

2017-01-03 06:48:30,809 [P10888/D2/T52] INFO  Umbraco.Core.UmbracoApplicationBase - Application shutdown. Details: BinDirChangeOrDirectoryRename

_shutDownMessage=Change Notification for critical directories.
bin dir change or directory rename
HostingEnvironment initiated shutdown
Change Notification for critical directories.
bin dir change or directory rename
Change Notification for critical directories.
bin dir change or directory rename
Change Notification for critical directories.
bin dir change or directory rename
Change Notification for critical directories.
bin dir change or directory rename
Change Notification for critical directories.
bin dir change or directory rename
Change Notification for critical directories.
bin dir change or directory rename
CONFIG change
HostingEnvironment caused shutdown

_shutDownStack=   at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
   at System.Environment.get_StackTrace()
   at System.Web.Hosting.HostingEnvironment.InitiateShutdownInternal()
   at System.Web.Hosting.HostingEnvironment.InitiateShutdownWithoutDemand()
   at System.Web.HttpRuntime.ShutdownAppDomain(String stackTrace)
   at System.Web.HttpRuntime.OnCriticalDirectoryChange(Object sender, FileChangeEvent e)
   at System.Web.FileChangesMonitor.OnCriticaldirChange(Object sender, FileChangeEvent e)
   at System.Web.DirectoryMonitor.FireNotifications()
   at System.Web.Util.WorkItem.CallCallbackWithAssert(WorkItemCallback callback)
   at System.Web.Util.WorkItem.OnQueueUserWorkItemCompletion(Object state)
   at System.Threading.QueueUserWorkItemCallback.WaitCallback_Context(Object state)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback()
 2017-01-03 06:48:56,044 [P10888/D5/T1] INFO  Umbraco.Core.CoreBootManager - Umbraco 7.5.6 application starting on PRUMWEWORKER010
 2017-01-03 06:48:56,090 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Determining hash of code files on disk
 2017-01-03 06:48:56,122 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Hash determined (took 28ms)
 2017-01-03 06:48:56,185 [P10888/D5/T1] INFO  Umbraco.Core.MainDom - Acquiring MainDom...
 2017-01-03 06:48:56,185 [P10888/D5/T1] INFO  Umbraco.Core.MainDom - Acquired MainDom.
 2017-01-03 06:48:56,200 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Starting resolution types of umbraco.interfaces.IApplicationStartupHandler
 2017-01-03 06:48:56,747 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Completed resolution of types of umbraco.interfaces.IApplicationStartupHandler, found 0 (took 556ms)
 2017-01-03 06:48:56,778 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Starting resolution types of Umbraco.Core.PropertyEditors.IPropertyEditorValueConverter
 2017-01-03 06:48:56,794 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Completed resolution of types of Umbraco.Core.PropertyEditors.IPropertyEditorValueConverter, found 0 (took 15ms)
 2017-01-03 06:48:56,794 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Starting resolution types of Umbraco.Core.PropertyEditors.IPropertyValueConverter
 2017-01-03 06:48:56,809 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Completed resolution of types of Umbraco.Core.PropertyEditors.IPropertyValueConverter, found 0 (took 19ms)
 2017-01-03 06:48:56,825 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Starting resolution types of Umbraco.Web.Mvc.SurfaceController
 2017-01-03 06:48:56,840 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Completed resolution of types of Umbraco.Web.Mvc.SurfaceController, found 0 (took 16ms)
 2017-01-03 06:48:56,840 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Starting resolution types of Umbraco.Web.WebApi.UmbracoApiController
 2017-01-03 06:48:56,903 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Completed resolution of types of Umbraco.Web.WebApi.UmbracoApiController, found 0 (took 58ms)
 2017-01-03 06:48:56,934 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Starting resolution types of Umbraco.Core.Media.IThumbnailProvider
 2017-01-03 06:48:56,950 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Completed resolution of types of Umbraco.Core.Media.IThumbnailProvider, found 0 (took 19ms)
 2017-01-03 06:48:56,950 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Starting resolution types of Umbraco.Core.Media.IImageUrlProvider
 2017-01-03 06:48:56,965 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Completed resolution of types of Umbraco.Core.Media.IImageUrlProvider, found 0 (took 17ms)
 2017-01-03 06:48:58,153 [P10888/D5/T1] INFO  Umbraco.Core.DatabaseContext - CanConnect = True
 2017-01-03 06:48:58,434 [P10888/D5/T1] INFO  Umbraco.Core.DatabaseContext - CanConnect = True
 2017-01-03 06:48:58,450 [P10888/D5/T1] INFO  Umbraco.Web.Cache.CacheRefresherEventHandler - Initializing Umbraco internal event handlers for cache refreshing
 2017-01-03 06:48:58,465 [P10888/D5/T1] INFO  Umbraco.Forms.Core.Cache.CacheEventHandler - Initializing Umbraco Forms Events to trigger Cache Refreshers
 2017-01-03 06:49:00,137 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Starting resolution types of Umbraco.Core.Persistence.Mappers.BaseMapper
 2017-01-03 06:49:00,153 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Completed resolution of types of Umbraco.Core.Persistence.Mappers.BaseMapper, found 0 (took 20ms)
 2017-01-03 06:49:03,075 [P10888/D5/T1] INFO  Umbraco.Web.Search.ExamineEvents - Initializing Examine and binding to business logic events
 2017-01-03 06:49:03,231 [P10888/D5/T1] INFO  Umbraco.Web.Search.ExamineEvents - Adding examine event handlers for index providers: 3
 2017-01-03 06:49:03,340 [P10888/D5/T1] INFO  umbraco.content - Load Xml from file...
 2017-01-03 06:49:03,387 [P10888/D5/T1] INFO  umbraco.content - Loaded Xml from file.
 2017-01-03 06:49:04,044 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Starting resolution types of Umbraco.Core.PropertyEditors.IParameterEditor
 2017-01-03 06:49:04,278 [P10888/D5/T1] INFO  Umbraco.Core.PluginManager - Completed resolution of types of Umbraco.Core.PropertyEditors.IParameterEditor, found 0 (took 234ms)
 2017-01-03 06:49:07,466 [P10888/D5/T41] INFO  Umbraco.Core.PluginManager - Starting resolution types of umbraco.interfaces.ICacheRefresher
 2017-01-03 06:49:07,544 [P10888/D5/T41] INFO  Umbraco.Core.PluginManager - Completed resolution of types of umbraco.interfaces.ICacheRefresher, found 0 (took 71ms)
 2017-01-03 06:49:08,419 [P10888/D5/T1] INFO  Articulate.ArticulateRoutes - Mapping routes for 1 Articulate root nodes
 2017-01-03 06:49:08,466 [P10888/D5/T1] DEBUG Articulate.UmbracoVirtualNodeByIdRouteHandler - Hosts/IDs map for node 1066. Values:  = 1066, 
 2017-01-03 06:49:08,466 [P10888/D5/T1] DEBUG Articulate.UmbracoVirtualNodeByIdRouteHandler - Hosts/IDs map for node 1066. Values:  = 1066, 
 2017-01-03 06:49:08,466 [P10888/D5/T1] DEBUG Articulate.UmbracoVirtualNodeByIdRouteHandler - Hosts/IDs map for node 1066. Values:  = 1066, 
 2017-01-03 06:49:08,481 [P10888/D5/T1] DEBUG Articulate.UmbracoVirtualNodeByIdRouteHandler - Hosts/IDs map for node 1066. Values:  = 1066, 
 2017-01-03 06:49:08,481 [P10888/D5/T1] DEBUG Articulate.UmbracoVirtualNodeByIdRouteHandler - Hosts/IDs map for node 1066. Values:  = 1066, 
 2017-01-03 06:49:08,481 [P10888/D5/T1] DEBUG Articulate.UmbracoVirtualNodeByIdRouteHandler - Hosts/IDs map for node 1066. Values:  = 1066, 
 2017-01-03 06:49:08,481 [P10888/D5/T1] INFO  Umbraco.Core.DatabaseContext - CanConnect = True
 2017-01-03 06:49:08,528 [P10888/D5/T1] INFO  Umbraco.Core.CoreBootManager - Umbraco application startup complete (took 12502ms)
 2017-01-03 06:49:11,481 [P10888/D5/T58] INFO  Umbraco.Core.Sync.ApplicationUrlHelper - ApplicationUrl: http://shazwazza.com:80/umbraco (UmbracoModule request)
 2017-01-03 06:50:12,592 [P10888/D5/T19] INFO  umbraco.BusinessLogic.Log - Log scrubbed.  Removed all items older than 2017-01-02 06:50:12
 2017-01-03 06:51:13,687 [P10888/D5/T58] ERROR Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory - Failed to build models.
System.Threading.ThreadAbortException: Thread was being aborted.
   at System.Threading.Monitor.ReliableEnter(Object obj, Boolean& lockTaken)
   at System.Threading.Monitor.Enter(Object obj, Boolean& lockTaken)
   at System.Web.Compilation.BuildManager.GetBuildResultFromCacheInternal(String cacheKey, Boolean keyFromVPP, VirtualPath virtualPath, Int64 hashCode, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResultFromCacheInternal(VirtualPath virtualPath, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResultInternal(VirtualPath virtualPath, Boolean noBuild, Boolean allowCrossApp, Boolean allowBuildInPrecompile, Boolean throwIfNotFound, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResultWithNoAssert(HttpContext context, VirtualPath virtualPath, Boolean noBuild, Boolean allowCrossApp, Boolean allowBuildInPrecompile, Boolean throwIfNotFound, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResult(HttpContext context, VirtualPath virtualPath, Boolean noBuild, Boolean allowCrossApp, Boolean allowBuildInPrecompile, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetCompiledAssembly(String virtualPath)
   at Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory.GetModelsAssembly(Boolean forceRebuild)
   at Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory.EnsureModels()
 2017-01-03 06:51:14,937 [P10888/D5/T58] WARN  Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory - Running without models.
 2017-01-03 06:51:52,595 [P10888/D5/T89] ERROR Umbraco.Web.Scheduling.KeepAlive - Failed (at "http://shazwazza.com:80/umbraco").
System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Umbraco.Web.Scheduling.KeepAlive.<PerformRunAsync>d__4.MoveNext()
 2017-01-03 06:51:52,829 [P10888/D5/T94] INFO  Umbraco.Core.MainDom - Stopping...
 2017-01-03 06:51:52,876 [P10888/D5/T94] INFO  Umbraco.Core.MainDom - Released MainDom.
 2017-01-03 06:51:52,892 [P10888/D5/T94] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledPublishing] Terminating
 2017-01-03 06:51:52,892 [P10888/D5/T94] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledPublishing] Waiting for tasks to complete
 2017-01-03 06:51:52,892 [P10888/D5/T94] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [LogScrubber] Terminating
 2017-01-03 06:51:52,892 [P10888/D5/T94] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [LogScrubber] Waiting for tasks to complete
 2017-01-03 06:51:52,892 [P10888/D5/T50] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledPublishing] Tasks completed, terminated
 2017-01-03 06:51:52,892 [P10888/D5/T19] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [LogScrubber] Tasks completed, terminated
 2017-01-03 06:51:52,892 [P10888/D5/T94] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledTasks] Terminating
 2017-01-03 06:51:52,892 [P10888/D5/T94] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledTasks] Waiting for tasks to complete
 2017-01-03 06:51:52,892 [P10888/D5/T57] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledTasks] Tasks completed, terminated
 2017-01-03 06:51:52,908 [P10888/D5/T94] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [KeepAlive] Terminating
 2017-01-03 06:51:52,908 [P10888/D5/T94] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [KeepAlive] Waiting for tasks to complete
 2017-01-03 06:51:52,908 [P10888/D5/T89] INFO  Umbraco.Web.Scheduling.BackgroundTaskRunner - [KeepAlive] Tasks completed, terminated
 2017-01-03 06:51:58,689 [P10888/D5/T3] ERROR Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory - Failed to build models.
System.Threading.ThreadAbortException: Thread was being aborted.
   at System.Threading.Monitor.ReliableEnter(Object obj, Boolean& lockTaken)
   at System.Threading.Monitor.Enter(Object obj, Boolean& lockTaken)
   at System.Web.Compilation.BuildManager.GetBuildResultFromCacheInternal(String cacheKey, Boolean keyFromVPP, VirtualPath virtualPath, Int64 hashCode, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResultFromCacheInternal(VirtualPath virtualPath, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResultInternal(VirtualPath virtualPath, Boolean noBuild, Boolean allowCrossApp, Boolean allowBuildInPrecompile, Boolean throwIfNotFound, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResultWithNoAssert(HttpContext context, VirtualPath virtualPath, Boolean noBuild, Boolean allowCrossApp, Boolean allowBuildInPrecompile, Boolean throwIfNotFound, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResult(HttpContext context, VirtualPath virtualPath, Boolean noBuild, Boolean allowCrossApp, Boolean allowBuildInPrecompile, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetCompiledAssembly(String virtualPath)
   at Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory.GetModelsAssembly(Boolean forceRebuild)
   at Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory.EnsureModels()
 2017-01-03 06:51:58,970 [P10888/D5/T3] WARN  Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory - Running without models.
 2017-01-03 06:53:43,769 [P10888/D5/T88] ERROR Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory - Failed to build models.
System.Threading.ThreadAbortException: Thread was being aborted.
   at System.Threading.Monitor.ReliableEnter(Object obj, Boolean& lockTaken)
   at System.Threading.Monitor.Enter(Object obj, Boolean& lockTaken)
   at System.Web.Compilation.BuildManager.GetBuildResultFromCacheInternal(String cacheKey, Boolean keyFromVPP, VirtualPath virtualPath, Int64 hashCode, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResultFromCacheInternal(VirtualPath virtualPath, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResultInternal(VirtualPath virtualPath, Boolean noBuild, Boolean allowCrossApp, Boolean allowBuildInPrecompile, Boolean throwIfNotFound, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResultWithNoAssert(HttpContext context, VirtualPath virtualPath, Boolean noBuild, Boolean allowCrossApp, Boolean allowBuildInPrecompile, Boolean throwIfNotFound, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResult(HttpContext context, VirtualPath virtualPath, Boolean noBuild, Boolean allowCrossApp, Boolean allowBuildInPrecompile, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetCompiledAssembly(String virtualPath)
   at Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory.GetModelsAssembly(Boolean forceRebuild)
   at Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory.EnsureModels()
 2017-01-03 06:53:44,519 [P10888/D5/T88] WARN  Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory - Running without models.
 2017-01-03 06:53:45,769 [P10888/D5/T7] ERROR Umbraco.Core.UmbracoApplicationBase - An unhandled exception occurred
System.Web.HttpParseException (0x80004005): Key cannot be null.
Parameter name: key ---> System.ArgumentNullException: Key cannot be null.
Parameter name: key
   at System.Collections.Specialized.ListDictionary.set_Item(Object key, Object value)
   at System.Collections.Specialized.HybridDictionary.set_Item(Object key, Object value)
   at System.Web.Util.ObjectSet.Add(Object o)
   at System.Web.Compilation.AssemblyBuilder.AddAssemblyReference(Assembly a)
   at Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory.RazorBuildProvider_CodeGenerationStarted(Object sender, EventArgs e)
   at System.Web.WebPages.Razor.RazorBuildProvider.OnCodeGenerationStarted(IAssemblyBuilder assemblyBuilder)
   at System.Web.WebPages.Razor.RazorBuildProvider.GenerateCodeCore(IAssemblyBuilder assemblyBuilder)
   at System.Web.WebPages.Razor.RazorBuildProvider.GenerateCode(AssemblyBuilder assemblyBuilder)
   at System.Web.Compilation.AssemblyBuilder.AddBuildProvider(BuildProvider buildProvider)
   at System.Web.Compilation.AssemblyBuilder.AddBuildProvider(BuildProvider buildProvider)
   at System.Web.Compilation.BuildProvidersCompiler.ProcessBuildProviders()
   at System.Web.Compilation.BuildProvidersCompiler.PerformBuild()
   at System.Web.Compilation.BuildManager.CompileWebFile(VirtualPath virtualPath)
   at System.Web.Compilation.BuildManager.GetVPathBuildResultInternal(VirtualPath virtualPath, Boolean noBuild, Boolean allowCrossApp, Boolean allowBuildInPrecompile, Boolean throwIfNotFound, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResultWithNoAssert(HttpContext context, VirtualPath virtualPath, Boolean noBuild, Boolean allowCrossApp, Boolean allowBuildInPrecompile, Boolean throwIfNotFound, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVirtualPathObjectFactory(VirtualPath virtualPath, HttpContext context, Boolean allowCrossApp, Boolean throwIfNotFound)
   at System.Web.Compilation.BuildManager.GetCompiledType(VirtualPath virtualPath)
   at System.Web.Compilation.BuildManager.GetCompiledType(String virtualPath)
   at System.Web.Mvc.BuildManagerWrapper.System.Web.Mvc.IBuildManager.GetCompiledType(String virtualPath)
   at System.Web.Mvc.BuildManagerCompiledView.Render(ViewContext viewContext, TextWriter writer)
   at Umbraco.Core.Profiling.ProfilingView.Render(ViewContext viewContext, TextWriter writer)
   at System.Web.Mvc.ViewResultBase.ExecuteResult(ControllerContext context)
   at System.Web.Mvc.ControllerActionInvoker.InvokeActionResult(ControllerContext controllerContext, ActionResult actionResult)
   at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult)
   at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult)
   at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult)
   at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult)
   at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultWithFilters(ControllerContext controllerContext, IList`1 filters, ActionResult actionResult)
   at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass21.<>c__DisplayClass2b.<BeginInvokeAction>b__1c()
   at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass21.<BeginInvokeAction>b__1e(IAsyncResult asyncResult)
   at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResult`1.CallEndDelegate(IAsyncResult asyncResult)
   at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResultBase`1.End()
   at System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeAction(IAsyncResult asyncResult)
   at System.Web.Mvc.Controller.<BeginExecuteCore>b__1d(IAsyncResult asyncResult, ExecuteCoreState innerState)
   at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid`1.CallEndDelegate(IAsyncResult asyncResult)
   at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResultBase`1.End()
   at System.Web.Mvc.Controller.EndExecuteCore(IAsyncResult asyncResult)
   at System.Web.Mvc.Controller.<BeginExecute>b__15(IAsyncResult asyncResult, Controller controller)
   at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid`1.CallEndDelegate(IAsyncResult asyncResult)
   at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResultBase`1.End()
   at System.Web.Mvc.Controller.EndExecute(IAsyncResult asyncResult)
   at System.Web.Mvc.Controller.System.Web.Mvc.Async.IAsyncController.EndExecute(IAsyncResult asyncResult)
   at System.Web.Mvc.MvcHandler.<BeginProcessRequest>b__5(IAsyncResult asyncResult, ProcessRequestState innerState)
   at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid`1.CallEndDelegate(IAsyncResult asyncResult)
   at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResultBase`1.End()
   at System.Web.Mvc.MvcHandler.EndProcessRequest(IAsyncResult asyncResult)
   at System.Web.Mvc.MvcHandler.System.Web.IHttpAsyncHandler.EndProcessRequest(IAsyncResult result)
   at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
   at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)
 2017-01-03 06:53:50,425 [P10888/D5/T6] INFO  Umbraco.Core.UmbracoApplicationBase - Application shutdown. Details: ConfigurationChange

_shutDownMessage=CONFIG change
HostingEnvironment initiated shutdown
CONFIG change
CONFIG change
HostingEnvironment caused shutdown
Change in C:\inetpub\temp\DWASFiles\Sites\17282d4b-4f60-402b-b620-e6e77fc47da9\Temporary ASP.NET Files\root\25a035db\ba4126c9\hash\hash.web

_shutDownStack=   at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
   at System.Environment.get_StackTrace()
   at System.Web.Hosting.HostingEnvironment.InitiateShutdownInternal()
   at System.Web.Hosting.HostingEnvironment.InitiateShutdownWithoutDemand()
   at System.Web.HttpRuntime.ShutdownAppDomain(String stackTrace)
   at System.Web.Configuration.HttpConfigurationSystem.OnConfigurationChanged(Object sender, InternalConfigEventArgs e)
   at System.Configuration.Internal.InternalConfigRoot.OnConfigChanged(InternalConfigEventArgs e)
   at System.Configuration.BaseConfigurationRecord.OnStreamChanged(String streamname)
   at System.Web.Configuration.WebConfigurationHostFileChange.OnFileChanged(Object sender, FileChangeEvent e)
   at System.Web.DirectoryMonitor.FireNotifications()
   at System.Web.Util.WorkItem.CallCallbackWithAssert(WorkItemCallback callback)
   at System.Web.Util.WorkItem.OnQueueUserWorkItemCompletion(Object state)
   at System.Threading.QueueUserWorkItemCallback.WaitCallback_Context(Object state)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback()
 2017-01-03 06:53:56,175 [P10888/D6/T22] INFO  Umbraco.Core.CoreBootManager - Umbraco 7.5.6 application starting on PRUMWEWORKER010
 2017-01-03 06:53:56,191 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Determining hash of code files on disk
 2017-01-03 06:53:56,222 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Hash determined (took 25ms)
 2017-01-03 06:53:56,269 [P10888/D6/T22] INFO  Umbraco.Core.MainDom - Acquiring MainDom...
 2017-01-03 06:53:56,269 [P10888/D6/T22] INFO  Umbraco.Core.MainDom - Acquired MainDom.
 2017-01-03 06:53:56,284 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Starting resolution types of umbraco.interfaces.IApplicationStartupHandler
 2017-01-03 06:53:56,300 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Completed resolution of types of umbraco.interfaces.IApplicationStartupHandler, found 0 (took 17ms)
 2017-01-03 06:53:56,331 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Starting resolution types of Umbraco.Core.PropertyEditors.IPropertyEditorValueConverter
 2017-01-03 06:53:56,331 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Completed resolution of types of Umbraco.Core.PropertyEditors.IPropertyEditorValueConverter, found 0 (took 2ms)
 2017-01-03 06:53:56,331 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Starting resolution types of Umbraco.Core.PropertyEditors.IPropertyValueConverter
 2017-01-03 06:53:56,331 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Completed resolution of types of Umbraco.Core.PropertyEditors.IPropertyValueConverter, found 0 (took 3ms)
 2017-01-03 06:53:56,347 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Starting resolution types of Umbraco.Web.Mvc.SurfaceController
 2017-01-03 06:53:56,347 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Completed resolution of types of Umbraco.Web.Mvc.SurfaceController, found 0 (took 2ms)
 2017-01-03 06:53:56,347 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Starting resolution types of Umbraco.Web.WebApi.UmbracoApiController
 2017-01-03 06:53:56,363 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Completed resolution of types of Umbraco.Web.WebApi.UmbracoApiController, found 0 (took 10ms)
 2017-01-03 06:53:56,394 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Starting resolution types of Umbraco.Core.Media.IThumbnailProvider
 2017-01-03 06:53:56,410 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Completed resolution of types of Umbraco.Core.Media.IThumbnailProvider, found 0 (took 1ms)
 2017-01-03 06:53:56,410 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Starting resolution types of Umbraco.Core.Media.IImageUrlProvider
 2017-01-03 06:53:56,410 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Completed resolution of types of Umbraco.Core.Media.IImageUrlProvider, found 0 (took 1ms)
 2017-01-03 06:53:57,581 [P10888/D6/T22] INFO  Umbraco.Core.DatabaseContext - CanConnect = True
 2017-01-03 06:53:57,816 [P10888/D6/T22] INFO  Umbraco.Core.DatabaseContext - CanConnect = True
 2017-01-03 06:53:57,831 [P10888/D6/T22] INFO  Umbraco.Web.Cache.CacheRefresherEventHandler - Initializing Umbraco internal event handlers for cache refreshing
 2017-01-03 06:53:57,847 [P10888/D6/T22] INFO  Umbraco.Forms.Core.Cache.CacheEventHandler - Initializing Umbraco Forms Events to trigger Cache Refreshers
 2017-01-03 06:54:00,128 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Starting resolution types of Umbraco.Core.Persistence.Mappers.BaseMapper
 2017-01-03 06:54:00,144 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Completed resolution of types of Umbraco.Core.Persistence.Mappers.BaseMapper, found 0 (took 1ms)
 2017-01-03 06:54:00,472 [P10888/D6/T22] INFO  Umbraco.Web.Search.ExamineEvents - Initializing Examine and binding to business logic events
 2017-01-03 06:54:00,581 [P10888/D6/T22] INFO  Umbraco.Web.Search.ExamineEvents - Adding examine event handlers for index providers: 3
 2017-01-03 06:54:00,628 [P10888/D6/T22] INFO  umbraco.content - Load Xml from file...
 2017-01-03 06:54:00,660 [P10888/D6/T22] INFO  umbraco.content - Loaded Xml from file.
 2017-01-03 06:54:01,035 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Starting resolution types of Umbraco.Core.PropertyEditors.IParameterEditor
 2017-01-03 06:54:01,035 [P10888/D6/T22] INFO  Umbraco.Core.PluginManager - Completed resolution of types of Umbraco.Core.PropertyEditors.IParameterEditor, found 0 (took 2ms)
 2017-01-03 06:54:01,597 [P10888/D6/T22] INFO  Articulate.ArticulateRoutes - Mapping routes for 1 Articulate root nodes
 2017-01-03 06:54:01,644 [P10888/D6/T22] DEBUG Articulate.UmbracoVirtualNodeByIdRouteHandler - Hosts/IDs map for node 1066. Values:  = 1066, 
 2017-01-03 06:54:01,644 [P10888/D6/T22] DEBUG Articulate.UmbracoVirtualNodeByIdRouteHandler - Hosts/IDs map for node 1066. Values:  = 1066, 
 2017-01-03 06:54:01,644 [P10888/D6/T22] DEBUG Articulate.UmbracoVirtualNodeByIdRouteHandler - Hosts/IDs map for node 1066. Values:  = 1066, 
 2017-01-03 06:54:01,660 [P10888/D6/T22] DEBUG Articulate.UmbracoVirtualNodeByIdRouteHandler - Hosts/IDs map for node 1066. Values:  = 1066, 
 2017-01-03 06:54:01,660 [P10888/D6/T22] DEBUG Articulate.UmbracoVirtualNodeByIdRouteHandler - Hosts/IDs map for node 1066. Values:  = 1066, 
 2017-01-03 06:54:01,660 [P10888/D6/T22] DEBUG Articulate.UmbracoVirtualNodeByIdRouteHandler - Hosts/IDs map for node 1066. Values:  = 1066, 
 2017-01-03 06:54:01,660 [P10888/D6/T22] INFO  Umbraco.Core.DatabaseContext - CanConnect = True
 2017-01-03 06:54:01,706 [P10888/D6/T22] INFO  Umbraco.Core.CoreBootManager - Umbraco application startup complete (took 5555ms)
 2017-01-03 06:54:03,472 [P10888/D6/T103] INFO  Umbraco.Core.Sync.ApplicationUrlHelper - ApplicationUrl: http://shazwazza.com:80/umbraco (UmbracoModule request)
@zpqrtbnk zpqrtbnk self-assigned this Mar 7, 2017
@zpqrtbnk zpqrtbnk added the type/bug Bug label Mar 7, 2017
@zpqrtbnk
Copy link
Collaborator

zpqrtbnk commented Mar 7, 2017

No idea what causes it, but seeing it on other Cloud sites. Looking into it.

@zpqrtbnk
Copy link
Collaborator

zpqrtbnk commented Mar 7, 2017

Another log:

2017-03-07 08:03:50,783 [P23288/D10/T195] ERROR Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory - Failed to build models.
System.Threading.ThreadAbortException: Thread was being aborted.
   at System.Threading.Monitor.ReliableEnter(Object obj, Boolean& lockTaken)
   at System.Web.Compilation.BuildManager.GetBuildResultFromCacheInternal(String cacheKey, Boolean keyFromVPP, VirtualPath virtualPath, Int64 hashCode, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResultFromCacheInternal(VirtualPath virtualPath, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResultInternal(VirtualPath virtualPath, Boolean noBuild, Boolean allowCrossApp, Boolean allowBuildInPrecompile, Boolean throwIfNotFound, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResultWithNoAssert(HttpContext context, VirtualPath virtualPath, Boolean noBuild, Boolean allowCrossApp, Boolean allowBuildInPrecompile, Boolean throwIfNotFound, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResult(HttpContext context, VirtualPath virtualPath, Boolean noBuild, Boolean allowCrossApp, Boolean allowBuildInPrecompile, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetCompiledAssembly(String virtualPath)
   at Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory.GetModelsAssembly(Boolean forceRebuild)
   at Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory.EnsureModels()

Because the exception comes from BuildManager.GetCompiledAssembly it means that we already went through the csharp code generation and are now compiling the code, and for some reason BuildManager fails due to... timeout?

@zpqrtbnk
Copy link
Collaborator

zpqrtbnk commented Mar 7, 2017

Looking at BuildManager source code this happens when:

lock(this) {
   ...

So, locking the BuildManager instance.

@zpqrtbnk
Copy link
Collaborator

zpqrtbnk commented Mar 7, 2017

Readings:

These explain what happens when a thread aborts, but not why a thread would abort while trying to ReliableEnter a monitor, though. I don't think it's due to ReliableEnter though - it's probably waiting for the lock and is being aborted by something else (ASP.NET timeout?).

@zpqrtbnk
Copy link
Collaborator

zpqrtbnk commented Mar 7, 2017

Notes:

It could be that the thread is being aborted due to timeout, depending on the value of

<httpRuntime executionTimeout="????" />

in web.config. MSDN seems to imply that the default value is 110s but what's the value on Cloud?

@zpqrtbnk
Copy link
Collaborator

zpqrtbnk commented Mar 9, 2017

About the ThreadAbortException: pretty sure it's due to a timeout, see U4-9595 which should detect when it's a timeout and log a more explicit message (due in 7.5.12).

Now need to figure out why we end up in a timeout, especially here in BuildManager. Wondering if that might be linked to some deadlock in our code. Investigating (see U4-9606).

zpqrtbnk pushed a commit that referenced this issue Mar 13, 2017
Review logs in PureLiveModelFactory [#127]
5f49099
@zpqrtbnk
Copy link
Collaborator

See PR #136 which tries to refactor the locks in PureLiveModelFactory to reduce the possibility of deadlocks. But TBH I cannot figure out exactly what's causing the timeout, and it's super hard to troubleshoot without repro.

@tigreye007
Copy link

tigreye007 commented Mar 21, 2017 •
edited

@zpqrtbnk We are receiving this in Umbraco 7.5.4. We are not sure what triggers this, as no deployments or doc type updates are being made prior to these log entries, however we do have several scheduled tasks (content syncs) that are called frequently via custom surface controller URLs that could possibly be interfering somehow if they happen to run at the same time as the model builder? In our specific Azure web app environment, this (deadlock?) is actually causing the entire site (including the umbraco backend) to become unresponsive until we restart the site. Note that these messages occur every minute until the reset.

2017-03-21 12:24:25,918 [P6588/D6/T14] ERROR Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory - Failed to build models.
System.Threading.ThreadAbortException: Thread was being aborted.
   at System.Threading.Monitor.ReliableEnter(Object obj, Boolean& lockTaken)
   at System.Web.Compilation.BuildManager.GetBuildResultFromCacheInternal(String cacheKey, Boolean keyFromVPP, VirtualPath virtualPath, Int64 hashCode, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResultFromCacheInternal(VirtualPath virtualPath, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResultInternal(VirtualPath virtualPath, Boolean noBuild, Boolean allowCrossApp, Boolean allowBuildInPrecompile, Boolean throwIfNotFound, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResultWithNoAssert(HttpContext context, VirtualPath virtualPath, Boolean noBuild, Boolean allowCrossApp, Boolean allowBuildInPrecompile, Boolean throwIfNotFound, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetVPathBuildResult(HttpContext context, VirtualPath virtualPath, Boolean noBuild, Boolean allowCrossApp, Boolean allowBuildInPrecompile, Boolean ensureIsUpToDate)
   at System.Web.Compilation.BuildManager.GetCompiledAssembly(String virtualPath)
   at Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory.GetModelsAssembly(Boolean forceRebuild)
   at Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory.EnsureModels()
 2017-03-21 12:24:26,012 [P6588/D6/T14] WARN  Umbraco.ModelsBuilder.Umbraco.PureLiveModelFactory - Running without models.

zpqrtbnk pushed a commit that referenced this issue Mar 28, 2017
More locks cleanup [#127]
1194c6d
zpqrtbnk added a commit that referenced this issue Mar 28, 2017
@zpqrtbnk
Merge pull request #136 from zpqrtbnk/issue-127
8f5ba2b 
Review logs in PureLiveModelFactory [#127]
@zpqrtbnk
Copy link
Collaborator

I have merged the PR, which should be more robust WRT locks. Also, next version of Core (7.5.12) will ship with a feature that auto-creates a (limited) number of process minidumps on ThreadAbortException due to a timeout. The idea is to be able to analyse these minidumps and understand what is causing the deadlocks.

Minidumps should show in ~/App_Data/MiniDump.

I'm keeping this issue open.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@zpqrtbnk zpqrtbnk

Labels
type/bug Bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@tigreye007 @Shazwazza @zpqrtbnk