Bug #35330 InvalidOperationException during Transaction Rollback
Submitted: 17 Mar 2008 10:37 Modified: 8 Jan 2010 11:58
Reporter: Please Remove Email Updates:
Status: Closed Impact on me:
None 
Category:Connector / NET Severity:S2 (Serious)
Version:5.2 latest OS:Any
Assigned to: Vladislav Vaintroub CPU Architecture:Any
Triage: D3 (Medium)

[17 Mar 2008 10:37] Please Remove
Description:
I came across this exception in our unhandled exception log:

System.InvalidOperationException: Connection must be valid and open to rollback transaction
   at MySql.Data.MySqlClient.MySqlTransaction.Rollback()
   at MySql.Data.MySqlClient.MySqlConnection.CloseFully()
   at MySql.Data.MySqlClient.MySqlPromotableTransaction.System.Transactions.IPromotableSinglePhaseNotification.Rollback(SinglePhaseEnlistment singlePhaseEnlistment)
   at System.Transactions.DurableEnlistmentAborting.EnterState(InternalEnlistment enlistment)
   at System.Transactions.DurableEnlistmentActive.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)

How to repeat:
No idea, as I just got it from a log. 

Suggested fix:
Again, no idea, but calling MySqlConnection.CloseFully() before MySqlTransaction.Rollback() seems wrong ;-)
[21 Mar 2008 14:24] Please Remove
Okay, after digging through the source code, calling MySqlConnection.CloseFully() before MySqlTransaction.Rollback() doesn't seem to be so wrong ;-)

But: 
MySqlPromotableTransaction.Rollback() only calls MySqlConnection.CloseFully() if connection.State == ConnectionState.Closed, and in MySqlConnection.CloseFully() a rollback is issued if driver.ServerStatus & ServerStatusFlags.InTransaction != 0 which was obviously the case, but as the connection is closed this fails. 

I'm still not sure, what the right thing to do is here, but I hope this gives Reggie a hint in the right direction.
[16 Jun 2008 16:46] Please Remove
Ok, one reproduce this with simple test case:

CREATE TABLE  "test" (
  "Id" int(10) unsigned NOT NULL default '0',
  PRIMARY KEY  ("Id")
);

MySqlHelper.ExecuteNonQuery(ConString, "TRUNCATE TABLE test;");

using (TransactionScope ts = new TransactionScope(TransactionScopeOption.RequiresNew, TimeSpan.FromSeconds(5)))
{
    for (int i = 0; i < 100000000; i++)
    {
        MySqlHelper.ExecuteNonQuery(ConString, String.Format("INSERT INTO test VALUES ({0})", i));
     }

     ts.Complete();
}

BUT: This doesn't always cause the aforementioned problem. Actually most of the times it causes these (with 5.1.5 or 5.1.6):

System.Threading.SemaphoreFullException was unhandled
  Message="Adding the given count to the semaphore would cause it to exceed its maximum count."
  Source="System"
  StackTrace:
       at System.Threading.Semaphore.Release(Int32 releaseCount)
       at System.Threading.Semaphore.Release()
       at MySql.Data.MySqlClient.MySqlPool.ReleaseConnection(Driver driver)
       at MySql.Data.MySqlClient.MySqlPoolManager.ReleaseConnection(Driver driver)
       at MySql.Data.MySqlClient.MySqlConnection.CloseFully()
       at MySql.Data.MySqlClient.MySqlConnection.Close()
       at MySql.Data.MySqlClient.MySqlConnection.Dispose(Boolean disposing)
       at System.ComponentModel.Component.Dispose()
       at MySql.Data.MySqlClient.MySqlHelper.ExecuteNonQuery(String connectionString, String commandText, MySqlParameter[] parms)
       at Bug35330.Program.TestOne() in C:\Users\Dennis\Documents\Visual Studio 2008\Projects\Bug35330\Bug35330\Program.cs:line 60
       at Bug35330.Program.Main(String[] args) in C:\Users\Dennis\Documents\Visual Studio 2008\Projects\Bug35330\Bug35330\Program.cs:line 15
       at System.AppDomain._nExecuteAssembly(Assembly assembly, String[] args)
       at Microsoft.VisualStudio.HostingProcess.HostProc.RunUsersAssembly()
       at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
       at System.Threading.ThreadHelper.ThreadStart()

