NH-2237 - On transaction timeout, cleanup code throws an InvalidOperationException on SequencedHashMap.OrderedEnumerator.MoveNext

[nhibernate-bot]

Daniel Jin created an issue — 12th July 2010, 13:56:05:

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.

---

Fabio Maulo added a comment — 14th August 2010, 7:37:08:

Are you sharing the same Session with more than one thread ?

---

Simon Søndergaard added a comment — 16th August 2010, 2:04:58:

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

---

Simon Søndergaard added a comment — 16th August 2010, 3:44:39:

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.

---

Brian Hartsock added a comment — 1st September 2010, 7:51:36:

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 <ins> " <" </ins> Thread.CurrentThread.ManagedThreadId <ins> "> - Prepare"); 
        preparingEnlistment.Prepared(); 
    } 

    public void Commit(Enlistment enlistment) 
    { 
        Console.WriteLine(id </ins> " <" <ins> Thread.CurrentThread.ManagedThreadId </ins> "> - Committ"); 
        Interlocked.Decrement(ref EnlistmentCounts); 
        enlistment.Done(); 
    } 

    public void Rollback(Enlistment enlistment) 
    { 
        Console.WriteLine(id <ins> " <" </ins> Thread.CurrentThread.ManagedThreadId <ins> "> - Rollback"); 
        Interlocked.Decrement(ref EnlistmentCounts); 
        enlistment.Done(); 
    } 

    public void InDoubt(Enlistment enlistment) 
    { 
        Console.WriteLine(id </ins> " <" <ins> Thread.CurrentThread.ManagedThreadId </ins> "> - InDoubt"); 
        Interlocked.Decrement(ref EnlistmentCounts); 
        enlistment.Done(); 
    } 
} 

<Test> 
public void ayendestestcase() 
{ 
    var newGuid = Guid.NewGuid(); 
    for (int i = 0; i < 100; i<ins></ins>) 
    { 
        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" <ins> i 
            }); 
            session.Flush(); 
             

            tx.Complete(); 
        } 
        session.Close(); 

        Console.WriteLine(i </ins> " <" <ins> Thread.CurrentThread.ManagedThreadId </ins> "> - 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 
1 

As 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)

---

Frédéric Delaporte added a comment — 29th June 2017, 17:15:54:

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.

[fredericDelaporte]

This has likely been fixed with #627 (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.