Fix concurrency issues on TransactionScope timeout (#3483)

.editorconfig

@@ -2,6 +2,7 @@ root=true
 
 [*]
 insert_final_newline = true
+charset = utf-8
 
 [*.cs]
 indent_style = tab

build-common/teamcity-hibernate.cfg.xml

@@ -26,5 +26,7 @@
 			<property name="odbc.explicit_datetime_scale"></property>
 			<property name="oracle.use_n_prefixed_types_for_unicode"></property>
 			<property name="query.default_cast_length"></property>
+			<property name="transaction.ignore_session_synchronization_failures"></property>
+			<property name="transaction.system_completion_lock_timeout"></property>
 		</session-factory>
 	</hibernate-configuration>

default.build

@@ -139,6 +139,26 @@
 				<namespace prefix="hbm" uri="urn:nhibernate-configuration-2.2" />
 			</namespaces>
 		</xmlpoke>
+
+		<!-- Make sure the property exists - it's only set for some scenarios. -->
+		<property name="nhibernate.transaction.ignore_session_synchronization_failures" value="" unless="${property::exists('nhibernate.transaction.ignore_session_synchronization_failures')}"/>
+		<xmlpoke file="${app.config}"
+			xpath="//*/hbm:property[@name='transaction.ignore_session_synchronization_failures']"
+			value="${nhibernate.transaction.ignore_session_synchronization_failures}">
+			<namespaces>
+				<namespace prefix="hbm" uri="urn:nhibernate-configuration-2.2" />
+			</namespaces>
+		</xmlpoke>
+
+		<!-- Make sure the property exists - it's only set for some scenarios. -->
+		<property name="nhibernate.transaction.system_completion_lock_timeout" value="" unless="${property::exists('nhibernate.transaction.system_completion_lock_timeout')}"/>
+		<xmlpoke file="${app.config}"
+			xpath="//*/hbm:property[@name='transaction.system_completion_lock_timeout']"
+			value="${nhibernate.transaction.system_completion_lock_timeout}">
+			<namespaces>
+				<namespace prefix="hbm" uri="urn:nhibernate-configuration-2.2" />
+			</namespaces>
+		</xmlpoke>
 	</target>
 
 	<target name="put-connection-settings-into-app-config">

doc/reference/modules/configuration.xml

@@ -1050,8 +1050,8 @@ var session = sessions.OpenSession(conn);
                                 after scope disposal. This occurs when the transaction is distributed.
                                 This notably concerns <literal>ISessionImplementor.AfterTransactionCompletion(bool, ITransaction)</literal>.
                                 NHibernate protects the session from being concurrently used by the code following the scope disposal
-                                with a lock. To prevent any application freeze, this lock has a default timeout of five seconds. If the
-                                application appears to require longer (!) running transaction completion events, this setting allows to
+                                with a lock. To prevent any application freeze, this lock has a default timeout of one second. If the
+                                application appears to require longer running transaction completion events, this setting allows to
                                 raise this timeout. <literal>-1</literal> disables the timeout.
                             </para>
                             <para>
@@ -1060,6 +1060,33 @@ var session = sessions.OpenSession(conn);
                             </para>
                         </entry>
                     </row>
+                    <row>
+                        <entry>
+                            <literal>transaction.ignore_session_synchronization_failures</literal>
+                        </entry>
+                        <entry>
+                            Whether session synchronisation failures occuring during finalizations of system transaction should be
+                            ignored or not. <literal>false</literal> by default.
+                            <para>
+                                When a system transaction terminates abnormaly, especially through timeouts, it may have its
+                                completion events running on concurrent threads while the session is still performing some processing.
+                                To prevent threading concurrency failures, NHibernate then wait for the session to end its processing,
+                                up to <literal>transaction.system_completion_lock_timeout</literal>. If the session processing is still ongoing
+                                afterwards, it will by default log an error, perform transaction finalization processing concurrently,
+                                then throw a synchronization error. This setting allows to disable that later throw.
+                            </para>
+                            <para>
+                                Disabling the throw can be useful if the used data provider has its own locking mechanism applied
+                                during transaction completion, preventing the session to end its processing. It may then be safe to
+                                ignore this synchronization failure. In case of threading concurrency failure, you may then need to
+                                raise <literal>transaction.system_completion_lock_timeout</literal>.
+                            </para>
+                            <para>
+                                <emphasis role="strong">eg.</emphasis>
+                                <literal>true</literal> | <literal>false</literal>
+                            </para>
+                        </entry>
+                    </row>
                     <row>
                         <entry>
                             <literal>transaction.auto_join</literal>

psake.ps1

@@ -29,6 +29,8 @@ Task Set-Configuration {
             'connection.connection_string' = 'Server=(local)\SQL2017;Uid=sa;Pwd=Password12!;Database=nhibernateOdbc;Driver={SQL Server Native Client 11.0};Mars_Connection=yes;';
             'connection.driver_class' = 'NHibernate.Driver.OdbcDriver';
             'odbc.explicit_datetime_scale' = '3';
+            'transaction.ignore_session_synchronization_failures' = 'true';
+            'transaction.system_completion_lock_timeout' = '200';
             <# We need to use a dialect that avoids mapping DbType.Time to TIME on MSSQL. On modern SQL Server
                 this becomes TIME(7). Later, such values cannot be read back over ODBC. The
                 error we get is "System.ArgumentException : Unknown SQL type - SS_TIME_EX.". I don't know for certain

src/NHibernate.Config.Templates/SapSQLAnywhere.cfg.xml

@@ -17,5 +17,7 @@ for your own use before compiling tests in Visual Studio.
 		</property>
 		<property name="dialect">NHibernate.Dialect.SybaseSQLAnywhere12Dialect</property>
 		<property name="query.substitutions">true=1;false=0</property>
+		<property name="transaction.ignore_session_synchronization_failures">true</property>
+		<property name="transaction.system_completion_lock_timeout">200</property>
 	</session-factory>
 </hibernate-configuration>

src/NHibernate.Test/Async/SystemTransactions/SystemTransactionFixture.cs

@@ -9,6 +9,7 @@
 
 
 using System;
+using System.Collections.Concurrent;
 using System.Collections.Generic;
 using System.Diagnostics;
 using System.Linq;
@@ -30,6 +31,13 @@ public class SystemTransactionFixtureAsync : SystemTransactionFixtureBase
 		protected override bool UseConnectionOnSystemTransactionPrepare => true;
 		protected override bool AutoJoinTransaction => true;
 
+		protected override void OnTearDown()
+		{
+			base.OnTearDown();
+			// The SupportsTransactionTimeout test may change this, restore it to its default value.
+			FailOnNotClosedSession = true;
+		}
+
 		[Test]
 		public async Task WillNotCrashOnPrepareFailureAsync()
 		{
@@ -524,6 +532,152 @@ public async Task EnforceConnectionUsageRulesOnTransactionCompletionAsync()
 			// Currently always forbidden, whatever UseConnectionOnSystemTransactionEvents.
 			Assert.That(interceptor.AfterException, Is.TypeOf<HibernateException>());
 		}
+
+		// This test check a concurrency issue hard to reproduce. If it is flaky, it has to be considered failing.
+		// In such case, raise triesCount to investigate it locally with more chances of triggering the trouble.
+		[Test]
+		public async Task SupportsTransactionTimeoutAsync()
+		{
+			Assume.That(TestDialect.SupportsTransactionScopeTimeouts, Is.True, "The tested dialect is not supported for transaction scope timeouts.");
+			// Other special cases: ODBC and SAP SQL Anywhere succeed this test only with transaction.ignore_session_synchronization_failures
+			// enabled.
+			// They freeze the session during the transaction cancellation. To avoid the test to be very long, the synchronization
+			// lock timeout should be lowered too.
+
+			// A concurrency issue exists with the legacy setting allowing to use the session from transaction completion, which
+			// may cause session leaks. Ignore them.
+			FailOnNotClosedSession = !UseConnectionOnSystemTransactionPrepare;
+
+			// Test case adapted from https://github.com/kaksmet/NHibBugRepro
+
+			// Create some test data.
+			const int entitiesCount = 5000;
+			using (var s = OpenSession())
+			using (var t = s.BeginTransaction())
+			{
+				for (var i = 0; i < entitiesCount; i++)
+				{
+					var person = new Person
+					{
+						NotNullData = Guid.NewGuid().ToString()
+					};
+
+					await (s.SaveAsync(person));
+				}
+
+				await (t.CommitAsync());
+			}
+
+			// Setup unhandled exception catcher.
+			_unhandledExceptions = new ConcurrentBag<object>();
+			AppDomain.CurrentDomain.UnhandledException += CurrentDomain_UnhandledException;
+			try
+			{
+				// Generate transaction timeouts.
+				const int triesCount = 100;
+				var txOptions = new TransactionOptions { Timeout = TimeSpan.FromMilliseconds(1) };
+				var timeoutsCount = 0;
+				for (var i = 0; i < triesCount; i++)
+				{
+					try
+					{
+						using var txScope = new TransactionScope(TransactionScopeOption.Required, txOptions, TransactionScopeAsyncFlowOption.Enabled);
+						using var session = OpenSession();
+						var data = await (session.CreateCriteria<Person>().ListAsync());
+						Assert.That(data, Has.Count.EqualTo(entitiesCount), "Unexpected count of loaded entities.");
+						await (Task.Delay(2));
+						var count = await (session.Query<Person>().CountAsync());
+						Assert.That(count, Is.EqualTo(entitiesCount), "Unexpected entities count.");
+						txScope.Complete();
+					}
+					catch
+					{
+						// Assume that is a transaction timeout. It may cause various failures, of which some are hard to identify.
+						timeoutsCount++;
+					}
+					// If in need of checking some specific failures, the following code may be used instead:
+					/*
+					catch (Exception ex)
+					{
+						var currentEx = ex;
+						// Depending on where the transaction aborption has broken NHibernate processing, we may
+						// get various exceptions, like directly a TransactionAbortedException with an inner
+						// TimeoutException, or a HibernateException encapsulating a TransactionException with a
+						// timeout, ...
+						bool isTransactionException, isTimeout;
+						do
+						{
+							isTransactionException = currentEx is System.Transactions.TransactionException;
+							isTimeout = isTransactionException && currentEx is TransactionAbortedException;
+							currentEx = currentEx.InnerException;
+						}
+						while (!isTransactionException && currentEx != null);
+						while (!isTimeout && currentEx != null)
+						{
+							isTimeout = currentEx is TimeoutException;
+							currentEx = currentEx?.InnerException;
+						}
+
+						if (!isTimeout)
+						{
+							// We may also get a GenericADOException with an InvalidOperationException stating the
+							// transaction associated to the connection is no more active but not yet suppressed,
+							// and that for executing some SQL, we need to suppress it. That is a weak way of
+							// identifying the case, especially with the many localizations of the message.
+							currentEx = ex;
+							do
+							{
+								isTimeout = currentEx is InvalidOperationException && currentEx.Message.Contains("SQL");
+								currentEx = currentEx?.InnerException;
+							}
+							while (!isTimeout && currentEx != null);
+						}
+
+						if (isTimeout)
+							timeoutsCount++;
+						else
+							throw;
+					}
+					*/
+				}
+
+				Assert.That(
+					_unhandledExceptions.Count,
+					Is.EqualTo(0),
+					"Unhandled exceptions have occurred: {0}",
+					string.Join(@"
+
+", _unhandledExceptions));
+
+				// Despite the Thread sleep and the count of entities to load, this test may get the timeout only for slightly
+				// more than 10% of the attempts.
+				Warn.Unless(timeoutsCount, Is.GreaterThan(5), "The test should have generated more timeouts.");
+			}
+			finally
+			{
+				AppDomain.CurrentDomain.UnhandledException -= CurrentDomain_UnhandledException;
+			}
+		}
+
+		private ConcurrentBag<object> _unhandledExceptions;
+
+		private void CurrentDomain_UnhandledException(object sender, UnhandledExceptionEventArgs e)
+		{
+			if (e.ExceptionObject is Exception exception)
+			{
+				// Ascertain NHibernate is involved. Some unhandled exceptions occur due to the
+				// TransactionScope timeout operating on an unexpected thread for the data provider.
+				var isNHibernateInvolved = false;
+				while (exception != null && !isNHibernateInvolved)
+				{
+					isNHibernateInvolved = exception.StackTrace != null && exception.StackTrace.ToLowerInvariant().Contains("nhibernate");
+					exception = exception.InnerException;
+				}
+				if (!isNHibernateInvolved)
+					return;
+			}
+			_unhandledExceptions.Add(e.ExceptionObject);
+		}
 	}
 
 	[TestFixture]