Twitter Image

Error 404 after publishing in MSCRM 2011

Written by Stéphane Dorrekens
Friday, 09 November 2012 10:54

Some days ago, I encountered an interesting issue.

A developper had a just upgraded CRM 2011 environment and right after publishing a change; the organisation stopped working and all he got was a 404 error.
The other organizations worked ok, but all urls pointing to the failed organization returned a 404.

I enabled the Trace on the server, and here's what I found :
>A failure occurred during the execution of the AuthenticationPipeline: System.ArgumentException: An item with the same key has already been added.
   at System.Collections.Generic.Dictionary`2.Insert(TKey key, TValue value, Boolean add)
   at Microsoft.Crm.Metadata.PreloadedMetadataCacheDataProvider.AddEntityRelationshipsToCollections(IPreloadedMetadataInitializationContext context)
   at Microsoft.Crm.Metadata.PreloadedMetadataCacheDataProvider.Initialize(IOrganizationContext organizationContext, MetadataContainer container, LoadMasks masks)
   at Microsoft.Crm.Metadata.MultiOrgSharableMetadataCacheLoader.CreateMetadataCacheDataProvider(MetadataContainer container, IOrganizationContext context, LoadMasks masks, CounterList counter)
   at Microsoft.Crm.Metadata.DynamicMetadataCacheLoader.BuildMetadataCacheFromMetadataContainer(MetadataContainer container, LoadMasks masks, IOrganizationContext context, CounterList counter)
   at Microsoft.Crm.Metadata.DynamicMetadataCacheLoader.LoadCacheFromDatabaseInternal(LoadMasks masks, CrmDbConnection connection, CrmTransaction transaction, IOrganizationContext context, CounterList counter)
   at Microsoft.Crm.Metadata.DynamicMetadataCacheLoader.LoadCacheFromDatabase(LoadMasks masks, IOrganizationContext context, CounterList counter)
   at Microsoft.Crm.Metadata.DynamicMetadataCacheFactory.LoadMetadataCache(LoadMethod method, CacheType type, IOrganizationContext context)
   at Microsoft.Crm.Metadata.MetadataCache.LoadCache(IOrganizationContext context, Boolean fileOnlyIfExists)
   at Microsoft.Crm.Metadata.MetadataCache.GetInstance(IOrganizationContext context)
   at Microsoft.Crm.BusinessEntities.BusinessEntityMoniker..ctor(Guid id, String entityName, IOrganizationContext orgContext)
   at Microsoft.Crm.Caching.UserDataCacheLoader.LoadCacheData(Guid key, ExecutionContext context)
   at Microsoft.Crm.Caching.ObjectModelCacheLoader`2.LoadCacheData(TKey key, IOrganizationContext context)
   at Microsoft.Crm.Caching.CrmMultiOrgCache`2.CreateEntry(TKey key, IOrganizationContext context)
   at Microsoft.Crm.Caching.CrmMultiOrgCache`2.LookupEntry(TKey key, IOrganizationContext context)
   at Microsoft.Crm.BusinessEntities.SecurityLibrary.GetUserInfoCommon(IOrganizationContext context, Guid userGuid, LocatorServiceContext locatorServiceContext)
   at Microsoft.Crm.BusinessEntities.SecurityLibrary.GetCallerAndBusinessGuidsFromThread(WindowsIdentity identity, Guid organizationId, LocatorServiceContext locatorServiceContext)
   at Microsoft.Crm.Authentication.CrmWindowsIdentity..ctor(WindowsIdentity innerIdentity, Boolean publishCrmUser, Guid organizationId)
   at Microsoft.Crm.Authentication.WindowsAuthenticationProviderBase.Authenticate(HttpApplication application, WindowsIdentity userIdentity)
   at Microsoft.Crm.Authentication.AuthenticationStep.Authenticate(HttpApplication application)
   at Microsoft.Crm.Authentication.AuthenticationPipeline.Authenticate(HttpApplication application)
   at Microsoft.Crm.Authentication.AuthenticationEngine.Execute(Object sender, EventArgs e)

So, it was failing while building the metadata cache for that organization with some kind of duplicate key "An item with the same key has already been added".
However, there wasn't an easy way to find the culprit; all I got from the developper was that he was handling connections in an entity when the organization failed on him; so I reverse read the verbose log to got which data could contain the duplicate and here're the requests made by the platform while building the cache :