With 5.2.2:

System.Transactions.TransactionException was unhandled
  Message="The operation is not valid for the state of the transaction."
  Source="System.Transactions"
  StackTrace:
       at System.Transactions.TransactionState.EnlistPromotableSinglePhase(InternalTransaction tx, IPromotableSinglePhaseNotification promotableSinglePhaseNotification, Transaction atomicTransaction)
       at System.Transactions.Transaction.EnlistPromotableSinglePhase(IPromotableSinglePhaseNotification promotableSinglePhaseNotification)
       at MySql.Data.MySqlClient.MySqlConnection.EnlistTransaction(Transaction transaction)
       at MySql.Data.MySqlClient.MySqlConnection.Open()
       at MySql.Data.MySqlClient.MySqlHelper.ExecuteNonQuery(String connectionString, String commandText, MySqlParameter[] parms)
       at Bug35330.Program.TestOne() in C:\Users\Dennis\Documents\Visual Studio 2008\Projects\Bug35330\Bug35330\Program.cs:line 61
       at Bug35330.Program.Main(String[] args) in C:\Users\Dennis\Documents\Visual Studio 2008\Projects\Bug35330\Bug35330\Program.cs:line 18
       at System.AppDomain._nExecuteAssembly(Assembly assembly, String[] args)
       at Microsoft.VisualStudio.HostingProcess.HostProc.RunUsersAssembly()
       at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
       at System.Threading.ThreadHelper.ThreadStart()
  InnerException: System.TimeoutException
       Message="Transaction Timeout"
       
Be sure to enable logging, because this will show an interesting thing:

In case the InvalidOperationException is thrown the log looks like this:

[16.06.2008 18:32:04] - Executing command QUERY with text ='INSERT INTO test VALUES (10883)'
[16.06.2008 18:32:04] - Executing command QUERY with text ='INSERT INTO test VALUES (10884)'
[16.06.2008 18:32:04] - Executing command QUERY with text ='ROLLBACK'

Notice that the last command that gets executed is the ROLLBACK statement. But in case of the other two exceptions, one or two commands are being executed after the ROLLBACK statement:

[16.06.2008 18:23:29] - Executing command QUERY with text ='ROLLBACK'
[16.06.2008 18:23:29] - Executing command QUERY with text ='INSERT INTO test VALUES (11172)'
[16.06.2008 18:23:29] - Executing command QUERY with text ='INSERT INTO test VALUES (11173)'

The behaviour is non-deterministic and it can take a while to reproduce the original problem.
[17 Jun 2008 17:40] Tonci Grgin
Hi Dennis and thanks for your report.

