Fix concurrency issues on TransactionScope timeout

fix #3355

Author: fredericDelaporte

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

@@ -19,6 +19,8 @@
 using NHibernate.Engine;
 using NHibernate.Test.TransactionTest;
 using NUnit.Framework;
+
+using SysTran = System.Transactions;
 using NHibernate.Linq;
 
 namespace NHibernate.Test.SystemTransactions
@@ -524,6 +526,116 @@ 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()
+		{
+			// 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 unhandler exception catcher
+			_unhandledExceptionCount = 0;
+			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));
+						await (Task.Delay(2));
+						var count = await (session.Query<Person>().CountAsync());
+						Assert.That(count, Is.EqualTo(entitiesCount));
+						txScope.Complete();
+					}
+					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;
+						do
+						{
+							isTransactionException = currentEx is SysTran.TransactionException;
+							currentEx = currentEx.InnerException;
+						}
+						while (!isTransactionException && currentEx != null);
+						bool isTimeout;
+						do
+						{
+							isTimeout = currentEx is TimeoutException;
+							currentEx = currentEx?.InnerException;
+						}
+						while (!isTimeout && currentEx != null);
+
+						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 possibility of localization 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;
+					}
+				}
+
+				// Despite the Thread sleep and the count of entities to load, this test does get the timeout only for slightly
+				// more than 10% of the attempts.
+				Assert.That(timeoutsCount, Is.GreaterThan(5));
+				Assert.That(_unhandledExceptionCount, Is.EqualTo(0));
+			}
+			finally
+			{
+				AppDomain.CurrentDomain.UnhandledException -= CurrentDomain_UnhandledException;
+			}
+		}
+
+		private int _unhandledExceptionCount;
+
+		private void CurrentDomain_UnhandledException(object sender, UnhandledExceptionEventArgs e)
+		{
+			_unhandledExceptionCount++;
+			Assert.Warn("Unhandled exception: {0}", e.ExceptionObject);
+		}
 	}
 
 	[TestFixture]

src/NHibernate.Test/SystemTransactions/SystemTransactionFixture.cs

@@ -10,6 +10,8 @@
 using NHibernate.Test.TransactionTest;
 using NUnit.Framework;
 
+using SysTran = System.Transactions;
+
 namespace NHibernate.Test.SystemTransactions
 {
 	[TestFixture]
@@ -643,24 +645,114 @@ public void CanUseSessionWithManyDependentTransaction(bool explicitFlush)
 			}
 		}
 
+		// 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 void SupportsTransactionTimeout()
 		{
 			// 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 < 5000; i++)
+				for (var i = 0; i < entitiesCount; i++)
 				{
-					var person = new Person();
+					var person = new Person
+					{
+						NotNullData = Guid.NewGuid().ToString()
+					};
+
 					s.Save(person);
 				}
 
 				t.Commit();
 			}
 
-			var txOptions = new TransactionOptions { Timeout = TimeSpan.FromMilliseconds(1) };
+			// Setup unhandler exception catcher
+			_unhandledExceptionCount = 0;
+			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);
+						using var session = OpenSession();
+						var data = session.CreateCriteria<Person>().List();
+						Assert.That(data, Has.Count.EqualTo(entitiesCount));
+						Thread.Sleep(2);
+						var count = session.Query<Person>().Count();
+						Assert.That(count, Is.EqualTo(entitiesCount));
+						txScope.Complete();
+					}
+					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;
+						do
+						{
+							isTransactionException = currentEx is SysTran.TransactionException;
+							currentEx = currentEx.InnerException;
+						}
+						while (!isTransactionException && currentEx != null);
+						bool isTimeout;
+						do
+						{
+							isTimeout = currentEx is TimeoutException;
+							currentEx = currentEx?.InnerException;
+						}
+						while (!isTimeout && currentEx != null);
+
+						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 possibility of localization 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;
+					}
+				}
+
+				// Despite the Thread sleep and the count of entities to load, this test does get the timeout only for slightly
+				// more than 10% of the attempts.
+				Assert.That(timeoutsCount, Is.GreaterThan(5));
+				Assert.That(_unhandledExceptionCount, Is.EqualTo(0));
+			}
+			finally
+			{
+				AppDomain.CurrentDomain.UnhandledException -= CurrentDomain_UnhandledException;
+			}
+		}
+
+		private int _unhandledExceptionCount;
 
