LDAP timeout

Unify.IdentityBroker.LDAP.Engine.dll v 5.0.4.0 provided yesterday is in the identityBroker\Services\Patches directory, alongside the earlier files (Adapter.Engine, Adapter.Engine.Notification, LDAP.Engine.interface, ldap.engine.notification and ldap.engine.shared)

Are there any other operations running concurrently with the Delta Import, including connector imports or reflection?

I do not think so. I will have to look again on Monday or maybe over the weekend I can stop EvB and try just running a delta import. thanks

Hey Curtis. I checked the run history for the weekend and none of the attempted Delta imports for CAMS users succeeded - all failed with stopped-extension-dll-exception - no other useful information. The last import changes for the adapter in IdB has:

Handling of LDAP change log request from user IdBAPPProxy on connection 127.0.0.1:46013 failed with error "The transaction has aborted.". Duration: 01:43:42.3517789.

I stopped Event broker and manually tried a Delta Import of Cams generic (13000 objects). FIM reported success (0 changes) in a second. The IdB adapter import changes showed a spinning thing - never went till I stopped service. Also, that showed for the other two CAMS adapters. I stopped IdB and removed the patched version of - Unify.IdentityBroker.LDAP.Engine.dll (dated 3/6) and rolled back to the patch from the day before. I have run a delta import for cams generic and all 4 adapters (the one I was reading, the other 2 cams ones and the safe one are reporting under Import changes:

There are no changed entities

Last Run: 06/Jun/2016 11:54:05

Please attach the IDB logs, there should be an entry for the processing of the relevant changelog requests. It sounds to me that if there truly are no changes then the only issue from your most recent comment is that the adapter statistics are displaying wrong. There is still the issue of timeouts from your previous comments.

How to attach?

I have emailed the log file. After rolling back to the previous ldap patch and restarting the service, the FIM Delta import for CAMS generics was kicked off at 11:54:02

no insert file option. I have html, formatting, bold, italic, underline, deleted, unordered list, ordered list, insert image, insert video, table, link, alignment, insert horizontal rule.

I just tried a delta import from cams users. FIM failed with stopped-extension-dll-exception.

EventViewer has:

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.<SearchRequestPaged>d__6.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__0`1.MoveNext()

at Unify.Product.IdentityBroker.ImportProxy.Import(GetImportEntriesRunStep importRunStep)

Forefront Identity Manager 4.1.3627.0"

CAMS adapter shows:

Import Changes

IdB log:

20160606,02:20:43,UNIFY Identity Broker,LDAP Engine,Information,A client has connected to the LDAP endpoint from address: 127.0.0.1:12171.,Normal
20160606,02:20:43,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP bind request.
Handling of LDAP bind request received on connection 127.0.0.1:12171 to connect as user IdBAPPProxy completed successfully. The bind was successful. Duration: 00:00:00.2496000.",Normal
20160606,02:20:43,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP Root DSE request.
Handling of LDAP Root DSE request from user IdBAPPProxy on connection 127.0.0.1:12171 for the Root DSE completed successfully. Duration: 00:00:00.",Normal
20160606,02:20:43,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP schema request.
Handling of LDAP schema request from user IdBAPPProxy on connection 127.0.0.1:12171 for the server schema completed successfully. Duration: 00:00:00.0468000.",Normal
20160606,02:20:44,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP Root DSE request.
Handling of LDAP Root DSE request from user IdBAPPProxy on connection 127.0.0.1:12171 for the Root DSE completed successfully. Duration: 00:00:00.",Normal
20160606,02:20:45,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP change log request.
Handling of LDAP change log request from user IdBAPPProxy on connection 127.0.0.1:12171 completed successfully. Added: 0. Modified: 0. Renamed: 0. Deleted: 1. Total: 1. Duration: 00:00:00.3900000.",Normal

Thanks Eddie,

It seems like only support agents can attach files - strange, I'll get an admin to look at enabling attachments for all users.

From the logs we can see at 01:54:05UTC (11:54:05AEST) there was an incoming changelog request. The first request is to verify that the changelog entry last processed by FIM still exists, and the second request is the real changelog request which in this case returned no results.

20160606,01:54:05,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP change log request.
Handling of LDAP change log request from user IdBAPPProxy on connection 127.0.0.1:10530 completed successfully. Added: 0. Modified: 1. Renamed: 0. Deleted: 0. Total: 1. Duration: 00:00:00.5460000.",Normal
20160606,01:54:05,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP change log request.
Handling of LDAP change log request from user IdBAPPProxy on connection 127.0.0.1:10530 completed successfully. Duration: 00:00:00.2964000.",Normal 

From your newest comment, the latest entry in the IDB logs is again for this initial confirming request to verify that the changelog hasn't been truncated (since applying changes from a truncated changelog would give invalid/unpredictable results), but the proper request hasn't completed yet.

The `Unify.Product.IdentityBroker.LdapOperationException` error thrown on the MA is the timeout used by the agent when waiting for incoming LDAP messages and is configurable on the run profile step with the Operation Timeout (s) setting. Do you know what value you have configured for this?

Operation timeout in the run profile for User delta import is 60s

timeout (on the same page as page size) is 0

No additional LDAP change log stuff after the last one I posted above at 12:20:45, but all three adapters have failed to reflect (15 min timeout):

Request to reflect change entities of the adapter.
Request to reflect change entities of the CAMS (b559ed6a-7a2b-4aa1-b7d0-6f6447b6abc5) adapter errored with message: This operation returned because the timeout period expired. (Exception from HRESULT: 0x800705B4). Duration: 00:15:00.0231938
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)

Where do I set that timeout value?

>all three adapters have failed to reflect

When you ran the Delta import for CAMS an hour ago were there any adapters running reflection? It looks like the deltas were working fine (admittedly with no changes present) in the logs earlier when reflection wasn't running. Have you only started experiencing timeouts again now that you have three adapters running reflection? Note that reflection triggering would also indicate that connector imports were ran - all of these operations (connector imports, adapter reflection and FIM deltas) share a single resource lock, which could definitely cause timeouts if any or all of the operations deal with large numbers.

Not as far as I know. I had done nothing that would cause reflection (as far as I know). Event broker is stopped so nothing is currently happening on the system. I ran the delta import from fim at 12:20. When I came back from lunch there were 4 failed reflection messages in the log, all with 15 minute timeout error at 12:35, 12:50, 13:05 and 13:20. Since then the first adapter has failed again at 13:35 and the second one at 13:50, so it seems to be a continuous process every 15 mins now. Is there a regular reflection process that runs under the covers? I cannot see why it would have happened otherwise. I did try to force reflection on one of the smaller adapters by selecting action generate changes. that now has 13468 entity count and 13468 pending, but nothing in the logs indicates that anything tried to do anything.

I am getting very concerned that I cannot get this to behave as expected in MPE as I need successful test results if we are going to be able to roll this to production, but at the moment I do not seem able to make it do anything but throw errors.

Should I remove all patches and go back to the base install and start again?

Hi Eddie, Can you please email through the logs again so I can see what might be causing reflection to trigger?

Hi Curtis - will do.

I have left it alone and see reflection failed (15 min timeout at 13:50 and 14:05). then at 14:14 I got:

Handling of LDAP change log request.
Handling of LDAP change log request from user IdBAPPProxy on connection 127.0.0.1:12171 failed with error "The transaction has aborted.". Duration: 01:53:27.6071307.

followed by:

An error occurred on client from 127.0.0.1:12171. More details:
Internal Server Error #11: System.Transactions.TransactionAbortedException: The transaction has aborted. ---> System.TimeoutException: Transaction Timeout
--- End of inner exception stack trace ---
at System.Transactions.TransactionStateAborted.BeginCommit(InternalTransaction tx, Boolean asyncCommit, AsyncCallback asyncCallback, Object asyncState)
at System.Transactions.CommittableTransaction.Commit()
at System.Transactions.TransactionScope.InternalDispose()
at System.Transactions.TransactionScope.Dispose()
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()

and then

Request to reflect change entities of the adapter.
Request to reflect change entities of the CAMSGeneric (30914957-d066-4f84-97e7-5c29d652d120) adapter completed with 0 adds, 13468 updates and 0 deletes across 5 pages. Duration: 00:14:52.0704000

At the moment my dashboard shows no alerts and none of my adapters have pending changes.

Hi Eddie,

It turns out there is an unnecessary acquisition of the lock during reflection in the case that there are actually no changes to process. I've attached Unify.IdentityBroker.Adapter.dll which bypasses the lock acquisition for this case, so you shouldn't see reflection timing out for this scenario. Note that you will still need to be careful of processing actual changes concurrently with a change log request. While I was investigating I confirmed that the change log request handler does release the lock between its own paging (distinct from the LDAP paging, similar to how other parts of IDB having auto-scaling paging to deal with large volumes of data efficiently), so it is not the case that the lock is held for the full duration of the change log request.

Hi Eddie,

What sort of behaviour have you experienced since putting the patch in?