Failed to read cache key

Mari Jørgensen
Vote:
I am investigating an issue where data is not updated as part of an import job. I have confirmed that logic is correct, the problem seem to be that product is not being saved.
In the log files I can see error messages like "Failed to Read cacheKey" and "System.Data.SqlClient.SqlException: Execution Timeout Expired." - see sample of full log message below.
We are running the site in Azure and using version 11.10.6 of Episerver.CMS.Core.
I know there were issues related to Episerver caching and version .NET 4.7 (ref https://vimvq1987.com/episerver-caching-issue-net-4-7/), but those should not apply since we are running v 11.10.6.
The import processes quite a huge amount of updates and works in batches of 24 which is processed in parallell.
2019-03-20 02:20:56,349 [15] ERROR EPiServer.Framework.Cache.ObjectInstanceCacheExtensions: Failed to Read cacheKey = 'EP:ECF:Version:85016'
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.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted)
at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
at EPiServer.Data.Providers.SqlTransientErrorsRetryPolicy.Execute[TResult](Func`1 method)
at Mediachase.Data.Provider.SqlDataProvider.ExecuteNonExec(DataCommand command)
at Mediachase.MetaDataPlus.Common.DBHelper.ExecuteNonQuery(String connectionString, CommandType commandType, String commandText, Int32 commandTimeout, DataParameter[] commandParameters)
at EPiServer.Commerce.Catalog.DataAccess.CatalogContentVersionDB.UpdateContentVersion(List`1 mappingData, DataTable workIdMapping, Boolean publishAction)
at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.CreateContentVersion(CatalogContentBase content, String currentUser, Boolean publishAction, Boolean skipSetCommonDraft)
at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.EnsureDraftsInAllLanguages(VersionCollection versionCollection, ContentReference contentLink)
at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.GetListFromDb(ContentReference contentLink)
at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.<>c__DisplayClass36_0.<GetContentVersions>b__0()
at EPiServer.Framework.Cache.ObjectInstanceCacheExtensions.ReadThroughWithWait[T](IObjectInstanceCache cache, String cacheKey, Func`1 readValue, Func`2 evictionPolicy)
at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.GetContentVersions(ContentReference contentLink)
at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.<>c__DisplayClass23_0.<List>b__0()
at EPiServer.Framework.Cache.ObjectInstanceCacheExtensions.ReadThroughWithWait[T](IObjectInstanceCache cache, String cacheKey, Func`1 readValue, Func`2 evictionPolicy)
ClientConnectionId:46c399d9-4ba2-405d-90f8-6b6cd197f407
Error Number:-2,State:0,Class:11
ClientConnectionId before routing:bd5514a4-0bf2-48e8-87fb-eaa7858584d3
Routing Destination:a5c98a899196.tr31.westeurope1-a.worker.database.windows.net,11119
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.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted)
at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
at EPiServer.Data.Providers.SqlTransientErrorsRetryPolicy.Execute[TResult](Func`1 method)
at Mediachase.Data.Provider.SqlDataProvider.ExecuteNonExec(DataCommand command)
at Mediachase.MetaDataPlus.Common.DBHelper.ExecuteNonQuery(String connectionString, CommandType commandType, String commandText, Int32 commandTimeout, DataParameter[] commandParameters)
at EPiServer.Commerce.Catalog.DataAccess.CatalogContentVersionDB.UpdateContentVersion(List`1 mappingData, DataTable workIdMapping, Boolean publishAction)
at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.CreateContentVersion(CatalogContentBase content, String currentUser, Boolean publishAction, Boolean skipSetCommonDraft)
at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.EnsureDraftsInAllLanguages(VersionCollection versionCollection, ContentReference contentLink)
at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.GetListFromDb(ContentReference contentLink)
at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.<>c__DisplayClass36_0.<GetContentVersions>b__0()
at EPiServer.Framework.Cache.ObjectInstanceCacheExtensions.ReadThroughWithWait[T](IObjectInstanceCache cache, String cacheKey, Func`1 readValue, Func`2 evictionPolicy)
at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.GetContentVersions(ContentReference contentLink)
at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.<>c__DisplayClass23_0.<List>b__0()
at EPiServer.Framework.Cache.ObjectInstanceCacheExtensions.ReadThroughWithWait[T](IObjectInstanceCache cache, String cacheKey, Func`1 readValue, Func`2 evictionPolicy)
ClientConnectionId:46c399d9-4ba2-405d-90f8-6b6cd197f407

