Error during processing of SearchRequest targetting cn=changelog: Operation timed out
The following 3 exceptions were logged today in the Application Event log for a failed MIM DI run profle against an IdB adapter:
<p style="margin-top:5pt;margin-bottom:5pt;font-family:Calibri;font-size:11.0pt"><span lang="en-US">Log Name: Application</span><span lang="en-AU"><br> </span><span lang="en-US">Source: FIMSynchronizationService</span><span lang="en-AU"><br> </span><span lang="en-US">Date: 5/07/2017 12:44:09 PM</span><span lang="en-AU"><br> </span><span lang="en-US">Event ID: 6110</span><span lang="en-AU"><br> </span><span lang="en-US">Task Category: Management Agent Run Profile</span><span lang="en-AU"><br> </span><span lang="en-US">Level: Warning</span><span lang="en-AU"><br> </span><span lang="en-US">Keywords: Classic</span><span lang="en-AU"><br> </span><span lang="en-US">User: N/A</span><span lang="en-AU"><br> </span><span lang="en-US">Computer: AUHBSMIMWP0001.corp.qbe.com</span><span lang="en-AU"><br> </span><span lang="en-US">Description:</span><span lang="en-AU"><br> </span><span lang="en-US">The management agent "License Entitlements" step execution completed on run profile "DI" but the watermark was not saved.</span><span lang="en-AU"><br> </span><span lang="en-US"> </span><span lang="en-AU"><br> </span><span lang="en-US"> Additional Information</span><span lang="en-AU"><br> </span><span lang="en-US"> Discovery Errors : "0"</span><span lang="en-AU"><br> </span><span lang="en-US"> Synchronization Errors : "0"</span><span lang="en-AU"><br> </span><span lang="en-US"> Metaverse Retry Errors : "0"</span><span lang="en-AU"><br> </span><span lang="en-US"> Export Errors : "0"</span><span lang="en-AU"><br> </span><span lang="en-US"> Warnings : "0"</span><span lang="en-AU"><br> </span><span lang="en-US"> </span><span lang="en-AU"><br> </span><span lang="en-US"> User Action</span><span lang="en-AU"><br> </span><span lang="en-US"> View the management agent run history for details.</span><span lang="en-AU"><br> </span><span lang="en-US">Event Xml:</span><span lang="en-AU"><br> </span><span lang="en-US"><Event xmlns="</span><a href="http://schemas.microsoft.com/win/2004/08/events/event"><span lang="en-US">http://schemas.microsoft.com/win/2004/08/events/event</span></a><span lang="en-US">"></span><span lang="en-AU"><br> </span><span lang="en-US"> <System></span><span lang="en-AU"><br> </span><span lang="en-US"> <Provider Name="FIMSynchronizationService" /></span><span lang="en-AU"><br> </span><span lang="en-US"> <EventID Qualifiers="32768">6110</EventID></span><span lang="en-AU"><br> </span><span lang="en-US"> <Level>3</Level></span><span lang="en-AU"><br> </span><span lang="en-US"> <Task>1</Task></span><span lang="en-AU"><br> </span><span lang="en-US"> <Keywords>0x80000000000000</Keywords></span><span lang="en-AU"><br> </span><span lang="en-US"> <TimeCreated SystemTime="2017-07-05T02:44:09.000000000Z" /></span><span lang="en-AU"><br> </span><span lang="en-US"> <EventRecordID>9375144</EventRecordID></span><span lang="en-AU"><br> </span><span lang="en-US"> <Channel>Application</Channel></span><span lang="en-AU"><br> </span><span lang="en-US"> <Computer>AUHBSMIMWP0001.corp.qbe.com</Computer></span><span lang="en-AU"><br> </span><span lang="en-US"> <Security /></span><span lang="en-AU"><br> </span><span lang="en-US"> </System></span><span lang="en-AU"><br> </span><span lang="en-US"> <EventData></span><span lang="en-AU"><br> </span><span lang="en-US"> <Data>License Entitlements</Data></span><span lang="en-AU"><br> </span><span lang="en-US"> <Data>DI</Data></span><span lang="en-AU"><br> </span><span lang="en-US"> <Data>0</Data></span><span lang="en-AU"><br> </span><span lang="en-US"> <Data>0</Data></span><span lang="en-AU"><br> </span><span lang="en-US"> <Data>0</Data></span><span lang="en-AU"><br> </span><span lang="en-US"> <Data>0</Data></span><span lang="en-AU"><br> </span><span lang="en-US"> <Data>0</Data></span><span lang="en-AU"><br> </span><span lang="en-US"> </EventData></span><span lang="en-AU"><br> </span><span lang="en-US"></Event></span></p> <p style="margin-top:5pt;margin-bottom:5pt;font-family:Calibri;font-size:11.0pt"><span lang="en-US">Log Name: Application</span><span lang="en-AU"><br> </span><span lang="en-US">Source: FIMSynchronizationService</span><span lang="en-AU"><br> </span><span lang="en-US">Date: 5/07/2017 12:44:09 PM</span><span lang="en-AU"><br> </span><span lang="en-US">Event ID: 6803</span><span lang="en-AU"><br> </span><span lang="en-US">Task Category: Management Agent Run Profile</span><span lang="en-AU"><br> </span><span lang="en-US">Level: Error</span><span lang="en-AU"><br> </span><span lang="en-US">Keywords: Classic</span><span lang="en-AU"><br> </span><span lang="en-US">User: N/A</span><span lang="en-AU"><br> </span><span lang="en-US">Computer: AUHBSMIMWP0001.corp.qbe.com</span><span lang="en-AU"><br> </span><span lang="en-US">Description:</span><span lang="en-AU"><br> </span><span lang="en-US">The management agent "License Entitlements" failed on run profile "DI" because the server encountered errors.</span><span lang="en-AU"><br> </span><span lang="en-US">Event Xml:</span><span lang="en-AU"><br> </span><span lang="en-US"><Event xmlns="</span><a href="http://schemas.microsoft.com/win/2004/08/events/event"><span lang="en-US">http://schemas.microsoft.com/win/2004/08/events/event</span></a><span lang="en-US">"></span><span lang="en-AU"><br> </span><span lang="en-US"> <System></span><span lang="en-AU"><br> </span><span lang="en-US"> <Provider Name="FIMSynchronizationService" /></span><span lang="en-AU"><br> </span><span lang="en-US"> <EventID Qualifiers="49152">6803</EventID></span><span lang="en-AU"><br> </span><span lang="en-US"> <Level>2</Level></span><span lang="en-AU"><br> </span><span lang="en-US"> <Task>1</Task></span><span lang="en-AU"><br> </span><span lang="en-US"> <Keywords>0x80000000000000</Keywords></span><span lang="en-AU"><br> </span><span lang="en-US"> <TimeCreated SystemTime="2017-07-05T02:44:09.000000000Z" /></span><span lang="en-AU"><br> </span><span lang="en-US"> <EventRecordID>9375143</EventRecordID></span><span lang="en-AU"><br> </span><span lang="en-US"> <Channel>Application</Channel></span><span lang="en-AU"><br> </span><span lang="en-US"> <Computer>AUHBSMIMWP0001.corp.qbe.com</Computer></span><span lang="en-AU"><br> </span><span lang="en-US"> <Security /></span><span lang="en-AU"><br> </span><span lang="en-US"> </System></span><span lang="en-AU"><br> </span><span lang="en-US"> <EventData></span><span lang="en-AU"><br> </span><span lang="en-US"> <Data>License Entitlements</Data></span><span lang="en-AU"><br> </span><span lang="en-US"> <Data>DI</Data></span><span lang="en-AU"><br> </span><span lang="en-US"> </EventData></span><span lang="en-AU"><br> </span><span lang="en-US"></Event></span></p> <p style="margin-top:5pt;margin-bottom:5pt;font-family:Calibri;font-size:11.0pt"><span lang="en-US">Log Name: Application</span><span lang="en-AU"><br> </span><span lang="en-US">Source: FIMSynchronizationService</span><span lang="en-AU"><br> </span><span lang="en-US">Date: 5/07/2017 12:44:09 PM</span><span lang="en-AU"><br> </span><span lang="en-US">Event ID: 6801</span><span lang="en-AU"><br> </span><span lang="en-US">Task Category: Server</span><span lang="en-AU"><br> </span><span lang="en-US">Level: Error</span><span lang="en-AU"><br> </span><span lang="en-US">Keywords: Classic</span><span lang="en-AU"><br> </span><span lang="en-US">User: N/A</span><span lang="en-AU"><br> </span><span lang="en-US">Computer: AUHBSMIMWP0001.corp.qbe.com</span><span lang="en-AU"><br> </span><span lang="en-US">Description:</span><span lang="en-AU"><br> </span><span lang="en-US">The extensible extension returned an unsupported error.</span><span lang="en-AU"><br> </span><span lang="en-US"> The stack trace is:</span><span lang="en-AU"><br> </span><span lang="en-US"> </span><span lang="en-AU"><br> </span><span lang="en-US"> "Unify.Product.IdentityBroker.LdapOperationException: Error during processing of SearchRequest targetting cn=changelog: Operation timed out.</span><span lang="en-AU"><br> </span><span lang="en-US"> at Unify.Product.IdentityBroker.LdapConnection.SendRequest(ILdapRequest request)</span><span lang="en-AU"><br> </span><span lang="en-US"> at Unify.Product.IdentityBroker.LdapConnectionProxy.<SearchRequestPaged>d__9.MoveNext()</span><span lang="en-AU"><br> </span><span lang="en-US"> at Unify.Product.IdentityBroker.ImportProxy.<GetChangedEntriesPaged>d__33.MoveNext()</span><span lang="en-AU"><br> </span><span lang="en-US"> at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()</span><span lang="en-AU"><br> </span><span lang="en-US"> at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()</span><span lang="en-AU"><br> </span><span lang="en-US"> at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()</span><span lang="en-AU"><br> </span><span lang="en-US"> at Unify.Product.IdentityBroker.ExtensionMethods.Take[TSource](IEnumerator`1 source, Int32 count, IList`1& items)</span><span lang="en-AU"><br> </span><span lang="en-US"> at Unify.Product.IdentityBroker.ExtensionMethods.<Page>d__3`1.MoveNext()</span><span lang="en-AU"><br> </span><span lang="en-US"> at Unify.Product.IdentityBroker.ImportProxy.Import(GetImportEntriesRunStep importRunStep)</span><span lang="en-AU"><br> </span><span lang="en-US">Forefront Identity Manager 4.3.2195.0"</span><span lang="en-AU"><br> </span><span lang="en-US">Event Xml:</span><span lang="en-AU"><br> </span><span lang="en-US"><Event xmlns="</span><a href="http://schemas.microsoft.com/win/2004/08/events/event"><span lang="en-US">http://schemas.microsoft.com/win/2004/08/events/event</span></a><span lang="en-US">"></span><span lang="en-AU"><br> </span><span lang="en-US"> <System></span><span lang="en-AU"><br> </span><span lang="en-US"> <Provider Name="FIMSynchronizationService" /></span><span lang="en-AU"><br> </span><span lang="en-US"> <EventID Qualifiers="49152">6801</EventID></span><span lang="en-AU"><br> </span><span lang="en-US"> <Level>2</Level></span><span lang="en-AU"><br> </span><span lang="en-US"> <Task>3</Task></span><span lang="en-AU"><br> </span><span lang="en-US"> <Keywords>0x80000000000000</Keywords></span><span lang="en-AU"><br> </span><span lang="en-US"> <TimeCreated SystemTime="2017-07-05T02:44:09.000000000Z" /></span><span lang="en-AU"><br> </span><span lang="en-US"> <EventRecordID>9375142</EventRecordID></span><span lang="en-AU"><br> </span><span lang="en-US"> <Channel>Application</Channel></span><span lang="en-AU"><br> </span><span lang="en-US"> <Computer>AUHBSMIMWP0001.corp.qbe.com</Computer></span><span lang="en-AU"><br> </span><span lang="en-US"> <Security /></span><span lang="en-AU"><br> </span><span lang="en-US"> </System></span><span lang="en-AU"><br> </span><span lang="en-US"> <EventData></span><span lang="en-AU"><br> </span><span lang="en-US"> <Data>Unify.Product.IdentityBroker.LdapOperationException: Error during processing of SearchRequest targetting cn=changelog: Operation timed out.</span><span lang="en-AU"><br> </span><span lang="en-US"> at Unify.Product.IdentityBroker.LdapConnection.SendRequest(ILdapRequest request)</span><span lang="en-AU"><br> </span><span lang="en-US"> at Unify.Product.IdentityBroker.LdapConnectionProxy.<SearchRequestPaged>d__9.MoveNext()</span><span lang="en-AU"><br> </span><span lang="en-US"> at Unify.Product.IdentityBroker.ImportProxy.<GetChangedEntriesPaged>d__33.MoveNext()</span><span lang="en-AU"><br> </span><span lang="en-US"> at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()</span><span lang="en-AU"><br> </span><span lang="en-US"> at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()</span><span lang="en-AU"><br> </span><span lang="en-US"> at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()</span><span lang="en-AU"><br> </span><span lang="en-US"> at Unify.Product.IdentityBroker.ExtensionMethods.Take[TSource](IEnumerator`1 source, Int32 count, IList`1& items)</span><span lang="en-AU"><br> </span><span lang="en-US"> at Unify.Product.IdentityBroker.ExtensionMethods.<Page>d__3`1.MoveNext()</span><span lang="en-AU"><br> </span><span lang="en-US"> at Unify.Product.IdentityBroker.ImportProxy.Import(GetImportEntriesRunStep importRunStep)</span><span lang="en-AU"><br> </span><span lang="en-US">Forefront Identity Manager 4.3.2195.0</Data></span><span lang="en-AU"><br> </span><span lang="en-US"> </EventData></span><span lang="en-AU"><br> </span><span lang="en-US"></Event></span></p>
This is the first time I've seen a timeout occur for a DI to the change log - is there something that can be set specifically to mitigate this? So far indexing issues have impacted only full imports, but not deltas - and these are mitigated by daily index rebuilds.
Answer
Hi Bob,
Which version of Identity Broker is installed, and do you have any patches installed for Unify.IdentityBroker.ChangeLog.Repository.Sql.dll? As of Identity Broker v5.1, there should no longer be any SQL locking around access to the changelog context. This change will also be included in an upcoming Identity Broker v5.0 release, although it is not present in the current v5.0.5 RC1.
Curtis - version is v5.0.5 Revision #0, and no there is no patch in place for that DLL. We in a position to upgrade to the latest 5.0 version so please let me know when this is ready so we can install to DEV/UAT. Thanks.
please let me know when this is ready
Will do.
Related issue: Delta Import timeouts on Identity Broker 5.1 Management Agents
Customer support service by UserEcho
Hi Bob,
Which version of Identity Broker is installed, and do you have any patches installed for Unify.IdentityBroker.ChangeLog.Repository.Sql.dll? As of Identity Broker v5.1, there should no longer be any SQL locking around access to the changelog context. This change will also be included in an upcoming Identity Broker v5.0 release, although it is not present in the current v5.0.5 RC1.