TransactionScope - The underlying provider failed on EnlistTransaction. MSDTC being aborted

Question

Our team have got a problem that manifests as:

The underlying provider failed on EnlistTransaction; Cannot access a disposed object.Object name: 'Transaction'.

which seemed to appear as soon as we began using TransactionScope to handle our applications' transactions.

The top part of the stacktrace is captured as:

at System.Data.EntityClient.EntityConnection.EnlistTransaction(Transaction transaction) at System.Data.Objects.ObjectContext.EnsureConnection() at System.Data.Objects.ObjectContext.ExecuteStoreCommand(String commandText, Object[] parameters) at Reconciliation.Models.BillLines.BillLines.Reconciliation.Interfaces.IBillLineEntities.ExecuteStoreCommand(String, Object[]) at Reconciliation.Models.Legacy.EntityDbEnvironment.ExecuteOracleSql(String sql) in EntityDbEnvironment.cs: line 41

At the same time the MSDTC log is updated, which I've extracted using the instructions here:

pid=7060       ;tid=7908       ;time=04/29/2013-16:38:30.269   ;seq=136        ;eventid=TRANSACTION_BEGUN                        ;tx_guid=60f6390c-7570-488a-97a9-2c3912c4ca3e     ;"TM Identifier='(null)                                            '" ;"transaction has begun, description :'<NULL>'"
pid=7060       ;tid=7908       ;time=04/29/2013-16:38:30.269   ;seq=137        ;eventid=RM_ENLISTED_IN_TRANSACTION               ;tx_guid=60f6390c-7570-488a-97a9-2c3912c4ca3e     ;"TM Identifier='(null)                                            '" ;"resource manager #1002 enlisted as transaction enlistment #1. RM guid = 'defc4277-47a6-4cd9-b092-93a668e2097b'"
pid=7060       ;tid=7908       ;time=04/29/2013-16:38:31.658   ;seq=138        ;eventid=RECEIVED_ABORT_REQUEST_FROM_BEGINNER     ;tx_guid=60f6390c-7570-488a-97a9-2c3912c4ca3e     ;"TM Identifier='(null)                                            '" ;"received request to abort the transaction from beginner"
pid=7060       ;tid=7908       ;time=04/29/2013-16:38:31.658   ;seq=139        ;eventid=TRANSACTION_ABORTING                     ;tx_guid=60f6390c-7570-488a-97a9-2c3912c4ca3e     ;"TM Identifier='(null)                                            '" ;"transaction is aborting"
pid=7060       ;tid=7908       ;time=04/29/2013-16:38:31.658   ;seq=140        ;eventid=RM_ISSUED_ABORT                          ;tx_guid=60f6390c-7570-488a-97a9-2c3912c4ca3e     ;"TM Identifier='(null)                                            '" ;"abort request issued to resource manager #1002 for transaction enlistment #1"
pid=7060       ;tid=7908       ;time=04/29/2013-16:38:31.658   ;seq=141        ;eventid=RM_ACKNOWLEDGED_ABORT                    ;tx_guid=60f6390c-7570-488a-97a9-2c3912c4ca3e     ;"TM Identifier='(null)                                            '" ;"received acknowledgement of abort request from the resource manager #1002 for transaction enlistment #1"
pid=7060       ;tid=7908       ;time=04/29/2013-16:38:31.658   ;seq=142        ;eventid=TRANSACTION_ABORTED                      ;tx_guid=60f6390c-7570-488a-97a9-2c3912c4ca3e     ;"TM Identifier='(null)                                            '" ;"transaction has been aborted"

As you can see an RECEIVED_ABORT_REQUEST_FROM_BEGINNER a second after RM_ENLISTED_IN_TRANSACTION was logged.

We can't understand where this abort request originates from, or why it was raised. The SQL causing the problem is a simple SELECT which we can execute without issue via our database client.

The application works most of the time, only occasionally displaying this issue.

We are using Oracle 10.2.0.5.0 with Entity Framework.

