umbracoLock timeout exceeded frequently for members

umbracoLock table timing out frequently

Umbraco version

I am seeing this issue on Umbraco version: 8.5.5

Reproduction

If you're filing a bug, please describe how to reproduce it. Include as much relevant information as possible, such as:

Bug summary

I am seeing many cases of Lock request time out period exceeded. Up to 2000/day which is causing significant issues using our site.

Looking at database statistics I observed that we are exceeding the hard coded 1800ms timeout on many days.

Specifics

Umbraco is running on Windows Server 2019 on premises The database is running on Azure, P2 scale.

Steps to reproduce

Any time we have relatively high activity. This often occurs when logging a member in, but it may happen in other instances as that is the most visible scenario

Expected result

umbracoLock performs quickly with no timeouts

Actual result

Exception

System.Data.SqlClient.SqlException (0x80131904): Lock request time out period exceeded.

The statement has been terminated.

   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 Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func`1 func) in D:\a\1\s\src\Umbraco.Core\Persistence\FaultHandling\RetryPolicy.cs:line 172

   at NPoco.Database.ExecuteNonQueryHelper(DbCommand cmd)

   at NPoco.Database.Execute(String sql, CommandType commandType, Object[] args)

   at Umbraco.Core.Persistence.SqlSyntax.SqlServerSyntaxProvider.WriteLock(IDatabase db, Int32[] lockIds) in D:\a\1\s\src\Umbraco.Core\Persistence\SqlSyntax\SqlServerSyntaxProvider.cs:line 264

   at Umbraco.Core.Services.Implement.MemberService.Save(IMember member, Boolean raiseEvents) in D:\a\1\s\src\Umbraco.Core\Services\Implement\MemberService.cs:line 837

   at Umbraco.Web.Security.Providers.UmbracoMembershipProvider`2.GetUser(String username, Boolean userIsOnline) in D:\a\1\s\src\Umbraco.Web\Security\Providers\UmbracoMembershipProvider.cs:line 362

   at UmbracoGC.Libs.CustomerMembership.BGVMemberMembershipProvider.ValidateUser(String username, String password) in C:\agent\vsts-agent-win-x64-2.159.2\_work\5\s\UmbracoGC\Libs\CustomMembership\BGVMemberMembershipProvider.cs:line 14

   at Umbraco.Web.Security.MembershipHelper.Login(String username, String password) in D:\a\1\s\src\Umbraco.Web\Security\MembershipHelper.cs:line 260

   at UmbracoGC.Services.Member.GrandCentralMemberService.LogIn(LoginViewModel LoginModel) in C:\agent\vsts-agent-win-x64-2.159.2\_work\5\s\UmbracoGC\Services\Member\GrandCentralMemberService.cs:line 63

ClientConnectionId:aec38c8b-5401-4758-8e72-ff2e093b8ae1

Error Number:1222,State:51,Class:16

System.Data.SqlClient.SqlException (0x80131904): Lock request time out period exceeded.

The statement has been terminated.

   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 Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func`1 func) in D:\a\1\s\src\Umbraco.Core\Persistence\FaultHandling\RetryPolicy.cs:line 172

   at NPoco.Database.ExecuteNonQueryHelper(DbCommand cmd)

   at NPoco.Database.Execute(String sql, CommandType commandType, Object[] args)

ClientConnectionId:b70e4664-8d20-4ad8-b31e-221227eede13

Error Number:1222,State:51,Class:16

Thanks for the report. 8.6.4 will have some fixes directly relating to this https://github.com/umbraco/Umbraco-CMS/issues?q=label%3Arelease%2F8.6.4+is%3Aclosed

But it's great you've provided a stack trace as we'll need to investigate further with the member logins

Thank you. Looking at this PR #8398 I'm not sure it addresses this problem specifically.

Please let me know what other information I can provide to assist identifying a solution.

One thing we are doing to reduce the number of ReadLocks on Members is to now internally cache members so we will reduce our calls to read members from the database significantly. Prior we were accessing Members directly from the Member Service on the scale of 10s of times per session.

Services.MemberService.GetByUsername(User.Identity.Name).GetValue<int>(CredentialIDAlias);

Hi @TimZander - we would love it if you could give the upcoming 8.6.4 release a spin, we think it will fix your issue and a few other ones as well.

The 8.6.4 build we intend to release is now available from the Artifacts on this build (where it says 3 published): https://dev.azure.com/umbraco/Umbraco%20Cms/_build/results?buildId=43999&view=results

We need to await test results from real-life usage to actually test this on your environments to make sure we have now eliminated the problems even in setups that might have different configurations on what we've tested it on. This needs to happen before we can release this build, so the sooner that happens, the sooner we can release! 😄

Please give it a spin and let us know how it goes!

In your case, I'd recommend first upgrading to 8.6.3 and from 8.6.3 to 8.6.4, the only differences are the dlls so you can drop in the new dlls on your target test environment.

Thank you, I will try this today

I have tried replacing the dlls after upgrading to 8.6.3, but it is now asking me to run an upgrade from 8.6.4 from 8.6.3.

Does this make any changes to the database, or can I just change the web.config value to 8.6.4 to skip this?

You can just run the installer it doesn't modify your database for patch releases.

Thanks, this has been fine in our testing environment, but we have been unable to replicate the lock timeout in anything but production, so I will be applying these changes to production in a few hours and will see if it makes a difference

Initially the number of theses errors seem to be reduced today, but not gone entirely. I would say they are roughly 1/3 of what they were previously. So far this quantity is not causing issues with stability or operation of the site, but I will continue monitoring

We have a site with over 26000 content items (at least that many rows in umbracoContent), and are having problems with lock request time outs as well and the content tree won't render in the backoffice. The SQL ActivityMonitor shows a lot of lock waits.

System.Data.SqlClient.SqlException (0x80131904): Lock request time out period exceeded.
The statement has been terminated.
   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 Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func`1 func) in d:\a\1\s\src\Umbraco.Core\Persistence\FaultHandling\RetryPolicy.cs:line 172
   at NPoco.Database.ExecuteNonQueryHelper(DbCommand cmd)
   at NPoco.Database.Execute(String sql, CommandType commandType, Object[] args)
   at Umbraco.Core.Persistence.SqlSyntax.SqlServerSyntaxProvider.WriteLock(IDatabase db, TimeSpan timeout, Int32[] lockIds) in d:\a\1\s\src\Umbraco.Core\Persistence\SqlSyntax\SqlServerSyntaxProvider.cs:line 269
   at Umbraco.Core.Services.Implement.ContentService.<PerformScheduledPublishInternal>d__59.MoveNext() in d:\a\1\s\src\Umbraco.Core\Services\Implement\ContentService.cs:line 1376
   at System.Collections.Generic.List`1..ctor(IEnumerable`1 collection)
   at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source)
   at Umbraco.Core.Services.Implement.ContentService.PerformScheduledPublish(DateTime date) in d:\a\1\s\src\Umbraco.Core\Services\Implement\ContentService.cs:line 1363
   at Umbraco.Web.Scheduling.ScheduledPublishing.PerformRun() in d:\a\1\s\src\Umbraco.Web\Scheduling\ScheduledPublishing.cs:line 72
