0
Answered

Delta Import timeouts on Identity Broker 5.1 Management Agents

Andrew Silcock 2 years ago in UNIFYBroker/Microsoft Identity Manager • updated by anonymous 2 years ago 23

Seeing some issues on IDB 5.1 MAs from FIM performing Delta Imports where after a period of time they will start reporting timeout issues, as below. The timeouts on the MA operations have been increased to 999, and the timeout settings I can find in IDB appear to be set to 10mins.

Currently the only workaround I can find is to perform a full import on the management agent which then seems to resolve the issue for subsequent delta imports - however this is not practical as full imports can take up to 3 hours. DB indexes are also regularly re-built.

Are you able to provide any guidance in troubleshooting this issue?

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.
at Unify.Product.IdentityBroker.LdapConnection.SendRequest(ILdapRequest request)
at Unify.Product.IdentityBroker.LdapConnectionProxy.<SearchRequestPaged>d__8.MoveNext()
at Unify.Product.IdentityBroker.ImportProxy.<GetChangedEntriesPaged>d__33.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"

Affected Versions:
Fixed by Version:

Answer

Answer

Can confirm that after running the full imports over the weekend in isolation that the issues appear to have resolved themselves.

Am going to tweak the Event Broker scheduling to try and prevent the scenario from occurring.

GOOD, I'M SATISFIED
Satisfaction mark by Andrew Silcock 2 years ago
Under review

Hi Andrew,

What is your configured setting for Page size (objects) on the Run Profile? How many changes are expected to be imported when the timeout occurs?

timeout settings are Timeout 999 secs, Operation Timeout 600. I believe the number of changes are normally small (in the 10s), however can't be certain of the number of objects as the adapter page in Broker 5.1 never seems to display the number of changes pending accurately.

As an example, I ran a Full Import on the MA last night and it brought in rougly 1600 changes. I'm attempting to run another Delta Import now.

Just had this timeout again


MIM Log:

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.
at Unify.Product.IdentityBroker.LdapConnection.SendRequest(ILdapRequest request)
at Unify.Product.IdentityBroker.LdapConnectionProxy.<SearchRequestPaged>d__8.MoveNext()
at Unify.Product.IdentityBroker.ImportProxy.<GetChangedEntriesPaged>d__33.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"

Identity Broker Log

28/Oct/2016 08:13:54
  • Information
LDAP engineHandling of LDAP Root DSE request.
Handling of LDAP Root DSE request from user ISAS on connection 127.0.0.1:63734 for the Root DSE completed successfully. Duration: 00:00:00.
28/Oct/2016 08:13:55
  • Information
LDAP engineHandling of LDAP change log request.
Handling of LDAP change log request from user ISAS on connection 127.0.0.1:63734 completed successfully. Added: 1. Modified: 0. Renamed: 0. Deleted: 0. Total: 1. Duration: 00:00:01.2268614.
28/Oct/2016 08:15:05
  • Information
LDAP engineHandling of LDAP unbind request.
Handling of LDAP unbind request received on connection 127.0.0.1:63734 to connect as user ISAS completed successfully. Duration: 00:00:00

The timing of the error in MIM corresponds with the unbind log entry in IDB.

Is it happening consistently to all Delta Import operations or only intermitantly?

has been intermittent - but this morning has been on all delta imports. I'm now running a Full Import again now, as the changes get lost - IDB appears to return them to the FIM MA, however the operation times out somewhere.

Will email the logs thru as there seems to be buttons for adding video/images but not files.

Thanks for the clarifications.

For the record, you should be able to attach files by simply dragging them into the reply box.

Hi Andrew, Could you also please attach a screenshot of the failed runs in MIM so I can compare the timestamps? Sorry, should have asked for this earlier.

The stopped-extension-dll exceptions correspond to the Windows event log entry originally included.

Thanks Andrew. From your screenshot and logs, they're all timing out just after 1 minute. You definitely don't have it set as 60 instead of 600? Of the Delta Imports that were successful, did they all finish in under a minute? Did any last longer? I might have to add in some extra logging because I can't see why the timeout would happen after only 60 seconds given your configuration.

leave it with me for the moment, will do some additional testing after the current full import completes.

Here are the log entries from the latest Delta Import attempt, confirmed the operation timeout was 600secs. The first and last entry times marry up with the start and end time of the MA.

Can this please be investigated as a priority as this is in a production environment (not yet live), with a go live target in the next few weeks. The way the system is currently behaving it will not be possible to go live with the system in this state - this MA in particular is the authoritative source for Student Identities.

Hi Andrew,

Unfortunately I haven't been able to reproduce this in my test environment. Could you please try placing this patched copy of Unify.IdentityBroker.FIMAdapter.dll into the MIM extensions directory and re-attempting the Delta Import? If you let me know of a directory that I could create log files in, I can add some extra logging as well to try to diagnose this quicker.

Edit: I originally uploaded the wrong file, I've updated the link above but the link/attachment in the email notification will likely still be wrong.

Can log to C:\UNIFY\Logs\

Hi Andrew,

Given that the timeouts are interspersed with timeouts for reflection as well, I'm wondering if there is just too much activity happening at the same time - Adam has hinted at this as well in your other issue (IDB 5.1 returning duplicate objects that only exist once in the Adapter/Connector). Could you please try reattempting the import in isolation of other operations in Identity Broker?

Answer

Can confirm that after running the full imports over the weekend in isolation that the issues appear to have resolved themselves.

Am going to tweak the Event Broker scheduling to try and prevent the scenario from occurring.

This issue is now occurring again with the same symptoms - further details provided to Adam via email, however the error within FIM is included below. EB Pending checks and Delta imports are timing out.

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 9. ---> System.OperationCanceledException: Operation timed out while waiting for message queue with id of 9.
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.VerifyChangeLogConsistency(Int64 lastChangeNumber)
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"

Hi Andrew, I've attached an Identity Broker patch that removes locking around the change log. It's one of the simpler tables as it doesn't have to deal with updates or deletes. I have been smashing my instance of Identity Broker with the patch and was unable to trigger any issues.

Unify.IdentityBroker.ChangeLog.Repository.Sql.dll

thanks Adam - does this go in the Services\Patches directory?

Either there, or the main Services directory.

Thanks.

+1

Thanks Adam - appears to be working now, so will keep monitoring over the coming week and advise if we run into issues again.