0
Fixed

FIM Delta Import Operations Timing Out on IDB

Hayden Gray 5 years ago updated by Beau Harrison (Senior Product Software Engineer) 5 years ago 9

Hi Guys,

We are currently experiencing an issue about every one or two weeks, where all FIM operations that import from IdB just time out. IdB produces a few of errors and there is also one in the event log, please find all the errors below:

IDB Errors:

Handling of LDAP change log request. Handling of LDAP change log request from user idBFull on connection 127.0.0.1:60915 requesting changelog records failed with error "This operation returned because the timeout period expired. (Exception from HRESULT: 0x800705B4)". Duration: 00:14:59.9875915.

An error occurred on client from 127.0.0.1:60915. More details: Internal Server Error #11: System.ApplicationException: This operation returned because the timeout period expired. (Exception from HRESULT: 0x800705B4) at System.Threading.ReaderWriterLock.AcquireReaderLockInternal(Int32 millisecondsTimeout) at System.Threading.ReaderWriterLock.AcquireReaderLock(TimeSpan timeout) at Unify.Framework.Data.LinqWhereQuery`5.GetEnumerator() at Unify.Product.IdentityBroker.ChangeLogRequestHandler.<performsearch>d__4.MoveNext() at Unify.Product.IdentityBroker.StoredSearchResults.MoveNext() at Unify.Product.IdentityBroker.SearchRequestHandlerBase.<finalizesearchresults>d__13.MoveNext() at Unify.Framework.Visitor.Visit[T](IEnumerable`1 visitCollection, Action`2 visitor) at Unify.Product.IdentityBroker.LDAPConnection.<respondtomessageasync>d__33.MoveNext()</respondtomessageasync></finalizesearchresults></performsearch>

Adapter Adapter 274fbf2d-9b71-4466-9c88-7ba6e789e279 page errored on page reflection. Duration: 00:20:16.5869103. Error: System.ApplicationException: This operation returned because the timeout period expired. (Exception from HRESULT: 0x800705B4) at System.Threading.ReaderWriterLock.AcquireWriterLockInternal(Int32 millisecondsTimeout) at System.Threading.ReaderWriterLock.AcquireWriterLock(TimeSpan timeout) at Unify.Framework.Data.LinqContextConversionBase`4.SubmitChanges() at Unify.Product.IdentityBroker.Adapter.ReflectChanges() at Unify.Product.IdentityBroker.AdapterNotifierDecorator.ReflectChanges() at Unify.Product.IdentityBroker.ReflectAdapterOnChangeDueJob.<runbase>b__10_0(IOperationalAdapter adapter). Error details: System.ApplicationException: This operation returned because the timeout period expired. (Exception from HRESULT: 0x800705B4) at System.Threading.ReaderWriterLock.AcquireWriterLockInternal(Int32 millisecondsTimeout) at System.Threading.ReaderWriterLock.AcquireWriterLock(TimeSpan timeout) at Unify.Framework.Data.LinqContextConversionBase`4.SubmitChanges() at Unify.Product.IdentityBroker.Adapter.ReflectChanges() at Unify.Product.IdentityBroker.AdapterNotifierDecorator.ReflectChanges() at Unify.Product.IdentityBroker.ReflectAdapterOnChangeDueJob.<runbase>b__10_0(IOperationalAdapter adapter)</runbase></runbase>