ClientConnectionId:575dc644-6feb-41c0-a8f1-e668803a4970
Error Number:1222,State:51,Class:16

That Exception happened shortly after an editor tried to move some content nodes which errored out

System.Data.SqlClient.SqlException (0x80131904): Cannot continue the execution because the session is in the kill state.
   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.SqlDataReader.TryCloseInternal(Boolean closeReader)
   at System.Data.SqlClient.SqlDataReader.Close()
   at System.Data.Common.DbDataReader.Dispose(Boolean disposing)
   at NPoco.Database.<Read>d__156`1.System.IDisposable.Dispose()
   at NPoco.Database.<Read>d__156`1.MoveNext()
   at NPoco.Database.<QueryImp>d__164`1.MoveNext()
   at System.Collections.Generic.List`1..ctor(IEnumerable`1 collection)
   at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source)
   at NPoco.Database.<Page>b__170_0[T](Page`1 paged, Sql thesql)
   at NPoco.Database.PageImp[T,TRet](Int64 page, Int64 itemsPerPage, String sql, Object[] args, Func`3 executeQueryFunc)
   at NPoco.Database.Page[T](Int64 page, Int64 itemsPerPage, String sql, Object[] args)
   at NPoco.Database.Page[T](Int64 page, Int64 itemsPerPage, Sql sql)
   at Umbraco.Core.Persistence.Repositories.Implement.ContentRepositoryBase`3.GetPage[TDto](IQuery`1 query, Int64 pageIndex, Int32 pageSize, Int64& totalRecords, Func`2 mapDtos, Sql`1 filter, Ordering ordering) in d:\a\1\s\src\Umbraco.Core\Persistence\Repositories\Implement\ContentRepositoryBase.cs:line 494
   at Umbraco.Core.Persistence.Repositories.Implement.DocumentRepository.GetPage(IQuery`1 query, Int64 pageIndex, Int32 pageSize, Int64& totalRecords, IQuery`1 filter, Ordering ordering) in d:\a\1\s\src\Umbraco.Core\Persistence\Repositories\Implement\DocumentRepository.cs:line 870
   at Umbraco.Core.Services.Implement.ContentService.PerformMoveLocked(IContent content, Int32 parentId, IContent parent, Int32 userId, ICollection`1 moves, Nullable`1 trash) in d:\a\1\s\src\Umbraco.Core\Services\Implement\ContentService.cs:line 2013
   at Umbraco.Core.Services.Implement.ContentService.Move(IContent content, Int32 parentId, Int32 userId) in d:\a\1\s\src\Umbraco.Core\Services\Implement\ContentService.cs:line 1963
   at Umbraco.Web.Editors.ContentController.PostMove(MoveOrCopy move) in d:\a\1\s\src\Umbraco.Web\Editors\ContentController.cs:line 1548
   at lambda_method(Closure , Object , Object[] )
   at System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ActionExecutor.<>c__DisplayClass6_2.<GetExecutor>b__2(Object instance, Object[] methodParameters)
   at System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ExecuteAsync(HttpControllerContext controllerContext, IDictionary`2 arguments, CancellationToken cancellationToken)
--- 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.Web.Http.Controllers.ApiControllerActionInvoker.<InvokeActionAsyncCore>d__1.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.Web.Http.Filters.ActionFilterAttribute.<CallOnActionExecutedAsync>d__6.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Web.Http.Filters.ActionFilterAttribute.<CallOnActionExecutedAsync>d__6.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.Web.Http.Filters.ActionFilterAttribute.<ExecuteActionFilterAsyncCore>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 System.Web.Http.Filters.ActionFilterAttribute.<CallOnActionExecutedAsync>d__6.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Web.Http.Filters.ActionFilterAttribute.<CallOnActionExecutedAsync>d__6.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.Web.Http.Filters.ActionFilterAttribute.<ExecuteActionFilterAsyncCore>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 System.Web.Http.Filters.ActionFilterAttribute.<CallOnActionExecutedAsync>d__6.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Web.Http.Filters.ActionFilterAttribute.<CallOnActionExecutedAsync>d__6.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.Web.Http.Filters.ActionFilterAttribute.<ExecuteActionFilterAsyncCore>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 System.Web.Http.Filters.ActionFilterAttribute.<CallOnActionExecutedAsync>d__6.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Web.Http.Filters.ActionFilterAttribute.<CallOnActionExecutedAsync>d__6.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.Web.Http.Filters.ActionFilterAttribute.<ExecuteActionFilterAsyncCore>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 System.Web.Http.Filters.ActionFilterAttribute.<CallOnActionExecutedAsync>d__6.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Web.Http.Filters.ActionFilterAttribute.<CallOnActionExecutedAsync>d__6.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.Web.Http.Filters.ActionFilterAttribute.<ExecuteActionFilterAsyncCore>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 System.Web.Http.Filters.ActionFilterAttribute.<CallOnActionExecutedAsync>d__6.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Web.Http.Filters.ActionFilterAttribute.<CallOnActionExecutedAsync>d__6.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.Web.Http.Filters.ActionFilterAttribute.<ExecuteActionFilterAsyncCore>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 System.Web.Http.Filters.ActionFilterAttribute.<CallOnActionExecutedAsync>d__6.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Web.Http.Filters.ActionFilterAttribute.<CallOnActionExecutedAsync>d__6.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.Web.Http.Filters.ActionFilterAttribute.<ExecuteActionFilterAsyncCore>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 System.Web.Http.Controllers.ActionFilterResult.<ExecuteAsync>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 System.Web.Http.Filters.AuthorizationFilterAttribute.<ExecuteAuthorizationFilterAsyncCore>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.Web.Http.Filters.AuthorizationFilterAttribute.<ExecuteAuthorizationFilterAsyncCore>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.Web.Http.Filters.AuthorizationFilterAttribute.<ExecuteAuthorizationFilterAsyncCore>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.Web.Http.Filters.AuthorizationFilterAttribute.<ExecuteAuthorizationFilterAsyncCore>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.Web.Http.Controllers.ExceptionFilterResult.<ExecuteAsync>d__6.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Web.Http.Controllers.ExceptionFilterResult.<ExecuteAsync>d__6.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.Web.Http.Dispatcher.HttpControllerDispatcher.<SendAsync>d__15.MoveNext()
ClientConnectionId:d74b1eed-112c-4882-bd92-da8704028153
Error Number:596,State:1,Class:21

Which happend shortly after something went really wrong with the move

System.Data.SqlClient.SqlException (0x80131904): A severe error occurred on the current command.  The results, if any, should be discarded.
   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.SqlDataReader.TryHasMoreRows(Boolean& moreRows)
   at System.Data.SqlClient.SqlDataReader.TryReadInternal(Boolean setTimeout, Boolean& more)
   at System.Data.SqlClient.SqlDataReader.Read()
   at NPoco.Database.<Read>d__156`1.MoveNext()
   at NPoco.Database.<QueryImp>d__164`1.MoveNext()
   at System.Collections.Generic.List`1..ctor(IEnumerable`1 collection)
   at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source)
   at NPoco.Database.<Page>b__170_0[T](Page`1 paged, Sql thesql)
   at NPoco.Database.PageImp[T,TRet](Int64 page, Int64 itemsPerPage, String sql, Object[] args, Func`3 executeQueryFunc)
   at NPoco.Database.Page[T](Int64 page, Int64 itemsPerPage, String sql, Object[] args)
   at NPoco.Database.Page[T](Int64 page, Int64 itemsPerPage, Sql sql)
   at Umbraco.Core.Persistence.Repositories.Implement.ContentRepositoryBase`3.GetPage[TDto](IQuery`1 query, Int64 pageIndex, Int32 pageSize, Int64& totalRecords, Func`2 mapDtos, Sql`1 filter, Ordering ordering) in d:\a\1\s\src\Umbraco.Core\Persistence\Repositories\Implement\ContentRepositoryBase.cs:line 494
   at Umbraco.Core.Persistence.Repositories.Implement.DocumentRepository.GetPage(IQuery`1 query, Int64 pageIndex, Int32 pageSize, Int64& totalRecords, IQuery`1 filter, Ordering ordering) in d:\a\1\s\src\Umbraco.Core\Persistence\Repositories\Implement\DocumentRepository.cs:line 870
   at Umbraco.Core.Services.Implement.ContentService.PerformMoveLocked(IContent content, Int32 parentId, IContent parent, Int32 userId, ICollection`1 moves, Nullable`1 trash) in d:\a\1\s\src\Umbraco.Core\Services\Implement\ContentService.cs:line 2013
   at Umbraco.Core.Services.Implement.ContentService.Move(IContent content, Int32 parentId, Int32 userId) in d:\a\1\s\src\Umbraco.Core\Services\Implement\ContentService.cs:line 1963
   at Umbraco.Web.Editors.ContentController.PostMove(MoveOrCopy move) in d:\a\1\s\src\Umbraco.Web\Editors\ContentController.cs:line 1548
   at lambda_method(Closure , Object , Object[] )
   at System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ActionExecutor.<>c__DisplayClass6_2.<GetExecutor>b__2(Object instance, Object[] methodParameters)
   at System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ExecuteAsync(HttpControllerContext controllerContext, IDictionary`2 arguments, CancellationToken cancellationToken)
ClientConnectionId:d74b1eed-112c-4882-bd92-da8704028153

I'm throwing this up here in case it helps or is even related. It's also quite possible I'm doing something I shouldn'. I have a number of events on Published/Saving/transformingIndexValues content to do various things such as send push notices, store some computed data in the ExternalIndex etc. I'll keep reviewing the code I've put into this site, if this sounds related, i'm happy to try 8.6.4.

@cleversolutions yes 8.6.4 will improve what you are seeing with the fixes to scheduled publishing. It may not fix everything entirely, it just depends on what's happening in your project. I would highly recommend you try the 8.6.4 build, it will definitely improve the lock contention for content. Please let us know any results

For long running operations like Move, lets say you are moving a huge amount of data, we cannot avoid SQL lock timeouts. We use SQL locks as the distributed locking mechanism. For long running operations the best we could do in the future would be to improve the handling of these errors and the UI so that we could detect long running operations and tell the user what is going on. There's certainly improvements in parts of the code that probably don't need to take a distributed lock or just not eagerly take one (like scheduled publishing was doing) which will all go a long way to improving this.

Hi @TimZander I've created a PR that you can find here https://github.com/umbraco/Umbraco-CMS/pull/8525 This change should alleviate the issue you are seeing as we will no longer take a write lock during member login (in the membership provider GetUser(string username, bool userIsOnline) call). This is the issue displayed in the stack traces you posted above initially. Read locks aren't an issue unless a corresponding write lock is being attempted.

And other good news is that you can see in the PR that I've fixed a long outstanding TODO in the code to ensure that members are cached by their username and not just by their ID so you can remove your own caches for that. Since you were already caching members this way you would have already seen the performance improvements but perhaps you'll see more I'm unsure. For others that haven't added their own caches and have member heavy sites this will reduce queries tremendously since calls are made to get a member by username on each request.

I'll wait until tomorrow for the build to finish since it's late here but if you are around, the latest build for this is here https://dev.azure.com/umbraco/Umbraco%20Cms/_build/results?buildId=45100&view=results If it's successful you will be able to get the artifacts for that build and test it out. If you do let me know how it goes, else i'll respond tomorrow once the build is complete.

@Shazwazza Awesome! Thank you, I will review and apply the artifact ASAP.

Would this be expected to be rolled into 8.6.4 when that is released?

@TimZander unfortunately no we've missed that deadline window so this will be an 8.6.5 release

@Shazwazza OK, thanks.

Thanks @Shazwazza I downloaded the artifacts yesterday as soon as the build completed and have been running them in our staging env. Early next week I'll apply to production and hope for the best!

@TimZander Hi Tim, Have you been able to test this in your production setup yet?

@clausjensen I will be applying to production in 9-10 hours. I will follow up in 24 hours with observed results

Thanks!

As of this morning we are no longer seeing many of this issue with umbracoLock timeout, however now I am seeing a number of other new exceptions.

System.Data.SqlClient.SqlException (0x80131904): Cannot insert duplicate key row in object 'dbo.umbracoPropertyData' with unique index 'IX_umbracoPropertyData_VersionId'. The duplicate key value is (3240, 312, <NULL>, <NULL>).
The statement has been terminated.
   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.SqlDataReader.TryConsumeMetaData()
   at System.Data.SqlClient.SqlDataReader.get_MetaData()
   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.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteScalar()
   at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func`1 func) in d:\a\1\s\src\Umbraco.Core\Persistence\FaultHandling\RetryPolicy.cs:line 172
   at NPoco.Database.ExecuteScalarHelper(DbCommand cmd)
   at NPoco.Database.InsertImp[T](PocoData pocoData, String tableName, String primaryKeyName, Boolean autoIncrement, T poco)
