Welcome to another short story about debugging an issue we faced recently during our production release. We use Azure DevOps build/release pipelines to release our code to higher environments.
The Problem
We have an Install Sitecore Items task in release pipeline to install Sitecore items on higher environments. We started facing an issue where the task failed with below errors -
2023-12-20T21:17:46.2357659Z Root config: C:\azagent\A3\_work\_tasks\InlinePowershell_31f040e5-e040-4336-878a-59a493355534\1.1.7\sitecore.json
2023-12-20T21:17:46.2383724Z [GraphQLHttpException] Unexpected HttpResponseMessage with code: InternalServerError
2023-12-20T21:17:46.2499102Z at GraphQL.Client.Http.Internal.GraphQLHttpHandler.ReadHttpResponseMessageAsync(HttpResponseMessage httpResponseMessage)
2023-12-20T21:17:46.2500367Z at GraphQL.Client.Http.Internal.GraphQLHttpHandler.PostAsync(GraphQLRequest request, CancellationToken cancellationToken)
2023-12-20T21:17:46.2501478Z at Sitecore.DevEx.Core.Client.GraphQl.SitecoreApiClient.<>c__DisplayClass11_0.<<RunQuery>b__0>d.MoveNext()
2023-12-20T21:17:46.2502543Z --- End of stack trace from previous location ---
2023-12-20T21:17:46.2504096Z at Sitecore.DevEx.Configuration.Authentication.OidcAuthenticationProvider.MakeAuthenticatedRequestInternal(HttpClient client, Func`2 requestAction) in C:\BA\ca7111d945a16af4\src\Sitecore.DevEx.Configuration\Authentication\OidcAuthenticationProvider.cs:line 87
2023-12-20T21:17:46.2505209Z at Sitecore.DevEx.Configuration.Authentication.OidcAuthenticationProvider.MakeAuthenticatedRequest(HttpClient client, Func`2 requestAction) in C:\BA\ca7111d945a16af4\src\Sitecore.DevEx.Configuration\Authentication\OidcAuthenticationProvider.cs:line 76
2023-12-20T21:17:46.2506308Z at Sitecore.DevEx.Configuration.Authentication.ClientCredentialsAuthenticationProvider.MakeAuthenticatedRequest(HttpClient client, Func`2 requestAction) in C:\BA\ca7111d945a16af4\src\Sitecore.DevEx.Configuration\Authentication\ClientCredentialsAuthenticationProvider.cs:line 106
2023-12-20T21:17:46.2507416Z at Sitecore.DevEx.Configuration.Models.EnvironmentConfiguration.MakeAuthenticatedRequest(HttpClient client, Func`2 requestAction) in C:\BA\ca7111d945a16af4\src\Sitecore.DevEx.Configuration\Models\EnvironmentConfiguration.cs:line 275
2023-12-20T21:17:46.2508581Z at Sitecore.DevEx.Core.Client.GraphQl.SitecoreApiClient.RunQuery(String servicePath, GraphQLRequest request, Boolean assertNoErrors, CancellationToken cancellationToken)
2023-12-20T21:17:46.2509746Z at Sitecore.DevEx.Serialization.Client.Datasources.Sc.Query.SitecoreTreeDataStore.ExecuteSingleBatchQuery[T](String batchQueryFragment, TreeScope scope, ItemSpec[] specs, CancellationToken cancellationToken)
2023-12-20T21:17:46.2510916Z at Sitecore.DevEx.Serialization.Client.Datasources.Sc.Query.SitecoreTreeDataStore.CreateParallelBatchQuery[T](String batchQueryFragment, TreeScope scope, ItemSpec[] specs, CancellationToken cancellationToken)
2023-12-20T21:17:46.2512035Z at Sitecore.DevEx.Serialization.Client.Datasources.Sc.Query.SitecoreTreeDataStore.GetTreeNodesInternal(IEnumerable`1 itemSpecs, TreeScope scope, CancellationToken cancellationToken)
2023-12-20T21:17:46.2513104Z at Sitecore.DevEx.Serialization.Client.Datasources.Sc.Query.SitecoreTreeDataStore.GetTreeNodes(IEnumerable`1 itemSpecs, CancellationToken cancellationToken)
2023-12-20T21:17:46.2514024Z at Sitecore.DevEx.Serialization.Client.TreeCongruencyCommandBuilder.<>c__DisplayClass11_0.<<CreateProcessDataflow>b__0>d.MoveNext()
2023-12-20T21:17:46.3912755Z ##[error]Sitecore CLI is failed
2023-12-20T21:17:46.2383724Z [GraphQLHttpException] Unexpected HttpResponseMessage with code: InternalServerError
2023-12-20T21:17:46.2499102Z at GraphQL.Client.Http.Internal.GraphQLHttpHandler.ReadHttpResponseMessageAsync(HttpResponseMessage httpResponseMessage)
2023-12-20T21:17:46.2500367Z at GraphQL.Client.Http.Internal.GraphQLHttpHandler.PostAsync(GraphQLRequest request, CancellationToken cancellationToken)
2023-12-20T21:17:46.2501478Z at Sitecore.DevEx.Core.Client.GraphQl.SitecoreApiClient.<>c__DisplayClass11_0.<<RunQuery>b__0>d.MoveNext()
2023-12-20T21:17:46.2502543Z --- End of stack trace from previous location ---
2023-12-20T21:17:46.2504096Z at Sitecore.DevEx.Configuration.Authentication.OidcAuthenticationProvider.MakeAuthenticatedRequestInternal(HttpClient client, Func`2 requestAction) in C:\BA\ca7111d945a16af4\src\Sitecore.DevEx.Configuration\Authentication\OidcAuthenticationProvider.cs:line 87
2023-12-20T21:17:46.2505209Z at Sitecore.DevEx.Configuration.Authentication.OidcAuthenticationProvider.MakeAuthenticatedRequest(HttpClient client, Func`2 requestAction) in C:\BA\ca7111d945a16af4\src\Sitecore.DevEx.Configuration\Authentication\OidcAuthenticationProvider.cs:line 76
2023-12-20T21:17:46.2506308Z at Sitecore.DevEx.Configuration.Authentication.ClientCredentialsAuthenticationProvider.MakeAuthenticatedRequest(HttpClient client, Func`2 requestAction) in C:\BA\ca7111d945a16af4\src\Sitecore.DevEx.Configuration\Authentication\ClientCredentialsAuthenticationProvider.cs:line 106
2023-12-20T21:17:46.2507416Z at Sitecore.DevEx.Configuration.Models.EnvironmentConfiguration.MakeAuthenticatedRequest(HttpClient client, Func`2 requestAction) in C:\BA\ca7111d945a16af4\src\Sitecore.DevEx.Configuration\Models\EnvironmentConfiguration.cs:line 275
2023-12-20T21:17:46.2508581Z at Sitecore.DevEx.Core.Client.GraphQl.SitecoreApiClient.RunQuery(String servicePath, GraphQLRequest request, Boolean assertNoErrors, CancellationToken cancellationToken)
2023-12-20T21:17:46.2509746Z at Sitecore.DevEx.Serialization.Client.Datasources.Sc.Query.SitecoreTreeDataStore.ExecuteSingleBatchQuery[T](String batchQueryFragment, TreeScope scope, ItemSpec[] specs, CancellationToken cancellationToken)
2023-12-20T21:17:46.2510916Z at Sitecore.DevEx.Serialization.Client.Datasources.Sc.Query.SitecoreTreeDataStore.CreateParallelBatchQuery[T](String batchQueryFragment, TreeScope scope, ItemSpec[] specs, CancellationToken cancellationToken)
2023-12-20T21:17:46.2512035Z at Sitecore.DevEx.Serialization.Client.Datasources.Sc.Query.SitecoreTreeDataStore.GetTreeNodesInternal(IEnumerable`1 itemSpecs, TreeScope scope, CancellationToken cancellationToken)
2023-12-20T21:17:46.2513104Z at Sitecore.DevEx.Serialization.Client.Datasources.Sc.Query.SitecoreTreeDataStore.GetTreeNodes(IEnumerable`1 itemSpecs, CancellationToken cancellationToken)
2023-12-20T21:17:46.2514024Z at Sitecore.DevEx.Serialization.Client.TreeCongruencyCommandBuilder.<>c__DisplayClass11_0.<<CreateProcessDataflow>b__0>d.MoveNext()
2023-12-20T21:17:46.3912755Z ##[error]Sitecore CLI is failed
When we looked at our CM logs, we found below errors which we never saw in logs before -
11808 21:17:36 INFO HttpModule is being initialized
11808 21:17:36 ERROR Application error.
Exception: System.Web.HttpException
Message: The request queue limit of the session is exceeded.
Source: System.Web
at System.Web.SessionState.SessionStateModule.QueueRef()
at System.Web.SessionState.SessionStateModule.PollLockedSession()
at System.Web.SessionState.SessionStateModule.GetSessionStateItem()
at System.Web.SessionState.SessionStateModule.BeginAcquireState(Object source, EventArgs e, AsyncCallback cb, Object extraData)
at System.Web.HttpApplication.AsyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
at System.Web.HttpApplication.ExecuteStepImpl(IExecutionStep step)
at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)
We tried increasing the polling intervals to 60 based on recommendations we could find on internet but it did not help. This issue did not occur in any of the lower environments which used the same release pipelines and deployed same Sitecore Item package.
The Research
The error we encountered was related to the exceptions noted on the CM side. Typically, the message "The request queue limit of the session is exceeded." arises when the server receives an excessive number of requests and can't process them all at once. This is due to the ASP .NET Session State Module's exclusive locking of each request from the same session, resulting in one-at-a-time request execution.
As far as we saw the provided logs, some of the requests take quite a noticeable amount of time to execute, for example:
2023-12-20T21:17:45.2197466Z [master] [GraphQL> Get metadata (master; 3 specs, SingleItem)] Request 422 returned in 8720ms
...
2023-12-20T21:17:45.7170789Z [master] [GraphQL> Get metadata (master; 2 specs, SingleItem)] Request 420 returned in 9217ms
...
2023-12-20T21:17:46.2331741Z [master] [GraphQL> Get metadata (master; 10 specs, SingleItem)] Request 417 returned in 9738ms
Thus, the issue could have been potentially caused by the slowness on the CM instance.
At the same time, it looked like the "aspnet:RequestQueueLimitPerSession" setting is set to 25 in your Web.config file. We realized since we didn't experience any noticeable performance issues in our CM instance apart from the failing CLI command, we tried increasing the value of the setting to see if it has any effect. This increased the max allowed request request queue and, thus, decrease the chance of this error arriving. And it worked!!
To confirm our theory, we also connected with the Sitecore Support team and they confirmed the fix we implemented is the expected solution in such scenarios.
Thanks for reading, hope it helps you!!
Comments
Post a Comment