From 0c3c705cf46a43e459e539e612c3677bae64ef57 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Fr=C3=A9d=C3=A9ric=20Delaporte?= <12201973+fredericDelaporte@users.noreply.github.com> Date: Tue, 5 Mar 2024 11:57:41 +0100 Subject: [PATCH] Fix concurrency issues on TransactionScope timeout (#3483) --- .editorconfig | 1 + build-common/teamcity-hibernate.cfg.xml | 2 + default.build | 20 +++ doc/reference/modules/configuration.xml | 31 +++- psake.ps1 | 2 + .../SapSQLAnywhere.cfg.xml | 2 + .../SystemTransactionFixture.cs | 154 ++++++++++++++++++ src/NHibernate.Test/DebugSessionFactory.cs | 47 ++++-- .../SystemTransactionFixture.cs | 154 ++++++++++++++++++ src/NHibernate.Test/TestCase.cs | 15 +- src/NHibernate.Test/TestDialect.cs | 5 + .../TestDialects/MySQL5TestDialect.cs | 5 + .../SapSQLAnywhere17TestDialect.cs | 2 +- .../AdoNetWithSystemTransactionFactory.cs | 1 + src/NHibernate/Cfg/Environment.cs | 21 ++- src/NHibernate/Engine/ISessionImplementor.cs | 3 + src/NHibernate/ISession.cs | 7 +- src/NHibernate/Impl/AbstractSessionImpl.cs | 33 +++- src/NHibernate/Impl/SessionImpl.cs | 22 +-- .../AdoNetWithSystemTransactionFactory.cs | 127 ++++++++++++--- src/NHibernate/nhibernate-configuration.xsd | 24 ++- teamcity.build | 2 + 22 files changed, 610 insertions(+), 70 deletions(-) diff --git a/.editorconfig b/.editorconfig index 9315aa4e45e..da812d88d1b 100644 --- a/.editorconfig +++ b/.editorconfig @@ -2,6 +2,7 @@ root=true [*] insert_final_newline = true +charset = utf-8 [*.cs] indent_style = tab diff --git a/build-common/teamcity-hibernate.cfg.xml b/build-common/teamcity-hibernate.cfg.xml index e8cb7f7e6dd..9cdad8f1e78 100644 --- a/build-common/teamcity-hibernate.cfg.xml +++ b/build-common/teamcity-hibernate.cfg.xml @@ -26,5 +26,7 @@ + + diff --git a/default.build b/default.build index c8020603e1c..2ee19e5a694 100644 --- a/default.build +++ b/default.build @@ -139,6 +139,26 @@ + + + + + + + + + + + + + + + + diff --git a/doc/reference/modules/configuration.xml b/doc/reference/modules/configuration.xml index dd0c4bd6a63..290e4e64bc0 100644 --- a/doc/reference/modules/configuration.xml +++ b/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 ISessionImplementor.AfterTransactionCompletion(bool, ITransaction). 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. -1 disables the timeout. @@ -1060,6 +1060,33 @@ var session = sessions.OpenSession(conn); + + + transaction.ignore_session_synchronization_failures + + + Whether session synchronisation failures occuring during finalizations of system transaction should be + ignored or not. false by default. + + 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 transaction.system_completion_lock_timeout. 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. + + + 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 transaction.system_completion_lock_timeout. + + + eg. + true | false + + + transaction.auto_join diff --git a/psake.ps1 b/psake.ps1 index 16f7a267f14..877321e24e3 100644 --- a/psake.ps1 +++ b/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 diff --git a/src/NHibernate.Config.Templates/SapSQLAnywhere.cfg.xml b/src/NHibernate.Config.Templates/SapSQLAnywhere.cfg.xml index 9512fef12d6..57e02f1a82e 100644 --- a/src/NHibernate.Config.Templates/SapSQLAnywhere.cfg.xml +++ b/src/NHibernate.Config.Templates/SapSQLAnywhere.cfg.xml @@ -17,5 +17,7 @@ for your own use before compiling tests in Visual Studio. NHibernate.Dialect.SybaseSQLAnywhere12Dialect true=1;false=0 + true + 200 diff --git a/src/NHibernate.Test/Async/SystemTransactions/SystemTransactionFixture.cs b/src/NHibernate.Test/Async/SystemTransactions/SystemTransactionFixture.cs index 056ae272b0a..a87793c3d9b 100644 --- a/src/NHibernate.Test/Async/SystemTransactions/SystemTransactionFixture.cs +++ b/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()); } + + // 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(); + 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().ListAsync()); + Assert.That(data, Has.Count.EqualTo(entitiesCount), "Unexpected count of loaded entities."); + await (Task.Delay(2)); + var count = await (session.Query().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 _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] diff --git a/src/NHibernate.Test/DebugSessionFactory.cs b/src/NHibernate.Test/DebugSessionFactory.cs index 7eb551bb83f..8c5d892b1d4 100644 --- a/src/NHibernate.Test/DebugSessionFactory.cs +++ b/src/NHibernate.Test/DebugSessionFactory.cs @@ -43,14 +43,13 @@ public partial class DebugSessionFactory : ISessionFactoryImplementor /// it debug or not. /// public DebugConnectionProvider DebugConnectionProvider - => _debugConnectionProvider ?? - (_debugConnectionProvider = ActualFactory.ConnectionProvider as DebugConnectionProvider); + => _debugConnectionProvider ??= ActualFactory.ConnectionProvider as DebugConnectionProvider; public ISessionFactoryImplementor ActualFactory { get; } public EventListeners EventListeners => ((SessionFactoryImpl)ActualFactory).EventListeners; [NonSerialized] - private readonly ConcurrentBag _openedSessions = new ConcurrentBag(); + private readonly ConcurrentQueue _openedSessions = new(); private static readonly ILog _log = LogManager.GetLogger(typeof(DebugSessionFactory).Assembly, typeof(TestCase)); public DebugSessionFactory(ISessionFactory actualFactory) @@ -63,29 +62,43 @@ public DebugSessionFactory(ISessionFactory actualFactory) public bool CheckSessionsWereClosed() { var allClosed = true; + var number = 1; foreach (var session in _openedSessions) { - // Do not inverse, we want to close all of them. - allClosed = CheckSessionWasClosed(session) && allClosed; + var wasClosed = CheckSessionWasClosed(session); + // No early exit out of the loop: we want to close all forgotten sessions. + if (!wasClosed) + { + _log.ErrorFormat("Test case didn't close session {0}, n°{1} of {2}, closing.", + session.SessionId, number, _openedSessions.Count); + } + allClosed = wasClosed && allClosed; + // Catches only session opened from another one while sharing the connection. Those // opened without sharing the connection stay un-monitored. foreach (var dependentSession in session.ConnectionManager.DependentSessions.ToList()) { - allClosed = CheckSessionWasClosed(dependentSession) && allClosed; + wasClosed = CheckSessionWasClosed(dependentSession); + if (!wasClosed) + { + _log.ErrorFormat("Test case didn't close dependent session {0} of the session {3}, n°{1} of {2}, closing.", + dependentSession.SessionId, number, _openedSessions.Count, session.SessionId); + } + allClosed = wasClosed && allClosed; } + number++; } return allClosed; } - private bool CheckSessionWasClosed(ISessionImplementor session) + private static bool CheckSessionWasClosed(ISessionImplementor session) { session.TransactionContext?.Wait(); if (!session.IsOpen) return true; - _log.Error($"Test case didn't close session {session.SessionId}, closing"); (session as ISession)?.Close(); (session as IStatelessSession)?.Close(); return false; @@ -101,7 +114,7 @@ ISession ISessionFactory.OpenSession(DbConnection connection) #pragma warning disable CS0618 // Type or member is obsolete var s = ActualFactory.OpenSession(connection); #pragma warning restore CS0618 // Type or member is obsolete - _openedSessions.Add(s.GetSessionImplementation()); + _openedSessions.Enqueue(s.GetSessionImplementation()); return s; } @@ -110,7 +123,7 @@ ISession ISessionFactory.OpenSession(IInterceptor sessionLocalInterceptor) #pragma warning disable CS0618 // Type or member is obsolete var s = ActualFactory.OpenSession(sessionLocalInterceptor); #pragma warning restore CS0618 // Type or member is obsolete - _openedSessions.Add(s.GetSessionImplementation()); + _openedSessions.Enqueue(s.GetSessionImplementation()); return s; } @@ -119,14 +132,14 @@ ISession ISessionFactory.OpenSession(DbConnection conn, IInterceptor sessionLoca #pragma warning disable CS0618 // Type or member is obsolete var s = ActualFactory.OpenSession(conn, sessionLocalInterceptor); #pragma warning restore CS0618 // Type or member is obsolete - _openedSessions.Add(s.GetSessionImplementation()); + _openedSessions.Enqueue(s.GetSessionImplementation()); return s; } ISession ISessionFactory.OpenSession() { var s = ActualFactory.OpenSession(); - _openedSessions.Add(s.GetSessionImplementation()); + _openedSessions.Enqueue(s.GetSessionImplementation()); return s; } @@ -138,14 +151,14 @@ IStatelessSessionBuilder ISessionFactory.WithStatelessOptions() IStatelessSession ISessionFactory.OpenStatelessSession() { var s = ActualFactory.OpenStatelessSession(); - _openedSessions.Add(s.GetSessionImplementation()); + _openedSessions.Enqueue(s.GetSessionImplementation()); return s; } IStatelessSession ISessionFactory.OpenStatelessSession(DbConnection connection) { var s = ActualFactory.OpenStatelessSession(connection); - _openedSessions.Add(s.GetSessionImplementation()); + _openedSessions.Enqueue(s.GetSessionImplementation()); return s; } @@ -158,7 +171,7 @@ ISession ISessionFactoryImplementor.OpenSession( #pragma warning disable CS0618 // Type or member is obsolete var s = ActualFactory.OpenSession(connection, flushBeforeCompletionEnabled, autoCloseSessionEnabled, connectionReleaseMode); #pragma warning restore CS0618 // Type or member is obsolete - _openedSessions.Add(s.GetSessionImplementation()); + _openedSessions.Enqueue(s.GetSessionImplementation()); return s; } @@ -429,7 +442,7 @@ public SessionBuilder(ISessionBuilder actualBuilder, DebugSessionFactory debugFa ISession ISessionBuilder.OpenSession() { var s = _actualBuilder.OpenSession(); - _debugFactory._openedSessions.Add(s.GetSessionImplementation()); + _debugFactory._openedSessions.Enqueue(s.GetSessionImplementation()); return s; } @@ -504,7 +517,7 @@ public StatelessSessionBuilder(IStatelessSessionBuilder actualBuilder, DebugSess IStatelessSession IStatelessSessionBuilder.OpenStatelessSession() { var s = _actualBuilder.OpenStatelessSession(); - _debugFactory._openedSessions.Add(s.GetSessionImplementation()); + _debugFactory._openedSessions.Enqueue(s.GetSessionImplementation()); return s; } diff --git a/src/NHibernate.Test/SystemTransactions/SystemTransactionFixture.cs b/src/NHibernate.Test/SystemTransactions/SystemTransactionFixture.cs index e5fb6fd46c0..8503de97948 100644 --- a/src/NHibernate.Test/SystemTransactions/SystemTransactionFixture.cs +++ b/src/NHibernate.Test/SystemTransactions/SystemTransactionFixture.cs @@ -1,4 +1,5 @@ using System; +using System.Collections.Concurrent; using System.Collections.Generic; using System.Diagnostics; using System.Linq; @@ -18,6 +19,13 @@ public class SystemTransactionFixture : 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 void WillNotCrashOnPrepareFailure() { @@ -643,6 +651,152 @@ 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() + { + 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() + }; + + s.Save(person); + } + + t.Commit(); + } + + // Setup unhandled exception catcher. + _unhandledExceptions = new ConcurrentBag(); + 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().List(); + Assert.That(data, Has.Count.EqualTo(entitiesCount), "Unexpected count of loaded entities."); + Thread.Sleep(2); + var count = session.Query().Count(); + 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 _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); + } + [Theory, Explicit("Bench")] public void BenchTransactionAccess(bool inTransaction) { diff --git a/src/NHibernate.Test/TestCase.cs b/src/NHibernate.Test/TestCase.cs index c58d819ed64..137818e1e90 100644 --- a/src/NHibernate.Test/TestCase.cs +++ b/src/NHibernate.Test/TestCase.cs @@ -54,6 +54,8 @@ protected TestDialect TestDialect get { return _testDialect ?? (_testDialect = TestDialect.GetTestDialect(Dialect)); } } + protected bool FailOnNotClosedSession { get; set; } = true; + /// /// Mapping files used in the TestCase /// @@ -157,6 +159,9 @@ public void TearDown() { var testResult = TestContext.CurrentContext.Result; var fail = false; + var wereClosed = true; + // In case the test Teardown needs to switch it off for other tests, back it up. + var failOnNotClosedSession = FailOnNotClosedSession; var testOwnTearDownDone = false; string badCleanupMessage = null; try @@ -170,12 +175,12 @@ public void TearDown() { try { - var wereClosed = _sessionFactory.CheckSessionsWereClosed(); + wereClosed = _sessionFactory.CheckSessionsWereClosed(); var wasCleaned = CheckDatabaseWasCleaned(); var wereConnectionsClosed = CheckConnectionsWereClosed(); - fail = !wereClosed || !wasCleaned || !wereConnectionsClosed; + fail = !wereClosed && failOnNotClosedSession || !wasCleaned || !wereConnectionsClosed; - if (fail) + if (fail || !wereClosed) { badCleanupMessage = "Test didn't clean up after itself. session closed: " + wereClosed + "; database cleaned: " + wasCleaned @@ -213,6 +218,10 @@ public void TearDown() { Assert.Fail(badCleanupMessage); } + else if (!wereClosed) + { + Assert.Warn(badCleanupMessage); + } } private string GetCombinedFailureMessage(TestContext.ResultAdapter result, string tearDownFailure, string tearDownStackTrace) diff --git a/src/NHibernate.Test/TestDialect.cs b/src/NHibernate.Test/TestDialect.cs index e7bc20d304f..69ab31fcb37 100644 --- a/src/NHibernate.Test/TestDialect.cs +++ b/src/NHibernate.Test/TestDialect.cs @@ -177,6 +177,11 @@ public bool SupportsSqlType(SqlType sqlType) /// public virtual bool SupportsDependentTransaction => true; + /// + /// Transaction scope timeouts occur on a dedicated thread which wrecks some data providers. + /// + public virtual bool SupportsTransactionScopeTimeouts => true; + /// /// Some databases (provider?) fails to compute adequate column types for queries which columns /// computing include a parameter value. diff --git a/src/NHibernate.Test/TestDialects/MySQL5TestDialect.cs b/src/NHibernate.Test/TestDialects/MySQL5TestDialect.cs index ea68e6f19b7..d37bef44dd5 100644 --- a/src/NHibernate.Test/TestDialects/MySQL5TestDialect.cs +++ b/src/NHibernate.Test/TestDialects/MySQL5TestDialect.cs @@ -21,5 +21,10 @@ public MySQL5TestDialect(Dialect.Dialect dialect) /// See https://dev.mysql.com/doc/refman/8.0/en/correlated-subqueries.html /// public override bool SupportsCorrelatedColumnsInSubselectJoin => false; + + /// + /// MySQL data provider may be wrecked by transaction scope timeouts to the point of causing even the teardown to fail. + /// + public override bool SupportsTransactionScopeTimeouts => false; } } diff --git a/src/NHibernate.Test/TestDialects/SapSQLAnywhere17TestDialect.cs b/src/NHibernate.Test/TestDialects/SapSQLAnywhere17TestDialect.cs index 35a35092ce3..3955f92aef7 100644 --- a/src/NHibernate.Test/TestDialects/SapSQLAnywhere17TestDialect.cs +++ b/src/NHibernate.Test/TestDialects/SapSQLAnywhere17TestDialect.cs @@ -1,4 +1,4 @@ -namespace NHibernate.Test.TestDialects +namespace NHibernate.Test.TestDialects { public class SapSQLAnywhere17TestDialect : TestDialect { diff --git a/src/NHibernate/Async/Transaction/AdoNetWithSystemTransactionFactory.cs b/src/NHibernate/Async/Transaction/AdoNetWithSystemTransactionFactory.cs index 91558147f86..3e9de8e7836 100644 --- a/src/NHibernate/Async/Transaction/AdoNetWithSystemTransactionFactory.cs +++ b/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; diff --git a/src/NHibernate/Cfg/Environment.cs b/src/NHibernate/Cfg/Environment.cs index cc107802524..c052cd64267 100644 --- a/src/NHibernate/Cfg/Environment.cs +++ b/src/NHibernate/Cfg/Environment.cs @@ -142,12 +142,29 @@ public static string Version /// after scope disposal. This occurs when the transaction is distributed. /// This notably concerns . /// 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. -1 disables the timeout. /// public const string SystemTransactionCompletionLockTimeout = "transaction.system_completion_lock_timeout"; /// + /// Whether session synchronisation failures occuring during finalizations of system transaction should be + /// ignored or not. by default. + /// + /// + /// 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 . 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. + /// 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 . + /// + public const string IgnoreSessionSynchronizationFailuresOnSystemTransaction = "transaction.ignore_session_synchronization_failures"; + /// /// When a system transaction is being prepared, is using connection during this process enabled? /// Default is , for supporting with transaction factories /// supporting system transactions. But this requires enlisting additional connections, retaining disposed diff --git a/src/NHibernate/Engine/ISessionImplementor.cs b/src/NHibernate/Engine/ISessionImplementor.cs index 9a0cb58b77a..d7af7a73fbd 100644 --- a/src/NHibernate/Engine/ISessionImplementor.cs +++ b/src/NHibernate/Engine/ISessionImplementor.cs @@ -66,6 +66,9 @@ internal static IDisposable BeginProcess(this ISessionImplementor session) : SessionIdLoggingContext.CreateOrNull(session.SessionId); } + internal static bool IsProcessing(this ISessionImplementor session) + => session is AbstractSessionImpl impl && impl.IsProcessing; + //6.0 TODO: Expose as ISessionImplementor.FutureBatch and replace method usages with property internal static IQueryBatch GetFutureBatch(this ISessionImplementor session) { diff --git a/src/NHibernate/ISession.cs b/src/NHibernate/ISession.cs index 237dc9823c0..92b276a88ab 100644 --- a/src/NHibernate/ISession.cs +++ b/src/NHibernate/ISession.cs @@ -243,8 +243,11 @@ public partial interface ISession : IDisposable /// End the ISession by disconnecting from the ADO.NET connection and cleaning up. /// /// - /// It is not strictly necessary to Close() the ISession but you must - /// at least Disconnect() it. + /// It is not strictly necessary to Close() the ISession but you must + /// at least Disconnect() or Dispose it. + /// Do not call this method inside a transaction scope, use Dispose instead, + /// since Close() is not aware of system transactions: if the transaction completion + /// requires the session, it will fail. /// /// The connection provided by the application or DbConnection Close(); diff --git a/src/NHibernate/Impl/AbstractSessionImpl.cs b/src/NHibernate/Impl/AbstractSessionImpl.cs index 4fe9c9ae598..bd51bb51697 100644 --- a/src/NHibernate/Impl/AbstractSessionImpl.cs +++ b/src/NHibernate/Impl/AbstractSessionImpl.cs @@ -394,6 +394,11 @@ public bool IsClosed get { return closed; } } + /// + /// Indicates if the session is currently processing some operations. + /// + public bool IsProcessing => _processHelper.Processing; + /// /// If not nested in another call to BeginProcess on this session, check and update the /// session status and set its session id in context. @@ -407,6 +412,21 @@ public IDisposable BeginProcess() return _processHelper.BeginProcess(this); } + /// + /// If not nested in another call to BeginProcess on this session, optionnaly check + /// and update the session status, then set its session id in context and flag it as processing. + /// + /// to initiate a processing without + /// checking and updating the session. + /// + /// If not already processing, an object to dispose for signaling the end of the process. + /// Otherwise, . + /// + protected IDisposable BeginProcess(bool noCheckAndUpdate) + { + return _processHelper.BeginProcess(this, noCheckAndUpdate); + } + /// /// If not nested in a call to BeginProcess on this session, set its session id in context. /// @@ -429,7 +449,7 @@ private sealed class ProcessHelper : IDisposable private IDisposable _context; [NonSerialized] - private bool _processing; + private volatile bool _processing; public ProcessHelper() { @@ -437,7 +457,7 @@ public ProcessHelper() public bool Processing { get => _processing; } - public IDisposable BeginProcess(AbstractSessionImpl session) + public IDisposable BeginProcess(AbstractSessionImpl session, bool noCheckAndUpdate = false) { if (_processing) return null; @@ -445,7 +465,14 @@ public IDisposable BeginProcess(AbstractSessionImpl session) try { _context = SessionIdLoggingContext.CreateOrNull(session.SessionId); - session.CheckAndUpdateSessionStatus(); + if (noCheckAndUpdate) + { + session.TransactionContext?.Wait(); + } + else + { + session.CheckAndUpdateSessionStatus(); + } _processing = true; } catch diff --git a/src/NHibernate/Impl/SessionImpl.cs b/src/NHibernate/Impl/SessionImpl.cs index 9a7120ae8b7..46d6f20c883 100644 --- a/src/NHibernate/Impl/SessionImpl.cs +++ b/src/NHibernate/Impl/SessionImpl.cs @@ -264,16 +264,10 @@ public bool ShouldAutoClose get { return IsAutoCloseSessionEnabled && !IsClosed; } } - /// - /// Close the session and release all resources - /// - /// Do not call this method inside a transaction scope, use Dispose instead, since - /// Close() is not aware of distributed transactions - /// - /// + /// public DbConnection Close() { - using (BeginContext()) + using (BeginProcess(true)) { log.Debug("closing session"); if (IsClosed) @@ -1488,18 +1482,18 @@ public void Reconnect(DbConnection conn) /// public void Dispose() { - using (BeginContext()) + // Ensure we are not disposing concurrently to transaction completion, which would + // remove the transaction context. + using (BeginProcess(true)) { log.Debug("[session-id={0}] running ISession.Dispose()", SessionId); - // Ensure we are not disposing concurrently to transaction completion, which would - // remove the context. (Do not store it into a local variable before the Wait.) - TransactionContext?.Wait(); - // If the synchronization above is bugged and lets a race condition remaining, we may + // If the BeginProcess synchronization is bugged and lets a race condition remaining, we may // blow here with a null ref exception after the null check. We could introduce // a local variable for avoiding it, but that would turn a failure causing an exception // into a failure causing a session and connection leak. So do not do it, better blow away // with a null ref rather than silently leaking a session. And then fix the synchronization. - if (TransactionContext != null && TransactionContext.CanFlushOnSystemTransactionCompleted) + if (TransactionContext != null && TransactionContext.CanFlushOnSystemTransactionCompleted && + TransactionContext.IsInActiveTransaction) { TransactionContext.ShouldCloseSessionOnSystemTransactionCompleted = true; return; diff --git a/src/NHibernate/Transaction/AdoNetWithSystemTransactionFactory.cs b/src/NHibernate/Transaction/AdoNetWithSystemTransactionFactory.cs index 7f74bc7218c..2c6973137c2 100644 --- a/src/NHibernate/Transaction/AdoNetWithSystemTransactionFactory.cs +++ b/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; @@ -23,6 +24,10 @@ public partial class AdoNetWithSystemTransactionFactory : AdoNetTransactionFacto /// protected int SystemTransactionCompletionLockTimeout { get; private set; } /// + /// See . + /// + protected bool IgnoreSessionSynchronizationFailuresOnSystemTransaction { get; private set; } + /// /// See . /// protected bool UseConnectionOnSystemTransactionPrepare { get; private set; } @@ -32,10 +37,12 @@ public override void Configure(IDictionary props) { base.Configure(props); SystemTransactionCompletionLockTimeout = - PropertiesHelper.GetInt32(Cfg.Environment.SystemTransactionCompletionLockTimeout, props, 5000); + PropertiesHelper.GetInt32(Cfg.Environment.SystemTransactionCompletionLockTimeout, props, 1000); if (SystemTransactionCompletionLockTimeout < -1) throw new HibernateException( $"Invalid {Cfg.Environment.SystemTransactionCompletionLockTimeout} value: {SystemTransactionCompletionLockTimeout}. It can not be less than -1."); + IgnoreSessionSynchronizationFailuresOnSystemTransaction = + PropertiesHelper.GetBoolean(Cfg.Environment.IgnoreSessionSynchronizationFailuresOnSystemTransaction, props, false); UseConnectionOnSystemTransactionPrepare = PropertiesHelper.GetBoolean(Cfg.Environment.UseConnectionOnSystemTransactionPrepare, props, true); } @@ -129,7 +136,7 @@ protected virtual ITransactionContext CreateAndEnlistMainContext( { var transactionContext = new SystemTransactionContext( session, transaction, SystemTransactionCompletionLockTimeout, - UseConnectionOnSystemTransactionPrepare); + UseConnectionOnSystemTransactionPrepare, IgnoreSessionSynchronizationFailuresOnSystemTransaction); transactionContext.EnlistedTransaction.EnlistVolatile( transactionContext, UseConnectionOnSystemTransactionPrepare @@ -188,6 +195,7 @@ public class SystemTransactionContext : ITransactionContext, IEnlistmentNotifica private readonly ISessionImplementor _session; private readonly bool _useConnectionOnSystemTransactionPrepare; + private readonly bool _ignoreSessionSynchronizationFailures; private readonly System.Transactions.Transaction _originalTransaction; private readonly ManualResetEventSlim _lock = new ManualResetEventSlim(true); private volatile bool _needCompletionLocking = true; @@ -203,6 +211,8 @@ public class SystemTransactionContext : ITransactionContext, IEnlistmentNotifica /// The transaction into which the context will be enlisted. /// See . /// See . + // Since 5.6 + [Obsolete("Use overload with an additionnal boolean parameter")] public SystemTransactionContext( ISessionImplementor session, System.Transactions.Transaction transaction, @@ -216,6 +226,29 @@ public SystemTransactionContext( _useConnectionOnSystemTransactionPrepare = useConnectionOnSystemTransactionPrepare; } + /// + /// Default constructor. + /// + /// The session to enlist with the transaction. + /// The transaction into which the context will be enlisted. + /// See . + /// See . + /// See . + public SystemTransactionContext( + ISessionImplementor session, + System.Transactions.Transaction transaction, + int systemTransactionCompletionLockTimeout, + bool useConnectionOnSystemTransactionPrepare, + bool ignoreSessionSynchronizationFailures) + { + _session = session ?? throw new ArgumentNullException(nameof(session)); + _originalTransaction = transaction ?? throw new ArgumentNullException(nameof(transaction)); + EnlistedTransaction = transaction.Clone(); + _systemTransactionCompletionLockTimeout = systemTransactionCompletionLockTimeout; + _useConnectionOnSystemTransactionPrepare = useConnectionOnSystemTransactionPrepare; + _ignoreSessionSynchronizationFailures = ignoreSessionSynchronizationFailures; + } + /// public virtual void Wait() { @@ -242,9 +275,9 @@ public virtual void Wait() // Remove the block then throw. Unlock(); 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."); + "A synchronization timeout occurred at 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."); } catch (HibernateException) { @@ -266,8 +299,8 @@ protected virtual void Lock() { if (!_needCompletionLocking || _isDisposed) return; - _needCompletionLocking = false; _lock.Reset(); + _needCompletionLocking = false; } /// @@ -418,23 +451,20 @@ void IEnlistmentNotification.InDoubt(Enlistment enlistment) /// callback, if this is an in-doubt callback. 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(); } } @@ -454,10 +484,47 @@ protected virtual void CompleteTransaction(bool isCommitted) // do an early exit here in such case. if (!IsInActiveTransaction) return; + Lock(); + // In case of a rollback due to a timeout, we may have the session disposal running concurrently + // to the transaction completion in a way our current locking mechanism cannot fully protect: the + // session disposal "BeginProcess" can go through the Wait before it is locked but flag the + // session as processing after the transaction completion has read it as not processing. To dodge + // that very unlikely case, we could consider the session as still processing initially regardless + // of its actual status in case of rollback by changing below condition to + // "!isCommitted || _session.IsProcessing()". That would cause a Thread.Sleep in all rollback cases. + // That would reinforce the impracticality of that concurrency possibility, but with an ugly crutch. + var isSessionProcessing = _session.IsProcessing(); try { // Allow transaction completed actions to run while others stay blocked. _bypassLock.Value = true; + // 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. + if (isSessionProcessing) + { + var timeOutGuard = new Stopwatch(); + timeOutGuard.Start(); + while (isSessionProcessing && timeOutGuard.ElapsedMilliseconds < _systemTransactionCompletionLockTimeout) + { + // Naïve yield. + Thread.Sleep(10); + isSessionProcessing = _session.IsProcessing(); + } + if (isSessionProcessing) + { + // Throwing would give up attempting to close the session if need be, which may still succeed. So, + // just log an error. + _logger.Warn( + "A synchronization timeout occurred at transaction completion: the session is still processing. " + + "Attempting to finalize the transaction concurrently, which may cause a thread concurrency failure. " + + "You may raise {0} if it is set too low. It may also be a limitation of the data provider, " + + "like locks applied on its side while processing transaction cancellations occurring on concurrent threads, " + + "thus preventing the session to finish its current processing during a transaction cancellation.", + Cfg.Environment.SystemTransactionCompletionLockTimeout); + } + } using (_session.BeginContext()) { // Flag active as false before running actions, otherwise the session may not cleanup as much @@ -477,7 +544,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); @@ -497,6 +564,18 @@ protected virtual void CompleteTransaction(bool isCommitted) // Dispose releases blocked threads by the way. Dispose(); } + + if (isSessionProcessing && !_ignoreSessionSynchronizationFailures) + { + throw new HibernateException( + "A synchronization timeout occurred at transaction completion: the session was still processing. " + + $"You may raise {Cfg.Environment.SystemTransactionCompletionLockTimeout} if it is set too low. " + + "It may also be a limitation of the data provider, " + + "like locks applied on its side while processing transaction cancellations occurring on concurrent threads, " + + "thus preventing the session to finish its current processing during a transaction cancellation. " + + $"In such case, you may enable {Cfg.Environment.IgnoreSessionSynchronizationFailuresOnSystemTransaction}, " + + $"and possibly lower {Cfg.Environment.SystemTransactionCompletionLockTimeout}."); + } } private static void Cleanup(ISessionImplementor session) @@ -504,7 +583,7 @@ private static void Cleanup(ISessionImplementor session) foreach (var dependentSession in session.ConnectionManager.DependentSessions.ToList()) { var dependentContext = dependentSession.TransactionContext; - // Do not nullify TransactionContext here, could create a race condition with + // Do not nullify TransactionContext here, it could create a race condition with // would be await-er on session for disposal (test cases cleanup checks by example). if (dependentContext == null) continue; diff --git a/src/NHibernate/nhibernate-configuration.xsd b/src/NHibernate/nhibernate-configuration.xsd index 08d922ad963..12abc622a52 100644 --- a/src/NHibernate/nhibernate-configuration.xsd +++ b/src/NHibernate/nhibernate-configuration.xsd @@ -233,12 +233,32 @@ after scope disposal. This occurs when the transaction is distributed. This notably concerns ISessionImplementor.AfterTransactionCompletion(bool, ITransaction). 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. -1 disables the timeout. + + + + Whether session synchronisation failures occuring during finalizations of system transaction should be + ignored or not. false by default. + + 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 transaction.system_completion_lock_timeout. 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. + + 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 transaction.system_completion_lock_timeout. + + + diff --git a/teamcity.build b/teamcity.build index b8125f5dfe5..9319ed389fc 100644 --- a/teamcity.build +++ b/teamcity.build @@ -50,6 +50,8 @@ + +