ClientConnectionId:21907364-5e16-4f42-937c-a4e835fd5bc9
Error Number:2601,State:1,Class:14

and

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.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at System.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)
   at System.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()
   at System.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()
   at System.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()
   at System.Data.SqlClient.TdsParserStateObject.TryReadByte(Byte& value)
   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at System.Data.SqlClient.SqlDataReader.TryConsumeMetaData()
   at System.Data.SqlClient.SqlDataReader.get_MetaData()
   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.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteScalar()
   at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func`1 func) in d:\a\1\s\src\Umbraco.Core\Persistence\FaultHandling\RetryPolicy.cs:line 172
   at NPoco.Database.ExecuteScalarHelper(DbCommand cmd)
   at NPoco.Database.InsertImp[T](PocoData pocoData, String tableName, String primaryKeyName, Boolean autoIncrement, T poco)
ClientConnectionId:92e6e568-3603-4c50-945b-1e75a924c7f4
Error Number:-2,State:0,Class:11

and still a few of these

System.Data.SqlClient.SqlException (0x80131904): Lock request time out period exceeded.
The statement has been terminated.
   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 Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func`1 func) in d:\a\1\s\src\Umbraco.Core\Persistence\FaultHandling\RetryPolicy.cs:line 172
   at NPoco.Database.ExecuteNonQueryHelper(DbCommand cmd)
   at NPoco.Database.Execute(String sql, CommandType commandType, Object[] args)
