search

umbraco / Umbraco-CMS

Umbraco is a free and open source .NET content management system helping you deliver delightful digital experiences.
https://umbraco.com
Other
4.49k stars 2.69k forks source link

Scheduled publish fails when multiple pages are published - Umbraco 8.6.1 #8030

Closed KevinJump closed 4 years ago

KevinJump commented 4 years ago

Scheduled publishing can fail when publishing multiple pages at the same time.

Umbraco version

I am seeing this issue on Umbraco version: 8.6.1

Reproduction

If you set multiple pages (in testing approx. 10-20 seems do it) to have the same scheduled publish date, then when that date arrives not all items will be published. and scope errors (below) will be reported in the log.

Specifics

It looks like its an issue with the Scope while running in a background task, but i am at a loss to see what it should be doing 😞

Steps to reproduce

  1. New Umbraco Install - (With standard starter key, SQLCE DB)
  2. Schedule the individual pages in the starter kit to publish at the same time (takes about 5-10 mins to do, so pick a time-date that gives you time to go through the site).
  3. Wait for publish
  4. Look through logs. should see the errors below:

Expected result

All pages should be published.

Actual result

Some pages are published, but the background process stops at some point with an error: 

System.AggregateException: Exceptions were thrown by listed actions. ---> System.NullReferenceException: Object reference not set to an instance of an object.
   at Umbraco.Core.Scoping.Scope.<>c__DisplayClass71_0.<RobustExit>b__2() in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 437
   at Umbraco.Core.Scoping.Scope.TryFinally(Int32 index, Action[] actions) in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 472
   at Umbraco.Core.Scoping.Scope.TryFinally(Int32 index, Action[] actions) in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 476
   at Umbraco.Core.Scoping.Scope.TryFinally(Int32 index, Action[] actions) in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 476
   at Umbraco.Core.Scoping.Scope.RobustExit(Boolean completed, Boolean onException) in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 420
   at Umbraco.Core.Scoping.Scope.DisposeLastScope() in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 400
   at Umbraco.Core.Scoping.Scope.Dispose() in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 363
   at Umbraco.Core.Services.Implement.UserService.GetUserById(Int32 id) in D:\a\1\s\src\Umbraco.Core\Services\Implement\UserService.cs:line 714
   at Umbraco.Core.Services.Implement.UserService.GetProfileById(Int32 id) in D:\a\1\s\src\Umbraco.Core\Services\Implement\UserService.cs:line 670
   at Umbraco.Core.ContentExtensions.GetWriterProfile(IContent content, IUserService userService) in D:\a\1\s\src\Umbraco.Core\ContentExtensions.cs:line 262
   at Umbraco.Examine.ContentValueSetBuilder.<GetValueSets>d__3.MoveNext() in D:\a\1\s\src\Umbraco.Examine\ContentValueSetBuilder.cs:line 43
   at System.Linq.Enumerable.WhereEnumerableIterator`1.MoveNext()
   at System.Linq.Lookup`2.Create[TSource](IEnumerable`1 source, Func`2 keySelector, Func`2 elementSelector, IEqualityComparer`1 comparer)
   at System.Linq.GroupedEnumerable`3.GetEnumerator()
   at System.Linq.Buffer`1..ctor(IEnumerable`1 source)
   at System.Linq.OrderedEnumerable`1.<GetEnumerator>d__1.MoveNext()
   at Umbraco.Examine.UmbracoContentIndex.PerformIndexItems(IEnumerable`1 values, Action`1 onComplete) in D:\a\1\s\src\Umbraco.Examine\UmbracoContentIndex.cs:line 87
   at Examine.Providers.BaseIndexProvider.IndexItems(IEnumerable`1 values) in C:\projects\examine-qvx04\src\Examine\Providers\BaseIndexProvider.cs:line 76

N.B for the above this error goes through the UserService - but I have also seen it in the PublicAccess service - I think DisposeLastScope is the issue?

before this error - there will usually be two scope warnings...

Missed "ScopeContext" Object "4c4688a1"

e.g

image

--

KevinJump commented 4 years ago

Not sure but It might be related ? https://github.com/umbraco/Umbraco-CMS/pull/7994 that too is about scopes and background threads ?

Shazwazza commented 4 years ago

Yep! that is exactly why this is happening. It's the exact same issue. Any background task that is performing any DB interaction with the services must use an explicit Scope, else an ambient CallContext scope will be used which will have problems if there is multi-threading going on in that CallContext.

In this case its while examine is indexing things and it calls into the ValueSetBuilder. In cases where the user's cache is expired it will make a DB query to get the user but in certain situations this will cause problems because the value set builder wasn't using an explicit Scope. This is fixed in https://github.com/umbraco/Umbraco-CMS/pull/7994 along with a small perf enhancement.

mzajkowski commented 3 years ago

@Shazwazza I thought it'll be gone with the recent upgrade, but we're seeing the same issue in 8.9.1 on our LB setup. It's seen on both replicas and it's causing the weird indexing issues (completely random). Any thoughts on how to get it sorted or at least stabilized?

System.NullReferenceException: Object reference not set to an instance of an object.
   at Umbraco.Core.Scoping.Scope.<>c__DisplayClass71_0.<RobustExit>b__2() in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 437
   at Umbraco.Core.Scoping.Scope.TryFinally(Int32 index, Action[] actions) in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 472
   at Umbraco.Core.Scoping.Scope.TryFinally(Int32 index, Action[] actions) in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 476
   at Umbraco.Core.Scoping.Scope.TryFinally(Int32 index, Action[] actions) in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 476
   at Umbraco.Core.Scoping.Scope.RobustExit(Boolean completed, Boolean onException) in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 420
   at Umbraco.Core.Scoping.Scope.Dispose() in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 363
   at Umbraco.Core.Services.Implement.PublicAccessService.GetEntryForContent(String contentPath) in D:\a\1\s\src\Umbraco.Core\Services\Implement\PublicAccessService.cs:line 71
   at Umbraco.Core.Services.Implement.PublicAccessService.IsProtected(String contentPath) in D:\a\1\s\src\Umbraco.Core\Services\Implement\PublicAccessService.cs:line 99
   at Umbraco.Examine.ContentValueSetValidator.ValidateProtectedContent(String path, String category) in D:\a\1\s\src\Umbraco.Examine\ContentValueSetValidator.cs:line 56
   at Umbraco.Examine.ContentValueSetValidator.Validate(ValueSet valueSet) in D:\a\1\s\src\Umbraco.Examine\ContentValueSetValidator.cs:line 127
   at Examine.Providers.BaseIndexProvider.<IndexItems>b__12_0(ValueSet x) in C:\projects\examine-qvx04\src\Examine\Providers\BaseIndexProvider.cs:line 76
   at System.Linq.Enumerable.WhereListIterator`1.MoveNext()
   at System.Linq.Lookup`2.Create[TSource](IEnumerable`1 source, Func`2 keySelector, Func`2 elementSelector, IEqualityComparer`1 comparer)
   at System.Linq.GroupedEnumerable`3.GetEnumerator()
   at System.Collections.Generic.List`1..ctor(IEnumerable`1 collection)
   at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source)
   at Umbraco.Examine.UmbracoContentIndex.PerformIndexItems(IEnumerable`1 values, Action`1 onComplete) in D:\a\1\s\src\Umbraco.Examine\UmbracoContentIndex.cs:line 69
   at Umbraco.Web.Search.ExamineComponent.DeferedReIndexForContent.<>c__DisplayClass5_0.<Execute>b__0() in D:\a\1\s\src\Umbraco.Web\Search\ExamineComponent.cs:line 646
   at Umbraco.Web.Scheduling.BackgroundTaskRunner`1.<RunAsync>d__40.MoveNext() in D:\a\1\s\src\Umbraco.Web\Scheduling\BackgroundTaskRunner.cs:line 562

image

Shazwazza commented 3 years ago

@mzajkowski so the error only occurs on replicas? I've just looked at the code and I think I know what the problem is. The fixes previously was to make sure we don't have N+1 issues and we eagerly create all of the value sets (which use DB + Scopes) which occurs on a background thread. This fixed the issue where a scope was being used incorrectly because it was being captured within an IEnumerable. But what was overlooked is that there is also another DB + Scope usage deeper in the chain during value set validation and a call being made to PublicAccessService.GetEntryForContent. The reason this is random is because most of the time the call to PublicAccessService.GetEntryForContent will be cached but when that cache expires it needs a DB lookup and since we aren't using an explicit scope on this background thread for this operation it randomly may fail why trying to use the Ambient scope. A work around for now - though this depends if you are able to do this or not depending on your requirements - is to set SupportProtectedContent to true for the external index so this lookup doesn't occur.

I've just pushed a commit which hopefully will resolve this https://github.com/umbraco/Umbraco-CMS/pull/9441 if all tests pass you'll be able to get the artifacts from the build here https://dev.azure.com/umbraco/Umbraco%20Cms/_build/results?buildId=52214 . This is based on the dev/v8 branch. If you can test this that would be really really great and speed up a patch release for this. Sorry about this annoyance wish we had caught this DB access the first time round.

mzajkowski commented 3 years ago

Thanks for the reply @Shazwazza! Yes, the issue is logged only on replicas. Backoffice instance is free of errors.

The fix looks good. I'll try to get it tested asap. It sounds also that the workaround might be OK for this project too but we might just wait for the patch release then to fix is 'correctly'. Hopefully for good! 🤞

alanwthom commented 3 years ago

Just wanted to say that I've also been able to replicate this issue (publish content on admin server, replica servers logs show two scope warnings followed by a background task failure and content doesn't appear in replica server index) using 8.6.5 in an LB environment.

Is it possible to patch the 8.6 release as well once the fix has been tested and verified please?

kuwukus commented 2 years ago

Hello I'm also facing this issue when content is published and replicated to front end instances. Can it be resolved if we rebuild examine indexes?