select * from ManagedProperty  where SolutionId <> 'fd140aad-4df4-11dd-bd17-0019b9312238' and OverwriteTime = 0 and ComponentState in (0, 2)  order by ComponentState asc
select * from OptionSet  where SolutionId <> 'fd140aad-4df4-11dd-bd17-0019b9312238' and OverwriteTime = 0 and ComponentState in (0, 2)  order by ComponentState asc
select * from Entity  where SolutionId <> 'fd140aad-4df4-11dd-bd17-0019b9312238' and OverwriteTime = 0 and ComponentState in (0, 2)  order by ComponentState asc
select * from Attribute  where SolutionId <> 'fd140aad-4df4-11dd-bd17-0019b9312238' and OverwriteTime = 0 and ComponentState in (0, 2)  order by ComponentState asc
select * from AttributeLookupValue  where SolutionId <> 'fd140aad-4df4-11dd-bd17-0019b9312238' and OverwriteTime = 0 and ComponentState in (0, 2)  order by ComponentState asc
select * from AttributePicklistValue  where SolutionId <> 'fd140aad-4df4-11dd-bd17-0019b9312238' and OverwriteTime = 0 and ComponentState in (0, 2)  order by ComponentState, DisplayOrder asc
select * from EntityRelationship  where SolutionId <> 'fd140aad-4df4-11dd-bd17-0019b9312238' and OverwriteTime = 0 and ComponentState in (0, 2)  order by ComponentState asc
select * from Relationship  where SolutionId <> 'fd140aad-4df4-11dd-bd17-0019b9312238' and OverwriteTime = 0 and ComponentState in (0, 2)  order by ComponentState asc
select * from RelationshipExtraCondition  where SolutionId <> 'fd140aad-4df4-11dd-bd17-0019b9312238' and OverwriteTime = 0 and ComponentState in (0, 2)  order by ComponentState asc
select * from EntityRelationshipRole  where SolutionId <> 'fd140aad-4df4-11dd-bd17-0019b9312238' and OverwriteTime = 0 and ComponentState in (0, 2)  order by ComponentState asc
select * from EntityRelationshipRelationships  where SolutionId <> 'fd140aad-4df4-11dd-bd17-0019b9312238' and OverwriteTime = 0 and ComponentState in (0, 2)  order by ComponentState asc
select * from ViewAttribute  where SolutionId <> 'fd140aad-4df4-11dd-bd17-0019b9312238' and OverwriteTime = 0 and ComponentState in (0, 2)  order by ComponentState asc

I made a guess that  "name" was the key field and started checking each table with queries as such:
select schemaname,count(*) from EntityRelationship 
group by schemaname
having count(*)>1

After a bit of drilldrown, two records were duplicated in RelationShip and EntityRelationShip :
xxx_agreement_connections1    C7866019-D3D1-40D7-B483-381FCDCCFFB2 D6CE8EBC-86DC-49CB-839A-
xxx_agreement_connections1    4E4D2C0B-BD41-E111-9A50-005056A877F9 256FA569-E732-4675-9519-
xxx_agreement_connections2    4E4D2C0B-BD41-E111-9A50-005056A877F9 05F6B370-01FE-4F3E-BF56-
xxx_agreement_connections2    C7866019-D3D1-40D7-B483-381FCDCCFFB2 48C02973-80A2-431B-8805-

In CRM 4.0, a custom entity was created called "connection" with links to other entities, in order to mimic some of the CRM2011 "connection" entity functions. The upgrade process went without issues and the organization was stable afterwards; however when the developper created a new 'CRM2011' connection, the platform created a new relationship with the exact same name as the one named with the 'CRM4' connection. As you cannot change the relationship name in connection, it was quite unavoidable and the platform crashed.

In order to fix the issue and get the organization back up, I manually changed the relationship name with the following statements:
UPDATE Relationship set name='xxx_agreement_connections1C' where RelationshipId='20E35F70-5965-4C6E-98EE-CAAA38ABCB5E'
UPDATE Relationship set name='xxx_agreement_connections2C' where RelationshipId='BE921610-4237-4A11-8883-00A4016D1DA0'
update EntityRelationship set schemaname = 'xxx_agreement_connections1C' where EntityRelationshipId = '296A89B6-DA41-E111-9A50-005056A877F9'
update EntityRelationship set schemaname = 'xxx_agreement_connections2C' where EntityRelationshipId = '70335CCE-DA41-E111-9A50-005056A877F9'

Warning :  this put back the organization up but the two lasts statements change the schemaname, you would also need to change the actual columns and views in the custom entity manually; in that particular case we wanted to get rid of the old connection, so we dropped them. Also, making direct changes to the system tables is quite dangerous so if you're unsure, it may be worth just restoring a backup of the organization.

In order to avoid those kind of issues; the easiest is to change the custom prefix to something different than the one in CRM 4.0; for example X11_ instead of XXX_ after the migration process has complete; that will force the platform to use a different name than what you could have in CRM 4.0