ClientConnectionId:e1f55d80-5f65-45ca-88db-dbe97a0b5fa3
Error Number:1222,State:51,Class:16

Thanks for the feedback @TimZander

We will not be including this fix for 8.6.4 as we do not really know whether this is then better or worse than what we had before without further testing. This would need further investigation from us and possibly some more fixing to ensure we get to a better state instead of risking making things worse and affecting more people than they already are.

I would however encourage you to look into if your content contains a lot of old versions. The issues you're seeing could be related to large amount of property data, causing unwanted timeouts when also querying the same tables for member data (members also use some data stored as property data). Could you share some numbers on row count in the property tables?

Hi @clausjensen

SELECT COUNT(*)
  FROM [dbo].[umbracoPropertyData]
417927

Is there a script to remove property data that is not the current version and older than a certain date?

@TimZander I believe there's a couple of variants of script allowing you to delete the versions but I'm not aware of which ones are most current and if any of them allows setting a date as well. There's also mentions of Unversion in here - I'd prolly recommend using that one instead of running scripts. As always .. please do a database backup before attempting any of this - just in case. https://our.umbraco.com/forum/umbraco-8/96498-delete-old-versions

Hi @TimZander any chance you have the entire stack traces for these errors? Without having the full stack trace it's not possible to know where exactly these errors are coming from. Any additional information will be helpful.

@Shazwazza Here is a different stack trace for the insert duplicate key row

System.Data.SqlClient.SqlException (0x80131904): Cannot insert duplicate key row in object 'dbo.umbracoPropertyData' with unique index 'IX_umbracoPropertyData_VersionId'. The duplicate key value is (29898, 50, <NULL>, <NULL>).  The statement has been terminated.     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.SqlDataReader.TryConsumeMetaData()     at System.Data.SqlClient.SqlDataReader.get_MetaData()     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.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)     at System.Data.SqlClient.SqlCommand.ExecuteScalar()     at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func`1 func) in d:\a\1\s\src\Umbraco.Core\Persistence\FaultHandling\RetryPolicy.cs:line 172     at NPoco.Database.ExecuteScalarHelper(DbCommand cmd)     at NPoco.Database.InsertImp[T](PocoData pocoData, String tableName, String primaryKeyName, Boolean autoIncrement, T poco)     at NPoco.Database.Insert[T](String tableName, String primaryKeyName, Boolean autoIncrement, T poco)     at NPoco.Database.Insert[T](T poco)     at Umbraco.Core.Persistence.Repositories.Implement.MemberRepository.PersistUpdatedItem(IMember entity) in d:\a\1\s\src\Umbraco.Core\Persistence\Repositories\Implement\MemberRepository.cs:line 392     at Umbraco.Core.Cache.DefaultRepositoryCachePolicy`2.Update(TEntity entity, Action`1 persistUpdated) in d:\a\1\s\src\Umbraco.Core\Cache\DefaultRepositoryCachePolicy.cs:line 128     at Umbraco.Core.Services.Implement.MemberService.Save(IMember member, Boolean raiseEvents) in d:\a\1\s\src\Umbraco.Core\Services\Implement\MemberService.cs:line 839     at UmbracoGC.Services.Member.GrandCentralMemberService.SavePreferredResort(IMember Member, Site Site) in C:\agent\_work\5\s\UmbracoGC\Services\Member\GrandCentralMemberService.cs:line 183  ClientConnectionId:1771512b-5bd2-461d-beea-64aa9f47b9a8  Error Number:2601,State:1,Class:14

This is coming about when we are trying to update a property on a member. Here is our relevant code:

                var jsonResort = JsonConvert.SerializeObject(new List<string>() { Site.ToString() });
                Member.SetValue(siteValues.PreferredResortMemberPropertyAlias, jsonResort);
                serviceContext.MemberService.Save(Member);

FYI I am going on holiday for the next two weeks, but my colleague may chime in here in my absence.

@TimZander I believe there's a couple of variants of script allowing you to delete the versions but I'm not aware of which ones are most current and if any of them allows setting a date as well. There's also mentions of Unversion in here - I'd prolly recommend using that one instead of running scripts. As always .. please do a database backup before attempting any of this - just in case. https://our.umbraco.com/forum/umbraco-8/96498-delete-old-versions

Thank you, my colleague will be setting this up in the next two weeks while I am on holiday. If he does not update with results I will give an update on my return

@Shazwazza

Here is another example

System.Data.SqlClient.SqlException: Cannot insert duplicate key row in object 'dbo.umbracoPropertyData' with unique index 'IX_umbracoPropertyData_VersionId'. The duplicate key value is (29896, 50, <NULL>, <NULL>).  The statement has been terminated.     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.SqlDataReader.TryConsumeMetaData()     at System.Data.SqlClient.SqlDataReader.get_MetaData()     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.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)     at System.Data.SqlClient.SqlCommand.ExecuteScalar()     at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func`1 func) in d:\a\1\s\src\Umbraco.Core\Persistence\FaultHandling\RetryPolicy.cs:line 172     at NPoco.Database.ExecuteScalarHelper(DbCommand cmd)     at NPoco.Database.InsertImp[T](PocoData pocoData, String tableName, String primaryKeyName, Boolean autoIncrement, T poco)     at NPoco.Database.Insert[T](String tableName, String primaryKeyName, Boolean autoIncrement, T poco)     at NPoco.Database.Insert[T](T poco)     at Umbraco.Core.Persistence.Repositories.Implement.MemberRepository.PersistUpdatedItem(IMember entity) in d:\a\1\s\src\Umbraco.Core\Persistence\Repositories\Implement\MemberRepository.cs:line 392     at Umbraco.Core.Cache.DefaultRepositoryCachePolicy`2.Update(TEntity entity, Action`1 persistUpdated) in d:\a\1\s\src\Umbraco.Core\Cache\DefaultRepositoryCachePolicy.cs:line 128     at Umbraco.Core.Services.Implement.MemberService.Save(IMember member, Boolean raiseEvents) in d:\a\1\s\src\Umbraco.Core\Services\Implement\MemberService.cs:line 839     at UmbracoGC.Services.Member.RecoveryService.<RecoverPasswordRequest>d__5.MoveNext() in C:\agent\_work\5\s\UmbracoGC\Services\Member\RecoveryService.cs:line 91  --- 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 UmbracoGC.Controllers.Authentication.RecoveryController.<RequestPasswordReset>d__4.MoveNext() in C:\agent\_work\5\s\UmbracoGC\Controllers\Authentication\RecoveryController.cs:line 50  --- 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.Web.Mvc.Async.TaskAsyncActionDescriptor.EndExecute(IAsyncResult asyncResult)     at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass8_0.<BeginInvokeAsynchronousActionMethod>b__1(IAsyncResult asyncResult)     at System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeActionMethod(IAsyncResult asyncResult)     at System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<>c__DisplayClass11_0.<InvokeActionMethodFilterAsynchronouslyRecursive>b__0()     at System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<>c__DisplayClass11_2.<InvokeActionMethodFilterAsynchronouslyRecursive>b__2()     at System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<>c__DisplayClass11_2.<InvokeActionMethodFilterAsynchronouslyRecursive>b__2()     at System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<>c__DisplayClass11_2.<InvokeActionMethodFilterAsynchronouslyRecursive>b__2()     at System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<>c__DisplayClass11_2.<InvokeActionMethodFilterAsynchronouslyRecursive>b__2()     at System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<>c__DisplayClass11_2.<InvokeActionMethodFilterAsynchronouslyRecursive>b__2()     at System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<>c__DisplayClass11_2.<InvokeActionMethodFilterAsynchronouslyRecursive>b__2()     at System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<>c__DisplayClass11_2.<InvokeActionMethodFilterAsynchronouslyRecursive>b__2()     at System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeActionMethodWithFilters(IAsyncResult asyncResult)     at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass3_6.<BeginInvokeAction>b__4()     at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass3_1.<BeginInvokeAction>b__1(IAsyncResult asyncResult)

