Scheduled content leads to SQL error when rebuilding cache

[mcl-sz]

When the content cache needs to rebuild and content contains items that scheduled, an error occures:

2020-07-07 11:13:25.512 +02:00 [Error] Exception ("0043983c").
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, Action1 wrapCloseInAction) at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action1 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, TaskCompletionSource1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry) at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource1 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](Func1 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.List1..ctor(IEnumerable1 collection) at System.Linq.Enumerable.ToList[TSource](IEnumerable1 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:97539b75-5224-4aa9-b4be-17db9ce2629b
Error Number:1222,State:51,Class:16
2020-07-07 11:13:25.512 +02:00 [Error] Failed.
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, Action1 wrapCloseInAction) at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action1 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, TaskCompletionSource1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry) at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource1 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](Func1 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.List1..ctor(IEnumerable1 collection) at System.Linq.Enumerable.ToList[TSource](IEnumerable1 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:97539b75-5224-4aa9-b4be-17db9ce2629b
Error Number:1222,State:51,Class:16

Umbraco version

I am seeing this issue on Umbraco version: 8.6.2

Reproduction

Create a content item and set schedulingdates. Under the Settings-section rebuild the cache.

[Shazwazza]

This PR #8398 fixes an issue where the scheduled publishing mechanism was trying to take an SQL write lock on the content tree every minute (since it checks for scheduled publishing each minute) even if there was nothing scheduled. This could be problematic for other things that might be waiting for a read or write lock.

[nul800sebastiaan]

@mcl-sz 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!

[mcl-sz]

@nul800sebastiaan Thanks for sending the link to this release! We will update our test-environment tomorrow. If the test-environment has no complications then i will try to update our production-environment on mondayevening. I will let you know our testresults.

[nul800sebastiaan]

Wonderful! Look forward to hearing how it goes!

[mcl-sz]

Hi @nul800sebastiaan , we're running a little bit behind but we've updates our test environment and the error didn't occure anymore. We've also tested updating a large ammount of member profiles via the memberservice and the content-cache didn't get corrupt.
We're planning to update production with 8.6.4RC on monday.

[nul800sebastiaan]

@mcl-sz Sounds good, keep us posted!

[mcl-sz]

We've updated our production environment last monday (a week ago) and since then the error above didn't occure anymore and also the Content-cache didn't get broken anymore when a memberprofile is updated via the memberservice.
Nice work!