What happened to my “item:deleted” event?

My QA team had a deployment issue recently, where Azure DevOps failed to successfully release to a couple of servers. The reason for the failure wasn't obvious to me immediately, so here's a quick write-up for Google, in the hope it saves some other people.

The reported error

The DevOps release pipeline had failed. It was the Unicorn sync step which reported an error, but the error messages were not initially helpful:

For Google's benefit, the error is here:

2021-09-06T10:56:24.4434898Z ##[section]Starting: Run Unicorn Sync
2021-09-06T10:56:24.4576402Z ==============================================================================
2021-09-06T10:56:24.4576705Z Task         : PowerShell
2021-09-06T10:56:24.4576990Z Description  : Run a PowerShell script on Linux, macOS, or Windows
2021-09-06T10:56:24.4577248Z Version      : 2.190.0
2021-09-06T10:56:24.4577458Z Author       : Microsoft Corporation
2021-09-06T10:56:24.4577771Z Help         : https://docs.microsoft.com/azure/devops/pipelines/tasks/utility/powershell
2021-09-06T10:56:24.4578219Z ==============================================================================
2021-09-06T10:56:25.3011750Z Generating script.
2021-09-06T10:56:25.3420551Z ========================== Starting Command Output ===========================
2021-09-06T10:56:25.3660200Z ##[command]"C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe" -NoLogo -NoProfile -NonInteractive -ExecutionPolicy Unrestricted -Command ". 'C:\azagent\A1\_work\_temp\6a50dc74-9a04-4072-afd1-03306e0b3fb2.ps1'"
2021-09-06T10:56:25.6931500Z Starting Unicorn sync
2021-09-06T10:56:26.4749680Z Sync-Unicorn: Executing Sync...
2021-09-06T10:56:26.7585296Z Sync-Unicorn : Exception calling "GetResponse" with "0" argument(s): "The
2021-09-06T10:56:26.7585814Z remote server returned an error: (500) Internal Server Error."
2021-09-06T10:56:26.7586285Z At C:\azagent\A1\_work\_temp\6a50dc74-9a04-4072-afd1-03306e0b3fb2.ps1:9 char:1
2021-09-06T10:56:26.7586747Z + Sync-Unicorn -ControlPanelUrl 'https://my-server-name/un ...
2021-09-06T10:56:26.7587192Z + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
2021-09-06T10:56:26.7587616Z     + CategoryInfo          : NotSpecified: (:) [Sync-Unicorn], MethodInvocationException
2021-09-06T10:56:26.7588307Z     + FullyQualifiedErrorId : WebException,Sync-Unicorn
2021-09-06T10:56:26.7588676Z
2021-09-06T10:56:26.8984825Z ##[error]PowerShell exited with code '1'.
2021-09-06T10:56:26.9490148Z ##[section]Finishing: Run Unicorn Sync

					

But basically all it says is that there was a 500 error calling Unicorn's sync endpoint.

A better error

That's not enough to solve the problem, so I needed to get some more details. The obvious thing to try was a manual sync of Unicorn. So loaded up /unicorn.aspx and told it to sync everything. That told me two things initially: Firstly that the actual seralised items were syncing ok. And secondly that the error was actually happening during the automatic publish afterwards. It failed with this display in the UI:

Again, for Google's benefit:

Message[1]: Ensure definition type did not complete successfully. StatusCode: 500, ReasonPhrase: 'Internal Server Error', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
Cache-Control: private
Date: Mon, 06 Sep 2021 10:56:26 GMT
Server: Microsoft-IIS/8.5
X-AspNet-Version: 4.0.30319
X-Powered-By: ASP.NET
Content-Length: 7903
Content-Type: text/html; charset=utf-8
}
Source[1]: Sitecore.Xdb.Common.Web
at Sitecore.Xdb.Common.Web.Synchronous.SynchronousExtensions.SuspendContextLock[TResult](Func`1 taskFactory)
at Sitecore.ExperienceAnalytics.Core.Repositories.ReferenceData.ExperienceAnalyticsSegmentReader.GetDefinitionTypeKey()
at Sitecore.ExperienceAnalytics.Core.Repositories.ReferenceData.ExperienceAnalyticsSegmentReader.Get(Guid key, NameValueCollection readingPreferences)
at Sitecore.ExperienceAnalytics.Client.Deployment.Events.SegmentDeployedEventHandler.DeleteSegment(Item deletedItem)
at Sitecore.Events.Event.EventSubscribers.RaiseEvent(String eventName, Object[] parameters, EventResult result)

101216 11:56:26 ERROR Failed to delete the item. Item ID: {1D54ADFD-3D04-49FF-9FA1-BEC77042AE65}, database: web
Exception: System.AggregateException
Message: One or more exceptions occurred while processing the subscribers to the 'item:deleted' event.
Source: Sitecore.Kernel
at Sitecore.Events.Event.EventSubscribers.RaiseEvent(String eventName, Object[] parameters, EventResult result)
at Sitecore.Events.Event.RaiseEvent(String eventName, Object[] parameters)
at System.EventHandler`1.Invoke(Object sender, TEventArgs e)
at Sitecore.Data.Engines.EngineCommand`2.RaiseEvent[TArgs](EventHandler`1 handlers, Func`2 argsCreator)
at Sitecore.Data.Engines.EngineCommand`2.Execute()
at Sitecore.Data.Engines.DataEngine.DeleteItem(Item item)

					

That error's telling us that what actually happened was that the item:deleted event has a subscriber that connects to xDB. And that's what's failing here.

A soluition – and some facepalming

I spent a bit of time reading the errors above, before spotting this bit:

Message[1]: Ensure definition type did not complete successfully. StatusCode: 500, ReasonPhrase: 'Internal Server Error'

					

And a bit of Googling pointed me to this article: "SITECORE: SYSTEM.INVALIDOPERATIONEXCEPTION: ENSURE DEFINITION TYPE DID NOT COMPLETE SUCCESSFULLY" and the sudden realisation that this was actually really obvious...

That article points out that the message in the Sitecore logs above correlates to a message in the xConnect logs which is much more obvious:

[Error] XConnect Web Application Error: “System.ApplicationException:
Exception trying to intialize Service Collection and Provider for for WebAPI Dependency Resolver, Inner Exception:
Required license is missing: Sitecore.xDB.Base —> Sitecore.Nexus.Licensing.LicenseException: Required license is missing: Sitecore.xDB.Base

					

Hence the facepalming... This whole business was another "our company's license has expired" issue – like the Docker issues I saw recently. My colleagues had correctly updated the license file for the XM roles, but it seems they forgot to update xConnect's copy of the license file. Ooops.

But, problem solved, as everything sorted itself out when I updated that missed license file. So a big thank you to Andy Burns for the blog post that helped me here.

↑ Back to top