My suspicion is that no transaction was started at all thus additional INSERTS you're seeing. Let me try making a test case for this.
[17 Jun 2008 18:41] Tonci Grgin
Dennis, I see nothing strange in these exceptions since TimeSpan of transaction is very limited. I would say all works as expected (can't commit/rollback aborted transaction in scope due to timeout) but I also see strange INSERT in log:
[17.06.08 20:30:59] - Executing command QUERY with text ='INSERT INTO bug35330 VALUES(4795)'
[17.06.08 20:30:59] - Executing command QUERY with text ='ROLLBACK'
[17.06.08 20:30:59] - Executing command QUERY with text ='INSERT INTO bug35330 VALUES(4796)' << This should not have happened.

Investigating more.

My test case on c/NET 5.2.2 and MySQL server 5.0.64pb on WinXP Pro SP2 localhost:
      MySqlConnection conn = new MySqlConnection("DataSource=localhost;Database=test;UserID=root;Password=*****;PORT=****;logging=true");
      conn.Open();
      MySqlCommand cmdsetup = new MySqlCommand("DROP TABLE IF EXISTS bug35330",conn);
      cmdsetup.ExecuteNonQuery();
      cmdsetup.CommandText = "CREATE TABLE  bug35330(Id int(10) unsigned NOT NULL default '0', PRIMARY KEY  (Id))ENGINE=InnoDB";
      cmdsetup.ExecuteNonQuery();
      cmdsetup.Dispose();
      conn.Close();
      conn.Dispose();

       using (TransactionScope ts = new TransactionScope(TransactionScopeOption.RequiresNew, TimeSpan.FromSeconds(5)))
       {
          for (int i = 0; i < 10000; i++)
          {
              MySqlHelper.ExecuteNonQuery("DataSource=localhost;Database=test;UserID=root;Password=*****;PORT=****;logging=true", String.Format("INSERT INTO bug35330 VALUES({0})", i));
                }
                ts.Complete();
            }

mysql> select count(*) from bug35330;

+----------+
| count(*) |
+----------+
|        1 |
+----------+
1 row in set (0.02 sec)

mysql>
[30 Jun 2008 20:15] Please Remove
Hi Tonci, thanks for looking into this.

I have to disagree with the notion that this is expected behavior. 

The exception in my first post is thrown from a timer callback thread and causes the executing application to close! A SemaphoreFullException also isn't really what I'd expect in case of a transaction timeout.

SQL Server 2005 throws a SQLException in this case, stating that the DTC has aborted the transaction. This is actually the other big problem with this behavior, as this really should have been a distributed transaction.
[2 Oct 2008 18:04] Tonci Grgin
Dennis, I apologize for the delay in processing. Will restart testing tomorrow.

Now as for what one expects and what really happens... Connectors bug reports are the worst nightmare to process. First you have to be the master of IDE and language. Then you have to master the framework specs to know what to expect and how to obtain it. Then you have to map all that knowledge to the specific way MySQL server does things. Never mind, will see what I can do here.

In the meantime, did you tried c/NET 5.2 or even 5.3?
[6 Oct 2008 14:19] Please Remove
Hi Tonci,

I can well imagine that connector bugs are hard to process, especially one like this. Will test with 5.3. I've posted the result with 5.2.2 above.
[22 Oct 2008 7:43] Please Remove
Tonci, I tried to build the trunk today, but the file 
MySql.Web\Providers\Properties\Resources.Designer.cs isn't checked in to the repository.
[10 Mar 2009 10:50] Tonci Grgin
Sorry Dennis, too much things to do...

You do not need that file or that part of tree... In my projects I add, for example, F:\svn-net\connector-net\branches\5.2\MySql.Data\Provider\MySql.Data.csproj into my solution together with my code. All you need to do for building is to remark //[assembly: AssemblyKeyName("ConnectorNet")] in AssemblyInfo.cs
[10 Mar 2009 11:46] Tonci Grgin
Dennis. I can agree we should handle this better:
[10.3.2009 12:36:20] - Executing command QUERY with text ='INSERT INTO bug35330 VALUES(3886)'
[10.3.2009 12:36:20] - Executing command QUERY with text ='ROLLBACK'
[10.3.2009 12:36:20] - Executing command QUERY with text ='INSERT INTO bug35330 VALUES(3887)'
[10.3.2009 12:36:20] - Executing command QUERY with text ='ROLLBACK'
A first chance exception of type 'System.Transactions.TransactionException' occurred in System.Transactions.dll
System.Transactions Critical: 0

Using very short TimeSpan of transaction scope, shorter than duration of transaction, will cause, after expiration, repeated tries to ROLLBACK transaction which is not possible any more as it's already dead. I think we should keep transaction alive for long enough to close it properly or stop ROLLBACKs from being issued.
[10 Mar 2009 11:47] Tonci Grgin
Workaround is rather simple, replacing TimeSpan.FromSeconds(X) with appropriate value of X.

Test case:
      MySqlConnection conn = new MySqlConnection("DataSource=localhost;Database=test;UserID=root;Password=**;PORT=**;logging=true");
      conn.Open();
      MySqlCommand cmdsetup = new MySqlCommand("DROP TABLE IF EXISTS bug35330", conn);
      cmdsetup.ExecuteNonQuery();
      cmdsetup.CommandText = "CREATE TABLE  bug35330(Id int(10) unsigned NOT NULL default '0', PRIMARY KEY  (Id))ENGINE=InnoDB";
      cmdsetup.ExecuteNonQuery();
      cmdsetup.CommandText = "SET autocommit = 0";
      cmdsetup.ExecuteNonQuery();
      cmdsetup.CommandText = "SET sql_mode=TRADITIONAL";
      cmdsetup.ExecuteNonQuery();
      cmdsetup.Dispose();
      conn.Close();
      conn.Dispose();

      using (TransactionScope ts = new TransactionScope(TransactionScopeOption.RequiresNew, TimeSpan.FromSeconds(5)))
      {
            for (int i = 0; i < 10000; i++)
            {
                MySqlHelper.ExecuteNonQuery("DataSource=localhost;Database=test;UserID=root;Password=**;PORT=**;logging=true", String.Format("INSERT INTO bug35330 VALUES({0})", i));
            }
      }
[10 Mar 2009 11:50] Tonci Grgin
-

Attachment: Stacktrace_BUG#35330.zip (application/zip, text), 1.50 KiB.

[12 Aug 2009 17:29] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/80702
[1 Sep 2009 20:13] Reggie Burnett
This will be fixed as part of a much larger XA patch
[1 Sep 2009 22:36] Reggie Burnett
I wanted to clarify my previous comment.  This patch did not have enough time to be reviewed prior to inclusion. It's a fairly large patch and I'm concerned that it doesn't really solve the problem.  We are working to provide better support for MySQL XA and that patch will solve this issue.
[4 Dec 2009 14:36] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/92890

811 Vladislav Vaintroub	2009-12-04
      Bug #35330 InvalidOperationException during Transaction Rollback :
      fix race condition between abort thread (the one that issues rollback)
      and the "main" thread (the one that is using TransactionScope).
      
      When transaction is being aborted, only aborting thread can execute 
      Driver commands, other threads will get TransactionAborted exceptions.
[4 Dec 2009 14:54] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/92892

811 Vladislav Vaintroub	2009-12-04
      Bug #35330 InvalidOperationException during Transaction Rollback :
      fix race condition between abort thread (the one that issues rollback)
      and the "main" thread (the one that is using TransactionScope).
      
      When transaction is being aborted, only aborting thread can execute 
      Driver commands, other threads will get TransactionAborted exceptions.
[15 Dec 2009 1:56] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/94020

811 Vladislav Vaintroub	2009-12-15
      Bug #35330 InvalidOperationException during Transaction Rollback :
      fix race condition between abort thread (the one that issues rollback)
      and the "main" thread (the one that is using TransactionScope).
[15 Dec 2009 2:05] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/94021

811 Vladislav Vaintroub	2009-12-15
      Bug #35330 InvalidOperationException during Transaction Rollback :
      fix race condition between abort thread (the one that issues rollback)
      and the "main" thread (the one that is using TransactionScope).
[15 Dec 2009 2:13] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/94022

811 Vladislav Vaintroub	2009-12-15
      Bug #35330 InvalidOperationException during Transaction Rollback :
      fix race condition between abort thread (the one that issues rollback)
      and the "main" thread (the one that is using TransactionScope).
[8 Jan 2010 11:58] Tony Bedford
An entry has been added to the 6.2.2 changelog:

MySQL Connector/NET generated an invalid operation exception during a transaction rollback:

System.InvalidOperationException: Connection must be valid and open to rollback
transaction
   at MySql.Data.MySqlClient.MySqlTransaction.Rollback()
   at MySql.Data.MySqlClient.MySqlConnection.CloseFully()
   at
MySql.Data.MySqlClient.MySqlPromotableTransaction.System.Transactions.IPromotableSinglePhaseNotification.Rollback(SinglePhaseEnlistment
singlePhaseEnlistment)
...
[3 Mar 2010 14:00] Usman Ali
Two step to solve System.Threading.Semaphore.Release Issue

1. Install Latest mySQL Connector 6.0 or later

2.Set pooling=false; in the connection string.

For Example :

ConnectionStringObject="server=localhost;user id=root;password=usman;database=uts1;persist security info=True;pooling=false;"

_________________

www.ashscholar.com
[3 Mar 2010 14:00] Usman Ali
Two step to solve System.Threading.Semaphore.Release Issue

1. Install Latest mySQL Connector 6.0 or later

2.Set pooling=false; in the connection string.

For Example :

ConnectionStringObject="server=localhost;user id=root;password=usman;database=uts1;persist security info=True;pooling=false;"

_________________

www.ashscholar.com