and the relevant code:

var guid = Guid.NewGuid().ToString();
            member.SetValue(siteValues.PasswordResetSentMemberPropertyAlias, DateTime.Now);
            member.SetValue(siteValues.PasswordResetEmailCodeMemberPropertyAlias, guid);
            memberService.Save(member);

I should note that we have not removed our member caching mechanism yet, could this be caused by calling Save() on an out of date Member object? Perhaps our member caching has caused more issues that it may have hoped to clear up.

Hi thanks for the info. The errors regarding duplicate keys aren't related to the changes I've made, however they could be yielding a different issue all together.

I should note that we have not removed our member caching mechanism yet, could this be caused by calling Save() on an out of date Member object? Perhaps our member caching has caused more issues that it may have hoped to clear up.

This could very well be part of the reason for this issue since it could be trying to insert a value for the same cached member version. I'll have to run some tests and see how to replicate this new issue.

However there was 2 other errors you posted above which I'm interesting in to see if we can get full stack traces for those:

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

and

System.Data.SqlClient.SqlException (0x80131904): Lock request time out period exceeded.

since those could be related to the changes I've made and need to figure out if that is the case or if these are separate issues.

Any info is appreciated, thanks!

@Shazwazza

Here is the full System.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired stack trace:


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.SqlDataReader.TryConsumeMetaData()
   at System.Data.SqlClient.SqlDataReader.get_MetaData()
   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.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteScalar()
   at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func`1 func) in d:\a\1\s\src\Umbraco.Core\Persistence\FaultHandling\RetryPolicy.cs:line 172
   at NPoco.Database.ExecuteScalarHelper(DbCommand cmd)
   at NPoco.Database.InsertImp[T](PocoData pocoData, String tableName, String primaryKeyName, Boolean autoIncrement, T poco)
   at NPoco.Database.Insert[T](String tableName, String primaryKeyName, Boolean autoIncrement, T poco)
   at NPoco.Database.Insert[T](T poco)
ClientConnectionId:b8e31fb3-284b-4c34-b783-62d951ec39fb
Error Number:-2,State:0,Class:11

@Shazwazza

And System.Data.SqlClient.SqlException (0x80131904): Lock request time out period exceeded:


System.Data.SqlClient.SqlException (0x80131904): Lock request time out period exceeded.
The statement has been terminated.
   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 Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func`1 func) in d:\a\1\s\src\Umbraco.Core\Persistence\FaultHandling\RetryPolicy.cs:line 172
   at NPoco.Database.ExecuteNonQueryHelper(DbCommand cmd)
   at NPoco.Database.Execute(String sql, CommandType commandType, Object[] args)
   at Umbraco.Core.Persistence.SqlSyntax.SqlServerSyntaxProvider.WriteLock(IDatabase db, TimeSpan timeout, Int32[] lockIds) in d:\a\1\s\src\Umbraco.Core\Persistence\SqlSyntax\SqlServerSyntaxProvider.cs:line 269
   at Umbraco.Core.Services.Implement.MemberService.Save(IMember member, Boolean raiseEvents) in d:\a\1\s\src\Umbraco.Core\Services\Implement\MemberService.cs:line 837
   at Umbraco.Web.Security.Providers.UmbracoMembershipProvider`2.PerformValidateUser(String username, String password) in d:\a\1\s\src\Umbraco.Web\Security\Providers\UmbracoMembershipProvider.cs:line 602
   at UmbracoGC.Libs.CustomerMembership.BGVMemberMembershipProvider.ValidateUser(String username, String password) in C:\agent\_work\5\s\UmbracoGC\Libs\CustomMembership\BGVMemberMembershipProvider.cs:line 18
   at Umbraco.Web.Security.MembershipHelper.Login(String username, String password) in d:\a\1\s\src\Umbraco.Web\Security\MembershipHelper.cs:line 260
   at UmbracoGC.Services.Member.GrandCentralMemberService.LogIn(LoginViewModel LoginModel) in C:\agent\_work\5\s\UmbracoGC\Services\Member\GrandCentralMemberService.cs:line 67
ClientConnectionId:21faf470-bda9-4874-a665-2bc0aa415677
Error Number:1222,State:51,Class:16

@Shazwazza I am working on removing our custom member caching mechanism and will release. I'll update when that's done and I have something to report.

Another update here. I have pushed a new fix/build that you can try out. I think part of the problem is due to the way the last login value is stored and how I was trying to update it. The last login date is based on the umbracoPropertyData table and acts just like a normal cms property since it's not stored directly on the member table. This original fix was to update the single property value in this table for the last login date without taking an explicit write lock (which was resulting in the lock timeout) but I realize now that's not actually possible due to the way this data is changed when a member is Saved normally. When a member is saved normally, the property data was cleared and then re-inserted. This will work ok so long as any transaction modifying that data takes an explicit write lock but we don't want to do that in this case. So I've modified the code:

We still don't take an explicit write lock for setting the last login date but we update the property value based on an SQL select with an update lock hint
Modified the member repository to do a Select/Update with an update lock hint instead of a Delete/Insert

This is potentially why you were seeing the duplicate key exception since it's possible that 2 or more transactions were attempting to both update, delete and insert the same data.

Would you also be able to tell me the result of this query on your live site if possible since it would be interesting to know what property type is ID 50 which is the one listed in your stack traces

SELECT * FROM cmsPropertyType WHERE id = 50

Here's the new build with artifacts: https://dev.azure.com/umbraco/Umbraco%20Cms/_build/results?buildId=45666&view=results

The changes for this are these revs:

Thanks for the info @unaligned, regarding that latest stack trace where the order of execution is:

at Umbraco.Core.Services.Implement.MemberService.Save(IMember member, Boolean raiseEvents) in d:\a\1\s\src\Umbraco.Core\Services\Implement\MemberService.cs:line 837
   at Umbraco.Web.Security.Providers.UmbracoMembershipProvider`2.PerformValidateUser(String username, String password) in d:\a\1\s\src\Umbraco.Web\Security\Providers\UmbracoMembershipProvider.cs:line 602
   at UmbracoGC.Libs.CustomerMembership.BGVMemberMembershipProvider.ValidateUser(String username, String password) in C:\agent\_work\5\s\UmbracoGC\Libs\CustomMembership\BGVMemberMembershipProvider.cs:line 18
   at Umbraco.Web.Security.MembershipHelper.Login(String username, String password) in d:\a\1\s\src\Umbraco.Web\Security\MembershipHelper.cs:line 260
   at UmbracoGC.Services.Member.GrandCentralMemberService.LogIn(LoginViewModel LoginModel) in C:\agent\_work\5\s\UmbracoGC\Services\Member\GrandCentralMemberService.cs:line 67

