TransactionScope leads to inconsistency with SQL Server (possibly any RDB with autocommit default behavior)

[inglun]

If ambient transaction (TransactionScope) times out during a Flush, changes can still be affectuated to the database. The premisis is that the connection to SQL Server is in autocommit mode (which is default).

The attached code has two tests, NHibernateBug and ObservedBehavior. The former exposes what I have encountered by halting processing in a custom interceptor (MyInterceptor). The latter is my "looks-like-this-is-happening-in-NHibernate" analysis. Look in the output from the tests too.

You can run NHiberneateBug with the "#if !true" changed to "#if true" and see that SET IMPLICIT_TRANSACTIONS ON is a workaround to the inconsistency problem.

using System;
using System.Data;
using System.Data.SqlClient;
using System.Threading;
using System.Transactions;
using System.Xml;
using Microsoft.VisualStudio.TestTools.UnitTesting;
using NHibernate;
using NHibernate.Cfg;
using NHibernate.SqlCommand;

namespace TransactionScopeTimeout {
    /*
CREATE TABLE T(
    Id uniqueidentifier NOT NULL default(newid()),
    V int NOT NULL,
    CONSTRAINT [PK_T] PRIMARY KEY CLUSTERED 
(
    [Id] ASC
))
     */

    [TestClass]
    public class ExporingTests {
        static ExporingTests() {
            var dummy = NHibUtil.__config; // trick to get NHibUtil ready to use
            dummy = null;
        }

        [TestInitialize]
        public void Setup() {
            using(var tx = DbUtil.CreateTxScope(false)) {
                DbUtil.CreateConnectionWithInitialCommand(cmd => {
                    cmd.CommandType = CommandType.Text;
                    cmd.CommandText = $"delete from T";
                    cmd.ExecuteNonQuery();
                }).Dispose();
                tx.Complete();
            }
        }

        IDbConnection CreateConnection() {
            return DbUtil.CreateConnectionWithInitialCommand(cmd => {
#if !true
                Console.WriteLine("SET IMPLICIT_TRANSACTIONS ON");
                cmd.CommandText = "SET IMPLICIT_TRANSACTIONS ON";
                cmd.ExecuteNonQuery(); 
#endif
            });
        }
        int CountRowsInT() {
            int rowCount = -1;
            DbUtil.CreateConnectionWithInitialCommand(cmd => {
                cmd.CommandText = "select count(*) from T";
                rowCount = (int)cmd.ExecuteScalar();
            }).Dispose();
            return rowCount;
        }

        [TestMethod]
        public void NHibernateBug() {
            try {
                using(var tx = DbUtil.CreateTxScope()) {
                    using(var cn = CreateConnection()) {

                        DbUtil.InsertMany(cn);

                        using(var sess = NHibUtil.CreateSession(cn)) {
                            for(int v = 1001;v < (1001 + 3);v++) {
                                sess.Save(new PoCo { Id = Guid.NewGuid().ToString(), V = v });
                            }
                            sess.Flush();
                        }
                    }

                    Console.WriteLine("Complete BEFORE");
                    tx.Complete();
                    Console.WriteLine("Complete AFTER");
                }
                Assert.Fail("'hidden' Dispose on previous line should cause en exception");
            } catch(/*TransactionAborted*/Exception ex) {
                Console.WriteLine($"Ended w Exception {ex}");
            }

            Assert.AreEqual(0, CountRowsInT());
        }

        [TestMethod]
        public void ObservedBehavior() {
            using(var tx = DbUtil.CreateTxScope()) {
                using(var cn = CreateConnection()) {
                    DbUtil.InsertMany(cn);
                    Thread.Sleep(10 * 1000);
                    Assert.IsTrue(Transaction.Current.TransactionInformation.Status == TransactionStatus.Aborted);
                    tx.Dispose(); // <<=== it *looks as* if a Dispose is done
                    DbUtil.InsertMany(cn, 1001);
                }

                //tx.Complete(); // here is "normal" place to vote complete
            }

            Assert.AreEqual(0, CountRowsInT());
        }
    }