Request to reflect change entities of the adapter. Request to reflect change entities of the LDAP Group (274fbf2d-9b71-4466-9c88-7ba6e789e279) adapter errored with message: This operation returned because the timeout period expired. (Exception from HRESULT: 0x800705B4). Duration: 00:20:16.7116713 Error details: System.ApplicationException: This operation returned because the timeout period expired. (Exception from HRESULT: 0x800705B4) at System.Threading.ReaderWriterLock.AcquireWriterLockInternal(Int32 millisecondsTimeout) at System.Threading.ReaderWriterLock.AcquireWriterLock(TimeSpan timeout) at Unify.Framework.Data.LinqContextConversionBase`4.SubmitChanges() at Unify.Product.IdentityBroker.Adapter.ReflectChanges() at Unify.Product.IdentityBroker.AdapterNotifierDecorator.ReflectChanges() at Unify.Product.IdentityBroker.ReflectAdapterOnChangeDueJob.<runbase>b__10_0(IOperationalAdapter adapter)</runbase>

Event Log Error:

The extensible extension returned an unsupported error. The stack trace is: "Unify.Product.IdentityBroker.LdapOperationException: Operation timed out. at Unify.Product.IdentityBroker.LdapConnection.SendRequest(ILdapRequest request) at Unify.Product.IdentityBroker.LdapConnectionProxy.PartitionDeltaRequestPaged(String partitionDN, Int64 lastChangeNumber, Int32 pageSize) at System.Linq.Enumerable.d__14`2.MoveNext() at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext() at System.Linq.Enumerable.d__14`2.MoveNext() at Unify.Product.IdentityBroker.ExtensionMethods.Take[TSource](IEnumerator`1 source, Int32 count, IList`1& items) at Unify.Product.IdentityBroker.ExtensionMethods.d__0`1.MoveNext() at Unify.Product.IdentityBroker.ImportProxy.Import(GetImportEntriesRunStep importRunStep) Forefront Identity Manager 4.1.3646.0"

I haven't noticed any one particular operation failure or time that causes this. The resolution is to restart the IdB service, after which deltas work as normal. Details on the services are as follows:

Identity Broker: 5.0.4

FIM: 4.1.3646.0

Let me know if you need any further testing done.Though it may be some time between updates as I cannot recreate the issue.

Thanks

Under review

Hi Hayden

This is a known issue that has been resolved. The fix is available in v5.1+ and a patch is available for v5.0. Ensure you use the patch file provided by Curtis which he specifies as being for v5.0.

Hi Beau

Thanks providing the to me. We're current working through change control with the patch. Just another question, we also appear to have a Full Import from IdB that is now timing out. The adapter its timing out on is the largest adapter we have which is about 400,000 records. It seems to time out around 240k~290k with this error in event log (I couldn't find the corresponding record in the IDB log around that time):

The extensible extension returned an unsupported error.
The stack trace is:

"Unify.Product.IdentityBroker.LdapOperationException: Operation timed out.
at Unify.Product.IdentityBroker.LdapConnection.SendRequest(ILdapRequest request)
at Unify.Product.IdentityBroker.LdapConnectionProxy.d__6.MoveNext()
at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
at System.Linq.Enumerable.d__14`2.MoveNext()
at System.Linq.Enumerable.d__14`2.MoveNext()
at System.Linq.Enumerable.d__14`2.MoveNext()
at Unify.Product.IdentityBroker.ExtensionMethods.Take[TSource](IEnumerator`1 source, Int32 count, IList`1& items)
at Unify.Product.IdentityBroker.ExtensionMethods.d__0`1.MoveNext()
at Unify.Product.IdentityBroker.ImportProxy.Import(GetImportEntriesRunStep importRunStep)
Forefront Identity Manager 4.1.3646.0"

Try reducing the Page Size value or increasing the Operation Timeout values in the run profiles. Or both. Note the timeout to increase is the one on the 3rd screen of the run profile configuration, not the one above the page size.

No worries the page size is set to 1000 at the moment, so I'll try increasing the timeout to 5000 as it is currently 2000, which is not every long for 400k records.

Thanks

There also seems to be an import changes cycling on the adapter while no operations are running in FIM. So I'll restart the server also.

The timeout is per page. If it's taking ~30 minutes for 1000 there may be something wrong other than performance issues. Change the log level of the Broker logger to Verbose. This will output more logs relating to the search request

Oh right ok, it is possible it was taking that long. I'll see if this fixes the issue first, otherwise if it does it again I can turn the verbose logging on.

Thanks

Hi Beau,

This one appears to be resolved now, increasing that timeout value allow the Import to complete. Happy to close this one.

Thanks for your help