That also seems peculiar since I'm unsure why the member is being Saved when just validating the login. Now that I look at this code in the core i can see this is a cause for lock contention too. In the MembershipHelper.Login method it calls provider.ValidateUser(username, password) which goes into UmbracoMembershipProvider.PerformValidateUser and in some cases can update a member if things like failed password attempts needs to be adjusted. However, in UmbracoMembershipProvider.PerformValidateUser this seems to always update the member everytime this method passes which I don't believe is correct because if that passes and the password attempts don't need to be updated I don't think this method needs to set the LastLoginDate because MembershipHelper.Login does that explicitly just after this call in provider.GetUser(username, true).

I will make some additional code changes since this is definitely going to cause more DB calls and lock requests than is necessary. I'll post an update on that soon.

I have pushed another update, the build output and artifacts are here https://dev.azure.com/umbraco/Umbraco%20Cms/_build/results?buildId=45672&view=results

This reduces the update queries and locks for logging in a member which means less lock contention and better throughput. The change for that is this rev: https://github.com/umbraco/Umbraco-CMS/pull/8525/commits/9fc3699a48c9f2e60e51110037ae8bb823a853f9

The new internal member cache should be sufficient for you without you having to cache your own members. Essentially it just means that any calls to IMemberService.GetByUsername is cached. This method is used for all login and authentication logic.

@Shazwazza

The result for this query:

SELECT * FROM cmsPropertyType WHERE id = 50

is the umbracoMemberLastLogin property.

@unaligned thanks! that's what I hoped/expected.

Hi @unaligned let me know if you get a chance to test that last build and any outcomes. Thanks!

@Shazwazza I've been reluctant to put this change into our production environment as an unofficial release, and we haven't been able to replicate the issues in a staging environment.

Have these already made it into the master branch? And if so, when would you expect to see them in a Nuget release?

@unaligned We are depending on people trying out these updates on their environments as they are impossible for us to replicate. We're doing everything we can to make this a safe update, there's additional unit tests, etc. But before we put it into a release we'd love to know if it has the intended effect.

As to your question, not to be flippant but.. we expect to see them in a NuGet release as soon as we can get some real-life testing done. 🙂

@nul800sebastiaan I figured that might be the case, just figured I'd ask the question.

@Shazwazza I've been testing this in a staging environment, and no longer see the errors present or other issues. However, I was not able to replicate the errors in the staging environment previously so that doesn't tell me anything. I'll look into promoting the build to our production server.

@Shazwazza

I just released this in our production environment because we were seeing significant numbers of errors this morning, and it was affecting the backoffice. Things seem be be working more smoothly, but I have another error to report. See stack trace below.



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.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at System.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)
   at System.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()
   at System.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()
   at System.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()
   at System.Data.SqlClient.TdsParserStateObject.TryReadByte(Byte& value)
   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 System.Data.SqlClient.SqlConnection.BeginDbTransaction(IsolationLevel isolationLevel)
   at StackExchange.Profiling.Data.ProfiledDbConnection.BeginDbTransaction(IsolationLevel isolationLevel) in C:\projects\dotnet\src\MiniProfiler.Shared\Data\ProfiledDbConnection.cs:line 138
   at NPoco.Database.BeginTransaction(IsolationLevel isolationLevel)
   at Umbraco.Core.Scoping.Scope.get_Database() in d:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 242
   at Umbraco.Core.Persistence.Repositories.Implement.UserRepository.ValidateLoginSession(Int32 userId, Guid sessionId) in d:\a\1\s\src\Umbraco.Core\Persistence\Repositories\Implement\UserRepository.cs:line 202
   at Umbraco.Core.Services.Implement.UserService.ValidateLoginSession(Int32 userId, Guid sessionId) in d:\a\1\s\src\Umbraco.Core\Services\Implement\UserService.cs:line 549
   at Umbraco.Core.Security.BackOfficeUserStore.ValidateSessionIdAsync(Int32 userId, String sessionId) in d:\a\1\s\src\Umbraco.Core\Security\BackOfficeUserStore.cs:line 780
   at Umbraco.Web.Security.BackOfficeUserManager`1.<ValidateSessionIdAsync>d__11.MoveNext() in d:\a\1\s\src\Umbraco.Web\Security\BackOfficeUserManager.cs:line 246
--- 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 Umbraco.Web.Security.SessionIdValidator.<ValidateSessionAsync>d__2.MoveNext() in d:\a\1\s\src\Umbraco.Web\Security\SessionIdValidator.cs:line 100
--- 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 Umbraco.Web.Security.SessionIdValidator.<ValidateSessionAsync>d__1.MoveNext() in d:\a\1\s\src\Umbraco.Web\Security\SessionIdValidator.cs:line 36
--- 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 Umbraco.Web.Security.BackOfficeCookieAuthenticationProvider.<EnsureValidSessionId>d__7.MoveNext() in d:\a\1\s\src\Umbraco.Web\Security\BackOfficeCookieAuthenticationProvider.cs:line 119
--- 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 Umbraco.Web.Security.BackOfficeCookieAuthenticationProvider.<ValidateIdentity>d__6.MoveNext() in d:\a\1\s\src\Umbraco.Web\Security\BackOfficeCookieAuthenticationProvider.cs:line 102
--- 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 Microsoft.Owin.Security.Cookies.CookieAuthenticationHandler.<AuthenticateCoreAsync>d__12.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 Microsoft.Owin.Security.Infrastructure.AuthenticationHandler.<BaseInitializeAsync>d__31.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 Microsoft.Owin.Security.Infrastructure.AuthenticationMiddleware`1.<Invoke>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 Microsoft.Owin.Security.Infrastructure.AuthenticationMiddleware`1.<Invoke>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 Kentor.OwinCookieSaver.KentorOwinCookieSaverMiddleware.<Invoke>d__2.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 Microsoft.AspNet.Identity.Owin.IdentityFactoryMiddleware`2.<Invoke>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 Microsoft.AspNet.Identity.Owin.IdentityFactoryMiddleware`2.<Invoke>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 Microsoft.Owin.Host.SystemWeb.IntegratedPipeline.IntegratedPipelineContextStage.<RunApp>d__7.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 Microsoft.Owin.Host.SystemWeb.IntegratedPi
```peline.IntegratedPipelineContext.<DoFinalWork>d__12.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at Microsoft.Owin.Host.SystemWeb.IntegratedPipeline.StageAsyncResult.End(IAsyncResult ar)
   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)