    public static class DbUtil {
        public static TransactionScope CreateTxScope(bool hookupEvent = true) {
            var res = new TransactionScope(TransactionScopeOption.Required, new TransactionOptions {
                IsolationLevel = System.Transactions.IsolationLevel.ReadCommitted,
                Timeout = new TimeSpan(0, 0, 5),
            });
            if(hookupEvent) {
                Transaction.Current.TransactionCompleted += (s, e) => {
                    Console.WriteLine($"Ambient completed on thread {Thread.CurrentThread.GetHashCode()} {e.Transaction.TransactionInformation.Status}");
                };
            }
            return res;
        }
        public static IDbConnection CreateConnection() {
            return CreateConnectionWithInitialCommand(null);
        }
        public static IDbConnection CreateConnectionWithInitialCommand(Action<IDbCommand> initialCommand) {
            var res = new SqlConnection(System.Configuration.ConfigurationManager.ConnectionStrings["AppDb"].ConnectionString);
            res.Open();

            if(initialCommand != null) {
                using(var cmd = res.CreateCommand()) {
                    cmd.CommandType = CommandType.Text;
                    initialCommand(cmd);
                }
            }

            return res;
        }

        const int cNumToInsert = 3;
        public static void InsertMany(IDbConnection cn, int start = 1, int count = cNumToInsert) {
            for(int v = start;v < (start + count);v++) {
                InsertOne(cn, v);
            }
        }
        public static void InsertOne(IDbConnection cn, int v) {
            using(var cmd = cn.CreateCommand()) {
                cmd.CommandType = CommandType.Text;
                cmd.CommandText = $"insert into T (V) values ({v})";
                cmd.ExecuteNonQuery();
            }
            Console.WriteLine($"inserted {v} ({Thread.CurrentThread.GetHashCode()})");
            Thread.Sleep(1000);
        }
    }

    public static class NHibUtil {
        public class MyInterceptor : EmptyInterceptor {
            public override SqlString OnPrepareStatement(SqlString sql) {
                Console.WriteLine($"OnPrepareStatement: {sql}");

                Console.WriteLine($"SLEEP before {Transaction.Current.TransactionInformation.Status}");
                Thread.Sleep(10 * 1000);
                Console.WriteLine($"SLEEP after {Transaction.Current.TransactionInformation.Status}");
                Assert.IsTrue(Transaction.Current.TransactionInformation.Status == TransactionStatus.Aborted);

                return base.OnPrepareStatement(sql);
            }
        }

        public static Configuration __config;
        static ISessionFactory __factory;

        static NHibUtil() {
            __config = new Configuration();
            var doc = new XmlDocument();
            doc.LoadXml(@"<hibernate-mapping xmlns='urn:nhibernate-mapping-2.2'>
    <class name='TransactionScopeTimeout.PoCo, TransactionScopeTimeout'
    table='T' lazy='false'>
        <id name='Id' column='Id' type='string' access='property'>
            <generator class='assigned' />
        </id>
        <property name='V' column='V' type='int' access='property' />
    </class>
</hibernate-mapping>");
            __config.AddDocument(doc);
            __config.Interceptor = new MyInterceptor();
            __factory = __config.BuildSessionFactory();
        }

        public static ISession CreateSession(IDbConnection conn) {
            ISession res = __factory.WithOptions()
                .Connection((System.Data.Common.DbConnection)conn)
                .OpenSession();
            res.FlushMode = FlushMode.Manual;
            return res;
        }
    }

    public static class Console {
        public static void WriteLine(string s) {
            System.Console.WriteLine($"th={Thread.CurrentThread.GetHashCode()}; {s}");
        }
    }

}

<configuration>
    <configSections>
        <section name="hibernate-configuration" type="NHibernate.Cfg.ConfigurationSectionHandler, NHibernate" />
    </configSections>

    <connectionStrings>
        <add name="AppDb" connectionString="Data Source=YourServer;initial catalog=YourDatabase;Max Pool Size=1;" />
    </connectionStrings>

    <hibernate-configuration xmlns="urn:nhibernate-configuration-2.2">
        <session-factory>
            <property name="connection.provider">NHibernate.Connection.DriverConnectionProvider</property>
            <property name="dialect">NHibernate.Dialect.MsSql2012Dialect</property>
            <property name="connection.driver_class">NHibernate.Driver.SqlClientDriver</property>
            <property name="connection.connection_string_name">AppDb</property>