+		private void CurrentDomain_UnhandledException(object sender, UnhandledExceptionEventArgs e)
+		{
+			_unhandledExceptionCount++;
+			Assert.Warn("Unhandled exception: {0}", e.ExceptionObject);
 		}
 
 		[Theory, Explicit("Bench")]

src/NHibernate/Async/Transaction/AdoNetWithSystemTransactionFactory.cs

@@ -10,6 +10,7 @@
 
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.Linq;
 using System.Threading;
 using System.Transactions;

src/NHibernate/Impl/AbstractSessionImpl.cs

@@ -429,7 +429,7 @@ private sealed class ProcessHelper : IDisposable
 			private IDisposable _context;
 
 			[NonSerialized]
-			private bool _processing;
+			private volatile bool _processing;
 
 			public ProcessHelper()
 			{

src/NHibernate/Transaction/AdoNetWithSystemTransactionFactory.cs

@@ -1,5 +1,6 @@
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.Linq;
 using System.Threading;
 using System.Transactions;
@@ -326,11 +327,11 @@ protected virtual void Unlock()
 					catch (InvalidOperationException ioe)
 					{
 						_logger.Warn(ioe, "Attempting to dodge a disposed transaction trouble, current" +
-						             "transaction was unreachable.");
+									 "transaction was unreachable.");
 					}
 
 					_logger.Warn(ode, "Enlisted transaction status is maybe wrongly active, original " +
-					             "transaction being already disposed. Will assume neither active nor committed.");
+								 "transaction being already disposed. Will assume neither active nor committed.");
 					return null;
 				}
 			}
@@ -418,23 +419,20 @@ void IEnlistmentNotification.InDoubt(Enlistment enlistment)
 			/// callback, <see langword="null"/> if this is an in-doubt callback.</param>
 			protected virtual void ProcessSecondPhase(Enlistment enlistment, bool? success)
 			{
-				using (_session.BeginContext())
-				{
-					_logger.Debug(
-						success.HasValue
-							? success.Value
-								? "Committing system transaction"
-								: "Rolled back system transaction"
-							: "System transaction is in doubt");
+				_logger.Debug(
+					success.HasValue
+						? success.Value
+							? "Committing system transaction"
+							: "Rolled back system transaction"
+						: "System transaction is in doubt");
 
-					try
-					{
-						CompleteTransaction(success ?? false);
-					}
-					finally
-					{
-						enlistment.Done();
-					}
+				try
+				{
+					CompleteTransaction(success ?? false);
+				}
+				finally
+				{
+					enlistment.Done();
 				}
 			}
 
@@ -458,7 +456,28 @@ protected virtual void CompleteTransaction(bool isCommitted)
 				{
 					// Allow transaction completed actions to run while others stay blocked.
 					_bypassLock.Value = true;
-					using (_session.BeginContext())
+					// Ensure no other session processing is still ongoing. In case of a transaction timeout, the transaction is
+					// cancelled on a new thread even for non-distributed scopes. So, the session could be doing some processing,
+					// and will not be interrupted until attempting some usage of the connection. See #3355.
+					// Thread safety of a concurrent session BeginProcess is ensured by the Wait performed by BeginProcess.
+					var context = _session.BeginProcess();
+					if (context == null)
+					{
+						var timeOutGuard = new Stopwatch();
+						timeOutGuard.Start();
+						while (context == null && timeOutGuard.ElapsedMilliseconds < _systemTransactionCompletionLockTimeout)
+						{
+							// Naïve yield.
+							Thread.Sleep(10);
+							context = _session.BeginProcess();
+						}
+						if (context == null)
+							throw new HibernateException(
+								$"Synchronization timeout for transaction completion. Either raise" +
+								$"{Cfg.Environment.SystemTransactionCompletionLockTimeout}, or check all scopes are properly" +
+								$"disposed and/or all direct System.Transaction.Current changes are properly managed.");
+					}
+					using (context)
 					{
 						// Flag active as false before running actions, otherwise the session may not cleanup as much
 						// as possible.
@@ -477,7 +496,7 @@ protected virtual void CompleteTransaction(bool isCommitted)
 							// within scopes, although mixing is not advised.
 							if (!ShouldCloseSessionOnSystemTransactionCompleted)
 								_session.ConnectionManager.EnlistIfRequired(null);
-							
+
 							_session.AfterTransactionCompletion(isCommitted, null);
 							foreach (var dependentSession in _session.ConnectionManager.DependentSessions)
 								dependentSession.AfterTransactionCompletion(isCommitted, null);