ClientConnectionId:4d8e33b9-e3ba-4c7b-b529-56c462d2f851
Error Number:-2,State:0,Class:11

And I'm also still getting some lock request timeouts:


System.Data.SqlClient.SqlException (0x80131904): Lock request time out period exceeded.
The statement has been terminated.
   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 Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func`1 func) in d:\a\1\s\src\Umbraco.Core\Persistence\FaultHandling\RetryPolicy.cs:line 172
   at NPoco.Database.ExecuteNonQueryHelper(DbCommand cmd)
   at NPoco.Database.Execute(String sql, CommandType commandType, Object[] args)
ClientConnectionId:491eeb73-6557-4859-8e7b-3f7c873883e8
Error Number:1222,State:51,Class:16

Thanks @unaligned, that is fairly good news

regarding these errors:

Things seem be be working more smoothly, but I have another error to report. See stack trace below.

This one is strange since this isn't a lock timeout, this is an query SQL timeout originating from user lookups

 at Umbraco.Core.Persistence.Repositories.Implement.UserRepository.ValidateLoginSession(Int32 userId, Guid sessionId) in d:\a\1\s\src\Umbraco.Core\Persistence\Repositories\Implement\UserRepository.cs:line 202
   at Umbraco.Core.Services.Implement.UserService.ValidateLoginSession(Int32 userId, Guid sessionId) in d:\a\1\s\src\Umbraco.Core\Services\Implement\UserService.cs:line 549

Are you able to tell me how many rows you have in your umbracoUserLogin table?

And I'm also still getting some lock request timeouts:

Do you have the full stack trace of where this query is originating? I mentioned before above (https://github.com/umbraco/Umbraco-CMS/issues/8433#issuecomment-666147491) that the lock timeouts in some cases won't be preventable. These SQL locks are used as distributed locks (like c# locks but distributed and with timeouts as to not lock indefinitely). There's probably more places to reduce the contention for these locks like I've been doing with all of the above changes which will help but to do that I need to know where the lock contentions are originating.

@Shazwazza We have 9313 records in the umbracoUserLogin table. That is backoffice users, correct? That seems strange to me. We definitely do not have that many employees we've given backoffice access.

Edit: Oh I see, they're sessions, not user records.

@unaligned those are use login sessions, they are kept for 15 days. Anytime a new user login session is created old ones are purged that are 15 days old. You could double check that is occurring and see if all records in that table aren't older than 15 days? That isn't an enormous amount of records to do a query against and the query is done against the PK so the query is fast, I was just wondering if there was somehow an enormous amount of records in there resulting in a query timeout. I've debugged this query locally and there's no real way to improve the query performance since it's a very simple query against the PK of the table.

Hi @unaligned + @TimZander,

Do you have any updates on how your site is working with all of these fixes applied? Are you continually seeing the same errors and if so do you have any info on replication steps and stack traces?

Thanks!

Hi @Shazwazza we are still seeing some issues with lock request time out exceeded. I am including the most verbose logs we have of those exceptions

{"@t":"2020-08-31T15:34:08.0496669Z","@mt":"Exception ({InstanceId}).","@l":"Error","@x":"System.Data.SqlClient.SqlException (0x80131904): Lock request time out period exceeded.\r\nThe statement has been terminated.\r\n   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)\r\n   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)\r\n   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)\r\n   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted)\r\n   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)\r\n   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)\r\n   at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)\r\n   at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()\r\n   at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func`1 func) in d:\\a\\1\\s\\src\\Umbraco.Core\\Persistence\\FaultHandling\\RetryPolicy.cs:line 172\r\n   at NPoco.Database.ExecuteNonQueryHelper(DbCommand cmd)\r\n   at NPoco.Database.Execute(String sql, CommandType commandType, Object[] args)\r\nClientConnectionId:77132367-34ca-4846-8088-1c844d5de18b\r\nError Number:1222,State:51,Class:16","InstanceId":"b64576be","SourceContext":"Umbraco.Core.Persistence.UmbracoDatabase","ProcessId":10636,"ProcessName":"w3wp","ThreadId":46,"AppDomainId":2,"AppDomainAppId":"LMW3SVC1ROOT","MachineName":"GRANDCENTRAL01","Log4NetLevel":"ERROR","HttpSessionId":"33uby3rcymz1ekch5tbznsae","HttpRequestNumber":53,"HttpRequestId":"884f84c6-f174-434e-a41d-c958889ab4a4"}

Also the issue with duplicate key insert

{"@t":"2020-08-31T15:34:52.5922740Z","@mt":"Exception ({InstanceId}).","@l":"Error","@x":"System.Data.SqlClient.SqlException (0x80131904): Cannot insert duplicate key row in object 'dbo.umbracoPropertyData' with unique index 'IX_umbracoPropertyData_VersionId'. The duplicate key value is (9922, 46, <NULL>, <NULL>).\r\nThe statement has been terminated.\r\n   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)\r\n   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)\r\n   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)\r\n   at System.Data.SqlClient.SqlDataReader.TryConsumeMetaData()\r\n   at System.Data.SqlClient.SqlDataReader.get_MetaData()\r\n   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted)\r\n   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)\r\n   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)\r\n   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)\r\n   at System.Data.SqlClient.SqlCommand.ExecuteScalar()\r\n   at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func`1 func) in d:\\a\\1\\s\\src\\Umbraco.Core\\Persistence\\FaultHandling\\RetryPolicy.cs:line 172\r\n   at NPoco.Database.ExecuteScalarHelper(DbCommand cmd)\r\n   at NPoco.Database.InsertImp[T](PocoData pocoData, String tableName, String primaryKeyName, Boolean autoIncrement, T poco)\r\nClientConnectionId:5c390dfc-c81f-40c3-bcb6-befb2445f97e\r\nError Number:2601,State:1,Class:14","InstanceId":"2e24c5c7","SourceContext":"Umbraco.Core.Persistence.UmbracoDatabase","ProcessId":10636,"ProcessName":"w3wp","ThreadId":39,"AppDomainId":2,"AppDomainAppId":"LMW3SVC1ROOT","MachineName":"GRANDCENTRAL01","Log4NetLevel":"ERROR","HttpSessionId":"33uby3rcymz1ekch5tbznsae","HttpRequestNumber":58,"HttpRequestId":"31fbb6cd-21f2-4603-83ab-c010142849df"}