2019-03-20 02:20:57,099 [15] ERROR lambda_method: One or more errors occurred.
System.AggregateException: One or more errors occurred. ---> System.Data.SqlClient.SqlException: Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception: The wait operation timed out
   --- End of inner exception stack trace ---
   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.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted)
   at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
   at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
   at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
   at EPiServer.Data.Providers.SqlTransientErrorsRetryPolicy.Execute[TResult](Func`1 method)
   at Mediachase.Data.Provider.SqlDataProvider.ExecuteNonExec(DataCommand command)
   at Mediachase.MetaDataPlus.Common.DBHelper.ExecuteNonQuery(String connectionString, CommandType commandType, String commandText, Int32 commandTimeout, DataParameter[] commandParameters)
   at EPiServer.Commerce.Catalog.DataAccess.CatalogContentVersionDB.UpdateContentVersion(List`1 mappingData, DataTable workIdMapping, Boolean publishAction)
   at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.CreateContentVersion(CatalogContentBase content, String currentUser, Boolean publishAction, Boolean skipSetCommonDraft)
   at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.EnsureDraftsInAllLanguages(VersionCollection versionCollection, ContentReference contentLink)
   at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.GetListFromDb(ContentReference contentLink)
   at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.<>c__DisplayClass36_0.<GetContentVersions>b__0()
   at EPiServer.Framework.Cache.ObjectInstanceCacheExtensions.ReadThroughWithWait[T](IObjectInstanceCache cache, String cacheKey, Func`1 readValue, Func`2 evictionPolicy)
   at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.GetContentVersions(ContentReference contentLink)
   at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.<>c__DisplayClass23_0.<List>b__0()
   at EPiServer.Framework.Cache.ObjectInstanceCacheExtensions.ReadThroughWithWait[T](IObjectInstanceCache cache, String cacheKey, Func`1 readValue, Func`2 evictionPolicy)
   at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.List(VersionFilter filter, Int32 startIndex, Int32 maxRows, Int32& totalCount)
   at EPiServer.Core.IContentVersionRepositoryExtensions.List(IContentVersionRepository contentVersionRepository, ContentReference contentLink)
   at EPiServer.Find.Commerce.CatalogEventIndexer.GetAllLanguageVersions(IContent content)
   at EPiServer.Find.Commerce.CatalogEventIndexer.IndexContentInAllLanguages(IContent content)
   at EPiServer.Find.Commerce.CatalogContentEventListener.IndexContentsIfNeeded(IEnumerable`1 contents, Action`1 indexAction, IDictionary`2 cachedReindexContentOnEventForType, Func`1 isReindexingContentOnUpdates)
   at EPiServer.Find.Commerce.CatalogContentEventListener.IndexContentsIfNeeded(IEnumerable`1 contentLinks, Action`1 indexAction)
   at EPiServer.Find.Commerce.CatalogContentEventListener.CatalogEventUpdated(Object sender, EventNotificationEventArgs e)
   at EPiServer.Events.Clients.Event.Raise(Guid raiserId, Object param, EventRaiseOption raiseOption)
   at Mediachase.Commerce.Catalog.Events.CatalogEventBroadcaster.RaiseEvent(CatalogContentUpdateEventArgs e)
   at Mediachase.Commerce.Catalog.Events.CatalogEventBroadcaster.SendEntryUpdateEvent(EntryEventArgs args)
   at Mediachase.Commerce.Catalog.EventContext.EntryEventHandler.Invoke(Object sender, EntryEventArgs e)
   at Mediachase.Commerce.Catalog.EventContext.RaiseEntryUpdatedEvent(CatalogEntryDto sender, EntryEventArgs args)
   at Mediachase.Data.Provider.TransactionScope.ExecuteActions(IEnumerable`1 actions)
   --- End of inner exception stack trace ---
   at Mediachase.Data.Provider.TransactionScope.ExecuteActions(IEnumerable`1 actions)
   at Mediachase.Data.Provider.TransactionScope.ThreadStaticTransactionScope.Commit()
   at Mediachase.Data.Provider.TransactionScope.Complete()
   at EPiServer.Commerce.Catalog.Provider.CatalogContentCommitterHandler.SaveVersionInternal(CatalogContentBase content, SaveAction action, String currentUser)
   at EPiServer.Commerce.Catalog.Provider.CatalogContentCommitterHandler.Save(CatalogContentBase content, SaveAction action, String currentUser)
   at EPiServer.Commerce.Catalog.Provider.CatalogContentProvider.Save(IContent content, SaveAction action)
   at EPiServer.Core.Internal.DefaultContentRepository.Save(IContent content, SaveAction action, AccessLevel access)
#202229
Mar 20, 2019 9:56
Quan Mai
Vote:
The one you should be looking at is
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

As you said you have 24 threads running in parallel, I'd suspect that is too much for SQL Server to handle, causing it to slow down and even timeout for some queries. Check your DTU percentage. Lowering your level of parallelism might help
#202230
Mar 20, 2019 10:01