1. UNIFYBroker Forum
  2. Bugs
0
Fixed

Potential issue with changes register being cleared regardless of delta import success

Matthew Clark 13 years ago • updated by anonymous 8 years ago • 2

At QDET in a mirror production environment we recently saw an issue around the changes register of Identity Broker. A full import was running on a large connector (500000~ users) where 40 changes in the target system were present. The Identity Broker Changes Plug-in detected a change during the import process and kicked off two delta imports into FIM. Possibly due to poor infrastructure or heavy database server load, the delta imports failed - logs below:

20111013,05:28:02,Adapter request to get attribute changes from adapter space.,Adapter,Information,Adapter request to get attribute changes from adapter space 53e85508-7648-409c-b451-0769028bba70.,Normal
20111013,05:28:05,Started processing changes register items.,Change detection engine,Information,Started processing changes register items for connector IRegister Person.,Normal
20111013,05:28:05,Changes register item processing completed.,Change detection engine,Information,Changes register item processing on connector IRegister Person completed. Duration: 00:00:00.0937500,Normal
20111013,05:28:41,Adapter request to get entity from adapter space failed.,Adapter,Warning,"Adapter request to get attribute changes from adapter space 53e85508-7648-409c-b451-0769028bba70 failed with reason The transaction is in doubt.. Duration: 00:00:39.3281250
Error details:
System.Transactions.TransactionInDoubtException: The transaction is in doubt. ---> System.Data.SqlClient.SqlException: Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)
at System.Data.SqlClient.TdsParserStateObject.ReadSni(DbAsyncResult asyncResult, TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParserStateObject.ReadNetworkPacket()
at System.Data.SqlClient.TdsParserStateObject.ReadBuffer()
at System.Data.SqlClient.TdsParserStateObject.ReadByte()
at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParser.TdsExecuteTransactionManagerRequest(Byte[] buffer, TransactionManagerRequestType request, String transactionName, TransactionManagerIsolationLevel isoLevel, Int32 timeout, SqlInternalTransaction transaction, TdsParserStateObject stateObj, Boolean isDelegateControlRequest)
at System.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransactionYukon(TransactionRequest transactionRequest, String transactionName, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
at System.Data.SqlClient.SqlDelegatedTransaction.SinglePhaseCommit(SinglePhaseEnlistment enlistment)
— End of inner exception stack trace —
at System.Transactions.TransactionStatePromotedIndoubt.PromotedTransactionOutcome(InternalTransaction tx)
at System.Transactions.CommittableTransaction.Commit()
at System.Transactions.TransactionScope.InternalDispose()
at System.Transactions.TransactionScope.Dispose()
at Unify.Framework.UnifyTransactionScope.Dispose()
at Unify.Data.LinqContextConversionBase`4.SubmitChanges()
at Unify.Repository.AdapterEntityPartitionUpdatableContextAdapter.SubmitChanges()
at Unify.Framework.Adapter.ProcessAttributeChangePage(IEnumerable`1 pageOfChangedIds)
at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
at Unify.Framework.EnumerableExtensions.<ActionOnLast>d__16`1.MoveNext()
at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
at Unify.Framework.EnumerableExtensions.<ActionOnFirst>d__1c`1.MoveNext()
at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
at Unify.Framework.ActionOnExceptionEnumerator`1.MoveNext()
at Unify.Framework.EnumerableExtensions.<ActionOnLast>d__16`1.MoveNext()
at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
at System.Linq.Enumerable.<ConcatIterator>d__71`1.MoveNext()
at Unify.Framework.LDIFComponentFileGenerator`1.GenerateFile(TextWriter writer, IEnumerable`1 entries)
at Unify.Framework.LDIFAdapter.<>c_DisplayClass5`1.<CreateLDIFComponentStream>b_4(Stream stream)
at Unify.Framework.LazyEvaluationStream.Evaluate(Object obj)",Normal
20111013,05:28:50,Connector processing success.,Connector Processor,Information,"Processing page 8 for connector IRegister Person processed 1875 entities, finding 5 differences. Duration: 00:00:48.6562500",Normal
20111013,05:28:50,Connector Processing started.,Connector Processor,Information,Connector Processing started for connector IRegister Person (page 9),Normal
20111013,05:28:50,Started processing changes register items.,Change detection engine,Information,Started processing changes register items for connector IRegister Person.,Normal
20111013,05:28:52,Changes register item processing completed.,Change detection engine,Information,Changes register item processing on connector IRegister Person completed. Duration: 00:00:01.5000000,Normal
20111013,05:28:54,Adapter request to get attribute changes from adapter space.,Adapter,Information,Adapter request to get attribute changes from adapter space 53e85508-7648-409c-b451-0769028bba70.,Normal
20111013,05:28:56,Connector processing success.,Connector Processor,Information,"Processing page 9 for connector IRegister Person processed 2000 entities, finding 0 differences. Duration: 00:00:06.1718750",Normal
20111013,05:28:56,Connector Processing started.,Connector Processor,Information,Connector Processing started for connector IRegister Person (page 10),Normal
20111013,05:28:56,Get all entities from connector completed.,Connector,Information,Get all entities from connector IRegister Person return 18412 entities. Duration: 00:02:01.6875000,Normal
20111013,05:29:10,Connector processing success.,Connector Processor,Information,"Processing page 10 for connector IRegister Person processed 1900 entities, finding 0 differences. Duration: 00:00:13.6093750",Normal
20111013,05:29:10,Connector Processing started.,Connector Processor,Information,Connector Processing started for connector IRegister Person (page 11),Normal
20111013,05:29:14,Connector processing success.,Connector Processor,Information,"Processing page 11 for connector IRegister Person processed 1012 entities, finding 0 differences. Duration: 00:00:04.3281250",Normal
20111013,05:29:32,Adapter request to get entity from adapter space failed.,Adapter,Warning,"Adapter request to get attribute changes from adapter space 53e85508-7648-409c-b451-0769028bba70 failed with reason The transaction is in doubt.. Duration: 00:00:38.0937500
Error details:
System.Transactions.TransactionInDoubtException: The transaction is in doubt. ---> System.Data.SqlClient.SqlException: Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)
at System.Data.SqlClient.TdsParserStateObject.ReadSni(DbAsyncResult asyncResult, TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParserStateObject.ReadNetworkPacket()
at System.Data.SqlClient.TdsParserStateObject.ReadBuffer()
at System.Data.SqlClient.TdsParserStateObject.ReadByte()
at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParser.TdsExecuteTransactionManagerRequest(Byte[] buffer, TransactionManagerRequestType request, String transactionName, TransactionManagerIsolationLevel isoLevel, Int32 timeout, SqlInternalTransaction transaction, TdsParserStateObject stateObj, Boolean isDelegateControlRequest)
at System.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransactionYukon(TransactionRequest transactionRequest, String transactionName, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
at System.Data.SqlClient.SqlDelegatedTransaction.SinglePhaseCommit(SinglePhaseEnlistment enlistment)
— End of inner exception stack trace —
at System.Transactions.TransactionStatePromotedIndoubt.PromotedTransactionOutcome(InternalTransaction tx)
at System.Transactions.CommittableTransaction.Commit()
at System.Transactions.TransactionScope.InternalDispose()
at System.Transactions.TransactionScope.Dispose()
at Unify.Framework.UnifyTransactionScope.Dispose()
at Unify.Data.LinqContextConversionBase`4.SubmitChanges()
at Unify.Repository.AdapterEntityPartitionUpdatableContextAdapter.SubmitChanges()
at Unify.Framework.Adapter.ProcessAttributeChangePage(IEnumerable`1 pageOfChangedIds)
at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
at Unify.Framework.EnumerableExtensions.<ActionOnLast>d__16`1.MoveNext()
at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
at Unify.Framework.EnumerableExtensions.<ActionOnFirst>d__1c`1.MoveNext()
at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
at Unify.Framework.ActionOnExceptionEnumerator`1.MoveNext()
at Unify.Framework.EnumerableExtensions.<ActionOnLast>d__16`1.MoveNext()
at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
at System.Linq.Enumerable.<ConcatIterator>d__71`1.MoveNext()
at Unify.Framework.LDIFComponentFileGenerator`1.GenerateFile(TextWriter writer, IEnumerable`1 entries)
at Unify.Framework.LDIFAdapter.<>c_DisplayClass5`1.<CreateLDIFComponentStream>b_4(Stream stream)
at Unify.Framework.LazyEvaluationStream.Evaluate(Object obj)",Normal
20111013,05:29:35,Change detection engine import all items completed.,Change detection engine,Information,Change detection engine import all items for connector IRegister Person completed. Duration: 00:02:44.3593750,Normal
20111013,05:29:47,Adapter request to get attribute changes from adapter space.,Adapter,Information,Adapter request to get attribute changes from adapter space 53e85508-7648-409c-b451-0769028bba70.,Normal

Subsequent delta imports into FIM were successful, however, the import returned 0 results. This may suggest that the changes register is cleared regardless of the return state of a delta import. A full import into FIM was required to pick up the changed users.

Attempts to replicate this behaviour have so far been unsuccessful - the database is no longer timing out.

This is not a pressing issue as we have been unable to replicate yet (and may not be able to), but it would be worth investigating (for this or future versions) to prevent this from occurring again as the behaviour does incur operational intervention.

Adam van Vliet 12 years ago

Hi Matthew,

I attempted to recreate this issue in a test app, unsuccessfully. Additionally, from inspection on the code, it is hard to see how this would be possible. There may be something that was missed or not documented that was the cause of the issue.

We can revisit it if we are able to reproduce.

Thanks.

Matthew Clark 12 years ago

Closed as unreproducible without exact environmental effects.

Customer support service by UserEcho