{"@t":"2020-08-31T16:00:23.0356256Z","@mt":"Exception ({InstanceId}).","@l":"Error","@x":"System.Data.SqlClient.SqlException (0x80131904): Lock request time out period exceeded.\r\nThe statement has been terminated.\r\n   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)\r\n   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)\r\n   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)\r\n   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted)\r\n   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)\r\n   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)\r\n   at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)\r\n   at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()\r\n   at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func`1 func) in d:\\a\\1\\s\\src\\Umbraco.Core\\Persistence\\FaultHandling\\RetryPolicy.cs:line 172\r\n   at NPoco.Database.ExecuteNonQueryHelper(DbCommand cmd)\r\n   at NPoco.Database.Execute(String sql, CommandType commandType, Object[] args)\r\nClientConnectionId:fbcab53c-4a0a-4b73-8102-baa45fbe9cd4\r\nError Number:1222,State:51,Class:16","InstanceId":"28732756","SourceContext":"Umbraco.Core.Persistence.UmbracoDatabase","ProcessId":10636,"ProcessName":"w3wp","ThreadId":72,"AppDomainId":2,"AppDomainAppId":"LMW3SVC1ROOT","MachineName":"GRANDCENTRAL01","Log4NetLevel":"ERROR","HttpSessionId":"ycbcpw5lqxigckhstxc1ugyz","HttpRequestNumber":164,"HttpRequestId":"25d187fc-091c-4ae5-8854-d5d2ce8f8bd0"}

{"@t":"2020-08-31T16:02:09.1579859Z","@mt":"Exception ({InstanceId}).","@l":"Error","@x":"System.Data.SqlClient.SqlException (0x80131904): Lock request time out period exceeded.\r\nThe statement has been terminated.\r\n   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)\r\n   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)\r\n   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)\r\n   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted)\r\n   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)\r\n   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)\r\n   at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)\r\n   at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()\r\n   at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func`1 func) in d:\\a\\1\\s\\src\\Umbraco.Core\\Persistence\\FaultHandling\\RetryPolicy.cs:line 172\r\n   at NPoco.Database.ExecuteNonQueryHelper(DbCommand cmd)\r\n   at NPoco.Database.Execute(String sql, CommandType commandType, Object[] args)\r\nClientConnectionId:34f88ce1-b7cb-4e0b-9101-6b706fce8c27\r\nError Number:1222,State:51,Class:16","InstanceId":"50264da6","SourceContext":"Umbraco.Core.Persistence.UmbracoDatabase","ProcessId":10636,"ProcessName":"w3wp","ThreadId":49,"AppDomainId":2,"AppDomainAppId":"LMW3SVC1ROOT","MachineName":"GRANDCENTRAL01","Log4NetLevel":"ERROR","HttpSessionId":"2writq0wdl3zpqeykeus33ff","HttpRequestNumber":172,"HttpRequestId":"01a8cae7-b04f-4ad3-b08e-95e748f1d98f"}

At times it is from where we are calling member.save()

{"@t":"2020-08-31T16:03:07.4940758Z","@mt":"Exception ({InstanceId}).","@l":"Error","@x":"System.Data.SqlClient.SqlException (0x80131904): Lock request time out period exceeded.\r\nThe statement has been terminated.\r\n   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)\r\n   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)\r\n   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)\r\n   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted)\r\n   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)\r\n   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)\r\n   at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)\r\n   at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()\r\n   at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func`1 func) in d:\\a\\1\\s\\src\\Umbraco.Core\\Persistence\\FaultHandling\\RetryPolicy.cs:line 172\r\n   at NPoco.Database.ExecuteNonQueryHelper(DbCommand cmd)\r\n   at NPoco.Database.Execute(String sql, CommandType commandType, Object[] args)\r\n   at Umbraco.Core.Persistence.SqlSyntax.SqlServerSyntaxProvider.WriteLock(IDatabase db, TimeSpan timeout, Int32[] lockIds) in d:\\a\\1\\s\\src\\Umbraco.Core\\Persistence\\SqlSyntax\\SqlServerSyntaxProvider.cs:line 269\r\n   at Umbraco.Core.Services.Implement.MemberService.Save(IMember member, Boolean raiseEvents) in d:\\a\\1\\s\\src\\Umbraco.Core\\Services\\Implement\\MemberService.cs:line 837\r\n   at UmbracoGC.Services.Member.GrandCentralMemberService.SavePreferredResort(IMember Member, Site Site) in C:\\agent\\_work\\5\\s\\UmbracoGC\\Services\\Member\\GrandCentralMemberService.cs:line 176\r\nClientConnectionId:e3996513-6ec4-4eff-bc82-33de7fe3992d\r\nError Number:1222,State:51,Class:16","InstanceId":"4b3d6b98","SourceContext":"Umbraco.Core.Persistence.UmbracoDatabase","ProcessId":10636,"ProcessName":"w3wp","ThreadId":55,"AppDomainId":2,"AppDomainAppId":"LMW3SVC1ROOT","MachineName":"GRANDCENTRAL01","Log4NetLevel":"ERROR","HttpSessionId":"gdmrzssr10mkjb3431wzxy1c","HttpRequestNumber":180,"HttpRequestId":"7eb83bbf-2806-4bab-a69a-6464bd7349de"}

The offending code from above is as follows:

                var jsonResort = JsonConvert.SerializeObject(new List<string>() { Site.ToString() });
                Member.SetValue(siteValues.PreferredResortMemberPropertyAlias, jsonResort);
                serviceContext.MemberService.Save(Member);

Thanks @TimZander ,

Are you getting less errors with the changes done so far?

Some additional questions:

When you say "At times it is from where we are calling member.save()" How often are you saving members?
Are you performing member saving multiple times in single operations in your code? I'm asking this because it's possible to wrap multiple service Save calls in a single transaction which can be done with explicit Scopes which may make sense for you depending on your needs

I will re-visit the duplicate key issue and will look to change the lock timeout period (configurable) since it is quite low.

@Shazwazza good suggestion, I'm going to take a deeper look at where and under what circumstances we are saving members.

As a general rule we are rarely(but sometimes) saving members automatically, more often we are saving members when a user changes a property on the member such as contact phone number.

And yes, we are getting significantly less error counts than prior to the changes

umbraco / Umbraco-CMS