0
Under review

Delta Imports timeout - can it be changed?

Eddie Kirkman 3 weeks ago • updated by Curtis Lusmore 6 days ago 16

I am seeing timeout issues while trying to perform a delta import from Identity Broker.  MIM just reports stopped-extension-dll-exception with no other detail, but in event viewer I see event id 6803.

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

Then event ID 6801:

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"

The corresponding time in IDB log has

26/Sep/2018 10:11:17 
Information
LDAP engine Handling of LDAP unbind request.
Handling of LDAP unbind request received on connection 127.0.0.1:61732 to connect as user ******** completed successfully. Duration: 00:00:00.

Is there a setting somewhere that will let me increase IDB LDAP timeouts?  I could not find one, but it has been a few years since I used the product.

Affected Versions:
Fixed by Version:
Under review

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.

IdB Log shows no error at that time

08/Oct/2018 10:59:39
  • Information
LDAP engineHandling of LDAP change log request.
Handling of LDAP change log request from user XXXXXX on connection 127.0.0.1:63213 completed successfully. Added: 0. Modified: 29. Renamed: 0. Deleted: 0. Total: 29. Duration: 00:00:48.4858175.
08/Oct/2018 10:59:39
  • Information
LDAP engineHandling of LDAP unbind request.
Handling of LDAP unbind request received on connection 127.0.0.1:63213 to connect as user TechOneSMS completed successfully. Duration: 00:00:00.

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:

08/Oct/2018 16:41:19
  • Information
LDAP EngineA client has connected to the LDAP endpoint from address: 127.0.0.1:55727.
08/Oct/2018 16:41:21
  • Information
LDAP engineHandling of LDAP bind request.
Handling of LDAP bind request received on connection 127.0.0.1:55727 to connect as user xxxxxx completed successfully. The bind was successful. Duration: 00:00:01.0478231.
08/Oct/2018 16:41:21
  • Information
LDAP engineHandling of LDAP unbind request.
Handling of LDAP unbind request received on connection 127.0.0.1:55727 to connect as user xxxxxx completed successfully. Duration: 00:00:00.0468845.
08/Oct/2018 16:41:33
  • Information
LDAP EngineA client has connected to the LDAP endpoint from address: 127.0.0.1:55777.

08/Oct/2018 16:41:34
  • Information
LDAP engineHandling of LDAP bind request.
Handling of LDAP bind request received on connection 127.0.0.1:55777 to connect as user xxxxxx completed successfully. The bind was successful. Duration: 00:00:00.3440018.
08/Oct/2018 16:41:34
  • Information
LDAP engineHandling of LDAP Root DSE request.
Handling of LDAP Root DSE request from user xxxxxx on connection 127.0.0.1:55777 for the Root DSE completed successfully. Duration: 00:00:00.
08/Oct/2018 16:41:34
  • Error
LDAP engineHandling of LDAP search request.
Handling of LDAP search request from user xxxxxx on connection 127.0.0.1:55777 targeting DC=IdentityBroker with a scope of SingleLevel failed with error "Could not load type 'Unify.Product.IdentityBroker.IForwardLookingEnumerator`1' from assembly 'Unify.IdentityBroker.LDAP.Engine.Interfaces, Version=5.1.0.0, Culture=neutral, PublicKeyToken=84b9288cb2633de4'.". Duration: 00:00:00.
08/Oct/2018 16:41:34
  • Error
LDAP EngineAn error occurred on client from 127.0.0.1:55777. More details:
Internal Server Error #11: System.TypeLoadException: Could not load type 'Unify.Product.IdentityBroker.IForwardLookingEnumerator`1' from assembly 'Unify.IdentityBroker.LDAP.Engine.Interfaces, Version=5.1.0.0, Culture=neutral, PublicKeyToken=84b9288cb2633de4'.
at Unify.Product.IdentityBroker.SearchRequestHandlerBase.HandleRequest(IRfcLdapMessage message, CancellationToken token, Action`1 postAction)
at Unify.Product.IdentityBroker.RequestHandlerAuditingDecorator.HandleRequest(IRfcLdapMessage message, CancellationToken token, Action`1 postAction)
at Unify.Product.IdentityBroker.LDAPRequestHandlerSecurityDecorator.HandleRequest(IRfcLdapMessage message, CancellationToken token, Action`1 postAction)
at Unify.Product.IdentityBroker.LDAPConnection.<RespondToMessageAsync>d__33.MoveNext()
08/Oct/2018 16:41:34
  • Information
LDAP engineHandling of LDAP unbind request.
Handling of LDAP unbind request received on connection 127.0.0.1:55777 to connect as user xxxxxx completed successfully. Duration: 00:00:00.

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.

Plugin KeyVersion
Extended Database Connector5.1.0.1
Microsoft Azure AD Connector5.1.0.1
Connector for D2L5.1.0.2
Unify.IdentityBroker.ChangeLog.Repository.Sql.dll5.1.0.0


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?