2

We are experiencing an intermittent problem which causes the initialisation of a local Sitecore instance to hang indefinitely, and we can't seem to figure out what is causing it. It seems to vary in frequency and can affect our local instance up to a full work day. The log messages seem to suggest that when the issue occurs, it happens at the same point each time during the initialisation of the instance. The following messages are the last to be written to the logs before the application hangs:

9492 10:57:01 INFO  Messaging : IMessageBus started successfully : 'Sitecore.Marketing.Automation.Messaging.Buses.PurgeFromCampaignMessagesBus'
6668 10:57:02 INFO  Cache created: 'SqlDataProvider - Prefetch data(web)' (max size: 100MB, running total: 1225MB)
20468 10:57:02 INFO  Scheduler - Adding agents
20468 10:57:02 INFO  Scheduler - Adding agent: Sitecore.Tasks.UrlAgent (interval: 00:15:00)
20468 10:57:02 INFO  Scheduler - Adding agent: Sitecore.Tasks.TaskDatabaseAgent (interval: 00:10:00)
20468 10:57:02 INFO  Scheduler - Adding agent: Sitecore.Tasks.CompactClientDataAgent (interval: 04:00:00)
20468 10:57:02 INFO  Scheduler - Adding agent: Sitecore.Tasks.CleanupPublishQueue (interval: 04:00:00)
20468 10:57:02 INFO  Scheduler - Adding agent: Sitecore.Tasks.CleanupEventQueue (interval: 04:00:00)
20468 10:57:02 INFO  Scheduler - Skipping inactive agent: Sitecore.Tasks.HtmlCacheClearAgent
20468 10:57:02 INFO  Scheduler - Adding agent: Sitecore.Tasks.CleanupAuthenticationTicketsAgent (interval: 04:00:00)
20468 10:57:02 INFO  Scheduler - Skipping inactive agent: Sitecore.Tasks.PublishAgent
20468 10:57:02 INFO  Scheduler - Adding agent: Sitecore.Tasks.CleanupAgent (interval: 06:00:00)
20468 10:57:02 INFO  Scheduler - Adding agent: Sitecore.Tasks.CounterDumpAgent (interval: 01:00:00)
20468 10:57:02 INFO  Scheduler - Adding agent: Sitecore.Tasks.CloneNotificationsCleanupAgent (interval: 1.00:00:00)
20468 10:57:02 INFO  Scheduler - Adding agent: Core_Database_Agent (interval: 00:10:00)
20468 10:57:02 INFO  Scheduler - Adding agent: Master_Database_Agent (interval: 00:10:00)
20468 10:57:02 INFO  Scheduler - Adding agent: Sitecore.Tasks.CleanupFDAObsoleteMediaData (interval: 1.00:00:00)
20468 10:57:02 INFO  Scheduler - Adding agent: Sitecore.Tasks.WebDAVOptionsCleanupAgent (interval: 1.00:00:00)
20468 10:57:02 INFO  Scheduler - Adding agent: Sitecore.ContentSearch.Tasks.Optimize (interval: 12:00:00)
20468 10:57:02 INFO  Scheduler - Adding agent: Sitecore.ContentSearch.SolrProvider.Agents.IsSolrAliveAgent (interval: 00:10:00)
20468 10:57:02 INFO  Scheduler - Adding agent: Sitecore.ContentSearch.SolrProvider.Agents.IndexingStateSwitcher (interval: 00:01:00)
20468 10:57:02 WARN  EmailDiagnosticsReportTask is not configured, check following settings: SupportPackage.RunDiagnosticsTask.FromAddress, SupportPackage.RunDiagnosticsTask.MailTo, MailServer, MailServerPort, MailServerUserName, MailServerPassword, MailServerUseSsl
20468 10:57:02 INFO  Scheduler - Adding agent: EmailDiagnosticsReportTask (interval: 01:00:00)
20468 10:57:02 INFO  Scheduler - Adding agent: Sitecore.ListManagement.Operations.UpdateListOperationsAgent (interval: 00:00:10)
20468 10:57:02 INFO  Scheduler - Adding agent: Sitecore.PathAnalyzer.Client.Tasks.HelpUpdateAgent (interval: 03:00:00)
20468 10:57:02 INFO  Scheduler - Adding agent: Sitecore.PathAnalyzer.Client.Tasks.HelpUpdateAgent (interval: 03:00:00)
20468 10:57:02 INFO  Scheduler - Agents added
ManagedPoolThread #0 10:57:07 INFO  Job started: Sitecore.ListManagement.Operations.UpdateListOperationsAgent
6668 10:57:12 INFO  Cache created: 'ItemCloningRelations' (max size: 50MB, running total: 1275MB)
ManagedPoolThread #0 10:57:36 INFO  Cache created: 'SqlDataProvider - Prefetch data(core)' (max size: 150MB, running total: 1425MB)

Occasionally we will get some additional messages regarding the application's health come through to the logs such as the following:

ManagedPoolThread #4 11:06:57 INFO  Health.PrivateBytes: 1,141,104,640
ManagedPoolThread #4 11:06:57 INFO  Health.CacheInstances: 52
ManagedPoolThread #4 11:06:57 INFO  Health.CacheTotalCount: 31,887
ManagedPoolThread #4 11:06:57 INFO  Health.CacheTotalSize: 168,119,591

