Delta Imports timeout - can it be changed?

Hi Eddie,

Please see UNIFYBroker/Microsoft Identity Manager Configuration for details on configuring the timeout for LDAP operations.

Please also see the section titled Maintenance Tasks on UNIFYBroker SQL Server Database Recommendations, as poor SQL performance is a common cause for slowdown in entity querying operations.

Thanks Curtis.  We are rebuilding the idexes for the IDB database (Richards's suggestion) so will see if that resolves things.  I will look at the timeout settings

rebuild of idexes completed (service has to be stopped to rebuild changelog)  Following that one MA DI worked the other still failed.  Set the LDAP timeout up from 60 to 240, but a DI still failed (within seconds of attempting).  We are currently running a FI in the hope that will at least fix temporarily.

Unfortunately although one of our MAs is now performing DI (after rebuild of indexes and a FI from MIM) the other one continues to fail. A FI takes over an hour and this is a time critical system so we really need to be able to bring in the handful of delta changes in near real time.  Any suggestion as to where to look next, please?

Were you able to check whether the DI is still failing for the same reason? Please check the latest in the event viewer and reply with the error, as well as the latest logs again. Thanks.

The delta imports are still failing. Eventvwr shows two errors - first a 6801 error:

The extensible extension returned an unsupported error.
 The stack trace is:
 
 "Unify.Product.IdentityBroker.LdapOperationException: Invalid change log format.
   at Unify.Product.IdentityBroker.LdapConnection.SendRequest(ILdapRequest request)
   at Unify.Product.IdentityBroker.LdapConnectionProxy.<SearchRequestPaged>d__8.MoveNext()
   at Unify.Product.IdentityBroker.ImportProxy.<GetChangedEntriesPaged>d__30.MoveNext()
   at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
   at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
   at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
   at Unify.Product.IdentityBroker.ExtensionMethods.Take[TSource](IEnumerator`1 source, Int32 count, IList`1& items)
   at Unify.Product.IdentityBroker.ExtensionMethods.<Page>d__3`1.MoveNext()
   at Unify.Product.IdentityBroker.ImportProxy.Import(GetImportEntriesRunStep importRunStep)

then a 6801 error

The management agent "XXXXXX" failed on run profile "DI" because the server encountered errors.

I believe this is a duplicate of Invalid Change Log Format on Delta Import from IDB 5.1

IdB Log shows no error at that time

I have put that ldap patch in.  So far it is causing the DI run to fail no-start-ma.  Just trying again with increased timeout on the run profile.  If it still fails I will remove the patch and see if we revert to the previous error

with a 20 minute timneout it waited 20 mins before failing - but still failed.  The IDB console showed no activity, but the log showed:

having removed that ldap patch, the original stpped-extension-dll-exception is recurring

Hi Eddie,

Thanks for the stacktrace. Which version of UNIFYBroker do you have installed?

UNIFY Identity Broker Management Studio
v5.1.0 Revision #0
© 2004 - 2016 UNIFY Solutions Pty. Ltd.

Thanks Eddie. Are you able to upgrade to the latest v5.1 release, which should include the patch?

I can look at getting an IdB version upgrade scheduled - but it will have to roll through DEV and STG and be tested before we can roll it to PRD.

Will the new version resolve the issue we are seeing or is that just to allow for the better logging 

Apologies for the delayed response. The patch would only help diagnose the issue. Are you able to reproduce this in DEV?

For now the issue has been resolved.  We were still unable to successfully run Delta Imports, but full imports would work.  Continuing to only use FI was untenable so the connector has been cleared (and the adapter) and a full import run to rebuild it.  I full import and sync to MIM has also been run and the delta imports are now working again.

This is a solution, but not a great one, since it required 6-7 hrs of "free" time to complete and had to be run over the weekend.  If the original error recurs I will open a new ticket

The clear and repopulate of the connector and adapter resolved the issue for a while, but it is now occurring again.

2 different MAs are giving us the same symptoms:

Running a DI results in a "stopped-extension-dll-exception" (for one of them that is after 30 minutes of nothing)

Eventvwr gives a 6801 error:

The extensible extension returned an unsupported error.
 The stack trace is:
 
 "Unify.Product.IdentityBroker.LdapOperationException: Error during processing of SearchRequest targetting cn=changelog: Operation timed out while waiting for message queue with id of 14. ---> System.OperationCanceledException: Operation timed out while waiting for message queue with id of 14.
   at Unify.Product.IdentityBroker.LdapConnection.GetMessage(Int32 messageId)
   at Unify.Product.IdentityBroker.SearchRequest.Send(Func`2 send, Func`2 recv)
   at Unify.Product.IdentityBroker.LdapConnection.SendRequest(ILdapRequest request)
   --- End of inner exception stack trace ---
   at Unify.Product.IdentityBroker.LdapConnection.SendRequest(ILdapRequest request)
   at Unify.Product.IdentityBroker.LdapConnectionProxy.<SearchRequestPaged>d__8.MoveNext()
   at Unify.Product.IdentityBroker.ImportProxy.<GetChangedEntriesPaged>d__30.MoveNext()
   at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
   at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
   at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
   at Unify.Product.IdentityBroker.ExtensionMethods.Take[TSource](IEnumerator`1 source, Int32 count, IList`1& items)
   at Unify.Product.IdentityBroker.ExtensionMethods.<Page>d__3`1.MoveNext()
   at Unify.Product.IdentityBroker.ImportProxy.Import(GetImportEntriesRunStep importRunStep)
Forefront Identity Manager 4.3.2266.0"

 followed by a 6803 error:

The management agent "XXXXXX" failed on run profile "DI" because the server encountered errors.

followed by a warning about watermarks

The management agent "XXXXXX" step execution completed on run profile "DI" but the watermark was not saved.
 
 Additional Information
 Discovery Errors    : "0"
 Synchronization Errors : "0"
 Metaverse Retry Errors : "0"
 Export Errors          : "0"
 Warnings               : "0"
 
 User Action
 View the management agent run history for details.

We really need some way of working out why this is repeatedly happening as it impacts on our expected SLA for provisioning and managing changes

So just to recap, we're back to the original issue of the timeout. There are multiple MAs connecting to the same instance of UNIFYBroker, where some MAs consistently work well and others are now consistently timing out. This suggests it isn't a DB performance issue in UNIFYBroker. A network trace of a timed out import shows the preamble of bind/schema/change log consistency processing smoothly and then no response to the change log request. A network trace of a successful import shows an identical conversation except that the change log request is processed and responded to correctly, although it happened to have no entries.

Eddie, are you able to

1. Confirm that one of the MAs which processes correctly has actually imported some changes via Delta Import recently, to rule out the issue being the import phase of a Delta Import.
2. Run a SQL query against the UNIFYBroker database to retrieve the change log entries that would be returned, to see if we can identify any issues there. Query attached: changelogs.sql

Thanks - I will look at getting a change stood up to roll that patch to DEV and Staging then Prod - I think we will not be able to confirm if it helps till Prod, but will need to roll through the other environments to ensure everything continues to work

Patch deployed to DEV and STG and awaiting permission to deploy to PRD

Identity Broker upgraded to v5.3.1 Revision #1

Issue is typically occurs once or more daily at present as there is significant levels of data changes in the source system in preparation for the academic year.

Seems to occur more often on SMS Enrolments, but also occasionally on SMS Students. Both have ~200K records however the Enrolment connector has some multi-valued attributes and a full import takes several hours. The problem often (but not always) starts when a MIM Delta Import is attempted while the Full Import is still running. 

Hi Boyd, the exception is being caused by the bad change log value. However, it does not seem possible for the code which generates this value to output what you're seeing.

Couple of questions

1. How clean was the install directory when in installed v5.3.1.3? Could there have been any old patches in in Services or Services/Patches directories?
2. Are there any other change log records being generated in the incorrect format like this one or is this the only instance?
3. If it is possible to make the same change in the target system on the same entity, does a polling import result in the same bad change log record? What about the same change on a different entity?

1. Files

There are no files in the patches folder.

These are the DLLs and EXEs in the Services are in the attached Services Files.xlsx

2. Log data to follow, I can see this morning imports are failing on a different Connector.

 3. Polling vs Full Imports

It is not possible to make changes in the target system, however a Full Import is only ever run once daily, given the number of failures in the past we can confidently say it can occur after either a Full or Polling import as it sometimes begins after on the first import of the day or occurs during the day.

Are you able to confirm that after the polling import which results in the above exception there are not two different entities with that DN?

Also, here is a patch which improves the above log to include more information about the entities which are supposedly clashing.

Unify.IdentityBroker.LDAP.Engine.dll

I ran the following query and only got a single record returned, which I take to mean it is unique.

SELECT DISTINCT EntityId
FROM EntityValue
WHERE StringValue = '457549616'
AND PartitionId = '8c359d6e-ab44-4a50-a6b8-6d2774c3e6e2'

Does that DLL go into the Patches folder or Services?

Services

Patch applied, new message below:

The extensible extension returned an unsupported error.
 The stack trace is:
 
 "Unify.Product.IdentityBroker.LdapOperationException: Found multiple entities with the distinguished name 'CN=471013589,OU=D2LUsers,DC=IdentityBroker'. Existing entity id: 'ce9ccccf-c4cb-4e64-9d34-f6304fcbfbca' - Existing entity key values: '398263' - New entity id: 'ce9ccccf-c4cb-4e64-9d34-f6304fcbfbca' - New entity key values: '398263'
   at Unify.Product.IdentityBroker.LdapConnection.SendRequest(ILdapRequest request)
   at Unify.Product.IdentityBroker.LdapConnectionProxy.<SearchRequestPaged>d__8.MoveNext()
   at Unify.Product.IdentityBroker.ImportProxy.<GetChangedEntriesPaged>d__30.MoveNext()
   at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
   at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
   at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
   at Unify.Product.IdentityBroker.ExtensionMethods.Take[TSource](IEnumerator`1 source, Int32 count, IList`1& items)
   at Unify.Product.IdentityBroker.ExtensionMethods.<Page>d__3`1.MoveNext()
   at Unify.Product.IdentityBroker.ImportProxy.Import(GetImportEntriesRunStep importRunStep)
Forefront Identity Manager 4.4.1749.0"

Change Logs.txt

Patch applied, this is the error now.

The extensible extension returned an unsupported error.
 The stack trace is:
 
 "Unify.Product.IdentityBroker.LdapOperationException: Internal Server Error #12: Invalid change log format: Unable to determine operation seperator from . ChangeLogKey: 12216627, ChangeTimeStamp: 2/20/2019 3:08:34 AM TargetDN: CN=450000013,OU=SMSEnrolments,DC=IdentityBroker
   at Unify.Product.IdentityBroker.ChangesToChangelogFormatBase.<ConvertFromChangelogItem>d__3.MoveNext()
   at Unify.Product.IdentityBroker.ChangesToChangelog2006Format.<Transform>d__1.MoveNext()
   at Unify.Product.IdentityBroker.RfcChangeLogEntry..ctor(Int64 changeNumber, IDictionary`2 attributes)
   at Unify.Product.IdentityBroker.ChangeLogToLDAPEntryConverter.Transform(IChangeLogItem sourceValue)
   at Unify.Product.IdentityBroker.ChangeLogRequestHandler.<NormalSearch>d__9.MoveNext()
   at Unify.Product.IdentityBroker.ForwardLookingEnumerator`1.MoveNext()
   at Unify.Product.IdentityBroker.StoredSearchResults.MoveNext()
   at Unify.Product.IdentityBroker.LDAPEngineExtensions.<TakeFromEnumerator>d__1`1.MoveNext()
   at Unify.Product.IdentityBroker.SearchRequestHandlerBase.<FinalizeSearchResults>d__12.MoveNext()
   at Unify.Framework.Visitor.Visit[T](IEnumerable`1 visitCollection, Action`2 visitor)
   at Unify.Product.IdentityBroker.SearchRequestHandlerBase.HandleRequest(IRfcLdapMessage message, CancellationToken token, Action`1 postAction)
   at Unify.Product.IdentityBroker.LdapConnection.SendRequest(ILdapRequest request)
   at Unify.Product.IdentityBroker.LdapConnectionProxy.<SearchRequestPaged>d__8.MoveNext()
   at Unify.Product.IdentityBroker.ImportProxy.<GetChangedEntriesPaged>d__30.MoveNext()
   at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
   at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
   at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
   at Unify.Product.IdentityBroker.ExtensionMethods.Take[TSource](IEnumerator`1 source, Int32 count, IList`1& items)
   at Unify.Product.IdentityBroker.ExtensionMethods.<Page>d__3`1.MoveNext()
   at Unify.Product.IdentityBroker.ImportProxy.Import(GetImportEntriesRunStep importRunStep)

The patch only corrects the generation of change log records. This change log shown is incorrectly generated, but judging by the timestamp, that change log entry was created before I provided the patch. Is this correct?

You will need to do a full import on the MIM management agent. This will update its knowledge of the latest change log number so subsequent deltas won't request the incorrectly generated change log entries from before applying the patch.

Yes the problem was occurring before it was applied, I will run the Full Import

Hi Boyd, how did this fix go? Any more problems?

Hi Beau

It has been working well I think this can be closed. I would like to deploy this fix for Brisbane Catholic Education has or will the fix be included in a release?

Boyd

Good to hear. These fixes will be included in the next v5.3 release which will be in the next day or so.