On transaction timeout, cleanup code throws an InvalidOperationException on SequencedHashMap.OrderedEnumerator.MoveNext
Description
Environment
is duplicated by
is related to
Activity
Frédéric DelaporteJuly 12, 2018 at 10:04 AM
Moved here.
This has likely been fixed NH-4011, v5.0.
Among the work done there, a synchronization point was introduced in the session handling after scope disposal for avoiding concurrency issues due to MsDTC distributed transactions.
Closing this as obsoleted. Please reopen it if it is reproduced with NH v5.0 or later.
Frédéric DelaporteJune 29, 2017 at 5:15 PMEdited
May someone provides a test case reproducing the issue with NHibernate?
Some rework is done on system transaction handling, which should remove concurrency issues. It would be better to ascertain this with test case reproducing encountered issues such as this one.
Currently, I only see code for demonstrating the asynchronism of MSDTC.
Brian HartsockSeptember 1, 2010 at 7:51 AMEdited
I have the same issue and have some logs that expose the problem.
NHibernate is assuming that the thread that handles TransactionCompleted and IEnlistmentNotification is the same thread where the TransactionScope is created. This isn't the case. I took Ayende's example http://ayende.com/Blog/archive/2010/05/29/who-stole-my-transaction.aspx and modified it to include an NHibernate session (also added some logging)
public class EnlistmentTracking : IEnlistmentNotification
{
public static int EnlistmentCounts;
private readonly int id;
public EnlistmentTracking(int id)
{
this.id = id;
Interlocked.Increment(ref EnlistmentCounts);
}
public void Prepare(PreparingEnlistment preparingEnlistment)
{
Console.WriteLine(id + " [" + Thread.CurrentThread.ManagedThreadId + "] - Prepare");
preparingEnlistment.Prepared();
}
public void Commit(Enlistment enlistment)
{
Console.WriteLine(id + " [" + Thread.CurrentThread.ManagedThreadId + "] - Committ");
Interlocked.Decrement(ref EnlistmentCounts);
enlistment.Done();
}
public void Rollback(Enlistment enlistment)
{
Console.WriteLine(id + " [" + Thread.CurrentThread.ManagedThreadId + "] - Rollback");
Interlocked.Decrement(ref EnlistmentCounts);
enlistment.Done();
}
public void InDoubt(Enlistment enlistment)
{
Console.WriteLine(id + " [" + Thread.CurrentThread.ManagedThreadId + "] - InDoubt");
Interlocked.Decrement(ref EnlistmentCounts);
enlistment.Done();
}
}
[Test]
public void ayendestestcase()
{
var newGuid = Guid.NewGuid();
for (int i = 0; i < 100; i++)
{
ISession session = null;
using (var tx = new TransactionScope())
{
Transaction.Current.EnlistDurable(newGuid, new EnlistmentTracking(i), EnlistmentOptions.None);
session = sessionFactory1.OpenSession();
session.Save(new Person()
{
Name = "Brian Hartsock" + i
});
session.Flush();
tx.Complete();
}
session.Close();
Console.WriteLine(i + " [" + Thread.CurrentThread.ManagedThreadId + "] - done");
Console.WriteLine(Thread.VolatileRead(ref EnlistmentTracking.EnlistmentCounts));
}
}Which printed the following logs:
2010-09-01 09:50:21,416 [TestRunnerThread] DEBUG NHibernate.Impl.SessionImpl [(null)] - [session-id=08233ec8-6579-4157-a4e5-9bc5f7746a45] opened session at timestamp: 634189314214, for session factory: [/52a51deef9884d9da4303eb2944b97d5]
2010-09-01 09:50:21,417 [TestRunnerThread] DEBUG NHibernate.Impl.AbstractSessionImpl [(null)] - enlisted into DTC transaction: Serializable
2010-09-01 09:50:21,417 [TestRunnerThread] DEBUG NHibernate.Event.Default.DefaultSaveOrUpdateEventListener [(null)] - saving transient instance
2010-09-01 09:50:21,421 [TestRunnerThread] DEBUG NHibernate.Event.Default.AbstractSaveEventListener [(null)] - saving [NHibernateDTC.Person#<null>]
2010-09-01 09:50:21,421 [TestRunnerThread] DEBUG NHibernate.Event.Default.AbstractSaveEventListener [(null)] - executing insertions
2010-09-01 09:50:21,422 [TestRunnerThread] DEBUG NHibernate.Event.Default.AbstractSaveEventListener [(null)] - executing identity-insert immediately
2010-09-01 09:50:21,423 [TestRunnerThread] DEBUG NHibernate.Persister.Entity.AbstractEntityPersister [(null)] - Inserting entity: NHibernateDTC.Person (native id)
2010-09-01 09:50:21,423 [TestRunnerThread] DEBUG NHibernate.AdoNet.AbstractBatcher [(null)] - Opened new IDbCommand, open IDbCommands: 1
2010-09-01 09:50:21,424 [TestRunnerThread] DEBUG NHibernate.AdoNet.AbstractBatcher [(null)] - Building an IDbCommand object for the SqlString: INSERT INTO person (person_name) VALUES (?)
2010-09-01 09:50:21,425 [TestRunnerThread] DEBUG NHibernate.Persister.Entity.AbstractEntityPersister [(null)] - Dehydrating entity: [NHibernateDTC.Person#<null>]
2010-09-01 09:50:21,426 [TestRunnerThread] DEBUG NHibernate.Type.StringType [(null)] - binding 'Brian Hartsock97' to parameter: 0
2010-09-01 09:50:21,426 [TestRunnerThread] DEBUG NHibernate.SQL [(null)] - INSERT INTO person (person_name) VALUES (?p0);?p0 = 'Brian Hartsock97'
2010-09-01 09:50:21,427 [TestRunnerThread] DEBUG NHibernate.Connection.DriverConnectionProvider [(null)] - Obtaining IDbConnection from Driver
2010-09-01 09:50:21,429 [TestRunnerThread] DEBUG NHibernate.AdoNet.AbstractBatcher [(null)] - ExecuteNonQuery took 0 ms
2010-09-01 09:50:21,429 [TestRunnerThread] DEBUG NHibernate.AdoNet.AbstractBatcher [(null)] - Closed IDbCommand, open IDbCommands: 0
2010-09-01 09:50:21,430 [TestRunnerThread] DEBUG NHibernate.AdoNet.AbstractBatcher [(null)] - Opened new IDbCommand, open IDbCommands: 1
2010-09-01 09:50:21,430 [TestRunnerThread] DEBUG NHibernate.AdoNet.AbstractBatcher [(null)] - Building an IDbCommand object for the SqlString: SELECT LAST_INSERT_ID()
2010-09-01 09:50:21,431 [TestRunnerThread] DEBUG NHibernate.SQL [(null)] - SELECT LAST_INSERT_ID()
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.AdoNet.AbstractBatcher [(null)] - ExecuteReader took 0 ms
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.AdoNet.AbstractBatcher [(null)] - Opened IDataReader, open IDataReaders: 1
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.Type.Int32Type [(null)] - returning '98' as column: LAST_INSERT_ID()
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.Id.IdentifierGeneratorFactory [(null)] - Natively generated identity: 98
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.Driver.NHybridDataReader [(null)] - running NHybridDataReader.Dispose()
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.AdoNet.AbstractBatcher [(null)] - Closed IDataReader, open IDataReaders :0
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.AdoNet.AbstractBatcher [(null)] - DataReader was closed after 0 ms
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.AdoNet.AbstractBatcher [(null)] - Closed IDbCommand, open IDbCommands: 0
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - flushing session
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - processing flush-time cascades
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - dirty checking collections
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - Flushing entities and processing referenced collections
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - Processing unreferenced collections
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - Scheduling collection removes/(re)creates/updates
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.Impl.Printer [(null)] - listing entities:
2010-09-01 09:50:21,432 [TestRunnerThread] DEBUG NHibernate.Impl.Printer [(null)] - NHibernateDTC.Person{'Id'='98', 'Name'='Brian Hartsock97'}
2010-09-01 09:50:21,442 [TestRunnerThread] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - executing flush
2010-09-01 09:50:21,442 [TestRunnerThread] DEBUG NHibernate.AdoNet.ConnectionManager [(null)] - registering flush begin
2010-09-01 09:50:21,443 [TestRunnerThread] DEBUG NHibernate.AdoNet.ConnectionManager [(null)] - registering flush end
2010-09-01 09:50:21,444 [TestRunnerThread] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - post flush
2010-09-01 09:50:21,444 [6] DEBUG NHibernate.Impl.SessionImpl [(null)] - before transaction completion
2010-09-01 09:50:21,445 [6] DEBUG NHibernate.Impl.AbstractSessionImpl [(null)] - [session-id=08233ec8-6579-4157-a4e5-9bc5f7746a45] Flushing from Dtc Transaction
2010-09-01 09:50:21,445 [6] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - flushing session
2010-09-01 09:50:21,446 [6] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - processing flush-time cascades
2010-09-01 09:50:21,446 [6] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - dirty checking collections
2010-09-01 09:50:21,447 [6] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - Flushing entities and processing referenced collections
2010-09-01 09:50:21,447 [6] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - Processing unreferenced collections
2010-09-01 09:50:21,449 [6] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - Scheduling collection removes/(re)creates/updates
2010-09-01 09:50:21,449 [6] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
2010-09-01 09:50:21,450 [6] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2010-09-01 09:50:21,450 [6] DEBUG NHibernate.Impl.Printer [(null)] - listing entities:
2010-09-01 09:50:21,451 [6] DEBUG NHibernate.Impl.Printer [(null)] - NHibernateDTC.Person{'Id'='98', 'Name'='Brian Hartsock97'}
2010-09-01 09:50:21,451 [6] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - executing flush
2010-09-01 09:50:21,452 [6] DEBUG NHibernate.AdoNet.ConnectionManager [(null)] - registering flush begin
2010-09-01 09:50:21,452 [6] DEBUG NHibernate.AdoNet.ConnectionManager [(null)] - registering flush end
2010-09-01 09:50:21,453 [6] DEBUG NHibernate.Event.Default.AbstractFlushingEventListener [(null)] - post flush
2010-09-01 09:50:21,453 [6] DEBUG NHibernate.Impl.AbstractSessionImpl [(null)] - prepared for DTC transaction
97 [6] - Prepare
2010-09-01 09:50:21,465 [6] DEBUG NHibernate.Impl.SessionImpl [(null)] - transaction completion
2010-09-01 09:50:21,465 [6] DEBUG NHibernate.AdoNet.ConnectionManager [(null)] - aggressively releasing database connection
2010-09-01 09:50:21,465 [6] DEBUG NHibernate.Connection.ConnectionProvider [(null)] - Closing connection
2010-09-01 09:50:21,465 [TestRunnerThread] DEBUG NHibernate.Impl.SessionImpl [(null)] - closing session
2010-09-01 09:50:21,465 [TestRunnerThread] DEBUG NHibernate.AdoNet.AbstractBatcher [(null)] - running BatcherImpl.Dispose(true)
97 [12] - done
1As you can see (the thread IDs are in []), the thread the callbacks are happening in is not TestRunnerThread. This doesn't reproduce the above problem, but exposes the fact that ISession is not thread safe and therefore distributed transactions can break.
(Another important thing to note, I have only seen this behavior when working with MySQL, and the above is with Oracle. Maybe that points to non-SQL Server drivers as part of the problem)
Simon SøndergaardAugust 16, 2010 at 3:44 AM
Even if one assumes that the IEnlistmentNotification.{Rollback()|InDoubt()} are called before (and on same thread as the delegate) I still think the code suspitions as session.AfterTransactionCompletion will be called twice.
should read:
Even if one assumes that the IEnlistmentNotification.{Rollback()|InDoubt()} are called before the delegate (and on same thread as the delegate) I still think the code suspitions as session.AfterTransactionCompletion will be called twice.
Simon SøndergaardAugust 16, 2010 at 2:04 AMEdited
We are currently seeing the same issue. We have encountered the same stacktrace a few times now 
Here is what I think is happening:
In EnlistInDistributedTransactionIfNeeded():
1) subscribe to TransactionCompleted with delegate that will call session.AfterTransactionCompletion()
2) we enlist a DistributedTransactionContext in the transaction, on Rollback() and InDoubt() session.AfterTransactionCompletion()
will be called.
Even if one assumes that the IEnlistmentNotification.Rollback()|InDoubt() are called before (and on same thread as the delegate) I still think the code suspicions as session.AfterTransactionCompletion will be called twice.
As you may have guessed I think the assumption about the ordering (and same thread) is not correct given the current implementation of MS DTC.
After reading this http://msdn.microsoft.com/en-us/library/ms678837(v=VS.85).aspx im convinced that is does NOT support synchronous executing phase two of the two-phase commit protocol. This suspicion has been confirmed by observations in the project im currently working on and by Ayende (See: http://ayende.com/Blog/archive/2010/05/29/who-stole-my-transaction.aspx).
I think the stacktrace above is caused by a thread executing 2) while another thread has already started executing 1).
This Friday we encountered this stacktrace:
at NHibernate.Util.SequencedHashMap.OrderedEnumerator.MoveNext()
at NHibernate.Engine.StatefulPersistenceContext.AfterTransactionCompletion()
at NHibernate.Impl.SessionImpl.AfterTransactionCompletion(Boolean success, ITransaction tx)
at NHibernate.Transaction.AdoNetWithDistrubtedTransactionFactory.<>c__DisplayClass1.<EnlistInDistributedTransactionIfNeeded>b__0(Object sender, TransactionEventArgs e)
at System.Transactions.TransactionCompletedEventHandler.Invoke(Object sender, TransactionEventArgs e)
at System.Transactions.InternalTransaction.FireCompletion()
at System.Transactions.TransactionStateAborted.EnterState(InternalTransaction tx)
at System.Transactions.TransactionStateActive.Rollback(InternalTransaction tx, Exception e)
at System.Transactions.EnlistableStates.Timeout(InternalTransaction tx)
at System.Transactions.Bucket.TimeoutTransactions()
at System.Transactions.BucketSet.TimeoutTransactions()
at System.Transactions.TransactionTable.ThreadTimer(Object state)
at System.Threading._TimerCallback.TimerCallback_Context(Object state)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading._TimerCallback.PerformTimerCallback(Object state)Most likely this is caused by 2) getting ahead of 1)
Br,
/Simon
Unfortunately this doesn't consistently happen and I couldn't recreate a sample project that would demonstrate this problem. But from reading through the stacktrace, looks like transaction timeout causes the cleanup handler to be executed on a separate timer thread, which is trying to enumerate a HashMap that's modified by the thread that is still fetching data.
System.InvalidOperationException: Enumerator was modified at NHibernate.Util.SequencedHashMap.OrderedEnumerator.MoveNext() at NHibernate.Engine.StatefulPersistenceContext.AfterTransactionCompletion() at NHibernate.Impl.SessionImpl.AfterTransactionCompletion(Boolean success, ITransaction tx) at NHibernate.Transaction.AdoNetWithDistrubtedTransactionFactory.DistributedTransactionContext.System.Transactions.IEnlistmentNotification.Rollback(Enlistment enlistment) at System.Transactions.VolatileEnlistmentAborting.EnterState(InternalEnlistment enlistment) at System.Transactions.VolatileEnlistmentActive.InternalAborted(InternalEnlistment enlistment) at System.Transactions.TransactionStateAborted.EnterState(InternalTransaction tx) at System.Transactions.TransactionStateActive.Rollback(InternalTransaction tx, Exception e) at System.Transactions.EnlistableStates.Timeout(InternalTransaction tx) at System.Transactions.Bucket.TimeoutTransactions() at System.Transactions.BucketSet.TimeoutTransactions() at System.Transactions.TransactionTable.ThreadTimer(Object state) at System.Threading._TimerCallback.TimerCallback_Context(Object state) at System.Threading.ExecutionContext.runTryCode(Object userData) at System.Runtime.CompilerServices.RuntimeHelpers.ExecuteCodeWithGuaranteedCleanup(TryCode code, CleanupCode backoutCode, Object userData) at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) at System.Threading._TimerCallback.PerformTimerCallback(Object state)I am using NHibernate.Driver.OracleDataClientDriver with ODP.NET 10.2.