We had a network drop today which caused an exception to be thrown immediately after which may give some indication as to where this is hanging, but we can't figure out where this may be from this:

1396 11:11:21 WARN  An error occurred when attempting to receive the next message: System.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception (0x80004005): The wait operation timed out
   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at System.Data.SqlClient.SqlCommand.InternalEndExecuteReader(IAsyncResult asyncResult, String endMethod, Boolean isInternal)
   at System.Data.SqlClient.SqlCommand.EndExecuteReaderInternal(IAsyncResult asyncResult)
   at System.Data.SqlClient.SqlCommand.EndExecuteReaderAsync(IAsyncResult asyncResult)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- 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 Rebus.SqlServer.Transport.SqlServerTransport.<Receive>d__27.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 Rebus.Workers.ThreadPoolBased.ThreadPoolWorker.<ReceiveTransportMessage>d__17.MoveNext()
ClientConnectionId:7da1570d-aed0-4291-af81-dc0b2498fd2a
Error Number:-2,State:0,Class:11
Rebus 1 worker 1 11:11:21 WARN  An error occurred when attempting to receive the next message: System.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception (0x80004005): The wait operation timed out
   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
   at System.Data.SqlClient.TdsParser.TdsExecuteTransactionManagerRequest(Byte[] buffer, TransactionManagerRequestType request, String transactionName, TransactionManagerIsolationLevel isoLevel, Int32 timeout, SqlInternalTransaction transaction, TdsParserStateObject stateObj, Boolean isDelegateControlRequest)
   at System.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransactionYukon(TransactionRequest transactionRequest, String transactionName, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
   at System.Data.SqlClient.SqlInternalConnection.BeginSqlTransaction(IsolationLevel iso, String transactionName, Boolean shouldReconnect)
   at System.Data.SqlClient.SqlConnection.BeginTransaction(IsolationLevel iso, String transactionName)
   at Rebus.SqlServer.DbConnectionProvider.<GetConnection>d__5.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 Rebus.SqlServer.Transport.SqlServerTransport.<>c__DisplayClass34_0.<<GetConnection>b__0>d.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 Rebus.SqlServer.Transport.SqlServerTransport.<Receive>d__27.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 Rebus.Workers.ThreadPoolBased.ThreadPoolWorker.<ReceiveTransportMessage>d__17.MoveNext()
ClientConnectionId:29e8a8b0-db52-46f6-afc6-82af717b0544
Error Number:-2,State:0,Class:11

Rebus is referenced in the stack trace, so we aren't sure if it is related to the messaging bus in anyway.

Our local instance runs via IIS while the databases used for our local instance are hosted on a separate server. Solr is used for indexing. Only one of our developers is not experiencing this issue.

We have tried the following in an attempt to fix the issue:

  • Rebuild of the solution in Visual Studio
  • Reboot of the machine
  • Killing the w3wp.exe process
  • iisreset
Improve this question
3
  • Try cleaning EventQueue and other tables mentioned here (via SQL) briancaos.wordpress.com/2016/08/12/…
    – Marek Musielak ♦
    Sep 2, 2020 at 14:43
  • Thanks Marek! That seems to have resolved the issue for now. We will keep an eye on it. If the problem happens again and the fix is consistent, we can count this as resolved!
    – Mitchell
    Sep 3, 2020 at 8:41
  • Glad it worked. I added it as an answer.
    – Marek Musielak ♦
    Sep 3, 2020 at 8:47

1 Answer 1

Reset to default
2

When you upgrade Sitecore to a newer version, many Sitecore items are changed. This may cause an issue with EventQueue table filled with thousands of entries.

If that's the case, Sitecore cannot handle it well when it starts.

You should run a script which removes data from EventQueue, PublishQueue and History tables:

/****** History ******/
delete FROM [YOURDATABASE_Core].[dbo].[History] where Created < DATEADD(HOUR, -12, GETDATE())
delete FROM [YOURDATABASE_Master].[dbo].[History] where Created < DATEADD(HOUR, -12, GETDATE())
delete FROM [YOURDATABASE_Web].[dbo].[History] where Created < DATEADD(HOUR, -12, GETDATE())
  
/****** Publishqueue ******/
delete FROM [YOURDATABASE_Core].[dbo].[PublishQueue] where Date < DATEADD(HOUR, -12, GETDATE());    
delete FROM [YOURDATABASE_Master].[dbo].[PublishQueue] where Date < DATEADD(HOUR, -12, GETDATE());
delete FROM [YOURDATABASE_Web].[dbo].[PublishQueue] where Date < DATEADD(HOUR, -12, GETDATE());
     
/****** EventQueue ******/
delete FROM [YOURDATABASE_Master].[dbo].[EventQueue] where [Created] < DATEADD(HOUR, -4, GETDATE())
delete FROM [YOURDATABASE_Core].[dbo].[EventQueue] where [Created] < DATEADD(HOUR, -4, GETDATE())
delete FROM [YOURDATABASE_Web].[dbo].[EventQueue] where [Created] < DATEADD(HOUR, -4, GETDATE())

And after it's done, restart Sitecore.

More can be found here: https://briancaos.wordpress.com/2016/08/12/sitecore-event-queue-how-to-clean-it-and-why/

Improve this answer

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.