UPDATE

Following advice from @Astrotrain I set up the logging on System.Transactions. The final entry produced is literally cut off half-way though:

....
<ApplicationData>
<TraceData>
<DataItem>
<TraceRecord xmlns="http://schemas.microsoft.com/2004/10/E2ETraceEvent/TraceRecord" Severity="Information">
<TraceIdentifier>http://msdn.microsoft.com/2004/06/System/Transactions/TransactionScopeCreated</TraceIdentifier>
<Description>TransactionScope Created</Description>
<AppDomain>BillLineGeneratorUI.exe</AppDomain>
<ExtendedData xmlns="http://schemas.microsoft.com/2004/03/Transactions/TransactionScopeCreatedTraceRecord">
<TraceSource>[Base]

As you can see the exception actually prevents the log finishing. What can I learn from this? Any ideas?

Answer 1

Instead of using the MSDTC trace tool (which I find horribly spartan), I can recommend using the System.Transactions trace source - just include the following in your web.config:
If you open the log files with SvcTraceViewer.exe you'll get a nice visual representation of the steps.

<configuration>
  <system.diagnostics>
   <trace autoflush="true" />
   <sources>
     <source name="System.Transactions" switchValue="Information">
       <listeners>
         <add name="tx"
              type="System.Diagnostics.XmlWriterTraceListener"
              initializeData="C:\MyApp-transactions-log.svclog" />
       </listeners>
     </source>
   </sources>
  </system.diagnostics>
</configuration>

Not a solution per se, but this might give you some more information about what goes wrong.

Answer 2

As you mentioned "The application works most of the time, only occasionally displaying this issue." by this we can conclude that the provider does supports distributed transactions and the reason is some other intermittent glitch either in connection or handling.

• Are you using nested transaction scopes, because if, due to some reason, inner scope is rolled back (disposed without calling complete) that would immediately roll back the outer transaction causing the error. Use TransactionScopeOption.Required (RequiresNew will also do but RequiresNew has other deadlock related issues associated with it so it is better to use Required) to resolve this

• Otherwise it might be because of some other operation while the transaction is active and to resolve in this case use IsolationLevel = IsolationLevel.ReadCommitted.

Answer 3

We had this problem too. The best way to solve it seems to open a new database connection and just do the things needed in the transaction. Keep transactions as small as possible is always good.

 DatabaseContext db1 = new DatabaseContext();

 doSomeDatabaseActions(db1);

 TransactionOptions transOpts = new TransactionOptions();
 transOpts.IsolationLevel = System.Transactions.IsolationLevel.Serializable;

 using (TransactionScope scope = new TransactionScope(TransactionScopeOption.Required, transOpts))
 {
     using (DatabaseContext db2 = new DatabaseContext())
     {
        doDatabaseChecksWithLock(db2);
        doChanges(db2);
        db2.SaveChanges();
     }

     scope.Complete();
  }

We had the problem without introducing the 2nd connection. Note that the error was also gone using 1 connection (db1) if the transaction was enlarged (made doSomeDatabaseActions part of the transaction).

Answer 4

This maybe should be a comment but it is too big. I hope it helps.

One of the most tipical error with nested transactions is this:

using(TransactionScope outerScope = new TransactionScope())
{
    // Execute query 1

    using(TransactionScope innerScope = new TransactionScope())
    {
        try
        {
            // Execute query 2
        }
        catch (Exception)
        {
        }

        innerScope.Complete();
    }

    outerScope.Complete();
}

Now if query 2 which is inside of the try/catch block, rasies an error you will catch the exception in the try/catch block and handle it, but here is a supprise the application will throw an ObjectDisposedException on line 15 when you try to complete the transaction. This is because the DTC has already caught the exception and although you have handled it, the TransactionScope objects where already disposed by the .Net code and the transaction has been rolled back. Notice that I have said “objects” this is because both of the TransactionScope object have been disposed as they are a part of the same transaction.