Sometimes you find yourself investigating errors which are made more difficult to solve by the sheer weight of hits for a term out on the internet. Top of my list of things that are a pain to Google, is any sort of Stack Overflow exception. You can guess why, right? 😉 Having gone throught that pain recently, here’s some notes on an issue I helped my colleagues diagnose recently which fell straight into that trap…
What was the issue we saw?
A while after a deployment, testers reported that some content editing operations caused the server in question to hang. Trying to lock an item for edit, change its Presentation Details or do some other operations which modified the item seemed to cause the problem. It happened on some items, but not others. Testers would see error dialogs poping up in Content Editor after a wait:
The server logs included crashes on the authoring server at about the same time. To confuse matters, it was only repeatable on the QA and UAT servers – developers could not reproduce it on their dev boxes. So initially, this was a bit of a confusing problem for the developers involved.
Looking at the server event logs, these hangs eventually resolved into crashes caused running out of Stack space with a
InsufficientExecutionStackException. Which is sort of a Stack Overflow… When we managed to see the actuall IIS error, it looked like this:
The stack traces varied a bit depending on how the error was triggered, but they were all huge (unsurprisingly). One example, from changing presentation details looked like this:
[InsufficientExecutionStackException: Insufficient stack to continue executing the program safely. This can happen from having too many functions on the call stack or function on the stack using too much stack space.] System.Runtime.CompilerServices.RuntimeHelpers.EnsureSufficientExecutionStack() +0 System.Web.UI.Control.FindControl(String id, Int32 pathOffset) +24 Sitecore.Web.WebUtil.FindControl(Control parent, String name) +90 Sitecore.Web.UI.HtmlControls.TreePicker.GetDisplayValue() +133 Sitecore.Web.UI.HtmlControls.ComboboxBase.set_Value(String value) +157 Sitecore.Web.UI.HtmlControls.TreePicker.OnDataContextChanged(DataContext dataContext) +328 Sitecore.Web.UI.HtmlControls.Control.HandleMessage(Message message) +971 Sitecore.Shell.Framework.Commands.MessageCommand.DispatchMessage(Control control) +79 Sitecore.Shell.Framework.Commands.MessageCommand.DispatchMessage(Control control) +171 Sitecore.Shell.Framework.Commands.MessageCommand.DispatchMessage(Control control) +171 Sitecore.Shell.Framework.Commands.MessageCommand.DispatchMessage(Control control) +171 Sitecore.Shell.Framework.Commands.MessageCommand.DispatchMessage(Control control) +171 Sitecore.Shell.Framework.Commands.MessageCommand.DispatchMessage(Control control) +171 Sitecore.Shell.Framework.Commands.MessageCommand.DispatchMessage(Control control) +171 Sitecore.Shell.Framework.Commands.MessageCommand.DispatchMessage(Control control) +171 Sitecore.Shell.Framework.Commands.MessageCommand.DispatchMessage(Control control) +171 Sitecore.Shell.Framework.Commands.MessageCommand.DispatchMessage(Control control) +171 Sitecore.Shell.Framework.Commands.MessageCommand.Execute(CommandContext context) +181 Sitecore.Web.UI.Sheer.ClientPage.SendMessage(Message message) +102 Sitecore.Web.UI.HtmlControls.DataContext.OnChanged() +294 Sitecore.Web.UI.HtmlControls.DataContext.ItemSavedNotification(Object sender, ItemSavedEventArgs args) +280 Sitecore.Data.Events.ItemSavedDelegate.Invoke(Object sender, ItemSavedEventArgs args) +0 Sitecore.Events.Event.RaiseItemSaved(Object sender, ItemSavedEventArgs args) +226 System.EventHandler`1.Invoke(Object sender, TEventArgs e) +0 Sitecore.Data.Engines.EngineCommand`2.RaiseEvent(EventHandler`1 handlers, Func`2 argsCreator) +129 Sitecore.Data.Engines.EngineCommand`2.Execute() +263 Sitecore.Data.Engines.DataEngine.SaveItem(Item item) +280 Sitecore.Data.Managers.ItemProvider.SaveItem(Item item) +291 Sitecore.Data.Managers.PipelineBasedItemProvider.ExecuteAndReturnResult(String pipelineName, String pipelineDomain, Func`1 pipelineArgsCreator, Func`1 fallbackResult) +165 Sitecore.Data.Managers.PipelineBasedItemProvider.SaveItem(Item item) +230 Sitecore.Data.Items.ItemEditing.AcceptChanges(Boolean updateStatistics, Boolean silent) +229 Sitecore.Data.Items.ItemEditing.EndEdit(Boolean updateStatistics, Boolean silent) +16 Sitecore.Data.Managers.ItemProvider.UpdateRevisions(Item item, Boolean includeAllLanguages) +577 -- -- Previous seven lines repeated hundreds of times -- -- [TargetInvocationException: Exception has been thrown by the target of an invocation.] System.RuntimeMethodHandle.InvokeMethod(Object target, Object arguments, Signature sig, Boolean constructor) +0 System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object parameters, Object arguments) +76 System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object parameters, CultureInfo culture) +211 System.Reflection.MethodBase.Invoke(Object obj, Object parameters) +35 Sitecore.Nexus.Pipelines.NexusPipelineApi.Resume(PipelineArgs args, Pipeline pipeline) +398 Sitecore.Web.UI.Sheer.ClientPage.ResumePipeline() +285 Sitecore.Web.UI.Sheer.ClientPage.OnPreRender(EventArgs e) +547 Sitecore.Shell.Applications.ContentManager.ContentEditorPage.OnPreRender(EventArgs e) +25 System.Web.UI.Control.PreRenderRecursiveInternal() +113 System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint) +4297
What was the underlying issue?
The stack trace was interesting for two reasons:
- Firstly: It contained no references to any of the custom code deployed to this instance of Sitecore.
- Secondly: The bit that is repeated a lot is all to do with the process of saving an item.
That lead to us thinking about why the save operation might get into a loop.
The obvious answer here was custom event handlers. If an event was triggering after Sitecore saved an item, causing it to be saved again and if Sitecore was running custom code on a separate thread, that could cause this sort of issue. So we tried disabling all of the custom events wired up in patches to the default Sitecore config.
That didn’t work.
So then we looked down a rabbit hole relating to search. The project was using Coveo, with some customisations to ensure that if a Data Source item for a page got saved, the page itself was re-indexed. The re-index was triggered by changing the “last updated” time on the page item. So we tried disabling search.
That didn’t solve the problem either.
Finally, after a lot of hair-pulling, we noticed that a custom Rule had been configured inside the Sitecore UI that was running in the On-Saved event. This rule was related to some SEO requirements to ensure that page Name and Display Name fields used “correct” values. Looking at the rule, an issue popped out:
The last thing in the rule is a custom “save the changes” action, and the rule is running in the “Item Saved” event.
The “shooting yourself in the foot” alarm went off at this point – and removing the “save the changes” action caused the hang/crash issues to go away.
Fixing the issue
Having found the underlying problem, the fix was pretty simple. And it’s an important rule to remember:
Don’t write changes to an item in a rule running on the “Item Saved” event – because it can cause the event to run again, leading to a loop. (Yes, it is possible to write to an item without triggering events – but I’d argue it’s better to put your code into the correct event than to hack around this issue)
If you need to modify the state of an item when it is saved, use the “Item Saving” event instead. That allows you to change the state, but rely on Sitecore to do the save operation for you afterwards. And it won’t trigger any further events at that point.
Note that out of the box, there isn’t a Rules Engine event for “Item Saving”. But you can plumb one in yourself easily enough – Have a Google for blogs on the subject of triggering rules, or just point your favourite decompiler at Sitecore’s code for running “Item Saved” to see how.