            <property name="show_sql">true</property>
            <!-- next needed to make insert/update/delete appear on output -->
            <property name="adonet.batch_size">0</property>
            <property name="format_sql">false</property>
        </session-factory>
    </hibernate-configuration>

</configuration>

[inglun]

Funny. I thought someone would react to this report. When using TransactionScope you would never expect a timed out transaction to be partially committed.

[fredericDelaporte]

Maybe because it seems unlikely to contributors this has anything to do with NHibernate. If things actually land into DB although the scope is not committed, while used connections were enlisted in the transaction, that is a transaction scope bug.

[oskarb]

@inglun Maybe you could elaborate a little bit. Are you suggesting that NHibernate somehow disposes the TransactionScope by mistake somewhere? Are you saying that changes made on the connection before such dispose are still persisted? Or that the connection lives on and becomes unenlisted when the transaction scope is somehow disposed to early and that something does more changes on the connection afterwards?

It used to be that an NHibernate session should always have an NHibernate transaction, even if there is an outer TransactionScope. It appears you don't. I haven't kept up to date with recent NH releases though - if this requirement has been relaxed or not.

So, are you causing a timeout during your call to session.Flush(), and you believe that error somehow makes NH either unenlist the connection from the TransactionScope, or that NH in some way keeps using the connection after the TransactionScope has been somehow destroyed and the connection unenlisted?

[inglun]

Maybe because it seems unlikely to contributors this has anything to do with NHibernate. If things actually lands into DB although the scope is not committed, while used connections were enlisted in the transaction, that is a transaction scope bug.

Yes. It is so very unlikely that I almost laughed at my coworker that first reported a behavior consistent with this

[inglun]

@inglun Maybe you could elaborate a little bit. Are you suggesting that NHibernate somehow disposes the TransactionScope by mistake somewhere? Are you saying that changes made on the connection before such dispose are still persisted? Or that the connection lives on and becomes unenlisted when the transaction scope is somehow disposed to early and that something does more changes on the connection afterwards?

I am saying (in the code) that it is "as if" the TransactionScope is disposed. Not that it is. Disposing the TransactionScope is the only way I could "reproduce" the behavior without NHibernate (with plain ADO.Net). The connection "lives on" and above all it is used. In my test case a bunch of inserts are issued on it after timeout and they are committed instantly since the default default behavior of/in SQL Server is AUTOCOMMIT. Disabling autocommit with SET IMPLICIT_TRANSACTIONS ON doesn't stop the insert issuing but it stops them from being persisted.

It used to be that an NHibernate session should always have an NHibernate transaction, even if there is an outer TransactionScope. It appears you don't. I haven't kept up to date with recent NH releases though - if this requirement has been relaxed or not.

I don't think a NH tx is necessary.

So, are you causing a timeout during your call to session.Flush(), and you believe that error somehow makes NH either unenlist the connection from the TransactionScope, or that NH in some way keeps using the connection after the TransactionScope has been somehow destroyed and the connection unenlisted?

The timeout is forced during Flush in my interceptor (you have to be picky where). NH keeps using the connection after the TransactionScope (or more accurately the ambient transaction) has timed out. How the heck that is possible is beyond me.

[kaksmet]

It used to be that an NHibernate session should always have an NHibernate transaction, even if there is an outer TransactionScope. It appears you don't. I haven't kept up to date with recent NH releases though - if this requirement has been relaxed or not.

The NHibernate Reference 12.8 says:

Instead of using NHibernate ITransaction, TransactionScope can be used. Please do not use both simultaneously.

[fredericDelaporte]

It used to be that an NHibernate session should always have an NHibernate transaction, even if there is an outer TransactionScope. It appears you don't. I haven't kept up to date with recent NH releases though - if this requirement has been relaxed or not.

From my view point such a recommendation has always been a mistake, whatever the NHibernate version. Using a NHibernate transaction opens a DbTransaction, and it is documented by Microsoft that one should not use a transaction scope and a DbTransaction simultaneously on the same connection.

[calledude]

I am currently facing this issue as well with transactions, using ISession.BeginTransaction(IsolationLevel) Trying to rollback yields an exception with a message looking something like Not connected

Currently using NHibernate 5.2.3 Any updates on this issue at all?

[fredericDelaporte]

This really looks to me like a trouble not bound to NHibernate. See this post on MSDN (requires a Microsoft account). It seems to be the exact same trouble, but without NHibernate.