Concurrency Issue with JsonSerializerSettings Cache

[billdeitrick]

Description

Filed on behalf of The Austin Stone Community Church in Austin, TX.

We've been seeing an issue where, following the nightly scheduled Application Pool restart, Rock will enter a state where certain functionality relying on Json object serialization will fail until Rock is restarted. This has most visibly affected certain control types when rendered via the Obsidian Registration Entry block (causing event registration pages to fail to load), and in one case caused any page loads initiated by an authenticated user to time out. In all cases, recycling the Application Pool resolved the issue.

The problem occurs seemingly at random, and while we've seen it manifest in different ways, what we've seen so far has consistently traced back to a concurrency issue with the JsonExtensions._jsonSerializeSettingsCache (here).

In cases where we've primarily seen Registration Entry affected, we see the block failing to load and throwing exceptions as follows:

 System.IndexOutOfRangeException	mscorlib	Index was outside the bounds of the array.
   at System.Collections.Generic.Dictionary`2.Insert(TKey key, TValue value, Boolean add)
   at Rock.JsonExtensions.GetSerializeSettings(Boolean indentOutput, Boolean ignoreErrors, Boolean camelCase)
   at Rock.JsonExtensions.ToCamelCaseJson(Object obj, Boolean indentOutput, Boolean ignoreErrors)
   at Rock.Field.Types.SelectSingleFieldType.GetPublicConfigurationValues(Dictionary`2 privateConfigurationValues, ConfigurationValueUsage usage, String privateValue) in \Rock\Field\Types\SelectSingleFieldType.cs:line 366
   at Rock.Attribute.PublicAttributeHelper.GetPublicAttributeForEdit(AttributeCache attribute) in \Rock\Attribute\PublicAttributeHelper.cs:line 139
   at Rock.Blocks.Event.RegistrationEntry.GetInitializationBox(RockContext rockContext)
   at Rock.Blocks.Event.RegistrationEntry.GetObsidianBlockInitialization()
   at Rock.Blocks.RockBlockType.GetObsidianBlockInitializationAsync() in \Rock\Blocks\RockBlockType.cs:line 233
   at Rock.Blocks.RockBlockType.GetBlockInitializationAsync(RockClientType clientType) in \Rock\Blocks\RockBlockType.cs:line 211
   at Rock.Blocks.RockBlockType.d__55.MoveNext() in \Rock\Blocks\RockBlockType.cs:line 527
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at Rock.Blocks.RockBlockType.d__53.MoveNext() in \Rock\Blocks\RockBlockType.cs:line 442
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)
   at Rock.Web.UI.RockBlockTypeWrapper.<>c__DisplayClass6_0.<b__0>d.MoveNext() in \Rock\Web\UI\RockBlockTypeWrapper.cs:line 83
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)
   at System.Web.UI.PageAsyncTaskManager.d__3.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)
   at System.Web.UI.Page.d__554.MoveNext()

In the second scenario, where authenticated users were unable to load Rock pages, the page load stalls and eventually times out:

System.Web.HttpException	System.Web	Request timed out.
   at System.Web.HttpContext.InvokeCancellableCallback(WaitCallback callback, Object state)
   at System.Web.UI.Page.d__554.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)
   at System.Web.TaskAsyncHelper.EndTask(IAsyncResult ar)
   at Rock.Web.UI.RockPage.EndProcessRequest(IAsyncResult result) in \Rock\Web\UI\RockPage.cs:line 5161
   at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
   at System.Web.HttpApplication.ExecuteStepImpl(IExecutionStep step)
   at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)

We were able to capture a memory dump showing the spinning requests in the second scenario. Analysis showed these requests' threads were hung at the following:

System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].FindEntry(System.__Canon)
System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].TryGetValue(System.__Canon, System.__Canon ByRef)
Rock.JsonExtensions.GetSerializeSettings(Boolean, Boolean, Boolean)
Rock.JsonExtensions.ToCamelCaseJson(System.Object, Boolean, Boolean)
Rock.Web.UI.RockPage.OnInit(System.EventArgs)
System.Web.UI.Control+d__225.MoveNext()
System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[System.Web.UI.Control+d__225, System.Web]](d__225 ByRef)
System.Web.UI.Control.InitRecursiveAsync(System.Web.UI.Control, System.Web.UI.Page)
System.Web.UI.Page+d__523.MoveNext()
System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[System.Web.UI.Page+d__523, System.Web]](d__523 ByRef)
System.Web.UI.Page.ProcessRequestMainAsync(Boolean, Boolean)
System.Web.UI.Page+d__515.MoveNext()
System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[System.Web.UI.Page+d__515, System.Web]](d__515 ByRef)
System.Web.UI.Page.ProcessRequestAsync(Boolean, Boolean)
System.Web.UI.Page+c__DisplayClass554_0.b__0(System.Object)
System.Web.HttpContext.InvokeCancellableCallback(System.Threading.WaitCallback, System.Object)
System.Web.UI.Page+d__554.MoveNext()
System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[System.Web.UI.Page+d__554, System.Web]](d__554 ByRef)
System.Web.UI.Page.ProcessRequestAsync(System.Web.HttpContext)
System.Web.TaskAsyncHelper.BeginTask(System.Func`1<System.Threading.Tasks.Task>, System.AsyncCallback, System.Object)
System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
System.Web.HttpApplication.ExecuteStepImpl(IExecutionStep)
System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Exception)
System.Web.HttpApplication.BeginProcessRequestNotification(System.Web.HttpContext, System.AsyncCallback)
System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)
System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)
DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)
[InlinedCallFrame: 0000003c0307f560] System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr, System.Web.RequestNotificationStatus ByRef)
[InlinedCallFrame: 0000003c0307f560] System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr, System.Web.RequestNotificationStatus ByRef)
DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, System.Web.RequestNotificationStatus ByRef)
System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)
DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)

The hung dictionary read call observed in the trace above is here.

Comments in JsonExtensions.cs indicate initialization via the constructor was intended to force initialization under single-threaded conditions to prevent concurrency issues, and the read operation is thread-safe. However, newer a bugfix added a call in RockApplicationStartupHelper.cs that creates a new comparer class instance. This in turn resets the settings cache dictionary, which is then repopulated on the fly as serialization settings are accessed. Thus, initialization of the settings cache dictionary is no longer happening in a thread-safe/single-threaded manner as it's happening on-demand based on requests/jobs/etc. instead of in the expected manner.

This could be resolved by converting _jsonSerializeSettingsCache to a ConcurrentDictionary, and replacing the cache reset in ReferenceEqualityComparer with a .Clear() call (here) instead of allocating a new dictionary.

Actual Behavior

Rock restarts into a bad state, seemingly randomly and dependent on load and conditions at time of startup.

Expected Behavior

Rock starts up consistently, regardless of load and startup conditions.

Steps to Reproduce

I wasn't able to reproduce this on Rock Solid Demo, though it may be possible by adding elevated request load during an application pool recycle or Rock restart. That said, I am happy to provide any further diagnostic information up on request.

Issue Confirmation

• Perform a search on the Github Issues to see if your bug is already reported.
• Reproduced the problem on a fresh install or on the demo site.

Rock Version

18.2

Client Culture Setting

en-US

[cabal95]

Thanks for the writeup @billdeitrick. We've added a copy-on-write pattern since the need to write to the dictionary is extremely rare. This gives about a 15% performance gain over ConcurrentDictionary since the read path is used pretty often.